Repository navigation
feat: trace and measure everything dispatch does in the background, on forge v1.12.9 and grove v1.8.0 - #34
Merged
Merged
Conversation
Moves the root module to forge v1.12.9 (and forge/extensions/auth), grove v1.8.0 with every driver and kv module we use, chronicle v1.9.0, relay v1.8.0 and warden v1.8.0. go-utils lands on v1.4.1 through forge. You get grove's db.client spans and query duration metric for every store call, and the chronicle and relay calls the hooks and the outbox make are now traced and measured by those libraries. trove stays on v1.7.0, and the qualification modules keep their deliberate pins.
Adds github.com/xraph/dispatch/telemetry, the one place the subsystems get their tracer and metric instruments from. It imports only the standard library, OpenTelemetry and go-utils metrics, so the worker, cron, workflow, durable and artifact packages can all import it, and exec stays a leaf. A Telemetry carries a tracer provider (nil means the global one, looked up per span) and a go-utils metric factory (nil means metrics are off). Every label has a fixed set of values and a vector drops anything outside it, so no series can grow per job, tenant or error message. Queue names become a label only when you configured them; anything else is recorded as "other". It also holds the helpers the reviews kept asking for: Detach strips the inherited span and baggage from a long-lived loop's context, Fail sets a short status class plus an exception.type event and never the error text, and a small bounded cache lets an attempt link to the span that enqueued its job when this process did the enqueue.
The pool now starts one root "process job" span per attempt in runJob, so the terminal write, the dead letter push and every lifecycle hook, JobStarted included, run inside it. The middleware span used to end before any of that happened. The attempt is its own trace; when this process enqueued the job it links back to the enqueue span instead of parenting off it, and nothing about the trace is stored with the job. Each terminal path gets a child span (complete job, schedule job retry, dead-letter job, requeue job, abandon job), and the attempt's outcome, exec status, executor and dead letter reason land on the process span. A lost lease adds a "lease lost" event to the attempt the heartbeat cancels. The tracing middleware's span is renamed from dispatch.job.execute to "run job handler" and nests under the attempt. It no longer copies err.Error() into the status or records the error with its message: a handler error can quote its payload. Success leaves the status unset. You also get the pool and runner metrics: attempts by queue and outcome, dead letters by reason, queue wait, polls, requeues, lease renewals, reclaimed jobs and the active attempt gauge. A reaper pass that reclaims anything leaves one root span; an empty pass, like an empty poll, records only a counter.
Every entry the leader finds due gets one root "fire cron entry" span, covering the lock, the re-read, the enqueue and the bookkeeping writes, so the job it enqueues hangs off the fire and the attempt links back to it. An idle tick (not the leader, or nothing due) starts nothing. You get dispatch_cron_fires_total by result (fired, locked, skipped, error), the lag between an entry's due time and its enqueue, and a 0/1 leadership gauge that drops to 0 when the scheduler stops.
A run gets a "run workflow" span. When the caller waits on it (Start, RunChild, MigrateRun) it is a child of the caller's span; when it outlives the caller (ResumeAll at boot, ReplayFrom, SpawnChild) it starts its own trace with a link back. ReplayFrom and spawned children used to keep the caller's span through WithoutCancel. Each step that runs gets a "run workflow step" span with its kind and name, and the step function receives that span's context. A step replayed from its checkpoint gets no span. Compensations are steps of kind compensate. Run and step durations are recorded by result.
Worker.Run now drops whatever span its context carries before it starts polling, because the engine hands it the context forge started the extension under. Every claim used to land in that boot trace. A claim that returns a task starts one root "process durable task" span, for all six task kinds, and an empty claim starts nothing. Inside it, replaying the workflow's history is a "replay workflow history" span and each call into activity code is a "run activity" span. Workflow and run IDs are chosen by whoever starts the workflow, so they stay off spans and metrics; the spans carry the task kind, queue, namespace, build and attempt. Contention, a lost lease, a handler this build lacks and a stopping worker are ordinary outcomes and are recorded as results, not errors. You get task durations by kind and result, claim polls by kind and result, and replay duration. Options gains a Telemetry field; nothing about the trace is written to start or commit requests, task payloads or history.
The publisher starts one root "deliver outbox event" producer span per claimed delivery, with the destination, the delivery's opaque ID and its attempt count, and the sink call runs inside it. The chronicle and relay calls a sink makes are traced by those libraries. An empty claim starts nothing, and the Delivery envelope is untouched. You get delivery attempt durations by destination and result (the publisher's existing failure categories plus acknowledged) and the lag from acceptance to acknowledgement. delivery.New takes options now, and WithTelemetry is the first. The remote sink's HTTP client wraps its transport with otelhttp, keeping the same timeouts, TLS floor and redirect policy, so a call to a remote Chronicle or Relay host carries traceparent and gets a client span. The publisher's context never carries inbound baggage to forward.
Start drops the boot span from the loop's context, and each pass that does work (this instance leads and the sweeper is enabled) runs under one "sweep artifacts" span with what it swept, purged, skipped and reclaimed. A follower's pass starts nothing, and RunOnce now checks leadership once per pass instead of twice. You get swept artifacts by reason (retention, orphan), purged artifacts by result (ok, skipped) and bytes reclaimed.
engine.Build now builds one Telemetry from WithMetricFactory and WithTracerProvider and hands it to the runner, the pool, the cron scheduler, the workflow runner and the durable worker. The Forge extension already passes app.Metrics(), and now also hands the engine's Telemetry to the outbox publisher and artifact sweeper it builds. Engine.Telemetry exposes it for anything you assemble beside the engine. Enqueue gets an "enqueue job" producer span, a child of whatever the caller's context carries, and the attempt that runs the job links to it. DLQ replays get the same span. Only the queues you configured (the ones your workers poll, the ones with limits or resource defaults) appear as a metric label. The worker-row heartbeat, the store wake listener and the durable worker all outlive Start, and all of them used to keep the "start dispatch" boot span forge puts on Start's context. Their queries now start no span, and each unit of work starts its own root. WithMetricFactory unset keeps the legacy counters on the default collector, but leaves the labelled dispatch_* metrics off, because that collector keys series by name alone.
The observability page now lists each span with its kind, parent and attributes, and each metric under the name forge scrapes, with every label value. It explains how a job attempt links to its enqueue, which pollers start no traces, and what never lands on a span. The legacy counters keep their own table. The README, the index, the architecture and package reference pages and AGENTS.md point at the telemetry package instead of claiming tracing lives in the middleware. The configuration example stops registering a second MetricsExtension, which double counted every event, and passes a metric factory instead.
The remote sink's traced transport would inject whatever baggage the calling context carried. The publisher's own context never has any, but Remote is exported and a host can call it from a request, where forge has already extracted the client's baggage. call now strips it, keeps traceparent, and a test checks the remote host sees one and not the other.
publish started its result at acknowledged and only overwrote it after the sink call, but returns early when Stop cancels the publisher's context. A delivery interrupted by shutdown was recorded with dispatch.outbox.result=acknowledged, an unset status and an acknowledged duration observation. The result now starts at cancelled, a documented value on the delivery duration histogram, and becomes acknowledged only once the store has taken the acknowledgement. A cancelled attempt is not an error: the delivery stays claimable and the next publisher picks it up. A test stops the publisher while a sink call is in flight.
Wrapping the transport with otelhttp broke Remote.Close. http.Client.CloseIdleConnections only reaches a transport that has that method, and otelhttp's Transport has RoundTrip alone, so Close stopped dropping idle connections. Remote now keeps the *http.Transport it built and closes its idle connections directly. A test watches the server side of a pooled connection hang up when you call Close.
Recover is the outermost middleware, so a panicking handler unwinds through the tracing middleware, and its "run job handler" span ended with an unset status, as if the handler had succeeded. The middleware now notices that next never returned and marks the span with the status class "panic" and exception.type "panic" before it ends. It does not recover, so the panic reaches Recover exactly as before. The pool's "process job" span does the same for a pool assembled without Recover, where the panic unwinds through runJob.
Pool.Stop cancels every in-flight attempt, so a terminal write racing a deploy fails with context.Canceled and was recorded as outcome store_error with an error status. An alert on store_error would fire on every rollout. When the attempt's own context is done, the failed write is now reported as the documented cancelled outcome with no error status. store_error is left for the store actually refusing the write. A test finishes a handler after its attempt is cancelled against a store that honours the context.
The lag histogram was observed after fireEntry returned, so it counted the lock release, the bookkeeping writes and the CronFired hooks as well, while the docs promise due time to enqueue. fireEntry now takes the due time and records the lag as soon as the enqueue succeeds. A test checks the observation already exists when the fire hook runs.
otelhttp writes the transport's own error text into the client span status when a request to a remote Chronicle or Relay host fails. The page now says so, and why that text can only hold the sink's scheme, host and path.
revive flags the envelope parameter the cancelled-delivery test's sink never reads. It is now blank.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
You get a trace per unit of work, plus labelled metrics, for job attempts, cron fires, checkpoint workflows, durable tasks, outbox deliveries and sweeper passes. Forge apps need no setup. Look for
process jobin your traces andforge_dispatch_on/_/metrics. Outside Forge, passengine.WithTracerProviderandengine.WithMetricFactory, and handeng.Telemetry()to anything built beside the engine.Each attempt is a root span owned by the pool, so the terminal write, DLQ push and hooks land inside it, linked to its
enqueue jobspan when this process enqueued it. Nothing is stored with the job: fingerprints, payloads and the Delivery envelope are untouched. Long-lived loops no longer keep forge'sstart dispatchspan, and an empty poll starts nothing.enqueue jobprocess jobrun job handler(wasdispatch.job.execute),stage job inputs,commit job outputscomplete job,schedule job retry,dead-letter job,requeue job,abandon jobreclaim job leases,fire cron entry,sweep artifactsrun workflow,run workflow stepprocess durable taskreplay workflow history,run activitydeliver outbox eventforge_prefix)dispatch_job_attempt_duration_secondsdispatch_jobs_enqueued_totaldispatch_jobs_dead_lettered_total,dispatch_jobs_requeued_totaldispatch_job_queue_wait_secondsdispatch_job_polls_total,dispatch_job_lease_renewals_totaldispatch_jobs_reclaimed_total,dispatch_jobs_activedispatch_cron_fires_total;dispatch_cron_fire_lag_seconds,dispatch_cron_leaderdispatch_workflow_run_duration_seconds,dispatch_workflow_step_duration_secondsdispatch_durable_task_duration_seconds,dispatch_durable_polls_total;dispatch_durable_replay_duration_secondsdispatch_outbox_delivery_duration_seconds,dispatch_outbox_delivery_lag_secondsdispatch_artifacts_swept_total,dispatch_artifacts_purged_total,dispatch_artifact_bytes_reclaimed_totalThe observability page lists every value; unconfigured queues collapse to
other. Shutdown shows up ascancelled, neverstore_errororacknowledged. No span carries a payload, error text or durable workflow ID; failures, panics included, get a short class andexception.type. Legacy counters keep their names. No log line went live.We also re-pin forge v1.12.9, grove v1.8.0, chronicle v1.9.0, relay v1.8.0 and warden v1.8.0. Relay renamed its delivery metrics, so check Relay dashboards. The remote sink's transport is traced and drops baggage. On failure otelhttp writes its transport error text into the client span status;
NewRemoterejects userinfo, query and fragment, so that text holds only the sink's scheme, host and path.Release once main is green:
Testing:
go test -race ./..., uncapped golangci-lint v2.12.2, gosec v2.28.0, govulncheck, goimports, tidy, the query guard against Postgres 17 and the docs checks pass. Tests check span names, kinds, parentage and links, feedalice@example.comthrough payloads and errors, and prove idle loops hand the store no span. One scrapesforge.New.