Hermit Debugging

Debugging Hermit Runs

Thesis: reach for hermit's logs before you reach for the source. Detcore emits a rich, structured trace of every scheduling decision, syscall, and virtual-time advance. Most "why did this diverge / hang / behave oddly?" questions are answered by reading that trace or diffing two of them — not by reading scheduler.rs. Read the code only once the log has told you where to look.

All commands below assume the repo root and the release binary target/release/hermit (use target/debug/hermit if that is what you built). On Meta devservers prefix network-touching commands with with-proxy.

0. First move, always

# Separate hermit's log (stderr) from the guest's own output (stdout):
hermit --log info run -- <program> [args...] 2>/tmp/h.log
#   ^ global flag, BEFORE the subcommand.   guest stdout stays on your terminal
wc -l /tmp/h.log      # a trivial `echo hello` produces ~350 INFO lines

Do not interleave hermit logs into guest stdout. Either redirect stderr as above, or use the dedicated flag:

hermit --log info --log-file /tmp/h.log run -- <program>

--log-file (env HERMIT_LOG_FILE) writes the trace to a file and leaves the guest's stdout/stderr untouched — the cleanest way to keep the two streams apart.

Log levels (-l/--log, env HERMIT_LOG)

Per-target filtering uses tracing/RUST_LOG syntax, so you can crank up one module without drowning in the rest:

HERMIT_LOG='info,detcore::scheduler=trace' hermit run -- <program> 2>/tmp/h.log

1. How to read the trace

Every line is TIMESTAMP LEVEL target: message. The target tells you the subsystem: detcore, detcore::scheduler, detcore::scheduler::runqueue, detcore::syscalls::files, detcore::tool_global, detcore::tool_local, reverie_ptrace::task. Grep by target to isolate a subsystem.

The two message classes that matter most both live in the deterministic trace:

COMMIT lines — one per scheduler turn. This is the serialized schedule.

[sched-step5] >>>>>>>
 COMMIT turn 0, dettid 3 using resources {ParentContinue { parent: DetPid(3), child: DetPid(3) }: W}, on previously committed 1_640_995_199.000_000_000s
 COMMIT turn 1, dettid 3 using resources {MemAddrSpace(DetPid(3)): RW}, on previously committed 1_640_995_199.000_500_000s

Read it as: turn N, thread dettid, acquired these resources (R/W), at this committed virtual time. The sequence of (turn, dettid) pairs is the schedule — the single most important thing to diff between two runs.

DETLOG lines — deterministic facts: syscalls, their results, RNG seeds, etc.

DETLOG [syscall][detcore, dtid 3] inbound syscall: openat(-100, ... "/etc/ld.so.cache", OFlag(O_CLOEXEC)) = ?
DETLOG [syscall][detcore, dtid 3] finish syscall #3: openat(...) = Ok(3)
DETLOG SCHEDRAND: seeding scheduler runqueue with seed 0
DETLOG USER RAND: seeding PRNG for root thread with seed 0

inbound syscall: ... = ? is interception; finish syscall #N: ... = Ok(..) is the sanitized result handed back to the guest. A syscall that appears inbound but whose result looks like passthrough of a host value is a determinism suspect.

Virtual time (DetTime / LogicalTime). Time in hermit is logical, not wall clock. detcore-model/src/time.rs defines:

• LogicalTime(u64) — absolute nanoseconds since a fixed epoch (starting_micros, default 1640995199000000 = 2021-12-31T23:59:59). This is why guest timestamps are identical across runs.
• DetTime { syscalls, rcbs, nondet_instrs, starting_micros, multiplier } — virtual time is a deterministic function of work done, not of the host clock. It advances by counting syscalls, RCBs (retired conditional branches, from the PMU — the preemption clock), and nondet_instrs (rdtsc/cpuid).

You see it advance in the trace:

[dtid 3] inbound rdtsc, new logical time: DetTime { syscalls: 1, rcbs: 49, nondet_instrs: 1, starting_micros: 1640995199000000, multiplier: 1.0 }

and summarized at shutdown:

Internally, the hermit scheduler ran 34 turns, recorded 0 events, replayed 0 events (0 desynced)
Final virtual global (cpu) time: 1_640_995_199.019_160_055s

If the RCB counts for the same logical point differ between two runs, the guest executed a different number of branches — a real divergence, not a clock artifact.

