Populate all access log fields in log()

Populate all fields in log() as populateAccessLogEntryFromHttpServletRequest was not guaranteed to be called (e.g. when request headers/uri has invalid encoding).

3 files changed, 76 insertions, 82 deletions

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 f72f0691deb..5c3298a7aff 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
@@ -48,14 +48,44 @@ public class AccessLogRequestLog extends AbstractLifeCycle implements RequestLog
     @Override
     public void log(final Request request, final Response response) {
         try {
-            final AccessLogEntry accessLogEntryFromServletRequest = (AccessLogEntry) request.getAttribute(
-                    JDiscHttpServlet.ATTRIBUTE_NAME_ACCESS_LOG_ENTRY);
-            final AccessLogEntry accessLogEntry;
-            if (accessLogEntryFromServletRequest != null) {
-                accessLogEntry = accessLogEntryFromServletRequest;
-            } else {
-                accessLogEntry = new AccessLogEntry();
-                populateAccessLogEntryFromHttpServletRequest(request, accessLogEntry);
+            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);
+            }
+
+            final String remoteAddress = getRemoteAddress(request);
+            final int remotePort = getRemotePort(request);
+            final String peerAddress = request.getRemoteAddr();
+            final int peerPort = request.getRemotePort();
+
+            accessLogEntry.setUserAgent(request.getHeader("User-Agent"));
+            accessLogEntry.setHttpMethod(request.getMethod());
+            accessLogEntry.setHostString(request.getHeader("Host"));
+            accessLogEntry.setReferer(request.getHeader("Referer"));
+            accessLogEntry.setIpV4Address(peerAddress);
+            accessLogEntry.setRemoteAddress(remoteAddress);
+            accessLogEntry.setRemotePort(remotePort);
+            if (!Objects.equal(remoteAddress, peerAddress)) {
+                accessLogEntry.setPeerAddress(peerAddress);
+            }
+            if (remotePort != peerPort) {
+                accessLogEntry.setPeerPort(peerPort);
+            }
+            accessLogEntry.setHttpVersion(request.getProtocol());
+            accessLogEntry.setScheme(request.getScheme());
+            accessLogEntry.setLocalPort(request.getLocalPort());
+            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());
             }
 
             final long startTime = request.getTimeStamp();
@@ -79,55 +109,6 @@ public class AccessLogRequestLog extends AbstractLifeCycle implements RequestLog
         }
     }
 
