- Add trace as a field in the josn access log.

- Add the trace top the accesslog entry if debugging is enabled in SearchHandler.

4 files changed, 231 insertions, 2 deletions

diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/AccessLogEntry.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/AccessLogEntry.java
index b943c03f48f..d8085cc808b 100644
--- a/container-accesslogging/src/main/java/com/yahoo/container/logging/AccessLogEntry.java
+++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/AccessLogEntry.java
@@ -2,6 +2,7 @@
 package com.yahoo.container.logging;
 
 import com.yahoo.collections.ListMap;
+import com.yahoo.yolean.trace.TraceNode;
 
 import javax.security.auth.x500.X500Principal;
 import java.net.InetAddress;
@@ -69,6 +70,7 @@ public class AccessLogEntry {
     private X500Principal sslPrincipal;
     private String rawPath;
     private String rawQuery;
+    private TraceNode traceNode;
 
     private ListMap<String,String> keyValues=null;
 
@@ -452,6 +454,18 @@ public class AccessLogEntry {
         }
     }
 
+    public void setTrace(TraceNode traceNode) {
+        synchronized (monitor) {
+            requireNull(this.traceNode);
+            this.traceNode = traceNode;
+        }
+    }
+    public TraceNode getTrace() {
+        synchronized (monitor) {
+            return traceNode;
+        }
+    }
+
     @Override
     public String toString() {
         synchronized (monitor) {
@@ -481,6 +495,7 @@ public class AccessLogEntry {
                     ", sslPrincipal=" + sslPrincipal +
                     ", rawPath='" + rawPath + '\'' +
                     ", rawQuery='" + rawQuery + '\'' +
+                    ", trace='" + traceNode + '\'' +
                     ", keyValues=" + keyValues +
                     '}';
         }
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 556b97ced62..ae794e5b60a 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
@@ -5,6 +5,7 @@ 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 com.yahoo.yolean.trace.TraceNode;
 
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
@@ -55,8 +56,7 @@ public class JSONFormatter {
             generator.writeStartObject();
             generator.writeStringField("ip", accessLogEntry.getIpV4Address());
             generator.writeNumberField("time", toTimestampInSeconds(accessLogEntry.getTimeStampMillis()));
-            generator.writeNumberField("duration",
-                                       durationAsSeconds(accessLogEntry.getDurationBetweenRequestResponseMillis()));
+            generator.writeNumberField("duration", durationAsSeconds(accessLogEntry.getDurationBetweenRequestResponseMillis()));
             generator.writeNumberField("responsesize", accessLogEntry.getReturnedContentSize());
             generator.writeNumberField("code", accessLogEntry.getStatusCode());
             generator.writeStringField("method", accessLogEntry.getHttpMethod());
@@ -95,6 +95,15 @@ public class JSONFormatter {
                 }
             }
 
+            TraceNode trace = accessLogEntry.getTrace();
+            if (trace != null) {
+                long timestamp = trace.timestamp();
+                if (timestamp == 0L) {
+                    timestamp = accessLogEntry.getTimeStampMillis();
+                }
+                trace.accept(new TraceRenderer(generator, timestamp));
+            }
+
             // Only add search sub block of this is a search request
             if (isSearchRequest(accessLogEntry)) {
                 generator.writeObjectFieldStart("search");
diff --git a/container-accesslogging/src/main/java/com/yahoo/container/logging/TraceRenderer.java b/container-accesslogging/src/main/java/com/yahoo/container/logging/TraceRenderer.java
new file mode 100644
index 00000000000..b974111b007
--- /dev/null
+++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/TraceRenderer.java
@@ -0,0 +1,173 @@
+package com.yahoo.container.logging;
+
+import com.yahoo.yolean.trace.TraceNode;
+import com.yahoo.yolean.trace.TraceVisitor;
+import com.fasterxml.jackson.core.JsonGenerator;
+
+import java.io.IOException;
+
+public class TraceRenderer extends TraceVisitor {
+    private static final String TRACE_CHILDREN = "children";
+    private static final String TRACE_MESSAGE = "message";
+    private static final String TRACE_TIMESTAMP = "timestamp";
+    private static final String TRACE = "trace";
+
+    private final long basetime;
+    private final JsonGenerator generator;
+    private final FieldConsumer fieldConsumer;
+    private boolean hasFieldName = false;
+    int emittedChildNesting = 0;
+    int currentChildNesting = 0;
+    private boolean insideOpenObject = false;
+
+    public interface FieldConsumer {
+        void consume(Object object) throws IOException;
+    }
+
+    private static class Consumer implements FieldConsumer {
+        private final JsonGenerator generator;
+
+        Consumer(JsonGenerator generator) {
+            this.generator = generator;
+        }
+
+        @Override
+        public void consume(Object object) throws IOException {
+            generator.writeObject(object);
+        }
+    }
+
+    TraceRenderer(JsonGenerator generator, long basetime) {
+        this(generator, new Consumer(generator), basetime);
+    }
+    public TraceRenderer(JsonGenerator generator, FieldConsumer consumer, long basetime) {
+        this.generator = generator;
+        this.fieldConsumer = consumer;
+        this.basetime = basetime;
+    }
+
+    @Override
+    public void entering(TraceNode node) {
+        ++currentChildNesting;
+    }
+
+    @Override
+    public void leaving(TraceNode node) {
+        conditionalEndObject();
+        if (currentChildNesting == emittedChildNesting) {
+            try {
+                generator.writeEndArray();
+                generator.writeEndObject();
+            } catch (IOException e) {
+                throw new TraceRenderWrapper(e);
+            }
+            --emittedChildNesting;
+        }
+        --currentChildNesting;
+    }
+
+    @Override
+    public void visit(TraceNode node) {
+        try {
+            doVisit(node.timestamp(), node.payload(), node.children().iterator().hasNext());
+        } catch (IOException e) {
+            throw new TraceRenderWrapper(e);
+        }
+    }
+
+    private void doVisit(long timestamp, Object payload, boolean hasChildren) throws IOException {
+        boolean dirty = false;
+        if (timestamp != 0L) {
+            header();
+            generator.writeStartObject();
+            generator.writeNumberField(TRACE_TIMESTAMP, timestamp - basetime);
+            dirty = true;
+        }
+        if (payload != null) {
+            if (!dirty) {
+                header();
+                generator.writeStartObject();
+            }
+            generator.writeFieldName(TRACE_MESSAGE);
+            fieldConsumer.consume(payload);
+            dirty = true;
+        }
+        if (dirty) {
+            if (!hasChildren) {
+                generator.writeEndObject();
+            } else {
+                setInsideOpenObject(true);
+            }
+        }
+    }
+    private void header() {
+        fieldName();
+        for (int i = 0; i < (currentChildNesting - emittedChildNesting); ++i) {
+            startChildArray();
+        }
+        emittedChildNesting = currentChildNesting;
+    }
+
+    private void startChildArray() {
+        try {
+            conditionalStartObject();
+            generator.writeArrayFieldStart(TRACE_CHILDREN);
+        } catch (IOException e) {
+            throw new TraceRenderWrapper(e);
+        }
+    }
+
+    private void conditionalStartObject() throws IOException {
+        if (!isInsideOpenObject()) {
+            generator.writeStartObject();
+        } else {
+            setInsideOpenObject(false);
+        }
+    }
+
+    private void conditionalEndObject() {
+        if (isInsideOpenObject()) {
+            // This triggers if we were inside a data node with payload and
+            // subnodes, but none of the subnodes contained data
+            try {
+                generator.writeEndObject();
+                setInsideOpenObject(false);
+            } catch (IOException e) {
+                throw new TraceRenderWrapper(e);
+            }
+        }
+    }
+
+    private void fieldName() {
+        if (hasFieldName) {
+            return;
+        }
+
+        try {
+            generator.writeFieldName(TRACE);
+        } catch (IOException e) {
+            throw new TraceRenderWrapper(e);
+        }
+        hasFieldName = true;
+    }
+
+    boolean isInsideOpenObject() {
+        return insideOpenObject;
+    }
+
+    void setInsideOpenObject(boolean insideOpenObject) {
+        this.insideOpenObject = insideOpenObject;
+    }
+    public static final class TraceRenderWrapper extends RuntimeException {
+
+        /**
+         * Should never be serialized, but this is still needed.
+         */
+        private static final long serialVersionUID = 2L;
+
+        TraceRenderWrapper(IOException wrapped) {
+            super(wrapped);
+        }
+
+    }
+}
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 8bbb8500cfd..6c7878f99ed 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
@@ -1,8 +1,10 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.container.logging;
 
+import com.yahoo.yolean.trace.TraceNode;
 import org.junit.Test;
 
+import java.io.IOException;
 import java.net.URI;
 
 import static org.junit.Assert.assertEquals;
@@ -70,6 +72,36 @@ public class JSONLogTestCase {
     }
 
     @Test
+    public void test_json_of_trace() throws IOException {
+        TraceNode root = new TraceNode("root", 7);
+        AccessLogEntry entry = newAccessLogEntry("test");
+        entry.setTrace(root);
+
+        String expectedOutput =
+                "{\"ip\":\"152.200.54.243\"," +
+                "\"time\":920880005.023," +
+                "\"duration\":0.122," +
+                "\"responsesize\":9875," +
+                "\"code\":200," +
+                "\"method\":\"GET\"," +
+                "\"uri\":\"?query=test\"," +
+                "\"version\":\"HTTP/1.1\"," +
+                "\"agent\":\"Mozilla/4.05 [en] (Win95; I)\"," +
+                "\"host\":\"localhost\"," +
+                "\"scheme\":null," +
+                "\"localport\":0," +
+                "\"trace\":{\"timestamp\":0,\"message\":\"root\"}," +
+                "\"search\":{" +
+                "\"totalhits\":1234," +
+                "\"hits\":0," +
+                "\"coverage\":{\"coverage\":100,\"documents\":100}" +
+                "}" +
+                "}";
+
+        assertEquals(expectedOutput, new JSONFormatter(entry).format());
+    }
+
+    @Test
     public void test_with_keyvalues() {
         AccessLogEntry entry = newAccessLogEntry("test");
         entry.addKeyValue("singlevalue", "value1");