mcu-diagnostics

name

mcu-diagnostics

description

Use when reading MCU diagnostics / crash forensics from the kalico structured logs — why an MCU reset/crashed/stalled/wedged, dumping the live MCU diag on demand (KALICO_DIAG_DUMP), reading the event-ring play-by-play, decoding a fault PC / reset cause / USB-ISR hog, or checking for hiccups after a manual test. Covers the events/*.jsonl store and the runtime.*/diag.* event catalog. For general LogsQL filtering use query-logs.

Reading MCU diagnostics & crash forensics

The MCU emits structured records (no printf) over MCU_MSG_LOG → the host writes them to ~/printer_data/logs/events/<source>.jsonl. This is the source of truth for MCU diagnostics — it supersedes the old klippy.log text dump.

Sources: mcu (H7 / main), bottom (F4) — the value is each MCU's klippy name. Also present: host-py (mirrors klippy.log content, structured), host-rust (motion-engine). Rotating: 32 MB × 5 backups (.1...5) per source.

For querying by session/print/level/field, use the query-logs skill (LogsQL over VictoriaLogs). This skill covers the MCU-specific features and event catalog and direct raw-file reading.

Three ways MCU diag reaches the store

Tier	Trigger	What you get
Live faults	engine raises a fault	runtime.fault_latched immediately (with code_name)
On-demand dump	KALICO_DIAG_DUMP gcode	full live diag snapshot now, no reset
Crash replay	the boot after a reset	prior-boot crash forensics (auto, once, at axis-config time)

The MCU only keeps the last 32 events in its ring (overwrites oldest) plus whole-run counters/maxima. So dump while evidence is fresh; a hiccup from hour 1 of a long run is gone by hour 3.

KALICO_DIAG_DUMP — check live state without a reset

Run it from the console, or via Moonraker:

ssh trident "curl -s -X POST http://localhost:7125/printer/gcode/script \
  -H 'Content-Type: application/json' -d '{\"script\":\"KALICO_DIAG_DUMP\"}'"

It sends kalico_diag_dump to every MCU; each emits (all debug): runtime.diag_dump (header: uptime_us, ring_seq) + runtime.isr_phase / block_source / tim5_ia + runtime.fg_freeze (if a stall latched) + the live event ring as diag.*, oldest-first. Then read the tail (recipe below).

Manual-test flow: run your test → KALICO_DIAG_DUMP → read events/<mcu>.jsonl.

Reading "why did it crash?"

After a reset the next boot replays the prior-boot forensics automatically (once, at axis-config time). Start at block_source, NOT mcu_reset — the reset cause bits are usually masked (see gotcha), so they are not the cause. Read the rest as a story:

• runtime.block_source usb_burst/stepout_burst (DWT cycles) — who hogged the CPU; this is the usual root cause. A burst > ~2× the sample period starves the foreground — period ≈ 52000 cyc (H7), ≈ 9000 cyc (F4), so > ~105k / ~18k is bad. ÷ core freq (H7 ~520 MHz, F4 ~180 MHz) → µs.
• runtime.tim5_ia min/max vs the sample period (≈52000 H7 / ≈9000 F4 cyc) — was the engine itself starved? min ≈ period & short ISRs ⇒ engine innocent.
• runtime.isr_phase — which engine phase ran (RT_PHASE_*; 9 = ISR_EXIT = engine was exiting cleanly).
• runtime.fg_freeze pc/stall_ticks — where the foreground hung (addr2line).
• runtime.hard_fault + runtime.fault_status — only for a real CPU fault (exc_kind, PC, LR, CFSR, HFSR).
• diag.* ring — the lead-up timeline (USB gaps, TIM5/OTG long ISRs, TX drops, engine transitions, rust faults).

Decode a pc (from fg_freeze/hard_fault) — the elf must match the flashed build: ssh trident "arm-none-eabi-addr2line -e ~/klipper/out/klipper.elf <pc-as-hex>" (the arg0 values are decimal in the log; convert to hex first).

Gotcha: block_source/tim5_ia are whole-run maxima since boot, not instantaneous. In a crash-replay they're the doomed run's worst → the real cause. In a live KALICO_DIAG_DUMP a big usb_burst is often just the connect-time spike, not "now" — trust the diag.* ring for the recent timeline.

