Observability & Production Ops
slog, Prometheus, OpenTelemetry, probes, SLOs, debugging a p99 spike
- 01
Your service logs with
log.Printf("order %s failed for tenant %s: %v", id, tenant, err)and the on-call cannot answer "how many of these were tenant A?" without grepping. What does moving tolog/slogactually change?EasyIt takes the facts out of the sentence:
slogwrites a stable message plus typed key/value attributes, so a line becomes a record you can filter and count instead of prose you have to parse back.// ❌ the fields are baked into the sentence, so every question is a grep func placeOld(id, tenant string, err error) { log.Printf("order %s failed for tenant %s: %v", id, tenant, err) } var level = new(slog.LevelVar) // Leveler: flip at runtime, no redeploy … - 02
You moved the service off the default Prometheus registry onto
prometheus.NewRegistry(), andgo_goroutines,go_memstats_*andprocess_resident_memory_bytesdisappeared from/metrics. Why, and what brings them back?EasyOnly the default registry has the Go and process collectors pre-registered; a fresh
prometheus.NewRegistry()is empty, so you registercollectors.NewGoCollector()andcollectors.NewProcessCollector(...)into it yourself.func newMetrics() (*prometheus.Registry, *prometheus.CounterVec) { reg := prometheus.NewRegistry() // empty — nothing is implicit here reg.MustRegister( collectors.NewGoCollector( collectors.WithGoCollectorRuntimeMetrics(collectors.MetricsScheduler), … - 03
A new HTTP service and a new queue worker both ship next week, and you have one sprint of instrumentation budget. Which metrics go in first, and why are they not the same set for the two?
EasyRED for anything that serves requests — Rate, Errors, Duration — and USE for anything with a resource that can saturate — Utilisation, Saturation, Errors. A worker needs both, because its "request rate" is somebody else's decision.
var ( reqs = prometheus.NewCounterVec(prometheus.CounterOpts{ Name: "http_requests_total", }, []string{"route", "method", "status"}) dur = prometheus.NewHistogramVec(prometheus.HistogramOpts{ … - 04
A pod is in
CrashLoopBackOffand the crash arrives in your log store as forty separate one-line events with no fields on any of them. What is producing that, and how do you get one usable record instead?EasyAn unrecovered panic is printed by the runtime straight to stderr as a multi-line goroutine dump, then the process exits with status 2 — it never passes through
slog, so the collector sees forty unrelated lines.// Every goroutine you start owns its own recover; the handler's does not cover it. func Go(ctx context.Context, name string, fn func()) { go func() { defer func() { if v := recover(); v != nil { slog.ErrorContext(ctx, "panic in goroutine", … - 05
Every handler in your service repeats
slog.Info(msg, "request_id", rid, "tenant", t), and the lines logged by the packages underneath have neither field. What is the shape that fixes this, and what is the trap in putting the logger into theContext?MediumBind the request's attributes once with
logger.With(...)and pass that child logger down; theContextis for carrying it across boundaries you do not control, not a substitute for a parameter you could have passed.// A handler wrapper, so trace_id lands on every record without touching call sites. type traceHandler struct{ slog.Handler } func (h traceHandler) Handle(ctx context.Context, r slog.Record) error { if sc := trace.SpanContextFromContext(ctx); sc.IsValid() { r.AddAttrs( … - 06
slog.Info("auth ok", "user", u)put a live bearer token into the log store, and that struct is logged from a dozen places. Where do you fix it once?MediumGive the type a
LogValue() slog.Valuemethod —slog.LogValueris resolved by the handler at output time, so every call site that logs that value, including the ones written next month, emits the redacted form.type Token string // Resolved by the handler at output time, everywhere this value is logged. func (Token) LogValue() slog.Value { return slog.StringValue("REDACTED") } type User struct { … - 07
One failing database call produces five
ERRORlines and five increments of your error counter, one per layer it passed through. What is the rule, and where does the single log line belong?MediumHandle an error once: either log it or return it, never both. Each layer adds context by wrapping —
fmt.Errorf("load order %s: %w", id, err)— and the outermost boundary writes the one record.// ❌ logged here, and again by every caller above func (r *Repo) load(ctx context.Context, id string) (Order, error) { var o Order if err := r.db.QueryRowContext(ctx, q, id).Scan(&o.ID); err != nil { slog.ErrorContext(ctx, "query failed", "err", err) return Order{}, err … - 08
Someone added a
user_idlabel tohttp_requests_total, and within a day Prometheus was holding four million series, using 20 GB and timing out on queries. What is the relationship between a label and that cost?MediumEvery distinct combination of label values is a separate time series, with its own entry in the head block, its own index postings and its own chunks on disk — so a label with user-scale cardinality multiplies the whole metric by that scale.
// ❌ one series per user and per raw path: unbounded on both axes var badReqs = prometheus.NewCounterVec(prometheus.CounterOpts{ Name: "http_requests_total", }, []string{"user_id", "path", "status"}) func badMiddleware(w http.ResponseWriter, r *http.Request, status int) { … - 09
Your p99 latency panel is built from a
Summary, every pod reports a different number, and averaging them across pods is meaningless. What does a histogram do differently, and how do you choose its buckets?MediumA summary computes its quantiles inside the process, and quantiles cannot be averaged — a histogram exports plain counters per bucket, so
histogram_quantile()can sum the buckets from every pod first and compute the quantile afterwards.var latency = prometheus.NewHistogramVec(prometheus.HistogramOpts{ Name: "http_request_duration_seconds", // Boundaries around the SLO (300ms) and out past the timeout (10s), // so the p99 does not saturate at the last bucket. Buckets: []float64{.005, .01, .025, .05, .1, .2, .3, .5, 1, 2.5, 5, 10, 30}, … - 10
The request returned a 500, the trace has the span, and the span is green with no error attached. What did the code skip, and what is the difference between recording an error and setting the status?
Mediumspan.RecordError(err)only adds an exception event; the span's status staysUnsetuntil you callspan.SetStatus(codes.Error, err.Error())— and the status is the field every backend colours, filters and alerts on.var tracer = otel.Tracer("github.com/acme/orders") func (s *Service) Load(ctx context.Context, id string) (Order, error) { // Attributes at Start are visible to the sampler; later ones are not. ctx, span := tracer.Start(ctx, "OrderService.Load", trace.WithAttributes(attribute.String("order.id", id))) … - 11
Traces from your gateway end at the gateway's own span: the downstream service opens a brand-new trace for the same request, even though both processes run the OpenTelemetry SDK. What is missing?
MediumThe Go SDK's default propagator is a no-op — nothing writes or reads the W3C
traceparentheader until you callotel.SetTextMapPropagator(...), in both processes, and use instrumentation that actually injects on the client side.func initPropagation() { // Without this the SDK propagates nothing at all. otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator( propagation.TraceContext{}, // W3C traceparent / tracestate propagation.Baggage{}, )) … - 12
During every rolling deploy a handful of requests come back as connection resets, although the service does call
srv.Shutdown(ctx)when it receivesSIGTERM. What ordering does the pod actually need?MediumSIGTERMand the removal of the pod from the Service's endpoints happen at the same time, not in sequence — so for a second or two after the signal, load balancers are still sending you traffic and the process must keep serving it before it starts draining.func run(srv *http.Server, ready *atomic.Bool, db *sql.DB, tp *sdktrace.TracerProvider) error { ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGTERM, os.Interrupt) defer stop() errc := make(chan error, 1) go func() { errc <- srv.ListenAndServe() }() … - 13
A 20-second blip on the primary database turned into a four-minute total outage of a service whose readiness probe pings that database. Account for the other three and a half minutes.
HardA readiness probe that checks a shared dependency converts one dependency's blip into a full outage: every replica fails the probe simultaneously, Kubernetes removes every endpoint from the Service, and the service now has zero capacity — including for requests that never touch the database.
type Probes struct { started atomic.Bool draining atomic.Bool db *sql.DB } … - 14
You sample traces head-based at 1%. A customer sends you the trace id printed on a 9-second checkout and it is not in the backend. What can a 1% sample answer, what can it never answer, and what would tail sampling have changed?
HardA head sampler decides at the root span, before anything interesting has happened, so a rare slow request survives only by luck — 1% answers aggregate questions about shape and can never answer "this request".
// Keep the ratio decision at the root, honour the parent everywhere else, // and give support a way to force one trace through. type debugOverride struct{ inner sdktrace.Sampler } func (d debugOverride) ShouldSample(p sdktrace.SamplingParameters) sdktrace.SamplingResult { for _, a := range p.Attributes { … - 15
At 14:05 the p99 tripled while the error rate, the request rate and CPU all stayed flat, and the last deploy was two days ago. Walk from the dashboards down to the line of code — and say how
net/http/pprofgets exposed without handing it to the internet.HardMetrics tell you which dimension moved, one trace tells you which span owns the added time, and a profile tells you which stack is spending it — and a tripled p99 at flat CPU means waiting, so the profile you want is block, mutex or goroutine, not CPU.
// Importing this package registers its handlers on http.DefaultServeMux from // its init() — which is exactly why the public server must never use that mux. import "net/http/pprof" func startAdmin(reg *prometheus.Registry) *http.Server { runtime.SetBlockProfileRate(10000) // 1 in 10k blocking events; off by default … - 16
Your team is paged at 3am for "CPU > 80%" and for "p99 > 500ms for 5 minutes", both of which clear themselves before anyone opens a laptop — while last month's real two-hour degradation paged nobody. Redesign the alerting.
HardPage on a symptom, measured as a burn rate against an SLO, and never on a cause. An alert has to answer "is the users' experience being spent faster than the error budget allows", which is a rate over a window, not a value at an instant.