Metrics tell you that something is wrong and by how much, traces tell you where in a request the time or the error went, and logs tell you exactly what happened in one event.
Metrics: numbers aggregated per label set (http_requests_total, latency histograms). They stay cheap at any traffic, so they drive dashboards and alerts, but they cannot show you one specific request.
Traces: a tree of timed spans for one request across services. They show which hop of a six-service call took the two seconds, but they are usually sampled, so a given request may be missing.
Logs: one record per event with any detail you like, including high-cardinality fields such as user_id or order_id. Expensive at volume and slow to aggregate.
Shared ids tie them together: a trace_id on every log line and exemplars on histograms take you from alert to metric to trace to log in a few clicks.
Continuous profiling is often called the fourth signal: it answers which line of code is spending the CPU or the memory.
GoSenior
Observability & Production Ops
slog, Prometheus, OpenTelemetry, probes, SLOs, debugging a p99 spike
Questions closed
0 / 24
- 0Review
- 1Asked often
Questions
Structured logging writes each event as a fixed message plus typed key/value fields, so the log store can filter and count by field instead of grepping text; log/slog (Go 1.21+) does this in the standard library.
The message names the event and never changes; everything variable goes beside it: slog.Info("order failed", "order_id", id, "tenant", t).
The Handler owns format and destination: slog.NewJSONHandler(os.Stdout, nil) in production, slog.NewTextHandler in a terminal.
Levels: Debug is detail for developers and is off in production; Info is a normal business event; Warn is something unexpected the service handled itself (a retry that succeeded, a fallback); Error means an operation failed and someone may have to act.
HandlerOptions.Level accepts a *slog.LevelVar, so you can switch one process to Debug during an incident without a redeploy.
In production write JSON to stdout at Info and above and let the platform ship it; never log request bodies, tokens or passwords.
ErrorContext gets err without a key, so slog writes it under the placeholder key !BADKEY: the line is there, but it has no err field to search, filter or alert on.
The variadic args are read as key/value pairs. A value that is neither a string key nor a slog.Attr does not fail the call: the handler emits "!BADKEY":"card declined" and moves on, so nothing breaks loudly in production.
The fix gives every value its key, "err", err. Typed attributes, slog.Any("err", err) or slog.String("order_id", orderID), cannot lose a key at all.
go vet reports arg "err" should be a string or a slog.Attr (possible missing key or value), and go test runs that check too. It sees direct calls to slog only, not a wrapper that forwards args ...any.
Teams that want typed attributes everywhere enforce it with sloglint (attr-only) in golangci-lint.
Prometheus pulls: every scrape interval (typically 15–30 s) it sends GET /metrics to each target, and promhttp answers with the current value of every metric as text. The service only keeps counters in memory; Grafana then queries Prometheus with PromQL.
The default registry already holds the Go and process collectors: go_goroutines, go_threads, go_gc_duration_seconds, go_memstats_*, process_cpu_seconds_total, process_resident_memory_bytes, process_open_fds.
The Go collector reads runtime/metrics at scrape time, so nothing accumulates between scrapes.
prometheus.NewRegistry() is empty: register collectors.NewGoCollector() and collectors.NewProcessCollector(...) yourself and serve it with promhttp.HandlerFor(reg, ...), because promhttp.Handler() serves only the default registry.
A registry of your own keeps registration out of global state: no library adds series behind your back, and each test starts clean.
Pull also tells you when a target is down (up == 0). Short-lived batch jobs that exit before a scrape push to a Pushgateway instead.
A counter only goes up and is read through rate(); a gauge goes up and down and is read as is; a histogram counts observations into buckets so percentiles can be computed across pods; a summary computes percentiles inside one process. Latency goes into a histogram.
Counter: requests, errors, bytes sent; the name ends in _total. It resets to zero on restart and rate() handles that, which is why you never Set a counter.
Gauge: a current value: in-flight requests, queue depth, pool size. Pair Inc with a deferred Dec, or an early return leaves it drifting upward forever. rate() of a gauge is meaningless.
Histogram: exports _bucket{le="..."}, _sum and _count. Buckets from every pod can be summed, and histogram_quantile then gives a fleet-wide p99.
Summary: quantiles precomputed in the client, which cannot be combined across instances. Rarely the right choice today.
An average (_sum / _count) hides the tail: if one request in a hundred takes 5 s, the mean barely moves, yet almost one page load in five that makes 20 calls hits it.
A trace is the whole journey of one request: a tree of spans, each one a timed operation (a handler, a query, an outgoing call) with attributes and a status. Every span of the request carries the same 128-bit trace id, plus its own span id and its parent's.
Inside a process the current span lives in context.Context: tracer.Start(ctx, name) creates a child of whatever span ctx holds and returns a new ctx for the code below.
Between processes it travels in a header. The W3C format is traceparent: 00-<trace-id>-<parent-span-id>-<flags>: the client injects it, the server extracts it and continues the same trace.
otelhttp and otelgrpc inject and extract for you; for a queue you put the header into the message metadata yourself.
The SDK batches finished spans and exports them over OTLP to a collector, which forwards them to Jaeger, Tempo or a vendor backend.
An SLI is a measured ratio of good events (say, requests answered without a 5xx in under 300 ms). An SLO is the target for it over a window, such as 99.9% over 30 days. An SLA is the contract with customers, with penalties, and is set looser than the SLO.
Measure the SLI where the user feels it (at the load balancer or from the server's request counters), not from CPU or memory.
The error budget is 1 − SLO: at 99.9% over 30 days you may fail 0.1% of requests, the equivalent of 43 minutes of full outage.
The budget is a decision tool: while some is left, ship features; once it is spent, risky releases wait and reliability work goes first.
100% is the wrong target: every extra nine costs far more than the last, and users' own networks fail more often than that anyway.
An SLO stricter than the SLA gives you room to react before the penalties start.
On an HTTP service start with RED (Rate, Errors, Duration) per route; on a queue worker start with USE-style saturation (queue depth and age of the oldest message) and add RED for the jobs it processes.
RED is two metrics: the counter http_requests_total{route,method,status} and the histogram http_request_duration_seconds{route}. Rate and error ratio are both queries over the counter.
For a checkout service that is the first dashboard row: requests per second, 5xx ratio and p99 per route, next to the same three for each dependency it calls.
For a worker, saturation is queue depth plus the age of the oldest waiting message. Depth alone lies: the same depth is fine at 1000 msg/s and a disaster at 10.
USE is Utilisation, Saturation, Errors per resource. Utilisation is busy workers over pool size. A prometheus.NewGaugeFunc reads values like these at scrape time, so the worker loop itself stays untouched.
Bind the request's attributes once with **logger.With(...)** and pass that child logger down. The Context is for crossing code you do not own, not a replacement for a parameter you could have passed.
With returns a new *slog.Logger whose handler has already formatted those attributes, so the cost is paid once per request rather than once per record.
A logger in Context is a hidden dependency: use it for code you cannot change, and have the helper fall back to slog.Default() so a missing middleware does not panic.
The attribute worth the most is trace_id: wrap the Handler to add it from trace.SpanContextFromContext(ctx); this works only for call sites that use the *Context methods (InfoContext, ErrorContext).
Give the type a **LogValue() slog.Value** method: slog.LogValuer is resolved by the handler at output time, so every call site that logs that value emits the redacted form.
Return slog.StringValue("REDACTED"), or slog.GroupValue(...) holding only the fields that are safe to print.
Watch the receiver. A LogValue on *User does not apply when you log a User value: the struct prints in full and the redaction silently does not happen.
fmt knows nothing about LogValuer, so fmt.Sprintf("%+v", u) walks straight past it and prints the token.
Make the secret its own type, type Token string: redaction attached to a field is a rule someone will forget, attached to the type it is the default.
Handle an error once: either log it or return it, never both. Each layer adds context by wrapping with fmt.Errorf("load order %s: %w", id, err), and the outermost boundary writes the single record.
The boundary is the HTTP handler, the gRPC interceptor, a worker loop or main: the place that knows the status code and whether the user was told.
Five lines for one failure makes every count taken from logs wrong by 5×, and the same over-counting hits the metric if each layer increments a counter too.
The boundary picks the level too, with errors.Is: a context.Canceled from a client that hung up is Info, not Error.
A goroutine with nobody to return to is its own boundary, which is exactly why it has to log.
The second call to prometheus.MustRegister panics with duplicate metrics collector registration attempted, because a counter with that name is already in the default registry. net/http recovers the panic and drops the connection, so from the second request on no order is ever created.
Metrics are created and registered once, at startup, as package-level promauto variables or in the constructor with an injected prometheus.Registerer. The hot path only calls Inc, Add or Observe.
Must* exists to make a duplicate fail at startup, where it is loud. Inside a handler it fails on every request, and the only trace is an http: panic serving ... line on stderr.
Switching to Register and ignoring the error would not help: each request would increment its own fresh counter that /metrics never shows.
An injected Registerer also lets a test pass prometheus.NewRegistry() and read the value with testutil.ToFloat64.
Put bucket boundaries around the SLO and past the timeout: the quantile is interpolated inside a bucket, so with the default top bound of 10 s a bad p99 reads as about ten seconds.
A boundary exactly on the SLO (le="0.3") makes "requests under 300 ms" an exact division of two counters instead of an interpolated guess.
More buckets mean more series: every bucket is a series per label combination, so a dozen buckets times many routes adds up.
Native histograms (NativeHistogramBucketFactor) remove the manual choice: the client exports exponentially sized buckets and the server stores them compactly.
The arguments of a deferred call are evaluated at the defer statement, so time.Since(start) is taken right after start is set: every request records about zero seconds, the p99 looks perfect and a latency alert can never fire.
defer postpones only the call to Observe. The argument time.Since(start).Seconds() runs immediately, nanoseconds after time.Now(), before checkout has even started.
Nothing else looks wrong: _count still grows with traffic, so rate panels are right, and only the latency is a lie. It usually surfaces in an incident, when the p99 stays flat while clients time out.
prometheus.NewTimer(h) stores the start time and reads the clock inside ObserveDuration, which runs at return. A closure, defer func() { h.Observe(time.Since(start).Seconds()) }(), works the same way.
go vet reports call to time.Since is not deferred, but go test does not run that check, so CI needs go vet ./... or golangci-lint. A test whose fake checkout sleeps 50 ms and asserts the histogram's sample sum catches it too.
**span.RecordError(err) only adds an exception event; the span's status stays Unset until you call span.SetStatus(codes.Error, err.Error())**, and the status is the field a backend colours, filters and alerts on.
Attributes passed to Start with trace.WithAttributes(...) are visible to the sampler; ones you add later are not.
RecordError adds an event named exception with the error type and message; it does not change the status.
Set Error only for real failures: a not-found or a 4xx on a server span is not a span error.
Two bugs: the ctx returned by tracer.Start is discarded, so the repository's span hangs off GetOrder's parent; and span.End() runs only on success, so every failed lookup leaves a span that is never ended and never exported.
tracer.Start cannot change the ctx you passed in: contexts are immutable. Write ctx, span := tracer.Start(ctx, ...) and pass that ctx on.
defer span.End() straight after Start covers every return and every panic.
The failure also has to be marked with span.RecordError(err) and span.SetStatus(codes.Error, ...), or the span shows green.
The spancheck linter in golangci-lint catches a missing End or SetStatus before review does.
The Go SDK's default propagator is a no-op: nothing writes or reads the W3C traceparent header until you call otel.SetTextMapPropagator(...), in both processes.
traceparent carries the trace id, the caller's span id and a sampled flag; the server extracts it, so its span becomes a child instead of a new root.
Set it once at startup: propagation.NewCompositeTextMapPropagator(propagation.TraceContext{}, propagation.Baggage{}).
The other usual break is the client side. otelhttp.NewHandler instruments your server, but an outbound call needs otelhttp.NewTransport or the next hop sees no header at all.
Any context.Background() in the middle ends the trace right there, and cancellation with it.
Liveness decides whether the container is restarted, readiness whether the pod receives traffic, and a startup probe holds both off until slow initialisation is done. All three should check only the process's own state.
Liveness: 200 unless the process is wedged: a worker loop that stopped ticking, a deadlocked component. A restart has to be able to fix whatever it detects, which rules out anything across the network.
Readiness: 200 once initialisation is done (config loaded, caches warm) and 503 from the moment SIGTERM arrives, so health-checking load balancers stop sending traffic while it drains.
Startup: for a slow warm-up: liveness does not run until it passes, instead of an initialDelaySeconds guess that is either too short for a cold start or too long to catch a hang.
Serve /livez and /readyz from the main listener: if the server stops accepting connections, the probes fail with it.
Never ping a shared database from a probe (see the readiness outage question).
**SIGTERM and the pod's removal from the Service endpoints happen at the same time, not in sequence**, and the removal takes seconds to reach kube-proxy and the load balancers, which keep sending traffic to a server Shutdown has already closed.
A preStop sleep of 5–10 s (built-in sleep action in Kubernetes 1.30+, no shell needed) lets endpoint removal reach kube-proxy before Shutdown starts.
Then call srv.Shutdown(ctx): it closes the listeners, drops idle keep-alive connections and waits for the handlers still running (see the HTTP topic for the Shutdown sequence).
Only after that close what the handlers use (the DB pool) and call TracerProvider.Shutdown to flush the last spans.
terminationGracePeriodSeconds (default 30) covers preStop plus your drain; when it runs out the kubelet sends SIGKILL. Keep the sleep plus the drain timeout below it.
Every distinct combination of label values is a separate time series, with its own index entries and its own chunks on disk, so a user_id label multiplies the whole metric by the number of users.
Cardinality multiplies rather than adds: 50 routes × 5 status classes × 100k users is 25 million series out of one metric.
A label has to be a set you could write down at deploy time: route template, method, status class. Identity (user, order, request) belongs in logs and traces, which are built for it.
In Go 1.23+ label with r.Pattern, the matched ServeMux pattern; r.URL.Path makes every /orders/8f2c… a new series. Map anything unmatched to a fixed value such as "unmatched", never to the raw input.
Find the offender on Prometheus's TSDB status page, which lists the metrics and labels with the most series, or with topk(10, count by (__name__) ({__name__=~".+"})).
Contain it on the server as well: sample_limit fails a scrape whose series count suddenly explodes, and metric_relabel_configs with labeldrop removes a label before it is stored.
Read r.Pattern after next.ServeHTTP returns: the mux fills it in during routing, so before the call it is empty.
Because every replica failed the probe at once, the Service had no endpoints; it came back only after the probes passed again and the pods had reconnected their pools and warmed up, and the reconnect stampede slowed the database that had just recovered.
The service had zero capacity even for requests that never touch the database, and it outlives the fault: a pod rejoins the endpoints only after the probe passes again (period times successThreshold), then every pod reconnects its pool at once with cold caches.
Readiness answers "can this process take a request right now": local, no I/O, and 503 the moment shutdown starts. Taking the pod out of rotation during a deploy is its real job.
If the liveness probe touches the database too, the pods are restarted, and you pay a cold start on top of the outage.
Keep the dependency check as /health/deep for a synthetic monitor and an alert: it informs humans, and it must never remove capacity.
A head sampler decides at the root span, before anything interesting has happened, so a rare slow request survives only by luck: 1% answers questions about the shape of traffic, never "this one request".
sdktrace.ParentBased(sdktrace.TraceIDRatioBased(0.01)): the root flips the coin and everyone below honours the flag from traceparent, or traces come out with holes.
What 1% does answer well: the shape of the latency distribution, which downstream dominates a typical request, where a common path spends its time.
Tail sampling moves the decision to the collector: it buffers every span of a trace until it finishes, then keeps the errors and the slow ones. That would have kept your 9-second checkout.
The price: all spans of a trace must reach the same collector instance, so you need a load balancer keyed on trace id and memory for the buffer; the saving is only in storage.
A tripled p99 at flat CPU means waiting, not computing: narrow with the labels you already have, open one trace from the slow bucket, then profile block, mutex or goroutine, not CPU.
Break the latency histogram down by route and instance: one instance means the host, one route means that code path, everywhere at once means a shared dependency.
Open the trace an exemplar from the slow bucket points at: the span whose duration grew names the culprit (a downstream call, a lock, a retry).
For waiting rather than computing, use the block, mutex and goroutine profiles (see the runtime topic).
Continuous profiling (Pyroscope, Parca or a vendor agent) keeps profiles from before the incident, so you can compare with the healthy hour.
net/http/pprof registers on http.DefaultServeMux; serve it from its own mux on 127.0.0.1 and reach it with kubectl port-forward.
Page on a symptom the user feels, measured as a burn rate against an SLO, and never on a cause. An alert must answer whether the error budget is being spent faster than you can afford: a rate over a window, not a value at an instant.
The SLI is good events over valid events, from counters you already export: non-5xx responses, or requests served under 300 ms. 99.9% over 30 days is 43 minutes of budget for the month.
Burn rate replaces the threshold. 14.4× over one hour spends 2% of the month's budget and would empty it in about two days: page. 6× over six hours: page. 1× over three days: a ticket.
Pair a long window with a short one in the same rule, 1h with 5m: the long one is the signal, the short one clears the alert as soon as the problem is over.
CPU, memory and queue depth are causes, so they belong on dashboards and in tickets. They fire constantly with nobody affected.