feat: introduce tracing

[eserilev]

Description

We replace log with tracing across the codebase. Where possible, we make use of structured logging now instead of templating strings.

tracing offers the ability to also record "span"s. A span lasts until its dropped and describes the entire duration that it is active for. All logs (in tracing term "events") are hierarchically embedded in all parent-spans).

We introduce several spans:

• On debug level: One for new_outgoing_connection, new_incoming_connection and new_established_connection
• On debug level: Connection::poll, Swarm::poll and Pool::poll
• On trace level: NetworkBehaviour::poll for each implementation of NetworkBehaviour
• On trace level: ConnectionHandler::poll for each implementation of (protocol) ConnectionHandlers

The idea here is that logging on debug level gives you a decent overview of what the system is doing. You get spans for the duration of connections and how often each connection gets polled.

Dropping down to trace level gives you an extremely detailed view of how long each individual ConnectionHandler was executed as part of poll which could be used for detailed analysis on how busy certain handlers are.

Most importantly, simply logging on info does not give you any spans. We consider info to be a good default that should be reasonably quiet.

Resolves #1533.

Notes & open questions

Change checklist

• I have performed a self-review of my own code
• I have made corresponding changes to the documentation
• I have added tests that prove my fix is effective or that my feature works
• A changelog entry has been made in the appropriate crates

[thomaseizinger]

Thank you for starting this!

I've left some notes :)

[eserilev]

thank you for the detailed feedback! I'll work to make the changes you suggested and will ping here when its ready for another review

[eserilev]

i've pushed up some changes. To summarize what I've done so far:

• pass error span into connection
• poll should call span.enter on every invocation
• changed span name to connection
• remove unneeded tracing::field::Empty
• removed tracing-subscriber dependency from swarm crate

will leave some comments on a few threads where I'd like to clarify some things

ALSO:
I needed to add a "dummy" span in some of the unit tests that create Connection instances

[thomaseizinger]

Thanks, good progress so far :)

The span is working, see the following screenshot from a local run of the ping-example on my machine:

As you can see, some of the information is duplicated. Now that we capture the PeerId within the connection span, it is printed redundantly in some of the messages. I think we should remove it from those messages.

Also, as I noted inline the peer_address prints the entire ConnectedPoint which is very noisy.

I'd encourage you to run the example yourself (I used RUST_LOG=libp2p_ping=trace,debug cargo run) and tweak the logs until they are concise and informative.

Once the ping protocol is done, we can move on to other protocols and tidy up the logs there!

[eserilev]

thanks again for the feedback. I've cleaned up the logs a bit, removed some of the redundancies, and made some changes based on your feedback. I think the logs look tidy!

[mxinden]

Excited for this to land. Thank you for working on it.

Feel free to ignore comments below at this point.

[thomaseizinger]

thanks again for the feedback. I've cleaned up the logs a bit, removed some of the redundancies, and made some changes based on your feedback. I think the logs look tidy!

This looks great!

@mxinden do you think we should transition more crates or do that in follow-up PRs?

[mxinden]

Either is fine by me.

[eserilev]

if it's ok with you all, I think ill just continue implementing tracing for the other protocols on this branch

[thomaseizinger]

if it's ok with you all, I think ill just continue implementing tracing for the other protocols on this branch

Yes, thank you!

[eserilev]

sorry for the long hiatus. getting back to working on this now

I'll do my best to separate each protocol changes to its own commit and will include some screenshots of tracing logs

first off is autonat logs:

[mxinden]

Apart from the outstanding comments, this is good to merge from my end. Thank you for the work! Looking forward to the insights we will gain from this.

[eserilev]

i believe i resolved the outstanding comments, hopefully I didnt miss anything. the metrics example is really neat!

[thomaseizinger]

@mxinden I believe all your comments have been addressed, please have another look!

[mxinden]

Great work everyone!

[thomaseizinger]

@eserilev Thank you especially for the continuous work here! Migrations like this are very tedious but I am excited for the insights this will bring to our users.

I will mention this prominently in our release notes.