Skip to content

fix: cap gossipsub's log output at ERROR unless RUST_LOG raises it - #719

Open
pablodeymo wants to merge 1 commit into
mainfrom
fix/gossipsub-log-filter
Open

pablodeymo wants to merge 1 commit into
mainfrom
fix/gossipsub-log-filter

Conversation

@pablodeymo

Copy link
Copy Markdown
Collaborator

🗒️ Description / Motivation

  • A beacon node on Hoodi logs WARN libp2p_gossipsub::behaviour: Send Queue full. Could not send Rpc. once per heartbeat for every slow peer, each line listing every IHAVE id dropped on an attestation subnet. The drop is already counted in the peer's failed_messages and charged to its score, so the line adds noise, not information.
  • The line is emitted inside the gossipsub crate. Rather than patching the libp2p fork, the node's default log filter now caps that crate at ERROR, which is how an operator sees the dependency's noise anyway. Lighthouse goes further and routes all libp2p_gossipsub and discv5 output to separate files.

What Changed

  • bin/ethlambda/src/main.rs: init_node_logging builds its filter from node_log_filter(RUST_LOG). With no RUST_LOG the directives are info,libp2p_gossipsub=error; with one they are libp2p_gossipsub=error,<RUST_LOG>. A RUST_LOG directive on libp2p_gossipsub replaces the cap, one on any other target adds to it, and RUST_LOG keeps replacing the info floor the way from_env_lossy always did. The floor is spelled out because EnvFilter only applies a default directive when it was given no directive at all.
  • Besides the send-queue line, the cap hides gossipsub's other warnings (bad signatures, substream limits, anonymous-mode field checks), all per-peer protocol violations that peer scoring already handles. Its 19 error sites still show.
  • The benchmark and keygen filters are untouched; neither runs a network.
  • docs/beacon_wire.md: one sentence next to the existing RUST_LOG example, saying how to see gossipsub's warnings.

Correctness / Behavior Guarantees

  • Default output changes only for the libp2p_gossipsub target: WARN and below are dropped, ERROR stays.
  • RUST_LOG semantics are preserved, including the pre-existing quirk that a RUST_LOG without its own info silences other targets. Verified against tracing-subscriber 0.3.23: an equal-specificity directive added later replaces the earlier one, and Ordering::Equal implies the same target, so no other directive is clobbered.
  • A bare RUST_LOG=debug keeps the cap, since the more specific directive wins; the doc comment says to name the crate.

Tests Added / Run

  • Three tests in main.rs drive real events through the filter: default behaviour (INFO floor, gossipsub WARN dropped, gossipsub ERROR kept), the lift via RUST_LOG=…,libp2p_gossipsub=warn,… alongside another directive, and the floor-replacement quirk.
  • cargo test --locked --profile release-fast -p ethlambda --bin ethlambda -- tests::node_logging tests::rust_log: 3 passed.
  • cargo clippy --locked -p ethlambda --all-targets -- -D warnings: clean. cargo fmt --all -- --check: clean.

Related Issues / PRs

✅ Verification Checklist

  • Ran make fmt — clean
  • Ran make lint (clippy with -D warnings) — run as cargo clippy -p ethlambda --all-targets -- -D warnings, the only crate changed; CI runs the workspace
  • Ran make test (test-consensus plus test-node, at release-fast) — the three new tests run at release-fast; CI runs the rest

A beacon node logs `WARN libp2p_gossipsub::behaviour: Send Queue full. Could
not send Rpc.` once per heartbeat for every slow peer, each line listing every
IHAVE id dropped on an attestation subnet. The drop is already counted in the
peer's failed-message tally and charged to its score, and gossipsub's other
warnings are per-peer protocol violations the scoring handles too, so the
node's default filter now reads `info,libp2p_gossipsub=error`.

`RUST_LOG=libp2p_gossipsub=warn` lifts the cap: the env directive on the same
target replaces the built-in one, while directives on other targets add to it
and keep replacing the `info` floor the way `from_env_lossy` always let them.
The floor is spelled out rather than passed as the default directive because
`EnvFilter` only falls back to that default when it was given no directive at
all. Three tests drive events through the filter for each of those cases.
@github-actions

Copy link
Copy Markdown

🤖 Kimi Code Review

I'll review this PR focusing on logging filter changes and test additions.

Overall Assessment

This is a well-crafted, focused PR that addresses operational noise from gossipsub warnings. The code is generally correct, well-tested, and follows Rust idioms. I have a few minor concerns.


Issues Found

1. Potential deadlock in test helper (bin/ethlambda/src/main.rs)

Lines 2323–2335 (test helper logged_with):

fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
    self.0.lock().expect("sink lock").extend_from_slice(buf);
    Ok(buf.len())
}

The Write::write implementation acquires a Mutex lock. In the tracing ecosystem, fmt::layer() with with_writer may call write multiple times per event (e.g., for timestamp, level, target, message, newline as separate writes). While this won't deadlock with a standard Mutex, if tracing ever re-enters or if the layer uses write_all (which calls write in a loop), this is fine. However, the flush() implementation is a no-op, which could cause issues if tracing relies on flush semantics for correctness (it typically doesn't, but this is worth noting).

