Debug level log appearing in stdout when log level is set to INFO

[jimmygchen]

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.

[chong-he]

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"

[jimmygchen]

Fixed in #7620