feat: make info log default level in most cases

[KolbyML]

What was wrong?

fixes #940

How was it fixed?

by adding info as the default log level. Then setting discv5 to Error cause it is super noisy.

https://stackoverflow.com/a/67310139 < apparently log level hierarchy is in order of error > warn > info > debug > trace. So by enabling info we are also enabling warn.

/home/kolby/.cargo/bin/cargo run --color=always --package trin --bin trin
    Finished dev [unoptimized + debuginfo] target(s) in 0.68s
     Running `target/debug/trin`
2023-10-18T01:00:53.405856Z  INFO trin: Launching Trin: v0.1.1-alpha.1-de638d
2023-10-18T01:00:53.405942Z  INFO trin: With: config=TrinConfig { networks: ["history"], capacity_mb: 100, ephemeral: false, json_rpc_url: /tmp/trin-jsonrpc.ipc, metrics_enabled: false }
2023-10-18T01:00:53.413046Z  INFO portalnet::socket: Connecting to STUN server to find public network endpoint
2023-10-18T01:00:53.639299Z  INFO portalnet::discovery: Starting discv5 enr.encoded=Enr { id: Some("v4"), seq: 6, NodeId: 0x3cad3f55f919d98b19d18585715423de28223470be2915cf88178b9a08b0d2f9, signature: "6d8bcd7d073db0024207c1542763e9eb40db1bf085a55c55cfdb3799091d9cca7da772cd286a5828dbdc047b8bbfb9cd27b6a9218c69205f0e885c60c1fb0027", IpV4 UDP Socket: Some(162.157.246.69:9000), IpV6 UDP Socket: None, IpV4 TCP Socket: None, IpV6 TCP Socket: None, Other Pairs: [("c", "967420302e312e312d616c7068612e312d646536333864"), ("secp256k1", "a10277004232d5c704729c216cd91a9c861dd1d72fa5e9beb6ddcd02506c980a34d5")] } enr.decoded=enr:-Jy4QG2LzX0HPbACQgfBVCdj6etA2xvwhaVcVc_bN5kJHZzKfadyzShqWCjb3AR7i7-5zSe2qSGMaSBfDohcYMH7ACcGY5Z0IDAuMS4xLWFscGhhLjEtZGU2MzhkgmlkgnY0gmlwhKKd9kWJc2VjcDI1NmsxoQJ3AEIy1ccEcpwhbNkanIYd0dcvpem-tt3NAlBsmAo01YN1ZHCCIyg
2023-10-18T01:00:53.640704Z  INFO portalnet::storage: Setting up RocksDB path=/home/kolby/.local/share/trin/trin_0x3cad3f/rocksdb
2023-10-18T01:00:53.709884Z  INFO portalnet::storage: Setting up SqliteDB path=/home/kolby/.local/share/trin/trin_0x3cad3f/trin.sqlite
2023-10-18T01:00:53.713269Z  INFO trin: Loaded master accumulator from: "validation_assets/merge_macc.bin"
2023-10-18T01:00:53.717797Z  INFO trin_history: About to spawn History Network with 11 boot nodes
2023-10-18T01:00:53.717835Z  INFO portalnet::overlay_service: Starting overlay service protocol=History
2023-10-18T01:00:53.719158Z  INFO trin_history: reports~ data: radius=1.6% content=100.2/100mb #=1500 disk=51.3mb; msgs: offers=0/0, accepts=0/0, validations=0/0
2023-10-18T01:00:53.719200Z  INFO trin_history: reports~ utp: (in/out): active=0 (0/0), success=0 (0/0), failed=0 (0/0) failed_connection=0 (0/0), failed_data_tx=0 (0/0), failed_shutdown=0 (0/0)
2023-10-18T01:00:54.212034Z  INFO portalnet::overlay: Bonded with bootnode alias=fluffy-4 protocol=History
2023-10-18T01:00:54.373834Z  INFO portalnet::overlay: Bonded with bootnode alias=trin-ams3-1 protocol=History
2023-10-18T01:00:54.456552Z  INFO portalnet::overlay: Bonded with bootnode alias=trin-nyc1-1 protocol=History
2023-10-18T01:00:55.011572Z  INFO portalnet::overlay: Bonded with bootnode alias=trin-sgp1-1 protocol=History
2023-10-18T01:00:55.472659Z  INFO portalnet::overlay: Bonded with bootnode alias=fluffy-1 protocol=History
2023-10-18T01:00:55.880641Z  INFO portalnet::overlay: Bonded with bootnode alias=fluffy-2 protocol=History
2023-10-18T01:00:56.310806Z  INFO portalnet::overlay: Bonded with bootnode alias=fluffy-3 protocol=History
2023-10-18T01:00:57.314254Z ERROR portalnet::overlay: Error bonding with bootnode alias=ultralight-1 protocol=History error=The request timed out
2023-10-18T01:00:58.317525Z ERROR portalnet::overlay: Error bonding with bootnode alias=ultralight-2 protocol=History error=The request timed out
2023-10-18T01:00:59.320746Z ERROR portalnet::overlay: Error bonding with bootnode alias=ultralight-3 protocol=History error=The request timed out
2023-10-18T01:01:00.324565Z ERROR portalnet::overlay: Error bonding with bootnode alias=ultralight-4 protocol=History error=The request timed out
2023-10-18T01:01:03.064548Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xfda8..714d }
2023-10-18T01:01:03.527396Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x9c70..5ce6 }
2023-10-18T01:01:05.979406Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xe8a1..c082 }
2023-10-18T01:01:09.650795Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xed7b..f86e }
2023-10-18T01:01:09.696368Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xc78c..9538 }
2023-10-18T01:01:12.042423Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xa445..1ddd }
2023-10-18T01:01:14.571173Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x78c4..5be8 }
2023-10-18T01:01:15.831416Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xbabb..19f9 }
2023-10-18T01:01:16.299992Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x8ffd..b148 }
2023-10-18T01:01:18.094395Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x8ffd..b148 }
2023-10-18T01:01:18.384973Z  WARN portalnet::overlay_service: Accepted content already stored content.key=0x028ffd59def0d765d909310da48b44d261e80491e98c24e1866febf1827bebb148
2023-10-18T01:01:21.842171Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xbabb..19f9 }
2023-10-18T01:01:22.159721Z  WARN portalnet::overlay_service: Accepted content already stored content.key=0x01babbd90fce526379a44d471d4c4c87b00e6fb4aae6d3ca4a456aa7e08e1919f9
2023-10-18T01:01:23.719611Z  INFO trin_history: reports~ data: radius=1.6% content=100.0/100mb #=1493 disk=50.0mb; msgs: offers=99/105, accepts=23/23, validations=24/24
2023-10-18T01:01:23.719658Z  INFO trin_history: reports~ utp: (in/out): active=3 (2/1), success=16 (13/3), failed=0 (0/0) failed_connection=0 (0/0), failed_data_tx=0 (0/0), failed_shutdown=0 (0/0)
2023-10-18T01:01:27.325276Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x6d4c..5d9c }
2023-10-18T01:01:46.879971Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xf9ae..ad2f }
2023-10-18T01:01:53.719499Z  INFO trin_history: reports~ data: radius=1.6% content=100.2/100mb #=1494 disk=50.4mb; msgs: offers=145/153, accepts=76/76, validations=32/32
2023-10-18T01:01:53.719553Z  INFO trin_history: reports~ utp: (in/out): active=1 (1/0), success=25 (19/6), failed=0 (0/0) failed_connection=0 (0/0), failed_data_tx=0 (0/0), failed_shutdown=0 (0/0)
2023-10-18T01:02:12.060103Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xfd04..c27a }
2023-10-18T01:02:23.718853Z  INFO trin_history: reports~ data: radius=1.6% content=100.0/100mb #=1485 disk=50.9mb; msgs: offers=160/169, accepts=89/89, validations=35/35
2023-10-18T01:02:23.718910Z  INFO trin_history: reports~ utp: (in/out): active=1 (1/0), success=27 (21/6), failed=0 (0/0) failed_connection=0 (0/0), failed_data_tx=0 (0/0), failed_shutdown=0 (0/0)
2023-10-18T01:02:50.110787Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x1142..a1c6 }
2023-10-18T01:02:53.719521Z  INFO trin_history: reports~ data: radius=1.6% content=100.1/100mb #=1490 disk=51.0mb; msgs: offers=197/209, accepts=152/152, validations=41/41
2023-10-18T01:02:53.719577Z  INFO trin_history: reports~ utp: (in/out): active=2 (2/0), success=33 (26/7), failed=0 (0/0) failed_connection=0 (0/0), failed_data_tx=0 (0/0), failed_shutdown=0 (0/0)
2023-10-18T01:02:53.907369Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x9733..e5a2 }
2023-10-18T01:03:08.371165Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0xb008..6dd4 }
2023-10-18T01:03:10.575076Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x94c6..ea1b }
2023-10-18T01:03:18.548284Z  INFO portalnet::overlay_service: Starting query for content key: BlockHeaderWithProof { block_hash: 0x90ae..ce87 }
2023-10-18T01:03:23.718954Z  INFO trin_history: reports~ data: radius=1.6% content=100.0/100mb #=1490 disk=51.4mb; msgs: offers=229/241, accepts=417/417, validations=49/49
2023-10-18T01:03:23.718992Z  INFO trin_history: reports~ utp: (in/out): active=1 (1/0), success=38 (30/8), failed=0 (0/0) failed_connection=0 (0/0), failed_data_tx=0 (0/0), failed_shutdown=0 (0/0)

