# Observability > Emit structured logs with slog, expose RED metrics for Prometheus, and trace requests with OpenTelemetry, all correlated by trace ID. Backend with Go roadmap · Production · 18 min read · https://levelcode.org/roadmaps/go-backend/observability When a service misbehaves in production, you can't attach a debugger. All you have is what the service tells you about itself. **Observability** is building services that answer questions you didn't think of in advance: why is checkout slow for some users, which dependency is failing, what happened to request `ab12…`. This lesson covers the three signals that answer those questions (logs, metrics and traces) and how to produce each idiomatically in Go. ## Three signals, three questions | Signal | Answers | Cost profile | Go tooling | |---|---|---|---| | **Logs** | What exactly happened in *this* request? | Grows with traffic | `log/slog` | | **Metrics** | How is the system behaving *overall*? Is it getting worse? | Fixed: numbers aggregated over time | Prometheus client | | **Traces** | Where did the time go across services for one request? | Usually sampled | OpenTelemetry | They complement each other. A metric alert tells you the error rate jumped. A trace shows that the slow part is the call to the payment provider. Logs for that trace show the provider's exact error message. The glue is a shared **trace ID** that appears in all three, so you can jump from one to the next. ## Structured logging with slog A log line like `user 42 failed to pay order 981: card declined` is easy to read and hard to query. **Structured logs** record the same event as key-value pairs that a log system can filter and aggregate: every failed payment for order 981, or every `WARN` from the billing component in the last hour. Go's standard `log/slog` package does this. Use the JSON handler in production and set it as the default so every package's logs share one format: ```go func newLogger(level *slog.LevelVar) *slog.Logger { h := slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: level}) return slog.New(contextHandler{h}) // contextHandler is defined below } func main() { var level slog.LevelVar // zero value is Info; level.Set(slog.LevelDebug) at runtime slog.SetDefault(newLogger(&level)) slog.Info("starting", "port", 8080) slog.Info("grouped", slog.Group("user", slog.Int64("id", 7), slog.String("role", "admin"))) billing := slog.Default().With("component", "billing") billing.Warn("payment failed", "order_id", 981, "err", errors.New("card declined")) } ``` ```text {"time":"2026-10-11T08:23:14.167482913Z","level":"INFO","msg":"starting","port":8080} {"time":"2026-10-11T08:23:14.167527104Z","level":"INFO","msg":"grouped","user":{"id":7,"role":"admin"}} {"time":"2026-10-11T08:23:14.167531390Z","level":"WARN","msg":"payment failed","component":"billing","order_id":981,"err":"card declined"} ``` A few conventions keep logs useful: - **The message is a constant**; variable data goes in attributes. `"payment failed"` plus `order_id=981` can be grouped and counted; `"payment failed for 981"` can't. - **`logger.With(...)`** returns a child logger that adds attributes to every record, which suits per-component or per-request context. - **Levels mean something.** `DEBUG` for detail you enable while investigating; `INFO` for normal significant events; `WARN` for something unexpected that was handled; `ERROR` for a failure someone may need to act on. A `slog.LevelVar` lets you change the level at runtime, for example from an admin endpoint. - **Log an error once**, where it's handled. If every layer logs and returns the same error, one failure produces five log lines. Lower layers wrap and return; the top layer logs. > [!WARNING] > Never log passwords, tokens, full card numbers or session cookies, and be careful with personal data. Give sensitive types a `LogValue` method so they redact themselves wherever they're logged: `func (Secret) LogValue() slog.Value { return slog.StringValue("[REDACTED]") }`. ### Adding request context automatically The request-logging middleware from the routing lesson logs one line per request. But logs written *inside* handlers also need to identify their request. Rather than passing IDs around by hand, wrap the handler so that every `slog.InfoContext(ctx, ...)` call picks up the trace and span IDs from the context: ```go type contextHandler struct{ slog.Handler } func (h contextHandler) Handle(ctx context.Context, r slog.Record) error { if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { r.AddAttrs( slog.String("trace_id", sc.TraceID().String()), slog.String("span_id", sc.SpanID().String()), ) } return h.Handler.Handle(ctx, r) } // Without these two methods, logger.With(...) would return the inner // handler and silently drop the wrapper. 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)} } ``` This only works if you use the `Context` variants (`InfoContext`, `WarnContext`, ...) and pass the request's context down. That's one more reason to thread `ctx` through every call. ## Metrics with Prometheus Metrics are numbers sampled over time. Prometheus, the most common open-source metrics system, **scrapes** an HTTP endpoint on your service (usually `/metrics`) every 15–30 seconds and stores the values as time series. Three metric types cover almost everything: - **Counter**: only goes up (requests served, errors). You query its *rate*. - **Gauge**: goes up and down (in-flight requests, pool connections in use). - **Histogram**: counts observations into buckets (request durations), so you can compute percentiles. For an HTTP service, start with the **RED** method: **R**ate of requests, **E**rrors, and **D**uration, per route: ```go var ( httpRequests = promauto.NewCounterVec(prometheus.CounterOpts{ Name: "http_requests_total", Help: "HTTP requests by route, method and status code.", }, []string{"route", "method", "code"}) httpDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{ Name: "http_request_duration_seconds", Help: "HTTP request latency by route.", Buckets: prometheus.DefBuckets, }, []string{"route", "method"}) ) func metrics(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() rec := &statusRecorder{ResponseWriter: w, status: http.StatusOK} // from the routing lesson next.ServeHTTP(rec, r) route := r.Pattern // e.g. "POST /v1/orders/{id}/pay", set by ServeMux while routing if route == "" { route = "unmatched" } httpRequests.WithLabelValues(route, r.Method, strconv.Itoa(rec.status)).Inc() httpDuration.WithLabelValues(route, r.Method).Observe(time.Since(start).Seconds()) }) } ``` Register `mux.Handle("GET /metrics", promhttp.Handler())` and the endpoint serves these alongside built-in Go runtime metrics such as `go_goroutines`: ```text http_requests_total{code="204",method="POST",route="POST /v1/orders/{id}/pay"} 1 http_requests_total{code="402",method="POST",route="POST /v1/orders/{id}/pay"} 1 http_request_duration_seconds_count{method="POST",route="POST /v1/orders/{id}/pay"} 2 ``` Dashboards and alerts are then queries in PromQL: ```text # requests per second, per route, over the last 5 minutes sum by (route) (rate(http_requests_total[5m])) # 95th-percentile latency per route histogram_quantile(0.95, sum by (le, route) (rate(http_request_duration_seconds_bucket[5m]))) ``` > [!IMPORTANT] > Every distinct combination of label values is a separate time series. Labelling by `r.URL.Path` (`/v1/orders/1`, `/v1/orders/2`, ...) or by user ID creates millions of series and can take down your metrics system. Use the route *pattern*, as above, and keep labels to small, bounded sets. ## Tracing with OpenTelemetry A **trace** follows one request through every service and component it touches. It is a tree of **spans**: each span has a name, a start and end time, attributes and a status, and a parent. Your HTTP handler's span might have children for a database query and a call to the payment service, which in turn has its own children in *its* process. Traces cross process boundaries through **context propagation**. When your service calls another, it sends a W3C `traceparent` header carrying the trace ID and the current span ID; the receiving service continues the same trace. OpenTelemetry (OTel) is the vendor-neutral standard for producing traces, and its Go SDK exports them over OTLP to a collector or a backend such as Jaeger or Grafana Tempo. Set up a tracer provider once at startup: ```go func setupTracing(ctx context.Context, exp sdktrace.SpanExporter) (func(context.Context) error, error) { res, err := resource.Merge(resource.Default(), resource.NewSchemaless(attribute.String("service.name", "orders-api"))) if err != nil { return nil, err } tp := sdktrace.NewTracerProvider( sdktrace.WithBatcher(exp), sdktrace.WithResource(res), // Keep 10% of new traces, but always follow the caller's decision. sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(0.1))), ) otel.SetTracerProvider(tp) otel.SetTextMapPropagator(propagation.TraceContext{}) return tp.Shutdown, nil // call on exit to flush buffered spans } ``` In production, pass `otlptracegrpc.New(ctx)`, which reads its endpoint from `OTEL_EXPORTER_OTLP_ENDPOINT`. Then instrument at three levels: 1. **Incoming HTTP**: wrap your router with `otelhttp.NewHandler(handler, "http.server")`. It starts a span per request, continuing any incoming `traceparent`, and puts it in `r.Context()`. 2. **Outgoing HTTP**: use `&http.Client{Transport: otelhttp.NewTransport(http.DefaultTransport)}` so calls carry `traceparent` and get child spans. Instrumentation libraries exist for pgx and go-redis too. 3. **Your own code**: start spans around interesting work. ```go var tracer = otel.Tracer("example.com/orders") func chargeCard(ctx context.Context, orderID int64) error { ctx, span := tracer.Start(ctx, "chargeCard") defer span.End() span.SetAttributes(attribute.Int64("order.id", orderID)) if err := paymentProvider.Charge(ctx, orderID); err != nil { span.RecordError(err) span.SetStatus(codes.Error, err.Error()) return err } slog.InfoContext(ctx, "card charged", "order_id", orderID) return nil } ``` `tracer.Start` returns a new context containing the span. Pass *that* context onward, or child spans and log correlation attach to the wrong parent. And always `defer span.End()`: a span that never ends is never exported. ## Alerting on what users feel Collecting signals is half the job; the other half is deciding what wakes someone up. Alert on **symptoms** users experience, not on every possible cause: - **Error rate**: the share of requests returning 5xx over the last few minutes, above an agreed threshold such as 1%. - **Latency**: the 95th or 99th percentile of `http_request_duration_seconds` per route, above its target. - **Saturation** that predicts trouble: database pool connections in use near `MaxConns`, or a queue growing without bound. Export these as gauges. A CPU spike that users don't notice is a dashboard curiosity, not a page at 3 a.m. When a symptom alert fires, the workflow is the one this lesson built: the metric tells you *which route* and *since when*, a sampled trace from that window shows *which span* is slow or failing, and the logs carrying that trace ID tell you *why*. ## Practice Build a small `orders-api` that ties all three signals together: 1. Configure slog with `newLogger` and `contextHandler`. 2. Add `POST /v1/orders/{id}/pay`, which calls `chargeCard`. Simulate the provider with a 20–50 ms sleep, and make orders whose ID is divisible by 5 fail with `card declined` (respond 402). 3. Wrap the mux with `metrics` and then `otelhttp.NewHandler`, and serve `GET /metrics`. 4. Export spans with `stdouttrace.New(stdouttrace.WithPrettyPrint())` and sample everything. Call `POST /v1/orders/1/pay` and `/v1/orders/5/pay`. Check that the `trace_id` in each log line matches the `TraceID` of the printed `chargeCard` span, and that `/metrics` shows a 204 and a 402. **Solution** ```go func chargeCard(ctx context.Context, orderID int64) error { ctx, span := tracer.Start(ctx, "chargeCard") defer span.End() span.SetAttributes(attribute.Int64("order.id", orderID)) time.Sleep(time.Duration(20+rand.IntN(30)) * time.Millisecond) // the "provider" if orderID%5 == 0 { err := errors.New("card declined") span.RecordError(err) span.SetStatus(codes.Error, err.Error()) return err } slog.InfoContext(ctx, "card charged", "order_id", orderID) return nil } func main() { var level slog.LevelVar slog.SetDefault(newLogger(&level)) exp, err := stdouttrace.New(stdouttrace.WithPrettyPrint()) if err != nil { log.Fatal(err) } // In setupTracing, use sdktrace.AlwaysSample() while experimenting. shutdown, err := setupTracing(context.Background(), exp) if err != nil { log.Fatal(err) } defer shutdown(context.Background()) mux := http.NewServeMux() mux.HandleFunc("POST /v1/orders/{id}/pay", func(w http.ResponseWriter, r *http.Request) { id, err := strconv.ParseInt(r.PathValue("id"), 10, 64) if err != nil { http.Error(w, "invalid id", http.StatusBadRequest) return } if err := chargeCard(r.Context(), id); err != nil { slog.WarnContext(r.Context(), "payment failed", "order_id", id, "err", err) http.Error(w, "payment failed", http.StatusPaymentRequired) return } w.WriteHeader(http.StatusNoContent) }) mux.Handle("GET /metrics", promhttp.Handler()) srv := &http.Server{Addr: ":8080", Handler: otelhttp.NewHandler(metrics(mux), "http.server")} log.Fatal(srv.ListenAndServe()) } ``` Log output, with timestamps trimmed: ```text {"level":"INFO","msg":"card charged","order_id":1,"trace_id":"0778402bddc4eff033fad74ae4182829","span_id":"5aa6fab45aa38e4d"} {"level":"WARN","msg":"payment failed","order_id":5,"err":"card declined","trace_id":"ca7cc8716787c9416079bdf0bc940a0b","span_id":"d2fc93ed6065a0f3"} ``` The printed `chargeCard` span shows `"TraceID": "0778402bddc4eff033fad74ae4182829"` and a `Parent` whose ID is the server span created by `otelhttp` (recent versions name it after the route pattern, `POST /v1/orders/{id}/pay`). Spans are batched, so they may appear a few seconds after the request. Because `log.Fatal` exits without running deferred calls, a real service should shut down gracefully so `shutdown` can flush the last spans (see the deployment lesson). ## Key takeaways - Logs explain single events, metrics show aggregate health and trends, traces show where time went; a shared trace ID links them. - Use `slog` with a JSON handler: constant messages, typed attributes, `With` for shared context, and errors logged once where they're handled. - Redact secrets with `LogValuer`, and use a wrapping handler plus `InfoContext` to add trace IDs to every log line. - Expose RED metrics (rate, errors, duration) with counters and histograms, labelled by route pattern, never by raw path or user ID. - Set up an OpenTelemetry tracer provider once, wrap servers and clients with `otelhttp`, and always pass on the context returned by `tracer.Start` and `defer span.End()`. ## Quiz 1. Which slog call is easiest to filter and aggregate in a log system? A. slog.Info(fmt.Sprintf("payment for order %d failed: %v", id, err)) B. slog.Info("payment failed", "order_id", id, "err", err) C. log.Printf("payment failed order=%d err=%v", id, err) D. fmt.Println("payment failed", id, err) **Answer: B.** A constant message with separate attributes lets the log system group all 'payment failed' events and filter by order_id. Formatting the values into the message makes every line unique text. 2. Why does the metrics middleware label requests with r.Pattern instead of r.URL.Path? A. r.URL.Path is not available in middleware B. Prometheus labels cannot contain slashes C. Raw paths contain IDs, creating an unbounded number of time series D. r.Pattern includes the response status code **Answer: C.** Each unique label combination is a separate series. /v1/orders/1, /v1/orders/2 and so on would explode cardinality; the pattern 'POST /v1/orders/{id}/pay' is one bounded value per route. 3. A request reaches service A, which calls service B over HTTP. How does B's span end up in the same trace as A's? A. A sends a W3C traceparent header containing the trace ID and parent span ID, and B continues the trace B. Both services export to the same collector, which matches spans by timestamp C. B queries A's tracer provider over gRPC D. The trace ID is derived from the request URL, so both services compute the same one **Answer: A.** Context propagation carries the trace context in headers. otelhttp.NewTransport injects traceparent on the client side; otelhttp.NewHandler extracts it on the server side. 4. In chargeCard, what goes wrong if you write `_, span := tracer.Start(ctx, "chargeCard")` and keep using the original ctx? A. The span is never exported B. The program panics when span.End is called C. The span is automatically marked as an error D. Child spans and InfoContext logs use the parent span instead of chargeCard **Answer: D.** The new span lives only in the context returned by Start. Code that receives the old context sees the parent span, so children attach to the wrong node and log lines carry the parent's span ID. The span itself is still exported when End is called.