Observability¶
Three layers report what the client is doing: logging, metrics and tracing. All of them sit above the resilience layers in the chain, so what they describe is the logical call the caller made — retries and their backoff included — not an individual network attempt.
Turning layers on¶
tracing_enabled, metrics_enabled and logging_enabled on the settings
object toggle the three layers; ObservabilityConfig is the same choice for a
hand-built chain. Two rules govern what actually ends up in the chain:
- Metrics need a registry.
metrics_enabled=Truewith no registry at all would record nothing, so the layer is left out entirely and a warning is logged — "no metrics" is visible in the chain instead of being a silent hop. A registry reaches the factory three ways, nearest wins:create_client(metrics=...)for one client,GrpcClientFactory(metrics=...)for every client and the pool it creates,settings.metrics_registryfor settings objects that carry one. The shipped collector is the usual value. - A layer that cannot work is announced, not silently added. With
tracing_enabled=Truebut no[tracing]extra, the interceptor is omitted and the omission logged.
The kit never talks to Prometheus or OpenTelemetry directly: metrics go
through GrpcClientMetricsProtocol (record_request, record_inflight_delta,
record_pool_stats), so any backend — or a test double — satisfies it.
Logging¶
One record per logical call, written once the call has an outcome, to the
logger grpc.client.<service_name>. At DEBUG a second record marks the start;
the fields are built only when the logger is actually enabled for DEBUG, since
this is a hot path.
Every record carries a freshly built extra mapping, so nothing leaks between
records of the same call:
| Field | On | Value |
|---|---|---|
grpc.service, grpc.method |
every record | The configured service name and the full method path |
request_id |
when present | From request-id or x-request-id in the call metadata |
grpc.metadata |
start (DEBUG) | The metadata with sensitive values replaced by *** |
grpc.request |
start (DEBUG) | Only with log_request_payload; <stream_request> for a streaming request |
grpc.duration_ms, grpc.status |
terminal | How long the call took, and how it ended |
grpc.error |
failures | The gRPC details string |
grpc.response |
success | Only with log_response_payload, and never for a stream |
grpc.sensitive |
sensitive methods | True |
Payloads are truncated to 1000 characters and are off by default; they are
only reachable through a hand-built ObservabilityConfig.
The severity of the terminal record follows the outcome:
- OK →
INFOby default;success_log_levellowers it. One line per successful RPC is a flood at high QPS — a client doing 10k calls a second writes 10k lines a second about nothing going wrong — so high-volume clients setsuccess_log_level=logging.DEBUGand keep the failures. - Cancelled →
INFO, statusCANCELLED. A caller abandoning a response stream arrives asGeneratorExitand is reported here too, so no call goes unaccounted for. - Refused by the open circuit breaker →
WARNING, one line per rejection. Rejections are the breaker doing its job while the circuit recovers, not fresh failures: reporting each asERRORwould bury the handful of genuine state-transition records under thousands of identical lines. INTERNAL,UNKNOWN,DATA_LOSS, or an error carrying no code →logger.exception, with the traceback: these point at a broken callee, or at us.- Any other gRPC status →
logger.errorwithout a traceback. ANOT_FOUNDis an expected outcome and does not deserve a stack trace.
A logger that will emit nothing costs nothing: when the logger's level is
above WARNING the interceptor skips metadata normalization and record
assembly entirely, so leaving the layer in the chain is free in a process that
has client logging turned off.
A streaming call says "stream" where a unary one says "call", and its record lands when the stream ends.
Redaction covers the usual credential-bearing headers by default
(authorization, cookie, x-api-key, token, password, …);
sensitive_headers replaces that set. Whole methods can be marked sensitive
too, by exact name or by regex — such a call logs no metadata, no payloads and
no error details, only that it happened and how it ended.
Metrics¶
Three measurements per call, recorded through the registry:
| Metric | Type | Meaning |
|---|---|---|
grpc_client_requests_total |
Counter | One increment per finished call |
grpc_client_request_duration_seconds |
Histogram | The RPC as the caller experienced it |
grpc_client_requests_in_flight |
Gauge | Calls currently running |
Labels are service, method, rpc_type, status and grpc_code.
status is one of:
success— the call completed withOK;error— the server (or the wire) failed it;rejected— the local circuit breaker refused it without touching the network. Kept apart fromerroron purpose: during an incident the first question is "is the breaker open, or is the backend down?", and a shared label pair would make that unanswerable on a dashboard;cancelled— the caller cancelled or abandoned it.
service and method are parsed from the method path, so
/orders.v1.Orders/Export becomes service="Orders", method="Export"; set
enable_method_label=False — on ObservabilityConfig or as
enable_method_label on your settings object — to collapse method to
total when a service has thousands of methods and cardinality matters.
The in-flight gauge is incremented before the call and decremented in a
finally, so it is balanced however the call ends — drained, failed,
cancelled, or abandoned mid-stream. Every RPC that was created is counted
exactly once, which is what keeps the counter and the gauge from drifting
apart. An exception raised by the registry itself is caught and logged: a
metrics hiccup never fails the call it was measuring.
Pool statistics¶
record_pool_stats(active_channels, idle_targets) is reported by the
channel pool whenever it changes:
active_channels counts pooled channels, idle_targets counts the distinct
addresses they lead to (one address can back several channel identities).
The factory's metrics= and settings.metrics_registry feed this
independently of metrics_enabled.
The shipped collector¶
GrpcClientMetrics (grpc_client_kit.metrics, the metrics extra) is the
Prometheus implementation of the protocol — and of the two extension
protocols below, so retries and the breaker are covered by the same instance:
| Metric | Type | Labels |
|---|---|---|
grpc_client_requests_total |
Counter | service, method, rpc_type, status, grpc_code |
grpc_client_request_duration_seconds |
Histogram | service, method, rpc_type |
grpc_client_requests_in_flight |
Gauge | service, method, rpc_type |
grpc_client_pool_channels, grpc_client_pool_targets |
Gauge | — |
grpc_client_retries_total |
Counter | service, method, grpc_code |
grpc_client_circuit_breaker_state |
Enum (closed / open / half-open) |
method |
grpc_client_circuit_breaker_rejections_total |
Counter | method |
from grpc_client_kit import GrpcClientFactory
from grpc_client_kit.metrics import get_grpc_client_metrics
factory = GrpcClientFactory(settings=settings, metrics=get_grpc_client_metrics())
The shape is deliberately grpc-server-kit's: GrpcServerMetrics registers
grpc_requests_total{service, method, status, grpc_code} and
grpc_request_duration_seconds{service, method} with the same
DEFAULT_GRPC_BUCKETS, and the client's series carry the same label names in
the same order with rpc_type added after method. A dashboard therefore
joins the caller's and the callee's request counters on the four shared
labels and compares the two latency histograms bucket for bucket — which is
the reason the buckets and the label order are fixed here rather than left to
every service. prefix="myapp" puts a prefix in front of every name.
Prometheus registers a metric name once per registry, so a second
GrpcClientMetrics() on the default registry raises ValueError — what a
test suite runs into when it rebuilds a container per test.
get_grpc_client_metrics(prefix=None, buckets=None) caches one instance per
prefix and hands it back on every later call; it raises ValueError when the
same prefix is asked for with different buckets, since silently keeping the
old ones would record latencies into the wrong bounds. A test that wants
isolation instead passes GrpcClientMetrics(registry=CollectorRegistry()).
The Dishka provider calls the getter for
you.
Opting into retry and breaker visibility¶
The request metrics sit above the retry layer and record one entry per logical call, so three wire attempts collapsing into one success look like a single request — a retry storm is invisible through them by construction. Two optional extension protocols close that gap; a registry opts in simply by implementing the methods:
| Protocol | Method | Told about |
|---|---|---|
RetryMetricsProtocol |
record_retry(service, method, attempt, grpc_code) |
Every scheduled retry, the moment it is scheduled |
CircuitBreakerMetricsProtocol |
record_circuit_state(method, state) |
Every state transition, by name (closed / open / half-open) |
record_circuit_rejection(method) |
Every call the open circuit refused locally |
The kit checks for these once, with isinstance, when the chain is built — a
registry that implements only the base protocol is never poked with methods it
does not have. Live snapshots are also available without metrics at all:
GrpcClient.circuit_breaker_states() and
GrpcClientFactory.circuit_breaker_states() return the current state of every
breaker, per target and method.
Tracing¶
One CLIENT span per logical call, named after the full method, with the
OpenTelemetry semantic-convention attributes rpc.system ("grpc"),
rpc.service (the configured service name) and rpc.method. A failed call
also carries rpc.grpc.status_code.
The parent is the span active in the current context — typically the
server span of the request being handled — and is deliberately not extracted
from the outgoing metadata: nothing has written a traceparent there yet at
that point, because this interceptor is what writes it. Extracting would yield
an empty context and quietly turn every client span into a root span.
Installing opentelemetry-api without configuring an SDK — the default state
of the [tracing] extra — hands out non-recording spans, and the interceptor
checks for exactly that: a non-recording span skips the attributes, the status
bookkeeping and the metadata rebuild entirely, so the layer costs next to
nothing until a real tracer provider is configured.
Propagation runs the other way: traceparent, tracestate and baggage are
injected into the outgoing metadata from the new span, replacing any stale
values the caller left under those keys, so the callee continues the same
trace.
A span is red only for statuses that mean something went wrong —
INTERNAL, UNKNOWN, UNAVAILABLE, DEADLINE_EXCEEDED, UNAUTHENTICATED,
PERMISSION_DENIED, DATA_LOSS. Ordinary application outcomes such as
NOT_FOUND leave the span OK with the code recorded as an attribute, so they
do not inflate error rates in the tracing backend. The span closes when the
unary response arrives or the response stream ends, never when the call was
merely created.
Without the [tracing] extra the interceptor is a documented pass-through:
calls run untouched, no metadata is added, no span is produced, and the
degradation is announced once per instance.