From fab1639f079ecdac91a0155a6f8fa2724d221d17 Mon Sep 17 00:00:00 2001 From: Mikayla Toffler Date: Thu, 23 Jan 2025 16:41:27 -0500 Subject: [PATCH] enable 128bit logging by default --- contrib/log/slog/slog.go | 21 +++++++- contrib/log/slog/slog_test.go | 33 ++++++++++-- contrib/sirupsen/logrus/logrus.go | 23 ++++++++- contrib/sirupsen/logrus/logrus_test.go | 26 +++++++++- ddtrace/tracer/log_test.go | 4 +- ddtrace/tracer/span.go | 2 +- ddtrace/tracer/span_test.go | 69 +++++++++++--------------- 7 files changed, 126 insertions(+), 52 deletions(-) diff --git a/contrib/log/slog/slog.go b/contrib/log/slog/slog.go index c43b8d3454..55e461b091 100644 --- a/contrib/log/slog/slog.go +++ b/contrib/log/slog/slog.go @@ -10,6 +10,7 @@ import ( "context" "io" "log/slog" + "os" "strconv" "github.com/DataDog/dd-trace-go/v2/ddtrace/ext" @@ -17,6 +18,8 @@ import ( "github.com/DataDog/dd-trace-go/v2/instrumentation" ) +var cfg = newConfig() + func init() { _ = instrumentation.Load(instrumentation.PackageLogSlog) } @@ -28,6 +31,16 @@ type group struct { attrs []slog.Attr } +type config struct { + log128bits bool +} + +func newConfig() *config { + return &config{ + log128bits: os.Getenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED") != "false", + } +} + // NewJSONHandler is a convenience function that returns a *slog.JSONHandler logger enhanced with // tracing information. func NewJSONHandler(w io.Writer, opts *slog.HandlerOptions) slog.Handler { @@ -59,7 +72,13 @@ func (h *handler) Handle(ctx context.Context, rec slog.Record) error { // set them at the root level. span, ok := tracer.SpanFromContext(ctx) if ok && span.Context().TraceID() != tracer.TraceIDZero { - traceID := span.Context().TraceID() + var traceID string + if cfg.log128bits { + traceID = span.Context().TraceID() + } else { + traceID = strconv.FormatUint(span.Context().TraceIDLower(), 10) + } + spanID := strconv.FormatUint(span.Context().SpanID(), 10) attrs := []slog.Attr{ diff --git a/contrib/log/slog/slog_test.go b/contrib/log/slog/slog_test.go index 269a3d2310..a1cc95831a 100644 --- a/contrib/log/slog/slog_test.go +++ b/contrib/log/slog/slog_test.go @@ -11,6 +11,7 @@ import ( "encoding/json" "io" "log/slog" + "os" "strconv" "strings" "testing" @@ -24,7 +25,7 @@ import ( "github.com/DataDog/dd-trace-go/v2/instrumentation/testutils" ) -func assertLogEntry(t *testing.T, rawEntry, wantMsg, wantLevel string, span *tracer.Span, assertExtra func(t *testing.T, entry map[string]interface{})) { +func assertLogEntry(t *testing.T, rawEntry, wantMsg, wantLevel string, traceID string, spanID string, assertExtra func(t *testing.T, entry map[string]interface{})) { t.Helper() t.Log(rawEntry) @@ -38,8 +39,6 @@ func assertLogEntry(t *testing.T, rawEntry, wantMsg, wantLevel string, span *tra assert.Equal(t, wantLevel, entry["level"]) assert.NotEmpty(t, entry["time"]) - traceID := span.Context().TraceID() - spanID := strconv.FormatUint(span.Context().SpanID(), 10) assert.Equal(t, traceID, entry[ext.LogKeyTraceID], "trace id not found") assert.Equal(t, spanID, entry[ext.LogKeySpanID], "span id not found") @@ -81,6 +80,16 @@ func testLogger(t *testing.T, createLogger func(b io.Writer) *slog.Logger, asser span, ctx := tracer.StartSpanFromContext(context.Background(), "test") defer span.Finish() + var traceID string + spanID := strconv.FormatUint(span.Context().SpanID(), 10) + if os.Getenv("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 + cfg = newConfig() + traceID = strconv.FormatUint(span.Context().TraceIDLower(), 10) + } else { + traceID = span.Context().TraceID() + } + // log a message using the context containing span information logger.Log(ctx, slog.LevelInfo, "this is an info log with tracing information") logger.Log(ctx, slog.LevelError, "this is an error log with tracing information") @@ -91,8 +100,8 @@ func testLogger(t *testing.T, createLogger func(b io.Writer) *slog.Logger, asser ) // assert log entries contain trace information require.Len(t, logs, 2) - assertLogEntry(t, logs[0], "this is an info log with tracing information", "INFO", span, assertExtra) - assertLogEntry(t, logs[1], "this is an error log with tracing information", "ERROR", span, assertExtra) + assertLogEntry(t, logs[0], "this is an info log with tracing information", "INFO", traceID, spanID, assertExtra) + assertLogEntry(t, logs[1], "this is an error log with tracing information", "ERROR", traceID, spanID, assertExtra) } func testLoggerNoTrace(t *testing.T, createLogger func(b io.Writer) *slog.Logger) { @@ -252,6 +261,20 @@ func TestRecordClone(t *testing.T) { assert.True(t, foundSentinel) } +func Test128BitLoggingDisabled(t *testing.T) { + os.Setenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED", "false") + defer os.Unsetenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED") + t.Run("testLogger", func(t *testing.T) { + testLogger( + t, + func(w io.Writer) *slog.Logger { + return slog.New(WrapHandler(slog.NewJSONHandler(w, nil))) + }, + nil, + ) + }) +} + func BenchmarkHandler(b *testing.B) { span, ctx := tracer.StartSpanFromContext(context.Background(), "test") defer span.Finish() diff --git a/contrib/sirupsen/logrus/logrus.go b/contrib/sirupsen/logrus/logrus.go index a110573678..c6aba412e0 100644 --- a/contrib/sirupsen/logrus/logrus.go +++ b/contrib/sirupsen/logrus/logrus.go @@ -7,6 +7,9 @@ package logrus import ( + "os" + "strconv" + "github.com/DataDog/dd-trace-go/v2/ddtrace/ext" "github.com/DataDog/dd-trace-go/v2/ddtrace/tracer" "github.com/DataDog/dd-trace-go/v2/instrumentation" @@ -23,6 +26,18 @@ func init() { // DDContextLogHook ensures that any span in the log context is correlated to log output. type DDContextLogHook struct{} +type config struct { + log128bits bool +} + +var cfg = newConfig() + +func newConfig() *config { + return &config{ + log128bits: os.Getenv("DD_TRACE_128_BIT_TRACEID_LOGGING_ENABLED") != "false", + } +} + // Levels implements logrus.Hook interface, this hook applies to all defined levels func (d *DDContextLogHook) Levels() []logrus.Level { return []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel, logrus.InfoLevel, logrus.DebugLevel, logrus.TraceLevel} @@ -34,7 +49,11 @@ func (d *DDContextLogHook) Fire(e *logrus.Entry) error { if !found { return nil } - e.Data[ext.LogKeyTraceID] = span.Context().TraceID() - e.Data[ext.LogKeySpanID] = span.Context().SpanID() + if cfg.log128bits && span.Context().TraceID() != tracer.TraceIDZero { + e.Data[ext.LogKeyTraceID] = span.Context().TraceID() + } else { + e.Data[ext.LogKeyTraceID] = strconv.FormatUint(span.Context().TraceIDLower(), 10) + } + e.Data[ext.LogKeySpanID] = strconv.FormatUint(span.Context().SpanID(), 10) return nil } diff --git a/contrib/sirupsen/logrus/logrus_test.go b/contrib/sirupsen/logrus/logrus_test.go index 33adc903cb..d20602abb8 100644 --- a/contrib/sirupsen/logrus/logrus_test.go +++ b/contrib/sirupsen/logrus/logrus_test.go @@ -7,6 +7,7 @@ package logrus import ( "context" + "strconv" "testing" "github.com/DataDog/dd-trace-go/v2/ddtrace/tracer" @@ -24,8 +25,29 @@ func TestFire(t *testing.T) { e := logrus.NewEntry(logrus.New()) e.Context = sctx err := hook.Fire(e) - assert.NoError(t, err) + + // By default, trace IDs are logged in 128bit format assert.Equal(t, sp.Context().TraceID(), e.Data["dd.trace_id"]) - assert.Equal(t, sp.Context().SpanID(), e.Data["dd.span_id"]) + assert.Equal(t, strconv.FormatUint(sp.Context().SpanID(), 10), e.Data["dd.span_id"]) +} + +func TestFire128BitDisabled(t *testing.T) { + 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 + cfg = newConfig() + + tracer.Start() + defer tracer.Stop() + sp, 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, strconv.FormatUint(sp.Context().TraceIDLower(), 10), e.Data["dd.trace_id"]) + assert.Equal(t, strconv.FormatUint(sp.Context().SpanID(), 10), e.Data["dd.span_id"]) } diff --git a/ddtrace/tracer/log_test.go b/ddtrace/tracer/log_test.go index 87016e08e3..78bc4b1e47 100644 --- a/ddtrace/tracer/log_test.go +++ b/ddtrace/tracer/log_test.go @@ -187,9 +187,9 @@ func TestLogFormat(t *testing.T) { defer stop() tp.Reset() tp.Ignore("appsec: ", telemetry.LogPrefix) - tracer.StartSpan("test", ServiceName("test-service"), ResourceName("/"), WithSpanID(12345)) + span := tracer.StartSpan("test", ServiceName("test-service"), ResourceName("/"), WithSpanID(12345)) 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="`+span.Context().TraceID()+`" 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.go b/ddtrace/tracer/span.go index d0e0c1d6ed..38784c045d 100644 --- a/ddtrace/tracer/span.go +++ b/ddtrace/tracer/span.go @@ -791,7 +791,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.TraceID() } else { traceID = fmt.Sprintf("%d", s.traceID) diff --git a/ddtrace/tracer/span_test.go b/ddtrace/tracer/span_test.go index 595334abb8..8bffcc6021 100644 --- a/ddtrace/tracer/span_test.go +++ b/ddtrace/tracer/span_test.go @@ -823,7 +823,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - 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"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) } t.Run("noservice_first", noServiceTest) @@ -834,7 +834,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - expect := fmt.Sprintf(`dd.service=tracer.test dd.trace_id="%d" dd.span_id="%d" dd.parent_id="0"`, span.traceID, span.spanID) + expect := fmt.Sprintf(`dd.service=tracer.test dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -844,7 +844,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - 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) + expect := fmt.Sprintf(`dd.service=tracer.test dd.env=testenv dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -854,7 +854,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - 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) + expect := fmt.Sprintf(`dd.service=tracer.test dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -864,7 +864,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - 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) + 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"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -877,7 +877,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request", ServiceName("subservice name")) - 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) + 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"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -890,7 +890,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - 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) + 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"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -900,7 +900,7 @@ func TestSpanLog(t *testing.T) { assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - expect := fmt.Sprintf(`%%!b(tracer.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) + expect := fmt.Sprintf(`%%!b(tracer.Span=dd.service=tracer.test dd.version=1.2.3 dd.trace_id="%s" dd.span_id="%d" dd.parent_id="0")`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%b", span)) }) @@ -911,7 +911,7 @@ func TestSpanLog(t *testing.T) { span := tracer.StartSpan("test.request") 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"`, span.context.TraceID(), span.spanID) assert.Equal(expect, fmt.Sprintf("%v", span)) }) @@ -926,32 +926,27 @@ func TestSpanLog(t *testing.T) { 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"`, span.context.TraceID(), 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, err := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv")) assert.Nil(err) defer stop() span := tracer.StartSpan("test.request") - 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.TraceID()) assert.Equal(expect, fmt.Sprintf("%v", span)) }) 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 128bit 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, err := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv")) assert.Nil(err) @@ -964,28 +959,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, err := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv")) - assert.Nil(err) - defer stop() - span := tracer.StartSpan("test.request") - 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.TraceID()) - assert.Equal(expect, fmt.Sprintf("%v", span)) - v, _ := span.context.meta(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, err := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv")) @@ -1002,7 +978,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, err := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv")) @@ -1015,6 +990,22 @@ func TestSpanLog(t *testing.T) { v, _ := span.context.meta(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, err := startTestTracer(t, WithService("tracer.test"), WithEnv("testenv")) + defer stop() + assert.Nil(err) + span := tracer.StartSpan("test.request") + 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) {