Integrate tracing

[ThreeHrSleep]

Issue Addressed

Tracing Integration

• reference

Proposed Changes

• replace slog & log with tracing throughout the codebase
• implement custom crit log
• make relevant changes in the formatter
• replace sloggers
• re-write SSE logging components

cc: @macladson @eserilev

[eserilev]

Tracing

Slog

[eserilev]

at the moment this is what a crit log looks like

its labeled as ERROR but with an error_type = crit. Im wondering if we can tweak the formatting here to display CRIT in purple instead of ERROR (as we have currently for our slog impl)

[eserilev]

Great work so far!

Most of my suggested changes revolve around making sure we stick to display formatting vs debug formatting.

I think we have some options to simplify the crit! macro a bit

For crit level errors we'll want to display the Crit log similarly to how they are currently displayed with slog. This will involve implementing a custom tracing layer that takes in those crit logs and formats them appropriately.

In situations where we use slog:o! I think we can replace those with a tracing span

Theres some instances where we are still importing slog, we should try removing those if possible

[mergify]

This pull request has merge conflicts. Could you please resolve them @ThreeHrSleep? 🙏

[eserilev]

It seems that when I had introduced #[instrument] macro usage in a previous commit, I broke some things. Sorry for all the headaches!

• I've tweaked the #[instrument] attribute macro to skip recording all arguments of a calling function/method via skip_all. We may have been recording complex/large data types would could have led to increased memory usage
• I've tweaked the #[instrument] macro with parent = None. Previously, active spans with the same name would reference each other and stack in a "hierarchy of events" tree that tracing manages under the hood. With parent = None, spans with the same name wont reference each other anymore, and are instead treated as root spans. I think we may have had some deeply nested spans that may have potentially contributed to some of our OOM issues.

Testing locally things seem okay now! Going to deploy to one of our holesky nodes soon

[eserilev]

Some feedback from anton:

Ensure we stick to comma separated kv format

we used to have this format:

Feb 05 13:58:01.139 DEBG Obtained peer's metadata                new_seq_no: 415, peer_id: 16Uiu2HAmEMKzZFRN2u1ByvwCWqU6nn9rutg87asbPyofd7NsM4Kn, service: libp2p

decoded as folllows :

match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +) error: %{GREEDYDATA:error}\), %{GREEDYDATA:kv_pairs}" }
match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +) %{GREEDYDATA:kv_pairs}" }
match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}" }

ideally we should keep this log format (comma separated key values)

Fix one of the log formats

if we can mutate this one from:

Feb 05 14:06:06.552 DEBUG 974b737b797058e49fad2090a55aabe34b26148e      service="network"

to:

Feb 05 14:06:06.552 DEBUG new message recorded                                                     message="974b737b797058e49fad2090a55aabe34b26148e", service="network"

to keep consistency

Match current parsing rules

current parsing rules:

bootnode: 
       match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +|\.) %{GREEDYDATA:kv_pairs}" }
vc: 
       match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +) %{GREEDYDATA:kv_pairs}" }
bn:
       match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +) error: %{GREEDYDATA:error}\), %{GREEDYDATA:kv_pairs}" }
       match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +) %{GREEDYDATA:kv_pairs}" }
       match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}" }

ideally any and all of these should be correctly parsed with just the one

match => { "message" => "%{SYSLOGTIMESTAMP} %{WORD:loglevel} %{DATA:msg}(,| +) %{GREEDYDATA:kv_pairs}" }

[ThreeHrSleep]

Fix one of the log formats

if we can mutate this one from:

Feb 05 14:06:06.552 DEBUG 974b737b797058e49fad2090a55aabe34b26148e      service="network"

to:

Feb 05 14:06:06.552 DEBUG new message recorded                                                     message="974b737b797058e49fad2090a55aabe34b26148e", service="network"

to keep consistency

it looks like this type of logs were appearing because in some places (like this) the word message was being used as field name which interfered with the literal log message

this should (hopefully) fix it

[antondlr]

we ran out of disk space on our tracing node because the file-based logs use different naming, and the limits are not respected:
we used to have one beacon.log for appending and beacon.log._n_(.gz) for rotating according to --logfile-max-number and --logfile-compress.
Now, all the logs are stored in one big beacon.$date.log file, rotated out every day but never (? maybe after max-number days?) cleaned, and crucially, never compressed.
Given the amount of logs one (debug) BN generates, this rapidly filled up our disk.

To minimise impact on other people's deployment, we should re-implement the old naming and rotation scheme.

[mergify]

This pull request has merge conflicts. Could you please resolve them @ThreeHrSleep? 🙏

[antondlr]

thanks for this ! 🙏
two more nits in this regard:

• rotation numbering is off, it just keeps going up where in the old naming scheme, there was always only a beacon.log.{1-n}.gz where n == --logfile-max-number
• the discv5 and libp2p logs are still on the monolithical, non-rotated, one-per-day naming scheme