More control options around javalin access logging

This commit is contained in:
2023-06-05 14:49:01 -05:00
parent f1ebff28eb
commit c91a678905
3 changed files with 238 additions and 49 deletions

View File

@ -38,8 +38,11 @@ import static com.kingsrook.qqq.backend.core.logging.LogUtils.logPair;
/******************************************************************************* /*******************************************************************************
** Access-Logger used for QJavalin handlers. ** Access-Logger used for QJavalin handlers.
** **
** Can be disabled through the JavalinMetaData in the QJavalinImplementation - ** Can be fully disabled through the JavalinMetaData object, or via system property:
** See one of those 2 places for details (e.g., system properties). ** qqq.javalin.loggerDisabled
*
** Alternatively, individual log types and even actions can be enabled or disabled
** via the logFilter in JavalinMetaData.
** **
** Note - when working in this class - be overly aggressive with wrapping ** Note - when working in this class - be overly aggressive with wrapping
** everything in try-catch, and not allowing exceptions to bubble. There isn't ** everything in try-catch, and not allowing exceptions to bubble. There isn't
@ -49,12 +52,38 @@ public class QJavalinAccessLogger
{ {
private static final QLogger LOG = QLogger.getLogger(QJavalinAccessLogger.class); private static final QLogger LOG = QLogger.getLogger(QJavalinAccessLogger.class);
public static final String DISABLED_PROPERTY = "qqq.javalin.loggerDisabled";
private static ThreadLocal<Long> requestStartTime = new ThreadLocal<>(); private static ThreadLocal<Long> requestStartTime = new ThreadLocal<>();
private static ThreadLocal<String> requestActionName = new ThreadLocal<>(); private static ThreadLocal<String> requestActionName = new ThreadLocal<>();
private static ThreadLocal<LogPair[]> requestLogPairs = new ThreadLocal<>(); private static ThreadLocal<LogPair[]> requestLogPairs = new ThreadLocal<>();
/*******************************************************************************
** Types of log entries - useful for a filter (from javalin meta data).
*******************************************************************************/
public enum LogType
{
START,
END_SUCCESS,
END_SUCCESS_SLOW,
END_FAIL,
PROCESS_SUMMARY
}
/*******************************************************************************
** input to filter method (from javalin meta data), to decide if entry should be logged.
*******************************************************************************/
public record LogEntry(LogType logType, String actionName)
{
}
/******************************************************************************* /*******************************************************************************
** **
*******************************************************************************/ *******************************************************************************/
@ -62,7 +91,7 @@ public class QJavalinAccessLogger
{ {
try try
{ {
if(!QJavalinImplementation.javalinMetaData.getLogAllAccessStarts() && !QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) if(isLoggerDisabled())
{ {
///////////////////////////////////////////////////// /////////////////////////////////////////////////////
// if we're not to log starts or ends, just return // // if we're not to log starts or ends, just return //
@ -72,11 +101,12 @@ public class QJavalinAccessLogger
setThreadLocals(actionName, logPairs); 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"));
if(shouldLog(new LogEntry(LogType.START, actionName)))
{ {
List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs));
pairList.add(0, logPair("action", actionName));
pairList.add(0, logPair("access", "start"));
LOG.info(pairList); LOG.info(pairList);
} }
} }
@ -88,6 +118,49 @@ public class QJavalinAccessLogger
/*******************************************************************************
**
*******************************************************************************/
private static boolean shouldLog(LogEntry logEntry)
{
if(isLoggerDisabled())
{
return (false);
}
if(QJavalinImplementation.javalinMetaData != null && QJavalinImplementation.javalinMetaData.getLogFilter() != null)
{
return (QJavalinImplementation.javalinMetaData.getLogFilter().apply(logEntry));
}
return (true);
}
/*******************************************************************************
**
*******************************************************************************/
private static boolean isLoggerDisabled()
{
/////////////////////////////////////////////////////////////////////////////////////
// if there's no javalin metadata, then just read the disabled property ourselves, //
// and be disabled iff the property value is "true" //
/////////////////////////////////////////////////////////////////////////////////////
if(QJavalinImplementation.javalinMetaData == null)
{
return System.getProperty(QJavalinAccessLogger.DISABLED_PROPERTY, "false").equals("true");
}
///////////////////////////////////////////////////////////////////////////////////////////////////
// else, there is javalinMetaData, then let IT say if we're disabled. //
// note that will use the same system property by default, but it may be overridden via app code //
///////////////////////////////////////////////////////////////////////////////////////////////////
return QJavalinImplementation.javalinMetaData.getLoggerDisabled();
}
/******************************************************************************* /*******************************************************************************
** **
*******************************************************************************/ *******************************************************************************/
@ -105,10 +178,7 @@ public class QJavalinAccessLogger
{ {
try try
{ {
//////////////////////////////////////////////////////// if(!isLoggerDisabled())
// only set the thread locals if we're doing log-ends //
////////////////////////////////////////////////////////
if(QJavalinImplementation.javalinMetaData.getLogAllAccessEnds())
{ {
requestActionName.set(actionName); requestActionName.set(actionName);
requestStartTime.set(System.currentTimeMillis()); requestStartTime.set(System.currentTimeMillis());
@ -130,7 +200,7 @@ public class QJavalinAccessLogger
{ {
try try
{ {
if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) if(isLoggerDisabled())
{ {
return; return;
} }
@ -145,7 +215,7 @@ public class QJavalinAccessLogger
if(millis != null && millis > slowThreshold) if(millis != null && millis > slowThreshold)
{ {
logEnd("success", new ArrayList<>(Arrays.asList(logPairs))); logEnd(LogType.END_SUCCESS_SLOW, "success", new ArrayList<>(Arrays.asList(logPairs)));
} }
} }
catch(Exception e) catch(Exception e)
@ -163,13 +233,13 @@ public class QJavalinAccessLogger
{ {
try try
{ {
if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) if(isLoggerDisabled())
{ {
return; return;
} }
List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs)); List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs));
logEnd("success", pairList); logEnd(LogType.END_SUCCESS, "success", pairList);
} }
catch(Exception e) catch(Exception e)
{ {
@ -186,7 +256,7 @@ public class QJavalinAccessLogger
{ {
try try
{ {
if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) if(isLoggerDisabled())
{ {
return; return;
} }
@ -194,7 +264,7 @@ public class QJavalinAccessLogger
List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs)); List<LogPair> pairList = new ArrayList<>(Arrays.asList(logPairs));
// pairList.add(0, logPair("exceptionMessage", t.getMessage())); // pairList.add(0, logPair("exceptionMessage", t.getMessage()));
// pairList.add(0, logPair("exceptionType", t.getClass().getSimpleName())); // pairList.add(0, logPair("exceptionType", t.getClass().getSimpleName()));
logEnd("failure", pairList); logEnd(LogType.END_FAIL, "failure", pairList);
} }
catch(Exception e) catch(Exception e)
{ {
@ -207,11 +277,11 @@ public class QJavalinAccessLogger
/******************************************************************************* /*******************************************************************************
** **
*******************************************************************************/ *******************************************************************************/
private static void logEnd(String accessType, List<LogPair> pairList) private static void logEnd(LogType logType, String accessType, List<LogPair> pairList)
{ {
try try
{ {
if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) if(isLoggerDisabled())
{ {
return; return;
} }
@ -266,7 +336,10 @@ public class QJavalinAccessLogger
return (false); return (false);
}); });
LOG.info(pairList); if(shouldLog(new LogEntry(logType, actionName)))
{
LOG.info(pairList);
}
} }
catch(Exception e) catch(Exception e)
{ {
@ -293,7 +366,7 @@ public class QJavalinAccessLogger
{ {
try try
{ {
if(!QJavalinImplementation.javalinMetaData.getLogAllAccessEnds()) if(isLoggerDisabled())
{ {
return; return;
} }
@ -325,7 +398,7 @@ public class QJavalinAccessLogger
} }
} }
logEnd("processSummary", logPairs); logEnd(LogType.PROCESS_SUMMARY, "processSummary", logPairs);
} }
catch(Exception e) catch(Exception e)
{ {

View File

@ -22,6 +22,9 @@
package com.kingsrook.qqq.backend.javalin; package com.kingsrook.qqq.backend.javalin;
import java.util.function.Function;
/******************************************************************************* /*******************************************************************************
** MetaData specific to a QQQ Javalin server. ** MetaData specific to a QQQ Javalin server.
*******************************************************************************/ *******************************************************************************/
@ -29,8 +32,9 @@ public class QJavalinMetaData
{ {
private String uploadedFileArchiveTableName; private String uploadedFileArchiveTableName;
private boolean logAllAccessStarts = true; private boolean loggerDisabled = false;
private boolean logAllAccessEnds = true;
private Function<QJavalinAccessLogger.LogEntry, Boolean> logFilter;
@ -40,8 +44,7 @@ public class QJavalinMetaData
*******************************************************************************/ *******************************************************************************/
public QJavalinMetaData() public QJavalinMetaData()
{ {
logAllAccessStarts = System.getProperty("qqq.javalin.logAllAccessStarts", "true").equals("true"); loggerDisabled = System.getProperty(QJavalinAccessLogger.DISABLED_PROPERTY, "false").equals("true");
logAllAccessEnds = System.getProperty("qqq.javalin.logAllAccessEnds", "true").equals("true");
} }
@ -81,62 +84,62 @@ public class QJavalinMetaData
/******************************************************************************* /*******************************************************************************
** Getter for logAllAccessStarts ** Getter for loggerDisabled
*******************************************************************************/ *******************************************************************************/
public boolean getLogAllAccessStarts() public boolean getLoggerDisabled()
{ {
return (this.logAllAccessStarts); return (this.loggerDisabled);
} }
/******************************************************************************* /*******************************************************************************
** Setter for logAllAccessStarts ** Setter for loggerDisabled
*******************************************************************************/ *******************************************************************************/
public void setLogAllAccessStarts(boolean logAllAccessStarts) public void setLoggerDisabled(boolean loggerDisabled)
{ {
this.logAllAccessStarts = logAllAccessStarts; this.loggerDisabled = loggerDisabled;
} }
/******************************************************************************* /*******************************************************************************
** Fluent setter for logAllAccessStarts ** Fluent setter for loggerDisabled
*******************************************************************************/ *******************************************************************************/
public QJavalinMetaData withLogAllAccessStarts(boolean logAllAccessStarts) public QJavalinMetaData withLoggerDisabled(boolean loggerDisabled)
{ {
this.logAllAccessStarts = logAllAccessStarts; this.loggerDisabled = loggerDisabled;
return (this); return (this);
} }
/******************************************************************************* /*******************************************************************************
** Getter for logAllAccessEnds ** Getter for logFilter
*******************************************************************************/ *******************************************************************************/
public boolean getLogAllAccessEnds() public Function<QJavalinAccessLogger.LogEntry, Boolean> getLogFilter()
{ {
return (this.logAllAccessEnds); return (this.logFilter);
} }
/******************************************************************************* /*******************************************************************************
** Setter for logAllAccessEnds ** Setter for logFilter
*******************************************************************************/ *******************************************************************************/
public void setLogAllAccessEnds(boolean logAllAccessEnds) public void setLogFilter(Function<QJavalinAccessLogger.LogEntry, Boolean> logFilter)
{ {
this.logAllAccessEnds = logAllAccessEnds; this.logFilter = logFilter;
} }
/******************************************************************************* /*******************************************************************************
** Fluent setter for logAllAccessEnds ** Fluent setter for logFilter
*******************************************************************************/ *******************************************************************************/
public QJavalinMetaData withLogAllAccessEnds(boolean logAllAccessEnds) public QJavalinMetaData withLogFilter(Function<QJavalinAccessLogger.LogEntry, Boolean> logFilter)
{ {
this.logAllAccessEnds = logAllAccessEnds; this.logFilter = logFilter;
return (this); return (this);
} }

View File

@ -34,41 +34,152 @@ import com.kingsrook.qqq.backend.core.model.metadata.QInstance;
import com.kingsrook.qqq.backend.core.processes.implementations.etl.streamedwithfrontend.StreamedETLWithFrontendProcess; import com.kingsrook.qqq.backend.core.processes.implementations.etl.streamedwithfrontend.StreamedETLWithFrontendProcess;
import com.kingsrook.qqq.backend.core.utils.SleepUtils; import com.kingsrook.qqq.backend.core.utils.SleepUtils;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import static com.kingsrook.qqq.backend.javalin.QJavalinAccessLogger.DISABLED_PROPERTY;
/******************************************************************************* /*******************************************************************************
** Unit test for QJavalinAccessLogger ** Unit test for QJavalinAccessLogger
**
** Note - we're not injecting any kind of logger mock, so we aren't making any
** assertions here - we're just verifying we don't blow up - other than that,
** manually verify results by reviewing log
*******************************************************************************/ *******************************************************************************/
class QJavalinAccessLoggerTest class QJavalinAccessLoggerTest
{ {
/******************************************************************************* /*******************************************************************************
** **
*******************************************************************************/ *******************************************************************************/
@Test @Test
void testTurnedOff() throws QInstanceValidationException void testDefaultOn() throws QInstanceValidationException
{ {
QInstance qInstance = TestUtils.defineInstance(); QInstance qInstance = TestUtils.defineInstance();
new QJavalinImplementation(qInstance, new QJavalinMetaData() new QJavalinImplementation(qInstance, new QJavalinMetaData());
.withLogAllAccessStarts(false)
.withLogAllAccessEnds(false));
System.out.println("All should log");
QJavalinAccessLogger.logStart("test"); QJavalinAccessLogger.logStart("test");
QJavalinAccessLogger.logEndSuccess(); QJavalinAccessLogger.logEndSuccess();
QJavalinAccessLogger.logEndFail(new Exception()); QJavalinAccessLogger.logEndFail(new Exception());
QJavalinAccessLogger.logEndSuccessIfSlow(1000);
QJavalinAccessLogger.logStart("testSlow");
QJavalinAccessLogger.logEndSuccessIfSlow(-1);
QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), new RunProcessOutput()); QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), new RunProcessOutput());
} }
/*******************************************************************************
**
*******************************************************************************/
@Test
void testTurnedOffByCode() throws QInstanceValidationException
{
QInstance qInstance = TestUtils.defineInstance();
new QJavalinImplementation(qInstance, new QJavalinMetaData()
.withLoggerDisabled(true));
System.out.println("Nothing should log");
QJavalinAccessLogger.logStart("test");
QJavalinAccessLogger.logEndSuccess();
QJavalinAccessLogger.logEndFail(new Exception());
QJavalinAccessLogger.logStart("testSlow");
QJavalinAccessLogger.logEndSuccessIfSlow(-1);
QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), new RunProcessOutput());
}
/*******************************************************************************
**
*******************************************************************************/
@Test
void testTurnedOffBySystemPropertyWithJavalinMetaData() throws QInstanceValidationException
{
System.setProperty(DISABLED_PROPERTY, "true");
QInstance qInstance = TestUtils.defineInstance();
new QJavalinImplementation(qInstance, new QJavalinMetaData());
System.out.println("shouldn't log");
QJavalinAccessLogger.logStart("test");
System.clearProperty(DISABLED_PROPERTY);
}
/*******************************************************************************
**
*******************************************************************************/
@Test
void testTurnedOffBySystemPropertyWithoutJavalinMetaData() throws QInstanceValidationException
{
System.setProperty(DISABLED_PROPERTY, "true");
QInstance qInstance = TestUtils.defineInstance();
new QJavalinImplementation(qInstance);
System.out.println("shouldn't log");
QJavalinAccessLogger.logStart("test");
System.clearProperty(DISABLED_PROPERTY);
}
/*******************************************************************************
**
*******************************************************************************/
@Test
void testFilter() throws QInstanceValidationException
{
QInstance qInstance = TestUtils.defineInstance();
new QJavalinImplementation(qInstance, new QJavalinMetaData()
.withLoggerDisabled(false)
.withLogFilter(logEntry ->
switch(logEntry.logType())
{
case START, PROCESS_SUMMARY -> false;
case END_SUCCESS, END_SUCCESS_SLOW -> true;
case END_FAIL -> logEntry.actionName().startsWith("yes");
}));
System.out.println("shouldn't log");
QJavalinAccessLogger.logStart("test"); // shouldn't log
System.out.println("should log");
QJavalinAccessLogger.logEndSuccess(); // SHOULD log
System.out.println("shouldn't log");
QJavalinAccessLogger.logStart("no"); // shouldn't log
System.out.println("shouldn't log");
QJavalinAccessLogger.logEndFail(new Exception()); // shouldn't log
System.out.println("shouldn't log");
QJavalinAccessLogger.logStart("yes"); // shouldn't log
System.out.println("should log");
QJavalinAccessLogger.logEndFail(new Exception()); // SHOULD log
System.out.println("shouldn't log");
QJavalinAccessLogger.logStart("testSlow"); // shouldn't log
System.out.println("should log");
QJavalinAccessLogger.logEndSuccessIfSlow(-1); // SHOULD log
System.out.println("shouldn't log");
QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), new RunProcessOutput()); // shouldn't log
}
/******************************************************************************* /*******************************************************************************
** **
*******************************************************************************/ *******************************************************************************/
@Test @Test
void testSlow() void testSlow()
{ {
System.out.println("should log");
QJavalinAccessLogger.logStart("test"); QJavalinAccessLogger.logStart("test");
System.out.println("should log");
SleepUtils.sleep(2, TimeUnit.MILLISECONDS); SleepUtils.sleep(2, TimeUnit.MILLISECONDS);
QJavalinAccessLogger.logEndSuccessIfSlow(1); QJavalinAccessLogger.logEndSuccessIfSlow(1);
} }
@ -85,12 +196,14 @@ class QJavalinAccessLoggerTest
runProcessOutput.addValue(StreamedETLWithFrontendProcess.FIELD_VALIDATION_SUMMARY, new ArrayList<>(List.of( runProcessOutput.addValue(StreamedETLWithFrontendProcess.FIELD_VALIDATION_SUMMARY, new ArrayList<>(List.of(
new ProcessSummaryLine(Status.OK, 5, "Test") new ProcessSummaryLine(Status.OK, 5, "Test")
))); )));
System.out.println("should log");
QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), runProcessOutput); QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), runProcessOutput);
runProcessOutput = new RunProcessOutput(); runProcessOutput = new RunProcessOutput();
runProcessOutput.addValue(StreamedETLWithFrontendProcess.FIELD_PROCESS_SUMMARY, new ArrayList<>(List.of( runProcessOutput.addValue(StreamedETLWithFrontendProcess.FIELD_PROCESS_SUMMARY, new ArrayList<>(List.of(
new ProcessSummaryLine(Status.OK, 5, "Test") new ProcessSummaryLine(Status.OK, 5, "Test")
))); )));
System.out.println("should log");
QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), runProcessOutput); QJavalinAccessLogger.logProcessSummary("testProcess", UUID.randomUUID().toString(), runProcessOutput);
} }