Formatted trace logs include tracing tags (#22)

Formatted trace logs include tracing tags
palantir · Aug 17, 2021 · caf1d56 · caf1d56
1 parent d29ba2a
commit caf1d56
Show file tree

Hide file tree

Showing 4 changed files with 45 additions and 13 deletions.
diff --git a/changelog/@unreleased/pr-22.v2.yml b/changelog/@unreleased/pr-22.v2.yml
@@ -0,0 +1,5 @@
+type: improvement
+improvement:
+  description: Formatted trace logs include tracing tags
+  links:
+  - https://github.com/palantir/witchcraft-java-logging/pull/22
diff --git a/...rmatting/src/main/java/com/palantir/witchcraft/java/logging/format/TraceLogFormatter.java b/...rmatting/src/main/java/com/palantir/witchcraft/java/logging/format/TraceLogFormatter.java
@@ -16,8 +16,10 @@
 
 package com.palantir.witchcraft.java.logging.format;
 
+import com.palantir.witchcraft.api.logging.Span;
 import com.palantir.witchcraft.api.logging.TraceLogV1;
 import java.time.format.DateTimeFormatter;
+import java.util.Map;
 
 final class TraceLogFormatter {
     private TraceLogFormatter() {}
@@ -26,15 +28,21 @@ static String format(TraceLogV1 trace) {
         return Formatting.withStringBuilder(buffer -> {
             buffer.append('[');
             DateTimeFormatter.ISO_INSTANT.formatTo(trace.getTime(), buffer);
-            buffer.append("] traceId: ")
-                    .append(trace.getSpan().getTraceId())
-                    .append(" id: ")
-                    .append(trace.getSpan().getId())
-                    .append(" name: ")
-                    .append(trace.getSpan().getName())
-                    .append(" duration: ")
-                    .append(trace.getSpan().getDuration().longValue())
-                    .append(" microseconds");
+            Span span = trace.getSpan();
+            buffer.append("] trace: ")
+                    .append(span.getTraceId())
+                    .append(", span: ")
+                    .append(span.getId())
+                    .append(", name: ")
+                    .append(span.getName())
+                    .append(", duration: ")
+                    .append(span.getDuration().longValue())
+                    .append(" µs");
+            Map<String, String> tags = span.getTags();
+            if (!tags.isEmpty()) {
+                buffer.append(' ');
+                Formatting.niceMap(tags, buffer);
+            }
         });
     }
 }
diff --git a/...ting/src/test/java/com/palantir/witchcraft/java/logging/format/TraceLogFormatterTest.java b/...ting/src/test/java/com/palantir/witchcraft/java/logging/format/TraceLogFormatterTest.java
@@ -40,7 +40,26 @@ void formats_correctly() {
                 .build());
 
         assertThat(formatted)
-                .isEqualTo(
-                        "[2019-12-25T01:02:03Z] traceId: abdefghijklmno id: id name: name duration: 31 microseconds");
+                .isEqualTo("[2019-12-25T01:02:03Z] trace: abdefghijklmno, span: id, name: name, duration: 31 µs");
+    }
+
+    @Test
+    void formats_tags_correctly() {
+        String formatted = TraceLogFormatter.format(TraceLogV1.builder()
+                .type("trace.1")
+                .time(TestData.XMAS_2019)
+                .span(Span.builder()
+                        .traceId("abdefghijklmno")
+                        .id("id")
+                        .name("name")
+                        .timestamp(SafeLong.of(999))
+                        .duration(SafeLong.of(31))
+                        .tags("tagName", "tagValue")
+                        .build())
+                .build());
+
+        assertThat(formatted)
+                .isEqualTo("[2019-12-25T01:02:03Z] trace: abdefghijklmno, span: id, "
+                        + "name: name, duration: 31 µs (tagName: tagValue)");
     }
 }
diff --git a/...rc/test/java/com/palantir/witchcraft/java/logging/idea/WitchcraftLogFormatFilterTest.java b/...rc/test/java/com/palantir/witchcraft/java/logging/idea/WitchcraftLogFormatFilterTest.java
@@ -69,8 +69,8 @@ public final class WitchcraftLogFormatFilterTest {
             + "\"name\":\"config-reload\",\"timestamp\":1558716040949000,\"duration\":618,"
             + "\"annotations\":[{\"timestamp\":1558716040949000,\"value\":\"lc\","
             + "\"endpoint\":{\"serviceName\":\"my-service\",\"ipv4\":\"10.193.122.103\"}}]}}";
-    private static final String TRACE_FORMATTED = "[2019-05-24T16:40:40.950Z] traceId: 2250486695021e19 "
-            + "id: c11b9a31555b7035 name: config-reload duration: 618 microseconds";
+    private static final String TRACE_FORMATTED = "[2019-05-24T16:40:40.950Z] trace: 2250486695021e19, "
+            + "span: c11b9a31555b7035, name: config-reload, duration: 618 µs";
 
     private static final String NEWLINE = "\n";