sync: the per-peer diagnostic was silent, not quiet - #70
Merged
Conversation
#69 shipped the per-peer reconcile timing at `debug!`. The daemon's default validation filter is `fabric=info`, set in `validation_log_filter`. So the line was dropped before it reached the log, and the instrument emitted NOTHING. I merged it, cut a release, rolled it to Silber, and then found three sync passes and zero `reconcile_peer` lines. Three passes is the positive control: the absence was the filter, not an idle daemon. Without that check I would have read an empty result as "reconcile is rare" and been wrong a fourth time in one evening. The fix is one word, `debug!` to `info!`. At about 4.6 lines a minute against the roughly 15 that log already writes, INFO is proportionate, and a diagnostic nobody can read is not cheaper than one they can. THE TEST IS THE POINT OF THIS COMMIT, AND I ARGUED AGAINST IT IN #69. I wrote there: "A test asserting that a log line fires would need a subscriber-capture harness and would mirror the change rather than check it." The first half was true. The second half was wrong, and it cost a merge, a release and a deploy. It is not a mirror. It pins the INTERACTION between two things written far apart and in different files: the level a diagnostic chooses, and the filter the daemon actually runs. Either can move without the other, and neither file mentions the other. `the_default_validation_filter_passes_info_and_drops_debug` builds the shipped default filter, installs it with a capturing writer, emits one INFO and one DEBUG event on the validation target, and asserts the first arrives and the second does not. I WATCHED IT FAIL IN THE EXACT SHAPE OF THE BUG. Changing the probe to `debug!` reproduces #69, and the test reports "an INFO diagnostic on the validation target must reach the log, got: " with an empty log. Verified on macOS 15 arm64: 238 lib tests, 12 bin tests, all pass. Agent: Silber.fabric
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
1 participant
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.
What this changes
#69 shipped an instrument that emits nothing. The per-peer reconcile timing
went out at
debug!. The daemon's default validation filter isfabric=info(
validation_log_filter,src/daemon.rs). The line was dropped before reachingthe log.
I merged it, cut a release, rolled it to Silber, then found three sync passes
and zero
reconcile_peerlines. Three passes is the positive control: theabsence was the filter, not an idle daemon. Without that check I would have read
an empty result as "reconcile is rare" and been wrong a fourth time in one
evening.
The fix is one word. At ~4.6 lines/min against the ~15 that log already writes,
INFO is proportionate, and a diagnostic nobody can read is not cheaper than one
they can.
The test is the point of this PR, and I argued against it in #69
I wrote there:
The first half was true. The second half was wrong, and it cost a merge, a
release and a deploy.
It is not a mirror. It pins the interaction between two things written far
apart, in different files: the level a diagnostic chooses, and the filter the
daemon actually runs. Either can move without the other, and neither file
mentions the other.
the_default_validation_filter_passes_info_and_drops_debugbuilds the shippeddefault filter, installs it with a capturing writer, emits one INFO and one DEBUG
event on the validation target, and asserts the first arrives and the second does
not.
What was verified, and what was not
Platform: macOS 15 on arm64 (Silber). Linux is CI's.
cargo test --lib— 238 passed, 0 failed.cargo test --bins— 12 passed, 0 failed.I watched it fail in the exact shape of the bug. Changing the probe to
debug!reproduces #69, and the test reportsan INFO diagnostic on the validation target must reach the log, got:with an empty log.Not verified: the per-peer split itself. That is the next step — deploy this,
then read whether the relay-routed peer dominates. The measurement #69 existed to
take has still not been taken.
The general lesson, since this is the second instance tonight
An instrument that cannot be read is worth less than no instrument, because it
looks like data. This is the same family as a green test on a behaviour that
never happens, and the same family as #67, where a test that could not compile
kept every check green.