-    /*
-     * Collecting all log entry population based on extracting information from HttpServletRequest in one method
-     * means that this may easily be moved to another location, e.g. if we want to populate this at instantiation
-     * time rather than at logging time. We may, for example, want to set things such as http headers and ip
-     * addresses up-front and make it illegal for request handlers to modify these later.
-     */
-    // TODO Move populating of access log entry to log(). populateAccessLogEntryFromHttpServletRequest() is not guaranteed
-    //  to be called if request is failed early (e.g invalid uri or header encoding).
-    public static void populateAccessLogEntryFromHttpServletRequest(
-            final HttpServletRequest request,
-            final AccessLogEntry accessLogEntry) {
-
-        accessLogEntry.setRawPath(request.getRequestURI());
-        String queryString = request.getQueryString();
-        if (queryString != null) {
-            accessLogEntry.setRawQuery(queryString);
-        }
-
-        final String remoteAddress = getRemoteAddress(request);
-        final int remotePort = getRemotePort(request);
-        final String peerAddress = request.getRemoteAddr();
-        final int peerPort = request.getRemotePort();
-
-        accessLogEntry.setUserAgent(request.getHeader("User-Agent"));
-        accessLogEntry.setHttpMethod(request.getMethod());
-        accessLogEntry.setHostString(request.getHeader("Host"));
-        accessLogEntry.setReferer(request.getHeader("Referer"));
-        accessLogEntry.setIpV4Address(peerAddress);
-        accessLogEntry.setRemoteAddress(remoteAddress);
-        accessLogEntry.setRemotePort(remotePort);
-        if (!Objects.equal(remoteAddress, peerAddress)) {
-            accessLogEntry.setPeerAddress(peerAddress);
-        }
-        if (remotePort != peerPort) {
-            accessLogEntry.setPeerPort(peerPort);
-        }
-        accessLogEntry.setHttpVersion(request.getProtocol());
-        accessLogEntry.setScheme(request.getScheme());
-        accessLogEntry.setLocalPort(request.getLocalPort());
-        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());
-        }
-    }
-
     private static String getRemoteAddress(final HttpServletRequest request) {
         return Alternative.preferred(request.getHeader(HEADER_NAME_X_FORWARDED_FOR))
                 .alternatively(() -> request.getHeader(HEADER_NAME_Y_RA))
diff --git a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JDiscHttpServlet.java b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JDiscHttpServlet.java
index 20c8f945b82..cf66af31a79 100644
--- a/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JDiscHttpServlet.java
+++ b/jdisc_http_service/src/main/java/com/yahoo/jdisc/http/server/jetty/JDiscHttpServlet.java
@@ -106,7 +106,6 @@ class JDiscHttpServlet extends HttpServlet {
 
     private void dispatchHttpRequest(HttpServletRequest request, HttpServletResponse response) throws IOException {
         AccessLogEntry accessLogEntry = new AccessLogEntry();
-        AccessLogRequestLog.populateAccessLogEntryFromHttpServletRequest(request, accessLogEntry);
         request.setAttribute(ATTRIBUTE_NAME_ACCESS_LOG_ENTRY, accessLogEntry);
         try {
             switch (request.getDispatcherType()) {
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 d5043f7b989..e6690ce6fbf 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,12 +1,14 @@
 // 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 org.eclipse.jetty.http.MetaData;
+import org.eclipse.jetty.server.HttpChannel;
+import org.eclipse.jetty.server.Request;
+import org.eclipse.jetty.server.Response;
 import org.testng.annotations.Test;
 
-import javax.servlet.http.HttpServletRequest;
-
 import java.util.Optional;
 
 import static org.hamcrest.CoreMatchers.is;
@@ -24,12 +26,12 @@ import static org.testng.Assert.assertTrue;
 public class AccessLogRequestLogTest {
     @Test
     public void requireThatQueryWithUnquotedSpecialCharactersIsHandled() {
-        final HttpServletRequest httpServletRequest = mock(HttpServletRequest.class);
-        when(httpServletRequest.getRequestURI()).thenReturn("/search/");
-        when(httpServletRequest.getQueryString()).thenReturn("query=year:>2010");
         final AccessLogEntry accessLogEntry = new AccessLogEntry();
+        final Request jettyRequest = createRequestMock(accessLogEntry);
+        when(jettyRequest.getRequestURI()).thenReturn("/search/");
+        when(jettyRequest.getQueryString()).thenReturn("query=year:>2010");
 
-        AccessLogRequestLog.populateAccessLogEntryFromHttpServletRequest(httpServletRequest, accessLogEntry);
+        new AccessLogRequestLog(mock(AccessLog.class)).log(jettyRequest, createResponseMock());
 
         assertThat(accessLogEntry.getRawPath(), is(not(nullValue())));
         assertTrue(accessLogEntry.getRawQuery().isPresent());
@@ -37,14 +39,14 @@ public class AccessLogRequestLogTest {
 
     @Test
     public void requireThatDoubleQuotingIsNotPerformed() {
-        final HttpServletRequest httpServletRequest = mock(HttpServletRequest.class);
+        final AccessLogEntry accessLogEntry = new AccessLogEntry();
+        final Request jettyRequest = createRequestMock(accessLogEntry);
         final String path = "/search/";
-        when(httpServletRequest.getRequestURI()).thenReturn(path);
+        when(jettyRequest.getRequestURI()).thenReturn(path);
         final String query = "query=year%252010+%3B&customParameter=something";
-        when(httpServletRequest.getQueryString()).thenReturn(query);
-        final AccessLogEntry accessLogEntry = new AccessLogEntry();
+        when(jettyRequest.getQueryString()).thenReturn(query);
 
-        AccessLogRequestLog.populateAccessLogEntryFromHttpServletRequest(httpServletRequest, accessLogEntry);
+        new AccessLogRequestLog(mock(AccessLog.class)).log(jettyRequest, createResponseMock());
 
         assertThat(accessLogEntry.getRawPath(), is(path));
         assertThat(accessLogEntry.getRawQuery().get(), is(query));
@@ -53,14 +55,14 @@ public class AccessLogRequestLogTest {
 
     @Test
     public void raw_path_and_query_are_set_from_request() {
-        HttpServletRequest httpServletRequest = mock(HttpServletRequest.class);
+        AccessLogEntry accessLogEntry = new AccessLogEntry();
+        Request jettyRequest = createRequestMock(accessLogEntry);
         String rawPath = "//search/";
-        when(httpServletRequest.getRequestURI()).thenReturn(rawPath);
+        when(jettyRequest.getRequestURI()).thenReturn(rawPath);
         String rawQuery = "q=%%2";
-        when(httpServletRequest.getQueryString()).thenReturn(rawQuery);
+        when(jettyRequest.getQueryString()).thenReturn(rawQuery);
 
-        AccessLogEntry accessLogEntry = new AccessLogEntry();
-        AccessLogRequestLog.populateAccessLogEntryFromHttpServletRequest(httpServletRequest, accessLogEntry);
+        new AccessLogRequestLog(mock(AccessLog.class)).log(jettyRequest, createResponseMock());
         assertThat(accessLogEntry.getRawPath(), is(rawPath));
         Optional<String> actualRawQuery = accessLogEntry.getRawQuery();
         assertThat(actualRawQuery.isPresent(), is(true));
@@ -69,15 +71,27 @@ public class AccessLogRequestLogTest {
 
     @Test
     public void verify_x_forwarded_for_precedence () {
-        HttpServletRequest httpServletRequest = mock(HttpServletRequest.class);
-        when(httpServletRequest.getRequestURI()).thenReturn("//search/");
-        when(httpServletRequest.getQueryString()).thenReturn("q=%%2");
-        when(httpServletRequest.getHeader("x-forwarded-for")).thenReturn("1.2.3.4");
-        when(httpServletRequest.getHeader("y-ra")).thenReturn("2.3.4.5");
-
         AccessLogEntry accessLogEntry = new AccessLogEntry();
-        AccessLogRequestLog.populateAccessLogEntryFromHttpServletRequest(httpServletRequest, accessLogEntry);
+        Request jettyRequest = createRequestMock(accessLogEntry);
+        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");
+
+        new AccessLogRequestLog(mock(AccessLog.class)).log(jettyRequest, createResponseMock());
         assertThat(accessLogEntry.getRemoteAddress(), is("1.2.3.4"));
     }
 
+    private static Request createRequestMock(AccessLogEntry entry) {
+        Request request = mock(Request.class);
+        when(request.getAttribute(JDiscHttpServlet.ATTRIBUTE_NAME_ACCESS_LOG_ENTRY)).thenReturn(entry);
+        return request;
+    }
+
+    private Response createResponseMock() {
+        Response response = mock(Response.class);
+        when(response.getHttpChannel()).thenReturn(mock(HttpChannel.class));
+        when(response.getCommittedMetaData()).thenReturn(mock(MetaData.Response.class));
+        return response;
+    }
 }