Revert "Access log optimizations [run-systemtest]"

5 files changed, 166 insertions, 68 deletions

diff --git a/container-core/abi-spec.json b/container-core/abi-spec.json
index 06366250c09..a5483d12b24 100644
--- a/container-core/abi-spec.json
+++ b/container-core/abi-spec.json
@@ -499,7 +499,6 @@
     ],
     "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()",
@@ -516,7 +515,6 @@
     ],
     "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)",
@@ -779,7 +777,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.RequestLogHandler)",
+      "public void <init>(com.yahoo.component.chain.Chain, com.yahoo.container.logging.AccessLogInterface)",
       "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 9bb9819cd1f..064b6cf6279 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,6 +3,7 @@ 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;
@@ -10,15 +11,16 @@ 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
@@ -26,43 +28,35 @@ import java.util.logging.Level;
  *
  * @author Steinar Knutsen
  */
-// TODO Vespa 8: Deprecate all constructors taking AccessLog as parameter
 public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler {
 
-    public LoggingRequestHandler(Executor executor, AccessLog ignored) {
-        this(executor, ignored, null);
-    }
+    private final AccessLog accessLog;
 
-    public LoggingRequestHandler(Executor executor) {
-        this(executor, null, null);
+    public LoggingRequestHandler(Executor executor, AccessLog accessLog) {
+        this(executor, accessLog, null);
     }
 
     public static class Context {
 
         final Executor executor;
-        final AccessLog ignored;
+        final AccessLog accessLog;
         final Metric metric;
 
         @Inject
-        public Context(Executor executor, AccessLog ignored, Metric metric) {
+        public Context(Executor executor, AccessLog accessLog, Metric metric) {
             this.executor = executor;
-            this.ignored = ignored;
+            this.accessLog = accessLog;
             this.metric = metric;
         }
 
-
-        public Context(Executor executor, Metric metric) {
-            this(executor, null, metric);
-        }
-
         public Context(Context other) {
             this.executor = other.executor;
-            this.ignored = other.ignored;
+            this.accessLog = other.accessLog;
             this.metric = other.metric;
         }
 
         public Executor getExecutor() { return executor; }
-        public AccessLog getAccessLog() { return ignored; }
+        public AccessLog getAccessLog() { return accessLog; }
         public Metric getMetric() { return metric; }
 
     }
@@ -80,19 +74,20 @@ public abstract class LoggingRequestHandler extends ThreadedHttpRequestHandler {
 
     @Inject
     public LoggingRequestHandler(Context ctx) {
-        this(ctx.executor, ctx.ignored, ctx.metric);
+        this(ctx.executor, ctx.accessLog, ctx.metric);
     }
 
     public LoggingRequestHandler(Context ctx, boolean allowAsyncResponse) {
-        this(ctx.executor, ctx.ignored, ctx.metric, allowAsyncResponse);
+        this(ctx.executor, ctx.accessLog, ctx.metric, allowAsyncResponse);
     }
 
-    public LoggingRequestHandler(Executor executor, AccessLog ignored, Metric metric) {
-        this(executor, ignored, metric, false);
+    public LoggingRequestHandler(Executor executor, AccessLog accessLog, Metric metric) {
+        this(executor, accessLog, metric, false);
     }
 
-    public LoggingRequestHandler(Executor executor, AccessLog ignored, Metric metric, boolean allowAsyncResponse) {
+    public LoggingRequestHandler(Executor executor, AccessLog accessLog, Metric metric, boolean allowAsyncResponse) {
         super(executor, metric, allowAsyncResponse);
+        this.accessLog = accessLog;
     }
 
     @Override
@@ -111,6 +106,26 @@ 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) {
@@ -242,8 +257,21 @@ 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();
-                httpResponse.populateAccessLogEntry(entry);
+            } 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);
         }
 
         private String getUri(com.yahoo.jdisc.http.HttpRequest jdiscRequest) {
@@ -257,4 +285,36 @@ 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 7170f63234e..d4e55dbc556 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.RequestLogHandler;
+import com.yahoo.container.logging.AccessLogInterface;
 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, RequestLogHandler accessLogInterface) {
+    public ProcessingTestDriver(Chain<Processor> chain, AccessLogInterface accessLogInterface) {
         this(createProcessingHandler(
                 Collections.singleton(chain),
                 new ComponentRegistry<>(),
                 createAccessLog(accessLogInterface)));
     }
 
-    private static AccessLog createAccessLog(RequestLogHandler accessLogInterface) {
-        ComponentRegistry<RequestLogHandler> componentRegistry = new ComponentRegistry<>();
+    private static AccessLog createAccessLog(AccessLogInterface accessLogInterface) {
+        ComponentRegistry<AccessLogInterface> 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 734b3fa11af..92fe347f7d1 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,43 +1,51 @@
 // 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 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 org.junit.After;
-import org.junit.Before;
+import static org.junit.Assert.*;
 
 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.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.container.logging.HitCounts;
+import com.yahoo.jdisc.Container;
+import com.yahoo.jdisc.References;
+import com.yahoo.jdisc.ResourceReference;
+import com.yahoo.jdisc.handler.RequestHandler;
+import com.yahoo.jdisc.service.CurrentContainer;
+import java.net.URI;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
 
-import static org.junit.Assert.fail;
+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;
 
 /**
  * Test contracts in LoggingRequestHandler.
  *
- * @author Steinar Knutsen
+ * @author <a href="mailto:steinar@yahoo-inc.com">Steinar Knutsen</a>
  */
 public class LoggingRequestHandlerTestCase {
 
+    StartTimePusher accessLogging;
     AccessLogTestHandler handler;
     ExecutorService executor;
 
@@ -113,9 +121,21 @@ 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 {
-        ComponentRegistry<RequestLogHandler> implementers = new ComponentRegistry<>();
+        accessLogging = new StartTimePusher();
+        ComponentRegistry<AccessLogInterface> implementers = new ComponentRegistry<>();
+        implementers.register(new ComponentId("nalle"), accessLogging);
         implementers.freeze();
         executor = Executors.newCachedThreadPool();
         handler = new AccessLogTestHandler(executor, new AccessLog(implementers));
@@ -123,11 +143,31 @@ 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 ae1076a4773..6498514c075 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,10 +8,9 @@ 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;
@@ -24,11 +23,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;
@@ -38,16 +37,17 @@ 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() {
-        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)));
+    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)));
     }
 
     @Test