Skip to content

fix(telemetry): emit task_processed from the workstream session worker (restores cron metric) - #2683

Closed
john-the-dev wants to merge 1 commit into
mainfrom
fix/workstream-worker-task-telemetry
Closed

john-the-dev wants to merge 1 commit into
mainfrom
fix/workstream-worker-task-telemetry

Conversation

@john-the-dev

Copy link
Copy Markdown
Collaborator

The regression

#2603 (isolate core sessions by workstream, merged today) routes eligible tasks — including crons — to the isolated workstream session-worker.py instead of the live core. But that worker never emitted the task_processed telemetry #2274 added on the live-core path, so cron-sourced tasks stopped being counted the moment #2603 shipped:

cron-sourced task_processed/day (PostHog, same 00:00-14:00 UTC window):
  08-02  5,774   08-03 10,492   08-04 5,901   08-05  115   <- ~98% drop

Blind spot, not an outage — crons still run and process fine; they just weren't counted.

The fix

Emit task_processed(<task.source>) after a successful publish in the worker's handle(), keyed on the task file's own source: header. Best-effort: swallowed on any error (telemetry must never break task handling), and telemetry._dispatch is already an async daemon thread, so it adds no handling latency (verified — that's why this can't regress the worker's timing tests).

Live test results

Ran the real _emit_task_processed against a real archived cron task file on this host, telemetry captured:

using real cron task file: task-cron-weekly-release-suggest-….txt
captured task_processed calls: ['cron']   -> source parsed as 'cron'
PASS: worker now emits task_processed for a cron task

Unit test added to tests/task-workstream-session-worker.test.py: source='cron' → emits 'cron'; no source header → 'unknown' (never dropped); a telemetry that raises is swallowed (best-effort). Passes.

🤖 Generated with Claude Code

#2603 routed eligible tasks (including crons) to the isolated workstream
session worker, but that worker never emitted the task_processed telemetry
#2274 added on the live-core path. Effect: cron-sourced task_processed
collapsed ~98% the day #2603 shipped (PostHog: 8,733/day -> 148) — a metrics
blind spot, not a functional outage (crons still run + process).

Emit task_processed(<task.source>) after a successful publish in the worker's
handle(), keyed on the task file's own source header, best-effort (telemetry
must never break task handling; the emit is swallowed on any error, and
telemetry._dispatch is already async so it adds no handling latency).

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
@john-the-dev john-the-dev added the ag2product AG2 product related (packages, PyPI, task-relay) label Aug 5, 2026

@sonichi sonichi left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed at head 8b28db43. The regression is real and worth fixing — but I think this fix changes what task_processed means, and the stated cause doesn't survive a check. One blocker question, two smaller items. All verified against origin/main, not inferred.

Blocker — task_processed is an ACCEPT-time event; this makes it completion-time for worker-handled tasks

src/telemetry.py:300 defines it as "One anonymous event per task the core accepts" — the activation signal for whether an install does anything after launch. Every existing emit fires at accept/creation, not completion:

site when
src/cron-runner.py:314 task_processed("cron", flush=True) at cron emission
src/agent-api.py:440/919/954/981/1211 immediately after write_text of the task file
discord/slack/telegram bridges at their own accept points
src/task-delegation.ts:56 at delegation

This PR emits after _publish_result(...), i.e. on successful completion. Two consequences I'd want resolved before merge:

  1. Possible double count. cron-runner.py:314 already emits task_processed("cron") when it writes the cron task file. If that task is workstream-assigned, it now produces two events — one at emission, one at completion.
  2. The stated cause doesn't hold as written. The body attributes the drop to "#2603 routes crons to the worker … that worker never emitted the telemetry." But #2603 does not touch src/cron-runner.py (its files: SKILL.md, agents/openai.yaml, session-worker.py, both start-cli.sh, task-notifier.sh, watch-tasks-stream.sh, and the test). An emit that fires at cron emission, upstream of routing, can't be suppressed by changing the handler.

The 98% drop is real data, so something did change — and my best candidate is a path this PR doesn't touch: #2603 modified src/watch-tasks-stream.sh, and src/task-delegation.ts:56 emits task_processed(parseTaskSource(content)) at delegation. If eligible tasks are now diverted before delegation sees them, that's where the emit was lost. I have not confirmed that — flagging it as the hypothesis to test rather than a finding.

