Skip to content

refactor(modules): route module logging through the tracing facade#183

Open
mfw78 wants to merge 4 commits into
developfrom
refactor/modules-tracing-macros
Open

refactor(modules): route module logging through the tracing facade#183
mfw78 wants to merge 4 commits into
developfrom
refactor/modules-tracing-macros

Conversation

@mfw78

@mfw78 mfw78 commented Jul 5, 2026

Copy link
Copy Markdown
Contributor

Summary

This routes module-authored logging through the tracing facade across every SDK-based module, replacing the raw host.log and logging::log wire-level calls with the standard tracing macros (info!, warn!, error!).

It completes the module-side adoption of the tracing facade begun in the module-logging work tracked in issue #179: the host sink and the facade seam already landed, and this change migrates the module call sites that still emitted through the raw host interface so that authors write ordinary tracing and the HostLogSink forwards to the host binding.

Behaviour is preserved end to end. Every migrated line keeps its level and its message text, the host-side records still arrive over the same logging binding, and the four SDK-free fixtures that install no subscriber are deliberately left on the raw form.

Changes

Migrated the strategy and init call sites in twap-monitor, ethflow-watcher, stop-loss, and price-alert to the tracing macros. Zero host.log( calls remain anywhere in modules/.

Moved the affected unit-test assertions from the mock's host.logging buffer onto capture_tracing, preserving every asserted substring and every level check. Assertions on lines that originate in the untouched SDK chainlink helper stay on host.logging, because that helper still logs through the host binding.

Adopted structured key=value fields for discrete numeric and identifier values in price-alert and stop-loss (answer, threshold, direction, price, trigger, uid, code, message), keeping the marker words in the message body so the rendered output still matches the existing substrings. Kept interpolated prose in twap-monitor and ethflow-watcher, where diagnostic sentences weave in owner addresses, keys, and uids that do not round-trip cleanly as Display fields; the message text there is byte-identical to the old format strings.

Migrated panic-bomb's init line to tracing::info! while keeping its hand-rolled sink (see notes below).

Left example, fuel-bomb, memory-bomb, and flaky-bomb on logging::log, each with a one-line note explaining that they install no subscriber. balance-tracker and http-probe were already on tracing and are unchanged.

Updated docs/tutorial-first-module.md only: the strategy, init, and unit-test samples now use the tracing macros plus capture_tracing, and the prose that taught the two wire-level forms was rewritten to teach the facade first while noting that the raw forms remain for pre-subscriber sites.

Test plan

  • cargo fmt --all --check
  • cargo clippy --workspace --all-targets --all-features -- -D warnings
  • cargo doc
  • Release build of all 11 module wasms, plus each built standalone under RUSTFLAGS="-D warnings" (clean, confirming no dead code from the retained panic-bomb sink)
  • cargo test --workspace --all-features --no-fail-fast (via just ci, exit 0)
  • cargo test -p nexum-runtime supervisor::tests with CI=1: 24 passed, 0 skipped
  • cargo test -p shepherd-cow-host --test cow_boot with CI=1: 3 passed, 0 skipped
  • Native unit tests for price-alert, stop-loss, twap-monitor, and ethflow-watcher pass
  • Test-regime revision: cargo fmt --all --check and cargo clippy --workspace --all-targets --all-features -- -D warnings rerun clean on both appended commits
  • Per-crate tests for every touched module plus nexum-sdk-test pass on each of the two appended commits independently
  • cargo test --workspace --all-features --no-fail-fast rerun twice, both exit 0
  • twap-monitor and nexum-sdk-test test binaries rerun 20 consecutive times at --test-threads=16, 20/20 green
  • just ci from the worktree root rerun without the private target override, so the supervisor and CoW e2e suites exercised freshly built in-tree wasms; PR CI is 11/11 green

The supervisor and CoW e2e suites ran against freshly built wasms from this branch, installed at the compile-time lookup path, so they exercised this branch's components rather than stale artefacts. With CI=1 a missing module wasm traps loudly rather than skipping, so the zero-skip counts are meaningful.

Notes for reviewer

install_tracing timing. Every SDK-based module calls install_tracing(), which invokes nexum_sdk::tracing::init and thus set_global_default, as the first statement of Guest::init. init always runs before on_event, and no module code runs before init, so the whole Guest lifecycle of every SDK-based module is post-install and every call site is safe to migrate. The only modules that never install a subscriber are the four SDK-free fixtures, which is why they keep the raw logging::log form.

panic-bomb decision. The init line moved to tracing::info!, but the hand-rolled sink is deliberately kept rather than adopting bind_host_via_wit_bindgen!. This fixture binds only the minimal nexum world and maps no host errors, so the macro would generate unused chain and local-store impls plus an unused sdk_err_into_wit converter, all of which are dead code and a hard error under the CI -D warnings wasm build. panic-bomb calls nexum_sdk::tracing::init directly and logs its init line after that call, so it too is post-install; the surviving logging::log there is the sink's own forwarding body, which routes through the same facade seam. Its three-source e2e test still passes. The reasoning is recorded in a code note.

capture_tracing flake fix (test infrastructure). This PR also touches crates/nexum-sdk-test, which the migration otherwise avoids. The migrated assertions surfaced a scheduling-dependent flake: capture_tracing installed the facade with a thread-local with_default scope, but tracing caches each callsite's Interest the first time it is hit against whichever dispatcher is current on that thread at that instant. Under parallel tests a callsite exercised outside any capture (a sibling test calling the same strategy function directly) registered against the no-op default and was cached never for the rest of the process, starving every later scoped capture of that event. The helper now installs the facade once as the process-global default and routes each rendered line to a thread-local buffer, so the cached interest is stable and capture no longer depends on which test touches a callsite first. The previously failing twap-monitor assertion now passes 40 consecutive runs at --test-threads=16 and two clean full-workspace runs.

Test regime revision (appended)

Following the initial review, the module test suites were revised to assert on domain outcomes rather than on captured log-line strings, with a typed capture helper added to nexum-sdk-test to carry the branches where the log line remains the only observable.

The interest-cache flake fixed above was a symptom of a broader fragility: assertions that matched substrings of a flattened log line broke whenever a message was reworded, coupled test intent to rendering detail rather than to the behaviour under test, and could not distinguish a message that merely looked right from state that was actually correct. The behaviour-first principle applied here is to assert on the state and mock-call effects a test can already observe (store keys, call counts, request logs) wherever those effects exist, and to reserve log assertions for the branches where the log line is the only externally observable signal of which code path ran.

Considered two off-the-shelf harnesses and rejected both. tracing-test insists on owning subscriber installation and offers only logs_contain substring assertions, exactly the fragile surface being removed, and would have re-fought the interest-cache fix. tracing-mock is an ordered expectation-sequence harness built for tracing's own test suite, awkward for the after-the-fact predicate queries this regime needs, and would likewise have replaced the proven dispatcher mechanism. The decision was an in-house typed capture helper of about 120 lines in nexum-sdk-test, keeping the interest-cache fix's dispatcher mechanism unchanged and exposing field-level predicates directly.

The redesigned helper returns a CapturedEvents collection of CapturedEvent { level, target, message, fields }, where fields is a map of the event's non-message fields typed as string, integer, boolean, or debug-rendered values. Predicate methods (any, expect_one, count_at, field, field_str) replace substring search over the old flattened log lines, while capture_tracing keeps its existing signature and the global-dispatcher-plus-thread-local-buffer mechanism from the interest-cache fix.

Twenty-five existing tests across the seven modules with capture-based assertions were reclassified: nine were rewritten to drop the log assertion entirely in favour of the state and mock-effect asserts they already had, five kept a log-only branch and were migrated to a typed predicate because no other observable distinguishes that branch, and eleven combine both, strengthening the state assertion and retyping the remaining log check. One new test was added to close a gap where only the absence of an alert was covered, not its firing, and five new unit tests in nexum-sdk-test pin the typed capture contract itself (message-only events, mixed field types, debug-rendered fields, out-of-capture drop, and cross-thread isolation).

To confirm the interest-cache fix still holds under the new typed assertions, the current twap-monitor and nexum-sdk-test test binaries were rerun 20 consecutive times at --test-threads=16 with 20 out of 20 green, alongside two clean full-workspace cargo test --workspace --all-features --no-fail-fast runs.

AI Assistance: Claude Code (Opus 4.8 implementation and adversarial review, Fable 5 architecture, Sonnet 5 PR authoring) used for the full change.

mfw78 added 4 commits July 5, 2026 08:04
Every SDK-based module installs the guest tracing facade at the top of
Guest::init, so its whole lifecycle runs post-install. Migrate those
call sites off the raw logging::log wire binding and the host.log trait
method onto the tracing macros: twap-monitor, ethflow-watcher,
price-alert, and stop-loss (init lines plus every strategy log), and the
init line of panic-bomb. Discrete numeric values move into structured
fields where they read as key=value data (price-alert, stop-loss);
diagnostic lines that weave a value into a sentence keep their prose.

Strategy unit tests capture the facade with nexum_sdk_test::capture_tracing
instead of asserting on MockHost.logging. Lines emitted by the SDK
chainlink helper still land on host.logging, so those assertions stay as
they were.

The example reference module and the fuel-bomb, memory-bomb, and
flaky-bomb fixtures install no subscriber and pull in no SDK, so they
keep the raw logging binding with a one-line note; their records reach
the host through the same sink the facade forwards to. panic-bomb keeps
its hand-rolled sink for the same reason and gains a note recording why
the generic bind macro is not worth its unused adapter code here.

The first-module tutorial now teaches the tracing macros in the strategy,
init, and unit-test samples.
capture_tracing installed the guest facade with a thread-local
with_default scope. tracing caches each callsite's Interest the first
time the callsite is exercised, computed against whichever dispatcher is
current on that thread at that instant. Under parallel module tests a
callsite hit outside any capture (a sibling test calling the same
strategy function directly) registered against the no-op default and was
cached never for the rest of the process, starving every later scoped
capture of that event. That surfaced as a scheduling-dependent flake in
the twap-monitor indexed-log assertion.

Install the facade once as the process-global default and route each
rendered line to a thread-local capture buffer. The global default keeps
the cached interest stable, so capture no longer depends on which test
touches a callsite first.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant