From bc248810cd2ede237e49d67f495a442bcd30dec9 Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Tue, 14 Jan 2025 16:45:13 -0500 Subject: [PATCH 1/8] Enable DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED by default --- contrib/net/http/trace_test.go | 4 +-- ddtrace/tracer/span.go | 2 +- ddtrace/tracer/span_test.go | 46 ++++++++++++++-------------------- 3 files changed, 22 insertions(+), 30 deletions(-) diff --git a/contrib/net/http/trace_test.go b/contrib/net/http/trace_test.go index f85a592861..0489f8c3ef 100644 --- a/contrib/net/http/trace_test.go +++ b/contrib/net/http/trace_test.go @@ -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) { diff --git a/ddtrace/tracer/span.go b/ddtrace/tracer/span.go index 6b7568ec48..c9d6bace83 100644 --- a/ddtrace/tracer/span.go +++ b/ddtrace/tracer/span.go @@ -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) diff --git a/ddtrace/tracer/span_test.go b/ddtrace/tracer/span_test.go index 4c9b4d1c59..581993cf81 100644 --- a/ddtrace/tracer/span_test.go +++ b/ddtrace/tracer/span_test.go @@ -810,27 +810,24 @@ func TestSpanLog(t *testing.T) { 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 // 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() @@ -842,27 +839,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")) @@ -878,7 +857,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")) @@ -890,6 +868,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) { From b08de4b1b97194736ad23b46c448c13e26a9d4b0 Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 15 Jan 2025 13:25:44 -0500 Subject: [PATCH 2/8] Update tests previously relying on 64bit tids --- ddtrace/tracer/log_test.go | 6 ++++-- ddtrace/tracer/span_test.go | 32 +++++++++++++++++++++----------- 2 files changed, 25 insertions(+), 13 deletions(-) diff --git a/ddtrace/tracer/log_test.go b/ddtrace/tracer/log_test.go index 268e0ad015..6319bbd6cb 100644 --- a/ddtrace/tracer/log_test.go +++ b/ddtrace/tracer/log_test.go @@ -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) { diff --git a/ddtrace/tracer/span_test.go b/ddtrace/tracer/span_test.go index 581993cf81..355ac35920 100644 --- a/ddtrace/tracer/span_test.go +++ b/ddtrace/tracer/span_test.go @@ -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) @@ -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)) }) @@ -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)) }) @@ -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)) }) @@ -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)) }) @@ -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)) }) @@ -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)) }) @@ -782,7 +789,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(`%%!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)) }) @@ -790,9 +798,10 @@ func TestSpanLog(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)) }) @@ -803,10 +812,11 @@ 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)) }) @@ -825,7 +835,7 @@ func TestSpanLog(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 + // 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") assert := assert.New(t) From 9851ac3437acf0f145bce88ee1406539262f75bc Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 22 Jan 2025 09:49:27 -0500 Subject: [PATCH 3/8] 128bit logging for logrus --- contrib/sirupsen/logrus/logrus.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/contrib/sirupsen/logrus/logrus.go b/contrib/sirupsen/logrus/logrus.go index d0e379d796..2d58deca5d 100644 --- a/contrib/sirupsen/logrus/logrus.go +++ b/contrib/sirupsen/logrus/logrus.go @@ -7,6 +7,7 @@ package logrus import ( + "gopkg.in/DataDog/dd-trace-go.v1/ddtrace" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer" "gopkg.in/DataDog/dd-trace-go.v1/internal/telemetry" @@ -35,7 +36,12 @@ func (d *DDContextLogHook) Fire(e *logrus.Entry) error { if !found { return nil } - e.Data[ext.LogKeyTraceID] = span.Context().TraceID() + spanCtx128, ok := span.Context().(ddtrace.SpanContextW3C) + if ok { + e.Data[ext.LogKeyTraceID] = spanCtx128.TraceID128() + } else { + e.Data[ext.LogKeyTraceID] = span.Context().TraceID() + } e.Data[ext.LogKeySpanID] = span.Context().SpanID() return nil } From 4baf3831c2710666de1ed34b31c08a0719d50629 Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 22 Jan 2025 12:30:07 -0500 Subject: [PATCH 4/8] Tie logrus 128bit logging to the env var seting --- contrib/sirupsen/logrus/logrus.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/contrib/sirupsen/logrus/logrus.go b/contrib/sirupsen/logrus/logrus.go index 2d58deca5d..39c216c113 100644 --- a/contrib/sirupsen/logrus/logrus.go +++ b/contrib/sirupsen/logrus/logrus.go @@ -10,6 +10,7 @@ import ( "gopkg.in/DataDog/dd-trace-go.v1/ddtrace" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer" + "gopkg.in/DataDog/dd-trace-go.v1/internal" "gopkg.in/DataDog/dd-trace-go.v1/internal/telemetry" "github.com/sirupsen/logrus" @@ -17,6 +18,8 @@ import ( const componentName = "sirupsen/logrus" +var log128bits = internal.BoolEnv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", true) + func init() { telemetry.LoadIntegration(componentName) tracer.MarkIntegrationImported("github.com/sirupsen/logrus") @@ -36,9 +39,8 @@ func (d *DDContextLogHook) Fire(e *logrus.Entry) error { if !found { return nil } - spanCtx128, ok := span.Context().(ddtrace.SpanContextW3C) - if ok { - e.Data[ext.LogKeyTraceID] = spanCtx128.TraceID128() + if ctxW3c, ok := span.Context().(ddtrace.SpanContextW3C); ok && log128bits { + e.Data[ext.LogKeyTraceID] = ctxW3c.TraceID128() } else { e.Data[ext.LogKeyTraceID] = span.Context().TraceID() } From 3ed7ac8cab6e1147324dda682248cef2bcabb505 Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 22 Jan 2025 12:43:37 -0500 Subject: [PATCH 5/8] log trace and span IDs as string in logrus --- contrib/sirupsen/logrus/logrus.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/contrib/sirupsen/logrus/logrus.go b/contrib/sirupsen/logrus/logrus.go index 39c216c113..9f8cc1d64a 100644 --- a/contrib/sirupsen/logrus/logrus.go +++ b/contrib/sirupsen/logrus/logrus.go @@ -7,6 +7,8 @@ package logrus import ( + "strconv" + "gopkg.in/DataDog/dd-trace-go.v1/ddtrace" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer" @@ -42,8 +44,8 @@ func (d *DDContextLogHook) Fire(e *logrus.Entry) error { if ctxW3c, ok := span.Context().(ddtrace.SpanContextW3C); ok && log128bits { e.Data[ext.LogKeyTraceID] = ctxW3c.TraceID128() } else { - e.Data[ext.LogKeyTraceID] = span.Context().TraceID() + e.Data[ext.LogKeyTraceID] = strconv.FormatUint(span.Context().TraceID(), 10) } - e.Data[ext.LogKeySpanID] = span.Context().SpanID() + e.Data[ext.LogKeySpanID] = strconv.FormatUint(span.Context().SpanID(), 10) return nil } From 564ae8cdc83e59697ad8ef38fa4d70e999b642bd Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 22 Jan 2025 14:02:49 -0500 Subject: [PATCH 6/8] in progess: changing logrus tests --- contrib/sirupsen/logrus/logrus_test.go | 28 +++++++++++++++++++++++--- 1 file changed, 25 insertions(+), 3 deletions(-) diff --git a/contrib/sirupsen/logrus/logrus_test.go b/contrib/sirupsen/logrus/logrus_test.go index be23324b4d..4d6d2d8cc0 100644 --- a/contrib/sirupsen/logrus/logrus_test.go +++ b/contrib/sirupsen/logrus/logrus_test.go @@ -7,15 +7,18 @@ package logrus import ( "context" + "strconv" "testing" + "gopkg.in/DataDog/dd-trace-go.v1/ddtrace" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer" "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" ) -func TestFire(t *testing.T) { +func TestFire128BitEnabled(t *testing.T) { + // By default, trace IDs are logged in 128bit format tracer.Start() defer tracer.Stop() _, sctx := tracer.StartSpanFromContext(context.Background(), "testSpan", tracer.WithSpanID(1234)) @@ -24,8 +27,27 @@ func TestFire(t *testing.T) { e := logrus.NewEntry(logrus.New()) e.Context = sctx err := hook.Fire(e) + assert.NoError(t, err) + + ctxW3c, ok := sctx.(ddtrace.SpanContextW3C) + assert.True(t, ok) + assert.Equal(t, strconv.FormatUint(ctxW3c.TraceID(), 10), e.Data["dd.trace_id"]) + assert.Equal(t, strconv.FormatUint(ctxW3c.SpanID(), 10), e.Data["dd.span_id"]) +} + +func TestFire128BitDisabled(t *testing.T) { + // By default, trace IDs are logged in 128bit format + t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "false") + tracer.Start() + defer tracer.Stop() + _, sctx := tracer.StartSpanFromContext(context.Background(), "testSpan", tracer.WithSpanID(1234)) + hook := &DDContextLogHook{} + e := logrus.NewEntry(logrus.New()) + e.Context = sctx + err := hook.Fire(e) assert.NoError(t, err) - assert.Equal(t, uint64(1234), e.Data["dd.trace_id"]) - assert.Equal(t, uint64(1234), e.Data["dd.span_id"]) + + assert.Equal(t, "1234", e.Data["dd.trace_id"]) + assert.Equal(t, "1234", e.Data["dd.span_id"]) } From 04335877732ee541d141930a947ad72ac56c81e0 Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 22 Jan 2025 17:53:08 -0500 Subject: [PATCH 7/8] fix logrus tests --- contrib/sirupsen/logrus/logrus.go | 4 ++++ contrib/sirupsen/logrus/logrus_test.go | 20 ++++++++++++++------ 2 files changed, 18 insertions(+), 6 deletions(-) diff --git a/contrib/sirupsen/logrus/logrus.go b/contrib/sirupsen/logrus/logrus.go index 9f8cc1d64a..5142fb641f 100644 --- a/contrib/sirupsen/logrus/logrus.go +++ b/contrib/sirupsen/logrus/logrus.go @@ -7,6 +7,7 @@ package logrus import ( + "fmt" "strconv" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace" @@ -37,13 +38,16 @@ func (d *DDContextLogHook) Levels() []logrus.Level { // Fire implements logrus.Hook interface, attaches trace and span details found in entry context func (d *DDContextLogHook) Fire(e *logrus.Entry) error { + fmt.Println("Is it enabled?", log128bits) span, found := tracer.SpanFromContext(e.Context) if !found { return nil } if ctxW3c, ok := span.Context().(ddtrace.SpanContextW3C); ok && log128bits { + fmt.Println("a true?") e.Data[ext.LogKeyTraceID] = ctxW3c.TraceID128() } else { + fmt.Println("false") e.Data[ext.LogKeyTraceID] = strconv.FormatUint(span.Context().TraceID(), 10) } e.Data[ext.LogKeySpanID] = strconv.FormatUint(span.Context().SpanID(), 10) diff --git a/contrib/sirupsen/logrus/logrus_test.go b/contrib/sirupsen/logrus/logrus_test.go index 4d6d2d8cc0..4b10eb7fff 100644 --- a/contrib/sirupsen/logrus/logrus_test.go +++ b/contrib/sirupsen/logrus/logrus_test.go @@ -12,6 +12,7 @@ import ( "gopkg.in/DataDog/dd-trace-go.v1/ddtrace" "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer" + "gopkg.in/DataDog/dd-trace-go.v1/internal" "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" @@ -21,7 +22,7 @@ func TestFire128BitEnabled(t *testing.T) { // By default, trace IDs are logged in 128bit format tracer.Start() defer tracer.Stop() - _, sctx := tracer.StartSpanFromContext(context.Background(), "testSpan", tracer.WithSpanID(1234)) + sp, sctx := tracer.StartSpanFromContext(context.Background(), "testSpan", tracer.WithSpanID(1234)) hook := &DDContextLogHook{} e := logrus.NewEntry(logrus.New()) @@ -29,17 +30,24 @@ func TestFire128BitEnabled(t *testing.T) { err := hook.Fire(e) assert.NoError(t, err) - ctxW3c, ok := sctx.(ddtrace.SpanContextW3C) + ctxW3c, ok := sp.Context().(ddtrace.SpanContextW3C) assert.True(t, ok) - assert.Equal(t, strconv.FormatUint(ctxW3c.TraceID(), 10), e.Data["dd.trace_id"]) - assert.Equal(t, strconv.FormatUint(ctxW3c.SpanID(), 10), e.Data["dd.span_id"]) + + assert.Equal(t, ctxW3c.TraceID128(), e.Data["dd.trace_id"]) + assert.Equal(t, strconv.FormatUint(sp.Context().SpanID(), 10), e.Data["dd.span_id"]) } func TestFire128BitDisabled(t *testing.T) { // By default, trace IDs are logged in 128bit format + t.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "false") + + // Re-initialize to account for race condition between setting env var in the test and reading it in the contrib + log128bits = internal.BoolEnv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", true) + tracer.Start() defer tracer.Stop() + id := 1234 _, sctx := tracer.StartSpanFromContext(context.Background(), "testSpan", tracer.WithSpanID(1234)) hook := &DDContextLogHook{} @@ -48,6 +56,6 @@ func TestFire128BitDisabled(t *testing.T) { err := hook.Fire(e) assert.NoError(t, err) - assert.Equal(t, "1234", e.Data["dd.trace_id"]) - assert.Equal(t, "1234", e.Data["dd.span_id"]) + assert.Equal(t, strconv.Itoa(id), e.Data["dd.trace_id"]) + assert.Equal(t, strconv.Itoa(id), e.Data["dd.span_id"]) } From 1d33656ec3222e1d33eb2c891cd70e8bbc005b9f Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Wed, 22 Jan 2025 17:54:29 -0500 Subject: [PATCH 8/8] reminder on slog package --- contrib/log/slog/slog_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/contrib/log/slog/slog_test.go b/contrib/log/slog/slog_test.go index 7546009b0f..f2c2158b6a 100644 --- a/contrib/log/slog/slog_test.go +++ b/contrib/log/slog/slog_test.go @@ -38,6 +38,7 @@ func assertLogEntry(t *testing.T, rawEntry, wantMsg, wantLevel string, span trac assert.Equal(t, wantLevel, entry["level"]) assert.NotEmpty(t, entry["time"]) + //TODO: Update tests to account for 128bit logging by default traceID := strconv.FormatUint(span.Context().TraceID(), 10) spanID := strconv.FormatUint(span.Context().SpanID(), 10) assert.Equal(t, traceID, entry[ext.LogKeyTraceID], "trace id not found")