Adding javalin access logs

qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinAccessLogger.java

@@ -26,13 +26,24 @@ import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
 import com.kingsrook.qqq.backend.core.logging.LogPair;
-import com.kingsrook.qqq.backend.core.utils.QLogger;
+import com.kingsrook.qqq.backend.core.logging.QLogger;
+import com.kingsrook.qqq.backend.core.model.actions.processes.ProcessSummaryLineInterface;
+import com.kingsrook.qqq.backend.core.model.actions.processes.RunProcessOutput;
+import com.kingsrook.qqq.backend.core.processes.implementations.etl.streamedwithfrontend.StreamedETLWithFrontendProcess;
+import com.kingsrook.qqq.backend.core.utils.CollectionUtils;
 import com.kingsrook.qqq.backend.core.utils.StringUtils;
 import static com.kingsrook.qqq.backend.core.logging.LogUtils.logPair;
 
 
 /*******************************************************************************
+ ** Access-Logger used for QJavalin handlers.
  **
+ ** Can be disabled through the JavalinMetaData in the QJavalinImplementation -
+ ** See one of those 2 places for details (e.g., system properties).
+ **
+ ** Note - when working in this class - be overly aggressive with wrapping
+ ** everything in try-catch, and not allowing exceptions to bubble.  There isn't
+ ** much more of a disappointment then when logging code breaks user actions...
  *******************************************************************************/
 public class QJavalinAccessLogger
 {
@@ -40,6 +51,7 @@ public class QJavalinAccessLogger
 
    private static ThreadLocal<Long>      requestStartTime  = new ThreadLocal<>();
    private static ThreadLocal<String>    requestActionName = new ThreadLocal<>();
+   private static ThreadLocal<LogPair[]> requestLogPairs   = new ThreadLocal<>();
 
 
 
@@ -48,13 +60,99 @@ public class QJavalinAccessLogger
     *******************************************************************************/
    static void logStart(String actionName, LogPair... logPairs)
    {
-      requestStartTime.set(System.currentTimeMillis());
+      try
-      requestActionName.set(actionName);
+      {
+         if(!QJavalinImplementation.javalinMetaData.getLogAllAccessStarts() && !QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            /////////////////////////////////////////////////////
+            // if we're not to log starts or ends, just return //
+            /////////////////////////////////////////////////////
+            return;
+         }
+
+         setThreadLocals(actionName, logPairs);
+
+         if(QJavalinImplementation.javalinMetaData.getLogAllAccessStarts())
+         {
             List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs));
+            pairList.add(0, logPair("action", actionName));
             pairList.add(0, logPair("access", "start"));
-      pairList.add(1, logPair("action", actionName));
             LOG.info(pairList);
          }
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   static void logStartSilent(String actionName)
+   {
+      setThreadLocals(actionName, null);
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   private static void setThreadLocals(String actionName, LogPair[] logPairs)
+   {
+      try
+      {
+         ////////////////////////////////////////////////////////
+         // only set the thread locals if we're doing log-ends //
+         ////////////////////////////////////////////////////////
+         if(QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            requestActionName.set(actionName);
+            requestStartTime.set(System.currentTimeMillis());
+            requestLogPairs.set(logPairs);
+         }
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   public static void logEndSuccessIfSlow(long slowThreshold, LogPair... logPairs)
+   {
+      try
+      {
+         if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            return;
+         }
+
+         Long startTime = requestStartTime.get();
+         Long millis    = null;
+         if(startTime != null)
+         {
+            long endTime = System.currentTimeMillis();
+            millis = endTime - startTime;
+         }
+
+         if(millis != null && millis > slowThreshold)
+         {
+            logEnd("success", new ArrayList<>(Arrays.asList(logPairs)));
+         }
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
+   }
 
 
 
@@ -63,9 +161,20 @@ public class QJavalinAccessLogger
     *******************************************************************************/
    static void logEndSuccess(LogPair... logPairs)
    {
+      try
+      {
+         if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            return;
+         }
+
          List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs));
-      pairList.add(0, logPair("access", "end-ok"));
+         logEnd("success", pairList);
-      accessLogEnd(pairList);
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
    }
 
 
@@ -75,11 +184,22 @@ public class QJavalinAccessLogger
     *******************************************************************************/
    static void logEndFail(Throwable t, LogPair... logPairs)
    {
+      try
+      {
+         if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            return;
+         }
+
          List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs));
-      pairList.add(0, logPair("access", "end-fail"));
+         // pairList.add(0, logPair("exceptionMessage", t.getMessage()));
-      pairList.add(1, logPair("exceptionType", t.getClass().getSimpleName()));
+         // pairList.add(0, logPair("exceptionType", t.getClass().getSimpleName()));
-      pairList.add(2, logPair("exceptionMessage", t.getMessage()));
+         logEnd("failure", pairList);
-      accessLogEnd(pairList);
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
    }
 
 
@@ -87,23 +207,178 @@ public class QJavalinAccessLogger
    /*******************************************************************************
     **
     *******************************************************************************/
