diff options
author | Morten Tokle <mortent@verizonmedia.com> | 2021-01-22 15:37:18 +0100 |
---|---|---|
committer | Morten Tokle <mortent@verizonmedia.com> | 2021-01-22 15:37:18 +0100 |
commit | b510834af37d4baf64c2d13d06afdd105824d1fc (patch) | |
tree | 0410344cd46d9c76a75705ad0479db472dd3a409 /jdisc_http_service/src/main/java | |
parent | 5ca33058e2652c9be23dfb38975280a575843f3a (diff) |
Move log formatting to writer thread
Diffstat (limited to 'jdisc_http_service/src/main/java')
8 files changed, 98 insertions, 88 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..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<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,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<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..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<RequestLogEntry> { 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 <LOGTYPE> { 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<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; @@ -64,10 +65,12 @@ class LogFileHandler { private volatile Writer writer; - static private class LogThread extends Thread { - LogFileHandler logFileHandler; + private final LogWriter<LOGTYPE> logWriter; + + static private class LogThread<LOGTYPE> extends Thread { + LogFileHandler<LOGTYPE> logFileHandler; long lastFlush = 0; - LogThread(LogFileHandler logFile) { + LogThread(LogFileHandler<LOGTYPE> 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<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 +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 <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)); } } |