Log correlation with Datadog and slog in Go

Injecting Trace IDs into your Logging

It’s been a while since I posted anything, but this took more time to get working than I care to admit. So, I thought I’d make a few notes about it, firstly for future reference, but also in case it’s useful to anyone else.

Essentially though, this post outlines how to add a trace ID to your logs in order to correlate them with your traces. Specifically in this case we’re using Datadog and the new structured logging package (slog) from the Go standard library.

If you’re reading this, then you probably already know why you’d want to do this, but just in case, here is an overview from Datadog which suggests that it requires zero developer time – apparently! 🙄

Structured Logging

In order to correlate our logs with our traces, we must first ensure our logs are sent to Datadog as JSON. Fortunately for us we now use the structured logging package that is included with Go 1.21 and already send our logs as json using the JSONHandler. There are already plenty of tutorials for slog so I won’t cover that too much here.

The Datadog documentation on this subject however is quite short and does not specifically cover how we’d use slog for this purpose. Instead they reference standard log statements and suggest using the %v format specifier.

This alone is quite interesting and could definitely send you down a rabbit hole trying to work how using that specifier results in the relevant data being logged. Suffice to say, I got lost for a while looking at MessagePack and the msgp package, but I still have some digging to do on that.

In addition, if you’re using some other logging library, such as logrus, there may be an alternative solution.

Obtaining the Trace ID

On the surface, this looks to be a simple problem to solve. When we perform a log statement, if we have a trace ID, we can simply log that alongside our other log attributes with slog.Uint64("trace_id",trace_id) right?

Well, the trace ID is in the span.Context(), so that becomes:

  • slog.Uint64("trace_id",span.Context().TraceID()).

If we’re doing this properly, the trace ID should really be included in the dd group, so this then becomes:

  • slog.Group("dd", slog.Uint64("trace_id", span.Context().TraceID())).

Clearly we really don’t want to be typing that for all our log statements!

Admittedly, we could get it once at the top of each function and shorten that, but it still doesn’t feel quite right and really increases the overhead for the developer.

Context

The right solution must surely be related to context since we’re injecting spans into the context and passing the context through our code all over the place. Slog even has context based logging methods such as slog.InfoContext(ctx, "message").

The slog documentation talks about this and specifically references this problem:

Some handlers may wish to include information from the context.Context that is available at the call site. One example of such information is the identifier for the current span when tracing is enabled.

Some handlers? OK, just not the standard JSONHandler we’re using. It turns out that some people have already tried to address this issue with their own slog handlers, but like most people, we’re keen to avoid third party packages where possible.

Does that mean we need to write our own handler? Not exactly…

Embedding Structs

In Go, it is possible to embed one struct in another which then “promotes” the original structs fields and methods as if they belonged to your new struct. If this is new to you, Eli Bendersky has some great articles on it.1

So, this means we should be able to embed an existing slog.Handler and just override the Handle method to inject our own attributes before passing to the real handler to do any remaining work – winner, we haven’t had to write our own handler!

type ContextHandler struct {
	slog.Handler
}
func (h ContextHandler) Handle(ctx context.Context, r slog.Record) error {
	r.AddAttrs(h.addTraceFromContext(ctx)...)
	return h.Handler.Handle(ctx, r)
}

func initialiseLogging() *slog.Logger {
    jsonHandler := slog.NewJSONHandler(os.Stdout, nil)
	ctxHandler := ContextHandler{jsonHandler}
    logger := slog.New(ctxHandler)
    slog.SetDefault(logger)
    return logger
}

On our first attempt, this worked perfectly for our trace id.

However, when we added our other Datadog variables as an slog.Group it no longer worked:

	ddvars := slog.Group("dd",
		slog.String("env", cfg.env),
		slog.String("service", cfg.serviceName),
		slog.String("version", cfg.version),
		slog.String("source", "go"),
	)
    logger = slog.New(ctxHandler).With(ddvars)

Additional Required Methods

It turns out that when you use With(), slog returns a new handler. This is performed by the WithAttrs method. From the slog handler guide:

WithAttrs must return a new handler with the additional attributes, leaving the original handler (its receiver) unchanged

This means that when With() was being called we were getting back a new JSONHandler, not a ContextHandler which doesn’t implement our new Handle method. 😭

This is also the same for the WithGroup method. So we just need to do the same here as we did with our Handle method, ensuring we return a new ContextHander having called the original JSONHandler version:

func (h ContextHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return ContextHandler{h.Handler.WithAttrs(attrs)}
}
func (h ContextHandler) WithGroup(name string) slog.Handler {
	return ContextHandler{h.Handler.WithGroup(name)}
}

Adding the Trace ID from Context

All that’s left is for us to implement the addTraceFromContext method on our ContextHandler.

Again I spent more time on this than was necessary, trying to identify the context key that was being used using reflection.

The Datadog tracer uses a private field called activeSpanKey for the key so it’s not possible to get the value using ctx.Value.

Fortunately though, they do provide a method called SpanFromContext which does provide what we need:

func (h ContextHandler) addTraceFromContext(ctx context.Context) (as []slog.Attr) {
	span, ok := tracer.SpanFromContext(ctx)
	if ok {
		traceID := span.Context().TraceID()
		ddgroup := slog.Group("dd", slog.Uint64("trace_id", traceID))
		as = append(as, ddgroup)
	}
	return
}

And that’s pretty much it. So far it seems to be working just fine.

TL;DR - Show Me The Code

This is the full code to get it working in the end, with initialiseLogging called from our main function:

type ContextHandler struct {
	slog.Handler
}

func (h ContextHandler) Handle(ctx context.Context, r slog.Record) error {
	r.AddAttrs(h.observe(ctx)...)
	return h.Handler.Handle(ctx, r)
}

func (h ContextHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return ContextHandler{h.Handler.WithAttrs(attrs)}
}

func (h ContextHandler) WithGroup(name string) slog.Handler {
	return ContextHandler{h.Handler.WithGroup(name)}
}

func (h ContextHandler) addTraceFromContext(ctx context.Context) (as []slog.Attr) {
	span, ok := tracer.SpanFromContext(ctx)
	if ok {
		traceID := span.Context().TraceID()
		ddgroup := slog.Group("dd", slog.Uint64("trace_id", traceID))
		as = append(as, ddgroup)
	}
	return
}

func initialiseLogging(cfg config) *slog.Logger {
	jsonHandler := slog.NewJSONHandler(os.Stdout, nil)
	ctxHandler := ContextHandler{jsonHandler}

	ddvars := slog.Group("dd",
		slog.String("env", cfg.env),
		slog.String("service", cfg.serviceName),
		slog.String("version", cfg.version),
		slog.String("source", "go"),
	)

	logger := slog.New(ctxHandler).With(ddvars)
	slog.SetDefault(logger)
	return logger
}

References

  1. Pretty much anything he writes is Gold! ↩︎

golang  datadog  telemetry 
comments powered by Disqus