Reduce tracing level for iroh internals?

[rklaehn]

When I write iroh based programs, it is quite annoying that your tracing log will be spammed with iroh internals even if you run at info level, unless you explicitly exclude iroh internals in the RUST_LOG=... env var.

Maybe we should have a way to shift iroh internals logs to trace somehow?

[flub]

The info level should be fairly curated and not spammy. If there's something spammy on there then that's a bug and we should fix it.

In general however I think we could do a pass through all the debug and trace messages and probably remove about half of them, (certainly trace, debug has had some small amount of curating already). Most were added to debug specific things that no longer need debugging by now.

[matheus23]

When I connect to another node, these are the iroh info logs I get:

logs

2025-03-04T09:52:32.979223Z  INFO ep{me=85e7945de3}:magicsock:actor: iroh::magicsock: home is now relay https://euw1-1.relay.iroh.network./, was None
2025-03-04T09:52:33.039937Z  INFO connect{me="85e7945de3" alpn="n0/drderp/1" remote="a55f26132e" remote="a55f26132e"}:discovery{me=85e7945de3 node=a55f26132e}:add_node_addr{me=85e7945de3}:add_node_addr{node=a55f26132e}: iroh::magicsock::node_map: inserting new node in NodeMap node=a55f26132e relay_url=Some(RelayUrl("https://euw1-1.relay.iroh.network./")) source=dns
2025-03-04T09:52:33.040537Z  INFO connect{me="85e7945de3" alpn="n0/drderp/1" remote="a55f26132e" remote="a55f26132e"}:try_send:get_send_addrs{node=a55f26132e}: iroh::magicsock::node_map::node_state: new connection type typ=relay(https://euw1-1.relay.iroh.network./)
2025-03-04T09:52:33.145064Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp(xxx.xxx.x.xx:41253)}: iroh::magicsock::node_map::node_state: new direct addr for node addr=xxx.xxx.x.xx:41253
2025-03-04T09:52:33.145449Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp([XXXX:XXXX:XXX:XXXX::XXXX]:41254)}: iroh::magicsock::node_map::node_state: new direct addr for node addr=[XXXX:XXXX:XXX:XXXX::XXXX]:41254
2025-03-04T09:52:33.145627Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)}: iroh::magicsock::node_map::node_state: new direct addr for node addr=[XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254
2025-03-04T09:52:33.145794Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)}: iroh::magicsock::node_map::node_state: new direct addr for node addr=[XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254
2025-03-04T09:52:33.146033Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp(xxx.xxx.x.xx:41253)}:handle_pong{m=Pong { tx_id: TransactionId(0x7D2D1ABFE2BC63B50764FD8E), ping_observed_addr: Udp(xxx.xxx.x.xx:42774) } src=Udp(xxx.xxx.x.xx:41253)}: iroh::magicsock::node_map::best_addr: selecting new direct path for node addr=xxx.xxx.x.xx:41253 latency=794.813µs trust_for=6.499953136s
2025-03-04T09:52:33.146256Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp([XXXX:XXXX:XXX:XXXX::XXXX]:41254)}:handle_pong{m=Pong { tx_id: TransactionId(0x1E14720AFADE775A818F2FE7), ping_observed_addr: Udp([XXXX:XXXX:XXX:XXXX::XXXX]:42775) } src=Udp([XXXX:XXXX:XXX:XXXX::XXXX]:41254)}: iroh::magicsock::node_map::best_addr: selecting new direct path for node addr=[XXXX:XXXX:XXX:XXXX::XXXX]:41254 latency=631.241µs trust_for=6.499958373s
2025-03-04T09:52:33.146356Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)}:handle_pong{m=Pong { tx_id: TransactionId(0x726F2555D4B4DA4747BE8B17), ping_observed_addr: Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:42775) } src=Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)}: iroh::magicsock::node_map::best_addr: selecting new direct path for node addr=[XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254 latency=545.963µs trust_for=6.499954812s
2025-03-04T09:52:33.146464Z  INFO ep{me=85e7945de3}:magicsock:poll_recv:disco_in{node=a55f26132e src=Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)}:handle_pong{m=Pong { tx_id: TransactionId(0x708EB3371ACE2DE94327565D), ping_observed_addr: Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:42775) } src=Udp([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)}: iroh::magicsock::node_map::best_addr: selecting new direct path for node addr=[XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254 latency=487.434µs trust_for=6.499948107s
2025-03-04T09:52:33.165654Z  INFO connect{me="85e7945de3" alpn="n0/drderp/1" remote="a55f26132e" remote="a55f26132e"}:try_send:get_send_addrs{node=a55f26132e}: iroh::magicsock::node_map::node_state: new connection type typ=direct([XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXXX]:41254)

I agree that's quite spammy for a single connection.

[flub]

The "home is now relay ..." and "selecting new direct path for node ..." are intentionally info I think. The others can probably be reduced.

I agree that on a busy node logging on info for every connection is perhaps not great, though we need to balance this with folks getting some easy positive affirmation that things work.