diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2020-02-12 22:40:24 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2020-02-12 22:40:24 +0100 |
commit | cf454a47f5a9de067d46e9d6db6bf046c899aeab (patch) | |
tree | f7bde7c62f958d983731481b7c374767f5d638a1 /container-accesslogging | |
parent | 97c1862a655f18b637a5dddb03c357c8265d762b (diff) | |
parent | 1a6abd7597167c066d419fc408f2a2fdd4a4dddd (diff) |
Merge pull request #12165 from vespa-engine/balder/add-support-for-trace-in-accesslog
Balder/add support for trace in accesslog
Diffstat (limited to 'container-accesslogging')
4 files changed, 243 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..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"); |