refactor(modules): route module logging through the tracing facade#183
Open
mfw78 wants to merge 4 commits into
Open
refactor(modules): route module logging through the tracing facade#183mfw78 wants to merge 4 commits into
mfw78 wants to merge 4 commits into
Conversation
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.
11 tasks
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
This routes module-authored logging through the
tracingfacade across every SDK-based module, replacing the rawhost.logandlogging::logwire-level calls with the standardtracingmacros (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
tracingand theHostLogSinkforwards 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
loggingbinding, 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, andprice-alertto thetracingmacros. Zerohost.log(calls remain anywhere inmodules/.Moved the affected unit-test assertions from the mock's
host.loggingbuffer ontocapture_tracing, preserving every asserted substring and every level check. Assertions on lines that originate in the untouched SDK chainlink helper stay onhost.logging, because that helper still logs through the host binding.Adopted structured
key=valuefields for discrete numeric and identifier values inprice-alertandstop-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 intwap-monitorandethflow-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 totracing::info!while keeping its hand-rolled sink (see notes below).Left
example,fuel-bomb,memory-bomb, andflaky-bombonlogging::log, each with a one-line note explaining that they install no subscriber.balance-trackerandhttp-probewere already ontracingand are unchanged.Updated
docs/tutorial-first-module.mdonly: the strategy, init, and unit-test samples now use thetracingmacros pluscapture_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 --checkcargo clippy --workspace --all-targets --all-features -- -D warningscargo docRUSTFLAGS="-D warnings"(clean, confirming no dead code from the retainedpanic-bombsink)cargo test --workspace --all-features --no-fail-fast(viajust ci, exit 0)cargo test -p nexum-runtime supervisor::testswithCI=1: 24 passed, 0 skippedcargo test -p shepherd-cow-host --test cow_bootwithCI=1: 3 passed, 0 skippedprice-alert,stop-loss,twap-monitor, andethflow-watcherpasscargo fmt --all --checkandcargo clippy --workspace --all-targets --all-features -- -D warningsrerun clean on both appended commitsnexum-sdk-testpass on each of the two appended commits independentlycargo test --workspace --all-features --no-fail-fastrerun twice, both exit 0twap-monitorandnexum-sdk-testtest binaries rerun 20 consecutive times at--test-threads=16, 20/20 greenjust cifrom 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 greenThe 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=1a missing module wasm traps loudly rather than skipping, so the zero-skip counts are meaningful.Notes for reviewer
install_tracingtiming. Every SDK-based module callsinstall_tracing(), which invokesnexum_sdk::tracing::initand thusset_global_default, as the first statement ofGuest::init.initalways runs beforeon_event, and no module code runs beforeinit, 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 rawlogging::logform.panic-bombdecision. The init line moved totracing::info!, but the hand-rolled sink is deliberately kept rather than adoptingbind_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 unusedsdk_err_into_witconverter, all of which are dead code and a hard error under the CI-D warningswasm build.panic-bombcallsnexum_sdk::tracing::initdirectly and logs its init line after that call, so it too is post-install; the survivinglogging::logthere 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_tracingflake fix (test infrastructure). This PR also touchescrates/nexum-sdk-test, which the migration otherwise avoids. The migrated assertions surfaced a scheduling-dependent flake:capture_tracinginstalled the facade with a thread-localwith_defaultscope, buttracingcaches each callsite'sInterestthe 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 cachedneverfor 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 failingtwap-monitorassertion now passes 40 consecutive runs at--test-threads=16and 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-testto 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-testinsists on owning subscriber installation and offers onlylogs_containsubstring assertions, exactly the fragile surface being removed, and would have re-fought the interest-cache fix.tracing-mockis an ordered expectation-sequence harness built fortracing'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 innexum-sdk-test, keeping the interest-cache fix's dispatcher mechanism unchanged and exposing field-level predicates directly.The redesigned helper returns a
CapturedEventscollection ofCapturedEvent { level, target, message, fields }, wherefieldsis 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, whilecapture_tracingkeeps 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-testpin 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-monitorandnexum-sdk-testtest binaries were rerun 20 consecutive times at--test-threads=16with 20 out of 20 green, alongside two clean full-workspacecargo test --workspace --all-features --no-fail-fastruns.AI Assistance: Claude Code (Opus 4.8 implementation and adversarial review, Fable 5 architecture, Sonnet 5 PR authoring) used for the full change.