Gotcha: klippy's connect-reset masks the immediate RCC cause, so the crash report is gated on a per-run freeze flag, not runtime.mcu_reset's cause bits (which may show SFTRST). iwdg_resets is a cumulative counter, not this crash.

Event catalog

level: trace|debug|warn|error. Numeric payload in arg0/arg1; faults also carry code + code_name. Canonical table: rust/runtime/src/log_codes.rs.

event	args	meaning
runtime.fault_latched	code=FaultCode, arg0=detail	engine fault (live)
runtime.mcu_ready	—	boot marker, drain online
runtime.log_drops	arg0=dropped	log-ring overflow (fail-loud)
runtime.mcu_reset	arg0=RCC bits, arg1=cum. IWDG	reset marker — cause bits often masked; not the cause (use block_source)
runtime.hard_fault	code=exc, arg0=pc, arg1=lr	CPU fault
runtime.fault_status	arg0=cfsr, arg1=hfsr	CPU fault regs
runtime.fg_freeze	arg0=pc, arg1=stall_ticks	foreground hung
runtime.rt_progress	arg0=packed, arg1=fault_count	engine progress at crash
runtime.last_dispatch	arg0=func, arg1=addr	last scheduler callback
runtime.isr_phase	arg0=RT_PHASE_*, arg1=ring_overflow	engine ISR phase (high ring_overflow = heavy event churn)
runtime.block_source	arg0=usb_burst, arg1=stepout_burst (cyc)	CPU hog
runtime.tim5_ia	arg0=min, arg1=max (cyc)	TIM5 inter-arrival
runtime.diag_dump	arg0=uptime_us, arg1=ring_seq	live-dump header
diag.tim5_long / diag.otg_long	arg0=dur cyc, arg1=enter	long ISR
diag.usb_in_gap / diag.usb_out_gap	arg0=gap, arg1=prev_t	USB stall
diag.tx_drop_kalico / diag.tx_drop_klipper	arg0=len/max, arg1=tpos	dropped TX
diag.engine_xition	arg0=(prev<<8|new), arg1=samples	engine state change
diag.rust_fault	arg0=err, arg1=detail	rust fault in the ring
motion.piece_start_past / motion.ring_full	…	motion engine
tick.interval_exceeded / tick.underrun	…	tick ISR
endstop.trip / endstop.arm_timeout	…	endstop

Reading the raw files

Fetch a snapshot first (don't analyze the live file):

scp trident:'~/printer_data/logs/events/mcu.jsonl' /tmp/mcu-$(date +%s).jsonl

Filter (no jq dependency) — level + event + message, newest activity last:

tail -400 /tmp/mcu-*.jsonl | python3 -c '
import sys,json
for l in sys.stdin:
 l=l.strip()
 if not l: continue
 try: d=json.loads(l)
 except: continue
 ev=d.get("event","")
 if ev.startswith("runtime.") or ev.startswith("diag."):
  print(d.get("level"), ev, "|", d.get("_msg",""))'

By one event: grep -a '"event":"runtime.block_source"' /tmp/mcu-*.jsonl. Each boot's forensics follow a runtime.mcu_ready marker; the last mcu_ready in the file is the current boot, so the crash story is the runtime.*/diag.* block right after the most recent mcu_ready. A record looks like: {"_time":"…","level":"warn","source":"mcu","event":"runtime.block_source","arg0":137808,"arg1":0,"_msg":"block usb_burst=137808 cyc stepout_burst=0 cyc"}

For indexed queries (by session_id, print_id, numeric ranges, code resolution), use query-logs instead of grepping.

When klippy.log is still useful

The structured store replaces klippy.log for MCU diagnostics. klippy.log keeps: host-side Python tracebacks, and the verbose prior_diag_summary_* deep-debug text (TIM5/RT histograms, USB register snapshots, task heartbeats, bfar/mmfar) — fields the structured path doesn't carry, retained as the robust always-works fallback for when the host structured-logging layer is unavailable.

Adding new MCU logs

Pick/add an event in rust/runtime/src/log_codes.rs (the wire-stable table), mirror any new C event in src/kalico_log.h, and call kalico_log_emit(level, subsystem, event, code, arg0, arg1) at the emit site. Engine faults go through the raise_* helpers in rust/runtime/src/fault_helpers.rs (auto-emit runtime.fault_latched).