From b510834af37d4baf64c2d13d06afdd105824d1fc Mon Sep 17 00:00:00 2001 From: Morten Tokle Date: Fri, 22 Jan 2021 15:37:18 +0100 Subject: Move log formatting to writer thread --- .../yahoo/container/logging/AccessLogHandler.java | 20 ++++---- .../container/logging/ConnectionLogHandler.java | 14 +++--- .../yahoo/container/logging/FileConnectionLog.java | 19 +++++--- .../com/yahoo/container/logging/JSONAccessLog.java | 11 +---- .../com/yahoo/container/logging/JSONFormatter.java | 19 ++------ .../yahoo/container/logging/LogFileHandler.java | 48 +++++++++--------- .../com/yahoo/container/logging/LogWriter.java | 10 ++++ .../yahoo/container/logging/VespaAccessLog.java | 45 ++++++++++------- .../yahoo/container/logging/JSONLogTestCase.java | 29 +++++++---- .../container/logging/LogFileHandlerTestCase.java | 57 ++++++++++------------ 10 files changed, 144 insertions(+), 128 deletions(-) create mode 100644 jdisc_http_service/src/main/java/com/yahoo/container/logging/LogWriter.java (limited to 'jdisc_http_service') 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..b410ae5dcf3 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 logFileHandler; - AccessLogHandler(AccessLogConfig.FileHandler config) { - logFileHandler = new LogFileHandler(toCompression(config), config.pattern(), config.rotation(), config.symlink()); + AccessLogHandler(AccessLogConfig.FileHandler config, LogWriter 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,10 @@ class AccessLogHandler { void shutdown() { logFileHandler.close(); - - if (logFileHandler!=null) - logFileHandler.shutdown(); + logFileHandler.shutdown(); } - void rotateNow() { - logFileHandler.rotateNow(); - } +// void rotateNow() { +// logFileHandler.rotateNow(); +// } } 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 logFileHandler; - public ConnectionLogHandler(String clusterName) { - logFileHandler = new LogFileHandler( + public ConnectionLogHandler(String clusterName, LogWriter 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 { 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..54ac284c6c8 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 @@ -9,6 +9,7 @@ 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 +21,7 @@ import java.util.logging.Logger; * * @author frodelu */ -public class JSONFormatter { +public class JSONFormatter implements LogWriter { private static final String COVERAGE = "coverage"; private static final String COVERAGE_COVERAGE = "coverage"; private static final String COVERAGE_DOCUMENTS = "documents"; @@ -38,15 +39,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 = generatorFactory.createGenerator(outputStream, JsonEncoding.UTF8)){ generator.writeStartObject(); String peerAddress = entry.peerAddress().get(); generator.writeStringField("ip", peerAddress); @@ -152,13 +147,9 @@ 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(); } 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..d0a890bf586 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 @@ -27,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.concurrent.atomic.AtomicBoolean; import java.util.logging.ErrorManager; import java.util.logging.Formatter; import java.util.logging.Level; @@ -41,7 +42,7 @@ import java.util.zip.GZIPOutputStream; * @author Bob Travis * @author bjorncs */ -class LogFileHandler { +class LogFileHandler { enum Compression { NONE, GZIP, ZSTD } @@ -51,11 +52,11 @@ class LogFileHandler { private final long[] rotationTimes; private final String filePattern; // default to current directory, ms time stamp private final String symlinkName; - private final ArrayBlockingQueue logQueue = new ArrayBlockingQueue<>(100000); - private final LogRecord rotateCmd = new LogRecord(Level.SEVERE, "rotateNow"); + private final ArrayBlockingQueue 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 logThread; private volatile FileOutputStream currentOutputStream = null; private volatile long nextRotationTime = 0; @@ -64,10 +65,12 @@ class LogFileHandler { private volatile Writer writer; - static private class LogThread extends Thread { - LogFileHandler logFileHandler; + private final LogWriter logWriter; + + static private class LogThread extends Thread { + LogFileHandler logFileHandler; long lastFlush = 0; - LogThread(LogFileHandler logFile) { + LogThread(LogFileHandler logFile) { super("Logger"); setDaemon(true); logFileHandler = logFile; @@ -86,14 +89,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 +113,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 logWriter) { + this(compression, filePattern, calcTimesMinutes(rotationTimes), symlinkName, logWriter); } LogFileHandler( Compression compression, String filePattern, long[] rotationTimes, - String symlinkName) { + String symlinkName, LogWriter 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 +136,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) { @@ -183,7 +187,7 @@ class LogFileHandler { flushAndClose(); } - 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 +199,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 +255,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 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 { + 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 { private static final ThreadLocal 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 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 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 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 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 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 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 { + + @Override + public void write(String record, OutputStream outputStream) throws IOException { + outputStream.write((record + "\n").getBytes(StandardCharsets.UTF_8)); + } + } } -- cgit v1.2.3 From cf182427ea6b9b169d583deac9be0504a5b5d8a7 Mon Sep 17 00:00:00 2001 From: Morten Tokle Date: Fri, 22 Jan 2021 16:02:06 +0100 Subject: Remove unused writer. --- .../yahoo/container/logging/AccessLogHandler.java | 4 -- .../yahoo/container/logging/LogFileHandler.java | 53 +++++++--------------- 2 files changed, 16 insertions(+), 41 deletions(-) (limited to 'jdisc_http_service') 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 b410ae5dcf3..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 @@ -34,8 +34,4 @@ class AccessLogHandler { logFileHandler.close(); logFileHandler.shutdown(); } - -// void rotateNow() { -// logFileHandler.rotateNow(); -// } } 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 d0a890bf586..9a75717af5c 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 @@ -63,12 +63,10 @@ class LogFileHandler { private volatile String fileName; private volatile long lastDropPosition = 0; - private volatile Writer writer; - private final LogWriter logWriter; static private class LogThread extends Thread { - LogFileHandler logFileHandler; + final LogFileHandler logFileHandler; long lastFlush = 0; LogThread(LogFileHandler logFile) { super("Logger"); @@ -144,19 +142,16 @@ 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; + if (currentOutputStream != null) { + if (compression == Compression.GZIP) { + long newPos = currentOutputStream.getChannel().position(); + if (newPos > lastDropPosition + 102400) { + nativeIO.dropPartialFileFromCache(currentOutputStream.getFD(), lastDropPosition, newPos, true); + lastDropPosition = newPos; + } + } else { + currentOutputStream.flush(); } } } catch (IOException e) { @@ -164,27 +159,13 @@ 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(); + currentOutputStream.close(); + } catch (Exception e) { + logger.log(Level.WARNING, "Got error while closing log file", e); + } } private void internalPublish(LOGTYPE r) { @@ -268,12 +249,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); -- cgit v1.2.3 From 56dc9397ed76cf1424216fc22984434c546550cf Mon Sep 17 00:00:00 2001 From: Bjørn Christian Seime Date: Fri, 22 Jan 2021 16:56:15 +0100 Subject: Disable AUTO_CLOSE_TARGET + FLUSH_PASSED_TO_STREAM --- .../src/main/java/com/yahoo/container/logging/JSONFormatter.java | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) (limited to 'jdisc_http_service') 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 54ac284c6c8..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,7 +7,6 @@ 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; @@ -41,7 +40,7 @@ public class JSONFormatter implements LogWriter { @Override public void write(RequestLogEntry entry, OutputStream outputStream) throws IOException { - try (JsonGenerator generator = generatorFactory.createGenerator(outputStream, JsonEncoding.UTF8)){ + try (JsonGenerator generator = createJsonGenerator(outputStream)){ generator.writeStartObject(); String peerAddress = entry.peerAddress().get(); generator.writeStringField("ip", peerAddress); @@ -152,6 +151,11 @@ public class JSONFormatter implements LogWriter { } } + 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); -- cgit v1.2.3 From 80abe89ea168132df7f8808f5408e6f08fcfd166 Mon Sep 17 00:00:00 2001 From: Bjørn Christian Seime Date: Fri, 22 Jan 2021 17:12:32 +0100 Subject: Ensure that 'currentOutputStream' before use --- .../com/yahoo/container/logging/LogFileHandler.java | 21 +++++++-------------- 1 file changed, 7 insertions(+), 14 deletions(-) (limited to 'jdisc_http_service') 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 9a75717af5c..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; @@ -28,12 +23,8 @@ import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; -import java.util.logging.ErrorManager; -import java.util.logging.Formatter; 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; /** @@ -143,15 +134,16 @@ class LogFileHandler { public synchronized void flush() { try { - if (currentOutputStream != null) { + FileOutputStream currentOut = this.currentOutputStream; + if (currentOut != null) { if (compression == Compression.GZIP) { - long newPos = currentOutputStream.getChannel().position(); + long newPos = currentOut.getChannel().position(); if (newPos > lastDropPosition + 102400) { - nativeIO.dropPartialFileFromCache(currentOutputStream.getFD(), lastDropPosition, newPos, true); + nativeIO.dropPartialFileFromCache(currentOut.getFD(), lastDropPosition, newPos, true); lastDropPosition = newPos; } } else { - currentOutputStream.flush(); + currentOut.flush(); } } } catch (IOException e) { @@ -162,7 +154,8 @@ class LogFileHandler { public void close() { try { flush(); - currentOutputStream.close(); + FileOutputStream currentOut = this.currentOutputStream; + if (currentOut != null) currentOut.close(); } catch (Exception e) { logger.log(Level.WARNING, "Got error while closing log file", e); } -- cgit v1.2.3