# 16. Observability

The service works end to end now — including the one per-user piece
[chapter 15](15-scoped-instances.md) added — but from the outside, a running instance is a black
box: there's no way to tell whether it's healthy, slow, or actually doing what a request asked for
without attaching a debugger. This chapter adds the three tools that answer those questions in
production: structured logs for "what happened," metrics for "how much and how fast," and traces
for "what did this one request actually do."

## Logs first, and why they're not a servo component

Every log line so far has used `log/slog`'s unconfigured default logger — plain text, no level
filtering. Fixing that is one function, and it deliberately isn't wired through servo. Create
`observability/logging.go`:

```go
package observability

// Logger is a defined type rather than a bare *slog.Logger. That matters
// more than it looks: a foreign type comes with foreign providers.
// slog.Default and a transitive dependency's logr helper both return
// *slog.Logger, and servo has no basis for choosing between them — it
// reports the ambiguity rather than guessing. Owning the type is the same
// rule as owning your configuration (chapter 3).
//
// The embedded *slog.Logger means callers write log.InfoContext(...)
// exactly as they would have.
type Logger struct{ *slog.Logger }

//servo:config prefix=OBS
type Config struct {
	LogLevel     string `config:"log_level,default=info"`
	OTLPEndpoint string `config:"otlp_endpoint"`
}

func NewLogger(cfg Config) *Logger {
	l := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
		Level: parseLevel(cfg.LogLevel),
	}))
	slog.SetDefault(l)
	return &Logger{Logger: l}
}

func parseLevel(s string) slog.Level {
	switch s {
	case "debug":
		return slog.LevelDebug
	case "warn":
		return slog.LevelWarn
	case "error":
		return slog.LevelError
	default:
		return slog.LevelInfo
	}
}
```

`NewLogger` is an ordinary provider, and that is the whole point.

The variables are `OBS_LOG_LEVEL` and `OBS_OTLP_ENDPOINT`. Chapter 3's hand-rolled ancestor of
this design let "app-wide" settings go unprefixed; the `//servo:config` directive doesn't, because
an unowned name is how two packages end up quietly reading one variable — so this package's
settings carry its prefix like everyone else's.

### Why the logger is a node, and not a call at the top of `main`

The tempting shape is a plain function called before anything else:

```go
// don't do this
observability.ConfigureLogging(cfg) // before anything else has a chance to log
app, err := New(ctx)
```

The argument for it is real: logging setup has to happen before anything logs, and calling it first
obviously achieves that. But look at what that sentence is doing — it is an *ordering assertion*,
made by a human, in a comment. It is exactly the kind of claim this whole tool exists to derive from
dependencies rather than assert, and servo cannot check it. Add a component tomorrow whose
constructor logs, and nothing tells you the ordering assumption still holds.

Making the logger a node removes the question instead of answering it. Anything that logs takes a
`*observability.Logger`:

```go
func New(cfg natsbroker.Config, log *observability.Logger) *Notifier
func New(repo repository.OrderRepository, c cache.OrderCache, publisher broker.EventPublisher, log *observability.Logger) *OrderService
```

so the logger is constructed before them by the same rule that orders everything else. "Did logging
get configured before X" is not a question anyone can ask, because X cannot be built without it.
`main` configures nothing at all now:

```go
func main() {
	ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
	defer stop()

	app, err := New(ctx)
	if err != nil {
		log.Fatal(err)
	}
	...
}
```

`NewLogger` still calls `slog.SetDefault`, and that is not a leftover. It is for code servo does not
wire: the standard library and third-party packages log through `slog.Default()` and have no
constructor to inject into. Our own code never relies on it — every component here takes the logger.
The global became a *consequence* of building the logger rather than the mechanism for configuring
it, and it now happens at the right moment by construction.

## Metrics, and a cardinality trap worth knowing about

Create `observability/metrics.go`:

```go
package observability

import (
	"net/http"
	"strconv"
	"time"

	"github.com/prometheus/client_golang/prometheus"
	"github.com/prometheus/client_golang/prometheus/promhttp"
)

type Metrics struct {
	registry        *prometheus.Registry
	requestsTotal   *prometheus.CounterVec
	requestDuration *prometheus.HistogramVec
}

func NewMetrics() *Metrics {
	m := &Metrics{
		registry: prometheus.NewRegistry(),
		requestsTotal: prometheus.NewCounterVec(prometheus.CounterOpts{
			Name: "orders_http_requests_total",
			Help: "Total HTTP requests, by method, route, and status.",
		}, []string{"method", "route", "status"}),
		requestDuration: prometheus.NewHistogramVec(prometheus.HistogramOpts{
			Name: "orders_http_request_duration_seconds",
			Help: "HTTP request duration in seconds, by method and route.",
		}, []string{"method", "route"}),
	}
	m.registry.MustRegister(m.requestsTotal, m.requestDuration)
	return m
}

func (m *Metrics) Handler() http.Handler {
	return promhttp.HandlerFor(m.registry, promhttp.HandlerOpts{})
}
```