-   private static void accessLogEnd(List<LogPair> pairList)
+   private static void logEnd(String accessType, List<LogPair> pairList)
    {
+      try
+      {
+         if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            return;
+         }
+
+         LogPair[] logPairsFromStart = requestLogPairs.get();
+         if(logPairsFromStart != null)
+         {
+            for(int i = logPairsFromStart.length - 1; i >= 0; i--)
+            {
+               pairList.add(0, logPairsFromStart[i]);
+            }
+         }
+
          String actionName = requestActionName.get();
          requestActionName.remove();
          if(StringUtils.hasContent(actionName))
          {
-         pairList.add(1, logPair("action", actionName));
+            pairList.add(0, logPair("action", actionName));
          }
 
+         pairList.add(0, logPair("access", accessType));
+
          Long startTime = requestStartTime.get();
          requestStartTime.remove();
+         Long millis;
          if(startTime != null)
          {
             long endTime = System.currentTimeMillis();
-         pairList.add(logPair("millis", (endTime - startTime)));
+            millis = endTime - startTime;
+            pairList.add(logPair("millis", millis));
          }
-      LOG.info(pairList);
+         else
+         {
+            //////////////////////////////////////////////////////////////////////
+            // done so var can be effectively null, and be used in lambda below //
+            //////////////////////////////////////////////////////////////////////
+            millis = null;
          }
 
+         ////////////////////////////////////////////////////////////////////////////////////////
+         // filter out any LogPairIfSlow objects we have, for in case the request was not slow //
+         ////////////////////////////////////////////////////////////////////////////////////////
+         pairList.removeIf(logPair ->
+         {
+            if(logPair instanceof LogPairIfSlow logPairIfSlow)
+            {
+               if(millis != null && millis < logPairIfSlow.getSlowThreshold())
+               {
+                  return (true);
+               }
+            }
+            return (false);
+         });
+
+         LOG.info(pairList);
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   public static LogPairIfSlow logPairIfSlow(String key, Object value, long slowThreshold)
+   {
+      return (new LogPairIfSlow(key, value, slowThreshold));
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   public static void logProcessSummary(String processName, String processUUID, RunProcessOutput runProcessOutput)
+   {
+      try
+      {
+         if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
+         {
+            return;
+         }
+
+         List<LogPair> logPairs = new ArrayList<>();
+         logPairs.add(logPair("processName", processName));
+         logPairs.add(logPair("processUUID", processUUID));
+
+         if(runProcessOutput != null)
+         {
+            runProcessOutput.getProcessState().getNextStepName().ifPresent(nextStep -> logPairs.add(logPair("nextStep", nextStep)));
+
+            try
+            {
+               if(runProcessOutput.getValues().containsKey(StreamedETLWithFrontendProcess.FIELD_PROCESS_SUMMARY))
+               {
+                  List<ProcessSummaryLineInterface> processSummaryLines = (List<ProcessSummaryLineInterface>) runProcessOutput.getValues().get(StreamedETLWithFrontendProcess.FIELD_PROCESS_SUMMARY);
+                  processSummaryListToLogPairs(logPairs, processSummaryLines);
+               }
+               else if(runProcessOutput.getValues().containsKey(StreamedETLWithFrontendProcess.FIELD_VALIDATION_SUMMARY))
+               {
+                  List<ProcessSummaryLineInterface> processSummaryLines = (List<ProcessSummaryLineInterface>) runProcessOutput.getValues().get(StreamedETLWithFrontendProcess.FIELD_VALIDATION_SUMMARY);
+                  processSummaryListToLogPairs(logPairs, processSummaryLines);
+               }
+            }
+            catch(Exception e)
+            {
+               logPairs.add(logPair("errorLoggingSummary", e.getMessage()));
+            }
+         }
+
+         logEnd("processSummary", logPairs);
+      }
+      catch(Exception e)
+      {
+         LOG.warn("Error in javalin access logger", e);
+      }
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   private static void processSummaryListToLogPairs(List<LogPair> logPairs, List<ProcessSummaryLineInterface> processSummaryLines)
+   {
+      int i = 0;
+      for(ProcessSummaryLineInterface processSummaryLine : CollectionUtils.nonNullList(processSummaryLines))
+      {
+         LogPair logPair = processSummaryLine.toLogPair();
+         logPair.setKey(logPair.getKey() + i++);
+         logPairs.add(logPair);
+      }
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   public static class LogPairIfSlow extends LogPair
+   {
+      private final long slowThreshold;
+
+
+
+      /*******************************************************************************
+       ** Constructor
+       **
+       *******************************************************************************/
+      public LogPairIfSlow(String key, Object value, long slowThreshold)
+      {
+         super(key, value);
+         this.slowThreshold = slowThreshold;
+      }
+
+
+
+      /*******************************************************************************
+       ** Getter for slowThreshold
+       **
+       *******************************************************************************/
+      public long getSlowThreshold()
+      {
+         return slowThreshold;
+      }
+   }
 }

qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinImplementation.java

@@ -62,6 +62,7 @@ import com.kingsrook.qqq.backend.core.exceptions.QPermissionDeniedException;
 import com.kingsrook.qqq.backend.core.exceptions.QUserFacingException;
 import com.kingsrook.qqq.backend.core.exceptions.QValueException;
 import com.kingsrook.qqq.backend.core.instances.QInstanceValidator;
+import com.kingsrook.qqq.backend.core.logging.QLogger;
 import com.kingsrook.qqq.backend.core.model.actions.AbstractActionInput;
 import com.kingsrook.qqq.backend.core.model.actions.metadata.MetaDataInput;
 import com.kingsrook.qqq.backend.core.model.actions.metadata.MetaDataOutput;
@@ -70,6 +71,7 @@ import com.kingsrook.qqq.backend.core.model.actions.metadata.ProcessMetaDataOutp
 import com.kingsrook.qqq.backend.core.model.actions.metadata.TableMetaDataInput;
 import com.kingsrook.qqq.backend.core.model.actions.metadata.TableMetaDataOutput;
 import com.kingsrook.qqq.backend.core.model.actions.reporting.ExportInput;
+import com.kingsrook.qqq.backend.core.model.actions.reporting.ExportOutput;
 import com.kingsrook.qqq.backend.core.model.actions.reporting.ReportFormat;
 import com.kingsrook.qqq.backend.core.model.actions.tables.count.CountInput;
 import com.kingsrook.qqq.backend.core.model.actions.tables.count.CountOutput;
@@ -99,15 +101,17 @@ import com.kingsrook.qqq.backend.core.modules.authentication.QAuthenticationModu
 import com.kingsrook.qqq.backend.core.utils.CollectionUtils;
 import com.kingsrook.qqq.backend.core.utils.ExceptionUtils;
 import com.kingsrook.qqq.backend.core.utils.JsonUtils;
-import com.kingsrook.qqq.backend.core.utils.QLogger;
 import com.kingsrook.qqq.backend.core.utils.StringUtils;
 import com.kingsrook.qqq.backend.core.utils.ValueUtils;
+import com.kingsrook.qqq.backend.core.utils.lambdas.UnsafeConsumer;
+import com.kingsrook.qqq.backend.core.utils.lambdas.UnsafeFunction;
 import io.javalin.Javalin;
 import io.javalin.apibuilder.EndpointGroup;
 import io.javalin.http.Context;
 import org.apache.commons.io.FileUtils;
 import org.eclipse.jetty.http.HttpStatus;
 import static com.kingsrook.qqq.backend.core.logging.LogUtils.logPair;
+import static com.kingsrook.qqq.backend.javalin.QJavalinAccessLogger.logPairIfSlow;
 import static io.javalin.apibuilder.ApiBuilder.delete;
 import static io.javalin.apibuilder.ApiBuilder.get;
 import static io.javalin.apibuilder.ApiBuilder.patch;
@@ -130,12 +134,13 @@ public class QJavalinImplementation
    private static final String BASIC_AUTH_NAME        = "basicAuthString";
 
    static QInstance        qInstance;
-   static QJavalinMetaData javalinMetaData = new QJavalinMetaData();
+   static QJavalinMetaData javalinMetaData;
 
    private static Supplier<QInstance> qInstanceHotSwapSupplier;
    private static long                lastQInstanceHotSwapMillis;
 
    private static final long MILLIS_BETWEEN_HOT_SWAPS = 2500;
+   private static final long SLOW_LOG_THRESHOLD_MS    = 1000;
 
    private static int DEFAULT_PORT = 8001;
 
@@ -161,8 +166,19 @@ public class QJavalinImplementation
     **
     *******************************************************************************/
    public QJavalinImplementation(QInstance qInstance) throws QInstanceValidationException
+   {
+      this(qInstance, new QJavalinMetaData());
+   }
+
+
+
+   /*******************************************************************************
+    **
+    *******************************************************************************/
+   public QJavalinImplementation(QInstance qInstance, QJavalinMetaData javalinMetaData) throws QInstanceValidationException
    {
       QJavalinImplementation.qInstance = qInstance;
+      QJavalinImplementation.javalinMetaData = javalinMetaData;
       new QInstanceValidator().validate(qInstance);
    }
 
@@ -176,6 +192,7 @@ public class QJavalinImplementation
       LOG.info("Loading qInstance from file (assuming json): " + qInstanceFilePath);
       String qInstanceJson = FileUtils.readFileToString(new File(qInstanceFilePath));
       QJavalinImplementation.qInstance = new QInstanceAdapter().jsonToQInstanceIncludingBackends(qInstanceJson);
+      QJavalinImplementation.javalinMetaData = new QJavalinMetaData();
    }
 
 
@@ -300,7 +317,7 @@ public class QJavalinImplementation
          {
             get("/", QJavalinImplementation::dataQuery);
             post("/query", QJavalinImplementation::dataQuery);
-            post("/", QJavalinImplementation::dataInsert); // todo - internal to that method, if input is a list, do a bulk - else, single.
+            post("/", QJavalinImplementation::dataInsert);
             get("/count", QJavalinImplementation::dataCount);
             post("/count", QJavalinImplementation::dataCount);
             get("/export", QJavalinImplementation::dataExportWithoutFilename);
@@ -321,7 +338,7 @@ public class QJavalinImplementation
             });
          });
 
