tracer: fix trace id logging (#1746)

When DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED is false, only the lower-order 64-bits of the TraceId should be logged.
When DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED is true, the format of the injected TraceId is conditional based on the higher-order 64 bits of the TraceId - specifically, when:
zero - the injected TraceId will be its decimal string encoding (preserving the current behavior of 64-bit TraceIds)
non-zero - the injected TraceId will be encoded as 32 lower-case hexadecimal characters with zero-padding as necessary

ddtrace/tracer/span.go

@@ -632,11 +632,13 @@ func (s *span) Format(f fmt.State, c rune) {
 				fmt.Fprintf(f, "dd.version=%s ", v)
 			}
 		}
-		if sharedinternal.BoolEnv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", false) {
-			fmt.Fprintf(f, `dd.trace_id="0x%s" `, strings.TrimLeft(s.context.TraceID128(), "0"))
+		var traceID string
+		if sharedinternal.BoolEnv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", false) && strings.TrimLeft(s.context.traceID128, "0") != "" {
+			traceID = s.context.TraceID128()
 		} else {
-			fmt.Fprintf(f, `dd.trace_id="%d" `, s.TraceID)
+			traceID = fmt.Sprintf("%d", s.TraceID)
 		}
+		fmt.Fprintf(f, `dd.trace_id=%q `, traceID)
 		fmt.Fprintf(f, `dd.span_id="%d"`, s.SpanID)
 	default:
 		fmt.Fprintf(f, "%%!%c(ddtrace.Span=%v)", c, s)

ddtrace/tracer/span_test.go

@@ -709,28 +709,61 @@ func TestSpanLog(t *testing.T) {
 		assert.Equal(expect, fmt.Sprintf("%v", span))
 	})
 
-	t.Run("128-bit-generation", func(t *testing.T) {
+	t.Run("128-bit-generation-only", func(t *testing.T) {
 		// Generate 128 bit trace ids, but don't log them. So only the lower
 		// 64 bits should be logged in decimal form.
 		t.Setenv("DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED", "true")
+		// DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED is false by default
 		assert := assert.New(t)
 		tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv"))
 		defer stop()
 		span := tracer.StartSpan("test.request").(*span)
-		expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id="%d" dd.span_id="%d"`, span.TraceID, span.SpanID)
+		span.TraceID = 12345678
+		span.SpanID = 87654321
+		expect := `dd.service=tracer.test dd.env=testenv dd.trace_id="12345678" dd.span_id="87654321"`
 		assert.Equal(expect, fmt.Sprintf("%v", span))
 	})
 
-	t.Run("128-bit-generation-and-logging", func(t *testing.T) {
+	t.Run("128-bit-logging-only", func(t *testing.T) {
+		// Logging 128-bit trace ids is enabled, but it's not present in
+		// the span. So only the lower 64 bits should be logged in decimal form.
+		t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "true")
+		// DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED is false by default
+		assert := assert.New(t)
+		tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv"))
+		defer stop()
+		span := tracer.StartSpan("test.request").(*span)
+		span.TraceID = 12345678
+		span.SpanID = 87654321
+		expect := `dd.service=tracer.test dd.env=testenv dd.trace_id="12345678" dd.span_id="87654321"`
+		assert.Equal(expect, fmt.Sprintf("%v", span))
+	})
+
+	t.Run("128-bit-logging-with-generation", func(t *testing.T) {
+		// Logging 128-bit trace ids is enabled, and a 128-bit trace id, so
+		// a quoted 32 byte hex string should be printed for the dd.trace_id.
 		t.Setenv("DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED", "true")
 		t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "true")
 		assert := assert.New(t)
 		tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv"))
 		defer stop()
 		span := tracer.StartSpan("test.request").(*span)
-		expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id="0x%s" dd.span_id="%d"`, span.context.TraceID128(), span.SpanID)
+		span.SpanID = 87654321
+		expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id=%q dd.span_id="87654321"`, span.context.TraceID128())
 		assert.Equal(expect, fmt.Sprintf("%v", span))
 	})
+
+	t.Run("128-bit-logging-with-small-upper-bits", func(t *testing.T) {
+		// Logging 128-bit trace ids is enabled, and a 128-bit trace id, so
+		// a quoted 32 byte hex string should be printed for the dd.trace_id.
+		t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "true")
+		assert := assert.New(t)
+		tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv"))
+		defer stop()
+		span := tracer.StartSpan("test.request", WithSpanID(87654321)).(*span)
+		span.context.traceID128 = "01"
+		assert.Equal(`dd.service=tracer.test dd.env=testenv dd.trace_id="00000000000000010000000005397fb1" dd.span_id="87654321"`, fmt.Sprintf("%v", span))
+	})
 }
 
 func TestRootSpanAccessor(t *testing.T) {