Skip to content

Commit 0e96ec4

Browse files
lesnik512claude
andauthored
feat: surface drain_timeout on the bundled Prometheus/OTel adapters (#96)
#92 added the drain_timeout recorder event but only the raw recorder seam saw it — the bundled adapters ignored it (forward-compatible) and the docs didn't mention it, so operators got no out-of-the-box metric. Complete the feature: - Prometheus: faststream_outbox_drain_timeout_total counter (consume labels). - OTel: messaging.outbox.drain_timeout meter counter (operation=process). - Docs: observability.md recorder-event table + event set; CLAUDE.md and architecture/metrics.md emission lists. Added PLR0911 to the two adapters' __call__ noqa (one more event branch in the flat event-dispatch dispatch, same shape as the existing C901/PLR0912 suppressions). Tests: test_{prometheus,otel}_drain_timeout_* assert the counter increments. just test -> 518 passed, 100% coverage; just lint clean; mkdocs --strict builds. Co-authored-by: Claude Opus 4.8 (1M context) <[email protected]>
1 parent ad6bd4a commit 0e96ec4

7 files changed

Lines changed: 41 additions & 5 deletions

File tree

CLAUDE.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -174,7 +174,7 @@ Caller owns the `AsyncEngine` — the broker never disposes it. The engine lives
174174

175175
Two complementary seams — **don't collapse them.**
176176

177-
- **Recorder seam** (`OutboxBroker(..., metrics_recorder=...)`): `Callable[[str, Mapping[str, Any]], None]`. Subscriber emits `fetched`, `dispatched`, `acked`, `nacked_retried`, `nacked_terminal`, `lease_lost`, plus `dlq_written` when `dlq_table` is set. Producer emits `published`. Default `_noop_recorder` lets sites fire unconditionally. Every call site is wrapped in `try/except` + DEBUG log. **Recorder must not block** (sync `Counter.inc()` fine; HTTP/StatsD not). `dlq_written` vs `nacked_terminal` divergence detects DLQ misconfiguration.
177+
- **Recorder seam** (`OutboxBroker(..., metrics_recorder=...)`): `Callable[[str, Mapping[str, Any]], None]`. Subscriber emits `fetched`, `dispatched`, `acked`, `nacked_retried`, `nacked_terminal`, `lease_lost`, `drain_timeout` (on a timed-out `stop()` drain), plus `dlq_written` when `dlq_table` is set. Producer emits `published`. The bundled Prometheus/OTel adapters translate every one of these (`drain_timeout``_outbox_drain_timeout_total` / `messaging.outbox.drain_timeout`). Default `_noop_recorder` lets sites fire unconditionally. Every call site is wrapped in `try/except` + DEBUG log. **Recorder must not block** (sync `Counter.inc()` fine; HTTP/StatsD not). `dlq_written` vs `nacked_terminal` divergence detects DLQ misconfiguration.
178178
- **Native middleware** (`opentelemetry/`, `prometheus/`): thin subclasses of upstream's `TelemetryMiddleware[OutboxPublishCommand]` and `PrometheusMiddleware[OutboxInnerMessage, OutboxPublishCommand]`. Register via the public `OutboxBroker(..., middlewares=[...])` constructor kwarg (forwarded internally as `broker_middlewares`). Fire on `consume_scope` (via `dispatch_one → self.consume(row)`) and `publish_scope` (via `_basic_publish`).
179179

180180
Why two: middleware owns `consume_scope` / `publish_scope` (spans, durations, status, size). Recorder owns events **outside** the bus — `fetched` (no `StreamMessage` at fetch time), `lease_lost` (after `consume_scope` exits), `nacked_terminal(reason="max_deliveries")` (before consume opens). Each fires for events the other physically cannot observe.

architecture/metrics.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@ User-facing: `docs/usage/observability.md`. Invariant summary: `CLAUDE.md` § Me
66

77
`OutboxBroker(..., metrics_recorder=...)` accepts a `MetricsRecorder = Callable[[str, Mapping[str, Any]], None]`. The default (`_noop_recorder`) lets instrumentation sites call unconditionally. The recorder threads through `OutboxBrokerConfig.metrics_recorder` to two places:
88

9-
- **Subscriber emission points** (`OutboxSubscriber._emit_metric`): `fetched`, `dispatched`, `acked`, `nacked_retried`, `nacked_terminal`, `lease_lost`, plus `dlq_written` when `dlq_table` is configured.
9+
- **Subscriber emission points** (`OutboxSubscriber._emit_metric`): `fetched`, `dispatched`, `acked`, `nacked_retried`, `nacked_terminal`, `lease_lost`, `drain_timeout` (a `stop()` drain that exceeded `graceful_timeout`), plus `dlq_written` when `dlq_table` is configured.
1010
- **Producer emission point** (`OutboxProducer._emit_metric`): `published`.
1111

1212
The producer reads the recorder from its own constructor kwarg (passed in alongside the config field) so the canonical insert path doesn't have to reach through the broker config at call time.

docs/usage/observability.md

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ from faststream_outbox import MetricsRecorder, OutboxBroker
2828

2929
def recorder(event: str, tags: dict) -> None:
3030
# event ∈ {fetched, dispatched, acked, nacked_retried, nacked_terminal,
31-
# lease_lost, dlq_written, published}
31+
# lease_lost, dlq_written, drain_timeout, published}
3232
# tags always include "queue"; subscriber-side events also include "subscriber"
3333
print(event, tags)
3434

@@ -82,6 +82,7 @@ broken recorder never poisons the dispatch loop.
8282
| `lease_lost` | `queue`, `subscriber`, `phase`, `row_id`, `deliveries_count` | | Terminal or retry write found `rowcount == 0` (`phase` = `terminal` \| `retry`) |
8383
| `published` | `queue`, `status`, `count`, `size_bytes`, `duration_seconds` | `exception_type` | Producer, after the INSERT executes (pre-commit; also fires on error with `status="error"`) |
8484
| `dlq_written` | `queue`, `subscriber`, `deliveries_count`, `failure_reason` | `exception_type` | DLQ CTE wrote an audit row. `exception_type` is **omitted** — not set to `None` — when the terminal had no exception (`max_deliveries`, or a manual `reject()` without one) |
85+
| `drain_timeout` | `queue`, `subscriber`, `drain_timeout_seconds` | | A `stop()` drain exceeded `graceful_timeout`; in-flight rows were abandoned to lease-expiry retry. `queue` is the subscriber's **first** queue |
8586

8687
`reason` on `nacked_terminal` is one of `max_deliveries`,
8788
`retry_terminal`, `rejected`. The same value lands in the DLQ

faststream_outbox/metrics/opentelemetry.py

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -149,6 +149,11 @@ def __init__(
149149
unit="event",
150150
description="DLQ audit rows written by terminal flush, broken down by reason",
151151
)
152+
self._drain_timeout = self._meter.create_counter(
153+
name="messaging.outbox.drain_timeout",
154+
unit="event",
155+
description="Drains that exceeded graceful_timeout, abandoning in-flight rows to lease-expiry retry",
156+
)
152157

153158
def _attrs(self, tags: Mapping[str, typing.Any], *, operation: str) -> dict[str, typing.Any]:
154159
attrs: dict[str, typing.Any] = {
@@ -161,7 +166,7 @@ def _attrs(self, tags: Mapping[str, typing.Any], *, operation: str) -> dict[str,
161166
attrs[_ATTR_HANDLER] = handler
162167
return attrs
163168

164-
def __call__(self, event: str, tags: Mapping[str, typing.Any]) -> None: # noqa: C901, PLR0912
169+
def __call__(self, event: str, tags: Mapping[str, typing.Any]) -> None: # noqa: C901, PLR0911, PLR0912
165170
if event == "fetched":
166171
self._fetch_batches.add(1, self._attrs(tags, operation="receive"))
167172
return
@@ -204,6 +209,10 @@ def __call__(self, event: str, tags: Mapping[str, typing.Any]) -> None: # noqa:
204209
self._dlq_written.add(1, attrs)
205210
return
206211

212+
if event == "drain_timeout":
213+
self._drain_timeout.add(1, self._attrs(tags, operation="process"))
214+
return
215+
207216
if event == "published":
208217
attrs = self._attrs(tags, operation="publish")
209218
attrs[_ATTR_STATUS] = tags.get("status", "success")

faststream_outbox/metrics/prometheus.py

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -212,6 +212,12 @@ def __init__(
212212
[*consume_labels, "reason"],
213213
registry=registry,
214214
)
215+
self._drain_timeout = Counter(
216+
f"{p}_outbox_drain_timeout_total",
217+
"Drains that exceeded graceful_timeout, abandoning in-flight rows to lease-expiry retry.",
218+
consume_labels,
219+
registry=registry,
220+
)
215221

216222
def _resolve_custom_values(self, tags: Mapping[str, typing.Any]) -> tuple[str, ...]:
217223
return tuple(
@@ -234,7 +240,7 @@ def _publish_values(self, tags: Mapping[str, typing.Any]) -> tuple[str, ...]:
234240
destination = tags.get("queue", "")
235241
return (self._app_name, BROKER_SYSTEM, destination, *self._resolve_custom_values(tags))
236242

237-
def __call__(self, event: str, tags: Mapping[str, typing.Any]) -> None: # noqa: C901, PLR0912
243+
def __call__(self, event: str, tags: Mapping[str, typing.Any]) -> None: # noqa: C901, PLR0911, PLR0912
238244
consume_base = self._consume_values(tags)
239245

240246
if event == "fetched":
@@ -282,6 +288,10 @@ def __call__(self, event: str, tags: Mapping[str, typing.Any]) -> None: # noqa:
282288
self._dlq_written.labels(*consume_base, tags["failure_reason"]).inc()
283289
return
284290

291+
if event == "drain_timeout":
292+
self._drain_timeout.labels(*consume_base).inc()
293+
return
294+
285295
if event == "published":
286296
publish_base = self._publish_values(tags)
287297
status = tags.get("status", "success")

tests/test_metrics_opentelemetry.py

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -123,6 +123,15 @@ def test_otel_unknown_event_is_silently_ignored() -> None:
123123
assert _collect_metrics(reader) == {}
124124

125125

126+
def test_otel_drain_timeout_emits_counter() -> None:
127+
"""The subscriber-emitted drain_timeout event increments its dedicated meter counter."""
128+
reader, rec = _reader_and_recorder()
129+
rec("drain_timeout", {"queue": "q", "subscriber": "h", "drain_timeout_seconds": 0.2})
130+
metrics = _collect_metrics(reader)
131+
assert "messaging.outbox.drain_timeout" in metrics
132+
assert sum(p.value for p in metrics["messaging.outbox.drain_timeout"].data_points) == 1
133+
134+
126135
def test_otel_dlq_written_emits_counter_with_reason_attr() -> None:
127136
reader, rec = _reader_and_recorder()
128137
rec(

tests/test_metrics_prometheus.py

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -219,6 +219,13 @@ def test_prometheus_unknown_event_is_silently_ignored() -> None:
219219
rec("future_event_not_yet_added", {"queue": "q", "subscriber": "h"}) # forward-compat
220220

221221

222+
def test_prometheus_drain_timeout_increments() -> None:
223+
"""The subscriber-emitted drain_timeout event increments its dedicated counter."""
224+
reg, rec = _make_recorder()
225+
rec("drain_timeout", {"queue": "q", "subscriber": "h", "drain_timeout_seconds": 0.2})
226+
assert _sample(reg, "faststream_outbox_drain_timeout_total", _base_labels()) == 1.0
227+
228+
222229
def test_prometheus_dlq_written_records_reason_label() -> None:
223230
reg, rec = _make_recorder()
224231
rec(

0 commit comments

Comments
 (0)