Fix: make host logging nonblocking and unify sim output

docs/dfx/host-trace.md

@@ -40,7 +40,7 @@ writes follows it: `LOG_*` records, `[STRACE]` spans, `[CLOCK_ANCHOR]`, the
 specially, so there is no state in which part of a run's log is in one place and
 part in another. The first non-empty directory in a process wins, and a record
 falls back to stderr rather than being lost whenever the file cannot take it: a
-path that does not fit, a failed open, a failed write, or a failed flush.
+path that does not fit, a failed open, or a failed write.
 
 **Python's own log records are part of this stream too.** Seeding the native
 threshold installs a handler on the `simpler` logger that forwards each record
@@ -52,15 +52,19 @@ the log rather than a second half of it. Records logged before a worker is
 initialized have no handler to forward through yet and stay on the root logger.
 See [logging.md](../logging.md).
 
-Each process's file is fully buffered. It is flushed when a depth-zero invocation
-record completes, which is the point at which the records so far describe a whole
-invocation, and whenever a `WARN` or `ERROR` record is written, which is rare and
-worth having on disk if the process dies. That flush runs on the thread that
-emitted the record, so this reduces the observer effect by roughly the ratio of
-records to flushes rather than removing it: expect a residual tail at each flush
-boundary, not a clean floor. A system tracer would hand the bytes to a consumer
-instead, and would bound its buffer and count what it drops; this does neither,
-deliberately.
+Each process has one bounded background writer. A producer formats a complete
+record of at most 512 bytes and submits it through a 4096-slot lock-free queue;
+after that writer is published, it never performs file/stderr I/O or waits for a
+flush. The pre-writer hierarchical initialization window is the deliberate
+exception: it writes synchronously so startup diagnostics survive the final
+local fork. The writer appends each accepted record directly to the process file
+(or stderr fallback). Queue-full, bounded-claim failure, and final output failure
+increment an explicit process drop counter. Worker shutdown and `os._exit()`
+call sites wait only boundedly for accepted records, so a stuck output cannot
+turn task execution or teardown into an unbounded wait; a timeout reports both
+pending and dropped counts. `WARN`, `ERROR`, and depth-zero spans use the same
+async path as every other steady-state record. An overlong ordinary record is
+truncated to 512 bytes and ends in `~\n`.
 
 ## Reading a run back
 

docs/logging.md

@@ -29,9 +29,9 @@ Each host module:
                   └─ simpler_host_log_bind_state(state*)
 
 Device logging:
-       AICPU keeps the device backend
-            ├─ sim: set_log_level(...) seeds its current level flags
-            └─ onboard: CANN level is sampled during device init
+       dev_vlog_* compatibility interface
+            ├─ sim: bound HostLogger → same state, envelope, and output
+            └─ onboard: separate CANN backend sampled during device init
 ```
 
 One threshold controls `DEBUG / INFO / TIMING / WARN / ERROR`; `NUL` suppresses
@@ -59,7 +59,7 @@ src/common/platform/
 ├── include/aicpu/device_log.h               device backend declarations
 ├── shared/aicpu/unified_log_device.cpp      LOG_* ABI → dev_vlog_* adapter
 ├── onboard/aicpu/device_log.cpp             onboard CANN backend
-└── sim/aicpu/device_log.cpp                 sim AICPU stderr backend
+└── sim/aicpu/device_log.cpp                 dev_vlog_* → bound HostLogger adapter
 ```
 
 There is no standalone `libsimpler_log.so`. Host consumers compile the two
@@ -118,45 +118,80 @@ forwards to its local backend.
 
 ### Layer 3 — backend primitives
 