-         get("/widget/{name}", QJavalinImplementation::widget);
+         get("/widget/{name}", QJavalinImplementation::widget); // todo - can we just do a slow log here?
 
          ////////////////////
          // process routes //
@@ -470,14 +487,19 @@ public class QJavalinImplementation
     *******************************************************************************/
    private static void dataDelete(Context context)
    {
+      String table      = context.pathParam("table");
+      String primaryKey = context.pathParam("primaryKey");
+
       try
       {
-         String             table       = context.pathParam("table");
          List<Serializable> primaryKeys = new ArrayList<>();
-         primaryKeys.add(context.pathParam("primaryKey"));
+         primaryKeys.add(primaryKey);
 
          DeleteInput deleteInput = new DeleteInput();
          setupSession(context, deleteInput);
+
+         QJavalinAccessLogger.logStart("delete", logPair("table", table), logPair("primaryKey", primaryKey));
+
          deleteInput.setTableName(table);
          deleteInput.setPrimaryKeys(primaryKeys);
 
@@ -486,10 +508,12 @@ public class QJavalinImplementation
          DeleteAction deleteAction = new DeleteAction();
          DeleteOutput deleteResult = deleteAction.execute(deleteInput);
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(deleteResult));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          handleException(context, e);
       }
    }
@@ -501,10 +525,11 @@ public class QJavalinImplementation
     *******************************************************************************/
    private static void dataUpdate(Context context)
    {
+      String table      = context.pathParam("table");
+      String primaryKey = context.pathParam("primaryKey");
+
       try
       {
-         String table = context.pathParam("table");
-
          UpdateInput updateInput = new UpdateInput();
          setupSession(context, updateInput);
          updateInput.setTableName(table);
@@ -538,17 +563,21 @@ public class QJavalinImplementation
          }
 
          QTableMetaData tableMetaData = qInstance.getTable(table);
-         record.setValue(tableMetaData.getPrimaryKeyField(), context.pathParam("primaryKey"));
+         record.setValue(tableMetaData.getPrimaryKeyField(), primaryKey);
+
+         QJavalinAccessLogger.logStart("update", logPair("table", table), logPair("primaryKey", primaryKey));
 
          updateInput.setRecords(recordList);
 
          UpdateAction updateAction = new UpdateAction();
          UpdateOutput updateResult = updateAction.execute(updateInput);
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(updateResult));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          handleException(context, e);
       }
    }
