Improve thread-safety of LogFileHandler

4 files changed, 58 insertions, 100 deletions

diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java
index 488a6137cc2..6b161406ebe 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogHandler.java
@@ -16,24 +16,12 @@ class AccessLogHandler {
     public AccessLogHandler(AccessLogConfig.FileHandler config) {
         access.setUseParentHandlers(false);
 
-        logFileHandler = new LogFileHandler(config.compressOnRotation());
-
-        logFileHandler.setFilePattern(config.pattern());
-        logFileHandler.setRotationTimes(config.rotation());
-
-        createSymlink(config, logFileHandler);
-
         LogFormatter lf = new LogFormatter();
         lf.messageOnly(true);
-        this.logFileHandler.setFormatter(lf);
+        logFileHandler = new LogFileHandler(config.compressOnRotation(), config.pattern(), config.rotation(), config.symlink(), lf);
         access.addHandler(this.logFileHandler);
     }
 
-    private void createSymlink(AccessLogConfig.FileHandler config, LogFileHandler handler) {
-        if (!config.symlink().isEmpty())
-            handler.setSymlinkName(config.symlink());
-    }
-
     public void shutdown() {
         logFileHandler.close();
         access.removeHandler(logFileHandler);
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogHandler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogHandler.java
index 1e64ac1618c..9515ef5f87e 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogHandler.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/ConnectionLogHandler.java
@@ -14,11 +14,14 @@ class ConnectionLogHandler {
     public ConnectionLogHandler(String clusterName) {
         connection.setUseParentHandlers(false);
 
-        logFileHandler = new LogFileHandler(true);
-        logFileHandler.setFilePattern(String.format("logs/vespa/qrs/connection.%s.%s", clusterName, "%Y%m%d%H%M%S"));
-
         LogFormatter lf = new LogFormatter();
         lf.messageOnly(true);
+        logFileHandler = new LogFileHandler(
+                true,
+                String.format("logs/vespa/qrs/connection.%s.%s", clusterName, "%Y%m%d%H%M%S"),
+                new long[]{0},
+                null,
+                lf);
         this.logFileHandler.setFormatter(lf);
         connection.addHandler(this.logFileHandler);
     }
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java
index 3c106e5cbf0..fa481e98870 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogFileHandler.java
@@ -17,6 +17,7 @@ import java.util.concurrent.ArrayBlockingQueue;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
 import java.util.concurrent.TimeUnit;
+import java.util.logging.Formatter;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
 import java.util.logging.Logger;
@@ -24,29 +25,29 @@ import java.util.logging.StreamHandler;
 import java.util.zip.GZIPOutputStream;
 
 /**
- * <p>Implements log file naming/rotating logic for container logs.</p>
- *
- * <p>Overridden methods: publish</p>
- *
- * <p>Added methods: setFilePattern, setRotationTimes, rotateNow (+ few others)</p>
+ * Implements log file naming/rotating logic for container logs.
  *
  * @author Bob Travis
+ * @author bjorncs
  */
 class LogFileHandler extends StreamHandler {
 
     private final static Logger logger = Logger.getLogger(LogFileHandler.class.getName());
+
     private final boolean compressOnRotation;
-    private long[] rotationTimes = {0}; //default to one log per day, at midnight
-    private String filePattern = "./log.%T";  // default to current directory, ms time stamp
-    private long nextRotationTime = 0;
-    private FileOutputStream currentOutputStream = null;
-    private volatile String fileName;
-    private String symlinkName = null;
-    private ArrayBlockingQueue<LogRecord> logQueue = new ArrayBlockingQueue<>(100000);
-    private LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow");
-    private ExecutorService executor = Executors.newCachedThreadPool(ThreadFactoryFactory.getDaemonThreadFactory("logfilehandler.compression"));
+    private final long[] rotationTimes;
+    private final String filePattern;  // default to current directory, ms time stamp
+    private final String symlinkName;
+    private final ArrayBlockingQueue<LogRecord> logQueue = new ArrayBlockingQueue<>(100000);
+    private final LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow");
+    private final ExecutorService executor = Executors.newCachedThreadPool(ThreadFactoryFactory.getDaemonThreadFactory("logfilehandler.compression"));
     private final NativeIO nativeIO = new NativeIO();
-    private long lastDropPosition = 0;
+    private final LogThread logThread;
+
+    private volatile FileOutputStream currentOutputStream = null;
+    private volatile long nextRotationTime = 0;
+    private volatile String fileName;
+    private volatile long lastDropPosition = 0;
 
     static private class LogThread extends Thread {
         LogFileHandler logFileHandler;
@@ -93,18 +94,25 @@ class LogFileHandler extends StreamHandler {
             }
         }
     }
-    private final LogThread logThread;
 
-    LogFileHandler() {
-        this(false);
+    LogFileHandler(boolean compressOnRotation, String filePattern, String rotationTimes, String symlinkName, Formatter formatter) {
+        this(compressOnRotation, filePattern, calcTimesMinutes(rotationTimes), symlinkName, formatter);
     }
 
-    LogFileHandler(boolean compressOnRotation)
-    {
+    LogFileHandler(
+            boolean compressOnRotation,
+            String filePattern,
+            long[] rotationTimes,
+            String symlinkName,
+            Formatter formatter) {
         super();
+        super.setFormatter(formatter);
         this.compressOnRotation = compressOnRotation;
-        logThread = new LogThread(this);
-        logThread.start();
+        this.filePattern = filePattern;
+        this.rotationTimes = rotationTimes;
+        this.symlinkName = (symlinkName != null && !symlinkName.isBlank()) ? symlinkName : null;
+        this.logThread = new LogThread(this);
+        this.logThread.start();
     }
 
     /**
@@ -151,33 +159,6 @@ class LogFileHandler extends StreamHandler {
     }
 
     /**
-     * Assign pattern for generating (rotating) file names.
-     *
-     * @param pattern See LogFormatter for definition
-     */
-    void setFilePattern ( String pattern ) {
-        filePattern = pattern;
-    }
-
-    /**
-     * Assign times for rotating output files.
-     *
-     * @param timesOfDay in millis, from midnight
-     *
-     */
-    void setRotationTimes ( long[] timesOfDay ) {
-        rotationTimes = timesOfDay;
-    }
-
-    /** Assign time for rotating output files
-     *
-     * @param prescription string form of times, in minutes
-     */
-    void setRotationTimes ( String prescription ) {
-        setRotationTimes(calcTimesMinutes(prescription));
-    }
-
-    /**
      * Find next rotation after specified time.
      *
      * @param now the specified time; if zero, current time is used.
@@ -369,10 +350,6 @@ class LogFileHandler extends StreamHandler {
         return time % lengthOfDayMillis;
     }
 
-    void setSymlinkName(String symlinkName) {
-        this.symlinkName = symlinkName;
-    }
-
     /**
      * Flushes all queued messages, interrupts the log thread in this and
      * waits for it to end before returning
diff --git a/jdisc_http_service/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java b/jdisc_http_service/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java
index bc7257b1ca9..19c5e69b257 100644
--- a/jdisc_http_service/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java
+++ b/jdisc_http_service/src/test/java/com/yahoo/container/logging/LogFileHandlerTestCase.java
@@ -36,22 +36,20 @@ public class LogFileHandlerTestCase {
     public void testIt() throws IOException {
         File root = temporaryFolder.newFolder("logfilehandlertest");
 
-        LogFileHandler h = new LogFileHandler();
-        h.setFilePattern(root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S");
-        h.setFormatter(new Formatter() {
-                public String format(LogRecord r) {
-                    DateFormat df = new SimpleDateFormat("yyyy.MM.dd:HH:mm:ss.SSS");
-                    String timeStamp = df.format(new Date(r.getMillis()));
-                    return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
-                }
-            } );
+        String pattern = root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S";
+        long[] rTimes = {1000, 2000, 10000};
+        Formatter formatter = new Formatter() {
+            public String format(LogRecord r) {
+                DateFormat df = new SimpleDateFormat("yyyy.MM.dd:HH:mm:ss.SSS");
+                String timeStamp = df.format(new Date(r.getMillis()));
+                return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
+            }
+        };
+        LogFileHandler h = new LogFileHandler(false, pattern, rTimes, null, formatter);
         long now = System.currentTimeMillis();
         long millisPerDay = 60*60*24*1000;
         long tomorrowDays = (now / millisPerDay) +1;
         long tomorrowMillis = tomorrowDays * millisPerDay;
-        assertThat(tomorrowMillis).isEqualTo(h.getNextRotationTime(now));
-        long[] rTimes = {1000, 2000, 10000};
-        h.setRotationTimes(rTimes);
         assertThat(tomorrowMillis+1000).isEqualTo(h.getNextRotationTime(tomorrowMillis));
         assertThat(tomorrowMillis+10000).isEqualTo(h.getNextRotationTime(tomorrowMillis+3000));
         LogRecord lr = new LogRecord(Level.INFO, "test");
@@ -68,10 +66,7 @@ public class LogFileHandlerTestCase {
         File logFile = temporaryFolder.newFile("testLogFileG1.txt");
 
       //create logfilehandler
-      LogFileHandler h = new LogFileHandler();
-      h.setFilePattern(logFile.getAbsolutePath());
-      h.setFormatter(new SimpleFormatter());
-      h.setRotationTimes("0 5 ...");
+      LogFileHandler h = new LogFileHandler(false, logFile.getAbsolutePath(), "0 5 ...", null, new SimpleFormatter());
 
       //write log
       LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileFirst1");
@@ -85,10 +80,7 @@ public class LogFileHandlerTestCase {
       File logFile = temporaryFolder.newFile("testLogFileG2.txt");
 
       //create logfilehandler
-      LogFileHandler h = new LogFileHandler();
-      h.setFilePattern(logFile.getAbsolutePath());
-      h.setFormatter(new SimpleFormatter());
-      h.setRotationTimes("0 5 ...");
+       LogFileHandler h = new LogFileHandler(false, logFile.getAbsolutePath(), "0 5 ...", null, new SimpleFormatter());
 
       //write log
       LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging1");
@@ -108,16 +100,15 @@ public class LogFileHandlerTestCase {
     @Test(timeout = /*5 minutes*/300_000)
     public void testSymlink() throws IOException, InterruptedException {
         File root = temporaryFolder.newFolder("testlogforsymlinkchecking");
-        LogFileHandler handler = new LogFileHandler();
-        handler.setFilePattern(root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s");
-        handler.setFormatter(new Formatter() {
+        Formatter formatter = new Formatter() {
             public String format(LogRecord r) {
                 DateFormat df = new SimpleDateFormat("yyyy.MM.dd:HH:mm:ss.SSS");
                 String timeStamp = df.format(new Date(r.getMillis()));
-                return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
+                return ("[" + timeStamp + "]" + " " + formatMessage(r) + "\n");
             }
-        } );
-        handler.setSymlinkName("symlink");
+        };
+        LogFileHandler handler = new LogFileHandler(
+                false, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink", formatter);
 
         handler.publish(new LogRecord(Level.INFO, "test"));
         String firstFile;
@@ -151,15 +142,14 @@ public class LogFileHandlerTestCase {
     public void testcompression() throws InterruptedException, IOException {
         File root = temporaryFolder.newFolder("testcompression");
 
-        LogFileHandler h = new LogFileHandler(true);
-        h.setFilePattern(root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s");
-        h.setFormatter(new Formatter() {
+        Formatter formatter = new Formatter() {
             public String format(LogRecord r) {
                 DateFormat df = new SimpleDateFormat("yyyy.MM.dd:HH:mm:ss.SSS");
                 String timeStamp = df.format(new Date(r.getMillis()));
-                return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
+                return ("[" + timeStamp + "]" + " " + formatMessage(r) + "\n");
             }
-        } );
+        };
+        LogFileHandler h = new LogFileHandler(true, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, null, formatter);
         int logEntries = 10000;
         for (int i = 0; i < logEntries; i++) {
             LogRecord lr = new LogRecord(Level.INFO, "test");