More importantly: tracing_subscriber::fmt::layer().with_writer(move || writer.clone()) clones the Arc on every write. The Sink clone is cheap, but the Mutex is held across each individual write call, not across the full formatted record. This is actually correct behavior for interleaving safety.

Verdict: Acceptable, but consider documenting why flush is intentionally empty.


2. expect message inconsistency and panic safety

Line 2324 and Line 2350:

self.0.lock().expect("sink lock")
// vs
let bytes = sink.0.lock().expect("sink lock").clone();

The expect messages are identical but occur in different contexts. Not a bug, but if this ever panics, debugging is harder. Consider "test sink mutex poisoned" for clarity.

More critically: tests use .expect() rather than propagating errors. This is acceptable in tests, but Mutex poisoning is possible if a panic occurs while holding the lock. Since this is test-only code with controlled execution, this is fine.


3. node_log_filter behavior edge case with empty RUST_LOG

Lines 2296–2301:

fn node_log_filter(rust_log: Option<&str>) -> EnvFilter {
    let directives = match rust_log.map(str::trim).filter(|value| !value.is_empty()) {
        Some(rust_log) => format!("{GOSSIPSUB_LOG_CAP},{rust_log}"),
        None => format!("{NODE_LOG_LEVEL},{GOSSIPSUB_LOG_CAP}"),
    };
    EnvFilter::builder().parse_lossy(directives)
}

Issue: When RUST_LOG="" (empty string), this correctly falls through to None due to .filter(|value| !value.is_empty()). Good.

Issue: When RUST_LOG=" " (whitespace only), same correct behavior.

Potential concern: The order of directives differs between the two arms:

  • RUST_LOG set: GOSSIPSUB_LOG_CAP, RUST_LOG → e.g., libp2p_gossipsub=error,info,ethlambda_p2p=debug
  • RUST_LOG unset: NODE_LOG_LEVEL, GOSSIPSUB_LOG_CAP → info,libp2p_gossipsub=error

In EnvFilter, later directives override earlier ones for the same target. The comment at lines 2284–2292 correctly explains that libp2p_gossipsub=warn in RUST_LOG will override the cap because it appears later. However, the asymmetric ordering is slightly confusing: when RUST_LOG is set, GOSSIPSUB_LOG_CAP comes first; when unset, NODE_LOG_LEVEL comes first.

This is actually correct by design (the comment explains it), but the asymmetry could be a maintenance footgun. Consider whether RUST_LOG="info,libp2p_gossipsub=error" (with explicit cap) should behave identically to the no-RUST_LOG case. Currently it would, because the later libp2p_gossipsub=error overrides the earlier... wait, no:

If RUST_LOG="info,libp2p_gossipsub=error", then directives = libp2p_gossipsub=error,info,libp2p_gossipsub=error. The later libp2p_gossipsub=error is redundant but harmless. If RUST_LOG="warn,libp2p_gossipsub=warn", then GOSSIPSUB_LOG_CAP is overridden.

Actually, re-reading: the format is "{GOSSIPSUB_LOG_CAP},{rust_log}", so for RUST_LOG="info" we get libp2p_gossipsub=error,info. The info here sets the default level. This seems correct.

Verdict: Behavior is correct, but the asymmetric ordering deserves a one-line comment in the code itself, not just in the doc comment.


4. Test coverage gap: RUST_LOG with explicit libp2p_gossipsub=error

There's no test verifying that RUST_LOG="libp2p_gossipsub=error" (redundant with cap) or RUST_LOG="warn" (broad level that should be capped) behaves correctly. The existing tests are good but don't cover the "broad RUST_LOG level interacts with specific cap" scenario.

Consider adding:

#[test]
fn rust_log_broad_level_respects_cap() {
    let out = logged_with(Some("warn"));
    // `warn` sets broad floor, but gossipsub cap should still apply
    assert!(!out.contains("gossipsub-warn"), "cap lost to broad level: {out}");
    assert!(out.contains("gossipsub-error"), "gossipsub errors lost: {out}");
}

Wait—actually, with RUST_LOG="warn", the directives are libp2p_gossipsub=error,warn. Does warn as a bare level apply globally? In EnvFilter, a bare level sets the default level. So warn would be the default, and libp2p_gossipsub=error is more specific. This should work correctly (specific wins). But worth testing.


5. Documentation accuracy

docs/beacon_wire.md line 851:

"gossipsub's own warnings, chiefly the send-queue-full line a slow peer earns once per heartbeat"

The comment in code says "once per heartbeat for every peer whose send queue is full" and "each line lists every IHAVE id it dropped". The doc simplifies to "chiefly the send-queue-full line". This is accurate enough for operators, but the doc doesn't mention that errors still show (though this is implied by "capped at ERROR").

Minor: Consider adding "errors and above still appear" for clarity.


