Implement changes after architecture review:

* Convert 'time' to JSON number
* Log 'duration' in seconds (with decimals)
* Rename 'size' to 'responsesize'
* Move search specific fields 'totalhits' and 'hits' to 'search' sub-object

2 files changed, 72 insertions, 47 deletions

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
index 8f2ef90318e..0cc71fcaedd 100644
--- a/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONFormatter.java
+++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/JSONFormatter.java
@@ -8,6 +8,8 @@ import com.fasterxml.jackson.databind.ObjectMapper;
 
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
+import java.math.BigDecimal;
+import java.math.RoundingMode;
 import java.net.URI;
 import java.util.List;
 import java.util.Map;
@@ -44,13 +46,11 @@ public class JSONFormatter {
             JsonGenerator generator = generatorFactory.createGenerator(logLine, JsonEncoding.UTF8);
             generator.writeStartObject();
             generator.writeStringField("ip", accessLogEntry.getIpV4Address());
-            generator.writeStringField("time", toTimestampWithFraction(accessLogEntry.getTimeStampMillis()));
+            generator.writeNumberField("time", toTimestampInSeconds(accessLogEntry.getTimeStampMillis()));
             generator.writeNumberField("duration",
-                                       capDuration(accessLogEntry.getDurationBetweenRequestResponseMillis()));
-            generator.writeNumberField("size", accessLogEntry.getReturnedContentSize());
+                                       durationAsSeconds(accessLogEntry.getDurationBetweenRequestResponseMillis()));
+            generator.writeNumberField("responsesize", accessLogEntry.getReturnedContentSize());
             generator.writeNumberField("code", accessLogEntry.getStatusCode());
-            generator.writeNumberField("totalhits", getTotalHitCount(accessLogEntry.getHitCounts()));
-            generator.writeNumberField("hits", getRetrievedHitCount(accessLogEntry.getHitCounts()));
             generator.writeStringField("method", accessLogEntry.getHttpMethod());
             generator.writeStringField("uri", getNormalizedURI(accessLogEntry.getURI()));
             generator.writeStringField("version", accessLogEntry.getHttpVersion());
@@ -75,6 +75,14 @@ public class JSONFormatter {
                 }
             }
 
+            // Only add search sub block of this is a search request
+            if (isSearchRequest(accessLogEntry)) {
+                generator.writeObjectFieldStart("search");
+                generator.writeNumberField("totalhits", getTotalHitCount(accessLogEntry.getHitCounts()));
+                generator.writeNumberField("hits", getRetrievedHitCount(accessLogEntry.getHitCounts()));
+                generator.writeEndObject();
+            }
+
             // 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
             Map<String,List<String>> keyValues = accessLogEntry.getKeyValues();
@@ -110,6 +118,10 @@ public class JSONFormatter {
         return remoteAddress != null && !Objects.equals(ipV4Address, remoteAddress);
     }
 
