Fix: keep forked host log records intact

[sunkaixuan2018]

Summary

• format each host log record dynamically and emit it with one write, preventing forked chip workers from interleaving STRACE records on shared stderr
• parse every STRACE marker on a physical line instead of letting greedy attrs consume later records
• add deterministic forked-process logger and adjacent-record parser regressions

Testing

• baseline regression: test_host_log_off fails on main with two child records merged onto one physical line
• ctest -R '^test_host_log_off$': 8/8 passed
• pytest tests/ut/py/test_strace_timing.py -q: 1 passed
• ctest -LE requires_hardware: 79/79 passed
• pre-commit checks passed, including formatting, Ruff, cpplint, pyright, headers, and clang-tidy
• full Python UT collection was blocked by the remote environment's stale editable install/Torch visibility; the targeted Python regression passed in an isolated checkout

Fixes #1690

[coderabbitai]

Important

Review skipped

Auto incremental reviews are disabled on this repository.

Please check the settings in the CodeRabbit UI or the .coderabbit.yaml file in this repository. To trigger a single review, invoke the @coderabbitai review command.

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro Plus

Run ID: 581800aa-e7aa-4c7f-bfa1-9fb768bbfc6b

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Use the checkbox below for a quick retry:

• 🔍 Trigger review

📝 Walkthrough

Walkthrough

Host logging now formats complete records and writes them through one retrying write path. A multi-process pipe test validates record integrity. STRACE parsing now yields adjacent marker records from one physical line, with unit coverage.

Changes

STRACE logging integrity

Layer / File(s)	Summary
Atomic host record emission src/common/log/include/host_log.h, src/common/log/host_log.cpp	HostLogger formats each record before writing it through a retrying stderr path. The header uses #pragma once and retains the va_list contract.
Concurrent record validation tests/ut/cpp/a5/test_host_log_off.cpp	A fork-based test writes large records from 16 child processes through one pipe and validates record completeness, uniqueness, attribution, payloads, and count.
Adjacent STRACE record parsing simpler_setup/tools/strace_timing.py, tests/ut/py/test_strace_timing.py	parse_spans yields all complete matches on each line. The test verifies adjacent records, identifiers, names, and attributes.

Estimated code review effort: 3 (Moderate) | ~25 minutes

Poem

I’m a rabbit with records in line,
Whole logs now hop through the pipe just fine.
Two STRACE marks share one row,
Both emerge in the parse flow.
No torn tails—just timing to show!

🚥 Pre-merge checks | ✅ 5

✅ Passed checks (5 passed)

Check name	Status	Explanation
Title check	✅ Passed	The title clearly describes the primary fix for preserving host log records across forked processes.
Description check	✅ Passed	The description directly explains the logging fix, parser fix, regression tests, and validation results.
Linked Issues check	✅ Passed	The PR addresses #1690 by making host records contiguous, parsing adjacent STRACE records, and adding regression tests for both failure modes.
Out of Scope Changes check	✅ Passed	All changes support the host logging fix, STRACE parsing fix, or their regression coverage; no unrelated code changes are evident.
Docstring Coverage	✅ Passed	No functions found in the changed files to evaluate docstring coverage. Skipping docstring coverage check.

---

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands.}

[coderabbitai]

Actionable comments posted: 2

🤖 Prompt for all review comments with AI agents

Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In `@simpler_setup/tools/strace_timing.py`:
- Line 54: The regex pattern's lookahead in strace_timing.py is including
intervening content (timestamp and TIMING prefix) in the attrs capture group
instead of terminating before the next host-log record prefix. Update the
lookahead boundary at the end of the pattern to match the start of the next
complete host-log record format, ensuring attrs captures only the actual
attributes without bleeding into the next record. Additionally, in
test_strace_timing.py, replace the startswith assertion on the attrs value with
an equality check for "rank=0" so the test detects this boundary corruption by
requiring an exact match rather than a partial one.

In `@src/common/log/host_log.cpp`:
- Around line 35-66: The write_stderr function does not enforce a PIPE_BUF limit
on the record size, allowing records larger than the atomic write boundary to be
interleaved with writes from other processes. Add a check at the start of
write_stderr to cap or route records that exceed PIPE_BUF—either by truncating
the record to fit within PIPE_BUF before the write loop begins, or by routing
oversized records to an alternative sink and emitting an instrumentation error.
Ensure the record remains atomic within the PIPE_BUF boundary to prevent
interleaving with concurrent child process writes.

🪄 Autofix

Fix all unresolved CodeRabbit comments on this PR:

