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

7 files changed, 76 insertions, 45 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 14236452ac0..08be5f2613e 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,23 +3,22 @@ package com.yahoo.container.logging;
 
 import com.yahoo.container.core.AccessLogConfig;
 
-import java.util.logging.Logger;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
 
 /**
  * @author Bjorn Borud
  */
 class AccessLogHandler {
 
-    public final Logger access = Logger.getAnonymousLogger();
     private final LogFileHandler logFileHandler;
 
     AccessLogHandler(AccessLogConfig.FileHandler config) {
-        access.setUseParentHandlers(false);
+        logFileHandler = new LogFileHandler(toCompression(config), config.pattern(), config.rotation(), config.symlink());
+    }
 
-        LogFormatter lf = new LogFormatter();
-        lf.messageOnly(true);
-        logFileHandler = new LogFileHandler(toCompression(config), config.pattern(), config.rotation(), config.symlink(), lf);
-        access.addHandler(this.logFileHandler);
+    public void log(String message) {
+        logFileHandler.publish(new LogRecord(Level.INFO, message));
     }
 
     private LogFileHandler.Compression toCompression(AccessLogConfig.FileHandler config) {
@@ -33,7 +32,6 @@ 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 c2013aeb128..82a84200f10 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,33 +2,30 @@
 
 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),
-                lf);
-        this.logFileHandler.setFormatter(lf);
-        connection.addHandler(this.logFileHandler);
+                String.format("ConnectionLog.%s", clusterName));
+    }
+
+    public void log(String message) {
+        logFileHandler.publish(new LogRecord(Level.INFO, message));
     }
 
     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 f7f4e1e8ed3..0b9e2e4a778 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.connection.log(Level.INFO, connectionLogEntry.toJson()+ '\n');
+            logHandler.log(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 aa2df959a4c..6fc4e886ec5 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,8 +3,6 @@ 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.
  *
@@ -23,7 +21,7 @@ public final class JSONAccessLog implements RequestLogHandler {
 
     @Override
     public void log(RequestLogEntry entry) {
-        logHandler.access.log(Level.INFO, formatter.format(entry) + '\n');
+        logHandler.log(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 5b30ffbe363..58a324b7f26 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,6 +13,11 @@ 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;
@@ -22,6 +27,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.ErrorManager;
 import java.util.logging.Formatter;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
@@ -35,7 +41,7 @@ import java.util.zip.GZIPOutputStream;
  * @author Bob Travis
  * @author bjorncs
  */
-class LogFileHandler extends StreamHandler {
+class LogFileHandler {
 
     enum Compression { NONE, GZIP, ZSTD }
 
@@ -56,6 +62,8 @@ class LogFileHandler extends StreamHandler {
     private volatile String fileName;
     private volatile long lastDropPosition = 0;
 
+    private volatile Writer writer;
+
     static private class LogThread extends Thread {
         LogFileHandler logFileHandler;
         long lastFlush = 0;
@@ -102,18 +110,15 @@ class LogFileHandler extends StreamHandler {
         }
     }
 
-    LogFileHandler(Compression compression, String filePattern, String rotationTimes, String symlinkName, Formatter formatter) {
-        this(compression, filePattern, calcTimesMinutes(rotationTimes), symlinkName, formatter);
+    LogFileHandler(Compression compression, String filePattern, String rotationTimes, String symlinkName) {
+        this(compression, filePattern, calcTimesMinutes(rotationTimes), symlinkName);
     }
 
     LogFileHandler(
             Compression compression,
             String filePattern,
             long[] rotationTimes,
-            String symlinkName,
-            Formatter formatter) {
-        super();
-        super.setFormatter(formatter);
+            String symlinkName) {
         this.compression = compression;
         this.filePattern = filePattern;
         this.rotationTimes = rotationTimes;
@@ -127,7 +132,6 @@ class LogFileHandler extends StreamHandler {
      *
      * @param r logrecord to publish
      */
-    @Override
     public void publish(LogRecord r) {
         try {
             logQueue.put(r);
@@ -135,9 +139,14 @@ class LogFileHandler extends StreamHandler {
         }
     }
 
-    @Override
     public synchronized void flush() {
-        super.flush();
+        if(writer != null) {
+            try {
+                writer.flush();
+            } catch (IOException e) {
+                logger.warning("Failed flushing file writer: " + Exceptions.toMessageString(e));
+            }
+        }
         try {
             if (currentOutputStream != null && compression == Compression.GZIP) {
                 long newPos = currentOutputStream.getChannel().position();
@@ -151,6 +160,29 @@ class LogFileHandler extends StreamHandler {
         }
     }
 
+    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
@@ -162,7 +194,11 @@ class LogFileHandler extends StreamHandler {
         if (now > nextRotationTime || currentOutputStream == null) {
             internalRotateNow();
         }
-        super.publish(r);
+        try {
+            writer.write(r.getMessage());
+        } catch (IOException e) {
+            logger.warning("Failed writing log record: " + Exceptions.toMessageString(e));
+        }
     }
 
     /**
@@ -228,12 +264,12 @@ class LogFileHandler extends StreamHandler {
         long now = System.currentTimeMillis();
         fileName = LogFormatter.insertDate(filePattern, now);
         flush();
-        super.close();
+        flushAndClose();
 
         try {
             checkAndCreateDir(fileName);
             FileOutputStream os = new FileOutputStream(fileName, true); // append mode, for safety
-            super.setOutputStream(os);
+            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 1040846dda3..347500a8c07 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.access.log(Level.INFO, sb.toString());
+        logHandler.log(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 c0dafe05bb6..d72a0ef653e 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, formatter);
+        LogFileHandler h = new LogFileHandler(Compression.NONE, pattern, rTimes, null);
         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, new SimpleFormatter());
+      LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null);
 
       //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, new SimpleFormatter());
+       LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null);
 
       //write log
       LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging1");
@@ -111,9 +111,10 @@ public class LogFileHandlerTestCase {
             }
         };
         LogFileHandler handler = new LogFileHandler(
-                Compression.NONE, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink", formatter);
+                Compression.NONE, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink");
 
-        handler.publish(new LogRecord(Level.INFO, "test"));
+        String message = formatter.format(new LogRecord(Level.INFO, "test"));
+        handler.publish(new LogRecord(Level.INFO, message));
         String firstFile;
         do {
              Thread.sleep(1);
@@ -126,7 +127,8 @@ public class LogFileHandlerTestCase {
             secondFileName = handler.getFileName();
         } while (firstFile.equals(secondFileName));
 
-        handler.publish(new LogRecord(Level.INFO, "string which is way longer than the word test"));
+        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.waitDrained();
         assertThat(Files.size(Paths.get(firstFile))).isEqualTo(31);
         final long expectedSecondFileLength = 72;
@@ -174,10 +176,10 @@ public class LogFileHandlerTestCase {
             }
         };
         LogFileHandler h = new LogFileHandler(
-                compression, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, null, formatter);
+                compression, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, null);
         int logEntries = 10000;
         for (int i = 0; i < logEntries; i++) {
-            LogRecord lr = new LogRecord(Level.INFO, "test");
+            LogRecord lr = new LogRecord(Level.INFO, "test\n");
             h.publish(lr);
         }
         h.waitDrained();