Critical dependency logging by eserilev · Pull Request #4988 · sigp/lighthouse

eserilev · 2023-12-06T23:13:04Z

Issue Addressed

Proposed Changes

This PR proposes adding logs for the following dependencies

libp2p (note: there is discussion below on which libp2p dependencies we want to log)
discv5

Each dependency has its own separate log file. Using the tracing appender library a non blocking file stream is created for each dependency. On each tracing event a timestamp, log level and log message are written to the respective log file. The files are rotated daily

Example discv5 logs

2023-12-30 06:19:53 INFO  Discv5 Service started
2023-12-30 06:19:53 INFO  Ip4
2023-12-30 06:19:53 INFO  16Uiu2HAmEgUR5kmcKF8z3VQKwEKxbBgDoToWHp3DdAefJybbwBoV
2023-12-30 06:19:54 INFO  Local UDP socket updated to: 77.127.179.45:9000
2023-12-30 06:20:14 WARN  NODES Response failed, but was partially processed from: Node: 0x2971..de4d, addr: 174.61.110.113:9100
2023-12-30 06:20:15 WARN  NODES Response failed, but was partially processed from: Node: 0x296a..2228, addr: 104.58.212.29:9002
2023-12-30 06:20:23 WARN  Query id: QueryId(2) timed out
2023-12-30 06:20:41 WARN  NODES Response failed, but was partially processed from: Node: 0xbbfc..d98e, addr: 165.154.224.42:9000
2023-12-30 06:20:50 WARN  NODES Response failed, but was partially processed from: Node: 0x7e81..ef2c, addr: 216.212.216.227:9005
2023-12-30 06:20:50 WARN  Query id: QueryId(7) timed out
2023-12-30 06:20:52 WARN  NODES Response failed, but was partially processed from: Node: 0x6b0a..7d2e, addr: 176.127.215.52:12103
2023-12-30 06:20:53 WARN  Query id: QueryId(8) timed out
2023-12-30 06:21:18 WARN  NODES Response failed, but was partially processed from: Node: 0x0a0a..2412, addr: 45.50.92.150:9000
2023-12-30 06:21:20 WARN  Query id: QueryId(12) timed out
2023-12-30 06:21:23 WARN  Query id: QueryId(13) timed out
2023-12-30 06:21:34 WARN  NODES Response failed, but was partially processed from: Node: 0x00d2..309e, addr: 90.197.108.62:12103
2023-12-30 06:21:35 WARN  NODES Response failed, but was partially processed from: Node: 0x003f..82ad, addr: 120.226.39.101:12000
2023-12-30 06:21:51 WARN  Query id: QueryId(18) timed out
2023-12-30 06:21:53 WARN  Query id: QueryId(19) timed out

Example libp2p-gossipsub logs

2023-12-30 06:34:41 WARN  Rejected message not in cache 879b74cbcbd330d52d1872b6cbd4a55c148628b0
2023-12-30 06:34:41 WARN  Rejected message not in cache fb859e0b1525fb96ab4ef1173e0e15b12231c9d2
2023-12-30 06:34:41 WARN  Rejected message not in cache 8739ca4f524019c786ade9c1082205a1c213ef83
2023-12-30 06:34:41 WARN  Rejected message not in cache 769a533ce08502ace31f7eda9d07037e3ec9e907
2023-12-30 06:34:41 WARN  Rejected message not in cache 22397a3372d2ecc518f68434a5d8ab1a0f65031c
2023-12-30 06:34:41 WARN  Rejected message not in cache a0eba3cdc2b94a888cab3fc79e641b762c4d257d
2023-12-30 06:34:41 WARN  Rejected message not in cache 1adca446acb3abe928f8b0d5ee47d93a9fe7374d
2023-12-30 06:34:41 WARN  Rejected message not in cache ad0dc640889db2209a6b012360a04ef3ec827210
2023-12-30 06:34:41 WARN  Rejected message not in cache d817cbe7d3095c31c2a17fe23696d0b881330d16
2023-12-30 06:34:41 WARN  Rejected message not in cache 6de7d7fb40600cf73a4e6764d3eefe040c18ec7e
2023-12-30 06:34:41 WARN  Rejected message not in cache 2fad3b164441bc50e27177f736b84b6cc0306a9b

Additional Info

This builds on top of changes made in #4979. It may be a bit difficult to review until that PR is merged

Most of my changes can be found in the following files

lighthouse/src/main.rs
lighthouse/common/logging/src/lib.rs
lighthouse/common/logging/src/tracing_logging_layer.rs

…itical-dependency-logging

