Trace Slack turn latency from message to reply #2269

Objective

Measure how long one Slack message takes from send to Slack-accepted reply. Show the main steps in one Sentry trace: ingress, queue, worker, turn, model, tools, sandbox, and reply. Today we cannot see the time between webhook ingress and turn start, and we do not record model time to first chunk.

Current state (verified at 484112922)

• The trace ends at slack.message.ingress. The queue message (task-execution/queue.ts) is a wake-up signal that carries only conversationId. No trace context crosses the mailbox, so worker spans start a new trace.
• The queue callback and worker (queue/callback.ts, task-execution/vercel-callback.ts, task-execution/worker.ts) emit no spans. They emit only info logs such as conversation.work.lease.acquired, and Sentry drops info logs in production.
• conversationWorkCallback discards the Vercel MessageMetadata (createdAt, deliveryCount).
• Mailbox entries store createdAtMs (Slack send time) and receivedAtMs (webhook receipt). No telemetry records either value.
• gen_ai.chat (pi/traced-stream.ts) covers the full model call. It does not record time to first chunk.
• First visible feedback (processing reaction, assistant status in slack/assistant-thread/status-send.ts) records failures only. The reply post (slack/reply.ts) has no timing of its own.
• Sandbox work already has spans: sandbox.acquire, sandbox.reuse_probe, sandbox.get, sandbox.create, sandbox.snapshot.*, sandbox.sync_skills. sandbox.acquire does not record which path it took.

Constraint: phased rollout for stored fields

inboundMessageSchema (task-execution/state.ts) is .strict(). If one pending message fails to parse, readConversation throws InvalidConversationRecordError. The worker then rejects the wake as invalid_record, and that conversation's queued work is lost. An old worker that reads a new field during a deploy causes this failure.

Decided: every new mailbox field ships in two PRs. First, readers accept the optional field, and that change deploys to production. Then a second PR starts to write the field. Turn cursor fields don't need this: storedTurnRecordSchema uses .strip(), so old readers drop unknown fields instead of failing.

Plan

Each PR links this issue and adds its fields to TELEMETRY.md. Only 5a → 5b → 6 depend on each other. The other PRs can branch from main.

• feat(task-execution): Trace conversation work with queue lag and outcome #2283 — PR 1: worker span. Wrap processConversationQueueMessage (the shared queue entry point; worker.ts is at its line limit) in a conversation.work.process span. Pass MessageMetadata through. Record app.queue.lag_ms, app.queue.delivery_count, app.worker.outcome, and app.worker.pending_count.
• feat(slack): Record mailbox input timing on chat.turn spans #2284 — PR 2: turn wait on chat.turn. Record app.turn.delivery_lag_ms (receivedAtMs − createdAtMs), app.turn.wait_ms (chat.turn start − receivedAtMs), and app.turn.input_count on chat.turn. Use the oldest input message. wait_ms ends at the chat.turn span start.
• feat(task-execution): Use Sentry queue spans for conversation work #2320 — PR 1b: Sentry queue conventions. Add a queue.publish span around the send in vercel-queue.ts. Change conversation.work.process to op queue.process. Rename app.queue.lag_ms to messaging.message.receive.latency and app.queue.delivery_count to messaging.message.retry.count. Always set messaging.system=vercel_queue and messaging.destination.name, so Slack log context values do not leak in. Merge before 5b.
• feat(telemetry): Record time to first byte and first token on gen_ai.chat #2286 — PR 3: model TTFB and TTFT. In pi/traced-stream.ts, relay the provider stream into a new stream that the agent loop reads, and time each event as the relay reads it. Record app.ai.time_to_first_byte_ms (first event, usually start), gen_ai.response.time_to_first_chunk (first content event), gen_ai.response.streaming, and app.ai.first_token_type.
• ref(slack): Trace assistant status calls for first feedback #2282 — PR 4: first feedback and reply accepted. Add an http.client span around assistant.threads.setStatus, the one Slack feedback call that had no span. No first-feedback attributes: first feedback is the earliest reactions.add or assistant.threads.setStatus span in the turn's trace. No slack.reply.post span: Junior's own http.client span for chat.postMessage already appears under chat.turn. The double processing reaction on mentions is tracked in Slack mention turns add the processing reaction twice #2318.
• feat(task-execution): Accept optional trace context on inbound messages #2280 — PR 5a: mailbox accepts trace context (reader only). Add an optional, tolerant traceContext: { sentryTrace, baggage } to inboundMessageSchema: malformed values are dropped, not rejected. Nothing writes it. Deploy to production before 5b merges.
• feat(slack): Put Slack turns in the ingress trace #2406 — PR 5b: connect the trace. Ingress stores the active sentry-trace and baggage as traceContext on each Slack mailbox entry. chat.turn opens inside continueTrace with the oldest input's context, so it is a child of slack.message.ingress. It links to the other inputs' ingress spans and to the worker (queue.process) span. With no or malformed context, the turn stays under the worker span.
• feat(slack): Keep resumed Slack slices in the Turn trace #2408 — PR 6: resumed slices. The Turn cursor stores traceContext (tolerant, like the mailbox field) instead of traceId. checkpoint.ts keeps the first saved value. Every resume path (yield, timeout, OAuth, lost worker) opens chat.turn in the original trace, as a child of the span that was active at the first save, with a link to the worker span. A single PR was enough: the cursor schema strips unknown fields.
• feat(sandbox): Record sandbox acquire outcome on span #2281 — PR 7: sandbox acquire outcome. Set app.sandbox.acquire.outcome (memory / resumed / created) on sandbox.acquire. For created, the child sandbox.create span says how it was created (app.sandbox.source, app.sandbox.snapshot.*). Derive per-turn sandbox cost from existing spans.

Merge order: #2280 (5a), #2283 (PR 1), #2284 (PR 2), #2282 (PR 4), #2320 (PR 1b), #2286 (PR 3), #2281 (PR 7), #2406 (5b, after #2280 reached production), #2408 (PR 6, stacked on 5b).

Decisions

• Trace shape: the turn joins the ingress trace through continueTrace.
• Model timing: record both time to first byte (first event of any kind) and time to first token (first content event), plus the content event type.
• Scope: Slack turns first.
• Telemetry never blocks work: malformed trace context is dropped, never a reason to reject a message.
• Resumed slice parent: a resumed chat.turn is a child of the span that was active at the first save, not a sibling under slack.message.ingress. Keep this for now and adjust if traces show a need.

Related: #557 (sandbox egress span correlation).

via @thomasjiangcy.

--

View Session [Sentry]