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

The scripts are not supported under any SolarWinds support program or service. The scripts are provided AS IS without warranty of any kind. SolarWinds further disclaims all warranties including, without limitation, any implied warranties of merchantability or of fitness for a particular purpose. The risk arising out of the use or performance of the scripts and documentation stays with you. In no event shall SolarWinds or anyone else involved in the creation, production, or delivery of the scripts be liable for any damages whatsoever (including, without limitation, damages for loss of business profits, business interruption, loss of business information, or other pecuniary loss) arising out of the use of or inability to use the scripts or documentation.