`NewMetrics` builds its own `*prometheus.Registry` rather than registering into
`prometheus.DefaultRegisterer` — deliberately. Prometheus panics on a duplicate metric
registration, and the global default registry is shared by the whole process; a normal `*App` and
a `NewTestApp` in the same test binary would both try to register `orders_http_requests_total`
into it and the second one would crash the test. A registry that belongs to this one `*Metrics`
instance can't collide with anything.

Now the middleware, and the cardinality trap it exists to avoid:

```go
func (m *Metrics) Middleware(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		start := time.Now()
		sw := &statusRecorder{ResponseWriter: w, status: http.StatusOK}
		next.ServeHTTP(sw, r)

		route := r.Pattern
		if route == "" {
			route = "unmatched"
		}
		m.requestsTotal.WithLabelValues(r.Method, route, strconv.Itoa(sw.status)).Inc()
		m.requestDuration.WithLabelValues(r.Method, route).Observe(time.Since(start).Seconds())
	})
}

type statusRecorder struct {
	http.ResponseWriter
	status int
}

func (w *statusRecorder) WriteHeader(status int) {
	w.status = status
	w.ResponseWriter.WriteHeader(status)
}
```

`r.Pattern` — not `r.URL.Path` — is the label. Go 1.22+'s `http.ServeMux` records which registered
pattern actually matched a request onto `r.Pattern` (`"GET /orders/{id}"`, not `/orders/<the
actual uuid>`). Using the raw path instead would give `GET /orders/<uuid>` its own, permanently
distinct label value for *every order ever created* — exactly the unbounded-cardinality mistake
that turns a small Prometheus instance into a struggling one. A test proves the label is actually
bounded:

```go
func TestMetricsMiddlewareLabelsByRoutePatternNotRawPath(t *testing.T) {
	m := observability.NewMetrics()

	mux := http.NewServeMux()
	mux.HandleFunc("GET /orders/{id}", func(w http.ResponseWriter, r *http.Request) {
		w.WriteHeader(http.StatusOK)
	})
	handler := m.Middleware(mux)

	req := httptest.NewRequest(http.MethodGet, "/orders/11111111-1111-1111-1111-111111111111", nil)
	handler.ServeHTTP(httptest.NewRecorder(), req)

	rec := httptest.NewRecorder()
	m.Handler().ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/metrics", nil))
	body := rec.Body.String()

	if !strings.Contains(body, `route="GET /orders/{id}"`) {
		t.Errorf("metrics output missing route=%q label, got:\n%s", "GET /orders/{id}", body)
	}
	if strings.Contains(body, "11111111-1111-1111-1111-111111111111") {
		t.Error("metrics output contains the raw order ID — route should be the pattern, not the path, to avoid unbounded label cardinality")
	}
}
```

`statusRecorder` here looks identical to `statusWriter` in `transport/api/middleware.go` from
[chapter 10](10-api-layer.md) — that's not an oversight. They live in different packages for
different, narrow reasons (this one is `observability`'s own concern; that one is `api`'s), and
sharing five lines isn't worth a cross-package dependency just to avoid typing them twice.

## Tracing: spans that survive tracing being turned off

Create `observability/tracing.go`. The constructor is where the interesting decision lives:

```go
package observability

import (
	"context"
	"fmt"
	"net/http"

	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp"
	"go.opentelemetry.io/otel/sdk/resource"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	semconv "go.opentelemetry.io/otel/semconv/v1.24.0"
)

// Tracer embeds the SDK provider rather than holding it in a field. The
// difference matters below, in "Spans around the dependencies": the
// embedding promotes the provider's Tracer method, so *Tracer implements
// trace.TracerProvider and is the node every generated wrapper depends on.
type Tracer struct {
	*sdktrace.TracerProvider
}

func NewTracer(cfg Config) (*Tracer, error) {
	ctx := context.Background()
	res, err := resource.New(ctx, resource.WithAttributes(
		semconv.ServiceName("servoorders"),
	))
	if err != nil {
		return nil, fmt.Errorf("observability: resource: %w", err)
	}

	opts := []sdktrace.TracerProviderOption{sdktrace.WithResource(res)}
	if cfg.OTLPEndpoint != "" {
		exporter, err := otlptracehttp.New(ctx,
			otlptracehttp.WithEndpoint(cfg.OTLPEndpoint),
			otlptracehttp.WithInsecure(),
		)
		if err != nil {
			return nil, fmt.Errorf("observability: otlp exporter: %w", err)
		}
		opts = append(opts, sdktrace.WithBatcher(exporter))
	}

	return &Tracer{TracerProvider: sdktrace.NewTracerProvider(opts...)}, nil
}

func (t *Tracer) Stop(ctx context.Context) error {
	return t.Shutdown(ctx)
}
```