@@ -560,18 +589,19 @@ public class QJavalinImplementation
     *******************************************************************************/
    private static void dataInsert(Context context)
    {
+      String tableName = context.pathParam("table");
       try
       {
-         String      table       = context.pathParam("table");
          InsertInput insertInput = new InsertInput();
          setupSession(context, insertInput);
-         insertInput.setTableName(table);
+         insertInput.setTableName(tableName);
+         QJavalinAccessLogger.logStart("insert", logPair("table", tableName));
 
          PermissionsHelper.checkTablePermissionThrowing(insertInput, TablePermissionSubType.INSERT);
 
          List<QRecord> recordList = new ArrayList<>();
          QRecord       record     = new QRecord();
-         record.setTableName(table);
+         record.setTableName(tableName);
          recordList.add(record);
 
          Map<?, ?> map = context.bodyAsClass(Map.class);
@@ -589,13 +619,15 @@ public class QJavalinImplementation
 
          if(CollectionUtils.nullSafeHasContents(insertOutput.getRecords().get(0).getErrors()))
          {
-            throw (new QUserFacingException("Error inserting " + qInstance.getTable(table).getLabel() + ": " + insertOutput.getRecords().get(0).getErrors().get(0)));
+            throw (new QUserFacingException("Error inserting " + qInstance.getTable(tableName).getLabel() + ": " + insertOutput.getRecords().get(0).getErrors().get(0)));
          }
 
+         QJavalinAccessLogger.logEndSuccess(logPair("primaryKey", () -> (insertOutput.getRecords().get(0).getValue(qInstance.getTable(tableName).getPrimaryKeyField()))));
          context.result(JsonUtils.toJson(insertOutput));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          handleException(context, e);
       }
    }
@@ -607,14 +639,17 @@ public class QJavalinImplementation
     ********************************************************************************/
    private static void dataGet(Context context)
    {
+      String tableName  = context.pathParam("table");
+      String primaryKey = context.pathParam("primaryKey");
+
       try
       {
-         String         tableName  = context.pathParam("table");
          QTableMetaData table    = qInstance.getTable(tableName);
-         String         primaryKey = context.pathParam("primaryKey");
          GetInput       getInput = new GetInput();
 
          setupSession(context, getInput);
+         QJavalinAccessLogger.logStart("get", logPair("table", tableName), logPair("primaryKey", primaryKey));
+
          getInput.setTableName(tableName);
          getInput.setShouldGenerateDisplayValues(true);
          getInput.setShouldTranslatePossibleValues(true);
@@ -638,10 +673,12 @@ public class QJavalinImplementation
                + table.getFields().get(table.getPrimaryKeyField()).getLabel() + " of " + primaryKey));
          }
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(getOutput.getRecord()));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          handleException(context, e);
       }
    }
@@ -662,15 +699,19 @@ public class QJavalinImplementation
     *******************************************************************************/
    static void dataCount(Context context)
    {
+      String table  = context.pathParam("table");
+      String filter = null;
+
       try
       {
          CountInput countInput = new CountInput();
          setupSession(context, countInput);
-         countInput.setTableName(context.pathParam("table"));
+         countInput.setTableName(table);
+         QJavalinAccessLogger.logStartSilent("count");
 
          PermissionsHelper.checkTablePermissionThrowing(countInput, TablePermissionSubType.READ);
 
-         String filter = stringQueryParam(context, "filter");
+         filter = stringQueryParam(context, "filter");
          if(!StringUtils.hasContent(filter))
          {
             filter = context.formParam("filter");
@@ -683,10 +724,12 @@ public class QJavalinImplementation
          CountAction countAction = new CountAction();
          CountOutput countOutput = countAction.execute(countInput);
 
+         QJavalinAccessLogger.logEndSuccessIfSlow(SLOW_LOG_THRESHOLD_MS, logPair("table", table), logPair("count", countOutput.getCount()), logPair("filter", filter));
          context.result(JsonUtils.toJson(countOutput));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e, logPair("table", table), logPair("filter", filter));
          handleException(context, e);
       }
    }
