Revert "Remove locks in access logging [run-systemtest]"

7 files changed, 45 insertions, 76 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 08be5f2613e..14236452ac0 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
@@ -3,22 +3,23 @@ package com.yahoo.container.logging;
 
 import com.yahoo.container.core.AccessLogConfig;
 
-import java.util.logging.Level;
-import java.util.logging.LogRecord;
+import java.util.logging.Logger;
 
 /**
  * @author Bjorn Borud
  */
 class AccessLogHandler {
 
+    public final Logger access = Logger.getAnonymousLogger();
     private final LogFileHandler logFileHandler;
 
     AccessLogHandler(AccessLogConfig.FileHandler config) {
-        logFileHandler = new LogFileHandler(toCompression(config), config.pattern(), config.rotation(), config.symlink());
-    }
+        access.setUseParentHandlers(false);
 
-    public void log(String message) {
-        logFileHandler.publish(new LogRecord(Level.INFO, message));
+        LogFormatter lf = new LogFormatter();
+        lf.messageOnly(true);
+        logFileHandler = new LogFileHandler(toCompression(config), config.pattern(), config.rotation(), config.symlink(), lf);
+        access.addHandler(this.logFileHandler);
     }
 
     private LogFileHandler.Compression toCompression(AccessLogConfig.FileHandler config) {
@@ -32,6 +33,7 @@ class AccessLogHandler {
 
     void shutdown() {
         logFileHandler.close();
+        access.removeHandler(logFileHandler);
 
         if (logFileHandler!=null)
             logFileHandler.shutdown();
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 82a84200f10..c2013aeb128 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
@@ -2,30 +2,33 @@
 
 package com.yahoo.container.logging;
 
-import java.util.logging.Level;
-import java.util.logging.LogRecord;
 import java.util.logging.Logger;
 
 /**
  * @author mortent
  */
 class ConnectionLogHandler {
+    public final Logger connection = Logger.getAnonymousLogger();
     private final LogFileHandler logFileHandler;
 
     public ConnectionLogHandler(String clusterName) {
+        connection.setUseParentHandlers(false);
+
+        LogFormatter lf = new LogFormatter();
+        lf.messageOnly(true);
         logFileHandler = new LogFileHandler(
                 LogFileHandler.Compression.ZSTD,
                 String.format("logs/vespa/qrs/ConnectionLog.%s.%s", clusterName, "%Y%m%d%H%M%S"),
                 "0 60 ...",
-                String.format("ConnectionLog.%s", clusterName));
-    }
-
-    public void log(String message) {
-        logFileHandler.publish(new LogRecord(Level.INFO, message));
+                String.format("ConnectionLog.%s", clusterName),
+                lf);
+        this.logFileHandler.setFormatter(lf);
+        connection.addHandler(this.logFileHandler);
     }
 
     public void shutdown() {
         logFileHandler.close();
+        connection.removeHandler(logFileHandler);
         logFileHandler.shutdown();
     }
-}
+}
\ No newline at end of file
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/FileConnectionLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/FileConnectionLog.java
index 0b9e2e4a778..f7f4e1e8ed3 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/FileConnectionLog.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/FileConnectionLog.java
@@ -24,7 +24,7 @@ public class FileConnectionLog extends AbstractComponent implements ConnectionLo
     @Override
     public void log(ConnectionLogEntry connectionLogEntry) {
         try {
-            logHandler.log(connectionLogEntry.toJson()+ '\n');
+            logHandler.connection.log(Level.INFO, connectionLogEntry.toJson()+ '\n');
         } catch (Exception e) {
             logger.log(Level.WARNING, "Unable to write connection log entry for connection id " + connectionLogEntry.id(), e);
         }
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java
index 6fc4e886ec5..aa2df959a4c 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java
@@ -3,6 +3,8 @@ package com.yahoo.container.logging;
 
 import com.yahoo.container.core.AccessLogConfig;
 
+import java.util.logging.Level;
+
 /**
  * Log a message in Vespa JSON access log format.
  *
@@ -21,7 +23,7 @@ public final class JSONAccessLog implements RequestLogHandler {
 
     @Override
     public void log(RequestLogEntry entry) {
-        logHandler.log(formatter.format(entry) + '\n');
+        logHandler.access.log(Level.INFO, formatter.format(entry) + '\n');
     }
 
     // TODO: This is never called. We should have a DI provider and call this method from its deconstruct.
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 58a324b7f26..5b30ffbe363 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
@@ -13,11 +13,6 @@ import java.io.FileInputStream;
 import java.io.FileOutputStream;
 import java.io.IOException;
 import java.io.InputStream;
-import java.io.OutputStream;
-import java.io.OutputStreamWriter;
-import java.io.UnsupportedEncodingException;
-import java.io.Writer;
-import java.nio.charset.StandardCharsets;
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.nio.file.Paths;
@@ -27,7 +22,6 @@ import java.util.concurrent.ArrayBlockingQueue;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
 import java.util.concurrent.TimeUnit;
-import java.util.logging.ErrorManager;
 import java.util.logging.Formatter;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
@@ -41,7 +35,7 @@ import java.util.zip.GZIPOutputStream;
  * @author Bob Travis
  * @author bjorncs
  */
-class LogFileHandler {
+class LogFileHandler extends StreamHandler {
 
     enum Compression { NONE, GZIP, ZSTD }
 
@@ -62,8 +56,6 @@ class LogFileHandler {
     private volatile String fileName;
     private volatile long lastDropPosition = 0;
 
-    private volatile Writer writer;
-
     static private class LogThread extends Thread {
         LogFileHandler logFileHandler;
         long lastFlush = 0;
@@ -110,15 +102,18 @@ class LogFileHandler {
         }
     }
 
-    LogFileHandler(Compression compression, String filePattern, String rotationTimes, String symlinkName) {
-        this(compression, filePattern, calcTimesMinutes(rotationTimes), symlinkName);
+    LogFileHandler(Compression compression, String filePattern, String rotationTimes, String symlinkName, Formatter formatter) {
+        this(compression, filePattern, calcTimesMinutes(rotationTimes), symlinkName, formatter);
     }
 
     LogFileHandler(
             Compression compression,
             String filePattern,
             long[] rotationTimes,
-            String symlinkName) {
+            String symlinkName,
+            Formatter formatter) {
+        super();
+        super.setFormatter(formatter);
         this.compression = compression;
         this.filePattern = filePattern;
         this.rotationTimes = rotationTimes;
@@ -132,6 +127,7 @@ class LogFileHandler {
      *
      * @param r logrecord to publish
      */
+    @Override
     public void publish(LogRecord r) {
         try {
             logQueue.put(r);
@@ -139,14 +135,9 @@ class LogFileHandler {
         }
     }
 
+    @Override
     public synchronized void flush() {
-        if(writer != null) {
-            try {
-                writer.flush();
-            } catch (IOException e) {
-                logger.warning("Failed flushing file writer: " + Exceptions.toMessageString(e));
-            }
-        }
+        super.flush();
         try {
             if (currentOutputStream != null && compression == Compression.GZIP) {
                 long newPos = currentOutputStream.getChannel().position();
@@ -160,29 +151,6 @@ class LogFileHandler {
         }
     }
 
-    private synchronized void setOutputStream(OutputStream out) {
-        if (out == null) {
-            throw new NullPointerException();
-        }
-        flushAndClose();
-        writer = new OutputStreamWriter(out, StandardCharsets.UTF_8);
-    }
-    private synchronized void flushAndClose() throws SecurityException {
-        if (writer != null) {
-            try {
-                writer.flush();
-                writer.close();
-            } catch (Exception ex) {
-                logger.log(Level.SEVERE, "Failed to close writer", ex);
-            }
-            writer = null;
-        }
-    }
-
-    public void close() {
-        flushAndClose();
-    }
-
     private void internalPublish(LogRecord r) {
         // first check to see if new file needed.
         // if so, use this.internalRotateNow() to do it
@@ -194,11 +162,7 @@ class LogFileHandler {
         if (now > nextRotationTime || currentOutputStream == null) {
             internalRotateNow();
         }
-        try {
-            writer.write(r.getMessage());
-        } catch (IOException e) {
-            logger.warning("Failed writing log record: " + Exceptions.toMessageString(e));
-        }
+        super.publish(r);
     }
 
     /**
@@ -264,12 +228,12 @@ class LogFileHandler {
         long now = System.currentTimeMillis();
         fileName = LogFormatter.insertDate(filePattern, now);
         flush();
-        flushAndClose();
+        super.close();
 
         try {
             checkAndCreateDir(fileName);
             FileOutputStream os = new FileOutputStream(fileName, true); // append mode, for safety
-            setOutputStream(os);
+            super.setOutputStream(os);
             currentOutputStream = os;
             lastDropPosition = 0;
             LogFileDb.nowLoggingTo(fileName);
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java
index 347500a8c07..1040846dda3 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java
@@ -69,7 +69,7 @@ public final class VespaAccessLog implements RequestLogHandler {
                 .append(" 0.0 ")
                 .append((hitcounts == null) ? 0 : hitcounts.getSummaryCount())
                 .append('\n');
-        logHandler.log(sb.toString());
+        logHandler.access.log(Level.INFO, sb.toString());
     }
 
     private void decimalsOfSecondsFromMilliseconds(long ms, StringBuilder sb) {
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 d72a0ef653e..c0dafe05bb6 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
@@ -48,7 +48,7 @@ public class LogFileHandlerTestCase {
                 return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
             }
         };
-        LogFileHandler h = new LogFileHandler(Compression.NONE, pattern, rTimes, null);
+        LogFileHandler h = new LogFileHandler(Compression.NONE, pattern, rTimes, null, formatter);
         long now = System.currentTimeMillis();
         long millisPerDay = 60*60*24*1000;
         long tomorrowDays = (now / millisPerDay) +1;
@@ -69,7 +69,7 @@ public class LogFileHandlerTestCase {
         File logFile = temporaryFolder.newFile("testLogFileG1.txt");
 
       //create logfilehandler
-      LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null);
+      LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null, new SimpleFormatter());
 
       //write log
       LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileFirst1");
@@ -83,7 +83,7 @@ public class LogFileHandlerTestCase {
       File logFile = temporaryFolder.newFile("testLogFileG2.txt");
 
       //create logfilehandler
-       LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null);
+       LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null, new SimpleFormatter());
 
       //write log
       LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging1");
@@ -111,10 +111,9 @@ public class LogFileHandlerTestCase {
             }
         };
         LogFileHandler handler = new LogFileHandler(
-                Compression.NONE, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink");
+                Compression.NONE, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink", formatter);
 
-        String message = formatter.format(new LogRecord(Level.INFO, "test"));
-        handler.publish(new LogRecord(Level.INFO, message));
+        handler.publish(new LogRecord(Level.INFO, "test"));
         String firstFile;
         do {
              Thread.sleep(1);
@@ -127,8 +126,7 @@ public class LogFileHandlerTestCase {
             secondFileName = handler.getFileName();
         } while (firstFile.equals(secondFileName));
 
-        String longMessage = formatter.format(new LogRecord(Level.INFO, "string which is way longer than the word test"));
-        handler.publish(new LogRecord(Level.INFO, longMessage));
+        handler.publish(new LogRecord(Level.INFO, "string which is way longer than the word test"));
         handler.waitDrained();
         assertThat(Files.size(Paths.get(firstFile))).isEqualTo(31);
         final long expectedSecondFileLength = 72;
@@ -176,10 +174,10 @@ public class LogFileHandlerTestCase {
             }
         };
         LogFileHandler h = new LogFileHandler(
-                compression, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, null);
+                compression, 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\n");
+            LogRecord lr = new LogRecord(Level.INFO, "test");
             h.publish(lr);
         }
         h.waitDrained();