Trace Context in Logs

Adding trace context to application logs provides the ability to correlate the log messages from a traced transaction, and if sampled, the log messages to the transaction trace detail.

The AppOptics Go agent supports manual log context injection. The loggable trace ID can be accessed via the method LoggableTraceID() of a trace. Below is a demo application showing how the loggable trace ID is used for logging purpose.

package main

import (
    "fmt"
    "github.com/appoptics/appoptics-apm-go/v1/ao"
    "log"
    "net/http"
    "strconv"
)

const (
    Port = 8090
)

func demoHandler(w http.ResponseWriter, r *http.Request) {
    t := ao.TraceFromContext(r.Context())
    log.Print(fmt.Sprintf("%s=%s\n", ao.LoggableTraceID, t.LoggableTraceID()))
    _, _ = fmt.Fprintf(w, "demo\n")
}

func main() {
    http.HandleFunc("/demo", ao.HTTPHandler(demoHandler))
    fmt.Printf("%v", http.ListenAndServe(":"+strconv.Itoa(Port), nil))
}

It prints the key and value of the loggable trace ID, for example, ao.traceId=91A2FC1F4FDE5F2FFFF177E7C884BF06E44678C3-1, if a client request accesses the endpoint /demo.

Note that,

  • ao.traceId: the recommended key, defined by ao.LoggableTraceID.
  • 91A2FC1F4FDE5F2FFFF177E7C884BF06E44678C3: the trace ID.
  • 1 (after the dash): the sampling flag, which could be either 0 (not sampled) or 1 (sampled).

The method LoggableTraceID() returns an empty string if there is no valid context for the trace, e.g., when the agent is disabled.

Zap

The loggable trace ID can be logged as a structured field in Zap:

var (
    logger *zap.Logger
    sugar  *zap.SugaredLogger
)

func init() {
    logger, _ = zap.NewProduction() // ignore error handling here for demo only
    sugar = logger.Sugar()
}

func demoHandler(w http.ResponseWriter, r *http.Request) {
    t := ao.TraceFromContext(r.Context())

    // Logger
    logger.Info("Failed to fetch URL.",
        zap.String(ao.LoggableTraceID, t.LoggableTraceID()),
    )

    // Sugared logger
    sugar.Infow("This is a demo log.",
        ao.LoggableTraceID, t.LoggableTraceID())

    _, _ = fmt.Fprintf(w, "demo\n")
}

An example output of it:

{"level":"info","ts":1557337865.186354,"caller":"go/test.go:29","msg":"Failed to fetch URL.","ao.traceId":"79CBEF7730D5E220FAFDEBEBD48EF5A38675031C-1"}
{"level":"info","ts":1557337865.1864462,"caller":"go/test.go:34","msg":"This is a demo log.","ao.traceId":"79CBEF7730D5E220FAFDEBEBD48EF5A38675031C-1"}

Logrus

Logrus also supports structured fields which is a good fit for the loggable trace ID:

func demoHandler(w http.ResponseWriter, r *http.Request) {
    t := ao.TraceFromContext(r.Context())

    log.WithFields(log.Fields{
        ao.LoggableTraceID: t.LoggableTraceID(),
    }).Info("This is a demo log.")

    _, _ = fmt.Fprintf(w, "demo\n")
}

An example output of it:

INFO[0005] This is a demo log.                           ao.traceId=1BDEE50BD073C5A543919E3DC2F2C924ACCA7527-1