6. init_benchmark_logging inconsistency (pre-existing, not changed)

Not part of this PR, but worth noting: init_benchmark_logging still uses from_env_lossy() without the gossipsub cap. If benchmarks produce gossipsub warnings, they'll still be noisy. This may be intentional (benchmarks don't run gossipsub?), but if they do, the cap should probably apply there too.


Positive Observations

  1. Excellent test coverage for the three core scenarios: default behavior, cap override, and floor replacement.
  2. Clear, extensive comments explaining the EnvFilter precedence semantics—critical for maintainability.
  3. Correct use of parse_lossy rather than parse—invalid directives in RUST_LOG won't crash the node.
  4. No consensus-critical code changed—this is purely operational logging, minimizing risk to chain safety.

Suggested Changes

Location Change Priority
main.rs:2324 Improve expect message to "test sink mutex poisoned" Low
main.rs:2284–2292 Add inline comment about asymmetric directive ordering Low
main.rs:2360+ Add test for RUST_LOG="warn" broad level with cap Low
docs/beacon_wire.md:851 Clarify that errors still appear Very low

Security Assessment

No security issues identified. This change does not affect:

  • Signature verification
  • State transition logic
  • Network message handling (only log filtering)
  • Cryptographic operations

The EnvFilter::parse_lossy usage correctly prevents DoS via malformed RUST_LOG values.


Automated review by Kimi (Moonshot AI) · kimi-k2.6 · custom prompt

@github-actions

Copy link
Copy Markdown

🤖 Codex Code Review

Looks good overall. The change is narrowly scoped to logging behavior and docs/tests; I don’t see any consensus, state-transition, SSZ, attestation, or signature-path risk in this diff.

  • bin/ethlambda/src/main.rs:186 correctly preserves the intended precedence: default info only when RUST_LOG is unset/empty, while libp2p_gossipsub=error remains as a more-specific cap unless explicitly overridden.
  • bin/ethlambda/src/main.rs:167 uses std::env::var(...).ok(), so invalid Unicode in RUST_LOG is treated as unset. That’s acceptable, but it is a small behavioral change from from_env_lossy(), which tolerated lossy parsing. If preserving exact prior ergonomics matters, consider var_os plus lossy conversion.
  • bin/ethlambda/src/main.rs:2313 test coverage is good for the precedence rules that matter most: default floor, explicit cap override, and replacement of the default floor by targeted RUST_LOG.

Minor note:

  • bin/ethlambda/src/main.rs:177 / docs/beacon_wire.md:851 hard-code assumptions about gossipsub warning semantics. That’s fine for now, but if upstream target names or warning categories change, the filter may stop matching or may hide newly important warnings. Not a blocker, just worth keeping in mind when bumping libp2p.

Validation note:

  • I could not run the Rust tests in this environment because rustup attempted to write under a read-only home directory.

Automated review by OpenAI Codex · gpt-5.4 · custom prompt

@github-actions

Copy link
Copy Markdown

🤖 Claude Code Review

Review of PR 719: cap libp2p_gossipsub at ERROR by default

I only read the diff. I did not build the branch or run the tests.

The approach is sound. It filters in the node, which is cheaper than carrying a patch to the libp2p fork. The directive ordering is also right: the cap comes first and RUST_LOG after it, so a RUST_LOG directive for libp2p_gossipsub replaces the cap. The tests drive real events through the filter instead of only asserting on strings, which is the right level.

Issues

  1. A RUST_LOG with no valid directive now silences the node (bin/ethlambda/src/main.rs, node_log_filter).

    • Previously from_env_lossy fell back to the INFO default when nothing parsed, for example with RUST_LOG=garbage or a typo like RUST_LOG=inof.
    • Now the string is libp2p_gossipsub=error,garbage. The bad directive is dropped, the cap is the only directive left, and the node logs nothing except gossipsub errors.
    • This is separate from the intended "no floor if RUST_LOG names only other targets" quirk, because here the operator never asked to drop the floor.
    • A cheap fix is to parse rust_log on its own first. If that yields no directives, use the NODE_LOG_LEVEL branch. It would also be worth a fourth test with an invalid value.
  2. The new default still drops the floor for target-only RUST_LOG values (minor, documented). RUST_LOG=ethlambda_p2p=debug hides everything else. The doc comment explains this, and keeping it matches the old behaviour. Item 1 is the real regression.

Minor notes

  • Capping at ERROR hides all gossipsub warnings, not only the send-queue line. The PR says so, and I think the trade-off is reasonable given peer scoring. The docs/beacon_wire.md note on how to lift the cap is enough.
  • The lean node subcommand also goes through init_node_logging, so the cap applies there too. That seems fine, but the PR text only mentions beacon.
  • The sink in the tests is solid. with_default scopes the subscriber, so the tests don't interfere with each other.

Verdict: Good change overall. I'd fix Item 1 before merging, since a typo in RUST_LOG now produces a silent node. The rest is fine.


Automated review by Claude (Anthropic) · sonnet · custom prompt

This branch has not been deployed

No deployments
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