@@ -710,6 +753,7 @@ public class QJavalinImplementation
    static void dataQuery(Context context)
    {
       String table  = context.pathParam("table");
+      String filter = null;
 
       try
       {
@@ -725,7 +769,7 @@ public class QJavalinImplementation
 
          PermissionsHelper.checkTablePermissionThrowing(queryInput, TablePermissionSubType.READ);
 
-         String filter = stringQueryParam(context, "filter");
+         filter = stringQueryParam(context, "filter");
          if(!StringUtils.hasContent(filter))
          {
             filter = context.formParam("filter");
@@ -738,13 +782,12 @@ public class QJavalinImplementation
          QueryAction queryAction = new QueryAction();
          QueryOutput queryOutput = queryAction.execute(queryInput);
 
-         QJavalinAccessLogger.logEndSuccess(logPair("table", table), logPair("recordCount", queryOutput.getRecords().size()));
+         QJavalinAccessLogger.logEndSuccess(logPair("recordCount", queryOutput.getRecords().size()), logPairIfSlow("filter", filter, SLOW_LOG_THRESHOLD_MS));
-
          context.result(JsonUtils.toJson(queryOutput));
       }
       catch(Exception e)
       {
-         QJavalinAccessLogger.logEndFail(e, logPair("table", table));
+         QJavalinAccessLogger.logEndFail(e, logPair("filter", filter));
          handleException(context, e);
       }
    }
@@ -848,13 +891,15 @@ public class QJavalinImplementation
     *******************************************************************************/
    private static void widget(Context context)
    {
-      try
+      String widgetName = context.pathParam("name");
-      {
-         InsertInput insertInput = new InsertInput();
-         setupSession(context, insertInput);
 
       RenderWidgetInput input = new RenderWidgetInput()
-            .withWidgetMetaData(qInstance.getWidget(context.pathParam("name")));
+         .withWidgetMetaData(qInstance.getWidget(widgetName));
+
+      try
+      {
+         setupSession(context, input);
+         QJavalinAccessLogger.logStartSilent("widget");
 
          // todo permission?
 
@@ -872,10 +917,12 @@ public class QJavalinImplementation
          }
 
          RenderWidgetOutput output = new RenderWidgetAction().execute(input);
+         QJavalinAccessLogger.logEndSuccessIfSlow(SLOW_LOG_THRESHOLD_MS, logPair("widgetName", widgetName), logPair("inputParams", input.getQueryParams()));
          context.result(JsonUtils.toJson(output.getWidgetData()));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e, logPair("widgetName", widgetName), logPair("inputParams", input.getQueryParams()));
          handleException(context, e);
       }
    }
