diff options
8 files changed, 272 insertions, 161 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..295786aa15d --- /dev/null +++ b/container-accesslogging/src/main/java/com/yahoo/container/logging/TraceRenderer.java @@ -0,0 +1,185 @@ +package com.yahoo.container.logging; + +import com.yahoo.data.access.Inspectable; +import com.yahoo.data.access.Inspector; +import com.yahoo.data.access.simple.JsonRender; +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 accept(Object object) throws IOException; + } + + private static class Consumer implements FieldConsumer { + private final JsonGenerator generator; + + Consumer(JsonGenerator generator) { + this.generator = generator; + } + + @Override + public void accept(Object object) throws IOException { + if (object instanceof Inspectable) { + renderInspectorDirect(((Inspectable) object).inspect()); + } else { + generator.writeObject(object); + } + } + private void renderInspectorDirect(Inspector data) throws IOException { + StringBuilder intermediate = new StringBuilder(); + JsonRender.render(data, intermediate, true); + generator.writeRawValue(intermediate.toString()); + } + } + + 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.accept(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"); diff --git a/container-search/abi-spec.json b/container-search/abi-spec.json index 437db99c45b..78d6dcc9670 100644 --- a/container-search/abi-spec.json +++ b/container-search/abi-spec.json @@ -6937,7 +6937,8 @@ "com.yahoo.search.rendering.JsonRenderer$FieldConsumer": { "superClass": "java.lang.Object", "interfaces": [ - "com.yahoo.search.result.Hit$RawUtf8Consumer" + "com.yahoo.search.result.Hit$RawUtf8Consumer", + "com.yahoo.container.logging.TraceRenderer$FieldConsumer" ], "attributes": [ "public" @@ -6949,6 +6950,7 @@ "protected boolean shouldRender(java.lang.String, java.lang.Object)", "protected boolean shouldRenderUtf8Value(java.lang.String, int)", "protected void renderFieldContents(java.lang.Object)", + "public void accept(java.lang.Object)", "public bridge synthetic void accept(java.lang.Object, java.lang.Object)" ], "fields": [] 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..dad106570ab 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..31f8194b3b7 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,12 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> { if (field instanceof Inspectable && ! (field instanceof FeatureData)) { renderInspector(((Inspectable)field).inspect()); } else { - renderFieldContentsDirect(field); + accept(field); } } - private void renderFieldContentsDirect(Object field) throws IOException { + @Override + public void accept(Object field) throws IOException { if (field == null) { generator.writeNull(); } else if (field instanceof Boolean) { |