Skip to content

Commit

Permalink
enable 128bit logging by default
Browse files Browse the repository at this point in the history
  • Loading branch information
mtoffl01 committed Jan 23, 2025
1 parent 7d516f3 commit fab1639
Show file tree
Hide file tree
Showing 7 changed files with 126 additions and 52 deletions.
21 changes: 20 additions & 1 deletion contrib/log/slog/slog.go
Original file line number Diff line number Diff line change
Expand Up @@ -10,13 +10,16 @@ import (
"context"
"io"
"log/slog"
"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"
)

var cfg = newConfig()

func init() {
_ = instrumentation.Load(instrumentation.PackageLogSlog)
}
Expand All @@ -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 {
Expand Down Expand Up @@ -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{
Expand Down
33 changes: 28 additions & 5 deletions contrib/log/slog/slog_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import (
"encoding/json"
"io"
"log/slog"
"os"
"strconv"
"strings"
"testing"
Expand All @@ -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)
Expand All @@ -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")

Expand Down Expand Up @@ -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")
Expand All @@ -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) {
Expand Down Expand Up @@ -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()
Expand Down
23 changes: 21 additions & 2 deletions contrib/sirupsen/logrus/logrus.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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}
Expand All @@ -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
}
26 changes: 24 additions & 2 deletions contrib/sirupsen/logrus/logrus_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ package logrus

import (
"context"
"strconv"
"testing"

"github.com/DataDog/dd-trace-go/v2/ddtrace/tracer"
Expand All @@ -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"])
}
4 changes: 2 additions & 2 deletions ddtrace/tracer/log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
2 changes: 1 addition & 1 deletion ddtrace/tracer/span.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
Loading

0 comments on commit fab1639

Please sign in to comment.