Lighthouse: Increase capacity of logging channel

[michaelsproul]

Description

This is a relatively common occurrence:

Aug 05 02:50:45.169 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.169 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.169 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.169 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.169 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.169 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.170 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.170 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 1
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 3
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 3
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 3
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 3
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 3
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 5
Aug 05 02:50:45.170 ERRO slog-async: logger dropped messages due to channel overflow, count: 3
Aug 05 02:50:45.170 DEBG Invalid attestation from network        type: "aggregated", peer_id: 16Uiu2HAmUNnUNkc6HhU4i6fAEUxep9XdsCT56CkPQoCVZeGomFnE, block: 0x2cb7…28a7

Version

Lighthouse Lighthouse/v0.2.0/f26adc0a
BLS Library: blst

Present Behaviour

Log messages are frequently dropped.

Expected Behaviour

Log messages should only be dropped in extreme cases, like #1463. Dropped logs could be obscuring important CRIT or ERRO messages -- as far as I can tell the logger doesn't prioritise these.

Steps to resolve

Increase the channel size as per https://github.com/slog-rs/async/issues/4 and confirm that a node running on Medalla experiences less dropped logs

[michaelsproul]

PS: default capacity seems to be 128, we could go to 256/512 I reckon

[paulhauner]

@realbigsean this would also be quite valuable low-hanging-fruit :)

[realbigsean]

I updated the channel size to 256 and tested it out using the local testnet scripts, 1024 validators, and trace logging. It seemed to reduce the number of logs dropped (by about 10%)... but not completely eliminate the problem. I played around with other configurations but couldn't get zero logs dropped until using a channel size of 2048.

Because the logging output scales with the # of validators, would it make sense to make this configurable? or have the default scale with the number of validators you're running? Or are you guys happy with hard-coding a config greater than 128?

[michaelsproul]

I'm happy for the size to hit 2048, it sounds like at most a few hundred KB in memory (2048 x 200 bytes per line)