Merge pull request #16167 from vespa-engine/mortent/move-log-formatting

Move log formatting to writer thread [run-systemtest]

10 files changed, 162 insertions, 174 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..4c156e2705f 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
@@ -11,14 +11,14 @@ import java.util.logging.LogRecord;
  */
 class AccessLogHandler {
 
-    private final LogFileHandler logFileHandler;
+    private final LogFileHandler<RequestLogEntry> logFileHandler;
 
-    AccessLogHandler(AccessLogConfig.FileHandler config) {
-        logFileHandler = new LogFileHandler(toCompression(config), config.pattern(), config.rotation(), config.symlink());
+    AccessLogHandler(AccessLogConfig.FileHandler config, LogWriter<RequestLogEntry> logWriter) {
+        logFileHandler = new LogFileHandler<>(toCompression(config), config.pattern(), config.rotation(), config.symlink(), logWriter);
     }
 
-    public void log(String message) {
-        logFileHandler.publish(new LogRecord(Level.INFO, message));
+    public void log(RequestLogEntry entry) {
+        logFileHandler.publish(entry);
     }
 
     private LogFileHandler.Compression toCompression(AccessLogConfig.FileHandler config) {
@@ -32,12 +32,6 @@ class AccessLogHandler {
 
     void shutdown() {
         logFileHandler.close();
-
-        if (logFileHandler!=null)
-            logFileHandler.shutdown();
-    }
-
-    void rotateNow() {
-        logFileHandler.rotateNow();
+        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..2a36e251d24 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
@@ -4,24 +4,24 @@ package com.yahoo.container.logging;
 
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
-import java.util.logging.Logger;
 
 /**
  * @author mortent
  */
 class ConnectionLogHandler {
-    private final LogFileHandler logFileHandler;
+    private final LogFileHandler<ConnectionLogEntry> logFileHandler;
 
-    public ConnectionLogHandler(String clusterName) {
-        logFileHandler = new LogFileHandler(
+    public ConnectionLogHandler(String clusterName, LogWriter<ConnectionLogEntry> logWriter) {
+        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));
+                String.format("ConnectionLog.%s", clusterName),
+                logWriter);
     }
 
-    public void log(String message) {
-        logFileHandler.publish(new LogRecord(Level.INFO, message));
+    public void log(ConnectionLogEntry entry) {
+        logFileHandler.publish(entry);
     }
 
     public void shutdown() {
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..62e53a5a514 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
@@ -5,33 +5,38 @@ package com.yahoo.container.logging;
 import com.google.inject.Inject;
 import com.yahoo.component.AbstractComponent;
 
+import java.io.IOException;
+import java.io.OutputStream;
+import java.nio.charset.StandardCharsets;
 import java.util.logging.Level;
 import java.util.logging.Logger;
 
 /**
  * @author mortent
  */
-public class FileConnectionLog extends AbstractComponent implements ConnectionLog {
+public class FileConnectionLog extends AbstractComponent implements ConnectionLog, LogWriter<ConnectionLogEntry> {
 
     private static final Logger logger = Logger.getLogger(FileConnectionLog.class.getName());
     private final ConnectionLogHandler logHandler;
 
     @Inject
     public FileConnectionLog(ConnectionLogConfig config) {
-        logHandler = new ConnectionLogHandler(config.cluster());
+        logHandler = new ConnectionLogHandler(config.cluster(), this);
     }
 
     @Override
     public void log(ConnectionLogEntry connectionLogEntry) {
-        try {
-            logHandler.log(connectionLogEntry.toJson()+ '\n');
-        } catch (Exception e) {
-            logger.log(Level.WARNING, "Unable to write connection log entry for connection id " + connectionLogEntry.id(), e);
-        }
+        logHandler.log(connectionLogEntry);
     }
 
     @Override
     public void deconstruct() {
         logHandler.shutdown();
     }
+
+    @Override
+    // TODO serialize directly to outputstream
+    public void write(ConnectionLogEntry entry, OutputStream outputStream) throws IOException {
+        outputStream.write(entry.toJson().getBytes(StandardCharsets.UTF_8));
+    }
 }
\ No newline at end of file
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..2cea7f7dd04 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
@@ -12,25 +12,18 @@ import com.yahoo.container.core.AccessLogConfig;
 public final class JSONAccessLog implements RequestLogHandler {
 
     private final AccessLogHandler logHandler;
-    private final JSONFormatter formatter;
 
     public JSONAccessLog(AccessLogConfig config) {
-        logHandler = new AccessLogHandler(config.fileHandler());
-        formatter = new JSONFormatter();
+        logHandler = new AccessLogHandler(config.fileHandler(), new JSONFormatter());
     }
 
     @Override
     public void log(RequestLogEntry entry) {
-        logHandler.log(formatter.format(entry) + '\n');
+        logHandler.log(entry);
     }
 
     // TODO: This is never called. We should have a DI provider and call this method from its deconstruct.
     public void shutdown() {
         logHandler.shutdown();
     }
-
-    void rotateNow() {
-        logHandler.rotateNow();
-    }
-
 }
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java
index e813b1bf4e1..c6d177684ac 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java
@@ -7,8 +7,8 @@ import com.fasterxml.jackson.core.JsonGenerator;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import com.yahoo.yolean.trace.TraceNode;
 
-import java.io.ByteArrayOutputStream;
 import java.io.IOException;
+import java.io.OutputStream;
 import java.security.Principal;
 import java.util.Collection;
 import java.util.Objects;
@@ -20,7 +20,7 @@ import java.util.logging.Logger;
  *
  * @author frodelu
  */
-public class JSONFormatter {
+public class JSONFormatter implements LogWriter<RequestLogEntry> {
     private static final String COVERAGE = "coverage";
     private static final String COVERAGE_COVERAGE = "coverage";
     private static final String COVERAGE_DOCUMENTS = "documents";
@@ -38,15 +38,9 @@ public class JSONFormatter {
         generatorFactory = new JsonFactory(new ObjectMapper());
     }
 
-    /**
-     * The main method for formatting the associated {@link RequestLogEntry} as a Vespa JSON access log string
-     *
-     * @return The Vespa JSON access log string without trailing newline
-     */
-    public String format(RequestLogEntry entry) {
-        ByteArrayOutputStream logLine = new ByteArrayOutputStream();
-        try {
-            JsonGenerator generator = generatorFactory.createGenerator(logLine, JsonEncoding.UTF8);
+    @Override
+    public void write(RequestLogEntry entry, OutputStream outputStream) throws IOException {
+        try (JsonGenerator generator = createJsonGenerator(outputStream)){
             generator.writeStartObject();
             String peerAddress = entry.peerAddress().get();
             generator.writeStringField("ip", peerAddress);
@@ -152,15 +146,16 @@ public class JSONFormatter {
             }
 
             generator.writeEndObject();
-            generator.close();
-
         } catch (IOException e) {
             logger.log(Level.WARNING, "Unable to generate JSON access log entry: " + e.getMessage(), e);
         }
-
-        return logLine.toString();
     }
 
+    private JsonGenerator createJsonGenerator(OutputStream outputStream) throws IOException {
+        return generatorFactory.createGenerator(outputStream, JsonEncoding.UTF8)
+                .configure(JsonGenerator.Feature.AUTO_CLOSE_TARGET, false)
+                .configure(JsonGenerator.Feature.FLUSH_PASSED_TO_STREAM, false);
+    }
 
     private boolean remoteAddressDiffers(String ipV4Address, String remoteAddress) {
         return remoteAddress != null && !Objects.equals(ipV4Address, remoteAddress);
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..b764f813c41 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,12 +22,9 @@ 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.concurrent.atomic.AtomicBoolean;
 import java.util.logging.Level;
-import java.util.logging.LogRecord;
 import java.util.logging.Logger;
-import java.util.logging.StreamHandler;
 import java.util.zip.GZIPOutputStream;
 
 /**
@@ -41,7 +33,7 @@ import java.util.zip.GZIPOutputStream;
  * @author Bob Travis
  * @author bjorncs
  */
-class LogFileHandler {
+class LogFileHandler <LOGTYPE>  {
 
     enum Compression { NONE, GZIP, ZSTD }
 
@@ -51,23 +43,23 @@ class LogFileHandler {
     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 ArrayBlockingQueue<LOGTYPE> logQueue = new ArrayBlockingQueue<>(100000);
+    private final AtomicBoolean rotate = new AtomicBoolean(false);
     private final ExecutorService executor = Executors.newCachedThreadPool(ThreadFactoryFactory.getDaemonThreadFactory("logfilehandler.compression"));
     private final NativeIO nativeIO = new NativeIO();
-    private final LogThread logThread;
+    private final LogThread<LOGTYPE> logThread;
 
     private volatile FileOutputStream currentOutputStream = null;
     private volatile long nextRotationTime = 0;
     private volatile String fileName;
     private volatile long lastDropPosition = 0;
 
-    private volatile Writer writer;
+    private final LogWriter<LOGTYPE> logWriter;
 
-    static private class LogThread extends Thread {
-        LogFileHandler logFileHandler;
+    static private class LogThread<LOGTYPE> extends Thread {
+        final LogFileHandler<LOGTYPE> logFileHandler;
         long lastFlush = 0;
-        LogThread(LogFileHandler logFile) {
+        LogThread(LogFileHandler<LOGTYPE> logFile) {
             super("Logger");
             setDaemon(true);
             logFileHandler = logFile;
@@ -86,14 +78,14 @@ class LogFileHandler {
 
         private void storeLogRecords() throws InterruptedException {
             while (!isInterrupted()) {
-                LogRecord r = logFileHandler.logQueue.poll(100, TimeUnit.MILLISECONDS);
+                LOGTYPE r = logFileHandler.logQueue.poll(100, TimeUnit.MILLISECONDS);
+                if(logFileHandler.rotate.get()) {
+                    logFileHandler.internalRotateNow();
+                    lastFlush = System.nanoTime();
+                    logFileHandler.rotate.set(false);
+                }
                 if (r != null) {
-                    if (r == logFileHandler.rotateCmd) {
-                        logFileHandler.internalRotateNow();
-                        lastFlush = System.nanoTime();
-                    } else {
-                        logFileHandler.internalPublish(r);
-                    }
+                    logFileHandler.internalPublish(r);
                     flushIfOld(3, TimeUnit.SECONDS);
                 } else {
                     flushIfOld(100, TimeUnit.MILLISECONDS);
@@ -110,20 +102,21 @@ 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, LogWriter<LOGTYPE> logWriter) {
+        this(compression, filePattern, calcTimesMinutes(rotationTimes), symlinkName, logWriter);
     }
 
     LogFileHandler(
             Compression compression,
             String filePattern,
             long[] rotationTimes,
-            String symlinkName) {
+            String symlinkName, LogWriter<LOGTYPE> logWriter) {
         this.compression = compression;
         this.filePattern = filePattern;
         this.rotationTimes = rotationTimes;
         this.symlinkName = (symlinkName != null && !symlinkName.isBlank()) ? symlinkName : null;
-        this.logThread = new LogThread(this);
+        this.logWriter = logWriter;
+        this.logThread = new LogThread<>(this);
         this.logThread.start();
     }
 
@@ -132,7 +125,7 @@ class LogFileHandler {
      *
      * @param r logrecord to publish
      */
-    public void publish(LogRecord r) {
+    public void publish(LOGTYPE r) {
         try {
             logQueue.put(r);
         } catch (InterruptedException e) {
@@ -140,19 +133,17 @@ class LogFileHandler {
     }
 
     public synchronized void 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();
-                if (newPos > lastDropPosition + 102400) {
-                    nativeIO.dropPartialFileFromCache(currentOutputStream.getFD(), lastDropPosition, newPos, true);
-                    lastDropPosition = newPos;
+            FileOutputStream currentOut = this.currentOutputStream;
+            if (currentOut != null) {
+                if (compression == Compression.GZIP) {
+                    long newPos = currentOut.getChannel().position();
+                    if (newPos > lastDropPosition + 102400) {
+                        nativeIO.dropPartialFileFromCache(currentOut.getFD(), lastDropPosition, newPos, true);
+                        lastDropPosition = newPos;
+                    }
+                } else {
+                    currentOut.flush();
                 }
             }
         } catch (IOException e) {
@@ -160,30 +151,17 @@ 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();
+        try {
+            flush();
+            FileOutputStream currentOut = this.currentOutputStream;
+            if (currentOut != null) currentOut.close();
+        } catch (Exception e) {
+            logger.log(Level.WARNING, "Got error while closing log file", e);
+        }
     }
 
-    private void internalPublish(LogRecord r) {
+    private void internalPublish(LOGTYPE r) {
         // first check to see if new file needed.
         // if so, use this.internalRotateNow() to do it
 
@@ -195,7 +173,7 @@ class LogFileHandler {
             internalRotateNow();
         }
         try {
-            writer.write(r.getMessage());
+            logWriter.write(r, currentOutputStream);
         } catch (IOException e) {
             logger.warning("Failed writing log record: " + Exceptions.toMessageString(e));
         }
@@ -251,7 +229,7 @@ class LogFileHandler {
      * Force file rotation now, independent of schedule.
      */
     void rotateNow () {
-        publish(rotateCmd);
+        rotate.set(true);
     }
 
     // Throw InterruptedException upwards rather than relying on isInterrupted to stop the thread as
@@ -264,12 +242,10 @@ class LogFileHandler {
         long now = System.currentTimeMillis();
         fileName = LogFormatter.insertDate(filePattern, now);
         flush();
-        flushAndClose();
 
         try {
             checkAndCreateDir(fileName);
             FileOutputStream os = new FileOutputStream(fileName, true); // append mode, for safety
-            setOutputStream(os);
             currentOutputStream = os;
             lastDropPosition = 0;
             LogFileDb.nowLoggingTo(fileName);
diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogWriter.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogWriter.java
new file mode 100644
index 00000000000..15a983cfb43
--- /dev/null
+++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/LogWriter.java
@@ -0,0 +1,10 @@
+// Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+package com.yahoo.container.logging;
+
+import java.io.IOException;
+import java.io.OutputStream;
+
+interface LogWriter <LOGTYPE>  {
+    void write(LOGTYPE record, OutputStream outputStream) throws IOException;
+}
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..b74e69ce172 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
@@ -3,6 +3,9 @@ package com.yahoo.container.logging;
 
 import com.yahoo.container.core.AccessLogConfig;
 
+import java.io.IOException;
+import java.io.OutputStream;
+import java.nio.charset.StandardCharsets;
 import java.text.SimpleDateFormat;
 import java.util.Date;
 import java.util.TimeZone;
@@ -12,14 +15,14 @@ import java.util.logging.Level;
  * @author Bjorn Borud
  * @author Oyvind Bakksjo
  */
-public final class VespaAccessLog implements RequestLogHandler {
+public final class VespaAccessLog implements RequestLogHandler, LogWriter<RequestLogEntry> {
 
     private static final ThreadLocal<SimpleDateFormat> dateFormat = ThreadLocal.withInitial(VespaAccessLog::createDateFormat);
 
     private final AccessLogHandler logHandler;
 
     public VespaAccessLog(AccessLogConfig config) {
-        logHandler = new AccessLogHandler(config.fileHandler());
+        logHandler = new AccessLogHandler(config.fileHandler(), this);
     }
 
     private static SimpleDateFormat createDateFormat() {
@@ -40,7 +43,7 @@ public final class VespaAccessLog implements RequestLogHandler {
         return (user == null) ? "-" : user;
     }
 
-    private void writeLog(String ipAddr, String user, String request, String referer, String agent,
+    private String toLogline(String ipAddr, String user, String request, String referer, String agent,
                           long durationMillis, long byteCount, HitCounts hitcounts, int returnCode)
     {
         long ms = Math.max(0L, durationMillis);
@@ -69,7 +72,7 @@ public final class VespaAccessLog implements RequestLogHandler {
                 .append(" 0.0 ")
                 .append((hitcounts == null) ? 0 : hitcounts.getSummaryCount())
                 .append('\n');
-        logHandler.log(sb.toString());
+        return sb.toString();
     }
 
     private void decimalsOfSecondsFromMilliseconds(long ms, StringBuilder sb) {
@@ -93,19 +96,25 @@ public final class VespaAccessLog implements RequestLogHandler {
 
     @Override
     public void log(RequestLogEntry entry) {
-        writeLog(
-                entry.peerAddress().get(),
-                null,
-                getRequest(
-                        entry.httpMethod().orElse(null),
-                        entry.rawPath().orElse(null),
-                        entry.rawQuery().orElse(null),
-                        entry.httpVersion().orElse(null)),
-                entry.referer().orElse(null),
-                entry.userAgent().orElse(null),
-                entry.duration().get().toMillis(),
-                entry.contentSize().orElse(0L),
-                entry.hitCounts().orElse(null),
-                entry.statusCode().orElse(0));
+        logHandler.log(entry);
+    }
+
+    @Override
+    public void write(RequestLogEntry entry, OutputStream outputStream) throws IOException {
+        outputStream.write(
+                toLogline(
+                        entry.peerAddress().get(),
+                        null,
+                        getRequest(
+                                entry.httpMethod().orElse(null),
+                                entry.rawPath().orElse(null),
+                                entry.rawQuery().orElse(null),
+                                entry.httpVersion().orElse(null)),
+                        entry.referer().orElse(null),
+                        entry.userAgent().orElse(null),
+                        entry.duration().get().toMillis(),
+                        entry.contentSize().orElse(0L),
+                        entry.hitCounts().orElse(null),
+                        entry.statusCode().orElse(0)).getBytes(StandardCharsets.UTF_8));
     }
 }
diff --git a/jdisc_http_service/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java b/jdisc_http_service/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
index 6c8e7fab140..cb3d1d0a12f 100644
--- a/jdisc_http_service/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
+++ b/jdisc_http_service/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
@@ -4,6 +4,8 @@ package com.yahoo.container.logging;
 import com.yahoo.yolean.trace.TraceNode;
 import org.junit.Test;
 
+import java.io.ByteArrayOutputStream;
+import java.io.IOException;
 import java.time.Duration;
 import java.time.Instant;
 
@@ -63,9 +65,8 @@ public class JSONLogTestCase {
             "}" +
             "}";
 
-        assertJsonEquals(new JSONFormatter().format(entry), expectedOutput);
+        assertJsonEquals(formatEntry(entry), expectedOutput);
     }
-
     @Test
     public void test_json_of_trace() {
         TraceNode root = new TraceNode("root", 7);
@@ -95,9 +96,8 @@ public class JSONLogTestCase {
                 "}" +
                 "}";
 
-        assertJsonEquals(new JSONFormatter().format(entry), expectedOutput);
+        assertJsonEquals(formatEntry(entry), expectedOutput);
     }
-
     @Test
     public void test_with_keyvalues() {
         RequestLogEntry entry = newRequestLogEntry("test")
@@ -130,7 +130,7 @@ public class JSONLogTestCase {
             "\"multivalue\":[\"value2\",\"value3\"]}" +
             "}";
 
-        assertJsonEquals(new JSONFormatter().format(entry), expectedOutput);
+        assertJsonEquals(formatEntry(entry), expectedOutput);
 
     }
 
@@ -162,7 +162,7 @@ public class JSONLogTestCase {
             "}" +
             "}";
 
-        assertJsonEquals(new JSONFormatter().format(entry), expectedOutput);
+        assertJsonEquals(formatEntry(entry), expectedOutput);
 
         // Add remote port and verify
         entry = newRequestLogEntry("test")
@@ -193,7 +193,7 @@ public class JSONLogTestCase {
             "}" +
             "}";
 
-        assertJsonEquals(new JSONFormatter().format(entry), expectedOutput);
+        assertJsonEquals(formatEntry(entry), expectedOutput);
     }
 
     @Test
@@ -203,7 +203,7 @@ public class JSONLogTestCase {
                 .remoteAddress(entry.peerAddress().get())
                 .build();
         JSONFormatter formatter = new JSONFormatter();
-        assertJsonEquals(formatter.format(entry), formatter.format(entrywithremote));
+        assertJsonEquals(formatEntry(entry), formatEntry(entrywithremote));
     }
 
     @Test
@@ -246,11 +246,11 @@ public class JSONLogTestCase {
             "}" +
             "}";
 
-        assertJsonEquals(new JSONFormatter().format(entry), expectedOutput);
+        assertJsonEquals(formatEntry(entry), expectedOutput);
     }
 
     private void verifyCoverage(String coverage, RequestLogEntry entry) {
-        assertJsonEquals(new JSONFormatter().format(entry),
+        assertJsonEquals(formatEntry(entry),
                 "{\"ip\":\"152.200.54.243\"," +
                 "\"peeraddr\":\"152.200.54.243\"," +
                 "\"time\":920880005.023," +
@@ -283,4 +283,13 @@ public class JSONLogTestCase {
         verifyCoverage("\"coverage\":{\"coverage\":50,\"documents\":100,\"degraded\":{\"adaptive-timeout\":true}}",
                        newRequestLogEntry("test",  new Coverage(100,200,200,4)).build());
     }
+
+    private String formatEntry(RequestLogEntry entry) {
+        try (ByteArrayOutputStream outputStream = new ByteArrayOutputStream()) {
+            new JSONFormatter().write(entry, outputStream);
+            return outputStream.toString();
+        } catch (IOException e) {
+            throw new RuntimeException(e);
+        }
+    }
 }
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..86c562f57ff 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
@@ -10,6 +10,8 @@ import org.junit.rules.TemporaryFolder;
 
 import java.io.File;
 import java.io.IOException;
+import java.io.OutputStream;
+import java.nio.charset.StandardCharsets;
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.nio.file.Paths;
@@ -20,7 +22,6 @@ import java.util.function.BiFunction;
 import java.util.logging.Formatter;
 import java.util.logging.Level;
 import java.util.logging.LogRecord;
-import java.util.logging.SimpleFormatter;
 import java.util.zip.GZIPInputStream;
 
 import static com.yahoo.yolean.Exceptions.uncheck;
@@ -48,18 +49,18 @@ public class LogFileHandlerTestCase {
                 return ("["+timeStamp+"]" + " " + formatMessage(r) + "\n");
             }
         };
-        LogFileHandler h = new LogFileHandler(Compression.NONE, pattern, rTimes, null);
+        LogFileHandler<String> h = new LogFileHandler<>(Compression.NONE, pattern, rTimes, null, new StringLogWriter());
         long now = System.currentTimeMillis();
         long millisPerDay = 60*60*24*1000;
         long tomorrowDays = (now / millisPerDay) +1;
         long tomorrowMillis = tomorrowDays * millisPerDay;
         assertThat(tomorrowMillis+1000).isEqualTo(h.getNextRotationTime(tomorrowMillis));
         assertThat(tomorrowMillis+10000).isEqualTo(h.getNextRotationTime(tomorrowMillis+3000));
-        LogRecord lr = new LogRecord(Level.INFO, "test");
-        h.publish(lr);
-        h.publish(new LogRecord(Level.INFO, "another test"));
+        String message = "test";
+        h.publish(message);
+        h.publish( "another test");
         h.rotateNow();
-        h.publish(lr);
+        h.publish(message);
         h.flush();
         h.shutdown();
     }
@@ -69,11 +70,10 @@ public class LogFileHandlerTestCase {
         File logFile = temporaryFolder.newFile("testLogFileG1.txt");
 
       //create logfilehandler
-      LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null);
+      LogFileHandler<String> h = new LogFileHandler<>(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null, new StringLogWriter());
 
       //write log
-      LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileFirst1");
-      h.publish(lr);
+      h.publish("testDeleteFileFirst1");
       h.flush();
       h.shutdown();
     }
@@ -83,19 +83,17 @@ public class LogFileHandlerTestCase {
       File logFile = temporaryFolder.newFile("testLogFileG2.txt");
 
       //create logfilehandler
-       LogFileHandler h = new LogFileHandler(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null);
+       LogFileHandler<String> h = new LogFileHandler<>(Compression.NONE, logFile.getAbsolutePath(), "0 5 ...", null, new StringLogWriter());
 
       //write log
-      LogRecord lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging1");
-      h.publish(lr);
+      h.publish("testDeleteFileDuringLogging1");
       h.flush();
 
       //delete log file
         logFile.delete();
 
       //write log again
-      lr = new LogRecord(Level.INFO, "testDeleteFileDuringLogging2");
-      h.publish(lr);
+      h.publish("testDeleteFileDuringLogging2");
       h.flush();
       h.shutdown();
     }
@@ -107,14 +105,14 @@ public class LogFileHandlerTestCase {
             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));
             }
         };
-        LogFileHandler handler = new LogFileHandler(
-                Compression.NONE, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink");
+        LogFileHandler<String> handler = new LogFileHandler<>(
+                Compression.NONE, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, "symlink", new StringLogWriter());
 
         String message = formatter.format(new LogRecord(Level.INFO, "test"));
-        handler.publish(new LogRecord(Level.INFO, message));
+        handler.publish(message);
         String firstFile;
         do {
              Thread.sleep(1);
@@ -128,7 +126,7 @@ public class LogFileHandlerTestCase {
         } 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(longMessage);
         handler.waitDrained();
         assertThat(Files.size(Paths.get(firstFile))).isEqualTo(31);
         final long expectedSecondFileLength = 72;
@@ -168,19 +166,11 @@ public class LogFileHandlerTestCase {
                                  BiFunction<Path, Integer, String> decompressor) throws IOException, InterruptedException {
         File root = temporaryFolder.newFolder("testcompression" + compression.name());
 
-        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(
-                compression, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, null);
+        LogFileHandler<String> h = new LogFileHandler<>(
+                compression, root.getAbsolutePath() + "/logfilehandlertest.%Y%m%d%H%M%S%s", new long[]{0}, null, new StringLogWriter());
         int logEntries = 10000;
         for (int i = 0; i < logEntries; i++) {
-            LogRecord lr = new LogRecord(Level.INFO, "test\n");
-            h.publish(lr);
+            h.publish("test");
         }
         h.waitDrained();
         String f1 = h.getFileName();
@@ -201,4 +191,11 @@ public class LogFileHandlerTestCase {
         h.shutdown();
     }
 
+    static class StringLogWriter implements LogWriter<String> {
+
+        @Override
+        public void write(String record, OutputStream outputStream) throws IOException {
+            outputStream.write((record + "\n").getBytes(StandardCharsets.UTF_8));
+        }
+    }
 }