Discv5 and libp2p_gossipsub Making Myriad New 'Warn' Log Entries After 'Time Bird' Upgrade

[JamesCropcho]

Description

Since upgrading Lighthouse from the most recent stable release, I have gone from seeing none of the WARN log entry types illuminated below, to myriad such log entries.

Version

Lighthouse

Output of lighthouse --version

Lighthouse v4.6.0-1be5253
BLS library: blst-modern
SHA256 hardware acceleration: true
Allocator: system
Profile: maxperf
Specs: mainnet (true), minimal (false), gnosis (false)

Command Issued for Building

PROFILE=maxperf RUSTFLAGS='-C target-cpu=native' FEATURES="modern" make

Rust

Output of rustc --version

rustc 1.76.0 (07dca489a 2024-02-04)

Present Behaviour

Since upgrading Lighthouse from the most recent stable release, I have gone from seeing none of the WARN log entry types illuminated below, to myriad such log entries.

My attestation success rate percentage does not appear to be affected.

Newly-Seen Log Entries Examples

discv5::handler, discv5::service

discv5::handler: Session has invalid ENR

WARN discv5::handler: Session has invalid ENR. Enr sockets: Some(157.90.128.69:7767), None. Expected: Node: 0x33b2..92b5, addr: 157.90.128.69:34527

This one is the most frequently seen, at roughly 1–2 dozen per minute.

discv5::handler: Authentication response already sent. Dropping session.

WARN discv5::handler: Authentication response already sent. Dropping session. Node: Node: 0x543a..69e0, addr: 49.13.11.197:30308

discv5::service: FINDNODE request failed with partial results

WARN discv5::service: FINDNODE request failed with partial results node_id=0x3411..7857 addr=186.182.184.12:9000 error=Timeout received=10 expected=3

discv5::service: RPC Request failed

WARN discv5::service: RPC Request failed: id: 05898c7eaeff92a4, error InvalidRemotePacket

libp2p_gossipsub::behaviour

libp2p_gossipsub::behaviour: Message not in cache

WARN libp2p_gossipsub::behaviour: Message not in cache. Ignoring forwarding 4e32f24c4efddd7c37146fd4c5e8b5ae927accc0

libp2p_gossipsub::behaviour: Received more messages than permitted

WARN libp2p_gossipsub::behaviour: Received more messages than permitted. Ignoring further messages. Processed: 500

libp2p_gossipsub::behaviour: Send Queue full. Could not send IHAVE

WARN libp2p_gossipsub::behaviour: Send Queue full. Could not send IHAVE peer=16Uiu2HAkydEW5ynmpswot9oubNMu2UrGQX3Zm55BZM1H1k1E9Atw

libp2p_gossipsub::behaviour: Rejected message not in cache

WARN libp2p_gossipsub::behaviour: Rejected message not in cache 2ed762f7b23b708d4c15b1a6a826a4f45b37b73d

Expected Behaviour

Uncertain.

If my beacon node is indeed experiencing lots of these problems which it was not experiencing before, then Present Behaviour matches Expected Behaviour.

If, on the other hand, these problems existed before and were not logged, then I would expect (or at least I would desire) more concise WARN logging. Presently, I am often encountering ~100 of these new log entries instantly, which makes examining my logs much more challenging.

Steps to resolve

If my beacon node is indeed malfunctioning, then I would like to know how, as well as the steps I can take to improve the rate at which the beacon node encounters these difficulties.

See Also (Possibly Related)

Issues

• Remove more gossipsub duplicate warnings #5197

Pull Requests

• Drop gossipsub stale messages when polling ConnectionHandler.  #5175
• Downgrade gossipsub duplicate logs #5163
• Add flag to disable warning logs for duplicate gossip messages #5009

[AgeManning]

Thanks for reporting this.

First of all, your beacon node is fine. These logs have always existed in the backgorund, but we have recently started capturing them into a log file. In the process they seem to be being emitted to the terminal which shouldn't be the case.

Are you using the -l CLI parameter? What is your OS? Have you set RUST_LOG environment variable by any chance?

This is also something @eserilev might be able to help figure out also.

[eserilev]

I'll take a look. If the RUST_LOG env variable is unset or contains an invalid value we'll end up defaulting to a warn tracing filter for discv5 and libp2p. Though those logs shouldn't ever be emitted to the terminal.

[JamesCropcho]

Thank you for your assurance that my beacon node is fine, Age (@AgeManning)! Such news is always welcome.

Are you using the -l CLI parameter?

In fact, it looks like I am! I've been using it for some time―a number of months, at least.

Seems rather probable that this is the reason for the myriad new log entries, no?

What is your OS?

Output of uname -a:

Linux [redact] 6.2.0-1018-aws #18~22.04.1-Ubuntu SMP Wed Jan 10 22:54:16 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

Have you set RUST_LOG environment variable by any chance? […] If the RUST_LOG env variable is unset or contains an invalid value we'll end up defaulting to a warn tracing filter for discv5 and libp2p[.]

I'm pretty sure that RUST_LOG is unset (env | grep -i rust as "main" commandline shell user, and sudo env | grep -i rust each yield no search results).

―James

cc: @eserilev

[eserilev]

@JamesCropcho Thanks for the additional info. -l is definitely the culprit. If you'd like to get rid of those redundant libp2p and discv5 warn logs in your terminal, you should restart your BN without the -l flag. These discv5 and libp2p logs end up getting captured in separate log files anyways, so you're not missing out on anything by leaving out the -l flag.

[eserilev]

I'm going to also go ahead and deprecate the -l flag functionality here as it no longer serves any purpose