• Push a commit to this branch (recommended)
• Create a new PR with the fixes

---

ℹ️ Review info

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro Plus

Run ID: f7c49780-410b-47d5-abcc-800381339b36

📥 Commits

Reviewing files that changed from the base of the PR and between b3bf3e7 and 3cfe35a.

📒 Files selected for processing (5)

• simpler_setup/tools/strace_timing.py
• src/common/log/host_log.cpp
• src/common/log/include/host_log.h
• tests/ut/cpp/a5/test_host_log_off.cpp
• tests/ut/py/test_strace_timing.py

[ChaoZheng109]

Reviewed the merge-base diff (639b95fbe...87a75b55e). Summary below, details in the inline comments.

What the PR does

HostLogger::emit wrote one logical record through four stdio calls under a process-local mutex, so forked chip workers sharing a captured stderr interleaved partial records; the parser then took one record per line with a greedy attrs, losing anything that followed. This PR buffers each record and emits it with a single write, and teaches the parser to read every marker on a line. Root cause and mechanism both look correctly identified.

The C++ regression test is well built: 16 forked children through a shared pipe, a start-pipe barrier so they actually contend, the reader thread started before the children are released so a full 64K pipe cannot deadlock it, and a per-line check that no record was spliced. CI is green across all 17 checks.

Against the suggestions in #1690

• (1) contiguous buffer + one atomic write — done.
• (2) harden parse_spans — half done. Multiple markers per line are handled; torn records are still dropped silently. See the inline comment on parse_spans.
• (3) validate rank/round counts and (4) stop reporting missing spans as 0.0 — correctly out of scope, and worth stating explicitly in the PR description: effective_us has zero occurrences in this repo, it lives in pypto-lib's benchmark. This is not a goal downgrade.
• (5) multi-process test — done.

Missing documentation

"one record, one write, indivisible up to PIPE_BUF" is now a contract that multi-process consumers depend on, and nothing records it. Two places need it in this same commit (.claude/rules/doc-consistency.md section 4):

• docs/logging.md section Output formats — state the guarantee, that it rests on the single write rather than on mutex_ (which each forked process holds its own copy of), and that records longer than PIPE_BUF are still splittable.
• docs/dfx/host-trace.md:25 — "One line per span" is no longer true now that a physical line can carry several markers. That file is the marker-grammar reference, so someone reading it would write exactly the one-match-per-line parser this PR is fixing.

