debug log level is very noisy

[thomaseizinger]

I appreciate the addition of logs but I'd like to discuss whether some of them can/should be demoted to trace. Here is a short excerpt from booting up a very simple rust-libp2p node:

2023-10-31T01:45:38.565352Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.565401Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.565444Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.565482Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.565519Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.565554Z DEBUG Swarm::poll: netlink_proto::connection: sending messages
2023-10-31T01:45:38.565618Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.565660Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.565699Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.565736Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.565772Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.565830Z DEBUG Swarm::poll: netlink_proto::connection: sending messages
2023-10-31T01:45:38.565883Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.565923Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.565962Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.565998Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.566034Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.566074Z DEBUG Swarm::poll: netlink_proto::connection: sending messages
2023-10-31T01:45:38.566121Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.566160Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.566199Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.566254Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.566295Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.566332Z DEBUG Swarm::poll: netlink_proto::connection: sending messages
2023-10-31T01:45:38.566379Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.566418Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.566464Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.566516Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.566552Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.566602Z DEBUG Swarm::poll: netlink_proto::connection: sending messages
2023-10-31T01:45:38.566653Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.566694Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.566739Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.566784Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.566824Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.566860Z DEBUG Swarm::poll: netlink_proto::connection: sending messages
2023-10-31T01:45:38.566908Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages
2023-10-31T01:45:38.566949Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message
2023-10-31T01:45:38.566990Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle
2023-10-31T01:45:38.567027Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle
2023-10-31T01:45:38.567078Z DEBUG Swarm::poll: netlink_proto::connection: handling requests
2023-10-31T01:45:38.567118Z DEBUG Swarm::poll: netlink_proto::connection: sending messages

Choosing the right log-level is in many ways subjective. Personally, I somewhat loosely follow these rules for debug vs trace:

• debug: Minor state change within the system or otherwise hints on what we have been doing. For example, if we make multiple attempts of something and end up succeeding on the 3rd, the first two could log as debug. Or if we bail early from a function because some pre-condition is not true, we could log that as debug.
• trace: Messages that are interleaved with the execution flow of the program, "describing" in detail what we are doing.

Based on the above, I'd categorize the following here all as trace:

netlink-proto/src/connection.rs

Lines 299 to 328 in aafea32

	fn poll(self: Pin<&mut Self>, cx: &mut Context) -> Poll<Self::Output> {
	trace!("polling Connection");
	let pinned = self.get_mut();
	debug!("reading incoming messages");
	pinned.poll_read_messages(cx);
	debug!("forwarding unsolicited messages to the connection handle");
	pinned.forward_unsolicited_messages();
	debug!(
	"forwarding responses to previous requests to the connection handle"
	);
	pinned.forward_responses();
	debug!("handling requests");
	pinned.poll_requests(cx);
	debug!("sending messages");
	pinned.poll_send_messages(cx);
	trace!("done polling Connection");
	if pinned.should_shut_down() {
	Poll::Ready(())
	} else {
	Poll::Pending
	}
	}
	}

What makes them particularly noisy is that they get logged every time, even if the called function doesn't actually do anything. (An orthogonal topic here is that the log messages should probably be placed inside the function to co-locate them with the functionality they are describing. That way, every caller "benefits" from these logs and doesn't have to duplicate them).

Let me know what you think! Happy to send a PR if you agree :)