First stab at JSON access log [VESPA-5228]

4 files changed, 473 insertions, 0 deletions

diff --git a/container-accesslogging/pom.xml b/container-accesslogging/pom.xml
index ceebdad2c6c..dc3350896ff 100644
--- a/container-accesslogging/pom.xml
+++ b/container-accesslogging/pom.xml
@@ -63,6 +63,21 @@
       <artifactId>hamcrest-all</artifactId>
       <scope>test</scope>
     </dependency>
+    <dependency>
+      <groupId>com.fasterxml.jackson.core</groupId>
+      <artifactId>jackson-core</artifactId>
+      <scope>provided</scope>
+    </dependency>
+    <dependency>
+      <groupId>com.fasterxml.jackson.core</groupId>
+      <artifactId>jackson-databind</artifactId>
+      <exclusions>
+        <exclusion>
+          <groupId>com.fasterxml.jackson.core</groupId>
+          <artifactId>jackson-core</artifactId>
+        </exclusion>
+      </exclusions>
+    </dependency>    
   </dependencies>
   <build>
     <plugins>
diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONAccessLog.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONAccessLog.java
new file mode 100644
index 00000000000..467618fdc2e
--- /dev/null
+++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONAccessLog.java
@@ -0,0 +1,36 @@
+// Copyright 2016 Yahoo Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+package com.yahoo.container.logging;
+
+import com.yahoo.container.core.AccessLogConfig;
+
+import java.util.logging.Level;
+
+/**
+ * Log a message in Vespa JSON access log format.
+ *
+ * @author frodelu
+ * @author tonytv
+ */
+public final class JSONAccessLog implements  AccessLogInterface {
+
+    private final AccessLogHandler logHandler;
+
+    public JSONAccessLog(AccessLogConfig config) {
+        logHandler = new AccessLogHandler(config.fileHandler());
+    }
+
+    @Override
+    public void log(final AccessLogEntry logEntry) {
+        logHandler.access.log(Level.INFO, new JSONFormatter(logEntry).format() + '\n');
+    }
+
+    // TODO: This is never called. We should have a DI provider and call this method from its deconstruct.
+    public void shutdown() {
+        logHandler.shutdown();
+    }
+
+    void rotateNow() {
+        logHandler.rotateNow();
+    }
+
+}
diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONFormatter.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONFormatter.java
new file mode 100644
index 00000000000..4fcc6625a5d
--- /dev/null
+++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONFormatter.java
@@ -0,0 +1,249 @@
+// Copyright 2016 Yahoo Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+package com.yahoo.container.logging;
+
+import com.fasterxml.jackson.core.JsonEncoding;
+import com.fasterxml.jackson.core.JsonFactory;
+import com.fasterxml.jackson.core.JsonGenerator;
+import com.fasterxml.jackson.databind.ObjectMapper;
+
+import java.io.ByteArrayOutputStream;
+import java.io.IOException;
+import java.net.URI;
+import java.util.List;
+import java.util.Map;
+import java.util.Objects;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+/**
+ * Formatting of an {@link AccessLogEntry} in the Vespa JSON access log format.
+ *
+ * @author frodelu
+ */
+public class JSONFormatter {
+
+    private AccessLogEntry accessLogEntry;
+    private final JsonFactory generatorFactory;
+
+    // Access log fields set from access log entry
+    private String ipV4AddressInDotDecimalNotation;
+    private String timestampWithMillis;
+    private String durationBetweenRequestResponseInMillis;
+    private String numBytesReturned;
+    private String statusCode;
+    private String uri;
+    private String httpVersion;
+    private String userAgent;
+    private String totalHits;
+    private String retrievedHits;
+    private String httpMethod;
+    private String hostString;
+    private String remoteAddress;
+    private String remotePort;
+    private String peerAddress;
+    private String peerPort;
+
+    private Map<String,List<String>> keyValues;
+
+    private static Logger logger = Logger.getLogger(JSONFormatter.class.getName());
+
+
+    public JSONFormatter(final AccessLogEntry entry) {
+        accessLogEntry = entry;
+        generatorFactory = new JsonFactory();
+        generatorFactory.setCodec(new ObjectMapper());
+    }
+
+    /**
+     * The main method for formatting the associated {@link AccessLogEntry} as a Vespa JSON access log string
+     *
+     * @return The Vespa JSON access log string without trailing newline
+     */
+    public String format() {
+        String logString;
+
+        setIpV4Address(accessLogEntry.getIpV4Address());
+        setTimeStampMillis(accessLogEntry.getTimeStampMillis());
+        setDurationBetweenRequestResponseMillis(accessLogEntry.getDurationBetweenRequestResponseMillis());
+        setReturnedContentSize(accessLogEntry.getReturnedContentSize());
+        setStatusCode(accessLogEntry.getStatusCode());
+        setHitCounts(accessLogEntry.getHitCounts());
+
+        setRemoteAddress(accessLogEntry.getRemoteAddress());
+        setRemotePort(accessLogEntry.getRemotePort());
+
+        setHttpMethod(accessLogEntry.getHttpMethod());
+        setURI(accessLogEntry.getURI());
+        setHttpVersion(accessLogEntry.getHttpVersion());
+
+        setUserAgent(accessLogEntry.getUserAgent());
+
+        setHostString(accessLogEntry.getHostString());
+        setPeerAddress(accessLogEntry.getPeerAddress());
+        setPeerPort(accessLogEntry.getPeerPort());
+
+        keyValues = accessLogEntry.getKeyValues();
+
+        try {
+            logString = toJSONAccessEntry();
+        } catch (IOException e) {
+            logString = "";
+        }
+
+        return logString;
+    }
+
+    private String toJSONAccessEntry() throws IOException {
+        ByteArrayOutputStream logLine = new ByteArrayOutputStream();
+        JsonGenerator generator = generatorFactory.createGenerator(logLine, JsonEncoding.UTF8);
+        generator.writeStartObject();
+        generator.writeStringField("ip", ipV4AddressInDotDecimalNotation);
+        generator.writeStringField("time", timestampWithMillis);
+        generator.writeStringField("duration", durationBetweenRequestResponseInMillis);
+        generator.writeStringField("size", numBytesReturned);
+        generator.writeStringField("code", statusCode);
+        generator.writeStringField("totalhits", totalHits);
+        generator.writeStringField("hits", retrievedHits);
+        generator.writeStringField("method", httpMethod);
+        generator.writeStringField("uri", uri);
+        generator.writeStringField("version", httpVersion);
+        generator.writeStringField("agent", userAgent);
+        generator.writeStringField("host", hostString);
+
+        // Only add remote address/port fields if relevant
+        if (remoteAddressDiffers(ipV4AddressInDotDecimalNotation, remoteAddress)) {
+            generator.writeStringField("remoteaddr", remoteAddress);
+            if (remotePort != null) {
+                generator.writeStringField("remoteport", remotePort);
+            }
+        }
+
+        // Only add peer address/port fields if relevant
+        if (peerAddress != null) {
+            generator.writeStringField("peeraddr", peerAddress);
+            if (peerPort != null && !peerPort.equals(remotePort)) {
+                generator.writeStringField("peerport", peerPort);
+            }
+        }
+
+        // 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
+        if (keyValues != null && !keyValues.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));
+                } else {
+                    generator.writeFieldName(entry.getKey());
+                    generator.writeStartArray();
+                    for (String s : entry.getValue()) {
+                        generator.writeString(s);
+                    }
+                    generator.writeEndArray();
+                }
+            }
+            generator.writeEndObject();
+        }
+
+        generator.writeEndObject();
+        generator.close();
+
+        return logLine.toString();
+    }
+
+    private boolean remoteAddressDiffers(String ipV4Address, String remoteAddress) {
+        return remoteAddress != null && !Objects.equals(ipV4Address, remoteAddress);
+    }
+
+    private void setUserAgent(String userAgent) { this.userAgent = userAgent; }
+
+    private void setHttpMethod(String method) { this.httpMethod = method; }
+
+    private void setHttpVersion(String httpVersion) { this.httpVersion = httpVersion; }
+
+    private void setHostString(String hostString) { this.hostString = hostString; }
+
+    private void setRemoteAddress(String remoteAddress) { this.remoteAddress = remoteAddress; }
+
+    private void setPeerAddress(final String peerAddress) { this.peerAddress = peerAddress; }
+
+    private void setRemotePort(int remotePort) {
+        if (remotePort == 0) {
+            this.remotePort = null;
+        } else {
+            this.remotePort = String.valueOf(remotePort);
+        }
+    }
+
+    private void setPeerPort(int peerPort) {
+        if (peerPort == 0) {
+            this.peerPort = null;
+        } else {
+            this.peerPort = String.valueOf(peerPort);
+        }
+    }
+
+    private void setHitCounts(HitCounts counts) {
+        if (counts == null) {
+            return;
+        }
+
+        this.totalHits = String.valueOf(counts.getTotalHitCount());
+        this.retrievedHits = String.valueOf(counts.getRetrievedHitCount());
+    }
+
+    private void setIpV4Address(String ipV4AddressInDotDecimalNotation) {
+        this.ipV4AddressInDotDecimalNotation = ipV4AddressInDotDecimalNotation;
+    }
+
+    private void setTimeStampMillis(long numMillisSince1Jan1970AtMidnightUTC) {
+        int unixTime = (int)(numMillisSince1Jan1970AtMidnightUTC/1000);
+        int milliSeconds = (int)(numMillisSince1Jan1970AtMidnightUTC % 1000);
+
+        if (numMillisSince1Jan1970AtMidnightUTC/1000 > 0x7fffffff) {
+            logger.log(Level.WARNING, "A year 2038 problem occurred.");
+            logger.log(Level.INFO, "numMillisSince1Jan1970AtMidnightUTC: "
+                       + numMillisSince1Jan1970AtMidnightUTC);
+            unixTime = (int)(numMillisSince1Jan1970AtMidnightUTC/1000 % 0x7fffffff);
+        }
+
+        timestampWithMillis = unixTime + "." + milliSeconds;
+    }
+
+    private void setDurationBetweenRequestResponseMillis(long timeInMillis) {
+        int duration = (int)timeInMillis;
+
+        if (timeInMillis > 0xffffffffL) {
+            logger.log(Level.WARNING, "Duration too long: " + timeInMillis);
+            duration = 0xffffffff;
+        }
+
+        durationBetweenRequestResponseInMillis = String.valueOf(duration);
+    }
+
+    private void setReturnedContentSize(long byteCount) {
+        numBytesReturned = String.valueOf(byteCount);
+    }
+
+    private void setURI(final URI uri) {
+        setNormalizedURI(uri.normalize());
+    }
+
+    private void setNormalizedURI(final URI normalizedUri) {
+        String uriString = normalizedUri.getPath();
+        if (normalizedUri.getRawQuery() != null) {
+            uriString = uriString + "?" + normalizedUri.getRawQuery();
+        }
+
+        this.uri = uriString;
+    }
+
+    private void setStatusCode(int statusCode) {
+        if (statusCode == 0) {
+            return;
+        }
+
+        this.statusCode = String.valueOf(statusCode);
+    }
+
+}
diff --git a/container-accesslogging/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java b/container-accesslogging/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
new file mode 100644
index 00000000000..ff85dfb4835
--- /dev/null
+++ b/container-accesslogging/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
@@ -0,0 +1,173 @@
+// Copyright 2016 Yahoo Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+package com.yahoo.container.logging;
+
+import java.net.URI;
+
+
+/**
+ * @author frodelu
+ */
+public class JSONLogTestCase extends junit.framework.TestCase {
+
+    private static String ipAddress = "152.200.54.243";
+    private static final String EMPTY_REFERRER = "";
+    private static final String EMPTY_USERAGENT = "";
+
+    private AccessLogEntry newAccessLogEntry(final String query) {
+        final AccessLogEntry entry = new AccessLogEntry();
+        entry.setURI(newQueryUri(query));
+        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));
+        entry.setHostString("localhost");
+        entry.setStatusCode(200);
+        entry.setTimeStamp(920880005123L);
+        entry.setDurationBetweenRequestResponse(122);
+        entry.setReturnedContentSize(9875);
+
+        return entry;
+    }
+
+    private static URI newQueryUri(final String query) {
+        return URI.create("http://localhost?query=" + query);
+    }
+
+    public void test_json_log_entry() throws Exception {
+        AccessLogEntry entry = newAccessLogEntry("test");
+
+         String expectedOutput =
+            "{\"ip\":\"152.200.54.243\"," +
+            "\"time\":\"920880005.123\"," +
+            "\"duration\":\"122\"," +
+            "\"size\":\"9875\"," +
+            "\"code\":\"200\"," +
+            "\"totalhits\":\"1234\"," +
+            "\"hits\":\"0\"," +
+            "\"method\":\"GET\"," +
+            "\"uri\":\"?query=test\"," +
+            "\"version\":\"HTTP/1.1\"," +
+            "\"agent\":\"Mozilla/4.05 [en] (Win95; I)\"," +
+            "\"host\":\"localhost\"" +
+             "}";
+
+        assertEquals(expectedOutput, new JSONFormatter(entry).format());
+    }
+
+    public void test_with_keyvalues() throws Exception {
+        AccessLogEntry entry = newAccessLogEntry("test");
+        entry.addKeyValue("singlevalue", "value1");
+        entry.addKeyValue("multivalue", "value2");
+        entry.addKeyValue("multivalue", "value3");
+
+        String expectedOutput =
+            "{\"ip\":\"152.200.54.243\"," +
+            "\"time\":\"920880005.123\"," +
+            "\"duration\":\"122\"," +
+            "\"size\":\"9875\"," +
+            "\"code\":\"200\"," +
+            "\"totalhits\":\"1234\"," +
+            "\"hits\":\"0\"," +
+            "\"method\":\"GET\"," +
+            "\"uri\":\"?query=test\"," +
+            "\"version\":\"HTTP/1.1\"," +
+            "\"agent\":\"Mozilla/4.05 [en] (Win95; I)\"," +
+            "\"host\":\"localhost\"," +
+            "\"attributes\":{" +
+            "\"singlevalue\":\"value1\"," +
+            "\"multivalue\":[\"value2\",\"value3\"]}" +
+            "}";
+
+        assertEquals(expectedOutput, new JSONFormatter(entry).format());
+
+    }
+
+    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");
+
+        String expectedOutput =
+            "{\"ip\":\"152.200.54.243\"," +
+            "\"time\":\"920880005.123\"," +
+            "\"duration\":\"122\"," +
+            "\"size\":\"9875\"," +
+            "\"code\":\"200\"," +
+            "\"totalhits\":\"1234\"," +
+            "\"hits\":\"0\"," +
+            "\"method\":\"GET\"," +
+            "\"uri\":\"?query=test\"," +
+            "\"version\":\"HTTP/1.1\"," +
+            "\"agent\":\"Mozilla/4.05 [en] (Win95; I)\"," +
+            "\"host\":\"localhost\"," +
+            "\"remoteaddr\":\"FE80:0000:0000:0000:0202:B3FF:FE1E:8329\"" +
+            "}";
+
+        assertEquals(expectedOutput, new JSONFormatter(entry).format());
+
+        // Add remote port and verify
+        entry.setRemotePort(1234);
+
+        expectedOutput =
+            "{\"ip\":\"152.200.54.243\"," +
+            "\"time\":\"920880005.123\"," +
+            "\"duration\":\"122\"," +
+            "\"size\":\"9875\"," +
+            "\"code\":\"200\"," +
+            "\"totalhits\":\"1234\"," +
+            "\"hits\":\"0\"," +
+            "\"method\":\"GET\"," +
+            "\"uri\":\"?query=test\"," +
+            "\"version\":\"HTTP/1.1\"," +
+            "\"agent\":\"Mozilla/4.05 [en] (Win95; I)\"," +
+            "\"host\":\"localhost\"," +
+            "\"remoteaddr\":\"FE80:0000:0000:0000:0202:B3FF:FE1E:8329\"," +
+            "\"remoteport\":\"1234\"" +
+            "}";
+
+        assertEquals(expectedOutput, new JSONFormatter(entry).format());
+    }
+
+    public void test_remote_address_same_as_ip_address() throws Exception {
+        AccessLogEntry entry = newAccessLogEntry("test");
+        AccessLogEntry entrywithremote = newAccessLogEntry("test");
+        entrywithremote.setRemoteAddress(entry.getIpV4Address());
+
+        assertEquals(new JSONFormatter(entry).format(), new JSONFormatter(entrywithremote).format());
+    }
+
+    public void test_useragent_with_quotes() throws Exception {
+        final AccessLogEntry entry = new AccessLogEntry();
+        entry.setURI(newQueryUri("test"));
+        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));
+        entry.setHostString("localhost");
+        entry.setStatusCode(200);
+        entry.setTimeStamp(920880005123L);
+        entry.setDurationBetweenRequestResponse(122);
+        entry.setReturnedContentSize(9875);
+
+        String expectedOutput =
+            "{\"ip\":\"152.200.54.243\"," +
+            "\"time\":\"920880005.123\"," +
+            "\"duration\":\"122\"," +
+            "\"size\":\"9875\"," +
+            "\"code\":\"200\"," +
+            "\"totalhits\":\"1234\"," +
+            "\"hits\":\"0\"," +
+            "\"method\":\"GET\"," +
+            "\"uri\":\"?query=test\"," +
+            "\"version\":\"HTTP/1.1\"," +
+            "\"agent\":\"Mozilla/4.05 [en] (Win95; I; \\\"Best Browser Ever\\\")\"," +
+            "\"host\":\"localhost\"" +
+            "}";
+
+        assertEquals(expectedOutput, new JSONFormatter(entry).format());
+    }
+
+}