diff options
author | Frode Lundgren <frodelu@yahoo-inc.com> | 2016-10-29 12:30:56 +0200 |
---|---|---|
committer | Frode Lundgren <frodelu@yahoo-inc.com> | 2016-10-29 12:30:56 +0200 |
commit | 1775306b3024afbf99aadfb525d70777d53701b4 (patch) | |
tree | 5bb043760195e4899f80e35cd5b1e5384deddb2b | |
parent | 74d1065ce23f039a3d587be52f9d630f2c6e563d (diff) |
First stab at JSON access log [VESPA-5228]
6 files changed, 480 insertions, 1 deletions
diff --git a/config-model/src/main/java/com/yahoo/vespa/model/container/component/AccessLogComponent.java b/config-model/src/main/java/com/yahoo/vespa/model/container/component/AccessLogComponent.java index 75ca2c1e958..4ef70cd717b 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/container/component/AccessLogComponent.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/container/component/AccessLogComponent.java @@ -4,6 +4,7 @@ package com.yahoo.vespa.model.container.component; import com.yahoo.container.core.AccessLogConfig; import com.yahoo.container.logging.VespaAccessLog; import com.yahoo.container.logging.YApacheAccessLog; +import com.yahoo.container.logging.JSONAccessLog; import com.yahoo.osgi.provider.model.ComponentModel; import edu.umd.cs.findbugs.annotations.Nullable; @@ -17,7 +18,7 @@ import static com.yahoo.container.core.AccessLogConfig.FileHandler.RotateScheme; public final class AccessLogComponent extends SimpleComponent implements AccessLogConfig.Producer { - public enum AccessLogType { queryAccessLog, yApacheAccessLog } + public enum AccessLogType { queryAccessLog, yApacheAccessLog, jsonAccessLog } private final String fileNamePattern; private final String rotationInterval; @@ -55,6 +56,8 @@ public final class AccessLogComponent extends SimpleComponent implements AccessL return YApacheAccessLog.class.getName(); case queryAccessLog: return VespaAccessLog.class.getName(); + case jsonAccessLog: + return JSONAccessLog.class.getName(); default: throw new AssertionError(); } diff --git a/config-model/src/main/java/com/yahoo/vespa/model/container/xml/AccessLogBuilder.java b/config-model/src/main/java/com/yahoo/vespa/model/container/xml/AccessLogBuilder.java index f6352e9ac35..1a63d900524 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/container/xml/AccessLogBuilder.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/container/xml/AccessLogBuilder.java @@ -27,6 +27,7 @@ public class AccessLogBuilder { private enum AccessLogTypeLiteral { VESPA("vespa"), YAPACHE("yapache"), + JSON("json"), DISABLED("disabled"); final String attributeValue; @@ -89,6 +90,8 @@ public class AccessLogBuilder { return Optional.of(new DomBuilder(AccessLogType.queryAccessLog).build(cluster, accessLogSpec)); case YAPACHE: return Optional.of(new DomBuilder(AccessLogType.yApacheAccessLog).build(cluster, accessLogSpec)); + case JSON: + return Optional.of(new DomBuilder(AccessLogType.jsonAccessLog).build(cluster, accessLogSpec)); default: throw new InconsistentSchemaAndCodeError(); } 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()); + } + +} |