divagant-martian

this needs some changes to correctly obtain at least the gossipsub messages, there are also some open questions about other deps

divagant-martian · 2023-12-11T23:10:42Z

common/logging/src/tracing_logging_layer.rs

+        match *meta.level() {
+            tracing_core::Level::INFO => {
+                let _ = file_writer.write(visitor.message);
+            }
+            tracing_core::Level::WARN => {
+                let _ = file_writer.write(visitor.message);
+            }
+            tracing_core::Level::ERROR => {
+                let _ = file_writer.write(visitor.message);
+            }
+            _ => {}
+        }


why are you filtering out debug messages?

no real reason, I'll add debug messages

don't think you should be filtering here by level, since that can be controlled with the RUST_LOG flag

divagant-martian · 2023-12-11T23:43:13Z

common/logging/src/tracing_logging_layer.rs

+
+lazy_static! {
+    pub static ref TRACING_LOGGING_DEPENDENCIES: Vec<String> =
+        vec!["libp2p".to_string(), "discv5".to_string()];


note that none of the libp2p dependencies has a target/module path named libp2p. I hacked my changes to get metrics on debug to showcase some of the names we will actually get

dep_debug_total{target="libp2p_core"} 11 dep_debug_total{target="libp2p_dns"} 8 dep_debug_total{target="libp2p_gossipsub"} 273 dep_debug_total{target="libp2p_mplex"} 31 dep_debug_total{target="libp2p_quic"} 2 dep_debug_total{target="libp2p_swarm"} 15 dep_debug_total{target="libp2p_tcp"} 13

we probably need to decide which of these we want and what to do with enabled logs of deps not on the list @AgeManning

I'm now capturing libp2p_gossipsub, but can make changes to include some, or all, of the libp2p dependencies based on what we decide

Yeah I think just gossipsub is fine initially. We can maybe add some others in later if things get really spicy.

AgeManning

Awesome! This looks great! Thanks a lot!

Had a few comments, some are just questions :)

AgeManning · 2023-12-12T21:38:35Z

common/logging/src/tracing_logging_layer.rs