-`HostLogger::vlog` is the host-side authority for level gating. It formats a
-complete record and performs one `write(2)` under its module-local mutex.
+`HostLogger::vlog` is the host-side authority for level gating. It formats one
+bounded record (at most the portable 512-byte `PIPE_BUF` floor) and submits it
+to the process-owned queue. The queue has 4096 fixed slots and a lock-free
+multi-producer claim path. Once the writer is published, producers never perform
+file or stderr I/O, wait on a condition variable, acquire the drain mutex, or
+grow memory. During hierarchical initialization only, before the final local
+fork and writer startup, records use the synchronous destination so startup
+failures are not silently discarded. A full queue or exhausted bounded claim is
+a dropped record and increments
+`dropped_record_count`. An immediately-unlinked named semaphore provides the
+writer wakeup because unnamed semaphores are not available on every supported
+host OS.
+
+Any ordinary human-readable record whose formatted envelope and body exceed
+512 bytes is truncated to that fixed size and ends in `~\n`. This keeps one
+record to one atomic pipe write when several forked processes share captured
+stderr; callers that need a large payload must split it into separate records.
+
+One background writer drains the queue. When `CallConfig.output_prefix` is
+present it appends every C++ host-log record to the process-private
+`host.<pid>.log`; otherwise it writes to stderr. A file open/write failure falls
+back to stderr, and a failure of that final destination is counted as a drop.
+Severity and span depth no longer choose synchronous producer-side flush paths.
+Explicit lifecycle drains wait boundedly for records already accepted by the
+process.
+
 `HostLogger::log_host_span` additionally bounds and escapes machine-readable
 fields so a STRACE record fits the portable `PIPE_BUF` floor. Its early gate
 keeps direct ABI and legacy STRACE callers from paying those encoding costs
 when TIMING is disabled; `vlog` remains the final check if the threshold changes
 between the caller's query and emission.
 
-The mutex serializes writers only within the DSO that owns it. Writers from
-different DSOs, or from forked processes sharing a pipe, are indivisible only
-when their single `write(2)` is no larger than that pipe's `PIPE_BUF`.
-Machine-readable `[STRACE]` records satisfy that bound. Longer human-readable
-records are best-effort and may interleave across module boundaries. Blocking
-and drop accounting for those writes remain part of issue #1792 item 6.
-
-The AICPU `dev_vlog_*` functions remain separate. Sim formats a single stderr
-record; onboard forwards through CANN dlog. Folding sim's device logger into
-the host backend is tracked separately by issue #1792 item 5.
+The AICPU `dev_vlog_*` interface remains source-compatible on both platforms.
+Sim implements it as a thin `va_list` adapter into its bound `HostLogger`, so it
+shares the live threshold, envelope, queue, destination, and fallback with
+the other host-side modules in that process. Only real-silicon AICPU retains a
+separate backend because its records go through CANN dlog rather than a host
+process.
 
 ## Cross-DSO host state
 
 Each host DSO has a private `HostLogger` object, but every copy in one process
 reads the same `SimplerHostLogState`:
 
 ```c
+struct SimplerHostLogState;
+typedef int (*SimplerHostLogEnqueueFn)(
+    void *context, struct SimplerHostLogState *state,
+    const char *record, uint32_t size, int32_t anchor_pid);
+
 typedef struct SimplerHostLogState {
     uint32_t abi_version;
     uint32_t struct_size;
     int32_t threshold;
     int32_t clock_anchor_pid;
+    int32_t log_directory_bound;
+    char log_directory[1024];
+    int32_t sink_owner_pid;
+    int32_t sink_process_pid;
+    void *sink_context;
+    SimplerHostLogEnqueueFn sink_enqueue;
+    uint64_t dropped_record_count;
+    uint64_t pending_record_count;
+    uint64_t sink_producer_state;
 } SimplerHostLogState;
 
 int simpler_host_log_bind_state(SimplerHostLogState *state);
 ```
 
-The native `_task_interface` extension owns the state for the process. The
-fields are plain fixed-width integers to keep the ABI compiler-independent;
-`host_log.cpp` accesses mutable fields with atomic builtins. ABI version and
-size are checked before a module accepts the pointer.
+The native `_task_interface` extension owns the state for the process. Version,
+size, thresholds, and counters use fixed-width integers; `sink_context` and
+`sink_enqueue` are process-local native pointer values shared only by modules
+from the same build. `host_log.cpp` accesses mutable fields with atomic
+builtins. ABI version and size are checked before a module accepts the pointer.
 
 Only `simpler_host_log_bind_state` is exported from a host logging consumer.
 `HostLogger` and every `unified_log_*` definition are hidden. This avoids
@@ -165,17 +200,40 @@ interposition while still giving loaders one stable binding entry point.
 
 `clock_anchor_pid` is also shared. Consequently the private logger copies
 coordinate one successful `[CLOCK_ANCHOR]` per process. A negative PID is a
