Replace AccessLogEntry with non-blocking RequestLogEntry

Keep AccessLogEntry as interface for adding extra information in handlers, but use the new RequestLogEntry for access log serialization.
Introduce new interface RequestLog that AccessLog class implements (to simplify unit testing).
Rename AccessLogInterface to RequestLogHandler.
Remove unused class AccessLogSampler.

5 files changed, 68 insertions, 166 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