Concretely, could you show which event the metric is supposed to be, and where the count is lost? If it's accept-time, the fix probably belongs at the routing/divert point, not at completion — and completion-time emission would inflate rather than restore it.

Test doesn't pin the fix

test_worker_emits_task_processed_mirroring_the_live_path calls worker._emit_task_processed(REPO, tf) directly. Delete the new call in handle() and this test still passes — it verifies the helper, not the wiring, and the wiring absence is the bug being fixed. Same for the live test in the body: it exercised _emit_task_processed, not handle(). Worth an assertion that a successful handle() emits exactly once.

unknown fallback doesn't hold on an unreadable file

The docstring and test say a missing source: yields "unknown" and is "never dropped". But _headers(task_file) is inside the same try/except Exception: pass, so if the task file is gone or unreadable when the emit runs (it's read after the model run, so there's a window), the exception is swallowed and nothing is emitted at all — a silent drop, the exact failure class this PR fixes. Reading the headers before the run, or giving the header read its own fallback, closes it.

What I checked and did and not verify

  • Confirmed the bug on main: session-worker.py at origin/main contains zero task_processed occurrences. The worker genuinely emits nothing.
  • Confirmed the emit is on the success path only, after _publish_result, and that best-effort swallowing means it can't break handling.
  • Not verified: whether cron tasks are in practice workstream-assigned on a typical host — that determines whether the double count is live or latent. resolve_workstream requires an explicit assignments[task_id] entry and fails open, so it isn't automatic.

@sonichi

sonichi commented Aug 5, 2026

Copy link
Copy Markdown
Owner

Follow-up — I said I hadn't verified whether cron tasks are workstream-assigned in practice, so I checked, and it cuts against the stated cause more than my review did.

On this host workspace/data/task-workstreams.json does not exist at all. resolve_workstream reads that store and returns None without it; probe() returns UNHANDLED when the id is falsy, and handle() bails on probe() != 0 before doing anything. So this worker handles zero tasks here — the new emit would never fire, and the double count I flagged is latent on this host, not live.

That's the useful part: if the worker only ever sees tasks with an explicit assignments[task_id] entry, the #2603 routing path is narrow by construction — which makes it a poor candidate for a ~98% fleet-wide drop in cron task_processed. A near-total drop needs a cause on a path that ~every cron task takes.

Caveat, stated plainly: this is one host. I cannot see whether Rui's or other fleet hosts have a populated store, and the PostHog numbers are fleet-wide. If those hosts do assign crons to workstreams, the double count becomes live there rather than latent.

Two things that would settle it faster than more code review:

  1. Is data/task-workstreams.json populated on the host(s) the 5,774/day figure came from?
  2. Does the drop line up with the src/watch-tasks-stream.sh change in feat(tasks): isolate core sessions by workstream #2603 rather than the worker — i.e. did task-delegation.ts:56's accept-time emit stop firing? That's a path every task takes, which fits a 98% drop far better.

@github-actions

github-actions Bot commented Aug 5, 2026

Copy link
Copy Markdown
Contributor

Coverage Gate

✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 77%.

Diff Coverage

Diff: origin/main...HEAD, staged and unstaged changes

  • skills/task-workstream-sessions/scripts/session-worker.py (100%)

Summary

  • Total: 11 lines
  • Missing: 0 lines
  • Coverage: 100%

@qingyun-wu qingyun-wu left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed at head 8b28db43, at the owner's request. I verified sonichi's blocker independently (from the emit sites, before reading their review) and can confirm it with additional evidence — plus one of their open hypotheses is refutable, which narrows the real question.

Confirmed: task_processed is accept-time; this PR makes it completion-time and can double-count

Every emitter on origin/main fires when the task is created/accepted, and three of them say so verbatim — the discord/slack/telegram bridges each carry the same comment: "one bucketed event per accepted task, tagged only with the inbound surface" (discord-bridge.py:3988, slack-bridge.py:1131, telegram-bridge.py:958). cron-runner.py:299-316 emits task_processed("cron", flush=True) in the same function that writes the cron task file — on origin/main today. A workstream-assigned cron task therefore already produces one event at emission; this PR adds a second at completion.

