diff options
author | Bjørn Christian Seime <bjorncs@verizonmedia.com> | 2021-01-21 14:47:39 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2021-01-21 14:47:39 +0100 |
commit | 99dff1d3c48ac9a481f25831c877bc51109848eb (patch) | |
tree | c76f3d1722af1d559270326590086b03685acb50 | |
parent | 94226d30ee8808887e11b689c92c417f35f15070 (diff) | |
parent | b1bbb58449af091cf20f296ba19130b446d68022 (diff) |
Merge pull request #16123 from vespa-engine/bjorncs/access-log-optimizations
Access log optimizations [run-systemtest]
26 files changed, 607 insertions, 547 deletions
diff --git a/container-core/abi-spec.json b/container-core/abi-spec.json index a5483d12b24..06366250c09 100644 --- a/container-core/abi-spec.json +++ b/container-core/abi-spec.json @@ -499,6 +499,7 @@ ], "methods": [ "public void <init>(java.util.concurrent.Executor, com.yahoo.container.logging.AccessLog, com.yahoo.jdisc.Metric)", + "public void <init>(java.util.concurrent.Executor, com.yahoo.jdisc.Metric)", "public void <init>(com.yahoo.container.jdisc.LoggingRequestHandler$Context)", "public java.util.concurrent.Executor getExecutor()", "public com.yahoo.container.logging.AccessLog getAccessLog()", @@ -515,6 +516,7 @@ ], "methods": [ "public void <init>(java.util.concurrent.Executor, com.yahoo.container.logging.AccessLog)", + "public void <init>(java.util.concurrent.Executor)", "public static com.yahoo.container.jdisc.LoggingRequestHandler$Context testOnlyContext()", "public void <init>(com.yahoo.container.jdisc.LoggingRequestHandler$Context)", "public void <init>(com.yahoo.container.jdisc.LoggingRequestHandler$Context, boolean)", @@ -777,7 +779,7 @@ "public void <init>(java.lang.String, java.util.Collection, com.yahoo.component.provider.ComponentRegistry)", "public void <init>(com.yahoo.processing.handler.ProcessingHandler)", "public void <init>(java.lang.String, com.yahoo.processing.handler.ProcessingHandler)", - "public void <init>(com.yahoo.component.chain.Chain, com.yahoo.container.logging.AccessLogInterface)", + "public void <init>(com.yahoo.component.chain.Chain, com.yahoo.container.logging.RequestLogHandler)", "public com.yahoo.processing.handler.ProcessingHandler processingHandler()" ], "fields": [] diff --git a/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java b/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java index 064b6cf6279..9bb9819cd1f 100644 --- a/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java +++ b/container-core/src/main/java/com/yahoo/container/jdisc/LoggingRequestHandler.java @@ -3,7 +3,6 @@ package com.yahoo.container.jdisc; import com.google.inject.Inject; import com.yahoo.container.handler.Timing; -import com.yahoo.container.http.AccessLogUtil; import com.yahoo.container.logging.AccessLog; import com.yahoo.container.logging.AccessLogEntry; import com.yahoo.jdisc.Metric; @@ -11,16 +10,15 @@ import com.yahoo.jdisc.Response; import com.yahoo.jdisc.handler.CompletionHandler; import com.yahoo.jdisc.handler.ContentChannel; import com.yahoo.jdisc.http.server.jetty.AccessLoggingRequestHandler; -import java.util.logging.Level; import com.yahoo.yolean.Exceptions; import java.io.IOException; import java.io.OutputStream; -import java.net.InetSocketAddress; import java.net.SocketAddress; import java.net.URI; import java.util.Optional; import java.util.concurrent.Executor; +import java.util.logging.Level; /** * A request handler base class extending the features of @@ -28,35 +26,43 @@ import java.util.concurrent.Executor; * * @author Steinar Knutsen */ +// TODO Vespa 8: Deprecate all constructors taking AccessLog as parameter public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler { - private final AccessLog accessLog; + public LoggingRequestHandler(Executor executor, AccessLog ignored) { + this(executor, ignored, null); + } - public LoggingRequestHandler(Executor executor, AccessLog accessLog) { - this(executor, accessLog, null); + public LoggingRequestHandler(Executor executor) { + this(executor, null, null); } public static class Context { final Executor executor; - final AccessLog accessLog; + final AccessLog ignored; final Metric metric; @Inject - public Context(Executor executor, AccessLog accessLog, Metric metric) { + public Context(Executor executor, AccessLog ignored, Metric metric) { this.executor = executor; - this.accessLog = accessLog; + this.ignored = ignored; this.metric = metric; } + + public Context(Executor executor, Metric metric) { + this(executor, null, metric); + } + public Context(Context other) { this.executor = other.executor; - this.accessLog = other.accessLog; + this.ignored = other.ignored; this.metric = other.metric; } public Executor getExecutor() { return executor; } - public AccessLog getAccessLog() { return accessLog; } + public AccessLog getAccessLog() { return ignored; } public Metric getMetric() { return metric; } } @@ -74,20 +80,19 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler { @Inject public LoggingRequestHandler(Context ctx) { - this(ctx.executor, ctx.accessLog, ctx.metric); + this(ctx.executor, ctx.ignored, ctx.metric); } public LoggingRequestHandler(Context ctx, boolean allowAsyncResponse) { - this(ctx.executor, ctx.accessLog, ctx.metric, allowAsyncResponse); + this(ctx.executor, ctx.ignored, ctx.metric, allowAsyncResponse); } - public LoggingRequestHandler(Executor executor, AccessLog accessLog, Metric metric) { - this(executor, accessLog, metric, false); + public LoggingRequestHandler(Executor executor, AccessLog ignored, Metric metric) { + this(executor, ignored, metric, false); } - public LoggingRequestHandler(Executor executor, AccessLog accessLog, Metric metric, boolean allowAsyncResponse) { + public LoggingRequestHandler(Executor executor, AccessLog ignored, Metric metric, boolean allowAsyncResponse) { super(executor, metric, allowAsyncResponse); - this.accessLog = accessLog; } @Override @@ -106,26 +111,6 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler { return clientAddress.toString(); } - private static long getEvalStart(Timing timing, long startTime) { - if (timing == null || timing.getQueryStartTime() == 0L) { - return startTime; - } else { - return timing.getQueryStartTime(); - } - } - - private static String remoteHostAddress(com.yahoo.jdisc.http.HttpRequest httpRequest) { - SocketAddress remoteAddress = httpRequest.getRemoteAddress(); - if (remoteAddress == null) return "0.0.0.0"; - - if (remoteAddress instanceof InetSocketAddress) { - return ((InetSocketAddress) remoteAddress).getAddress().getHostAddress(); - } else { - throw new RuntimeException("Expected remote address of type InetSocketAddress, got " + - remoteAddress.getClass().getName()); - } - } - private void logTimes(long startTime, String sourceIP, long renderStartTime, long commitStartTime, long endTime, String req, String normalizedQuery, Timing t) { @@ -257,21 +242,8 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler { // The request is created by JDisc http layer (Jetty) // Actual logging will be done by the Jetty integration; here, we just need to populate. entry = jdiscRequestAccessLogEntry.get(); - } else { - // Not running on JDisc http layer (Jetty), e.g unit tests - AccessLogEntry accessLogEntry = new AccessLogEntry(); - populateAccessLogEntryNotCreatedByHttpServer(accessLogEntry, - jdiscRequest, - extendedResponse.getTiming(), - httpRequest.getUri().toString(), - commitStartTime, - startTime, - rendererWiring.written(), - httpResponse.getStatus()); - accessLog.log(accessLogEntry); - entry = accessLogEntry; + httpResponse.populateAccessLogEntry(entry); } - httpResponse.populateAccessLogEntry(entry); } private String getUri(com.yahoo.jdisc.http.HttpRequest jdiscRequest) { @@ -285,36 +257,4 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler { } } - private void populateAccessLogEntryNotCreatedByHttpServer(AccessLogEntry logEntry, - com.yahoo.jdisc.http.HttpRequest httpRequest, - Timing timing, - String fullRequest, - long commitStartTime, - long startTime, - long written, - int status) { - try { - InetSocketAddress remoteAddress = AccessLogUtil.getRemoteAddress(httpRequest); - long evalStartTime = getEvalStart(timing, startTime); - logEntry.setIpV4Address(remoteHostAddress(httpRequest)); - logEntry.setTimeStamp(evalStartTime); - logEntry.setDurationBetweenRequestResponse(commitStartTime - evalStartTime); - logEntry.setReturnedContentSize(written); - logEntry.setStatusCode(status); - if (remoteAddress != null) { - logEntry.setRemoteAddress(remoteAddress); - logEntry.setRemotePort(remoteAddress.getPort()); - } - URI uri = AccessLogUtil.getUri(httpRequest); - logEntry.setRawPath(uri.getRawPath()); - logEntry.setRawQuery(uri.getRawQuery()); - logEntry.setUserAgent(AccessLogUtil.getUserAgentHeader(httpRequest)); - logEntry.setReferer(AccessLogUtil.getReferrerHeader(httpRequest)); - logEntry.setHttpMethod(AccessLogUtil.getHttpMethod(httpRequest)); - logEntry.setHttpVersion(AccessLogUtil.getHttpVersion(httpRequest)); - } catch (Exception e) { - log.log(Level.WARNING, "Could not populate the access log [" + fullRequest + "]", e); - } - } - } diff --git a/container-core/src/main/java/com/yahoo/processing/handler/ProcessingTestDriver.java b/container-core/src/main/java/com/yahoo/processing/handler/ProcessingTestDriver.java index d4e55dbc556..7170f63234e 100644 --- a/container-core/src/main/java/com/yahoo/processing/handler/ProcessingTestDriver.java +++ b/container-core/src/main/java/com/yahoo/processing/handler/ProcessingTestDriver.java @@ -7,7 +7,7 @@ import com.yahoo.component.chain.Chain; import com.yahoo.component.provider.ComponentRegistry; import com.yahoo.container.jdisc.RequestHandlerTestDriver; import com.yahoo.container.logging.AccessLog; -import com.yahoo.container.logging.AccessLogInterface; +import com.yahoo.container.logging.RequestLogHandler; import com.yahoo.processing.Processor; import com.yahoo.processing.execution.chain.ChainRegistry; import com.yahoo.processing.rendering.Renderer; @@ -60,15 +60,15 @@ public class ProcessingTestDriver extends RequestHandlerTestDriver { this.processingHandler = processingHandler; } - public ProcessingTestDriver(Chain<Processor> chain, AccessLogInterface accessLogInterface) { + public ProcessingTestDriver(Chain<Processor> chain, RequestLogHandler accessLogInterface) { this(createProcessingHandler( Collections.singleton(chain), new ComponentRegistry<>(), createAccessLog(accessLogInterface))); } - private static AccessLog createAccessLog(AccessLogInterface accessLogInterface) { - ComponentRegistry<AccessLogInterface> componentRegistry = new ComponentRegistry<>(); + private static AccessLog createAccessLog(RequestLogHandler accessLogInterface) { + ComponentRegistry<RequestLogHandler> componentRegistry = new ComponentRegistry<>(); componentRegistry.register(ComponentId.createAnonymousComponentId("access-log"), accessLogInterface); componentRegistry.freeze(); diff --git a/container-core/src/test/java/com/yahoo/container/jdisc/LoggingRequestHandlerTestCase.java b/container-core/src/test/java/com/yahoo/container/jdisc/LoggingRequestHandlerTestCase.java index 92fe347f7d1..734b3fa11af 100644 --- a/container-core/src/test/java/com/yahoo/container/jdisc/LoggingRequestHandlerTestCase.java +++ b/container-core/src/test/java/com/yahoo/container/jdisc/LoggingRequestHandlerTestCase.java @@ -1,51 +1,43 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.container.jdisc; -import static org.junit.Assert.*; - -import java.io.IOException; -import java.io.OutputStream; -import java.net.InetSocketAddress; -import java.net.URISyntaxException; -import java.nio.ByteBuffer; -import java.util.concurrent.ArrayBlockingQueue; -import java.util.concurrent.Executor; -import java.util.concurrent.ExecutorService; -import java.util.concurrent.Executors; -import java.util.concurrent.TimeUnit; - import com.google.inject.Key; +import com.yahoo.component.provider.ComponentRegistry; +import com.yahoo.container.handler.Coverage; +import com.yahoo.container.handler.Timing; +import com.yahoo.container.logging.AccessLog; import com.yahoo.container.logging.HitCounts; +import com.yahoo.container.logging.RequestLogHandler; import com.yahoo.jdisc.Container; import com.yahoo.jdisc.References; import com.yahoo.jdisc.ResourceReference; +import com.yahoo.jdisc.handler.CompletionHandler; +import com.yahoo.jdisc.handler.ContentChannel; import com.yahoo.jdisc.handler.RequestHandler; +import com.yahoo.jdisc.handler.ResponseHandler; import com.yahoo.jdisc.service.CurrentContainer; -import java.net.URI; import org.junit.After; import org.junit.Before; -import org.junit.Test; -import com.yahoo.component.ComponentId; -import com.yahoo.component.provider.ComponentRegistry; -import com.yahoo.container.handler.Coverage; -import com.yahoo.container.handler.Timing; -import com.yahoo.container.logging.AccessLog; -import com.yahoo.container.logging.AccessLogEntry; -import com.yahoo.container.logging.AccessLogInterface; -import com.yahoo.jdisc.handler.BufferedContentChannel; -import com.yahoo.jdisc.handler.CompletionHandler; -import com.yahoo.jdisc.handler.ContentChannel; -import com.yahoo.jdisc.handler.ResponseHandler; +import java.io.IOException; +import java.io.OutputStream; +import java.net.InetSocketAddress; +import java.net.URI; +import java.net.URISyntaxException; +import java.nio.ByteBuffer; +import java.util.concurrent.Executor; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; + +import static org.junit.Assert.fail; /** * Test contracts in LoggingRequestHandler. * - * @author <a href="mailto:steinar@yahoo-inc.com">Steinar Knutsen</a> + * @author Steinar Knutsen */ public class LoggingRequestHandlerTestCase { - StartTimePusher accessLogging; AccessLogTestHandler handler; ExecutorService executor; @@ -121,21 +113,9 @@ public class LoggingRequestHandlerTestCase { } - static final class StartTimePusher implements AccessLogInterface { - - public final ArrayBlockingQueue<Long> starts = new ArrayBlockingQueue<>(1); - - @Override - public void log(final AccessLogEntry accessLogEntry) { - starts.offer(Long.valueOf(accessLogEntry.getTimeStampMillis())); - } - } - @Before public void setUp() throws Exception { - accessLogging = new StartTimePusher(); - ComponentRegistry<AccessLogInterface> implementers = new ComponentRegistry<>(); - implementers.register(new ComponentId("nalle"), accessLogging); + ComponentRegistry<RequestLogHandler> implementers = new ComponentRegistry<>(); implementers.freeze(); executor = Executors.newCachedThreadPool(); handler = new AccessLogTestHandler(executor, new AccessLog(implementers)); @@ -143,31 +123,11 @@ public class LoggingRequestHandlerTestCase { @After public void tearDown() throws Exception { - accessLogging = null; handler = null; executor.shutdown(); executor = null; } - @Test - public final void checkStartIsNotZeroWithoutTimingInstance() throws InterruptedException { - Long startTime; - - MockResponseHandler responseHandler = new MockResponseHandler(); - com.yahoo.jdisc.http.HttpRequest request = createRequest(); - BufferedContentChannel requestContent = new BufferedContentChannel(); - requestContent.close(null); - handler.handleRequest(request, requestContent, responseHandler); - startTime = accessLogging.starts.poll(5, TimeUnit.MINUTES); - if (startTime == null) { - // test timed out, ignoring - } else { - assertFalse( - "Start time was 0, that should never happen after the first millisecond of 1970.", - startTime.longValue() == 0L); - } - } - public static com.yahoo.jdisc.http.HttpRequest createRequest() { return createRequest("http://localhost/search/?query=geewhiz"); } diff --git a/container-core/src/test/java/com/yahoo/processing/handler/ProcessingHandlerTestCase.java b/container-core/src/test/java/com/yahoo/processing/handler/ProcessingHandlerTestCase.java index 6498514c075..ae1076a4773 100644 --- a/container-core/src/test/java/com/yahoo/processing/handler/ProcessingHandlerTestCase.java +++ b/container-core/src/test/java/com/yahoo/processing/handler/ProcessingHandlerTestCase.java @@ -8,9 +8,10 @@ import com.yahoo.component.chain.Chain; import com.yahoo.component.provider.ComponentRegistry; import com.yahoo.container.jdisc.RequestHandlerTestDriver; import com.yahoo.container.logging.AccessLogEntry; -import com.yahoo.container.logging.AccessLogInterface; import com.yahoo.container.protect.Error; +import com.yahoo.jdisc.Request; import com.yahoo.jdisc.Response; +import com.yahoo.jdisc.handler.ContentChannel; import com.yahoo.jdisc.http.HttpRequest; import com.yahoo.processing.Processor; import com.yahoo.processing.execution.Execution; @@ -23,11 +24,11 @@ import com.yahoo.processing.test.ProcessorLibrary; import org.junit.After; import org.junit.Ignore; import org.junit.Test; -import org.mockito.ArgumentCaptor; -import org.mockito.Mockito; import java.io.IOException; import java.io.InputStream; +import java.net.URI; +import java.nio.ByteBuffer; import java.util.ArrayList; import java.util.Arrays; import java.util.Collections; @@ -37,17 +38,16 @@ import java.util.List; import java.util.Map; import java.util.concurrent.ExecutionException; +import static com.yahoo.jdisc.http.server.jetty.AccessLoggingRequestHandler.CONTEXT_KEY_ACCESS_LOG_ENTRY; import static com.yahoo.processing.test.ProcessorLibrary.MapData; import static org.hamcrest.CoreMatchers.is; import static org.hamcrest.CoreMatchers.notNullValue; import static org.hamcrest.CoreMatchers.sameInstance; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; -import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertNull; import static org.junit.Assert.assertThat; import static org.junit.Assert.assertTrue; -import static org.mockito.Mockito.times; /** * Tests processing handler scenarios end to end. @@ -83,18 +83,18 @@ public class ProcessingHandlerTestCase { } @Test - public void processing_handler_stores_trace_log_values_in_the_access_log_entry() throws InterruptedException { - ArgumentCaptor<AccessLogEntry> accessLogEntryCaptor = ArgumentCaptor.forClass(AccessLogEntry.class); - AccessLogInterface accessLog = Mockito.mock(AccessLogInterface.class); - - driver = new ProcessingTestDriver(logValueChain, accessLog); - driver.sendRequest("http://localhost/?chain=log-value").readAll(); - - Mockito.verify(accessLog, times(1)).log(accessLogEntryCaptor.capture()); - - AccessLogEntry entry = accessLogEntryCaptor.getValue(); - assertNotNull(entry); - assertThat(entry.getKeyValues().get(LOG_KEY), is(Collections.singletonList(LOG_VALUE))); + public void processing_handler_stores_trace_log_values_in_the_access_log_entry() { + driver = new ProcessingTestDriver(logValueChain); + Request request = HttpRequest.newServerRequest(driver.jDiscDriver(), URI.create("http://localhost/?chain=log-value"), HttpRequest.Method.GET); + AccessLogEntry entry = new AccessLogEntry(); + request.context().put(CONTEXT_KEY_ACCESS_LOG_ENTRY, entry); + RequestHandlerTestDriver.MockResponseHandler responseHandler = new RequestHandlerTestDriver.MockResponseHandler(); + ContentChannel requestContent = request.connect(responseHandler); + requestContent.write(ByteBuffer.allocate(0), null); + requestContent.close(null); + request.release(); + responseHandler.readAll(); + assertThat(entry.getKeyValues().get(LOG_KEY), is(List.of(LOG_VALUE))); } @Test diff --git a/jdisc_http_service/pom.xml b/jdisc_http_service/pom.xml index 1563a1a3d17..68a0f0636d3 100644 --- a/jdisc_http_service/pom.xml +++ b/jdisc_http_service/pom.xml @@ -145,6 +145,12 @@ <artifactId>assertj-core</artifactId> <scope>test</scope> </dependency> + <dependency> + <groupId>com.yahoo.vespa</groupId> + <artifactId>testutil</artifactId> + <version>${project.version}</version> + <scope>test</scope> + </dependency> </dependencies> <build> <plugins> diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java index 5c1a549070c..cdb4febb775 100644 --- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLog.java @@ -9,13 +9,14 @@ import com.yahoo.component.provider.ComponentRegistry; * Logs to all the configured access logs. * * @author Tony Vaagenes + * @author bjorncs */ -public class AccessLog { +public class AccessLog implements RequestLog { - private ComponentRegistry<AccessLogInterface> implementers; + private final ComponentRegistry<RequestLogHandler> implementers; @Inject - public AccessLog(ComponentRegistry<AccessLogInterface> implementers) { + public AccessLog(ComponentRegistry<RequestLogHandler> implementers) { this.implementers = implementers; } @@ -23,9 +24,10 @@ public class AccessLog { return new AccessLog(new ComponentRegistry<>()); } - public void log(AccessLogEntry accessLogEntry) { - for (AccessLogInterface log: implementers.allComponents()) { - log.log(accessLogEntry); + @Override + public void log(RequestLogEntry entry) { + for (RequestLogHandler handler: implementers.allComponents()) { + handler.log(entry); } } diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java deleted file mode 100644 index 12d29c2f333..00000000000 --- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogSampler.java +++ /dev/null @@ -1,37 +0,0 @@ -// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. -package com.yahoo.container.logging; - -import java.util.concurrent.atomic.AtomicLong; - -/** - * Samples entries from access log. It first samples every query until it have some data, and then sub-samples - * much less frequently to reduce CPU usage and latency impact. It only samples successful requests and requests - * that starts with /search. - * - * @author dybis - */ -public class AccessLogSampler implements AccessLogInterface { - - private final AtomicLong accessLineCounter = new AtomicLong(0); - private final CircularArrayAccessLogKeeper circularArrayAccessLogKeeper; - - public AccessLogSampler(CircularArrayAccessLogKeeper circularArrayAccessLogKeeper) { - this.circularArrayAccessLogKeeper = circularArrayAccessLogKeeper; - } - - @Override - public void log(AccessLogEntry accessLogEntry) { - if (accessLogEntry.getStatusCode() != 200) { - return; - } - String uriString = accessLogEntry.getRawPath(); - if (! uriString.startsWith("/search")) { - return; - } - final long count = accessLineCounter.incrementAndGet(); - if (count >= CircularArrayAccessLogKeeper.SIZE && count % CircularArrayAccessLogKeeper.SIZE != 0) { - return; - } - circularArrayAccessLogKeeper.addUri(uriString); - } -} 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 5a188d68e89..aa2df959a4c 100644 --- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONAccessLog.java @@ -11,7 +11,7 @@ import java.util.logging.Level; * @author frodelu * @author Tony Vaagenes */ -public final class JSONAccessLog implements AccessLogInterface { +public final class JSONAccessLog implements RequestLogHandler { private final AccessLogHandler logHandler; private final JSONFormatter formatter; @@ -22,8 +22,8 @@ public final class JSONAccessLog implements AccessLogInterface { } @Override - public void log(AccessLogEntry logEntry) { - logHandler.access.log(Level.INFO, formatter.format(logEntry) + '\n'); + public void log(RequestLogEntry entry) { + logHandler.access.log(Level.INFO, formatter.format(entry) + '\n'); } // TODO: This is never called. We should have a DI provider and call this method from its deconstruct. diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/JSONFormatter.java index b6ceaa08007..dc0acc4fbac 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 @@ -12,8 +12,7 @@ import java.io.IOException; import java.math.BigDecimal; import java.math.RoundingMode; import java.security.Principal; -import java.util.List; -import java.util.Map; +import java.util.Collection; import java.util.Objects; import java.util.logging.Level; import java.util.logging.Logger; @@ -42,76 +41,76 @@ public class JSONFormatter { } /** - * The main method for formatting the associated {@link AccessLogEntry} as a Vespa JSON access log string + * 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(AccessLogEntry accessLogEntry) { + public String format(RequestLogEntry entry) { ByteArrayOutputStream logLine = new ByteArrayOutputStream(); try { JsonGenerator generator = generatorFactory.createGenerator(logLine, JsonEncoding.UTF8); generator.writeStartObject(); - generator.writeStringField("ip", accessLogEntry.getIpV4Address()); - generator.writeNumberField("time", toTimestampInSeconds(accessLogEntry.getTimeStampMillis())); - generator.writeNumberField("duration", durationAsSeconds(accessLogEntry.getDurationBetweenRequestResponseMillis())); - generator.writeNumberField("responsesize", accessLogEntry.getReturnedContentSize()); - generator.writeNumberField("code", accessLogEntry.getStatusCode()); - generator.writeStringField("method", accessLogEntry.getHttpMethod()); - generator.writeStringField("uri", getNormalizedURI(accessLogEntry.getRawPath(), accessLogEntry.getRawQuery().orElse(null))); - generator.writeStringField("version", accessLogEntry.getHttpVersion()); - generator.writeStringField("agent", accessLogEntry.getUserAgent()); - generator.writeStringField("host", accessLogEntry.getHostString()); - generator.writeStringField("scheme", accessLogEntry.getScheme()); - generator.writeNumberField("localport", accessLogEntry.getLocalPort()); - - String connectionId = accessLogEntry.getConnectionId().orElse(null); + String peerAddress = entry.peerAddress().get(); + generator.writeStringField("ip", peerAddress); + long time = entry.timestamp().get().toEpochMilli(); + generator.writeNumberField("time", toTimestampInSeconds(time)); + generator.writeNumberField("duration", durationAsSeconds(entry.duration().get().toMillis())); + generator.writeNumberField("responsesize", entry.contentSize().orElse(0)); + generator.writeNumberField("code", entry.statusCode().orElse(0)); + generator.writeStringField("method", entry.httpMethod().orElse("")); + generator.writeStringField("uri", getNormalizedURI(entry.rawPath().get(), entry.rawQuery().orElse(null))); + generator.writeStringField("version", entry.httpVersion().orElse("")); + generator.writeStringField("agent", entry.userAgent().orElse("")); + generator.writeStringField("host", entry.hostString().orElse("")); + generator.writeStringField("scheme", entry.scheme().orElse(null)); + generator.writeNumberField("localport", entry.localPort().getAsInt()); + + String connectionId = entry.connectionId().orElse(null); if (connectionId != null) { generator.writeStringField("connection", connectionId); } - Principal principal = accessLogEntry.getUserPrincipal(); + Principal principal = entry.userPrincipal().orElse(null); if (principal != null) { generator.writeStringField("user-principal", principal.getName()); } - Principal sslPrincipal = accessLogEntry.getSslPrincipal(); - if (sslPrincipal != null) { - generator.writeStringField("ssl-principal", sslPrincipal.getName()); - } - + String remoteAddress = entry.remoteAddress().orElse(null); + int remotePort = entry.remotePort().orElse(0); // Only add remote address/port fields if relevant - if (remoteAddressDiffers(accessLogEntry.getIpV4Address(), accessLogEntry.getRemoteAddress())) { - generator.writeStringField("remoteaddr", accessLogEntry.getRemoteAddress()); - if (accessLogEntry.getRemotePort() > 0) { - generator.writeNumberField("remoteport", accessLogEntry.getRemotePort()); + if (remoteAddressDiffers(peerAddress, remoteAddress)) { + generator.writeStringField("remoteaddr", remoteAddress); + if (remotePort > 0) { + generator.writeNumberField("remoteport", remotePort); } } // Only add peer address/port fields if relevant - if (accessLogEntry.getPeerAddress() != null) { - generator.writeStringField("peeraddr", accessLogEntry.getPeerAddress()); + if (peerAddress != null) { + generator.writeStringField("peeraddr", peerAddress); - int peerPort = accessLogEntry.getPeerPort(); - if (peerPort > 0 && peerPort != accessLogEntry.getRemotePort()) { + int peerPort = entry.peerPort().getAsInt(); + if (peerPort > 0 && peerPort != remotePort) { generator.writeNumberField("peerport", peerPort); } } - TraceNode trace = accessLogEntry.getTrace(); + TraceNode trace = entry.traceNode().orElse(null); if (trace != null) { long timestamp = trace.timestamp(); if (timestamp == 0L) { - timestamp = accessLogEntry.getTimeStampMillis(); + timestamp = time; } trace.accept(new TraceRenderer(generator, timestamp)); } // Only add search sub block of this is a search request - if (isSearchRequest(accessLogEntry)) { + if (isSearchRequest(entry)) { + HitCounts hitCounts = entry.hitCounts().get(); generator.writeObjectFieldStart("search"); - generator.writeNumberField("totalhits", getTotalHitCount(accessLogEntry.getHitCounts())); - generator.writeNumberField("hits", getRetrievedHitCount(accessLogEntry.getHitCounts())); - Coverage c = accessLogEntry.getHitCounts().getCoverage(); + generator.writeNumberField("totalhits", getTotalHitCount(hitCounts)); + generator.writeNumberField("hits", getRetrievedHitCount(hitCounts)); + Coverage c = hitCounts.getCoverage(); if (c != null) { generator.writeObjectFieldStart(COVERAGE); generator.writeNumberField(COVERAGE_COVERAGE, c.getResultPercentage()); @@ -135,16 +134,17 @@ public class JSONFormatter { // Add key/value access log entries. Keys with single values are written as single // string value fields while keys with multiple values are written as string arrays - Map<String,List<String>> keyValues = accessLogEntry.getKeyValues(); - if (keyValues != null && !keyValues.isEmpty()) { + Collection<String> keys = entry.extraAttributeKeys(); + if (!keys.isEmpty()) { generator.writeObjectFieldStart("attributes"); - for (Map.Entry<String,List<String>> entry : keyValues.entrySet()) { - if (entry.getValue().size() == 1) { - generator.writeStringField(entry.getKey(), entry.getValue().get(0)); + for (String key : keys) { + Collection<String> values = entry.extraAttributeValues(key); + if (values.size() == 1) { + generator.writeStringField(key, values.iterator().next()); } else { - generator.writeFieldName(entry.getKey()); + generator.writeFieldName(key); generator.writeStartArray(); - for (String s : entry.getValue()) { + for (String s : values) { generator.writeString(s); } generator.writeEndArray(); @@ -168,8 +168,8 @@ public class JSONFormatter { return remoteAddress != null && !Objects.equals(ipV4Address, remoteAddress); } - private boolean isSearchRequest(AccessLogEntry logEntry) { - return logEntry != null && (logEntry.getHitCounts() != null); + private boolean isSearchRequest(RequestLogEntry entry) { + return entry != null && entry.hitCounts().isPresent(); } private long getTotalHitCount(HitCounts counts) { diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLog.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLog.java new file mode 100644 index 00000000000..2090ba1b9f1 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLog.java @@ -0,0 +1,13 @@ +// Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.container.logging; + +/** + * Access logging for requests + * + * @author bjorncs + */ +public interface RequestLog { + + void log(RequestLogEntry entry); + +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLogEntry.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLogEntry.java new file mode 100644 index 00000000000..b771ea11ed0 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLogEntry.java @@ -0,0 +1,181 @@ +// 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 com.yahoo.yolean.trace.TraceNode; + +import java.security.Principal; +import java.time.Duration; +import java.time.Instant; +import java.util.ArrayList; +import java.util.Collection; +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; +import java.util.Optional; +import java.util.OptionalInt; +import java.util.OptionalLong; + +import static java.util.Objects.requireNonNull; + +/** + * A immutable request log entry + * + * @author bjorncs + */ +public class RequestLogEntry { + + private final String connectionId; + private final Instant timestamp; + private final Duration duration; + private final int localPort; + private final String peerAddress; + private final int peerPort; + private final String remoteAddress; + private final int remotePort; + private final String userAgent; + private final String referer; + private final String httpMethod; + private final String httpVersion; + private final String hostString; + private final int statusCode; + private final long contentSize; + private final String scheme; + private final String rawPath; + private final String rawQuery; + private final Principal userPrincipal; + private final HitCounts hitCounts; + private final TraceNode traceNode; + private final Map<String, Collection<String>> extraAttributes; + + private RequestLogEntry(Builder builder) { + this.connectionId = builder.connectionId; + this.timestamp = builder.timestamp; + this.duration = builder.duration; + this.localPort = builder.localPort; + this.peerAddress = builder.peerAddress; + this.peerPort = builder.peerPort; + this.remoteAddress = builder.remoteAddress; + this.remotePort = builder.remotePort; + this.userAgent = builder.userAgent; + this.referer = builder.referer; + this.httpMethod = builder.httpMethod; + this.httpVersion = builder.httpVersion; + this.hostString = builder.hostString; + this.statusCode = builder.statusCode; + this.contentSize = builder.contentSize; + this.scheme = builder.scheme; + this.rawPath = builder.rawPath; + this.rawQuery = builder.rawQuery; + this.userPrincipal = builder.userPrincipal; + this.hitCounts = builder.hitCounts; + this.traceNode = builder.traceNode; + this.extraAttributes = copyExtraAttributes(builder.extraAttributes); + } + + public Optional<String> connectionId() { return Optional.ofNullable(connectionId); } + public Optional<Instant> timestamp() { return Optional.ofNullable(timestamp); } + public Optional<Duration> duration() { return Optional.ofNullable(duration); } + public OptionalInt localPort() { return optionalInt(localPort); } + public Optional<String> peerAddress() { return Optional.ofNullable(peerAddress); } + public OptionalInt peerPort() { return optionalInt(peerPort); } + public Optional<String> remoteAddress() { return Optional.ofNullable(remoteAddress); } + public OptionalInt remotePort() { return optionalInt(remotePort); } + public Optional<String> userAgent() { return Optional.ofNullable(userAgent); } + public Optional<String> referer() { return Optional.ofNullable(referer); } + public Optional<String> httpMethod() { return Optional.ofNullable(httpMethod); } + public Optional<String> httpVersion() { return Optional.ofNullable(httpVersion); } + public Optional<String> hostString() { return Optional.ofNullable(hostString); } + public OptionalInt statusCode() { return optionalInt(statusCode); } + public OptionalLong contentSize() { return optionalLong(contentSize); } + public Optional<String> scheme() { return Optional.ofNullable(scheme); } + public Optional<String> rawPath() { return Optional.ofNullable(rawPath); } + public Optional<String> rawQuery() { return Optional.ofNullable(rawQuery); } + public Optional<Principal> userPrincipal() { return Optional.ofNullable(userPrincipal); } + public Optional<HitCounts> hitCounts() { return Optional.ofNullable(hitCounts); } + public Optional<TraceNode> traceNode() { return Optional.ofNullable(traceNode); } + public Collection<String> extraAttributeKeys() { return Collections.unmodifiableCollection(extraAttributes.keySet()); } + public Collection<String> extraAttributeValues(String key) { return Collections.unmodifiableCollection(extraAttributes.get(key)); } + + private static OptionalInt optionalInt(int value) { + if (value == -1) return OptionalInt.empty(); + return OptionalInt.of(value); + } + + private static OptionalLong optionalLong(long value) { + if (value == -1) return OptionalLong.empty(); + return OptionalLong.of(value); + } + + private static Map<String, Collection<String>> copyExtraAttributes(Map<String, Collection<String>> extraAttributes) { + Map<String, Collection<String>> copy = new HashMap<>(); + extraAttributes.forEach((key, value) -> copy.put(key, new ArrayList<>(value))); + return copy; + } + + public static class Builder { + + private String connectionId; + private Instant timestamp; + private Duration duration; + private int localPort = -1; + private String peerAddress; + private int peerPort = -1; + private String remoteAddress; + private int remotePort = -1; + private String userAgent; + private String referer; + private String httpMethod; + private String httpVersion; + private String hostString; + private int statusCode = -1; + private long contentSize = -1; + private String scheme; + private String rawPath; + private String rawQuery; + private Principal userPrincipal; + private HitCounts hitCounts; + private TraceNode traceNode; + private final Map<String, Collection<String>> extraAttributes = new HashMap<>(); + + public Builder connectionId(String connectionId) { this.connectionId = requireNonNull(connectionId); return this; } + public Builder timestamp(Instant timestamp) { this.timestamp = requireNonNull(timestamp); return this; } + public Builder duration(Duration duration) { this.duration = requireNonNull(duration); return this; } + public Builder localPort(int localPort) { this.localPort = requireNonNegative(localPort); return this; } + public Builder peerAddress(String peerAddress) { this.peerAddress = requireNonNull(peerAddress); return this; } + public Builder peerPort(int peerPort) { this.peerPort = requireNonNegative(peerPort); return this; } + public Builder remoteAddress(String remoteAddress) { this.remoteAddress = requireNonNull(remoteAddress); return this; } + public Builder remotePort(int remotePort) { this.remotePort = requireNonNegative(remotePort); return this; } + public Builder userAgent(String userAgent) { this.userAgent = requireNonNull(userAgent); return this; } + public Builder referer(String referer) { this.referer = requireNonNull(referer); return this; } + public Builder httpMethod(String httpMethod) { this.httpMethod = requireNonNull(httpMethod); return this; } + public Builder httpVersion(String httpVersion) { this.httpVersion = requireNonNull(httpVersion); return this; } + public Builder hostString(String hostString) { this.hostString = requireNonNull(hostString); return this; } + public Builder statusCode(int statusCode) { this.statusCode = requireNonNegative(statusCode); return this; } + public Builder contentSize(long contentSize) { this.contentSize = requireNonNegative(contentSize); return this; } + public Builder scheme(String scheme) { this.scheme = requireNonNull(scheme); return this; } + public Builder rawPath(String rawPath) { this.rawPath = requireNonNull(rawPath); return this; } + public Builder rawQuery(String rawQuery) { this.rawQuery = requireNonNull(rawQuery); return this; } + public Builder userPrincipal(Principal userPrincipal) { this.userPrincipal = requireNonNull(userPrincipal); return this; } + public Builder hitCounts(HitCounts hitCounts) { this.hitCounts = requireNonNull(hitCounts); return this; } + public Builder traceNode(TraceNode traceNode) { this.traceNode = requireNonNull(traceNode); return this; } + public Builder addExtraAttribute(String key, String value) { + this.extraAttributes.computeIfAbsent(requireNonNull(key), __ -> new ArrayList<>()).add(requireNonNull(value)); + return this; + } + public Builder addExtraAttributes(String key, Collection<String> values) { + this.extraAttributes.computeIfAbsent(requireNonNull(key), __ -> new ArrayList<>()).addAll(requireNonNull(values)); + return this; + } + public RequestLogEntry build() { return new RequestLogEntry(this); } + + private static int requireNonNegative(int value) { + if (value < 0) throw new IllegalArgumentException("Value must be non-negative: " + value); + return value; + } + + private static long requireNonNegative(long value) { + if (value < 0) throw new IllegalArgumentException("Value must be non-negative: " + value); + return value; + } + } +} diff --git a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogInterface.java b/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLogHandler.java index 2523174abef..85df08e4abb 100644 --- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/AccessLogInterface.java +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/RequestLogHandler.java @@ -4,6 +4,6 @@ package com.yahoo.container.logging; /** * @author Tony Vaagenes */ -public interface AccessLogInterface { - void log(AccessLogEntry accessLogEntry); +public interface RequestLogHandler { + void log(RequestLogEntry entry); } 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 054fc0fcbf7..1040846dda3 100644 --- a/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java +++ b/jdisc_http_service/src/main/java/com/yahoo/container/logging/VespaAccessLog.java @@ -12,7 +12,7 @@ import java.util.logging.Level; * @author Bjorn Borud * @author Oyvind Bakksjo */ -public final class VespaAccessLog implements AccessLogInterface { +public final class VespaAccessLog implements RequestLogHandler { private static final ThreadLocal<SimpleDateFormat> dateFormat = ThreadLocal.withInitial(VespaAccessLog::createDateFormat); @@ -92,20 +92,20 @@ public final class VespaAccessLog implements AccessLogInterface { } @Override - public void log(final AccessLogEntry accessLogEntry) { + public void log(RequestLogEntry entry) { writeLog( - accessLogEntry.getIpV4Address(), - accessLogEntry.getUser(), + entry.peerAddress().get(), + null, getRequest( - accessLogEntry.getHttpMethod(), - accessLogEntry.getRawPath(), - accessLogEntry.getRawQuery().orElse(null), - accessLogEntry.getHttpVersion()), - accessLogEntry.getReferer(), - accessLogEntry.getUserAgent(), - accessLogEntry.getDurationBetweenRequestResponseMillis(), - accessLogEntry.getReturnedContentSize(), - accessLogEntry.getHitCounts(), - accessLogEntry.getStatusCode()); + 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)); } } diff --git a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java index 32790534f86..e82373fdaae 100644 --- a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java +++ b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLog.java @@ -4,20 +4,22 @@ package com.yahoo.jdisc.http.server.jetty; import com.google.common.base.Objects; import com.yahoo.container.logging.AccessLog; import com.yahoo.container.logging.AccessLogEntry; +import com.yahoo.container.logging.RequestLog; +import com.yahoo.container.logging.RequestLogEntry; import com.yahoo.jdisc.http.ServerConfig; import com.yahoo.jdisc.http.servlet.ServletRequest; import org.eclipse.jetty.server.Request; -import org.eclipse.jetty.server.RequestLog; import org.eclipse.jetty.server.Response; import org.eclipse.jetty.util.component.AbstractLifeCycle; import javax.servlet.http.HttpServletRequest; import java.security.Principal; -import java.security.cert.X509Certificate; +import java.time.Duration; +import java.time.Instant; import java.util.List; -import java.util.Optional; import java.util.OptionalInt; import java.util.UUID; +import java.util.function.BiConsumer; import java.util.logging.Level; import java.util.logging.Logger; @@ -30,19 +32,19 @@ import static com.yahoo.jdisc.http.core.HttpServletRequestUtils.getConnectorLoca * @author Oyvind Bakksjo * @author bjorncs */ -class AccessLogRequestLog extends AbstractLifeCycle implements RequestLog { +class AccessLogRequestLog extends AbstractLifeCycle implements org.eclipse.jetty.server.RequestLog { private static final Logger logger = Logger.getLogger(AccessLogRequestLog.class.getName()); // HTTP headers that are logged as extra key-value-pairs in access log entries private static final List<String> LOGGED_REQUEST_HEADERS = List.of("Vespa-Client-Version"); - private final AccessLog accessLog; + private final RequestLog requestLog; private final List<String> remoteAddressHeaders; private final List<String> remotePortHeaders; - AccessLogRequestLog(AccessLog accessLog, ServerConfig.AccessLog config) { - this.accessLog = accessLog; + AccessLogRequestLog(RequestLog requestLog, ServerConfig.AccessLog config) { + this.requestLog = requestLog; this.remoteAddressHeaders = config.remoteAddressHeaders(); this.remotePortHeaders = config.remotePortHeaders(); } @@ -50,83 +52,67 @@ class AccessLogRequestLog extends AbstractLifeCycle implements RequestLog { @Override public void log(Request request, Response response) { try { - AccessLogEntry accessLogEntry = Optional.ofNullable(request.getAttribute(JDiscHttpServlet.ATTRIBUTE_NAME_ACCESS_LOG_ENTRY)) - .map(AccessLogEntry.class::cast) - .orElseGet(AccessLogEntry::new); - - accessLogEntry.setRawPath(request.getRequestURI()); - String queryString = request.getQueryString(); - if (queryString != null) { - accessLogEntry.setRawQuery(queryString); - } - - accessLogEntry.setUserAgent(request.getHeader("User-Agent")); - accessLogEntry.setHttpMethod(request.getMethod()); - accessLogEntry.setHostString(request.getHeader("Host")); - accessLogEntry.setReferer(request.getHeader("Referer")); + RequestLogEntry.Builder builder = new RequestLogEntry.Builder(); String peerAddress = request.getRemoteAddr(); - accessLogEntry.setIpV4Address(peerAddress); - accessLogEntry.setPeerAddress(peerAddress); - String remoteAddress = getRemoteAddress(request); - if (!Objects.equal(remoteAddress, peerAddress)) { - accessLogEntry.setRemoteAddress(remoteAddress); - } - int peerPort = request.getRemotePort(); - accessLogEntry.setPeerPort(peerPort); - int remotePort = getRemotePort(request); - if (remotePort != peerPort) { - accessLogEntry.setRemotePort(remotePort); - } - accessLogEntry.setHttpVersion(request.getProtocol()); - accessLogEntry.setScheme(request.getScheme()); - accessLogEntry.setLocalPort(getConnectorLocalPort(request)); + long startTime = request.getTimeStamp(); + long endTime = System.currentTimeMillis(); + builder.peerAddress(peerAddress) + .peerPort(peerPort) + .localPort(getConnectorLocalPort(request)) + .timestamp(Instant.ofEpochMilli(startTime)) + .duration(Duration.ofMillis(endTime - startTime)) + .contentSize(response.getHttpChannel().getBytesWritten()) + .statusCode(response.getCommittedMetaData().getStatus()); + + addNonNullValue(builder, request.getMethod(), RequestLogEntry.Builder::httpMethod); + addNonNullValue(builder, request.getRequestURI(), RequestLogEntry.Builder::rawPath); + addNonNullValue(builder, request.getProtocol(), RequestLogEntry.Builder::httpVersion); + addNonNullValue(builder, request.getScheme(), RequestLogEntry.Builder::scheme); + addNonNullValue(builder, request.getHeader("User-Agent"), RequestLogEntry.Builder::userAgent); + addNonNullValue(builder, request.getHeader("Host"), RequestLogEntry.Builder::hostString); + addNonNullValue(builder, request.getHeader("Referer"), RequestLogEntry.Builder::referer); + addNonNullValue(builder, request.getQueryString(), RequestLogEntry.Builder::rawQuery); + Principal principal = (Principal) request.getAttribute(ServletRequest.JDISC_REQUEST_PRINCIPAL); - if (principal != null) { - accessLogEntry.setUserPrincipal(principal); - } - X509Certificate[] clientCert = (X509Certificate[]) request.getAttribute(ServletRequest.SERVLET_REQUEST_X509CERT); - if (clientCert != null && clientCert.length > 0) { - accessLogEntry.setSslPrincipal(clientCert[0].getSubjectX500Principal()); - } - String sslSessionId = (String) request.getAttribute(ServletRequest.SERVLET_REQUEST_SSL_SESSION_ID); - if (sslSessionId != null) { - accessLogEntry.addKeyValue("ssl-session-id", sslSessionId); - } - String cipherSuite = (String) request.getAttribute(ServletRequest.SERVLET_REQUEST_CIPHER_SUITE); - if (cipherSuite != null) { - accessLogEntry.addKeyValue("cipher-suite", cipherSuite); - } + addNonNullValue(builder, principal, RequestLogEntry.Builder::userPrincipal); + String requestFilterId = (String) request.getAttribute(ServletRequest.JDISC_REQUEST_CHAIN); - if (requestFilterId != null) { - accessLogEntry.addKeyValue("request-chain", requestFilterId); - } + addNonNullValue(builder, requestFilterId, (b, chain) -> b.addExtraAttribute("request-chain", chain)); + String responseFilterId = (String) request.getAttribute(ServletRequest.JDISC_RESPONSE_CHAIN); - if (responseFilterId != null) { - accessLogEntry.addKeyValue("response-chain", responseFilterId); - } + addNonNullValue(builder, responseFilterId, (b, chain) -> b.addExtraAttribute("response-chain", chain)); - long startTime = request.getTimeStamp(); - long endTime = System.currentTimeMillis(); - accessLogEntry.setTimeStamp(startTime); - accessLogEntry.setDurationBetweenRequestResponse(endTime - startTime); - accessLogEntry.setReturnedContentSize(response.getHttpChannel().getBytesWritten()); - accessLogEntry.setStatusCode(response.getCommittedMetaData().getStatus()); + UUID connectionId = (UUID) request.getAttribute(JettyConnectionLogger.CONNECTION_ID_REQUEST_ATTRIBUTE); + addNonNullValue(builder, connectionId, (b, uuid) -> b.connectionId(uuid.toString())); + String remoteAddress = getRemoteAddress(request); + if (!Objects.equal(remoteAddress, peerAddress)) { + builder.remoteAddress(remoteAddress); + } + int remotePort = getRemotePort(request); + if (remotePort != peerPort) { + builder.remotePort(remotePort); + } LOGGED_REQUEST_HEADERS.forEach(header -> { String value = request.getHeader(header); if (value != null) { - accessLogEntry.addKeyValue(header, value); + builder.addExtraAttribute(header, value); } }); - UUID connectionId = (UUID) request.getAttribute(JettyConnectionLogger.CONNECTION_ID_REQUEST_ATTRIBUTE); - if (connectionId != null) { - accessLogEntry.setConnectionId(connectionId.toString()); + AccessLogEntry accessLogEntry = (AccessLogEntry) request.getAttribute(JDiscHttpServlet.ATTRIBUTE_NAME_ACCESS_LOG_ENTRY); + if (accessLogEntry != null) { + var extraAttributes = accessLogEntry.getKeyValues(); + if (extraAttributes != null) { + extraAttributes.forEach(builder::addExtraAttributes); + } + addNonNullValue(builder, accessLogEntry.getHitCounts(), RequestLogEntry.Builder::hitCounts); + addNonNullValue(builder, accessLogEntry.getTrace(), RequestLogEntry.Builder::traceNode); } - accessLog.log(accessLogEntry); + requestLog.log(builder.build()); } catch (Exception e) { // Catching any exceptions here as it is unclear how Jetty handles exceptions from a RequestLog. logger.log(Level.SEVERE, "Failed to log access log entry: " + e.getMessage(), e); @@ -160,4 +146,11 @@ class AccessLogRequestLog extends AbstractLifeCycle implements RequestLog { } } + private static <T> void addNonNullValue( + RequestLogEntry.Builder builder, T value, BiConsumer<RequestLogEntry.Builder, T> setter) { + if (value != null) { + setter.accept(builder, value); + } + } + } diff --git a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyHttpServer.java b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyHttpServer.java index 1e077c32ea1..510c561c10f 100644 --- a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyHttpServer.java +++ b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JettyHttpServer.java @@ -7,6 +7,7 @@ import com.yahoo.component.provider.ComponentRegistry; import com.yahoo.concurrent.DaemonThreadFactory; import com.yahoo.container.logging.AccessLog; import com.yahoo.container.logging.ConnectionLog; +import com.yahoo.container.logging.RequestLog; import com.yahoo.jdisc.Metric; import com.yahoo.jdisc.http.ConnectorConfig; import com.yahoo.jdisc.http.ServerConfig; @@ -73,7 +74,7 @@ public class JettyHttpServer extends AbstractServerProvider { ComponentRegistry<ConnectorFactory> connectorFactories, ComponentRegistry<ServletHolder> servletHolders, FilterInvoker filterInvoker, - AccessLog accessLog, + RequestLog requestLog, ConnectionLog connectionLog) { super(container); if (connectorFactories.allComponents().isEmpty()) @@ -83,7 +84,7 @@ public class JettyHttpServer extends AbstractServerProvider { server = new Server(); server.setStopTimeout((long)(serverConfig.stopTimeout() * 1000.0)); - server.setRequestLog(new AccessLogRequestLog(accessLog, serverConfig.accessLog())); + server.setRequestLog(new AccessLogRequestLog(requestLog, serverConfig.accessLog())); setupJmx(server, serverConfig); configureJettyThreadpool(server, serverConfig); JettyConnectionLogger connectionLogger = new JettyConnectionLogger(serverConfig.connectionLog(), connectionLog); diff --git a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/VoidRequestLog.java b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/VoidRequestLog.java new file mode 100644 index 00000000000..9db5ba99115 --- /dev/null +++ b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/VoidRequestLog.java @@ -0,0 +1,14 @@ +// Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.jdisc.http.server.jetty; + +import com.yahoo.container.logging.RequestLog; +import com.yahoo.container.logging.RequestLogEntry; + +/** + * @author bjorncs + */ +public class VoidRequestLog implements RequestLog { + + @Override public void log(RequestLogEntry entry) {} + +} diff --git a/jdisc_http_service/src/test/java/com/yahoo/container/logging/AccessLogSamplerTest.java b/jdisc_http_service/src/test/java/com/yahoo/container/logging/AccessLogSamplerTest.java deleted file mode 100644 index 32a55b4bb72..00000000000 --- a/jdisc_http_service/src/test/java/com/yahoo/container/logging/AccessLogSamplerTest.java +++ /dev/null @@ -1,62 +0,0 @@ -// Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. -package com.yahoo.container.logging; - -import org.junit.Test; - -import java.util.ArrayList; -import java.util.List; - -import static org.hamcrest.CoreMatchers.hasItem; -import static org.hamcrest.CoreMatchers.hasItems; -import static org.hamcrest.CoreMatchers.is; -import static org.hamcrest.Matchers.contains; -import static org.junit.Assert.assertThat; - -public class AccessLogSamplerTest { - - private final List<String> uris = new ArrayList<>(); - private CircularArrayAccessLogKeeper circularArrayAccessLogKeeperMock = new CircularArrayAccessLogKeeper() { - @Override - public void addUri(String uri) { - uris.add(uri); - } - }; - private AccessLogSampler accessLogSampler = new AccessLogSampler(circularArrayAccessLogKeeperMock); - - @Test - public void testAFewLines() { - accessLogSampler.log(createLogEntry(200, "/search/foo")); - accessLogSampler.log(createLogEntry(500, "/search/bar")); - accessLogSampler.log(createLogEntry(500, "bar")); - accessLogSampler.log(createLogEntry(200, "/search/what")); - assertThat(uris, contains("/search/foo", "/search/what")); - } - - @Test - public void testSubSampling() { - for (int i = 0; i < CircularArrayAccessLogKeeper.SIZE; i++) { - accessLogSampler.log(createLogEntry(200, "/search/" + String.valueOf(i))); - } - assertThat(uris.size(), is(CircularArrayAccessLogKeeper.SIZE)); - assertThat(uris, hasItems("/search/0", "/search/1", "/search/2", - "/search/" + String.valueOf(CircularArrayAccessLogKeeper.SIZE - 1))); - uris.clear(); - for (int i = 0; i < CircularArrayAccessLogKeeper.SIZE; i++) { - accessLogSampler.log(createLogEntry(200, "/search/fuzz")); - } - assertThat(uris, hasItem("/search/fuzz")); - assertThat(uris.size(), is(1)); - for (int i = 0; i < CircularArrayAccessLogKeeper.SIZE; i++) { - accessLogSampler.log(createLogEntry(200, "/search/ball")); - } - assertThat(uris, hasItem("/search/ball")); - assertThat(uris.size(), is(2)); - } - - private AccessLogEntry createLogEntry(int statusCode, String uri) { - AccessLogEntry accessLogEntry = new AccessLogEntry(); - accessLogEntry.setStatusCode(statusCode); - accessLogEntry.setRawPath(uri); - return accessLogEntry; - } -} 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 703dcb95d95..f6a0d7418a0 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 @@ -6,8 +6,10 @@ import org.junit.Test; import java.io.IOException; import java.net.URI; +import java.time.Duration; +import java.time.Instant; -import static org.junit.Assert.assertEquals; +import static com.yahoo.test.json.JsonTestHelper.assertJsonEquals; /** @@ -19,25 +21,25 @@ public class JSONLogTestCase { private static final String EMPTY_REFERRER = ""; private static final String EMPTY_USERAGENT = ""; - private AccessLogEntry newAccessLogEntry(final String query) { - return newAccessLogEntry(query, new Coverage(100,100,100,0)); + private RequestLogEntry.Builder newRequestLogEntry(final String query) { + return newRequestLogEntry(query, new Coverage(100,100,100,0)); } - private AccessLogEntry newAccessLogEntry(final String query, Coverage coverage) { - final AccessLogEntry entry = new AccessLogEntry(); - entry.setRawQuery("query="+query); - entry.setRawPath(""); - entry.setIpV4Address(ipAddress); - entry.setHttpMethod("GET"); - entry.setHttpVersion("HTTP/1.1"); - entry.setUserAgent("Mozilla/4.05 [en] (Win95; I)"); - entry.setHitCounts(new HitCounts(0, 10, 1234, 0, 10, coverage)); - entry.setHostString("localhost"); - entry.setStatusCode(200); - entry.setTimeStamp(920880005023L); - entry.setDurationBetweenRequestResponse(122); - entry.setReturnedContentSize(9875); - - return entry; + private RequestLogEntry.Builder newRequestLogEntry(final String query, Coverage coverage) { + return new RequestLogEntry.Builder() + .rawQuery("query=" + query) + .rawPath("") + .peerAddress(ipAddress) + .httpMethod("GET") + .httpVersion("HTTP/1.1") + .userAgent("Mozilla/4.05 [en] (Win95; I)") + .hitCounts(new HitCounts(0, 10, 1234, 0, 10, coverage)) + .hostString("localhost") + .statusCode(200) + .timestamp(Instant.ofEpochMilli(920880005023L)) + .duration(Duration.ofMillis(122)) + .contentSize(9875) + .localPort(0) + .peerPort(0); } private static URI newQueryUri(final String query) { @@ -46,10 +48,11 @@ public class JSONLogTestCase { @Test public void test_json_log_entry() throws Exception { - AccessLogEntry entry = newAccessLogEntry("test"); + RequestLogEntry entry = newRequestLogEntry("test").build(); String expectedOutput = "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -68,17 +71,19 @@ public class JSONLogTestCase { "}" + "}"; - assertEquals(expectedOutput, new JSONFormatter().format(entry)); + assertJsonEquals(new JSONFormatter().format(entry), expectedOutput); } @Test public void test_json_of_trace() throws IOException { TraceNode root = new TraceNode("root", 7); - AccessLogEntry entry = newAccessLogEntry("test"); - entry.setTrace(root); + RequestLogEntry entry = newRequestLogEntry("test") + .traceNode(root) + .build(); String expectedOutput = "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -98,18 +103,20 @@ public class JSONLogTestCase { "}" + "}"; - assertEquals(expectedOutput, new JSONFormatter().format(entry)); + assertJsonEquals(new JSONFormatter().format(entry), expectedOutput); } @Test public void test_with_keyvalues() { - AccessLogEntry entry = newAccessLogEntry("test"); - entry.addKeyValue("singlevalue", "value1"); - entry.addKeyValue("multivalue", "value2"); - entry.addKeyValue("multivalue", "value3"); + RequestLogEntry entry = newRequestLogEntry("test") + .addExtraAttribute("singlevalue", "value1") + .addExtraAttribute("multivalue", "value2") + .addExtraAttribute("multivalue", "value3") + .build(); String expectedOutput = "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -131,19 +138,19 @@ public class JSONLogTestCase { "\"multivalue\":[\"value2\",\"value3\"]}" + "}"; - assertEquals(expectedOutput, new JSONFormatter().format(entry)); + assertJsonEquals(new JSONFormatter().format(entry), expectedOutput); } @Test public void test_with_remoteaddrport() throws Exception { - AccessLogEntry entry = newAccessLogEntry("test"); - - // First test with only remote address and not port set - entry.setRemoteAddress("FE80:0000:0000:0000:0202:B3FF:FE1E:8329"); + RequestLogEntry entry = newRequestLogEntry("test") + .remoteAddress("FE80:0000:0000:0000:0202:B3FF:FE1E:8329") + .build(); String expectedOutput = "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -163,13 +170,17 @@ public class JSONLogTestCase { "}" + "}"; - assertEquals(expectedOutput, new JSONFormatter().format(entry)); + assertJsonEquals(new JSONFormatter().format(entry), expectedOutput); // Add remote port and verify - entry.setRemotePort(1234); + entry = newRequestLogEntry("test") + .remoteAddress("FE80:0000:0000:0000:0202:B3FF:FE1E:8329") + .remotePort(1234) + .build(); expectedOutput = "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -190,36 +201,41 @@ public class JSONLogTestCase { "}" + "}"; - assertEquals(expectedOutput, new JSONFormatter().format(entry)); + assertJsonEquals(new JSONFormatter().format(entry), expectedOutput); } @Test public void test_remote_address_same_as_ip_address() throws Exception { - AccessLogEntry entry = newAccessLogEntry("test"); - AccessLogEntry entrywithremote = newAccessLogEntry("test"); - entrywithremote.setRemoteAddress(entry.getIpV4Address()); + RequestLogEntry entry = newRequestLogEntry("test").build(); + RequestLogEntry entrywithremote = newRequestLogEntry("test") + .remoteAddress(entry.peerAddress().get()) + .build(); JSONFormatter formatter = new JSONFormatter(); - assertEquals(formatter.format(entry), formatter.format(entrywithremote)); + assertJsonEquals(formatter.format(entry), formatter.format(entrywithremote)); } @Test public void test_useragent_with_quotes() { - final AccessLogEntry entry = new AccessLogEntry(); - entry.setRawQuery("query=test"); - entry.setRawPath(""); - entry.setIpV4Address(ipAddress); - entry.setHttpMethod("GET"); - entry.setHttpVersion("HTTP/1.1"); - entry.setUserAgent("Mozilla/4.05 [en] (Win95; I; \"Best Browser Ever\")"); - entry.setHitCounts(new HitCounts(0, 10, 1234, 0, 10, new Coverage(100,200,200,0))); - entry.setHostString("localhost"); - entry.setStatusCode(200); - entry.setTimeStamp(920880005023L); - entry.setDurationBetweenRequestResponse(122); - entry.setReturnedContentSize(9875); + RequestLogEntry entry = new RequestLogEntry.Builder() + .rawQuery("query=test") + .rawPath("") + .peerAddress(ipAddress) + .httpMethod("GET") + .httpVersion("HTTP/1.1") + .userAgent("Mozilla/4.05 [en] (Win95; I; \"Best Browser Ever\")") + .hitCounts(new HitCounts(0, 10, 1234, 0, 10, new Coverage(100, 200, 200, 0))) + .hostString("localhost") + .statusCode(200) + .timestamp(Instant.ofEpochMilli(920880005023L)) + .duration(Duration.ofMillis(122)) + .contentSize(9875) + .localPort(0) + .peerPort(0) + .build(); String expectedOutput = "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -238,11 +254,13 @@ public class JSONLogTestCase { "}" + "}"; - assertEquals(expectedOutput, new JSONFormatter().format(entry)); + assertJsonEquals(new JSONFormatter().format(entry), expectedOutput); } - private void verifyCoverage(String coverage, AccessLogEntry entry) { - assertEquals("{\"ip\":\"152.200.54.243\"," + + private void verifyCoverage(String coverage, RequestLogEntry entry) { + assertJsonEquals(new JSONFormatter().format(entry), + "{\"ip\":\"152.200.54.243\"," + + "\"peeraddr\":\"152.200.54.243\"," + "\"time\":920880005.023," + "\"duration\":0.122," + "\"responsesize\":9875," + @@ -259,18 +277,18 @@ public class JSONLogTestCase { "\"hits\":0," + coverage + "}" + - "}", new JSONFormatter().format(entry)); + "}"); } @Test public void test_with_coverage_degradation() { verifyCoverage("\"coverage\":{\"coverage\":50,\"documents\":100,\"degraded\":{\"non-ideal-state\":true}}", - newAccessLogEntry("test", new Coverage(100,200,200,0))); + newRequestLogEntry("test", new Coverage(100,200,200,0)).build()); verifyCoverage("\"coverage\":{\"coverage\":50,\"documents\":100,\"degraded\":{\"match-phase\":true}}", - newAccessLogEntry("test", new Coverage(100,200,200,1))); + newRequestLogEntry("test", new Coverage(100,200,200,1)).build()); verifyCoverage("\"coverage\":{\"coverage\":50,\"documents\":100,\"degraded\":{\"timeout\":true}}", - newAccessLogEntry("test", new Coverage(100,200,200,2))); + newRequestLogEntry("test", new Coverage(100,200,200,2)).build()); verifyCoverage("\"coverage\":{\"coverage\":50,\"documents\":100,\"degraded\":{\"adaptive-timeout\":true}}", - newAccessLogEntry("test", new Coverage(100,200,200,4))); + newRequestLogEntry("test", new Coverage(100,200,200,4)).build()); } } diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLogTest.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLogTest.java index a4fd7c9bc5f..c9b466517b3 100644 --- a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLogTest.java +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/AccessLogRequestLogTest.java @@ -1,8 +1,9 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.jdisc.http.server.jetty; -import com.yahoo.container.logging.AccessLog; import com.yahoo.container.logging.AccessLogEntry; +import com.yahoo.container.logging.RequestLog; +import com.yahoo.container.logging.RequestLogEntry; import com.yahoo.jdisc.http.ServerConfig; import org.eclipse.jetty.http.MetaData; import org.eclipse.jetty.server.HttpChannel; @@ -19,6 +20,7 @@ import static org.hamcrest.CoreMatchers.is; import static org.hamcrest.CoreMatchers.not; import static org.hamcrest.CoreMatchers.nullValue; import static org.hamcrest.MatcherAssert.assertThat; +import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertTrue; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.when; @@ -30,103 +32,115 @@ import static org.mockito.Mockito.when; public class AccessLogRequestLogTest { @Test public void requireThatQueryWithUnquotedSpecialCharactersIsHandled() { - final AccessLogEntry accessLogEntry = new AccessLogEntry(); - final Request jettyRequest = createRequestMock(accessLogEntry); + final Request jettyRequest = createRequestMock(); when(jettyRequest.getRequestURI()).thenReturn("/search/"); when(jettyRequest.getQueryString()).thenReturn("query=year:>2010"); - doAccessLoggingOfRequest(jettyRequest); + InMemoryRequestLog requestLog = new InMemoryRequestLog(); + doAccessLoggingOfRequest(requestLog, jettyRequest); + RequestLogEntry entry = requestLog.entries().get(0); - assertThat(accessLogEntry.getRawPath(), is(not(nullValue()))); - assertTrue(accessLogEntry.getRawQuery().isPresent()); + assertThat(entry.rawPath().get(), is(not(nullValue()))); + assertTrue(entry.rawQuery().isPresent()); } @Test public void requireThatDoubleQuotingIsNotPerformed() { - final AccessLogEntry accessLogEntry = new AccessLogEntry(); - final Request jettyRequest = createRequestMock(accessLogEntry); + final Request jettyRequest = createRequestMock(); final String path = "/search/"; when(jettyRequest.getRequestURI()).thenReturn(path); final String query = "query=year%252010+%3B&customParameter=something"; when(jettyRequest.getQueryString()).thenReturn(query); - doAccessLoggingOfRequest(jettyRequest); + InMemoryRequestLog requestLog = new InMemoryRequestLog(); + doAccessLoggingOfRequest(requestLog, jettyRequest); + RequestLogEntry entry = requestLog.entries().get(0); - assertThat(accessLogEntry.getRawPath(), is(path)); - assertThat(accessLogEntry.getRawQuery().get(), is(query)); + assertThat(entry.rawPath().get(), is(path)); + assertThat(entry.rawQuery().get(), is(query)); } @Test public void raw_path_and_query_are_set_from_request() { - AccessLogEntry accessLogEntry = new AccessLogEntry(); - Request jettyRequest = createRequestMock(accessLogEntry); + Request jettyRequest = createRequestMock(); String rawPath = "//search/"; when(jettyRequest.getRequestURI()).thenReturn(rawPath); String rawQuery = "q=%%2"; when(jettyRequest.getQueryString()).thenReturn(rawQuery); - doAccessLoggingOfRequest(jettyRequest); - assertThat(accessLogEntry.getRawPath(), is(rawPath)); - Optional<String> actualRawQuery = accessLogEntry.getRawQuery(); + InMemoryRequestLog requestLog = new InMemoryRequestLog(); + doAccessLoggingOfRequest(requestLog, jettyRequest); + RequestLogEntry entry = requestLog.entries().get(0); + assertThat(entry.rawPath().get(), is(rawPath)); + Optional<String> actualRawQuery = entry.rawQuery(); assertThat(actualRawQuery.isPresent(), is(true)); assertThat(actualRawQuery.get(), is(rawQuery)); } @Test public void verify_x_forwarded_for_precedence () { - AccessLogEntry accessLogEntry = new AccessLogEntry(); - Request jettyRequest = createRequestMock(accessLogEntry); + Request jettyRequest = createRequestMock(); when(jettyRequest.getRequestURI()).thenReturn("//search/"); when(jettyRequest.getQueryString()).thenReturn("q=%%2"); when(jettyRequest.getHeader("x-forwarded-for")).thenReturn("1.2.3.4"); when(jettyRequest.getHeader("y-ra")).thenReturn("2.3.4.5"); - doAccessLoggingOfRequest(jettyRequest); - assertThat(accessLogEntry.getRemoteAddress(), is("1.2.3.4")); + InMemoryRequestLog requestLog = new InMemoryRequestLog(); + doAccessLoggingOfRequest(requestLog, jettyRequest); + RequestLogEntry entry = requestLog.entries().get(0); + assertThat(entry.remoteAddress().get(), is("1.2.3.4")); } @Test public void verify_x_forwarded_port_precedence () { - AccessLogEntry accessLogEntry = new AccessLogEntry(); - Request jettyRequest = createRequestMock(accessLogEntry); + Request jettyRequest = createRequestMock(); when(jettyRequest.getRequestURI()).thenReturn("//search/"); when(jettyRequest.getQueryString()).thenReturn("q=%%2"); when(jettyRequest.getHeader("X-Forwarded-Port")).thenReturn("80"); when(jettyRequest.getHeader("y-rp")).thenReturn("8080"); - doAccessLoggingOfRequest(jettyRequest); - assertThat(accessLogEntry.getRemotePort(), is(80)); + InMemoryRequestLog requestLog = new InMemoryRequestLog(); + doAccessLoggingOfRequest(requestLog, jettyRequest); + RequestLogEntry entry = requestLog.entries().get(0); + assertThat(entry.remotePort().getAsInt(), is(80)); } @Test public void defaults_to_peer_port_if_remote_port_header_is_invalid() { - final AccessLogEntry accessLogEntry = new AccessLogEntry(); - final Request jettyRequest = createRequestMock(accessLogEntry); + final Request jettyRequest = createRequestMock(); when(jettyRequest.getRequestURI()).thenReturn("/search/"); when(jettyRequest.getHeader("X-Forwarded-Port")).thenReturn("8o8o"); when(jettyRequest.getRemotePort()).thenReturn(80); - doAccessLoggingOfRequest(jettyRequest); - assertThat(accessLogEntry.getRemotePort(), is(0)); - assertThat(accessLogEntry.getPeerPort(), is(80)); + InMemoryRequestLog requestLog = new InMemoryRequestLog(); + doAccessLoggingOfRequest(requestLog, jettyRequest); + RequestLogEntry entry = requestLog.entries().get(0); + assertFalse(entry.remotePort().isPresent()); + assertThat(entry.peerPort().getAsInt(), is(80)); } - private void doAccessLoggingOfRequest(Request jettyRequest) { + private void doAccessLoggingOfRequest(RequestLog requestLog, Request jettyRequest) { ServerConfig.AccessLog config = new ServerConfig.AccessLog( new ServerConfig.AccessLog.Builder() .remoteAddressHeaders(List.of("x-forwarded-for", "y-ra")) .remotePortHeaders(List.of("X-Forwarded-Port", "y-rp"))); - new AccessLogRequestLog(mock(AccessLog.class), config).log(jettyRequest, createResponseMock()); + new AccessLogRequestLog(requestLog, config).log(jettyRequest, createResponseMock()); } - private static Request createRequestMock(AccessLogEntry entry) { + private static Request createRequestMock() { ServerConnector serverConnector = mock(ServerConnector.class); when(serverConnector.getLocalPort()).thenReturn(1234); HttpConnection httpConnection = mock(HttpConnection.class); when(httpConnection.getConnector()).thenReturn(serverConnector); Request request = mock(Request.class); - when(request.getAttribute(JDiscHttpServlet.ATTRIBUTE_NAME_ACCESS_LOG_ENTRY)).thenReturn(entry); + when(request.getMethod()).thenReturn("GET"); + when(request.getRemoteAddr()).thenReturn("localhost"); + when(request.getRemotePort()).thenReturn(12345); + when(request.getProtocol()).thenReturn("HTTP/1.1"); + when(request.getScheme()).thenReturn("http"); + when(request.getTimeStamp()).thenReturn(0L); + when(request.getAttribute(JDiscHttpServlet.ATTRIBUTE_NAME_ACCESS_LOG_ENTRY)).thenReturn(new AccessLogEntry()); when(request.getAttribute("org.eclipse.jetty.server.HttpConnection")).thenReturn(httpConnection); return request; } diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/FilterTestCase.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/FilterTestCase.java index 33fbe4e3016..a67656dd5ca 100644 --- a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/FilterTestCase.java +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/FilterTestCase.java @@ -4,6 +4,7 @@ package com.yahoo.jdisc.http.server.jetty; import com.google.inject.AbstractModule; import com.google.inject.util.Modules; import com.yahoo.container.logging.ConnectionLog; +import com.yahoo.container.logging.RequestLog; import com.yahoo.jdisc.AbstractResource; import com.yahoo.jdisc.Request; import com.yahoo.jdisc.ResourceReference; @@ -556,6 +557,7 @@ public class FilterTestCase { bind(ConnectorConfig.class).toInstance(new ConnectorConfig(new ConnectorConfig.Builder())); bind(ServletPathsConfig.class).toInstance(new ServletPathsConfig(new ServletPathsConfig.Builder())); bind(ConnectionLog.class).toInstance(new VoidConnectionLog()); + bind(RequestLog.class).toInstance(new VoidRequestLog()); } }, new ConnectorFactoryRegistryModule(), diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerConformanceTest.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerConformanceTest.java index 2f8e35fffa6..5659dfc2d3c 100644 --- a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerConformanceTest.java +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerConformanceTest.java @@ -5,6 +5,7 @@ import com.google.inject.AbstractModule; import com.google.inject.Module; import com.google.inject.util.Modules; import com.yahoo.container.logging.ConnectionLog; +import com.yahoo.container.logging.RequestLog; import com.yahoo.jdisc.http.ServerConfig; import com.yahoo.jdisc.http.ServletPathsConfig; import com.yahoo.jdisc.http.guiceModules.ConnectorFactoryRegistryModule; @@ -776,6 +777,8 @@ public class HttpServerConformanceTest extends ServerProviderConformanceTest { .toInstance(new ServletPathsConfig(new ServletPathsConfig.Builder())); bind(ConnectionLog.class) .toInstance(new VoidConnectionLog()); + bind(RequestLog.class) + .toInstance(new VoidRequestLog()); } }, new ConnectorFactoryRegistryModule()); diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerTest.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerTest.java index 81ccb2ccb1c..96464a48938 100644 --- a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerTest.java +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/HttpServerTest.java @@ -3,10 +3,10 @@ package com.yahoo.jdisc.http.server.jetty; import com.google.inject.AbstractModule; import com.google.inject.Module; -import com.yahoo.container.logging.AccessLog; -import com.yahoo.container.logging.AccessLogEntry; import com.yahoo.container.logging.ConnectionLog; import com.yahoo.container.logging.ConnectionLogEntry; +import com.yahoo.container.logging.RequestLog; +import com.yahoo.container.logging.RequestLogEntry; import com.yahoo.jdisc.References; import com.yahoo.jdisc.Request; import com.yahoo.jdisc.Response; @@ -71,7 +71,6 @@ import java.util.List; import java.util.Map; import java.util.TreeMap; import java.util.UUID; -import java.util.concurrent.CopyOnWriteArrayList; import java.util.concurrent.ExecutionException; import java.util.concurrent.TimeUnit; import java.util.logging.Level; @@ -176,31 +175,18 @@ public class HttpServerTest { @Test public void requireThatAccessLogIsCalledForRequestRejectedByJetty() throws Exception { - AccessLogMock accessLogMock = new AccessLogMock(); + InMemoryRequestLog requestLogMock = new InMemoryRequestLog(); final TestDriver driver = TestDrivers.newConfiguredInstance( mockRequestHandler(), new ServerConfig.Builder(), new ConnectorConfig.Builder().requestHeaderSize(1), - binder -> binder.bind(AccessLog.class).toInstance(accessLogMock)); + binder -> binder.bind(RequestLog.class).toInstance(requestLogMock)); driver.client().get("/status.html") .expectStatusCode(is(REQUEST_URI_TOO_LONG)); assertThat(driver.close(), is(true)); - - assertThat(accessLogMock.logEntries.size(), equalTo(1)); - AccessLogEntry accessLogEntry = accessLogMock.logEntries.get(0); - assertEquals(414, accessLogEntry.getStatusCode()); - } - - private static class AccessLogMock extends AccessLog { - - final List<AccessLogEntry> logEntries = new CopyOnWriteArrayList<>(); - - AccessLogMock() { super(null); } - - @Override - public void log(AccessLogEntry accessLogEntry) { - logEntries.add(accessLogEntry); - } + assertThat(requestLogMock.entries().size(), equalTo(1)); + RequestLogEntry entry = requestLogMock.entries().get(0); + assertEquals(414, entry.statusCode().getAsInt()); } @Test @@ -776,9 +762,9 @@ public class HttpServerTest { Path privateKeyFile = tmpFolder.newFile().toPath(); Path certificateFile = tmpFolder.newFile().toPath(); generatePrivateKeyAndCertificate(privateKeyFile, certificateFile); - AccessLogMock accessLogMock = new AccessLogMock(); + InMemoryRequestLog requestLogMock = new InMemoryRequestLog(); InMemoryConnectionLog connectionLog = new InMemoryConnectionLog(); - TestDriver driver = createSslWithProxyProtocolTestDriver(certificateFile, privateKeyFile, accessLogMock, /*mixedMode*/connectionLog, false); + TestDriver driver = createSslWithProxyProtocolTestDriver(certificateFile, privateKeyFile, requestLogMock, /*mixedMode*/connectionLog, false); String proxiedRemoteAddress = "192.168.0.100"; int proxiedRemotePort = 12345; @@ -786,9 +772,9 @@ public class HttpServerTest { sendJettyClientRequest(driver, certificateFile, new V2.Tag(proxiedRemoteAddress, proxiedRemotePort)); assertTrue(driver.close()); - assertEquals(2, accessLogMock.logEntries.size()); - assertLogEntryHasRemote(accessLogMock.logEntries.get(0), proxiedRemoteAddress, proxiedRemotePort); - assertLogEntryHasRemote(accessLogMock.logEntries.get(1), proxiedRemoteAddress, proxiedRemotePort); + assertEquals(2, requestLogMock.entries().size()); + assertLogEntryHasRemote(requestLogMock.entries().get(0), proxiedRemoteAddress, proxiedRemotePort); + assertLogEntryHasRemote(requestLogMock.entries().get(1), proxiedRemoteAddress, proxiedRemotePort); Assertions.assertThat(connectionLog.logEntries()).hasSize(2); assertLogEntryHasRemote(connectionLog.logEntries().get(0), proxiedRemoteAddress, proxiedRemotePort); assertLogEntryHasRemote(connectionLog.logEntries().get(1), proxiedRemoteAddress, proxiedRemotePort); @@ -799,18 +785,18 @@ public class HttpServerTest { Path privateKeyFile = tmpFolder.newFile().toPath(); Path certificateFile = tmpFolder.newFile().toPath(); generatePrivateKeyAndCertificate(privateKeyFile, certificateFile); - AccessLogMock accessLogMock = new AccessLogMock(); + InMemoryRequestLog requestLogMock = new InMemoryRequestLog(); InMemoryConnectionLog connectionLog = new InMemoryConnectionLog(); - TestDriver driver = createSslWithProxyProtocolTestDriver(certificateFile, privateKeyFile, accessLogMock, /*mixedMode*/connectionLog, true); + TestDriver driver = createSslWithProxyProtocolTestDriver(certificateFile, privateKeyFile, requestLogMock, /*mixedMode*/connectionLog, true); String proxiedRemoteAddress = "192.168.0.100"; sendJettyClientRequest(driver, certificateFile, null); sendJettyClientRequest(driver, certificateFile, new V2.Tag(proxiedRemoteAddress, 12345)); assertTrue(driver.close()); - assertEquals(2, accessLogMock.logEntries.size()); - assertLogEntryHasRemote(accessLogMock.logEntries.get(0), "127.0.0.1", 0); - assertLogEntryHasRemote(accessLogMock.logEntries.get(1), proxiedRemoteAddress, 0); + assertEquals(2, requestLogMock.entries().size()); + assertLogEntryHasRemote(requestLogMock.entries().get(0), "127.0.0.1", 0); + assertLogEntryHasRemote(requestLogMock.entries().get(1), proxiedRemoteAddress, 0); Assertions.assertThat(connectionLog.logEntries()).hasSize(2); assertLogEntryHasRemote(connectionLog.logEntries().get(0), null, 0); assertLogEntryHasRemote(connectionLog.logEntries().get(1), proxiedRemoteAddress, 12345); @@ -821,9 +807,9 @@ public class HttpServerTest { Path privateKeyFile = tmpFolder.newFile().toPath(); Path certificateFile = tmpFolder.newFile().toPath(); generatePrivateKeyAndCertificate(privateKeyFile, certificateFile); - AccessLogMock accessLogMock = new AccessLogMock(); + InMemoryRequestLog requestLogMock = new InMemoryRequestLog(); InMemoryConnectionLog connectionLog = new InMemoryConnectionLog(); - TestDriver driver = createSslWithProxyProtocolTestDriver(certificateFile, privateKeyFile, accessLogMock, connectionLog, /*mixedMode*/false); + TestDriver driver = createSslWithProxyProtocolTestDriver(certificateFile, privateKeyFile, requestLogMock, connectionLog, /*mixedMode*/false); String proxiedRemoteAddress = "192.168.0.100"; int proxiedRemotePort = 12345; @@ -906,10 +892,10 @@ public class HttpServerTest { return client; } - private static void assertLogEntryHasRemote(AccessLogEntry entry, String expectedAddress, int expectedPort) { - assertEquals(expectedAddress, entry.getPeerAddress()); + private static void assertLogEntryHasRemote(RequestLogEntry entry, String expectedAddress, int expectedPort) { + assertEquals(expectedAddress, entry.peerAddress().get()); if (expectedPort > 0) { - assertEquals(expectedPort, entry.getPeerPort()); + assertEquals(expectedPort, entry.peerPort().getAsInt()); } } @@ -927,8 +913,8 @@ public class HttpServerTest { } private static TestDriver createSslWithProxyProtocolTestDriver( - Path certificateFile, Path privateKeyFile, AccessLogMock accessLogMock, - InMemoryConnectionLog connectionLog, boolean mixedMode) { + Path certificateFile, Path privateKeyFile, RequestLog requestLog, + ConnectionLog connectionLog, boolean mixedMode) { ConnectorConfig.Builder connectorConfig = new ConnectorConfig.Builder() .proxyProtocol(new ConnectorConfig.ProxyProtocol.Builder() .enabled(true) @@ -943,7 +929,7 @@ public class HttpServerTest { new ServerConfig.Builder().connectionLog(new ServerConfig.ConnectionLog.Builder().enabled(true)), connectorConfig, binder -> { - binder.bind(AccessLog.class).toInstance(accessLogMock); + binder.bind(RequestLog.class).toInstance(requestLog); binder.bind(ConnectionLog.class).toInstance(connectionLog); }); } diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/InMemoryRequestLog.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/InMemoryRequestLog.java new file mode 100644 index 00000000000..b87ec5e8b8b --- /dev/null +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/InMemoryRequestLog.java @@ -0,0 +1,20 @@ +// Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. +package com.yahoo.jdisc.http.server.jetty; + +import com.yahoo.container.logging.RequestLog; +import com.yahoo.container.logging.RequestLogEntry; + +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; + +/** + * @author bjorncs + */ +public class InMemoryRequestLog implements RequestLog { + + private final List<RequestLogEntry> entries = new CopyOnWriteArrayList<>(); + + @Override public void log(RequestLogEntry entry) { entries.add(entry); } + + List<RequestLogEntry> entries() { return entries; } +} diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/TestDrivers.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/TestDrivers.java index 4b8a9bed1f3..7d7530c32e0 100644 --- a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/TestDrivers.java +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/TestDrivers.java @@ -5,6 +5,7 @@ import com.google.inject.AbstractModule; import com.google.inject.Module; import com.google.inject.util.Modules; import com.yahoo.container.logging.ConnectionLog; +import com.yahoo.container.logging.RequestLog; import com.yahoo.jdisc.handler.RequestHandler; import com.yahoo.jdisc.http.ConnectorConfig; import com.yahoo.jdisc.http.ServerConfig; @@ -82,6 +83,7 @@ public class TestDrivers { bind(ConnectorConfig.class).toInstance(new ConnectorConfig(connectorConfigBuilder)); bind(FilterBindings.class).toInstance(new FilterBindings.Builder().build()); bind(ConnectionLog.class).toInstance(new VoidConnectionLog()); + bind(RequestLog.class).toInstance(new VoidRequestLog()); } }, new ConnectorFactoryRegistryModule(connectorConfigBuilder), diff --git a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/servlet/ServletAccessLoggingTest.java b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/servlet/ServletAccessLoggingTest.java index 6637ee24b5f..a533a447f6a 100644 --- a/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/servlet/ServletAccessLoggingTest.java +++ b/jdisc_http_service/src/test/java/com/yahoo/jdisc/http/server/jetty/servlet/ServletAccessLoggingTest.java @@ -5,7 +5,8 @@ import com.google.inject.AbstractModule; import com.google.inject.Module; import com.google.inject.util.Modules; import com.yahoo.container.logging.AccessLog; -import com.yahoo.container.logging.AccessLogEntry; +import com.yahoo.container.logging.RequestLog; +import com.yahoo.container.logging.RequestLogEntry; import com.yahoo.jdisc.http.server.jetty.TestDriver; import com.yahoo.jdisc.http.server.jetty.TestDrivers; import org.junit.Test; @@ -21,6 +22,7 @@ import static org.mockito.Mockito.verify; /** * @author bakksjo + * @author bjorncs */ public class ServletAccessLoggingTest extends ServletTestBase { private static final long MAX_LOG_WAIT_TIME_MILLIS = TimeUnit.SECONDS.toMillis(60); @@ -41,20 +43,20 @@ public class ServletAccessLoggingTest extends ServletTestBase { verifyCallsLog(accessLog, timeout(MAX_LOG_WAIT_TIME_MILLIS).times(1)); } - private void verifyCallsLog(final AccessLog accessLog, final VerificationMode verificationMode) { - verify(accessLog, verificationMode).log(any(AccessLogEntry.class)); + private void verifyCallsLog(RequestLog requestLog, final VerificationMode verificationMode) { + verify(requestLog, verificationMode).log(any(RequestLogEntry.class)); } - private TestDriver newTestDriver(final AccessLog accessLog) throws IOException { - return TestDrivers.newInstance(dummyRequestHandler, bindings(accessLog)); + private TestDriver newTestDriver(RequestLog requestLog) throws IOException { + return TestDrivers.newInstance(dummyRequestHandler, bindings(requestLog)); } - private Module bindings(final AccessLog accessLog) { + private Module bindings(RequestLog requestLog) { return Modules.combine( new AbstractModule() { @Override protected void configure() { - bind(AccessLog.class).toInstance(accessLog); + bind(RequestLog.class).toInstance(requestLog); } }, guiceModule()); |