feat(executor): end-to-end latency instrumentation with correlation ids

[thesithunyein]

What

End-to-end execution latency instrumentation for the full pipeline the issue
describes — event-tracker → SQS → executor → runner/broadcast. Every event
trigger now gets a correlation id minted at the moment it is first observed
and carried through every stage, with per-stage timestamps and latency
histograms:

observed → received → started → dispatched → broadcast → completed

Why

Latency today is only observable per-workflow from inside the engine
(workflow.execution.duration_ms). Nothing distinguishes producer → queue →
executor delay from executor → runner delay, and there is no key that joins
an event's tracker-stage logs to its SQS/executor/runner-stage logs. This
implements #2289's ask directly: a correlation id and stage timestamps from the
event-tracker through the executor, plus histograms, so a slow producer, a slow
queue and a slow runner are each visible independently — and a single run can be
traced across three systems on one key.

What changed (2 commits, 13 files, +614/−13)

Commit 1 — executor stage (1d53470):

File	Change
keeperhub-executor/latency.ts (new)	ExecutionLatency stage tracker — idempotent marks (first wins), derived durations, JSON-safe log fields, CSPRNG generateCorrelationId() (16 hex, no new deps)
keeperhub-executor/index.ts	Correlation id reused/minted at receive; dispatchExecution marks dispatched, emits the receive→dispatch histogram and a structured [Executor:Latency] summary line (skipped for in-process, which records its own full-timeline line)
keeperhub-executor/in-process.ts	Marks started/completed around the engine call; receive→started + receive→completed histograms; correlation id on Completed/Fatal logs
keeperhub-executor/k8s-job.ts	KH_CORRELATION_ID env var + correlation-id pod label
lib/metrics/types.ts	executor.dispatch.latency_ms, executor.execution.latency_ms; correlation_id, dispatch_target labels

Commit 2 — tracker + runner legs (4e6330e):

