trace

name

trace

description

Add precise timestamped debug logging across PrairieLearn using the concentric/adaptive model — start at the code CLOSEST to the issue (ring 0), read the merged cross-process timeline, widen the field only if the narrow ring didn't reveal it. Covers the TS⇄Python boundary, SQL, sockets, and the zygote via @pldebug/trace. Runs inline. Use when the user says "add logging", "trace this", "instrument", "where is time going", "why is this swallowed", or when debug-issue reaches CLASSIFY and the cause isn't obvious.

trace

Get one sortable, correlated timeline across Node, SQL, the TS⇄Python code-caller boundary, and Python — then read it. Mechanics: @pldebug/trace README. Seams: reference/control-surfaces.md.

The method (concentric — this is the whole point)

Don't instrument the whole app. Place logs in rings and expand only on miss:

1. Hypothesize. Name the one function/element/route closest to the bug (the ring-0 suspect).
2. Install the spine. ./scripts/inject-trace.sh --worktree <wt> — copies pldebug-trace.ts and pldebug_trace.py in. No app behavior changes yet. (Add --seam to auto-wire the TS⇄Python boundary correlation — see below.)
3. Ring 0 — closest to the issue. Add a few trace() calls inside the suspect code:
   • TS: import { trace } from './pldebug-trace'; trace('freeform:grade', 'enter', () => ({ qid }), 0);
   • Python: from pldebug_trace import trace, span; trace('zygote:call', 'recv', {'file': file}, ring=0, corr=call_id)
   • Put one at entry, one at each branch/return, one before the suspect await/call.
4. Reproduce. ./scripts/run-journey.sh --issue N --ring 0 → /tmp/prairielearn-debug/<id>/logs/trace.log (a --variant after-fix run writes trace-after-fix.log — compare it against the baseline trace.log).
5. Read the timeline.
   • sort <trace.log> | less — true cross-process order (timestamp is the first token).
   • tsx packages/dev-tools/src/trace-reader.ts <trace.log> --corr <id> — one request across layers + the slowest gaps (the stall).
6. Narrow or widen:
   • Cause visible? Stop. You're done — fix it.
   • Cause is upstream/elsewhere? Move ring 0 to the new suspect, or step out one ring:
     • Ring 1 — immediate boundary: the code-caller call it makes (code-caller-native:call, log JSON in/out with a shared call_id), or its 2–3 SQL queries.
     • Ring 2 — whole layer: ./scripts/inject-trace.sh --worktree <wt> --wide (routes all existing PL logger output into the trace file) + PL_DEBUG=prairielearn:*, and wrapPool(sqldb) for all SQL. Re-run with --ring 2.
7. Fix, then re-run and confirm the timeline shows the corrected path.

Correlation across the TS⇄Python boundary

The hardest PL bugs hide where Node hands a call to the Python zygote (errors get swallowed into the call's output). ./scripts/inject-trace.sh --worktree <wt> --seam wires this for you (reversible): a server middleware binds one corr id per request, the code-caller stamps it into every Python call payload, and the zygote reads it back — so code-caller-native:call sent and zygote:call recv share the id. Then sort / --corr <id> lines up "Node sent at T1 / Python ran at T2 / returned at T3" (and the slowest-gap surfaces the stall — e.g. the zygote's ~10s cold-import warmup). To carry it by hand instead: stamp the id with withCorrelation on the Node side, pass it in the stdin payload, print it from pldebug_trace.trace(..., corr=call_id).

Rules

• Ring discipline. Default --ring 0. Widening is a deliberate step, not the start. A 5000-line trace you can't read is a failure.
• Lazy payloads. TS data arg is a factory () => ({...}) — never build expensive objects when tracing is off.
• stderr is free in the zygote — Python trace() writes there, and Node folds it into the same stream, so you often don't need the file write.

Cleanup

./scripts/inject-trace.sh --worktree <wt> --revert strips every inserted block and the copied primitives. Run it before keeping the branch; confirm with git -C <wt> diff --stat.