New evidence: #2603 cannot have removed an emit — none of its files ever had one

I grepped the pre-merge (a98737b~1) versions of every file #2603 touched — src/watch-tasks-stream.sh, src/agent/codex/cli/task-notifier.sh, both start-cli.sh — for task_processed/telemetry: zero occurrences (only an unrelated skill-usage-telemetry hook wiring in claude/start-cli.sh). The PR body's mechanism ("the worker never emitted what the live core emitted") has no referent: there was never a handling-time emit anywhere for the worker to be missing.

Refuted: the divert-point hypothesis (sonichi flagged it as untested — I tested it)

task-delegation.ts's emit lives in LocalTaskBackend.submitTask() (task-delegation.ts:85-88): it fires immediately after writeFileSync of the task file — creation-time, upstream of the watcher, so no routing change in watch-tasks-stream.sh can bypass it. And its own header comment scopes it to "locally-created tasks (voice, chat, context-drop)" — it cannot be the source of cron-tagged events. That path is not where the metric was lost.

The remaining open question — worth answering before any fix

None of the traced emitters explains 5,774–10,492 cron events/day collapsing to 115 via anything #2603 touched. The launchd cron-runner writes far fewer task files than that, and no #2603 file ever emitted. Before re-wiring telemetry, it would be worth pulling one PostHog event's properties (install-id spread, flush vs async path) to identify which emitter produced the pre-drop volume — otherwise the fix is aimed at a mechanism the data doesn't implicate. If the drop is fleet-wide and real, the producing site is one we haven't identified, and this PR wouldn't restore it — it would add a different (completion-time) signal that happens to have the same name.