Notice there's no `Init` here, even though `postgres.Store`, `redis.Cache`, and
`natsbroker.Publisher` all have one. That's deliberate, and it's a real ordering constraint worth
understanding rather than a style choice: `api.Server`'s own constructor needs a fully-working
`*Tracer` immediately, to wrap its handler with tracing middleware — and servo only guarantees a
*dependency's constructor* has already returned by the time a *dependent's* constructor runs, not
that its `Init` has too. `Init` calls all happen later, together, in one `errgroup`. Splitting this
into `New` (build) + `Init` (start) the way `postgres.Store` does would hand `api.Server` a
`*Tracer` whose provider field is still `nil`. Doing all the setup inside `New` itself — the same
shape a generated config loader uses too — sidesteps the whole question.

The `if cfg.OTLPEndpoint != ""` branch is the other thing worth noticing: with no endpoint
configured, `NewTracer` still returns a fully working `*Tracer` — spans are created, sampled, and
given real trace and span IDs — they're just never exported anywhere. Tracing is opt-in this way
on purpose; a service shouldn't refuse to start just because nobody configured a trace backend for
it:

```go
func TestNewTracerWithNoEndpointStillCreatesSpans(t *testing.T) {
	tracer, err := observability.NewTracer(observability.Config{OTLPEndpoint: ""})
	if err != nil {
		t.Fatalf("NewTracer: %v", err)
	}
	t.Cleanup(func() { tracer.Stop(context.Background()) })

	var sawSpanContext bool
	mux := http.NewServeMux()
	mux.HandleFunc("GET /orders/{id}", func(w http.ResponseWriter, r *http.Request) {
		sawSpanContext = trace.SpanContextFromContext(r.Context()).IsValid()
	})
	handler := tracer.Middleware(mux)
	handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/orders/abc", nil))

	if !sawSpanContext {
		t.Error("expected a valid span context inside the handler even with OTLPEndpoint unset — spans are still created, just never exported")
	}
}
```

One more thing worth testing explicitly, because the opposite assumption is an easy one to make:
`otlptracehttp.New` doesn't dial the endpoint at construction time at all — export happens later,
asynchronously, in the background. `NewTracer` succeeds immediately even against a garbage address:

```go
func TestNewTracerRejectsAnUnreachableEndpointOnlyAtExportTimeNotConstruction(t *testing.T) {
	tracer, err := observability.NewTracer(observability.Config{OTLPEndpoint: "127.0.0.1:1"})
	if err != nil {
		t.Fatalf("NewTracer: %v, want it to succeed even with an unreachable endpoint", err)
	}
	tracer.Stop(context.Background())
}
```

Last, the middleware — reusing the same route-not-path decision from the metrics middleware above,
for a span name instead of a label:

```go
func (t *Tracer) Middleware(next http.Handler) http.Handler {
	return otelhttp.NewHandler(next, "http.request",
		otelhttp.WithTracerProvider(t.TracerProvider),
		otelhttp.WithSpanNameFormatter(func(operation string, r *http.Request) string {
			if r.Pattern != "" {
				return r.Pattern
			}
			return operation
		}),
	)
}
```

## Spans around the dependencies, without instrumenting them

The request span above answers "was this request slow". It does not answer "was it the database,
the cache, or NATS", because none of those three is instrumented — and the honest options for
instrumenting them are both bad. Reaching into `postgres.Store` to start a span in every method
ties the repository to a tracing library it has no other reason to know about. Writing a
decorator that implements `repository.OrderRepository`, starts a span, and delegates is clean,
but it is the kind of code that is complete the day it is written and silently short one method
after the next refactor: add `Archive` to the interface and the compiler makes you add it to the
decorator, but nothing makes you add the span.

The decorator is the right shape; the problem is maintaining it by hand. servo generates it. The
directive injector from [chapter 13](13-directive-transport.md) carries four lines its spec has
had since then, and this is what they do:

