Observability: spans, metrics, logs

English translation of docs/observability.md (the Russian text is the original). A user guide to TZ Р7 and [С §15.5]. Decisions: D-5240..D-5259 in docs/decisions.md; the design is in docs/ARCHITECTURE.md, section "Observability".

Without configuration nothing is exported and nothing is opened: spans are not recorded (a single atomic flag is checked), there is no metrics port. An in-process rpc call stays within 0.2–0.3 µs.

Quick start#

# spans, metrics and logs to an OpenTelemetry Collector over gRPC
OTEL_EXPORTER_OTLP_ENDPOINT=http://collector:4317 OTEL_SERVICE_NAME=shop ./shop

# Prometheus: the page http://127.0.0.1:9464/metrics
./shop --metrics-listen 127.0.0.1:9464

The address: http://host:4317 (no TLS, h2c), https://host:4317 (TLS, system root certificates) or host:port; the default port is 4317. A bare --metrics-listen 9464 listens on 127.0.0.1 only; to open it to the outside specify 0.0.0.0:9464 (the page is not protected — put it behind a firewall).

Spans#

The following spans are created automatically:

The status ERROR is set for any rpc outcome except ok (including a domain error; the message is the name of the outcome), for the HTTP server on a 5xx code, for the HTTP client on 4xx/5xx and when there is no response.

Context propagation#

• gRPC: the metadata header traceparent (W3C Trace Context, version 00); compatible with all OpenTelemetry SDKs. The former x-oxl-trace is still sent and read.
• HTTP (std.http): the server reads the request's traceparent, the client adds it to outgoing requests.
• ctx.traceId (32 hex digits, the same in all processes) and ctx.spanId (16 hex digits, the span in which the code is running) are available in rpc handlers.
• Child tasks (spawn, scope) inherit the current span.

Sampling#

The decision is taken once, at the root of the trace, by the hash of the traceId: all processes that see one identifier decide identically; after that the parent's decision (the flag 01/00 in traceparent) is respected by everybody. A call with a dropped trace still carries the traceId and ctx.spanId, but the spans are not recorded.

• @trace(sample: 0.1) on an rpc is the sampling fraction for traces rooted at this rpc; 0.0 — do not trace, 1.0 — always.
• Otherwise — the process fraction: --trace-sample / OXL_TRACE_SAMPLE. The "cluster" value of §15.5 is today the process value (see D-5241, a question to the customer).

Custom spans#

use std.obs { span, metric, log }

fn charge(order: Order) io {
  span.with("charge") {                 // closed on exit, including on a panic
    let s = span.start("antifraud")     // or manually
    s.set("order", "{order.id}")
    s.setInt("amount", order.cents)
    if s.recording() { /* an expensive attribute computation */ }
    s.setError("score too high")          // status ERROR
    s.end()
  }
}

Close spans in the reverse order of opening and in the same task. If tracing is off or the trace is not selected, span.start costs nothing.

Metrics#

let paid = metric.counter("orders_paid_total", help: "Paid orders.", labels: {"shop": "eu"})
paid.inc()
let queue = metric.gauge("queue_length")
queue.set(12.0); queue.dec()
let size = metric.histogram("payload_bytes", buckets: [64.0, 1024.0, 65536.0])
size.observe(300.0)

• The name is a Prometheus name ([a-zA-Z_:][a-zA-Z0-9_:]*); the ending _total is customary for counters. An invalid name or label, or a name already taken by a metric of another kind, is reported once on stderr, and the handle does nothing.
• The same name and labels are the same series. Create the handle once and keep it: the lookup is done under a mutex, the increment is an atomic operation.
• Without buckets a histogram has latency buckets in seconds: 0.0001 … 10.

Built-in metrics (/metrics and OTLP):

The rpc latency is measured for the first 256 calls of a method and then for every 16th (with weight 16); the call counters are exact (D-5254).

The page format is Prometheus text 0.0.4. GET /metrics gives 200, other paths 404, non-GET 405.

Logs#

log.info("order {id} paid") inside an rpc handler or a span carries identifiers:

2026-11-03T15:04:05.250Z INFO  order 42 paid id=42 trace_id=4bf92f3577b34da6a3ce929d0e0e4736 span_id=00f067aa0ba902b7
{"ts":"…","level":"info","msg":"order 42 paid","trace_id":"4bf9…","span_id":"00f0…","fields":{"id":"42"}}

With OTEL_LOGS_EXPORTER=otlp the records also go over OTLP (with trace_id/span_id in the record itself, the fields as attributes).

Export: guarantees and losses#

• The queue is bounded (OTEL_BSP_MAX_QUEUE_SIZE); on overflow new spans are dropped and counted in oxl_telemetry_spans_dropped_total. The hot path never waits for the network.
• Batches are sent by a separate task every OTEL_BSP_SCHEDULE_DELAY or immediately when a batch has accumulated. An unreachable collector does not hinder the program: the batch is dropped and counted, the first three failures are written to stderr.
• On a normal exit (and after SIGTERM, after draining) the rest of the queues is sent synchronously, for no longer than a second per request.

Verification#

• scripts/bench.py --rpc — the latency of an in-process call (with tracing off and with tracing on but sampling dropping the trace).
• ctest telemetry_otlp: two processes, an own mock OTLP collector, checking the common traceId, the parent–child link client → server, /metrics, logs with identifiers and sampling.

Inspector#

--inspect-ui[=addr] (127.0.0.1:8090 by default) opens the cluster state web interface in the node [С III.8]: one built-in page and the JSON API GET /api/<section> (nodes roles config dynconf services actors sagas streams traces logs rights), POST /api/action (header X-Oxl-Inspect: 1). Any node shows the whole cluster: the local data of the other nodes is requested over the inter-node channel. The same API is the gRPC service oxl.Inspect (runtime/proto/oxl/inspect.proto) on the node's port; oxl inspect --cluster host:port brings the page up locally. The trace and log buffers are 64 MB / 15 min per node with a UI (or on all nodes with OXL_INSPECT_BUFFERS=1). Access is the role Admin or inspect (JWT), actions need separate roles, everything is written to oxl.audit; in the dev profile with --insecure-dev the local user is an operator. Decisions: D-6400..D-6410.

Traces from the command line, request journal, A/B#

• oxl trace <traceId> --cluster host:port prints a trace from the node buffers (the traces section of the inspector): the tree of spans by node and the call graph between them.
• oxl trace --record f.oxlrec --cluster host:port --for 60s [--service S] records the incoming unary rpcs of all nodes (method, request, metadata without credentials, user, trace, time, response or error) into a .oxlrec journal (format — docs/oxlrec.md); oxl replay f.oxlrec|<traceId> --cluster host:port sends them again and compares the responses.
• A/B experiments ([С §18.5]): the code learns the variant through ab.variant("name") (std.ab); oxl test --kind ab runs recorded traffic, oxl ab start|status|stop works in a cluster. The built-in variant metrics are latency.p50/p95/p99/mean (handler time, ms) and error_rate; user ones are any std.obs metrics by name. Significance is Welch's t-test for means and a z-test for proportions, p < 0.05 with ≥ 100 requests per variant. Decisions: D-6850..D-6866.

Source: docs/observability.en.md