File	Change
keeperhub-events/event-tracker/lib/correlation.ts (new)	Shared generateCorrelationId() (same format as the executor's)
.../lib/workflow-sqs.ts	Optional correlationId/observedAt carried on the SQS message; absent for legacy callers (undefined is dropped by JSON.stringify)
.../src/listener/event-listener.ts	Id + observedAt minted at the moment the event is first observed; observed <tx> correlationId=… log line
keeperhub-executor/types.ts + message-schema.ts	Optional correlationId/observedAt on event messages; legacy messages without them still validate (drift guard kept)
keeperhub-executor/workflow-runner.ts	Emits KH_CORRELATION_ID on start, completion and fatal logs so the pod joins the same trace key

Design notes

• First mark wins — a recovered/redelivered path can never overwrite the
  first observation, keeping the histograms honest.
• Failure never fabricates latency — completed is only marked when a
  terminal status lands; a crash shows as a missing series, not a fast fake
  reading. Error paths still carry the correlation id.
• Backward compatible — all new message fields are optional and the tracker
  omits them for legacy callers, so older producers/messages behave exactly as
  before (the executor falls back to minting its own id).
• No new dependencies — node:crypto only.
• Emission points are single — in-process runs record their own full
  timeline; handed-off targets (k8s-job/api) record the receive→dispatch
  handoff. No double counts.

Testing

• 20 new unit tests (13 executor latency + schema, 5 executor observed
  stage/queue leg/ordering, 2 tracker SQS payload carry/legacy omission)
• Executor suite: 143 tests passing
• Event-tracker unit suite: 222 tests passing
• tsc --noEmit clean for both packages (touched files)

Follow-up (deliberately out of scope)

• Dashboard/alert wiring on the new histograms.
• Scheduler (cron/block) producers could carry the same id/observedAt — the
  executor already handles it whenever a message carries the fields.

Verification for reviewers

pnpm install
npx vitest run keeperhub-executor/latency.test.ts
npx vitest run keeperhub-executor
cd keeperhub-events/event-tracker && npx vitest run tests/unit

Sample emitted line (tracker):

[EventListener:abc123] observed 0xdead… correlationId=1a2b3c4d5e6f7890

Sample emitted line (executor, in-process run):

[Executor:Latency] correlationId=1a2b3c4d5e6f7890 workflowId=wf-1 executionId=exec-1 triggerType=event dispatchTarget=in-process observedAt=… receivedAt=… startedAt=… completedAt=… queueToStartMs=50 totalMs=200

[github-actions]

About the build check on this pull request

This pull request comes from a fork, so GitHub does not pass it the credentials build normally uses for our image registry cache and staging build configuration. The build still runs and still compiles the image, so a red build here is real; it just takes longer than on team branches.

Every workflow run on a pull request from a fork also waits for a maintainer to approve it, so checks can sit at "awaiting approval" for a while after each push. Nothing is needed from you for either of these.

[joelorzet]

The metrics half of this is dead. It will not be merged in this state.

piece	state
executor.dispatch.latency_ms	name only, no histogram, nothing recorded
executor.execution.latency_ms	name only, no histogram, nothing recorded
broadcast stage	declared, never marked

Every sample is discarded and logs Unknown latency metric. A declaration nothing implements is not a smaller version of the feature. It is a feature that does not exist while looking like it does.

Please finish all three here. We are not landing the shape now and the implementation later.

The correlation id half is done and worth keeping. The tracker mints the id and puts correlationId and observedAt on the SQS message, the executor reads them and mints its own when they are absent, and k8s-job.ts injects KH_CORRELATION_ID plus a correlation-id label so the runner pod joins on the same key. One run is traceable across three services, and each stage is recorded once so a retry cannot overwrite the first observation.

Four things inline.

Smaller: keeperhub-events/event-tracker/lib/correlation.ts has no trailing newline, and it duplicates generateCorrelationId. If the package boundary forces the copy, say so in the comment the way in-flight.ts does.

[joelorzet]

Adding a name here does not create a metric. Neither of these reaches Prometheus.

recordLatency resolves the name against a fixed map and drops anything it does not know:

const histogram = histogramMap[name];
if (histogram) {
  histogram.observe(sanitizeLabels(labels), durationMs);
} else {
  logWarn(`[Prometheus] Unknown latency metric: ${name}`);
}

histogramMap in lib/metrics/collectors/prometheus.ts holds four latency histograms and neither of these is among them. This PR does not touch that file, and the executor imports the same collector, so every sample is discarded and each execution writes a warning instead.

Register both there with a help string and buckets, and add a test asserting a sample lands. Nothing here would have caught this.

One thing to address while you are in that file. It carries a note saying workflow execution and step metrics deliberately moved to DB-sourced gauges, and dbSourcedMetrics holds workflow.execution.duration_ms and workflow.step.duration_ms. Your two measure queue time and dispatch hand-off, which the database has no timestamps for, so runtime histograms are the right choice. Say that in the comment, otherwise the next reader sees you going against a decision recorded a few lines above.

[joelorzet]

Keep this out of the histogram labels when you register them.

A correlation id is a fresh value per execution, so it creates one time series per execution. #2289 rules this out by name: "per-workflow labels on a latency histogram are a metrics-cost problem", and this is finer-grained than per-workflow. The comment in latency.ts calling the id "short enough for labels" points the wrong way.

The id belongs in the structured log, where it already does its job. Label the histograms with trigger, dispatch_target and stage.

[joelorzet]

broadcast is declared here and in STAGE_ORDER, and nothing marks it. Across the whole diff the marks are observed, received, started, dispatched and completed. The only edit inside the pod that broadcasts, in workflow-runner.ts, appends the correlation id to two log lines and records no timestamp.

That is the measurement the issue exists for. #2289 lists "Transaction broadcast" as a required stage, and asks for the distribution of time from event observed to transaction broadcast, and which stage dominated it. observed is recorded and broadcast is not, so that interval cannot be computed and the per-stage attribution stops one hop short.

Mark it where the transaction actually goes to the chain.

[joelorzet]

Use logInfo for these lines rather than building the summary by hand.

lib/logging.ts exports logInfo(message, labels), which emits the canonical structured line with the labels already in the shape the log pipeline parses. This builds a second, parallel format to carry the same fields, and getting the correlation id into the logs is the point of the PR.

Scope it to the new latency lines only. The surrounding console.log calls in the executor are the existing convention there and are not yours to change.

One thing to watch: lib/logging.ts imports @sentry/nextjs. You already import lib/metrics, so most of the chain is present, but if that import breaks the executor bundle, say so and keep console.log with a note explaining why.

[thesithunyein]

Thanks for the precise review — all four points were correct, and all four are fixed in edc6193. The metrics half is real now.

1. Histograms registered (lib/metrics/collectors/prometheus.ts)

Both names are now in histogramMap, registered on apiRegistry with help strings and buckets:

• executor.dispatch.latency_ms -> keeperhub_executor_dispatch_latency_ms, buckets [50 ... 60_000]
• executor.execution.latency_ms -> keeperhub_executor_execution_latency_ms, buckets [100 ... 300_000]
• plus executor.broadcast.latency_ms -> keeperhub_executor_broadcast_latency_ms (point 3 below)

The DB-sourced-gauges note is addressed in a comment directly above the registration: workflow.execution.duration_ms / workflow.step.duration_ms moved to DB gauges because the database holds their per-row data; these measure the SQS queue leg and the dispatch hand-off — intervals between in-memory stages that leave no database timestamps — so runtime histograms are the deliberate exception, not an oversight.

Regression test: lib/metrics/__tests__/executor-latency.test.ts records a sample via recordLatency and asserts it lands in the exposition (_count and _bucket lines) — the exact failure mode ("nothing would have caught this") is now caught.

2. Correlation id out of histogram labels (lib/metrics/types.ts)

LabelKeys.CORRELATION_ID is deleted. Histograms are labeled trigger_type, dispatch_target, and (for the two split-by-stage histograms) stage. The "short enough for labels" comment in latency.ts is rewritten to state the opposite: the id lives in the structured logs and KH_CORRELATION_ID, never in metric labels. A test asserts LabelKeys contains no correlation_id.

3. broadcast is marked where the transaction goes to the chain

Marks now sit at four real broadcast points:

• lib/web3/chain-adapter/evm.ts — sendTransaction (both the sign-once-failover path and the legacy signer.sendTransaction fallback) and executeContractCall (failover + legacy fn(...) path)
• lib/web3/chain-adapter/solana.ts — after submitSignedSolanaTransactionWithFailover resolves a signature
• lib/web3/sponsored-transaction-manager.ts — after Turnkey's Gas Station accepts the submit

The structural constraint: the write paths run in a context with no handle on the ExecutionLatency instance (separate runner pod for k8s-job dispatches; a separate engine call for in-process). So the timestamp travels by side channel, best-effort, never able to fail the transaction it observes:

• keeperhub-executor/lib/broadcast-marker.ts writes {executionId, broadcastAt} to a fixed /tmp sidecar (one web3 write in flight per pod by construction) and bumps a process-local counter.
• The counter ships to the executor in the existing counter-delta ingest (keeperhub_executor_broadcasts_total) — the broadcast stage is visible fleet-wide even where the timestamp is not.
• In-process: recordInProcessLatency reads the marker back after executeWorkflow returns, marks broadcast, and records the observed -> broadcast distribution (executor.broadcast.latency_ms) — the headline interval from End-to-end trigger-to-broadcast latency is inferred from code, never measured #2289.
• k8s-job: the runner reads the marker after the engine returns and logs Broadcast stage: executionId=... correlationId=... broadcastAt=.... Ephemeral pods deliberately do not ship histogram observations (metrics-shipping.ts), so the per-run log line joined on correlation id is the record for the Job path; a central histogram for Jobs would need point-sample ingestion first, which I left out rather than half-build. Happy to add that ingestion if you want it.

4. logInfo for the latency lines (keeperhub-executor/latency.ts + call sites)

The hand-built summaryLine is deleted. ExecutionLatency.emitLog() emits via lib/logging's logInfo(message, labels) — canonical shape, correlation id, workflow/execution ids, stage timestamps and durations as labels. Scoped to the latency lines only; the surrounding console.log calls are untouched. On the bundle question: the executor already imports lib/logging transitively (index.ts -> backstop-capture -> logSecurityEvent), and in-process.ts pulls in the engine which imports it directly, so @sentry/nextjs was already in both graphs — tsc and the full executor suite are clean.

Smaller point

correlation.ts got its trailing newline and a comment explaining the duplication ("keeperhub-events is a separate pnpm workspace and cannot import root lib/", same convention as phantom.ts / sqs-message-auth.ts).

Tests

152 executor tests + 7 web3/metrics tests pass, including 7 new broadcast-marker tests (sidecar write/read/clear, corrupt-file tolerance, ALS execution-id resolution, counter bumps), 5 histogram-observability tests, and rewritten emitLog assertions. tsc --noEmit is clean across the repo.

One note for CI: the fork build check may sit at "awaiting approval" per the bot comment above — nothing needed from you on that.

[thesithunyein]

Follow-up: the door I left open in the reply above is now closed in 14c4390.

Point latency observations from runner pods. executor.broadcast.latency_ms previously filled only for in-process runs; real web3 writes dispatch to k8s Jobs, whose pods cannot write the executor's histograms (your own metrics-shipping.ts comment: histogram observations cannot be merged across pods without losing bucket fidelity). Point observations can, so:

• the pod ships {correlationId, executionId, stage, durationMs} over the existing counter-delta ingest (KH_RECEIVED_AT/KH_OBSERVED_AT injected by k8s-job.ts, broadcast from the sidecar marker)
• the executor folds each sample back onto the originating run's timeline (bounded correlation map) and into the central histograms — so Job broadcasts now fill the observed→broadcast distribution, the headline interval from End-to-end trigger-to-broadcast latency is inferred from code, never measured #2289
• completion is anchored on the executor's own received stamp, so a skewed pod clock cannot distort the queue leg; unknown correlation ids lose nothing for self-contained intervals

16 new tests (168 executor total, tsc clean). Happy to trim this if the PR has grown past what you want in one change — the observation modules are self-contained (latency-observations / correlation-map / observation-applier) and split cleanly if you'd prefer them as a follow-up PR.

[thesithunyein]

Hi @joelorzet — friendly ping ahead of the hackathon submission deadline (Sep 18). All four review points are fixed (same-day, with tests — the executor suite is now at 168), and the follow-up in 14c4390 also closes the Job-pod dispatch-path gap for the broadcast distribution. I see release: To Prod is being cut; happy to rebase if staging moved, and glad to address anything further or split the PR if that helps review. Thanks again for the precise first pass!

[thesithunyein]

Small hardening commit (1667d01) while preparing the demo recording: running the repo's own scripts — pnpm type-check:tsc:executor and pnpm type-check:tsc — surfaced two loose ends my ad-hoc checks had missed:

1. executorBroadcastsTotal was module-private in lib/metrics/collectors/prometheus.ts while metrics-shipping.ts destructures it — now exported (with a comment explaining the pod-side shipping path).
2. collectLatencyObservations accepted triggerType: string | undefined but the LatencyObservation wire contract is a strict string — now normalized at collection ("manual", matching the platform's label for non-trigger-originated runs) so the types line up without loosening the contract.

Both type-check:tsc:executor and type-check:tsc are clean; 168/168 executor tests pass. No behavior change beyond the defaulting above.