@@ -908,12 +955,13 @@ public class QJavalinImplementation
     *******************************************************************************/
    private static void dataExport(Context context, Optional<String> optionalFilename)
    {
+      String tableName = context.pathParam("table");
+
       try
       {
          //////////////////////////////////////////
          // read params from the request context //
          //////////////////////////////////////////
-         String  tableName = context.pathParam("table");
          String  format = context.queryParam("format");
          String  filter = context.queryParam("filter");
          Integer limit  = integerQueryParam(context, "limit");
@@ -931,6 +979,7 @@ public class QJavalinImplementation
          /////////////////////////////////////////////
          ExportInput exportInput = new ExportInput();
          setupSession(context, exportInput);
+
          exportInput.setTableName(tableName);
          exportInput.setReportFormat(reportFormat);
          exportInput.setFilename(filename);
@@ -949,7 +998,7 @@ public class QJavalinImplementation
             exportInput.setQueryFilter(JsonUtils.toObject(filter, QQueryFilter.class));
          }
 
-         UnsafeFunction<PipedOutputStream, ExportAction> preAction = (PipedOutputStream pos) ->
+         UnsafeFunction<PipedOutputStream, ExportAction, Exception> preAction = (PipedOutputStream pos) ->
          {
             exportInput.setReportOutputStream(pos);
 
@@ -958,9 +1007,19 @@ public class QJavalinImplementation
             return (exportAction);
          };
 
-         UnsafeConsumer<ExportAction> execute = (ExportAction exportAction) ->
+         UnsafeConsumer<ExportAction, Exception> execute = (ExportAction exportAction) ->
          {
-            exportAction.execute(exportInput);
+            QJavalinAccessLogger.logStart("export", logPair("table", tableName));
+            try
+            {
+               ExportOutput exportOutput = exportAction.execute(exportInput);
+               QJavalinAccessLogger.logEndSuccess(logPair("recordCount", exportOutput.getRecordCount()), logPairIfSlow("filter", filter, SLOW_LOG_THRESHOLD_MS));
+            }
+            catch(Exception e)
+            {
+               QJavalinAccessLogger.logEndFail(e, logPair("filter", filter));
+               throw (e);
+            }
          };
 
          runStreamedExportOrReport(context, reportFormat, filename, preAction, execute);
@@ -976,35 +1035,7 @@ public class QJavalinImplementation
    /*******************************************************************************
     **
     *******************************************************************************/
-   @FunctionalInterface
+   public static <T> void runStreamedExportOrReport(Context context, ReportFormat reportFormat, String filename, UnsafeFunction<PipedOutputStream, T, Exception> preAction, UnsafeConsumer<T, Exception> executor) throws Exception
-   public interface UnsafeFunction<T, R>
-   {
-      /*******************************************************************************
-       **
-       *******************************************************************************/
-      R run(T t) throws Exception;
-   }
-
-
-
-   /*******************************************************************************
-    **
-    *******************************************************************************/
-   @FunctionalInterface
-   public interface UnsafeConsumer<T>
-   {
-      /*******************************************************************************
-       **
-       *******************************************************************************/
-      void run(T t) throws Exception;
-   }
-
-
-
-   /*******************************************************************************
-    **
-    *******************************************************************************/
-   public static <T> void runStreamedExportOrReport(Context context, ReportFormat reportFormat, String filename, UnsafeFunction<PipedOutputStream, T> preAction, UnsafeConsumer<T> executor) throws Exception
    {
       ///////////////////////////////////////////////////////////////////////////////////////////////////////
       // set up the I/O pipe streams.                                                                      //
@@ -1015,7 +1046,7 @@ public class QJavalinImplementation
       PipedInputStream  pipedInputStream  = new PipedInputStream();
       pipedOutputStream.connect(pipedInputStream);
 
-      T t = preAction.run(pipedOutputStream);
+      T t = preAction.apply(pipedOutputStream);
 
       /////////////////////////////////////////////////////////////////////////////////////////////////////
       // start the async job.                                                                            //

qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinMetaData.java

@@ -29,6 +29,21 @@ public class QJavalinMetaData
 {
    private String uploadedFileArchiveTableName;
 
+   private boolean logAllAccessStarts = true;
+   private boolean logAllAccessEnds   = true;
+
+
+
+   /*******************************************************************************
+    ** Constructor
+    **
+    *******************************************************************************/
+   public QJavalinMetaData()
+   {
+      logAllAccessStarts = System.getProperty("qqq.javalin.logAllAccessStarts", "true").equals("true");
+      logAllAccessEnds = System.getProperty("qqq.javalin.logAllAccessEnds", "true").equals("true");
+   }
+
 
 
    /*******************************************************************************
@@ -63,4 +78,66 @@ public class QJavalinMetaData
       return (this);
    }
 
+
+
+   /*******************************************************************************
+    ** Getter for logAllAccessStarts
+    *******************************************************************************/
+   public boolean getLogAllAccessStarts()
+   {
+      return (this.logAllAccessStarts);
+   }
+
+
+
+   /*******************************************************************************
+    ** Setter for logAllAccessStarts
+    *******************************************************************************/
+   public void setLogAllAccessStarts(boolean logAllAccessStarts)
+   {
+      this.logAllAccessStarts = logAllAccessStarts;
+   }
+
+
+
+   /*******************************************************************************
+    ** Fluent setter for logAllAccessStarts
+    *******************************************************************************/
+   public QJavalinMetaData withLogAllAccessStarts(boolean logAllAccessStarts)
+   {
+      this.logAllAccessStarts = logAllAccessStarts;
+      return (this);
+   }
+
+
+
+   /*******************************************************************************
+    ** Getter for logAllAccessEnds
+    *******************************************************************************/
+   public boolean getLogAllAccessEnds()
+   {
+      return (this.logAllAccessEnds);
+   }
+
+
+
+   /*******************************************************************************
+    ** Setter for logAllAccessEnds
+    *******************************************************************************/
+   public void setLogAllAccessEnds(boolean logAllAccessEnds)
+   {
+      this.logAllAccessEnds = logAllAccessEnds;
+   }
+
+
+
+   /*******************************************************************************
+    ** Fluent setter for logAllAccessEnds
+    *******************************************************************************/
+   public QJavalinMetaData withLogAllAccessEnds(boolean logAllAccessEnds)
+   {
+      this.logAllAccessEnds = logAllAccessEnds;
+      return (this);
+   }
+
 }

qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinProcessHandler.java

@@ -24,7 +24,6 @@ package com.kingsrook.qqq.backend.javalin;
 
 import java.io.File;
 import java.io.FileInputStream;
-import java.io.FileNotFoundException;
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.PipedOutputStream;
@@ -56,6 +55,7 @@ import com.kingsrook.qqq.backend.core.exceptions.QModuleDispatchException;
 import com.kingsrook.qqq.backend.core.exceptions.QNotFoundException;
 import com.kingsrook.qqq.backend.core.exceptions.QPermissionDeniedException;
 import com.kingsrook.qqq.backend.core.exceptions.QUserFacingException;
+import com.kingsrook.qqq.backend.core.logging.QLogger;
 import com.kingsrook.qqq.backend.core.model.actions.AbstractActionInput;
 import com.kingsrook.qqq.backend.core.model.actions.processes.ProcessState;
 import com.kingsrook.qqq.backend.core.model.actions.processes.QUploadedFile;
@@ -79,14 +79,16 @@ import com.kingsrook.qqq.backend.core.state.UUIDAndTypeStateKey;
 import com.kingsrook.qqq.backend.core.utils.CollectionUtils;
 import com.kingsrook.qqq.backend.core.utils.ExceptionUtils;
 import com.kingsrook.qqq.backend.core.utils.JsonUtils;
-import com.kingsrook.qqq.backend.core.utils.QLogger;
 import com.kingsrook.qqq.backend.core.utils.StringUtils;
 import com.kingsrook.qqq.backend.core.utils.ValueUtils;
+import com.kingsrook.qqq.backend.core.utils.lambdas.UnsafeConsumer;
+import com.kingsrook.qqq.backend.core.utils.lambdas.UnsafeFunction;
 import io.javalin.apibuilder.EndpointGroup;
 import io.javalin.http.Context;
 import io.javalin.http.UploadedFile;
 import org.apache.commons.lang.NotImplementedException;
 import org.eclipse.jetty.http.HttpStatus;
+import static com.kingsrook.qqq.backend.core.logging.LogUtils.logPair;
 import static io.javalin.apibuilder.ApiBuilder.get;
 import static io.javalin.apibuilder.ApiBuilder.path;
 import static io.javalin.apibuilder.ApiBuilder.post;
@@ -230,7 +232,7 @@ public class QJavalinProcessHandler
             }
          }
 