```go
servo.Trace[repository.OrderRepository](servo.Expected(domain.ErrNotFound)),
servo.Trace[repository.UserRepository](servo.Expected(domain.ErrNotFound)),
servo.Trace[cache.OrderCache](servo.Expected(cache.ErrMiss)),
servo.Trace[broker.EventPublisher](),
```

For each interface, `servo generate` emits a type into `cmd/ordersservo/servo_gen.go` that
implements it, and hands that type to every consumer of the interface in place of the
implementation the interface resolved to — the same `postgres.Store` as before, now one layer
down. Here is one method of the generated wrapper for the cache, verbatim:

```go
func (t *tracedOrderCache) Get(ctx context.Context, id uuid.UUID) (*domain.Order, error) {
	ctx, span := t.tracer.Start(ctx, "cache.OrderCache/Get")
	defer span.End()
	r0, err := t.inner.Get(ctx, id)
	if err != nil && !errors.Is(err, cache.ErrMiss) {
		span.RecordError(err)
		span.SetStatus(codes.Error, err.Error())
	}
	return r0, err
}
```

Three decisions in that method are worth seeing rather than taking on faith. The span's context
is what `t.inner.Get` receives, so anything the implementation starts — a `pgx` query span, if you
ever add one — nests beneath it, and the whole call nests beneath the request span
`Tracer.Middleware` opened, because that is the context the handler was given. The error check
names `cache.ErrMiss`: a miss is a result, not a failure, and without the `servo.Expected` line
every miss would be a red span and the error rate a trace backend computes from spans would be
meaningless. And the method set is regenerated from the interface every time — the `Archive`
method from the paragraph above gets its span the moment `servo generate` runs.

