| 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:
- Hypothesize. Name the one function/element/route closest to the bug (the ring-0 suspect).
- 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.)
- 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.
- 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).
- 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).
- 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.
- 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.
