From 3f0e09e32a7c53dffb64a79549653842cc42f6fd Mon Sep 17 00:00:00 2001 From: Darin Kelkhoff Date: Wed, 18 Jan 2023 12:04:12 -0600 Subject: [PATCH] Adding javalin access logs --- .../backend/javalin/QJavalinAccessLogger.java | 335 ++++++++++++++++-- .../javalin/QJavalinImplementation.java | 163 +++++---- .../qqq/backend/javalin/QJavalinMetaData.java | 77 ++++ .../javalin/QJavalinProcessHandler.java | 60 +++- .../javalin/QJavalinScriptsHandler.java | 23 +- 5 files changed, 549 insertions(+), 109 deletions(-) diff --git a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinAccessLogger.java b/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinAccessLogger.java index bb943e62..3aee984d 100644 --- a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinAccessLogger.java +++ b/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinAccessLogger.java @@ -26,20 +26,32 @@ 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 { private static final QLogger LOG = QLogger.getLogger(QJavalinAccessLogger.class); - private static ThreadLocal requestStartTime = new ThreadLocal<>(); - private static ThreadLocal requestActionName = new ThreadLocal<>(); + private static ThreadLocal requestStartTime = new ThreadLocal<>(); + private static ThreadLocal requestActionName = new ThreadLocal<>(); + private static ThreadLocal requestLogPairs = new ThreadLocal<>(); @@ -48,12 +60,98 @@ public class QJavalinAccessLogger *******************************************************************************/ static void logStart(String actionName, LogPair... logPairs) { - requestStartTime.set(System.currentTimeMillis()); - requestActionName.set(actionName); - List pairList = new ArrayList<>(Arrays.asList(logPairs)); - pairList.add(0, logPair("access", "start")); - pairList.add(1, logPair("action", actionName)); - LOG.info(pairList); + try + { + 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 pairList = new ArrayList<>(Arrays.asList(logPairs)); + pairList.add(0, logPair("action", actionName)); + pairList.add(0, logPair("access", "start")); + 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) { - List pairList = new ArrayList<>(Arrays.asList(logPairs)); - pairList.add(0, logPair("access", "end-ok")); - accessLogEnd(pairList); + try + { + if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) + { + return; + } + + List pairList = new ArrayList<>(Arrays.asList(logPairs)); + logEnd("success", 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) { - List pairList = new ArrayList<>(Arrays.asList(logPairs)); - pairList.add(0, logPair("access", "end-fail")); - pairList.add(1, logPair("exceptionType", t.getClass().getSimpleName())); - pairList.add(2, logPair("exceptionMessage", t.getMessage())); - accessLogEnd(pairList); + try + { + if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) + { + return; + } + + List pairList = new ArrayList<>(Arrays.asList(logPairs)); + // pairList.add(0, logPair("exceptionMessage", t.getMessage())); + // pairList.add(0, logPair("exceptionType", t.getClass().getSimpleName())); + logEnd("failure", pairList); + } + catch(Exception e) + { + LOG.warn("Error in javalin access logger", e); + } } @@ -87,23 +207,178 @@ public class QJavalinAccessLogger /******************************************************************************* ** *******************************************************************************/ - private static void accessLogEnd(List pairList) + private static void logEnd(String accessType, List pairList) { - String actionName = requestActionName.get(); - requestActionName.remove(); - if(StringUtils.hasContent(actionName)) + try { - pairList.add(1, logPair("action", actionName)); - } + if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) + { + return; + } - Long startTime = requestStartTime.get(); - requestStartTime.remove(); - if(startTime != null) - { - long endTime = System.currentTimeMillis(); - pairList.add(logPair("millis", (endTime - startTime))); + 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(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(); + millis = endTime - startTime; + pairList.add(logPair("millis", millis)); + } + 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); } - LOG.info(pairList); } + + + /******************************************************************************* + ** + *******************************************************************************/ + 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 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 processSummaryLines = (List) runProcessOutput.getValues().get(StreamedETLWithFrontendProcess.FIELD_PROCESS_SUMMARY); + processSummaryListToLogPairs(logPairs, processSummaryLines); + } + else if(runProcessOutput.getValues().containsKey(StreamedETLWithFrontendProcess.FIELD_VALIDATION_SUMMARY)) + { + List processSummaryLines = (List) 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 logPairs, List 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; + } + } } diff --git a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinImplementation.java b/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinImplementation.java index ee12f229..92e9a1fa 100644 --- a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinImplementation.java +++ b/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 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 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 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(); + QTableMetaData table = qInstance.getTable(tableName); + 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); } } @@ -709,7 +752,8 @@ public class QJavalinImplementation *******************************************************************************/ static void dataQuery(Context context) { - String table = context.pathParam("table"); + 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) { + String widgetName = context.pathParam("name"); + + RenderWidgetInput input = new RenderWidgetInput() + .withWidgetMetaData(qInstance.getWidget(widgetName)); + try { - InsertInput insertInput = new InsertInput(); - setupSession(context, insertInput); - - RenderWidgetInput input = new RenderWidgetInput() - .withWidgetMetaData(qInstance.getWidget(context.pathParam("name"))); + 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,15 +955,16 @@ public class QJavalinImplementation *******************************************************************************/ private static void dataExport(Context context, Optional 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"); + String format = context.queryParam("format"); + String filter = context.queryParam("filter"); + Integer limit = integerQueryParam(context, "limit"); ReportFormat reportFormat = getReportFormat(context, optionalFilename, format); if(reportFormat == null) @@ -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 preAction = (PipedOutputStream pos) -> + UnsafeFunction preAction = (PipedOutputStream pos) -> { exportInput.setReportOutputStream(pos); @@ -958,9 +1007,19 @@ public class QJavalinImplementation return (exportAction); }; - UnsafeConsumer execute = (ExportAction exportAction) -> + UnsafeConsumer 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 interface UnsafeFunction - { - /******************************************************************************* - ** - *******************************************************************************/ - R run(T t) throws Exception; - } - - - - /******************************************************************************* - ** - *******************************************************************************/ - @FunctionalInterface - public interface UnsafeConsumer - { - /******************************************************************************* - ** - *******************************************************************************/ - void run(T t) throws Exception; - } - - - - /******************************************************************************* - ** - *******************************************************************************/ - public static void runStreamedExportOrReport(Context context, ReportFormat reportFormat, String filename, UnsafeFunction preAction, UnsafeConsumer executor) throws Exception + public static void runStreamedExportOrReport(Context context, ReportFormat reportFormat, String filename, UnsafeFunction preAction, UnsafeConsumer 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. // diff --git a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinMetaData.java b/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinMetaData.java index f383e236..06321225 100644 --- a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinMetaData.java +++ b/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); + } + } diff --git a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinProcessHandler.java b/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinProcessHandler.java index d32251b9..ccea9e19 100644 --- a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinProcessHandler.java +++ b/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 preAction = (PipedOutputStream pos) -> + UnsafeFunction preAction = (PipedOutputStream pos) -> { reportInput.setReportOutputStream(pos); @@ -239,9 +241,19 @@ public class QJavalinProcessHandler return (reportAction); }; - QJavalinImplementation.UnsafeConsumer execute = (GenerateReportAction generateReportAction) -> + UnsafeConsumer execute = (GenerateReportAction generateReportAction) -> { - generateReportAction.execute(reportInput); + 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,11 +269,19 @@ public class QJavalinProcessHandler /******************************************************************************* ** *******************************************************************************/ - private static void downloadFile(Context context) throws FileNotFoundException + private static void downloadFile(Context context) { - // todo context.contentType(reportFormat.getMimeType()); - context.header("Content-Disposition", "filename=" + context.pathParam("file")); - context.result(new FileInputStream(context.queryParam("filePath"))); + 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); + } } @@ -282,7 +302,8 @@ public class QJavalinProcessHandler *******************************************************************************/ private static void doProcessInitOrStep(Context context, String processUUID, String startAfterStep) { - Map resultForCaller = new HashMap<>(); + Map 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 { diff --git a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinScriptsHandler.java b/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinScriptsHandler.java index b4a7c616..fea2a6e4 100644 --- a/qqq-middleware-javalin/src/main/java/com/kingsrook/qqq/backend/javalin/QJavalinScriptsHandler.java +++ b/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 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.setTableName(context.pathParam("table")); - input.setRecordPrimaryKey(context.pathParam("primaryKey")); + input.setFieldName(fieldName); + input.setTableName(table); + 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 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); } }