+                    let _ = NonBlockingFileWriter::clear_file(&path);
+                }
+
+                if let Err(e) = writeln!(file, "{}", message) {


I think it might be useful to tag on the time here.

Typically when things go wrong, they break at some specific time. It would be very useful to have a timestamp so we can cross-reference with metrics/lighthouse logs.

AgeManning · 2023-12-12T21:39:04Z

common/logging/src/tracing_logging_layer.rs

+    }
+
+    fn clear_file(path: &PathBuf) -> std::io::Result<()> {
+        File::create(path)?;


Is it possible for us to maybe just nuke half the file?

Just worried about the case that we get a bug, but we have just recently removed all our logs and have no history.

AgeManning · 2023-12-12T21:45:07Z

lighthouse/src/main.rs

+    // Debugging output for discv5, libp2p and external crates.
    if matches.is_present("env_log") {
-        Builder::from_env(Env::default()).init();
+        eprintln!("The -l flag is DEPRECATED. Dependency logging will be on by default.");


We can probably just remove this conditional altogether.

I dont think we ever use logging to terminal outside of slog, so probably not worth having this exception here. I'm not sure anyone is really using this flag anyway, except for the devs

ok talked to paul and he tells me you discussed this. We are then NOT removing the flag, simply the warning. Leaving here for the record

done in c222b36

AgeManning · 2023-12-12T21:50:34Z

common/logging/src/lib.rs


+pub fn create_tracing_layer(logfile_max_size: u64, base_tracing_log_path: PathBuf) {
+    let filter_layer = match tracing_subscriber::EnvFilter::try_from_default_env()
+        .or_else(|_| tracing_subscriber::EnvFilter::try_new("warn"))


Maybe we use debug by default?

this one's for me, will change to debug

done in c222b36

AgeManning · 2023-12-12T21:56:56Z

common/logging/src/tracing_logging_layer.rs

+                }
+            };
+
+            for message in receiver {


Maybe I'm missing something here.

Shouldn't we have a loop here somewhere. It seems like this thread just reads all the messages, writes them, then ends?

It also looks like there is one of these threads per dependency/file. I was expecting an await, or perhaps this tasks continually gets created, but I only saw one initialisation. I'm likely missing something.

Shouldn't we have a loop here somewhere. It seems like this thread just reads all the messages, writes them, then ends?

As far as i understand it, the mpsc channel creates a sender and receiver. The receiver blocks until a message is available (as long as sender still exists).

https://doc.rust-lang.org/std/sync/mpsc/fn.channel.html

So that for message in receiver loop blocks until a message is received and should never end as long as the sender exists.

It also looks like there is one of these threads per dependency/file. I was expecting an await, or perhaps this tasks continually gets created, but I only saw one initialisation. I'm likely missing something.

There is one thread per dependency, the stream initialization per dependency happens here

Might be a bit overkill to spawn a new stream per dependency, I can change it to one stream for all dependencies if that makes more sense

ah yeah all good. Sorry have been in tokio async land too long and forgot about std channels :p

AgeManning · 2023-12-12T23:15:40Z

common/logging/src/lib.rs

+    {
+        Ok(filter) => filter,
+        Err(e) => {
+            eprintln!("Failed to initialize dependency tracing {e}");


I think at this point we don't have a useable slogger, so we are forced into prtinln! right?

yep that's the reason

AgeManning · 2023-12-19T03:53:17Z

@divagant-martian has suggested some traits that might make this a bit nicer.

There is this trait: https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/fmt/writer/trait.MakeWriter.html which might help with logging fancy logs and timestamps etc.

There is this one: https://docs.rs/tracing-appender/latest/tracing_appender/non_blocking/struct.NonBlocking.html
Which may help with the non-blocking writing of logs.

And this one: https://docs.rs/tracing-appender/latest/tracing_appender/rolling/struct.RollingFileAppender.html

Which might help with writing to a file with in a rolling fashion so we can maintain the size rather than clearing half periodically, etc.

eserilev · 2023-12-30T07:35:58Z

those suggestions seem to have simplified some things. I think this should be ready for another review

eserilev · 2023-12-30T07:43:37Z

discv5 logs

2023-12-30 06:19:53 INFO  Discv5 Service started
2023-12-30 06:19:53 INFO  Ip4
2023-12-30 06:19:53 INFO  16Uiu2HAmEgUR5kmcKF8z3VQKwEKxbBgDoToWHp3DdAefJybbwBoV
2023-12-30 06:19:54 INFO  Local UDP socket updated to: 77.127.179.45:9000
2023-12-30 06:20:14 WARN  NODES Response failed, but was partially processed from: Node: 0x2971..de4d, addr: 174.61.110.113:9100
2023-12-30 06:20:15 WARN  NODES Response failed, but was partially processed from: Node: 0x296a..2228, addr: 104.58.212.29:9002
2023-12-30 06:20:23 WARN  Query id: QueryId(2) timed out
2023-12-30 06:20:41 WARN  NODES Response failed, but was partially processed from: Node: 0xbbfc..d98e, addr: 165.154.224.42:9000
2023-12-30 06:20:50 WARN  NODES Response failed, but was partially processed from: Node: 0x7e81..ef2c, addr: 216.212.216.227:9005
2023-12-30 06:20:50 WARN  Query id: QueryId(7) timed out
2023-12-30 06:20:52 WARN  NODES Response failed, but was partially processed from: Node: 0x6b0a..7d2e, addr: 176.127.215.52:12103
2023-12-30 06:20:53 WARN  Query id: QueryId(8) timed out
2023-12-30 06:21:18 WARN  NODES Response failed, but was partially processed from: Node: 0x0a0a..2412, addr: 45.50.92.150:9000
2023-12-30 06:21:20 WARN  Query id: QueryId(12) timed out
2023-12-30 06:21:23 WARN  Query id: QueryId(13) timed out
2023-12-30 06:21:34 WARN  NODES Response failed, but was partially processed from: Node: 0x00d2..309e, addr: 90.197.108.62:12103
2023-12-30 06:21:35 WARN  NODES Response failed, but was partially processed from: Node: 0x003f..82ad, addr: 120.226.39.101:12000
2023-12-30 06:21:51 WARN  Query id: QueryId(18) timed out
2023-12-30 06:21:53 WARN  Query id: QueryId(19) timed out

libp2p logs

2023-12-30 06:34:41 WARN  Rejected message not in cache 879b74cbcbd330d52d1872b6cbd4a55c148628b0
2023-12-30 06:34:41 WARN  Rejected message not in cache fb859e0b1525fb96ab4ef1173e0e15b12231c9d2
2023-12-30 06:34:41 WARN  Rejected message not in cache 8739ca4f524019c786ade9c1082205a1c213ef83
2023-12-30 06:34:41 WARN  Rejected message not in cache 769a533ce08502ace31f7eda9d07037e3ec9e907
2023-12-30 06:34:41 WARN  Rejected message not in cache 22397a3372d2ecc518f68434a5d8ab1a0f65031c
2023-12-30 06:34:41 WARN  Rejected message not in cache a0eba3cdc2b94a888cab3fc79e641b762c4d257d
2023-12-30 06:34:41 WARN  Rejected message not in cache 1adca446acb3abe928f8b0d5ee47d93a9fe7374d
2023-12-30 06:34:41 WARN  Rejected message not in cache ad0dc640889db2209a6b012360a04ef3ec827210
2023-12-30 06:34:41 WARN  Rejected message not in cache d817cbe7d3095c31c2a17fe23696d0b881330d16
2023-12-30 06:34:41 WARN  Rejected message not in cache 6de7d7fb40600cf73a4e6764d3eefe040c18ec7e
2023-12-30 06:34:41 WARN  Rejected message not in cache 2fad3b164441bc50e27177f736b84b6cc0306a9b

AgeManning

Nice. This looks much cleaner.

We are doing some releases at the moment. So will get this guy in once we're accepting more code.

divagant-martian and others added 22 commits December 4, 2023 16:00

add metrics layer

0087a0e

add metrics

39b2533

simplify getting the target

57baf2d

make clippy happy

71ad6a0

fix typos

dc46e92

unify deps under workspace

b3e5ea0

make import statement shorter, fix typos

94573c7

enable warn by default, mark flag as deprecated

a18c189

do not exit on error when initializing logging fails

908ad21

revert exit on error

9dd307d

adjust bootnode logging

9a6d862

add logging layer

5b2395b

non blocking file writer

de2840e

non blocking file writer

d6ff17e

add tracing visitor

a158865

Merge branch 'unstable' of https://github.com/sigp/lighthouse into cr…

1ffac2c

…itical-dependency-logging

use target as is by default

85deec7

make libp2p events register correctly

46e0ec9

Merge branch 'unstable' into deps-logging-metrics

c2b7423

adjust repilcated cli help

f6c4d27

refactor tracing layer

bedf55f

linting

7e227a0

eserilev changed the title ~~[WIP] Critical dependency logging~~ Critical dependency logging Dec 11, 2023

filesize

5bbf27f

eserilev marked this pull request as ready for review December 11, 2023 22:57

divagant-martian suggested changes Dec 11, 2023

View reviewed changes

divagant-martian added the waiting-on-author The reviewer has suggested changes and awaits thier implementation. label Dec 12, 2023

log gossipsub, dont filter by log level

6ce1a4e

AgeManning reviewed Dec 12, 2023

View reviewed changes

AgeManning mentioned this pull request Dec 12, 2023

add tracing metrics layer for dependency logging #4979

Merged

divagant-martian and others added 5 commits December 13, 2023 11:57

turn on debug logs by default, remove deprecation warning

c222b36

Merge branch 'unstable' into deps-logging-metrics

e256953

resolve merge conflicts

72ee781

truncate file, add timestamp, add unit test

509a421

suppress output (#5)

0d73f76

use tracing appender

f25dcb6

merge changes from 4979

5abb2c5

cleanup

958bb7b

AgeManning approved these changes Jan 9, 2024

View reviewed changes

AgeManning added ready-for-merge This PR is ready to merge. and removed waiting-on-author The reviewer has suggested changes and awaits thier implementation. labels Jan 9, 2024

AgeManning added 3 commits January 16, 2024 12:25

Merge latest unstable

ebf4b29

Add a task to remove old log files and upgrade to warn level

f7dea99

Add the time feature for tokio

32bbbfd

macladson mentioned this pull request Jan 16, 2024

Add env-filter feature flag to tracing-subscriber #5072

Closed

Udeps and fmt

b2f9d96

AgeManning merged commit f22e5b0 into sigp:unstable Jan 16, 2024

pawanjay176 mentioned this pull request Mar 11, 2024

Gossipsub logging #5389

Closed

ackintosh mentioned this pull request May 22, 2024

Ciritical dependency logging #4954

Closed

jimmygchen mentioned this pull request Aug 9, 2024

"Failed to initialize libp2p rolling file" when --logfile is specified #6246

Closed

Conversation

eserilev commented Dec 6, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Issue Addressed

Proposed Changes

Additional Info

Uh oh!

divagant-martian left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

divagant-martian Dec 11, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

AgeManning left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

AgeManning commented Dec 19, 2023

Uh oh!

eserilev commented Dec 30, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

eserilev commented Dec 30, 2023

Uh oh!

AgeManning left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

eserilev commented Dec 6, 2023 •

edited

Loading

divagant-martian Dec 11, 2023 •

edited

Loading

eserilev commented Dec 30, 2023 •

edited

Loading