Traces, Spans and Context

A trace is one request's journey, a span is one step in it, and context.Context is how each span finds its parent.

Syntaxctx, span := tracer.Start(ctx, "operation name"); defer span.End()

A trace is the record of one request's whole journey through your systems. A span is one step inside that journey: a unit of work with a name, a start time and an end time. One request that reaches an HTTP handler, runs a database query and calls another service is one trace made of several spans. Tracing exists because a log line tells you what happened in one place. A trace tells you where the time went across all of them.

How spans nest

Every span carries a trace ID, which is the same for every span in the trace, and its own span ID. A span also records the span ID of its parent, meaning the step it happened inside. The first span, the one with no parent, is the root span. Those values together are called the span context.

In Go the span context travels inside a context.Context. tracer.Start takes a context and returns a new one with the new span in it. Pass that returned context down, and the next call to Start finds the span and nests under it. The tree is built by passing contexts, nothing more.

What trips people up

A span that never ends is never exported, so write defer span.End() on the line after Start. Create spans for work that deserves a row in a timeline, not for every function. A span also records failure only if you say so: span.RecordError(err) stores the message, and span.SetStatus(codes.Error, "...") is what marks the span as failed.

Example

Example · go
package main

import (
	"context"
	"fmt"

	"go.opentelemetry.io/otel"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
)

// printer is a span exporter: the SDK hands it spans that have ended.
type printer struct{}

func (printer) ExportSpans(ctx context.Context, spans []sdktrace.ReadOnlySpan) error {
	for _, s := range spans {
		// Parent() is the span context of the step this span ran inside.
		fmt.Printf("%q parent: %v\n", s.Name(), s.Parent().IsValid())
	}
	return nil
}

func (printer) Shutdown(ctx context.Context) error { return nil }

func main() {
	// WithSyncer exports each span the moment it ends. Batch in production.
	tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(printer{}))
	otel.SetTracerProvider(tp)
	tracer := otel.Tracer("shop")

	ctx, order := tracer.Start(context.Background(), "place order")
	// The context Start returned holds the span, so the next span nests.
	_, charge := tracer.Start(ctx, "charge card")
	charge.End()
	order.End()
}

// Output:
// "charge card" parent: true
// "place order" parent: false

When to use it

  • Find which of five services made a checkout request take four seconds.
  • Attach an order ID to a span so you can search for one customer's failed request.
  • Put the trace ID in every log line so a log search leads straight to the trace.
  • See how many database queries one HTTP handler actually makes.

More examples

Attributes, errors and status on a span

A span with a name and a duration tells you something was slow. Attributes tell you which order it was. Reach for this whenever you would otherwise add an identifier to a log line: put it on the span instead, and the trace becomes searchable by order ID. The codes package is go.opentelemetry.io/otel/codes and attribute is go.opentelemetry.io/otel/attribute.

Example · go
// charge runs inside a request, so it receives the request's context.
func (s *Store) charge(ctx context.Context, orderID string, cents int) error {
	ctx, span := otel.Tracer("shop").Start(ctx, "charge card")
	defer span.End()

	// Attributes are searchable key/value pairs on this one span.
	span.SetAttributes(
		attribute.String("order.id", orderID),
		attribute.Int("charge.cents", cents),
	)

	if err := s.gateway.Charge(ctx, orderID, cents); err != nil {
		// RecordError stores the message as an event on the span.
		span.RecordError(err)
		// SetStatus is what actually marks the span as failed.
		span.SetStatus(codes.Error, "charge failed")
		return err
	}
	return nil
}

Putting the trace ID in every log line

Logs and traces answer different questions, and this line joins them. SpanContextFromContext reads the current span context out of the request context without creating anything. Use it in request logging so that an error log gives you a trace ID you can paste into the trace UI.

Example · go
// requestLogger logs one line per request with the trace ID attached, so a
// log search can jump straight to the matching trace.
func requestLogger(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		next.ServeHTTP(w, r)

		sc := trace.SpanContextFromContext(r.Context())
		if !sc.IsValid() {
			// No span in the context: the tracing middleware did not run.
			slog.Info("request", "path", r.URL.Path)
			return
		}
		slog.Info("request",
			"path", r.URL.Path,
			"trace_id", sc.TraceID().String(),
			"span_id", sc.SpanID().String(),
		)
	})
}

The context plumbing, shorthand and longhand

The first two functions are identical in behaviour; the shorthand is idiomatic and the longhand shows why it works. The third is the mistake that produces most broken traces, and no compiler or test will catch it. Read the third function whenever a trace in your UI looks like two unrelated halves.

Example · go
// Shorthand, and what you will see in most code: reuse the name ctx. The new
// context shadows the old one for the rest of the function.
func withShorthand(ctx context.Context, tracer trace.Tracer) {
	ctx, span := tracer.Start(ctx, "step")
	defer span.End()
	doWork(ctx)
}

// Longhand. Exactly the same thing with the two contexts kept apart.
func withLonghand(ctx context.Context, tracer trace.Tracer) {
	spanCtx, span := tracer.Start(ctx, "step")
	defer span.End()
	doWork(spanCtx)
}

// Broken, and it compiles. doWork gets the context from before the span, so
// any span it starts is a second root and the trace splits in two.
func broken(ctx context.Context, tracer trace.Tracer) {
	_, span := tracer.Start(ctx, "step")
	defer span.End()
	doWork(ctx)
}

Related

go context basicsgo sloggo otel setupgo trace propagationgo request logging

Discussion

  • Be the first to comment on this lesson.