The wrapper is why `Tracer` embeds `*sdktrace.TracerProvider` instead of holding it in a field.
Every generated wrapper takes `trace.TracerProvider` as an ordinary dependency — an interface,
resolved like any other — and the embedding is what makes `*observability.Tracer` implement it:
the SDK's `Tracer` method is promoted, `Tracer` is the one implementation in the module, and it
auto-binds. There is no `otel.SetTracerProvider` anywhere in this service, for the reason the
[logger](#why-the-logger-is-a-node-and-not-a-call-at-the-top-of-main) is a node rather than a
call at the top of `main`: a global would be an ordering assertion nothing checks, and the
dependency is a fact servo orders construction by.

What stays out of the generated file is as deliberate as what goes in. `postgres.Store`,
`redis.Cache` and `natsbroker.Publisher` did not change, and `internal/repository` still imports
no tracing library — the wrapper lives in the injector package, and the OpenTelemetry imports it
needs are this module's, not servo's. The implementation keeps its own `Init` and `Stop`; the
wrapper has no lifecycle, so nothing is connected or closed twice. And `NewTestApp` wraps the
gomock mocks through the same generated type, so the test in `cmd/ordersservo/app_test.go`
exercises every wrapper without knowing they exist.

Two things it cannot do, both by design. A constructor that takes `*postgres.Store` directly gets
the store, not the wrapper — tracing is a property of the interface edge, which is one more
reason the service layer depends on `repository.OrderRepository` rather than on Postgres. And the
wrapper is spans only: the Prometheus metrics above stay where they are. The full contract,
including every diagnostic, is at [Traced interfaces](../reference/tracing.md).

## Wire both into api.Server

`New` grows two more parameters — `sessions` and `log` are already there, from
[chapter 15](15-scoped-instances.md) and [chapter 10](10-api-layer.md) — and the middleware
chain grows two more layers:

```go
func New(
	cfg Config,
	orders *service.OrderService,
	authSvc *service.AuthService,
	issuer *auth.Issuer,
	metrics *observability.Metrics,
	tracer *observability.Tracer,
	sessions session.Sessions,
	log *observability.Logger,
) *Server {
	// ... routes unchanged ...

	handler := loggingMiddleware(log, mux)
	handler = metrics.Middleware(handler)
	handler = tracer.Middleware(handler)
	handler = recoverMiddleware(log, handler)

	s.http = &http.Server{Addr: cfg.HTTPAddr, Handler: handler}
	return s
}
```

`/metrics` can't be reached the same way `/healthz` and `/readyz` were in
[chapter 10](10-api-layer.md) — `Metrics` lives *inside* `api.Server`, not on the outer `App` — so
`Server` needs to expose it, and `main.go` reaches for it directly, the same way `app_test.go`
already reaches `app.server` (both files are `package main`):

```go
// transport/api/server.go
func (s *Server) MetricsHandler() http.Handler {
	return s.metrics.Handler()
}
```

```go
// cmd/orders/main.go
adminSrv := admin.New(app.apiConfig.AdminAddr, app, app.server.MetricsHandler())
```

## Try it — logs, metrics, and a real trace in Jaeger

Add Jaeger to `deploy/docker-compose.yml` (it accepts OTLP over HTTP natively, no separate
collector needed):

```yaml
jaeger:
  image: jaegertracing/all-in-one:1.60
  environment:
    COLLECTOR_OTLP_ENABLED: "true"
  ports:
    - "16686:16686" # web UI
    - "4318:4318"   # OTLP over HTTP
```

Start everything, including `OBS_OTLP_ENDPOINT` this time:

```
$ make up
$ POSTGRES_DSN=... REDIS_ADDR=... NATS_URL=... JWT_SECRET=... \
  OBS_OTLP_ENDPOINT=localhost:4318 \
  go run ./cmd/orders
```

Log lines are now structured JSON:

```
{"time":"2026-08-27T14:44:55.548596+02:00","level":"INFO","msg":"request","method":"POST","path":"/auth/login","status":200}
```

After logging in and creating an order, `/metrics` on the admin port shows real data:

```
$ curl -s http://localhost:8081/metrics | grep orders_http_requests_total
orders_http_requests_total{method="POST",route="POST /auth/login",status="200"} 1
orders_http_requests_total{method="POST",route="POST /orders",status="201"} 1
```

And Jaeger (`http://localhost:16686` in a browser, or its query API) has a real trace, with real
semantic HTTP attributes attached automatically by `otelhttp` — nothing hand-instrumented:

```
$ curl -s "http://localhost:16686/api/traces?service=servoorders&limit=1" | python3 -m json.tool
```
```
operation: POST /orders
duration (us): 2470
  http.request.method = POST
  http.response.status_code = 201
  url.path = /orders
```

The span is named `POST /orders` — the route pattern, exactly as configured — not a path with a
UUID baked into a hundred different span names.

Run `cmd/ordersservo` instead of `cmd/orders` and repeat the request, and the same trace gains
children: `repository.OrderRepository/Create`, `cache.OrderCache/Set` and
`broker.EventPublisher/PublishOrderPlaced`, each the duration of one call into the layer below,
each nested under `POST /orders` because the handler's context flowed into the generated wrapper
and out to the implementation. That is the whole promise of the four `servo.Trace` lines: the
question "which of the three was slow" now has an answer in the trace, and nobody instrumented
anything.

## Diagnostics

- **No traces show up in Jaeger even though `OTLPEndpoint` is set correctly** — the SDK batches
  spans and exports on an interval (a few seconds by default), not immediately on every request.
  Give it several seconds after the request before concluding it isn't working; then check the
  service's own logs for OTLP export errors, and confirm Jaeger's OTLP port (`4318`) is actually
  the one the endpoint points at, not its UI port (`16686`).
- **`/metrics` shows a metric with far more label combinations than expected** — almost always a
  label built from something request-specific (a raw path, a user ID, a request ID) rather than a
  bounded set of values. `route` here is safe specifically because `r.Pattern` only ever takes one
  of a handful of registered values, never one per request.
- **Log lines are plain text, not JSON, right at process startup** — a small, known gap: anything
  logged before `NewLogger` runs uses the unconfigured default handler. Nothing in this codebase is
  in that window, because every component that logs depends on the logger and so cannot be built
  first — but a library logging from an `init` function would be, and it is worth knowing the gap
  exists rather than assuming every line is guaranteed structured.

## Do's and don'ts

- **Do** treat "would this label's value be unbounded" as a question to ask before adding any new
  Prometheus label, every time — not just for HTTP routes. A user ID, an order ID, a raw error
  message: all classic ways this goes wrong later.
- **Do** let spans get created even when there's nowhere to export them. A service that behaves
  differently depending on whether tracing infrastructure exists is harder to reason about, not
  easier.
- **Don't** log a full request or response body at `INFO` by default — `loggingMiddleware` only
  ever logs method, path, and status, deliberately, going back to
  [chapter 10](10-api-layer.md#dos-and-donts).
- **Don't** reach for a global metrics/tracer registry out of habit. It's the more common pattern
  in small single-instance programs, but it's also exactly what makes two `*App`s (or an `*App` and
  a `NewTestApp`) in the same process collide.

## Next

[Chapter 17: Resilience](17-resilience.md) — a circuit breaker around the cache, and a rate
limiter in front of the API.