^ This is an example of what it looks like

[njgheorghita]

Seems like it's also worth implementing the fix for #938 in this pr

[KolbyML]

@njgheorghita ok I will change utp to error cause that is the only thing we can do on Trin side. I think that issue is mostly for modifying logs in the uTP repo itself

[njgheorghita]

I do agree that by default, utp library errors should be set to ERROR. But I understood the issue as referring to the following trin-native logs that are emitted based on utp tx performance. I think these are what @ogenev was referring to updating to DEBUG / TRACE. The following is just some of the places where this happens that I noticed, it's not a conclusive list, there might be others I missed

• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L846
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L818
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L866
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1126
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1137
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1275
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1284
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1302
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1539
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1585
• https://github.com/ethereum/trin/blob/master/portalnet/src/overlay_service.rs#L1592

[KolbyML]

Ok I pushed a change, changing uTP related ones to debug as I don't think those logs fit within the guidelines for a trace log. I did leave 2 warns if sending a talk_req over discv5 failed as those logs aren't uTP issues technically.

[njgheorghita]

While we're improving these logs... could you also update this log...

2023-10-18T01:00:53.639299Z  INFO portalnet::discovery: Starting discv5 enr.encoded=Enr { id: Some("v4"), seq: 6, NodeId: 0x3cad3f55f919d98b19d18585715423de28223470be2915cf88178b9a08b0d2f9, signature: "6d8bcd7d073db0024207c1542763e9eb40db1bf085a55c55cfdb3799091d9cca7da772cd286a5828dbdc047b8bbfb9cd27b6a9218c69205f0e885c60c1fb0027", IpV4 UDP Socket: Some(162.157.246.69:9000), IpV6 UDP Socket: None, IpV4 TCP Socket: None, IpV6 TCP Socket: None, Other Pairs: [("c", "967420302e312e312d616c7068612e312d646536333864"), ("secp256k1", "a10277004232d5c704729c216cd91a9c861dd1d72fa5e9beb6ddcd02506c980a34d5")] } enr.decoded=enr:-Jy4QG2LzX0HPbACQgfBVCdj6etA2xvwhaVcVc_bN5kJHZzKfadyzShqWCjb3AR7i7-5zSe2qSGMaSBfDohcYMH7ACcGY5Z0IDAuMS4xLWFscGhhLjEtZGU2MzhkgmlkgnY0gmlwhKKd9kWJc2VjcDI1NmsxoQJ3AEIy1ccEcpwhbNkanIYd0dcvpem-tt3NAlBsmAo01YN1ZHCCIyg

IMO all it should show is the decoded enr at the INFO level. But it might be useful to add a DEBUG level log that contains all of the above information.

[KolbyML]

Ok change pushed

[KolbyML]

Nick told me how he wanted the chore: make discv5 start log hierarchical commit and said he wanted more eyes on what the text should be in the debug log. We talked about it on discord so just propogating the goal.

[njgheorghita]

#1000 🥳 🚢

[mrferris]

#💯0

wording on debug logs looks good

👍

[pipermerriam]

1000 pull requests!