Quick grep cookbook

grep ' COMMIT turn '            /tmp/h.log   # the schedule (turn, dettid) sequence
grep ' DETLOG '                 /tmp/h.log   # deterministic facts
grep 'inbound syscall'          /tmp/h.log   # syscalls intercepted, in order
grep 'new logical time'         /tmp/h.log   # virtual-time advances (DetTime)
grep -iE 'park|unpark|go-ahead|New thread|run queue|quiescen' /tmp/h.log  # thread lifecycle
grep -oE 'detcore[a-z_:]*'      /tmp/h.log | sort | uniq -c | sort -rn    # subsystem histogram

2. Finding a nondeterminism / divergence point

When hermit run --strict --verify reports "nondeterministic", hermit already ran twice and compared the deterministic trace. To localize the divergence yourself, capture two runs and use the built-in log differ — it is far smarter than plain diff because it normalizes known-nondeterministic noise (hex pointers, tmp paths, /proc/<pid>/, elapsed-time fields).

hermit --log info run -- <program> 2>/tmp/a.log
hermit --log info run -- <program> 2>/tmp/b.log
hermit log-diff /tmp/a.log /tmp/b.log        # compares COMMIT + DETLOG only

Useful log-diff flags (detcore/src/logdiff.rs):

Interpretation: the first divergence is the one that matters; everything after it is downstream noise. If the first diff is a COMMIT line ((turn, dettid) differs), the schedule diverged — a thread-interleaving problem. If COMMITs match but a DETLOG line differs, the schedule is stable but a syscall returned different data — an unvirtualized source.

3. Common root causes, and their log signatures

4. Debugging-specific CLI flags

Global (before the subcommand): --log, --log-file, --backend <ptrace|dbi|kvm>.

On run (see hermit run --help), the internal/debug flags:

• --panic-on-unsupported-syscalls — turn a silent fallthrough into a fatal error with a backtrace (debugging detcore itself; do not use in production).
• --stacktrace-event <index[,path]> — print the guest stack at a given schedule event; pairs with record/replay.
• --preemption-stacktrace[-log-file <f>] — dump a stack at each preemption (chaos mode).
• --debug-futex-mode <precise|polling|external> — switch the futex model when diagnosing a futex-related hang.
• --debug-externalize-sockets — treat all sockets as external/nondeterministic to isolate socket-driven nondeterminism.
• --detlog-heap / --detlog-stack — log hashes of heap/stack maps for memory-determinism (L3) checking.
• --stop-after-turn <N> / --stop-after-iter <N> — halt after a scheduler turn/loop iteration (requires --sequentialize-threads) to bisect a schedule.
• --imprecise-timers / RCB-count knobs — change how logical time is derived when the PMU is unavailable or noisy.
• --gdbserver — start a gdbserver for remote debugging.

Higher-level analysis subcommands: hermit log-diff (above), hermit analyze (analyze passing vs failing runs), and hermit bisect (--good <schedule> --bad <schedule> to localize a race between two recorded schedules).

5. Assurance ladder (name the level you reached)

Per AGENTS.md, never say "works". State the level, backend, log level, and relaxations:

• L1 deterministic: hermit run --strict completes.
• L2 bitwise-identical repeat: hermit run --strict --verify.
• L3 memory determinism: add --detlog-heap --detlog-stack.
• L4 stress-hardened: L2/L3 repeated ~20x with no divergence.

Example of a correct report: "passes at L2 (ptrace backend, --log default, relaxations: none)".

6. Source-code map (read after the log points you here)

• detcore/src/scheduler.rs — the sched loop; [scheduler], [sched-step*], and COMMIT emission (info!/debug!/trace!). The COMMIT point is step 4.
• detcore/src/logdiff.rs — the log comparator: strip_log_entry normalization, is_commit/is_detlog, LogComparisonMode, LogDiffOpts.
• detcore-model/src/time.rs — LogicalTime, DetTime, GlobalTime, and the RCB↔nanosecond conversions.
• detcore/src/syscalls/ — per-syscall handlers (files.rs, etc.).
• detcore/src/cpuid.rs, detcore/src/time.rs — CPUID and time virtualization.
• detcore/src/tool_local.rs / tool_global.rs — per-task events vs shared deterministic state (they talk over RPC).
• docs/Developers/Architecture.md — architecture overview.