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

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

3 files changed, 25 insertions, 158 deletions

diff --git a/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java b/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java
index 3602d21f7d8..d636d3bc925 100644
--- a/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java
+++ b/container-search/src/main/java/com/yahoo/search/handler/HttpSearchResponse.java
@@ -23,6 +23,7 @@ import com.yahoo.processing.rendering.Renderer;
 import com.yahoo.search.Query;
 import com.yahoo.search.Result;
 import com.yahoo.search.query.context.QueryContext;
+import com.yahoo.yolean.trace.TraceNode;
 
 /**
  * Wrap the result of a query as an HTTP response.
@@ -36,8 +37,13 @@ public class HttpSearchResponse extends ExtendedResponse {
     private final Renderer<Result> rendererCopy;
     private final Timing timing;
     private final HitCounts hitCounts;
+    private final TraceNode trace;
 
     public HttpSearchResponse(int status, Result result, Query query, Renderer renderer) {
+        this(status, result, query, renderer, null);
+    }
+
+    HttpSearchResponse(int status, Result result, Query query, Renderer renderer, TraceNode trace) {
         super(status);
         this.query = query;
         this.result = result;
@@ -45,6 +51,7 @@ public class HttpSearchResponse extends ExtendedResponse {
 
         this.timing = SearchResponse.createTiming(query, result);
         this.hitCounts = SearchResponse.createHitCounts(query, result);
+        this.trace = trace;
         populateHeaders(headers(), result.getHeaders(false));
     }
 
@@ -107,6 +114,9 @@ public class HttpSearchResponse extends ExtendedResponse {
     @Override
     public void populateAccessLogEntry(final AccessLogEntry accessLogEntry) {
         super.populateAccessLogEntry(accessLogEntry);
+        if (trace != null) {
+            accessLogEntry.setTrace(trace);
+        }
         populateAccessLogEntry(accessLogEntry, getHitCounts());
     }
 
diff --git a/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java b/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java
index 0f0df3aa93e..dc066e65434 100644
--- a/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java
+++ b/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java
@@ -296,7 +296,10 @@ public class SearchHandler extends LoggingRequestHandler {
         // Transform result to response
         Renderer renderer = toRendererCopy(query.getPresentation().getRenderer());
         HttpSearchResponse response = new HttpSearchResponse(getHttpResponseStatus(request, result),
-                                                             result, query, renderer);
+                                                             result, query, renderer,
+                                                             log.isLoggable(Level.FINE)
+                                                                     ? query.getContext(false).getTrace().traceNode()
+                                                                     : null);
         if (hostResponseHeaderKey.isPresent())
             response.headers().add(hostResponseHeaderKey.get(), selfHostname);
 
@@ -410,7 +413,7 @@ public class SearchHandler extends LoggingRequestHandler {
         } catch (ParseException e) {
             ErrorMessage error = ErrorMessage.createIllegalQuery("Could not parse query [" + request + "]: "
                                                                  + Exceptions.toMessageString(e));
-            log.log(LogLevel.DEBUG, () -> error.getDetailedMessage());
+            log.log(LogLevel.DEBUG, error.getDetailedMessage());
             return new Result(query, error);
         } catch (IllegalArgumentException e) {
             if ("Comparison method violates its general contract!".equals(e.getMessage())) {
@@ -422,7 +425,7 @@ public class SearchHandler extends LoggingRequestHandler {
             else {
                 ErrorMessage error = ErrorMessage.createBadRequest("Invalid search request [" + request + "]: "
                                                                    + Exceptions.toMessageString(e));
-                log.log(LogLevel.DEBUG, () -> error.getDetailedMessage());
+                log.log(LogLevel.DEBUG, error.getDetailedMessage());
                 return new Result(query, error);
             }
         } catch (LinkageError | StackOverflowError e) {
diff --git a/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java b/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java
index af453983f89..89135128cba 100644
--- a/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java
+++ b/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java
@@ -7,6 +7,7 @@ import com.fasterxml.jackson.core.JsonGenerator;
 import com.fasterxml.jackson.core.TreeNode;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import com.google.common.base.Preconditions;
+import com.yahoo.container.logging.TraceRenderer;
 import com.yahoo.data.JsonProducer;
 import com.yahoo.data.access.Inspectable;
 import com.yahoo.data.access.Inspector;
@@ -44,8 +45,6 @@ import com.yahoo.search.result.Hit;
 import com.yahoo.search.result.HitGroup;
 import com.yahoo.search.result.NanNumber;
 import com.yahoo.tensor.Tensor;
-import com.yahoo.yolean.trace.TraceNode;
-import com.yahoo.yolean.trace.TraceVisitor;
 import org.json.JSONArray;
 import org.json.JSONObject;
 
@@ -111,10 +110,6 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> {
     private static final String ROOT = "root";
     private static final String SOURCE = "source";
     private static final String TOTAL_COUNT = "totalCount";
-    private static final String TRACE = "trace";
-    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 TIMING = "timing";
     private static final String QUERY_TIME = "querytime";
     private static final String SUMMARY_FETCH_TIME = "summaryfetchtime";
@@ -132,145 +127,6 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> {
     private LongSupplier timeSource;
     private OutputStream stream;
 
-    private class TraceRenderer extends TraceVisitor {
-        private final long basetime;
-        private boolean hasFieldName = false;
-        int emittedChildNesting = 0;
-        int currentChildNesting = 0;
-        private boolean insideOpenObject = false;
-
-        TraceRenderer(long basetime) {
-            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.renderFieldContentsDirect(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;
-        }
-    }
-
-    private 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);
-        }
-
-    }
-
     public JsonRenderer() {
         this(null);
     }
@@ -352,8 +208,8 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> {
             long basetime = trace.traceNode().timestamp();
             if (basetime == 0L)
                 basetime = getResult().getElapsedTime().first();
-            trace.accept(new TraceRenderer(basetime));
-        } catch (TraceRenderWrapper e) {
+            trace.accept(new TraceRenderer(generator, fieldConsumer, basetime));
+        } catch (TraceRenderer.TraceRenderWrapper e) {
             throw new IOException(e);
         }
     }
@@ -641,11 +497,9 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> {
 
     private String getJsonCallback() {
         Result result = getResult();
-        if (result != null) {
-            Query query = result.getQuery();
-            if (query != null) {
-                return query.properties().getString(JSON_CALLBACK, null);
-            }
+        Query query = result.getQuery();
+        if (query != null) {
+            return query.properties().getString(JSON_CALLBACK, null);
         }
         return null;
     }
@@ -671,7 +525,7 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> {
      * This instance is reused for all hits of a Result since we are in a single-threaded context
      * and want to limit object creation.
      */
-    public static class FieldConsumer implements Hit.RawUtf8Consumer {
+    public static class FieldConsumer implements Hit.RawUtf8Consumer, TraceRenderer.FieldConsumer {
 
         private final JsonGenerator generator;
         private final boolean debugRendering;
@@ -788,11 +642,11 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> {
             if (field instanceof Inspectable && ! (field instanceof FeatureData)) {
                 renderInspector(((Inspectable)field).inspect());
             } else {
-                renderFieldContentsDirect(field);
+                consume(field);
             }
         }
 
-        private void renderFieldContentsDirect(Object field) throws IOException {
+        public void consume(Object field) throws IOException {
             if (field == null) {
                 generator.writeNull();
             } else if (field instanceof Boolean) {