-temporary writer claim; a failed stderr write releases the claim so the next
-record can retry.
+temporary writer claim; a failed output releases the claim so the next record
+can retry. The first non-empty `log_directory` binding wins, so every bound DSO
+in the process chooses the same output without moving a file already in use.
+
+The owner publishes a C callback and opaque context in the same state. A private
+logger in any bound DSO can therefore submit to the one process queue without
+exporting a C++ object or relying on ELF interposition. The callback accepts a
+record only after it owns a queue slot. Binding marks that private logger as a
+consumer: it can recognize and use an existing sink, but it cannot create one.
+Only the extension copy that owns the process state creates the writer, so a
+transient DSO cannot leave its callback or thread behind after `dlclose()`.
+`pending_record_count` tracks accepted
+work for bounded drains; `dropped_record_count` tracks enqueue rejection and
+final write failure. The high bit of `sink_producer_state` closes admission
+before a fork boundary; its low bits keep `sink_context` alive until every DSO
+caller that may have loaded it has returned. `_host_log_dropped_records()`
+exposes the drop counter to diagnostics and tests, while
+`_host_log_pending_records()` distinguishes accepted work still waiting for the
+writer. Python and C++ flush defaults are both 1000 ms. Teardown and `os._exit()`
+paths report a timeout with both counters instead of silently abandoning the
+accepted backlog.
 
 ### Load and bind order
 
 Python seeds the extension-owned state before C++ loads consumers:
 
 ```python
-_initialize_host_log(level)
+_initialize_host_log(level, defer_writer=is_hierarchical)
+# Hierarchical workers perform all local forks here.
+_start_host_log_writer()
 self._impl.init(host_path, aicpu_path, aicore_path, dispatcher_path,
                 device_id, prewarm_config, enable_sdma, sim_context_path)
+# At submit, after CallConfig is available:
+_set_host_log_directory(config.output_prefix)
 ```
 
 `ChipWorker::init` then performs the module-specific work:
@@ -229,28 +287,26 @@ trace/swimlane JSON while leaving event timestamps monotonic and relative. See
 ### AICPU sim
 
 ```text
-[DEBUG]  func: [file.cpp:line] message
-[INFO]   func: [file.cpp:line] message
-[TIMING] func: [file.cpp:line] message
-[WARN]   func: [file.cpp:line] message
-[ERROR]  func: [file.cpp:line] message
+[mono_ns=MONOTONIC_NS][T0xTID][LEVEL] func: [file.cpp:line] message
 ```
 
-This is still the sim device backend, so it has no host monotonic/tid prefix.
-Onboard AICPU uses the CANN dlog format. Device TIMING uses CANN WARN and adds a
-`[TIMING]` message tag.
+Sim AICPU runs on a host CPU in the host process and uses the same envelope and
+destination as other bound host modules. The `dev_vlog_*` names remain as the
+compatibility boundary consumed by `unified_log_device.cpp`. Onboard AICPU uses
+the CANN dlog format. Device TIMING uses CANN WARN and adds a `[TIMING]` message
+tag.
 
 ## Configuration flow
 
 | Stage | Action | Source |
 | ----- | ------ | ------ |
 | Python import | Register `TIMING` / `NUL`; default the `simpler` logger to TIMING | `python/simpler/_log.py` |
-| `Worker.init()` | Normalize the Python logger level, seed native state before the first fork, and point the `simpler` logger at the host logger | `python/simpler/worker.py` |
+| `Worker.init()` | Normalize the Python level, attach it to the host logger, quiesce an old writer before local forks, then start a new writer after the final fork | `python/simpler/worker.py` |
 | `ChipWorker.init()` | Re-seed inherited native state in a chip child, then enter C++ | `python/simpler/task_interface.py` |
 | `_ChipWorker.init()` | Load sim context and host runtime, then bind each module's logger state | `src/common/worker/chip_worker.cpp` |
 | `simpler_init` | Onboard maps the bound threshold to CANN; attach and take executor binaries | `src/common/platform/{onboard,sim}/host/c_api_shared.cpp` |
 | Nested host load | Bind generated host orchestration/AICore logger state before entry | runtime maker / sim device runner |
-| AICPU init | Snapshot the applicable device threshold | platform AICPU init |
+| AICPU init | Sim binds the live host state; onboard snapshots CANN policy | platform AICPU init |
 
 The Python level is still sampled during worker initialization. Calling
 `logger.setLevel(...)` does not itself call the native setter; recreate or
@@ -289,11 +345,14 @@ someone gave a custom number.
 
 ### Forked chip subprocesses
 