Smaller items (both align with sonichi's)

  • The new test calls worker._emit_task_processed(...) directly — delete the new call in handle() and the test still passes (the wiring absence is the bug class). I ran the test in isolation: it passes, but it pins the helper, not the fix.
  • If completion-time counting is genuinely wanted (it's a reasonable product question!), the clean shape is a new event name (task_completed) rather than overloading task_processed — that preserves the accept-time activation metric's meaning and gives you the completion funnel as a separate series.

Supporting sonichi's CHANGES_REQUESTED; not stacking a second one.

@qingyun-wu qingyun-wu left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed current head 8b28db4.

Blocking findings:

  • [P1] skills/task-workstream-sessions/scripts/session-worker.py:367-370 emits task_processed after _publish_result, which changes the metric from accept-time to successful-completion-time for worker-handled tasks. src/telemetry.py defines task_processed as one event per task the core accepts, and existing sites emit at accept/delegation time: cron-runner at src/cron-runner.py:314, task-delegation at src/task-delegation.ts:56, plus the agent-api and bridge accept paths. A cron/workstream task can now be counted at emission/delegation and again at completion, while failed worker tasks disappear from the activation metric. Please emit at the routing/accept point that diverts to the worker, or otherwise preserve the accept-time contract and document a separate completion metric if that is intended.
  • [P2] tests/task-workstream-session-worker.test.py:824-855 calls _emit_task_processed(...) directly, so deleting the new call from handle() would still leave the new test green. The regression is missing wiring in the worker success path; please assert through handle() that a successful worker-handled task emits exactly once, and ideally that telemetry failure remains best-effort.
  • [P2] skills/task-workstream-sessions/scripts/session-worker.py:337-345 reads headers from the task file inside the broad best-effort telemetry block after the worker has finished. If the task file is unreadable or has already been moved/removed, the whole emit is swallowed instead of falling back to the advertised unknown source. Please derive the source while accepting the task, or catch header read failures separately and still emit unknown.

Focused checks run in an isolated /private/tmp checkout:

  • git diff --check origin/main...HEAD
  • python3 tests/task-workstream-session-worker.test.py

Reviewed by Qingyun's Personal Codex.

@sonichi

sonichi commented Aug 5, 2026

Copy link
Copy Markdown
Owner

Retracting the hypothesis I floated, so you don't spend time on it.

I suggested the count might have been lost at src/task-delegation.ts:56 because #2603 modified src/watch-tasks-stream.sh. I tested it and it doesn't hold. emitTaskProcessed is called on task submission — its own comment says it must not "block or throw into task submission", i.e. the voice/chat/context-drop path — not on the watcher path. And TASK_FILE's only other consumer is src/agent/codex/cli/task-notifier.sh. #2603's dispatch layer wouldn't suppress that emit for cron tasks.

So the mechanism for the drop is still unestablished, and that's the part I'd want nailed before the fix lands. The accept-time cron emit is src/cron-runner.py:314 (task_processed("cron", flush=True)), which #2603 does not touch — so on the code I can see, cron tasks should still be counted at emission regardless of routing.

That leaves a few possibilities worth distinguishing, and the PostHog data probably separates them faster than reading code:

  • Did the drop hit only source: cron, or other sources too? A broad drop points at the emitter/collector, not at routing.
  • Is cron-runner.py (launchd) actually the producer of the tasks behind the 5,774/day figure, or are those from a different path that does pass through the worker?
  • Did anything else land in the same window — a telemetry opt-out, a collector change, or a host that stopped running crons?

My blocker from the review is unchanged and independent of this: task_processed is defined as an accept-time event (src/telemetry.py:300) and every existing emit fires at accept, so adding a completion-time emit changes the metric's meaning and risks double-counting against cron-runner.py:314. That holds whatever the drop's cause turns out to be.

@john-the-dev

Copy link
Copy Markdown
Collaborator Author

Closing per owner decision. Verified against PostHog: task_processed is healthy and growing (Aug 3 = 23.8k, Aug 4 = 21.9k), so there was no historical outage to fix — the Jul-29 cron jump was the #2274 instrumentation newly counting crons, which I mis-read as a drop. And #2603 only merged today (2026-08-05T13:14Z), so it can't have caused a past regression. The reviewers were also right that the completion-time emit would double-count crons and drop failed tasks. If the #2603 optional task-handler is activated in production and diverts tasks from the core, the correct fix is a single accept-time emit at the worker's claim point — will open that separately if the data shows an emerging gap. Thanks @sonichi and @qingyun-wu for the careful review.

@sonichi

sonichi commented Aug 5, 2026

Copy link
Copy Markdown
Owner

Narrowing my own blocker, since it is gating a fix that was asked to be prioritized. One half weakens, the other stands.

Weakened — the double count is conditional, not automatic. I flagged that cron-runner.py:314 already emits at cron emission, so a worker completion-emit would count the same task twice. That requires the task to be workstream-assigned, and I checked how assignment happens: resolve_workstream reads data/task-workstreams.json, and the only assignment path I can find is POST /tasks/workstreams/infer, documented in src/agent-api.py as an "authenticated manual workstream-classifier trigger". So tasks are not auto-assigned as they arrive — the double count needs a manual classifier run that assigns a cron task. Reachable, but not the default, and on this host the store does not exist at all. I should not have implied it was automatic.

Stands, and it is the one I would actually gate on — it is independent of routing. src/telemetry.py:300 defines task_processed as "one anonymous event per task the core accepts", and every emit site fires at accept: cron-runner.py:314, agent-api.py (×5, immediately after write_text), the three bridges, task-delegation.ts:56, conversation-server.ts:431. This PR emits after _publish_result, on successful completion. That makes one event name mean "accepted" for most sources and "completed" for worker-handled ones, so any aggregate over it silently mixes two populations — and completion-emission also drops tasks that fail, which an activation metric should still count.

If the goal is genuinely to count cron acceptance, the emit belongs where the task is accepted, and the question stays the one from my last comment: which event is the 5,774/day figure made of, and where did it stop being produced? If the goal is a new completion metric, that is a defensible thing to want — but it should be a new event name, not this one.

Disclosure on my evidence: this checkout is 67 commits behind and does not contain skills/task-workstream-sessions/ at all, so my first grep for the assignment writer returned zero hits and I nearly read that as "nothing writes it". Everything above was re-read at origin/main.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ag2product AG2 product related (packages, PyPI, task-relay)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants