AbstractBufferedRollingFileAppender: Handle flush timeouts for log ev…

…ents with custom log levels (#24)

src/main/java/com/yscope/logging/log4j1/AbstractBufferedRollingFileAppender.java

@@ -176,6 +176,9 @@ public void setCloseOnShutdown (boolean closeOnShutdown) {
 
   /**
    * Sets the per-log-level hard timeouts for flushing.
+   * <p>
+   * NOTE: Timeouts for custom log-levels are not supported. Log events with
+   * these levels will be assigned the timeout of the INFO level.
    * @param csvTimeouts A CSV string of kv-pairs. The key being the log-level in
    * all caps and the value being the hard timeout for flushing in minutes. E.g.
    * "INFO=30,WARN=10,ERROR=5"
@@ -199,6 +202,9 @@ public void setFlushHardTimeoutsInMinutes (String csvTimeouts) {
 
   /**
    * Sets the per-log-level soft timeouts for flushing.
+   * <p>
+   * NOTE: Timeouts for custom log-levels are not supported. Log events with
+   * these levels will be assigned the timeout of the INFO level.
    * @param csvTimeouts A CSV string of kv-pairs. The key being the log-level in
    * all caps and the value being the soft timeout for flushing in seconds. E.g.
    * "INFO=180,WARN=15,ERROR=10"
@@ -514,11 +520,14 @@ private void resetFreshnessTimeouts () {
    */
   private void updateFreshnessTimeouts (LoggingEvent loggingEvent) {
     Level level = loggingEvent.getLevel();
-    long timeoutTimestamp = loggingEvent.timeStamp + flushHardTimeoutPerLevel.get(level);
+    long flushHardTimeout = flushHardTimeoutPerLevel.computeIfAbsent(level,
+        v -> flushHardTimeoutPerLevel.get(Level.INFO));
+    long timeoutTimestamp = loggingEvent.timeStamp + flushHardTimeout;
     flushHardTimeoutTimestamp = Math.min(flushHardTimeoutTimestamp, timeoutTimestamp);
 
-    flushMaximumSoftTimeout = Math.min(flushMaximumSoftTimeout,
-                                       flushSoftTimeoutPerLevel.get(level));
+    long flushSoftTimeout = flushSoftTimeoutPerLevel.computeIfAbsent(level,
+        v -> flushSoftTimeoutPerLevel.get(Level.INFO));
+    flushMaximumSoftTimeout = Math.min(flushMaximumSoftTimeout, flushSoftTimeout);
     flushSoftTimeoutTimestamp = loggingEvent.timeStamp + flushMaximumSoftTimeout;
   }
 

src/test/java/com/yscope/logging/log4j1/TestRollingFileLogAppender.java

@@ -193,6 +193,22 @@ public void testSoftTimeout () {
     validateNumSyncAndCloseEvents(appender, expectedNumSyncs, expectedNumRollovers);
   }
 
+  /**
+   * Tests custom log levels with the hard timeouts
+   */
+  @Test
+  public void testCustomLogLevelsWithHardTimeout () {
+    validateFlushTimeoutSupportForCustomLogLevels(false);
+  }
+
+  /**
+   * Tests custom log levels with the soft timeouts
+   */
+  @Test
+  public void testCustomLogLevelWithSoftTimeout () {
+    validateFlushTimeoutSupportForCustomLogLevels(true);
+  }
+
   /**
    * Tests closing the appender with different closeOnShutdown settings
    */
@@ -265,6 +281,37 @@ private void validateBasicFlushTimeoutSupport (boolean testSoftTimeout) {
     validateNumSyncAndCloseEvents(appender, expectedNumSyncs, expectedNumRollovers);
   }
 
+  /**
+   * Performs basic validation of flush timeout support for custom log levels
+   * (not specific to either soft/hard timeouts)
+   * @param testSoftTimeout Whether to test soft (true) or hard (false) timeout
+   * support
+   */
+  private void validateFlushTimeoutSupportForCustomLogLevels (boolean testSoftTimeout) {
+    int timeoutUnitInMilliseconds =
+        testSoftTimeout ? flushSoftTimeoutUnitInMilliseconds : flushHardTimeoutUnitInMilliseconds;
+    RollingFileTestAppender appender =
+        createTestAppender(false == testSoftTimeout, testSoftTimeout);
+    appender.activateOptions();
+    int expectedNumSyncs = 0;
+    int expectedNumRollovers = 0;
+    int currentTimestamp = 0;
+
+    // Verify an event with a custom log level can be handled and is assigned
+    // the INFO level timeout
+    appendLogEvent(currentTimestamp, new CustomLog4jLogLevel(Level.DEBUG_INT + 1, "DEBUG1",
+                                                             Level.DEBUG.getSyslogEquivalent()),
+                   appender);
+    currentTimestamp += flushInfoLevelTimeout * timeoutUnitInMilliseconds;
+    ++expectedNumSyncs;
+    validateSyncAfterTimeout(currentTimestamp, expectedNumSyncs, expectedNumRollovers, appender);
+
+    // Verify a rollover after closing the appender
+    appender.close();
+    ++expectedNumRollovers;
+    validateNumSyncAndCloseEvents(appender, expectedNumSyncs, expectedNumRollovers);
+  }
+
   /**
    * Validates the flush and sync logic when the appender is closed
    * @param closeOnShutdown The value of closeOnShutdown to use when validating
@@ -487,3 +534,12 @@ private RollingFileTestAppender createTestAppender (boolean disableSoftTimeout,
     return appender;
   }
 }
+
+/**
+ * A custom Log4j Level class used for testing log events with custom log levels
+ */
+class CustomLog4jLogLevel extends Level {
+  public CustomLog4jLogLevel (int level, String levelStr, int syslogEquivalent) {
+    super(level, levelStr, syslogEquivalent);
+  }
+}