feat(telemetry): add processing_latency_ms to event handler stop measurements

[yordis]

Summary

• Adds processing_latency_ms to the measurements emitted on [:commanded, :event, :handle, :stop] and [:commanded, :event, :batch, :stop] telemetry events — the elapsed milliseconds between RecordedEvent.created_at and when the handler finished processing it
• The measurement lives at the event handler layer rather than the projector layer because processing latency is meaningful for any handler, not just Ecto projectors
• For batch handlers, processing_latency_ms reflects the oldest event in the batch (worst-case processing latency for that invocation — the signal that drives SLA alerting)
• Fixes {:ok, handler_state} batch telemetry emitting the full Handler struct as handler_state in metadata instead of the application handler's own state

Related

• feat: Add OpenTelemetry instrumentation for event handlers #41 — origin: introduced the event handler telemetry infrastructure this builds on
• fix(event_store): defer stream_forward telemetry until stream consumed #64 — related: recent telemetry improvement (deferred stream_forward timing)

[cursor]

PR Summary

Medium Risk
Touches core event handler telemetry emission paths to add a new processing_latency_ms measurement, which could impact consumers of telemetry measurements and relies on correct created_at ordering for batches.

Overview
Adds a new processing_latency_ms measurement to [:commanded, :event, :handle, :stop] and [:commanded, :event, :batch, :stop] telemetry, computed as milliseconds from RecordedEvent.created_at to handler completion (for batches, based on the oldest event).

Updates event handler telemetry emission to pass additional measurements through Telemetry.stop/4 and Telemetry.exception/7, fixes batch {:ok, handler_state} to emit the actual handler state (not the full Handler struct), and replaces/extends tests to assert the new measurement and verify batch ordering assumptions.

^{Reviewed by Cursor Bugbot for commit 6da285a. Bugbot is set up for automated code reviews on this repo. Configure here.}

[coderabbitai]

Caution

Review failed

Pull request was closed or merged during review

Walkthrough

Adds a new processing_latency_ms telemetry measurement for event handler stop events (single and batch), updates telemetry helper signatures to forward the measurement, and adjusts tests—removing an old batch telemetry test, adding new telemetry tests, and adding a batch ordering test.

Changes

Cohort / File(s)	Summary
Documentation guides/explanations/fork-differences.md	Appended "Event Handler Processing Latency Telemetry" documenting new processing_latency_ms for [:commanded, :event, :handle, :stop] and [:commanded, :event, :batch, :stop], defined as elapsed ms from RecordedEvent.created_at to handler completion (batch reports oldest event).
Core Implementation lib/commanded/event/handler.ex	Added processing_latency_measurements/1 to compute processing_latency_ms; extended stop/exception telemetry emission to include this measurement; updated helper signatures (telemetry_stop/4, telemetry_exception/7) to accept and forward additional measurements.
Tests — telemetry test/event/event_handler_telemetry_test.exs, test/event/event_handler_batch_telemetry_test.exs	Removed the old Commanded.Event.EventHandlerBatchTelemetryTest (test/event/event_handler_batch_telemetry_test.exs deleted). Added Commanded.Event.EventHandlerTelemetryTest asserting start/stop/exception telemetry for single and batch handlers and that measurements.processing_latency_ms exists, is an integer, and non-negative. Includes a MockAdapter.ack_event/3.
Tests — ordering test/event/event_handler_batch_ordering_test.exs	Added Commanded.Event.EventHandlerBatchOrderingTest to assert stream_forward returns events ordered ascending by event_number and created_at; sets up a Commanded.Application with EventStore test adapter and appends events to a stream.

Estimated code review effort

🎯 3 (Moderate) | ⏱️ ~22 minutes

Poem

🐰 I hopped through timestamps, keen and spry,
Counting milliseconds as they fly—
From created_at to handler's end,
I logged each latency, friend by friend,
A tiny hop for telemetry joy!

🚥 Pre-merge checks | ✅ 2 | ❌ 1

❌ Failed checks (1 warning)

Check name	Status	Explanation	Resolution
Docstring Coverage	⚠️ Warning	Docstring coverage is 0.00% which is insufficient. The required threshold is 80.00%.	Write docstrings for the functions missing them to satisfy the coverage threshold.

✅ Passed checks (2 passed)

Check name	Status	Explanation
Title check	✅ Passed	The title directly and specifically describes the main change: adding processing_latency_ms measurement to event handler stop telemetry events.
Description check	✅ Passed	The description is clearly related to the changeset, detailing what processing_latency_ms measurement is, where it's implemented, and how it works for batch handlers.

_{✏️ Tip: You can configure your own custom pre-merge checks in the settings.}

✨ Finishing Touches

📝 Generate docstrings

• Create stacked PR
• Commit on current branch

🧪 Generate unit tests (beta)

• Create PR with unit tests
• Commit unit tests in branch improve-otel

---

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands and usage tips.}

[cursor]

Cursor Bugbot has reviewed your changes and found 1 potential issue.

^{❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.}

^{Reviewed by Cursor Bugbot for commit 62c8812. Configure here.}