+    private boolean isSearchRequest(AccessLogEntry logEntry) {
+        return logEntry != null && (logEntry.getHitCounts() != null);
+    }
+
     private long getTotalHitCount(HitCounts counts) {
         if (counts == null) {
             return 0;
@@ -126,29 +138,32 @@ public class JSONFormatter {
         return counts.getRetrievedHitCount();
     }
 
-    private String toTimestampWithFraction(long numMillisSince1Jan1970AtMidnightUTC) {
-        int unixTime = (int)(numMillisSince1Jan1970AtMidnightUTC/1000);
-        int milliSeconds = (int)(numMillisSince1Jan1970AtMidnightUTC % 1000);
+    private BigDecimal toTimestampInSeconds(long numMillisSince1Jan1970AtMidnightUTC) {
+        BigDecimal timestampInSeconds =
+            new BigDecimal(numMillisSince1Jan1970AtMidnightUTC).divide(BigDecimal.valueOf(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);
+            timestampInSeconds =
+                new BigDecimal(numMillisSince1Jan1970AtMidnightUTC)
+                    .divide(BigDecimal.valueOf(1000))
+                    .remainder(BigDecimal.valueOf(0x7fffffff));
         }
-
-        return unixTime + "." + milliSeconds;
+        return timestampInSeconds.setScale(3, RoundingMode.HALF_UP);
     }
 
-    private int capDuration(long timeInMillis) {
-        int duration = (int)timeInMillis;
+    private BigDecimal durationAsSeconds(long timeInMillis) {
+        BigDecimal duration =
+            new BigDecimal(timeInMillis).divide(BigDecimal.valueOf(1000));
 
         if (timeInMillis > 0xffffffffL) {
             logger.log(Level.WARNING, "Duration too long: " + timeInMillis);
-            duration = 0xffffffff;
+            duration = new BigDecimal(0xffffffff);
         }
 
-        return duration;
+        return duration.setScale(3, BigDecimal.ROUND_HALF_UP);
     }
 
     private String getNormalizedURI(URI uri) {
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
index f41e35243ad..6676c684593 100644
--- a/container-accesslogging/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
+++ b/container-accesslogging/src/test/java/com/yahoo/container/logging/JSONLogTestCase.java
@@ -23,7 +23,7 @@ public class JSONLogTestCase extends junit.framework.TestCase {
         entry.setHitCounts(new HitCounts(0, 10, 1234, 0, 10));
         entry.setHostString("localhost");
         entry.setStatusCode(200);
-        entry.setTimeStamp(920880005123L);
+        entry.setTimeStamp(920880005023L);
         entry.setDurationBetweenRequestResponse(122);
         entry.setReturnedContentSize(9875);
 
@@ -39,18 +39,20 @@ public class JSONLogTestCase extends junit.framework.TestCase {
 
          String expectedOutput =
             "{\"ip\":\"152.200.54.243\"," +
-            "\"time\":\"920880005.123\"," +
-            "\"duration\":122," +
-            "\"size\":9875," +
+            "\"time\":920880005.023," +
+            "\"duration\":0.122," +
+            "\"responsesize\":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\"" +
-             "}";
+            "\"host\":\"localhost\"," +
+            "\"search\":{" +
+            "\"totalhits\":1234," +
+            "\"hits\":0" +
+            "}" +
+            "}";
 
         assertEquals(expectedOutput, new JSONFormatter(entry).format());
     }
@@ -63,17 +65,19 @@ public class JSONLogTestCase extends junit.framework.TestCase {
 
         String expectedOutput =
             "{\"ip\":\"152.200.54.243\"," +
-            "\"time\":\"920880005.123\"," +
-            "\"duration\":122," +
-            "\"size\":9875," +
+            "\"time\":920880005.023," +
+            "\"duration\":0.122," +
+            "\"responsesize\":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\"," +
+            "\"search\":{" +
+            "\"totalhits\":1234," +
+            "\"hits\":0" +
+            "}," +
             "\"attributes\":{" +
             "\"singlevalue\":\"value1\"," +
             "\"multivalue\":[\"value2\",\"value3\"]}" +
@@ -91,18 +95,20 @@ public class JSONLogTestCase extends junit.framework.TestCase {
 
         String expectedOutput =
             "{\"ip\":\"152.200.54.243\"," +
-            "\"time\":\"920880005.123\"," +
-            "\"duration\":122," +
-            "\"size\":9875," +
+            "\"time\":920880005.023," +
+            "\"duration\":0.122," +
+            "\"responsesize\":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\"" +
+            "\"remoteaddr\":\"FE80:0000:0000:0000:0202:B3FF:FE1E:8329\"," +
+            "\"search\":{" +
+            "\"totalhits\":1234," +
+            "\"hits\":0" +
+            "}" +
             "}";
 
         assertEquals(expectedOutput, new JSONFormatter(entry).format());
@@ -112,19 +118,21 @@ public class JSONLogTestCase extends junit.framework.TestCase {
 
         expectedOutput =
             "{\"ip\":\"152.200.54.243\"," +
-            "\"time\":\"920880005.123\"," +
-            "\"duration\":122," +
-            "\"size\":9875," +
+            "\"time\":920880005.023," +
+            "\"duration\":0.122," +
+            "\"responsesize\":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" +
+            "\"remoteport\":1234," +
+            "\"search\":{" +
+            "\"totalhits\":1234," +
+            "\"hits\":0" +
+            "}" +
             "}";
 
         assertEquals(expectedOutput, new JSONFormatter(entry).format());
@@ -148,23 +156,25 @@ public class JSONLogTestCase extends junit.framework.TestCase {
         entry.setHitCounts(new HitCounts(0, 10, 1234, 0, 10));
         entry.setHostString("localhost");
         entry.setStatusCode(200);
-        entry.setTimeStamp(920880005123L);
+        entry.setTimeStamp(920880005023L);
         entry.setDurationBetweenRequestResponse(122);
         entry.setReturnedContentSize(9875);
 
         String expectedOutput =
             "{\"ip\":\"152.200.54.243\"," +
-            "\"time\":\"920880005.123\"," +
-            "\"duration\":122," +
-            "\"size\":9875," +
+            "\"time\":920880005.023," +
+            "\"duration\":0.122," +
+            "\"responsesize\":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\"" +
+            "\"host\":\"localhost\"," +
+            "\"search\":{" +
+            "\"totalhits\":1234," +
+            "\"hits\":0" +
+            "}" +
             "}";
 
         assertEquals(expectedOutput, new JSONFormatter(entry).format());