From 36e753129fb7c7d9d60a1f22c5e206767f47e68e Mon Sep 17 00:00:00 2001 From: Mike Dalessio Date: Fri, 9 Oct 2026 14:08:17 -0400 Subject: [PATCH] Count a call interrupted by an exception as `exception`, not `ok` When an exception, such as the application's own request timeout, escaped a call, `yabeda-hotcell` counted the call as `code="ok"` and recorded a `perform` of 0 seconds, inflating `ok` for the call's cell and operation. Count it under `code="exception"` and skip the `perform` observation. [Fix #93] --- CHANGELOG.md | 8 ++++++++ docs/observability.md | 4 ++-- yabeda-hotcell/lib/yabeda/hot_cell.rb | 9 ++++++--- yabeda-hotcell/test/perform_test.rb | 18 ++++++++++++++++++ 4 files changed, 34 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a5563c3..34a81c4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,14 @@ This changelog covers these gems, which release together on the same version: A `Tooling` section records changes to the checks and scripts in `bin/` and `examples/`, which ship in no gem but are what an operator runs against their own image. +## next / unreleased + +### Yabeda::HotCell + +#### Fixed + +* A call that an exception interrupted, such as the application's own request timeout, is counted in `requests` under `code="exception"` and records no `perform` observation. Previously, it was counted as `code="ok"` with a `perform` of 0 seconds. (#93) + ## v1.1.0 / 2026-10-08 ### HotCell::Server diff --git a/docs/observability.md b/docs/observability.md index f037c19..2859118 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -134,8 +134,8 @@ The metrics are in the `hotcell` group: | Metric | Type | Tags | Description | | --- | --- | --- | --- | -| `requests` | counter | `cell`, `operation`, `code`, `cause` | Each call. `code` is `ok` on success, and `cause` is empty when there's none. | -| `perform` | histogram | `cell`, `operation` | Seconds that the cell spent in `perform`. | +| `requests` | counter | `cell`, `operation`, `code`, `cause` | Each call. `code` is `ok` on success, and `exception` when an exception interrupted the call, such as the application's own request timeout. `cause` is empty when there's none. | +| `perform` | histogram | `cell`, `operation` | Seconds that the cell spent in `perform`. A call that an exception interrupted records nothing. | | `up` | gauge | `cell` | 1 when the local cell answers its control socket, otherwise 0. | | `running` | gauge | `cell` | Workers busy right now. | | `queued` | gauge | `cell` | Connections waiting for a worker. | diff --git a/yabeda-hotcell/lib/yabeda/hot_cell.rb b/yabeda-hotcell/lib/yabeda/hot_cell.rb index 4a1ae0f..46f9377 100644 --- a/yabeda-hotcell/lib/yabeda/hot_cell.rb +++ b/yabeda-hotcell/lib/yabeda/hot_cell.rb @@ -68,14 +68,17 @@ def self.subscribe_to_performs end # A failed call is not reported from here: the raise the caller sees already reaches the error reporter. + # + # An exception that escapes the call, such as the application's own request timeout, leaves no code on the + # event, and the cell measured nothing. def self.record_perform(event) labels = { cell: event.payload[:cell], operation: event.payload[:operation] } + code = event.payload[:code] || (event.payload[:exception] ? "exception" : "ok") # Empty rather than absent, because a label that is sometimes missing is a separate series in Prometheus # and a query by code would silently split. - Yabeda.hotcell.requests.increment(labels.merge(code: event.payload[:code] || "ok", - cause: event.payload[:cause].to_s)) - Yabeda.hotcell.perform.measure(labels, (event.payload[:perform_ms] || 0) / 1000.0) + Yabeda.hotcell.requests.increment(labels.merge(code: code, cause: event.payload[:cause].to_s)) + Yabeda.hotcell.perform.measure(labels, (event.payload[:perform_ms] || 0) / 1000.0) unless code == "exception" end private_class_method def self.set_counters(cell, counters) diff --git a/yabeda-hotcell/test/perform_test.rb b/yabeda-hotcell/test/perform_test.rb index ca37520..52fd183 100644 --- a/yabeda-hotcell/test/perform_test.rb +++ b/yabeda-hotcell/test/perform_test.rb @@ -31,6 +31,15 @@ def test_counts_a_kill_under_its_cause assert_equal 1, requests(code: "killed", cause: "fsize") end + def test_counts_a_call_interrupted_by_an_exception_under_its_own_code_and_measures_nothing + answer_by_raising + + assert_raises(RuntimeError) { Anything.perform_in_hotcell [], [], {} } + + assert_equal({ { **labels, code: "exception", cause: "" } => 1 }, all_requests) + assert_nil perform_seconds + end + # A subscriber raises into whoever called instrument, so a bug here would otherwise arrive as a failed call. def test_a_metrics_bug_arrives_as_a_report_rather_than_as_a_failed_call ActiveSupport::Notifications.instrument("perform.hot_cell", cell: "test", perform_ms: "not a number") { } @@ -44,6 +53,11 @@ def answer(response) register transport: CannedTransport.new(response) end + def answer_by_raising + HotCell.root = "/nowhere" + register transport: BrokenTransport.new + end + def failed(code:, cause: nil) HotCell::Response.failed HotCell::Failure.new(code: code, cause: cause, message: "no"), timing: { perform_ms: 1 } end @@ -52,6 +66,10 @@ def requests(**tags) Yabeda::TestAdapter.instance.counters[Yabeda.hotcell.requests][{ **labels, **tags }] end + def all_requests + Yabeda::TestAdapter.instance.counters[Yabeda.hotcell.requests] + end + def perform_seconds Yabeda::TestAdapter.instance.histograms[Yabeda.hotcell.perform][labels] end