Same defect class in the sim backend (not this PR's job)

src/common/platform/sim/aicpu/device_log.cpp still emits a record via fprintf + vfprintf + fputc with no lock at all, so sim interleaves across forked chip workers and across plain AICPU sim threads — aicpu_thread_num > 1 alone is enough, no fork needed. Filed separately as #1697. Not asking for it here, but a line in the PR description would stop readers assuming the defect class is gone repo-wide. Onboard is unaffected: it buffers into char buffer[2048] and issues one dlog_* call.

Verdict

Approve with comments. Worth resolving before merge: the re.MULTILINE anchor and the torn-record counter — both small, and both close the same "records vanish silently" gap this PR exists to fix. The ostringstream performance note is optional, but there is a concrete alternative that is faster and keeps the atomicity.

[ChaoZheng109]

Should fix. The \r?$ alternative only anchors at the end of the string — re.MULTILINE is not set. Since . never crosses \n, attrs stops at a newline, and at that position none of the three alternatives can match, so the whole record fails to match.

Effect: if a caller passes a multi-line chunk instead of one line per item, every record except the last is silently dropped. Measured against this branch:

input: two complete records, each on its own line, joined into one string
  old regex (main): finds record 1
  this regex:       finds only record 2   <- record 1 lost
  + re.MULTILINE:   finds both

In-repo this does not bite, because main() uses readlines(). But parse_spans is a module-level function consumers (pypto-lib) can call with a blob, and silently losing records is exactly the failure class this PR is fixing.

Adding re.MULTILINE to the re.compile(...) call is enough. I checked it leaves every other case unchanged: single line with and without trailing newline, CRLF, two records on one line, and the real [file:line] prefix form.

[sunkaixuan2018]

Fixed in dffab7e — added re.MULTILINE to the re.compile(...) call.

Confirmed your reproduction on this branch: two complete records joined into one string, the first was dropped silently. With MULTILINE both are found. I re-checked the cases you listed and they are unchanged — single line with and without a trailing newline, CRLF, two records on one physical line, and the real [file:line] prefix form.

test_parse_spans_keeps_every_record_of_a_multi_line_blob now pins this.

[ChaoZheng109]

Should fix. This covers the first half of suggestion (2) in #1690 — find multiple markers on a line — but not the second, detecting malformed/torn input. A record torn mid-write still yields nothing and produces no signal at all, which is precisely how #1690 manifested: effective_us=0.0 with no way to distinguish instrumentation loss from a real measurement.

Suggestion: count record heads per line and compare against the number of spans actually yielded; if the totals differ, print one warning to stderr in main() before the table. Cheap, and it converts a silent data loss into something the operator can see.

Matching the head ([STRACE] v=) rather than the bare [STRACE] literal keeps false positives away from prose that happens to mention the marker.

[sunkaixuan2018]

Fixed in dffab7e, taking your suggestion as described.

count_record_heads(lines) counts [STRACE] v= heads independently of whether the rest of the record survived, and main() prints one stderr warning before the table when that total exceeds the spans actually parsed:

warning: 1 of 2 [STRACE] records are incomplete and are excluded from the timing below

Matching the head rather than the bare [STRACE] literal, as you suggested. test_count_record_heads_sees_a_torn_record_that_parse_spans_drops covers it.

[ChaoZheng109]

Consider (performance). The single-write fix is right, but ostringstream is an expensive way to reach it — and this PR's whole purpose is trustworthy benchmark timing.

Per record this now does: a sizing vsnprintf, a std::vector<char> heap allocation, a second vsnprintf, a std::string copy, then an ostringstream (allocating again) for the prefix. Measured on this branch (aarch64, -O2, 200k calls through HostLogger::log with stderr on /dev/null, best of 3 runs):

variant	ns/record
main (fprintf x4, non-atomic)	~1400
this PR (ostringstream)	~2100
stack buffer + snprintf	~1000

The atomicity does not require the extra cost. Rendering the whole record (prefix + message + newline) with snprintf/vsnprintf straight into a fixed stack buffer, falling back to a heap buffer only when it does not fit, still emits exactly one write — and lands ~30% faster than main instead of ~50% slower. snprintf returns the length it needed, so "did it fit" is just comparing that against the buffer size, and the second render only happens on the rare oversized record.

Why it matters here specifically: a span's own dur is sampled before its marker is emitted, but a parent span's dur includes every child's emit cost, and PYPTO_BENCH's per-round wall clock includes all of it. At ~10 spans per decode invocation that is a few microseconds added to every measured round.

Mitigating: it is only paid when tracing is on (is_enabled short-circuits above TIMING) — but that is exactly the configuration this PR targets.

The onboard AICPU backend already uses this shape (char buffer[2048] + one dlog_* call, src/common/platform/onboard/aicpu/device_log.cpp), so it would also make the two backends consistent.

[sunkaixuan2018]

Fixed in dffab7e — ostringstream is gone, replaced by the stack-buffer + snprintf shape you described, with a heap buffer allocated only when the record does not fit (snprintf reports the needed length, so the second render only happens on the rare oversized record).

I reproduced your benchmark independently and got the same ordering (aarch64, -O2, 200k calls through HostLogger::log, stderr on /dev/null, three runs each):

variant	ns/record
main (fprintf x4, non-atomic)	1401–1450
previous commit (ostringstream)	2428–2472
this commit (stack buffer + snprintf)	926–982

So ~34% faster than main rather than ~74% slower, and the single write is unchanged.

Two notes on the implementation:

• The record is now formatted outside the mutex; only the write is under it. That was already true in intent, but the ostringstream version built the string before taking the lock too, so this is not a new property — just no longer paying for it.
• kRecordStackCapacity is 2048, matching the AICPU backend you pointed at. The fork test in this PR writes ~2.1 KB records, so it exercises the heap fallback rather than skipping over it.

[ChaoZheng109]

Should fix. This holds for STRACE markers but not for HostLogger's other callers, and the comment reads as an unconditional invariant.

A long LOG_ERROR — a diagnostic dump, say — pushes the record past PIPE_BUF, at which point write_stderr's partial-write loop is exactly where tearing happens, silently.

Suggest wording it as the conditional it actually is: records at or below PIPE_BUF are indivisible, longer ones can still be torn. Per .claude/rules/comments.md a comment should state a fact that holds as written.

[sunkaixuan2018]

Fixed in dffab7e. You are right that it read as an unconditional invariant, and it is not one. New wording:

// One write per record: a record of at most PIPE_BUF bytes reaches a shared
// pipe indivisibly, so forked workers writing a captured stderr cannot
// interleave inside it. A longer record — a large LOG_ERROR dump, say — has
// no such guarantee; STRACE markers stay well below the limit.

This also answers the CodeRabbit finding on the same lines, which asked for a hard PIPE_BUF cap. I did not add one: truncating or rerouting every long record would regress large LOG_ERROR diagnostic dumps to fix a case that only arises when several forked processes share one stderr pipe and a single record exceeds PIPE_BUF. Stating the boundary honestly is the cheaper correct answer.

[ChaoZheng109]

Consider. This guard swap is unrelated to the fix. The repo carries both styles (67 files use #pragma once, 125 use include guards), so it is not a style violation — but per .claude/rules/discipline.md section 2 every changed line should trace back to the request, and an unrelated hunk costs reviewer attention and invites conflicts.

The vlog comment update just below is the opposite case and should stay: the old text claimed the path avoided "an intermediate vsnprintf-to-buffer round-trip", which this PR makes untrue, so updating it is required doc-consistency work.

[sunkaixuan2018]

Keeping this one, but flagging the reason rather than just overruling you — happy to revert if you still disagree.

.claude/rules/codestyle.md §12 makes #pragma once the convention and explicitly sanctions this edit:

Use #pragma once for header guards, not #ifndef/#define/#endif. […] Existing files are converted on sight during routine edits; a dedicated sweep is not required.

"On sight during routine edits" is exactly this case — the PR already modifies this header for the vlog comment you noted should stay, so the file was being touched regardless. The 67/125 split you measured is the migration in progress rather than a settled two-style equilibrium.

I read discipline.md §2 as aimed at drive-by reformatting and unrelated refactors; a conversion an always-loaded rule instructs you to make while editing the file is the sanctioned exception. If you would still rather keep the diff minimal, say so and I will drop the hunk.

[ChaoZheng109]

Consider. This fixture is not quite the real wire shape. LOG_TIMING prepends [%s:%d] (__FILENAME__, __LINE__) to the caller's format string (src/common/log/include/common/unified_log.h:45), so on stderr the marker is preceded by e.g. [strace.h:132] rather than sitting flush against the func: separator. I checked that the regex handles the real form correctly, so this is not a bug — but the test guards a simplified input, which weakens it as a regression barrier.

Also worth a comment near _HOST_LOG_PREFIX: its [^:\r\n]+ for the func segment relies on func being __FUNCTION__, i.e. an unqualified name. If a qualified name containing :: ever reached it, the prefix alternative would stop matching and attrs would silently absorb the next record's timestamp prefix — the [STRACE] alternative would still recover the following span, so it would degrade quietly rather than fail loudly. Worth pinning down as an assumption.

[sunkaixuan2018]

Fixed in dffab7e — both parts.

The fixture is now built by a _record() helper that emits the real wire shape, including the [strace.h:132] segment LOG_TIMING prepends, so the marker no longer sits flush against the <func>: separator. All three parser tests share it.

And the [^:\r\n]+ assumption is now written down at _HOST_LOG_PREFIX:

# The host-log record prefix `HostLogger::emit` writes ahead of every message.
# Its func segment excludes : because `LOG_TIMING` passes `__FUNCTION__`, an
# unqualified name; a qualified name containing :: would stop this alternative
# from matching, leaving the `[STRACE]` alternative to bound the record instead.

That records both the assumption and the degradation mode you described.

[sunkaixuan2018]

Addressed @ChaoZheng109's review in dffab7e. Five of the six are fixed; one I am pushing back on with a rule citation, in that thread.

• re.MULTILINE — fixed. Reproduced the multi-line-blob drop first; both records survive now.
• Torn-record signal — fixed. count_record_heads() plus a one-line stderr warning from main().
• ostringstream cost — fixed, replaced by stack buffer + snprintf with a heap fallback. Independently re-measured: 1401–1450 ns/record on main, 2428–2472 on the previous commit, 926–982 now (aarch64, -O2, 200k records, best of 3).
• PIPE_BUF comment — fixed, now states the boundary as the conditional it is. This also answers CodeRabbit's request for a hard cap on the same lines; I explain there why capping would regress long LOG_ERROR dumps.
• Test fixture wire shape — fixed, the fixture now carries the [<file>:<line>] segment LOG_TIMING prepends, and the __FUNCTION__ assumption is documented at _HOST_LOG_PREFIX.
• #pragma once — keeping it; .claude/rules/codestyle.md §12 directs converting headers "on sight during routine edits", and this PR edits the header anyway. Will drop the hunk if you would still rather keep the diff minimal.

Validation on an aarch64 box: 80/80 non-hardware C++ tests pass, the forked-pipe test passes 10/10 standalone, the 3 parser tests pass, and pre-commit is clean on all touched files.