Observability

Three questions come up about a service in production: what happened to this request, how slow is this endpoint, and which log lines belong together. Muzak answers all three without a dependency. Tracing records a span per request and carries the W3C trace context across services, the access log and the request logger carry the trace, and a request observer feeds whatever metrics library you already use.

Every part of it is off until it is configured, and off means free: no header is parsed, no identifier is drawn and nothing is allocated on any request.

Turning tracing on

Tracing is on when AppOptions.Tracing names a Tracer. The one most services want is the OTLP exporter in muzak.dev/framework/otlp, which sends spans to any OpenTelemetry collector (Jaeger, Tempo, Honeycomb, Grafana Cloud, Datadog's OTLP intake and so on).

exporter, err := otlp.New(otlp.Options{
    Endpoint:    settings.OTLPEndpoint,
    ServiceName: "shop",
    Headers:     otlp.Headers{"Authorization": "Bearer " + settings.OTLPToken},
    Gzip:        true,
})
if err != nil {
    log.Fatal(err)
}

app := muzak.New(muzak.AppOptions{
    Title:   settings.AppName,
    Tracing: muzak.TracingOptions{Tracer: exporter},
})

type Settings struct {
    // OTLPEndpoint is the collector's OTLP/HTTP base URL. Spans are posted
    // to it followed by /v1/traces.
    OTLPEndpoint string `env:"OTLP_ENDPOINT" default:"http://localhost:4318"`
    // OTLPToken authenticates to a hosted collector. The exporter sends it
    // as a header and never logs it; secret keeps it out of a config error.
    OTLPToken string `env:"OTLP_TOKEN" secret:"true"`
}

The exporter is also a lifecycle component, and naming it as the Tracer is enough for the application to start it before the first request and stop it after the last. Stopping it sends what is still queued. Registering it with WithLifecycle as well does no harm; it is started once. See Lifecycle for the order components start and stop in.

Sampler, Parent and RecordUserAgent only mean something beside a Tracer, so setting any of them without one is a build error rather than an option silently ignored.

The server span

Every request gets one span, of kind server, named after its method and route template:

GET /orgs/{org_id}/apps/{app_id}/keys

Never after its path. The path carries identifiers, which makes one span name per request, and often personal data. A request no route answers, a 404, is named after its method alone. A method no standard defines, which a client can make up per request, is written HTTP in the name unless a route registered for that very method answered it. A handler mount answers every method a client sends, so through one such a method is HTTP /debug/pprof, named after the mount's prefix. A HEAD that a GET route answers is named after that route.

The span carries the OpenTelemetry HTTP attributes:

url.path and url.query are deliberately absent, for the reason the name avoids the path. A handler that wants them on a span adds them itself.

When it is an error

A failure the log records is added to the span as an exception event with exception.type and exception.message, carrying the same text the log line does and nothing more. A panic is recorded as type panic with the framework's own message; its value and stack stay in the log.

When it ends

After the response has been written. For an event stream that is when the stream ends, and for a WebSocket when the connection closes, so the span measures how long the client was served (see Server-Sent Events and WebSockets for what ends each). A handler that takes the connection over ends its span when it returns.

Trace context

A request carrying a traceparent continues that trace: the server span gets the same trace identifier, records the caller's span as its parent, and inherits its sampling decision. The tracestate travels with it. Both are read strictly, as the W3C recommendation writes them:

• traceparent version 00 is exactly 55 characters of lowercase hex and dashes. Uppercase hex, an identifier of all zeroes, version ff and two traceparent headers are refused, and the request starts a new trace.
• A later version is read forward-compatibly: its first 55 characters as version 00, and anything after them must start a new field with a dash. It is written onward as version 00.
• tracestate is refused whole, and the parent kept, when it has more than 32 members, is longer than 512 bytes, repeats a key, or has one key or value outside the grammar. It is never read unless the traceparent was accepted.

Identifiers this server draws come from crypto/rand, so nobody who sees one trace can guess the next.

Whose trace to believe

A client choosing its own trace identifier can attach its requests to someone else's trace, and a client setting the sampled flag decides for you that every one of its requests is recorded, whatever your Sampler says. Inside a system that traces end to end that is what you want; at the edge it is not, and the default believes every caller. A service the internet reaches directly sets Parent:

muzak.AppOptions{
    ClientIP: muzak.ClientIPOptions{TrustedProxies: []string{"10.0.0.0/8"}},
    Tracing: muzak.TracingOptions{
        Tracer: exporter,
        Parent: muzak.TraceParentFromTrustedProxies,
    },
}

A traceparent that is not believed is not even parsed.

TraceParentFromTrustedProxies is only as good as the proxy. Many load balancers pass a client's traceparent on unchanged, and with it the client's choice, so the proxy must replace or remove the header; where it cannot, use TraceParentIgnore. Behind a Proxy covers naming the proxies in ClientIP.TrustedProxies.

Sampling

A trace this server starts is sampled unless a Sampler says otherwise. A trace it continues keeps its caller's decision, and the sampler is not asked.

muzak.TracingOptions{
    Tracer:  exporter,
    Sampler: muzak.SampleRatio(0.1),
}

SampleRatio decides from the trace identifier, so every service sampling at the same ratio makes the same decision for the same trace. A request that is not sampled still has identifiers, which are propagated with the sampled flag cleared and written to the logs, but the Tracer is never called for it.

A Sampler is a function of the request and the trace identifier, so it can also leave out requests nobody wants a span for, such as a platform's health probes:

ratio := muzak.SampleRatio(0.1)
sampler := func(r *http.Request, trace muzak.TraceID) bool {
    if r.URL.Path == muzak.DefaultLivenessPath || r.URL.Path == muzak.DefaultReadinessPath {
        return false
    }
    return ratio(r, trace)
}

Calling another service

A client built with muzak.NewClient carries the trace along by itself: its default Propagate, DefaultPropagate, writes the current span as the parent beside the request identifier, and leaves a traceparent you set alone. See HTTP Client. Any other client calls InjectTraceContext:

func ChargeCard(ctx *muzak.Context, in schemas.ChargeIn) (schemas.ChargeOut, error) {
    req, err := http.NewRequestWithContext(ctx.Context(), http.MethodPost, paymentsURL, body)
    if err != nil {
        return schemas.ChargeOut{}, err
    }
    muzak.InjectTraceContext(req.Context(), req.Header)
    // ...
}

InjectTraceContext writes the current span as the parent, with its sampling decision and its tracestate, and removes a tracestate already in the headers when the trace has none. A context that carries no span, which is every context when tracing is off, leaves the headers as they are. SpanContextFromContext returns the same identity for anything that is not an HTTP request: a message published to a queue, a row in an audit table.

A tool call made through the application's MCP endpoint is served in-process as a child of the MCP request's span, so the route that answers it joins the same trace.

Spans of your own

func GetOrder(ctx *muzak.Context, in schemas.OrderParams) (schemas.OrderOut, error) {
    // Add what the handler knows to the server span.
    muzak.SpanFromContext(ctx.Context()).SetAttributes(slog.String("tenant.id", in.Tenant))

    // A child span, recorded through the same Tracer.
    queryCtx, span := muzak.StartSpan(ctx.Context(), "load order", muzak.SpanKindClient,
        slog.String("db.system.name", "postgresql"))
    defer span.End()

    order, err := orders.Load(queryCtx, in.ID)
    if err != nil {
        span.SetStatus(muzak.SpanStatusError, "the order could not be loaded")
        return schemas.OrderOut{}, err
    }
    return order, nil
}

Attributes are slog.Attr, so what a handler logs and what it records on a span are built the same way. With tracing off, StartSpan returns the context unchanged and a span that records nothing, without allocating, so code written to trace costs nothing where it is not configured. The server span is the framework's to end; a span you start is yours.

Logs that join the trace

With tracing on, the access log and every record written through ctx.Logger() carry the trace and the server span:

{"level":"INFO","msg":"GET /orders/42","scope":"Request","status":200,"duration":412000,"bytes":181,"request_id":"0611f4b2...","route":"/orders/{id}","trace_id":"0af7651916cd43dd8448eb211c80319c","span_id":"b7ad6b7169203331"}

The keys are muzak.TraceIDKey and muzak.SpanIDKey. An unsampled request logs its identifiers too, which is how a log line is still joined to the requests around it. See Logging.

Request metrics

AppOptions.Observer is told about every request once its response is written. It is the hook a Prometheus histogram or an OpenTelemetry meter is fed from, and Muzak needs no dependency on either.

// RequestMetrics records a histogram of request durations per endpoint.
type RequestMetrics struct {
    duration *prometheus.HistogramVec
}

func (m *RequestMetrics) ObserveRequest(o muzak.RequestObservation) {
    m.duration.WithLabelValues(o.Method, o.Route, strconv.Itoa(o.Status)).
        Observe(o.Duration.Seconds())
}

app := muzak.New(muzak.AppOptions{
    Title:    settings.AppName,
    Observer: core.NewRequestMetrics(prometheus.DefaultRegisterer),
})

Every field a metric could be labelled by has a bounded set of values, so labelling by all of them cannot grow a time series per request. The path is not in the observation at all.

The observer is called exactly once per request: a 404, a 405, a handler that failed or panicked, a response that was aborted, an event stream when it ends and a WebSocket when it closes. Health probes are answered after it, so each one is observed, and traced, as a request no route answered: a metric labelled by route counts them under the empty route, and a Sampler can leave them out of the trace by path, as above. It runs on the request's goroutine before the connection is handed back, so keep it quick and safe for concurrent use. muzak.RequestObserverFunc adapts a plain function.

A Tracer or observer that panics

Both run on the request path, above panic recovery. A Tracer that panics costs the request its span, a sampler that panics leaves the trace unsampled, and an observer that panics misses one observation; each is logged with its stack, and the client sees nothing.

The OTLP exporter

muzak.dev/framework/otlp sends spans over OTLP/HTTP with the JSON encoding, and imports nothing but the standard library and the framework.

What it promises a request

Nothing it does is waited on. A span that ends goes into a bounded queue; when the queue is full the span is dropped and counted, never waited for. One goroutine sends the batches.

What it promises the collector

• A batch answered with 429, 502, 503 or 504, or that could not be delivered at all, is retried with exponential backoff and jitter. A Retry-After that asks for longer than the backoff lengthens the wait, up to RetryMaxInterval; one that asks for less, zero included, never shortens it, so a collector cannot have a batch sent again without pause. Every other answer, every other 4xx and 5xx included, is final.
• An answer is read up to 64 KiB, so a collector that sends more holds nothing.
• A redirect is not followed, because it would carry the headers, credentials included, to wherever it pointed. It counts as a refusal.
• A partial success, a collector accepting the request and rejecting some spans in it, is counted and its message logged.

Stopping

Stop sends what is queued within its context's deadline. When the deadline passes, the request in flight is abandoned, nothing more is sent, and Stop returns an error saying how many spans were lost. Either way it returns only once the exporter's goroutine has exited and, for an exporter on a client of its own, that client's idle connections are closed. Spans the collector refused are logged and counted, but are not an error of Stop's. Calling Stop again returns at once. Flush sends what is queued without stopping, and returns otlp.ErrNotRunning for an exporter that is not running.

Knowing what it did

stats := exporter.Stats()
// stats.Exported: accepted by the collector
// stats.Dropped:  never sent (queue full, stopped, or out of time at shutdown)
// stats.Failed:   sent and refused, given up on, or rejected one by one
// stats.Queued:   waiting

Drops are logged at most once per BatchInterval, with the count, however many there are.

Bounds on one span

A span is your code's to fill, so it is bounded: 128 attributes, 128 events with 128 attributes each, strings and names cut to 4 KiB, lists to 128 elements, nesting to four levels, and 64 KiB in all. The 64 KiB counts every value a span keeps, not only its text, so a list of numbers or of empty strings is charged for what it occupies. What does not fit is dropped and counted in droppedAttributesCount and droppedEventsCount, which is how OpenTelemetry reports a limit being reached. The queue's memory is therefore bounded by QueueSize times about 64 KiB: the span's own name, status description and tracestate are held beside the budget, which adds a few KiB at most.

What it does not do

It does not read the OTEL_EXPORTER_OTLP_* environment variables, speak gRPC or protobuf, or export metrics or logs. Request metrics are the observer's.

Bringing another tracer

Tracer and Span are small interfaces, so an adapter to another SDK is a short file.

type Tracer interface {
    StartSpan(ctx context.Context, start muzak.SpanStart) muzak.Span
}

type Span interface {
    SetName(name string)
    SetAttributes(attrs ...slog.Attr)
    AddEvent(name string, attrs ...slog.Attr)
    SetStatus(code muzak.SpanStatusCode, description string)
    End()
}

Muzak decides a span's identity before the Tracer sees it: SpanStart.SpanContext already holds identifiers drawn from crypto/rand, and those are what is propagated and logged. A Tracer records them rather than choosing its own. StartSpan runs on the request's goroutine and is only called for a sampled trace; it must be safe for concurrent use and must not block on the network. A Tracer or an observer that also implements Lifecycle is started and stopped with the application.

Limits

• The default Parent, TraceParentAccept, lets any client choose its trace and force its requests to be sampled. Set TraceParentFromTrustedProxies or TraceParentIgnore on a service the internet reaches, as above.
• An application that failed to build answers every request with a 500 ahead of its chain, so those requests are neither traced nor observed. Run refuses to start such an application; this only matters when it is served through ServeHTTP.
• One exporter belongs to one application. Named as the Tracer of two, it is stopped by the first one to shut down, and the other's spans are not sent after that. Build one per application.

Where to go next

Logging covers the access log and the request logger the trace is written to, Behind a Proxy covers naming the proxies whose traceparent is believed, HTTP Client covers the client that carries the trace to the next service, Middleware covers where the tracing middleware sits in the chain, and Lifecycle covers how the exporter is started and stopped.