-The hierarchical parent seeds native state before `fork()` and passes the
-normalized level explicitly to `_chip_process_loop`. The child re-seeds its
-inherited copy before loading runtime modules. This covers both chip-owning L3
-workers and higher-level processes that emit scheduler spans without loading a
-chip runtime.
+The hierarchical parent seeds native state and joins any prior writer before
+`fork()`. It starts its new writer only after the final local child exists and
+before remote activation creates other threads. A generic fork child starts a
+writer after its fallible setup returns (setup may recursively fork a lower
+subtree); a chip child starts one while initializing its `ChipWorker`. Normal
+`os._exit()` paths and Worker/ChipWorker teardown perform a bounded drain. This
+covers both chip-owning L3 workers and higher-level processes that emit
+scheduler spans without loading a chip runtime.
 
 ### Onboard AICPU severity is CANN-owned
 
@@ -321,6 +380,8 @@ There is no logger build step or logger field in `RuntimeBinaries`. Instead:
 
 - `_task_interface`, all host runtimes, sim-context, and sim AICore targets add
   `host_log.cpp` and `unified_log_host.cpp` to their source lists.
+- Sim AICPU targets add `host_log.cpp` while retaining
+  `unified_log_device.cpp`; the existing device ABI delegates to HostLogger.
 - Host-compiled generated orchestration SOs receive the same sources through
   `KernelCompiler.get_orchestration_cache_inputs`; those sources therefore
   participate in the scene-test cache key.
@@ -336,7 +397,7 @@ There is no logger build step or logger field in `RuntimeBinaries`. Instead:
 | Change the user-facing level model | `python/simpler/_log.py` and `docs/testing.md` |
 | Change host output or STRACE grammar | `src/common/log/host_log.cpp` |
 | Change the shared-state ABI | `src/common/log/include/common/host_log_state.h` |
-| Change sim AICPU output | `src/common/platform/sim/aicpu/device_log.cpp` |
+| Change sim AICPU adaptation | `src/common/platform/sim/aicpu/device_log.cpp` |
 | Change onboard CANN tagging | `src/common/platform/onboard/aicpu/device_log.cpp` |
 | Add a host logging consumer | compile both host logger sources, include `src/common/log/include`, and bind state during module init |
 | Add a level | `log_level.h`, `_log.py`, `simpler_setup/log_config.py`, and AICPU `set_log_level` |

python/bindings/task_interface.cpp

@@ -1736,12 +1736,44 @@ NB_MODULE(_task_interface, m) {
     );
     m.def(
         "_initialize_host_log",
-        [](int level) {
+        [](int level, bool defer_writer) {
             if (!simpler::log::is_valid_level(level)) return false;
-            HostLogger::get_instance().set_level(static_cast<simpler::log::LogLevel>(level));
-            return true;
+            HostLogger &logger = HostLogger::get_instance();
+            if (defer_writer && !logger.prepare_to_fork()) return false;
+            logger.set_level(static_cast<simpler::log::LogLevel>(level), /*defer_writer=*/true);
+            return defer_writer || logger.start_writer();
+        },
+        nb::arg("level"), nb::arg("defer_writer") = false,
+        "Seed the process-owned host-log state. A hierarchical worker defers its writer until after its last fork."
+    );
+    m.def(
+        "_start_host_log_writer",
+        [] {
+            return HostLogger::get_instance().start_writer();
+        },
+        "Start this process's bounded host-log writer after its final local fork."
+    );
+    m.def(
+        "_flush_host_log",
+        [](uint32_t timeout_ms) {
+            return HostLogger::get_instance().flush(timeout_ms);
+        },
+        nb::arg("timeout_ms") = 1000, nb::call_guard<nb::gil_scoped_release>(),
+        "Wait boundedly for all host-log records accepted by this process to be written."
+    );
+    m.def(
+        "_host_log_dropped_records",
+        [] {
+            return HostLogger::get_instance().dropped_records();
+        },
+        "Return the number of host-log records rejected by or lost from this process sink."
+    );
+    m.def(
+        "_host_log_pending_records",
+        [] {
+            return HostLogger::get_instance().pending_records();
         },
-        nb::arg("level"), "Seed the process-owned host-log state before workers fork or load runtime modules."
+        "Return the number of accepted host-log records not yet written by this process sink."
     );
     m.def(
         "_set_host_log_directory",