lighthouse
lighthouse copied to clipboard
sigp
Debug level log appearing in stdout when log level is set to INFO
This bug affects latest unstable and was introduced when tracing was merged.
Actual Behaviour
I'm seeing some DEBUG level logs even when log level is set to INFO via the --debug-level=info flag
[cl-1-lighthouse-geth] Mar 17 12:22:02.893 DEBUG Batch downloaded epoch: 5618, blocks: 28, batch_state: "[p,E,E,E,E]", awaiting_batches: 0, chain: 3, service: "range_sync"
I don't see any other DEBUG logs though, not sure why only this log made it to stdout.
Expected Behaviour
DEBUG log should not be written to stdout when --debug-level is set to info.
A few more debug logs appearing in journalctl:
May 16 16:28:45.037 DEBUG New head chain started syncing id: 1, component: "range_sync"
May 16 16:28:45.037 INFO Sync state updated old_state: Stalled, new_state: Syncing Head Chain, service: "sync"
May 16 16:28:46.861 DEBUG Batch downloaded epoch: 13519, blocks: 31, batch_state: "[p,D,D,E,E]", awaiting_batches: 0, chain: 1, service: "range_sync"
May 16 16:28:46.876 DEBUG Batch downloaded epoch: 13520, blocks: 31, batch_state: "[P,p,D,E,E]", awaiting_batches: 1, chain: 1, service: "range_sync"
May 16 16:28:48.545 DEBUG Batch downloaded epoch: 13521, blocks: 21, batch_state: "[P,p,p,E,E]", awaiting_batches: 2, chain: 1, service: "range_sync"
May 16 16:28:54.000 INFO Syncing peers: "3", distance: "86 slots (17 mins)", est_time: "--"
May 16 16:28:54.000 WARN Syncing deposit contract block cache est_blocks_remaining: "48"
service: "network"
May 16 16:29:06.001 INFO Syncing peers: "2", distance: "54 slots (10 est_blocks_remaining: "48"
May 16 16:29:06.477 DEBUG New head chain started syncing id: 11, component: "range_sync"
May 16 16:29:06.642 DEBUG Batch downloaded epoch: 13520, blocks: 31, batch_state: "[E,E,E,E,E]", awaiting_batches: 0, chain: 11, service: "range_sync"
May 16 16:29:08.474 DEBUG Batch downloaded epoch: 13521, blocks: 23, batch_state: "[p,E,E,E,E]", awaiting_batches: 0, chain: 11, service: "range_sync"
May 16 16:29:18.001 INFO Syncing peers: "4", distance: "23 slots (4 mins)", speed: "2.71 slots/sec", est_time: "0 mins"
May 16 16:29:18.001 WARN Syncing deposit contract block cache est_blocks_remaining: "48"
May 16 16:29:18.933 DEBUG Chain removed id: 1, sync_type: Head, reason: ChainCompleted, op: "batch processing result", component: "range_sync"
May 16 16:29:19.504 DEBUG Chain removed id: 11, sync_type: Head, reason: ChainCompleted, op: "batch processing result", component: "range_sync"
May 16 16:29:19.504 INFO Sync state updated old_state: Syncing Head Chain, new_state: Syncing Historical Blocks, service: "sync"
Re-opening this, I'm still seeing some debug logs even when debug level is set to info, ~~however i no longer see the "Batch downloaded" log, which means the fix in #7620 is effective and should be applied elsewhere~~
^ Still seeing it, the fix didn't help
Jul 05 17:46:52.646 DEBUG New head chain started syncing id: 1, component: "range_sync"
Jul 05 17:46:52.646 INFO Sync state updated old_state: Stalled, new_state: Syncing Head Chain, service: "sync"
Jul 05 17:46:53.618 DEBUG New head chain started syncing id: 2, component: "range_sync"
Jul 05 17:46:53.904 DEBUG New head chain started syncing id: 3, component: "range_sync"
Jul 05 17:46:58.765 INFO Address updated ip: 111.220.88.252, udp_port: 3110, service: "network"
Jul 05 17:47:06.004 INFO Syncing peers: "7", distance: "25831 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:47:16.635 DEBUG New head chain started syncing id: 4, component: "range_sync"
Jul 05 17:47:18.002 INFO Syncing peers: "20", distance: "25832 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:47:30.000 INFO Syncing peers: "32", distance: "25833 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:47:38.595 DEBUG Chain removed id: 4, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:47:38.596 DEBUG New head chain started syncing id: 5, component: "range_sync"
Jul 05 17:47:42.001 INFO Syncing peers: "35", distance: "25834 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:47:46.701 DEBUG Chain removed id: 45, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:47:52.404 DEBUG Chain removed id: 43, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:47:54.001 INFO Syncing peers: "38", distance: "25835 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:48:06.001 INFO Syncing peers: "37", distance: "25836 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:48:06.592 DEBUG Chain removed id: 44, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:48:07.873 DEBUG Chain removed id: 3, sync_type: Head, reason: ChainFailed { blacklist: false, failing_batch: Epoch(1200) }, op: "RPC error", component: "range_sync"
Jul 05 17:48:07.874 DEBUG New head chain started syncing id: 638, component: "range_sync"
Jul 05 17:48:13.640 DEBUG Chain removed id: 2, sync_type: Head, reason: ChainFailed { blacklist: false, failing_batch: Epoch(1198) }, op: "RPC error", component: "range_sync"
Jul 05 17:48:18.001 INFO Syncing peers: "38", distance: "25837 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:48:26.960 DEBUG Chain removed id: 638, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:48:26.960 DEBUG New head chain started syncing id: 1314, component: "range_sync"
Jul 05 17:48:30.001 INFO Syncing peers: "36", distance: "25838 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:48:42.002 INFO Syncing peers: "36", distance: "25839 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:48:54.001 INFO Syncing peers: "32", distance: "25840 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:49:03.378 DEBUG Chain removed id: 5, sync_type: Head, reason: ChainFailed { blacklist: false, failing_batch: Epoch(1200) }, op: "RPC error", component: "range_sync"
Jul 05 17:49:03.378 DEBUG New head chain started syncing id: 1437, component: "range_sync"
Jul 05 17:49:05.034 DEBUG Chain removed id: 1314, sync_type: Head, reason: ChainFailed { blacklist: false, failing_batch: Epoch(1199) }, op: "RPC error", component: "range_sync"
Jul 05 17:49:05.035 DEBUG New head chain started syncing id: 1506, component: "range_sync"
Jul 05 17:49:06.000 INFO Syncing peers: "29", distance: "25841 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:49:18.001 INFO Syncing peers: "29", distance: "25842 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:49:18.382 DEBUG Chain removed id: 1437, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:49:18.382 DEBUG New head chain started syncing id: 2222, component: "range_sync"
Jul 05 17:49:27.831 DEBUG Chain removed id: 1506, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:49:27.831 DEBUG New head chain started syncing id: 614, component: "range_sync"
Jul 05 17:49:30.001 INFO Syncing peers: "27", distance: "25843 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:49:42.001 INFO Syncing peers: "26", distance: "25844 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:49:44.161 DEBUG New head chain started syncing id: 2223, component: "range_sync"
Jul 05 17:49:54.043 INFO Syncing peers: "25", distance: "25845 slots (3 days 14 hrs)", est_time: "--"
Jul 05 17:49:57.202 DEBUG Chain removed id: 2223, sync_type: Head, reason: EmptyPeerPool, op: "peer removed", component: "range_sync"
Jul 05 17:49:57.202 DEBUG New head chain started syncing id: 2978, component: "range_sync"
Looks like we might have to manually set all log level to debug / tracing for all #[instrument] as it defaults to info
Oh, I guess we need to set them all to debug. I thought I tested this 🤦♂️
