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.