-         QJavalinImplementation.UnsafeFunction<PipedOutputStream, GenerateReportAction> preAction = (PipedOutputStream pos) ->
+         UnsafeFunction<PipedOutputStream, GenerateReportAction, Exception> preAction = (PipedOutputStream pos) ->
          {
             reportInput.setReportOutputStream(pos);
 
@@ -239,9 +241,19 @@ public class QJavalinProcessHandler
             return (reportAction);
          };
 
-         QJavalinImplementation.UnsafeConsumer<GenerateReportAction> execute = (GenerateReportAction generateReportAction) ->
+         UnsafeConsumer<GenerateReportAction, Exception> execute = (GenerateReportAction generateReportAction) ->
+         {
+            QJavalinAccessLogger.logStart("report", logPair("reportName", reportName), logPair("format", reportFormat));
+            try
             {
                generateReportAction.execute(reportInput);
+               QJavalinAccessLogger.logEndSuccess();
+            }
+            catch(Exception e)
+            {
+               QJavalinAccessLogger.logEndFail(e);
+               throw (e);
+            }
          };
 
          QJavalinImplementation.runStreamedExportOrReport(context, reportFormat, filename, preAction, execute);
@@ -257,12 +269,20 @@ public class QJavalinProcessHandler
    /*******************************************************************************
     **
     *******************************************************************************/
-   private static void downloadFile(Context context) throws FileNotFoundException
+   private static void downloadFile(Context context)
    {
+      try
+      {
+         QJavalinImplementation.setupSession(context, new AbstractActionInput());
          // todo context.contentType(reportFormat.getMimeType());
          context.header("Content-Disposition", "filename=" + context.pathParam("file"));
          context.result(new FileInputStream(context.queryParam("filePath")));
       }
+      catch(Exception e)
+      {
+         QJavalinImplementation.handleException(context, e);
+      }
+   }
 
 
 
@@ -283,6 +303,7 @@ public class QJavalinProcessHandler
    private static void doProcessInitOrStep(Context context, String processUUID, String startAfterStep)
    {
       Map<String, Object> resultForCaller    = new HashMap<>();
+      Exception           returningException = null;
 
       try
       {
@@ -305,6 +326,11 @@ public class QJavalinProcessHandler
          runProcessInput.setStartAfterStep(startAfterStep);
          populateRunProcessRequestWithValuesFromContext(context, runProcessInput);
 
+         String reportName = ValueUtils.getValueAsString(runProcessInput.getValue("reportName"));
+         QJavalinAccessLogger.logStart(startAfterStep == null ? "processInit" : "processStep", logPair("processName", processName), logPair("processUUID", processUUID),
+            StringUtils.hasContent(startAfterStep) ? logPair("startAfterStep", startAfterStep) : null,
+            StringUtils.hasContent(reportName) ? logPair("reportName", reportName) : null);
+
          //////////////////////////////////////////////////////////////////////////////////////////////////
          // important to do this check AFTER the runProcessInput is populated with values from context - //
          // e.g., in case things like a reportName are set in here                                       //
@@ -328,6 +354,7 @@ public class QJavalinProcessHandler
          }
 
          serializeRunProcessResultForCaller(resultForCaller, runProcessOutput);
+         QJavalinAccessLogger.logProcessSummary(processName, processUUID, runProcessOutput);
       }
       catch(JobGoingAsyncException jgae)
       {
@@ -335,6 +362,7 @@ public class QJavalinProcessHandler
       }
       catch(QPermissionDeniedException pde)
       {
+         returningException = pde;
          QJavalinImplementation.handleException(context, pde);
       }
       catch(Exception e)
@@ -345,9 +373,19 @@ public class QJavalinProcessHandler
          // but - other process-step actions, they always return a 200, just with an //
          // optional error message - so - keep all of the processes consistent.      //
          //////////////////////////////////////////////////////////////////////////////
+         returningException = e;
          serializeRunProcessExceptionForCaller(resultForCaller, e);
       }
 