[coderabbitai]

Actionable comments posted: 2

Caution

Some comments are outside the diff and can’t be posted inline due to platform limitations.

⚠️ Outside diff range comments (1)

lib/commanded/event/handler.ex (1)

1084-1093: ⚠️ Potential issue | 🟡 Minor

CI is blocked by formatter failures in these ranges.

mix format --check-formatted is failing for this file (as reported in pipeline). Please run formatter on the updated telemetry calls/signatures.

Also applies to: 1162-1180, 1437-1459

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@lib/commanded/event/handler.ex` around lines 1084 - 1093, The formatter check
is failing due to unformatted changes around the telemetry call sites and
updated function signatures; run mix format over the modified ranges and ensure
telemetry_exception/6 and related telemetry calls (and their surrounding
concatenated Logger.error blocks) are formatted to match project formatting
rules; specifically reformat the block that calls
telemetry_exception(start_time, :error, reason, stacktrace, telemetry_metadata,
:handle, lag), the failure_context/retry_fun/handle_event_error sequence, and
the Logger.error describe(state) <> " failed to handle event " concatenation
(also apply the same formatting fixes to the other affected ranges around the
existing telemetry and Logger blocks at the noted locations).

🤖 Prompt for all review comments with AI agents

Verify each finding against the current code and only fix it if needed.

Inline comments:
In `@lib/commanded/event/handler.ex`:
- Around line 1045-1047: The lag measurement is being captured too early; move
the call to lag_measurements so it runs after handler execution and use that
value when emitting the stop/exception telemetry. Specifically, keep
telemetry_start(telemetry_metadata, :handle) where it is, but call
lag_measurements(event) after delegate_event_to_handler/2 returns (and also in
the rescue/exception path) and pass that computed lag (e.g., lag_ms) into the
subsequent stop/exception emit logic so the reported lag reflects time "when the
handler finished."
- Around line 1148-1150: The telemetry metadata currently injects the full
%Handler{} (variable state) instead of the returned handler_state; update the
call to telemetry_stop in the {:ok, handler_state} branch to pass handler_state
(not state) into the metadata (i.e., %{telemetry_metadata | handler_state:
handler_state}) so telemetry_stop and subsequent confirm_receipt receive the
correct handler_state value from the invoked handler function.

---

Outside diff comments:
In `@lib/commanded/event/handler.ex`:
- Around line 1084-1093: The formatter check is failing due to unformatted
changes around the telemetry call sites and updated function signatures; run mix
format over the modified ranges and ensure telemetry_exception/6 and related
telemetry calls (and their surrounding concatenated Logger.error blocks) are
formatted to match project formatting rules; specifically reformat the block
that calls telemetry_exception(start_time, :error, reason, stacktrace,
telemetry_metadata, :handle, lag), the
failure_context/retry_fun/handle_event_error sequence, and the Logger.error
describe(state) <> " failed to handle event " concatenation (also apply the same
formatting fixes to the other affected ranges around the existing telemetry and
Logger blocks at the noted locations).

🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

• Push a commit to this branch (recommended)
• Create a new PR with the fixes

---

ℹ️ Review info

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 55cf829e-1d4e-490b-b06c-6109d9caeb18

📥 Commits

Reviewing files that changed from the base of the PR and between e4e9034 and 62c8812.

📒 Files selected for processing (4)

• guides/explanations/fork-differences.md
• lib/commanded/event/handler.ex
• test/event/event_handler_batch_telemetry_test.exs
• test/event/event_handler_telemetry_test.exs

[coderabbitai]

Actionable comments posted: 1

🤖 Prompt for all review comments with AI agents

Verify each finding against the current code and only fix it if needed.

Inline comments:
In `@test/event/event_handler_telemetry_test.exs`:
- Around line 18-30: The test name and PR text mention "lag_ms" but the code
emits "processing_latency_ms"; update the measurement name to be consistent by
either changing the emitted telemetry key in the handler (where
Handler.handle_info/2 and EchoHandler produce telemetry) to use :lag_ms or
rename the test assertions to expect :processing_latency_ms so names match;
additionally, add an assertion verifying the handler actually processed the
event (e.g., assert_receive for EchoHandler's reply message) before asserting
telemetry to ensure the telemetry came from a successful handling path.

🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

• Push a commit to this branch (recommended)
• Create a new PR with the fixes

---

ℹ️ Review info

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 8313497a-7e66-4a16-b525-185cd60eaa9c

📥 Commits

Reviewing files that changed from the base of the PR and between 62c8812 and 592bf14.

📒 Files selected for processing (4)

• guides/explanations/fork-differences.md
• lib/commanded/event/handler.ex
• test/event/event_handler_batch_telemetry_test.exs
• test/event/event_handler_telemetry_test.exs

✅ Files skipped from review due to trivial changes (2)

• test/event/event_handler_batch_telemetry_test.exs
• guides/explanations/fork-differences.md

🚧 Files skipped from review as they are similar to previous changes (1)

• lib/commanded/event/handler.ex