Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ddtrace/tracer: Enable 128bit trace ID logging by default #3086

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
Open

ddtrace/tracer: Enable 128bit trace ID logging by default #3086

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
bc24881
Enable DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED by default
mtoffl01 Jan 14, 2025
b08de4b
Update tests previously relying on 64bit tids
mtoffl01 Jan 15, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions contrib/net/http/trace_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -329,8 +329,8 @@ func TestTraceAndServe(t *testing.T) {
t.Setenv("DD_TRACE_HTTP_SERVER_ERROR_STATUSES", "500")

cfg := &ServeConfig{
Service: "service",
Resource: "resource",
Service: "service",
Resource: "resource",
}

handler := func(w http.ResponseWriter, r *http.Request) {
Expand Down
6 changes: 4 additions & 2 deletions ddtrace/tracer/log_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -187,9 +187,11 @@ func TestLogFormat(t *testing.T) {
defer stop()
tp.Reset()
tp.Ignore("appsec: ", telemetry.LogPrefix)
tracer.StartSpan("test", ServiceName("test-service"), ResourceName("/"), WithSpanID(12345))
sp := tracer.StartSpan("test", ServiceName("test-service"), ResourceName("/"), WithSpanID(12345))
sCtx, ok := sp.Context().(*spanContext)
assert.True(ok)
assert.Len(tp.Logs(), 1)
assert.Regexp(logPrefixRegexp+` DEBUG: Started Span: dd.trace_id="12345" dd.span_id="12345" dd.parent_id="0", Operation: test, Resource: /, Tags: map.*, map.*`, tp.Logs()[0])
assert.Regexp(logPrefixRegexp+` DEBUG: Started Span: dd.trace_id="`+sCtx.TraceID128()+`" dd.span_id="12345" dd.parent_id="0", Operation: test, Resource: /, Tags: map.*, map.*`, tp.Logs()[0])
}

func TestLogPropagators(t *testing.T) {
Expand Down
2 changes: 1 addition & 1 deletion ddtrace/tracer/span.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -709,7 +709,7 @@ func (s *span) Format(f fmt.State, c rune) {
}
}
var traceID string
if sharedinternal.BoolEnv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", false) && s.context.traceID.HasUpper() {
if sharedinternal.BoolEnv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", true) && s.context.traceID.HasUpper() {
traceID = s.context.TraceID128()
} else {
traceID = fmt.Sprintf("%d", s.TraceID)
Expand Down
78 changes: 40 additions & 38 deletions ddtrace/tracer/span_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -712,7 +712,8 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t)
defer stop()
span := tracer.StartSpan("test.request").(*span)
expect := fmt.Sprintf(`dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
}
t.Run("noservice_first", noServiceTest)
Expand All @@ -722,7 +723,8 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"))
defer stop()
span := tracer.StartSpan("test.request").(*span)
expect := fmt.Sprintf(`dd.service=tracer.test dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.service=tracer.test dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -731,7 +733,8 @@ func TestSpanLog(t *testing.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" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -740,7 +743,8 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithServiceVersion("1.2.3"))
defer stop()
span := tracer.StartSpan("test.request").(*span)
expect := fmt.Sprintf(`dd.service=tracer.test dd.version=1.2.3 dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.service=tracer.test dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -749,7 +753,8 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithServiceVersion("1.2.3"), WithEnv("testenv"))
defer stop()
span := tracer.StartSpan("test.request").(*span)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.version=1.2.3 dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -761,7 +766,8 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithServiceVersion("1.2.3"), WithEnv("testenv"))
defer stop()
span := tracer.StartSpan("test.request", ServiceName("subservice name")).(*span)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.version=1.2.3 dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -773,7 +779,8 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t)
defer stop()
span := tracer.StartSpan("test.request").(*span)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.version=1.2.3 dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -782,17 +789,19 @@ func TestSpanLog(t *testing.T) {
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithServiceVersion("1.2.3"))
defer stop()
span := tracer.StartSpan("test.request").(*span)
expect := fmt.Sprintf(`%%!b(ddtrace.Span=dd.service=tracer.test dd.version=1.2.3 dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0")`, span.TraceID, span.SpanID)
sctx := span.Context().(*spanContext)
expect := fmt.Sprintf(`%%!b(ddtrace.Span=dd.service=tracer.test dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0")`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%b", span))
})

t.Run("notracer/options", func(t *testing.T) {
assert := assert.New(t)
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithServiceVersion("1.2.3"), WithEnv("testenv"))
span := tracer.StartSpan("test.request").(*span)
sctx := span.Context().(*spanContext)
stop()
// no service, env, or version after the tracer is stopped
expect := fmt.Sprintf(`dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
expect := fmt.Sprintf(`dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

Expand All @@ -803,34 +812,32 @@ func TestSpanLog(t *testing.T) {
assert := assert.New(t)
tracer, _, _, stop := startTestTracer(t)
span := tracer.StartSpan("test.request").(*span)
sctx := span.Context().(*spanContext)
stop()
// service is not included: it is cleared when we stop the tracer
// env, version are included: it reads the environment variable when there is no tracer
expect := fmt.Sprintf(`dd.env=testenv dd.version=1.2.3 dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.TraceID, span.SpanID)
expect := fmt.Sprintf(`dd.env=testenv dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, sctx.TraceID128(), span.SpanID)
assert.Equal(expect, fmt.Sprintf("%v", span))
})

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.
// DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED is true by default
// DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED is false by default
t.Run("128-bit-logging-default", func(t *testing.T) {
// Generate and log 128 bit trace ids 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
span.Finish()
expect := `dd.service=tracer.test dd.env=testenv dd.trace_id="12345678" dd.span_id="87654321" dd.parent_id="0"`
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id=%q dd.span_id="87654321" dd.parent_id="0"`, span.context.TraceID128())
assert.Equal(expect, fmt.Sprintf("%v", span))
v, _ := getMeta(span, keyTraceID128)
assert.NotEmpty(v)
})

t.Run("128-bit-logging-only", func(t *testing.T) {
// Logging 128-bit trace ids is enabled, but it's not present in
// Logging 128-bit trace ids is enabled, but format is not present in
// the span. So only the lower 64 bits should be logged in decimal form.
t.Setenv("DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED", "false")
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()
Expand All @@ -842,27 +849,9 @@ func TestSpanLog(t *testing.T) {
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)
span.SpanID = 87654321
span.Finish()
expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id=%q dd.span_id="87654321" dd.parent_id="0"`, span.context.TraceID128())
assert.Equal(expect, fmt.Sprintf("%v", span))
v, _ := getMeta(span, keyTraceID128)
assert.NotEmpty(v)
})

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")
t.Setenv("DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED", "false")
assert := assert.New(t)
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv"))
Expand All @@ -878,7 +867,6 @@ func TestSpanLog(t *testing.T) {
t.Run("128-bit-logging-with-empty-upper-bits", func(t *testing.T) {
// Logging 128-bit trace ids is enabled, and but the upper 64 bits
// are empty, so the dd.trace_id should be printed as raw digits (not hex).
t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "true")
t.Setenv("DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED", "false")
assert := assert.New(t)
tracer, _, _, stop := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv"))
Expand All @@ -890,6 +878,20 @@ func TestSpanLog(t *testing.T) {
v, _ := getMeta(span, keyTraceID128)
assert.Equal("", v)
})
t.Run("128-bit-logging-disabled", func(t *testing.T) {
// Only the lower 64 bits should be logged in decimal form.
// DD_TRACE_128_BIT_TRACEID_GENERATION_ENABLED is true by default
t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "false")
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
span.Finish()
expect := `dd.service=tracer.test dd.env=testenv dd.trace_id="12345678" dd.span_id="87654321" dd.parent_id="0"`
assert.Equal(expect, fmt.Sprintf("%v", span))
})
}

func TestRootSpanAccessor(t *testing.T) {
Expand Down
Loading