+      if(returningException != null)
+      {
+         QJavalinAccessLogger.logEndFail(returningException);
+      }
+      else
+      {
+         QJavalinAccessLogger.logEndSuccess();
+      }
+
       context.result(JsonUtils.toJson(resultForCaller));
    }
 
@@ -573,6 +611,7 @@ public class QJavalinProcessHandler
 
          // todo... get process values? PermissionsHelper.checkProcessPermissionThrowing(input, context.pathParam("processName"));
 
+         String processName = context.pathParam("processName");
          String processUUID = context.pathParam("processUUID");
          String jobUUID     = context.pathParam("jobUUID");
 
@@ -602,6 +641,7 @@ public class QJavalinProcessHandler
                {
                   RunProcessOutput runProcessOutput = new RunProcessOutput(processState.get());
                   serializeRunProcessResultForCaller(resultForCaller, runProcessOutput);
+                  QJavalinAccessLogger.logProcessSummary(processName, processUUID, runProcessOutput);
                }
                else
                {

qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinScriptsHandler.java

@@ -62,6 +62,7 @@ import com.kingsrook.qqq.backend.core.utils.CollectionUtils;
 import com.kingsrook.qqq.backend.core.utils.JsonUtils;
 import io.javalin.http.ContentType;
 import io.javalin.http.Context;
+import static com.kingsrook.qqq.backend.core.logging.LogUtils.logPair;
 import static io.javalin.apibuilder.ApiBuilder.get;
 import static io.javalin.apibuilder.ApiBuilder.post;
 
@@ -100,6 +101,7 @@ public class QJavalinScriptsHandler
          GetInput       getInput   = new GetInput();
 
          QJavalinImplementation.setupSession(context, getInput);
+         QJavalinAccessLogger.logStart("getRecordDeveloperMode", logPair("table", tableName), logPair("primaryKey", primaryKey));
          getInput.setTableName(tableName);
          getInput.setShouldGenerateDisplayValues(true);
          getInput.setShouldTranslatePossibleValues(true);
@@ -183,10 +185,12 @@ public class QJavalinScriptsHandler
             }
          }
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(rs));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          QJavalinImplementation.handleException(context, e);
       }
    }
@@ -226,6 +230,7 @@ public class QJavalinScriptsHandler
          getReferencedRecordToEnsureAccess(context);
 
          String scriptRevisionId = context.pathParam("scriptRevisionId");
+         QJavalinAccessLogger.logStart("getAssociatedScriptLogs", logPair("scriptRevisionId", scriptRevisionId));
 
          QueryInput queryInput = new QueryInput();
          QJavalinImplementation.setupSession(context, queryInput);
@@ -245,10 +250,12 @@ public class QJavalinScriptsHandler
          Map<String, Serializable> rs = new HashMap<>();
          rs.put("scriptLogRecords", new ArrayList<>(queryOutput.getRecords()));
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(rs));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          QJavalinImplementation.handleException(context, e);
       }
    }
@@ -301,11 +308,16 @@ public class QJavalinScriptsHandler
          StoreAssociatedScriptInput input = new StoreAssociatedScriptInput();
          QJavalinImplementation.setupSession(context, input);
 
+         String fieldName  = context.pathParam("fieldName");
+         String table      = context.pathParam("table");
+         String primaryKey = context.pathParam("primaryKey");
+
          input.setCode(context.formParam("contents"));
          input.setCommitMessage(context.formParam("commitMessage"));
-         input.setFieldName(context.pathParam("fieldName"));
+         input.setFieldName(fieldName);
-         input.setTableName(context.pathParam("table"));
+         input.setTableName(table);
-         input.setRecordPrimaryKey(context.pathParam("primaryKey"));
+         input.setRecordPrimaryKey(primaryKey);
+         QJavalinAccessLogger.logStart("storeRecordAssociatedScript", logPair("table", table), logPair("fieldName", fieldName), logPair("primaryKey", primaryKey));
 
          PermissionsHelper.checkTablePermissionThrowing(input, TablePermissionSubType.EDIT); // todo ... is this enough??
 
@@ -314,10 +326,12 @@ public class QJavalinScriptsHandler
          StoreAssociatedScriptAction storeAssociatedScriptAction = new StoreAssociatedScriptAction();
          storeAssociatedScriptAction.run(input, output);
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(output));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          QJavalinImplementation.handleException(context, e);
       }
    }
@@ -345,6 +359,7 @@ public class QJavalinScriptsHandler
          String         tableName = context.pathParam("table");
          String         fieldName = context.pathParam("fieldName");
          QTableMetaData table     = QJavalinImplementation.qInstance.getTable(tableName);
+         QJavalinAccessLogger.logStart("testAssociatedScript", logPair("table", tableName), logPair("fieldName", fieldName));
 
          Optional<AssociatedScript> optionalAssociatedScript = table.getAssociatedScripts().stream().filter(as -> as.getFieldName().equals(fieldName)).findFirst();
          if(optionalAssociatedScript.isEmpty())
@@ -378,10 +393,12 @@ public class QJavalinScriptsHandler
          TestScriptOutput          output       = new TestScriptOutput();
          scriptTester.execute(input, output);
 
+         QJavalinAccessLogger.logEndSuccess();
          context.result(JsonUtils.toJson(output));
       }
       catch(Exception e)
       {
+         QJavalinAccessLogger.logEndFail(e);
          QJavalinImplementation.handleException(context, e);
       }
    }