Revisiting log levels (#1788)

* Update log level - #1779 #1785

* Address review comments

* Document the logging strategy [skip ci]

Author: mratsim

beacon_chain/attestation_pool.nim

@@ -55,7 +55,7 @@ proc init*(T: type AttestationPool, chainDag: ChainDAGRef, quarantine: Quarantin
 
     doAssert status.isOk(), "Error in preloading the fork choice: " & $status.error
 
-  info "Fork choice initialized",
+  debug "Fork choice initialized",
     justified_epoch = chainDag.headState.data.data.current_justified_checkpoint.epoch,
     finalized_epoch = chainDag.headState.data.data.finalized_checkpoint.epoch,
     finalized_root = shortlog(chainDag.finalizedHead.blck.root)
@@ -184,7 +184,7 @@ proc addAttestation*(pool: var AttestationPool,
           attestation.data.slot, participants, attestation.data.beacon_block_root,
           wallSlot)
 
-        info "Attestation resolved",
+        debug "Attestation resolved",
           attestation = shortLog(attestation),
           validations = a.validations.len()
 
@@ -201,7 +201,7 @@ proc addAttestation*(pool: var AttestationPool,
       attestation.data.slot, participants, attestation.data.beacon_block_root,
       wallSlot)
 
-    info "Attestation resolved",
+    debug "Attestation resolved",
       attestation = shortLog(attestation),
       validations = 1
 

beacon_chain/beacon_node.nim

@@ -186,7 +186,7 @@ proc init*(T: type BeaconNode,
       if bnStatus == BeaconNodeStatus.Stopping:
         return nil
 
-      info "Eth2 genesis state detected",
+      notice "Eth2 genesis state detected",
         genesisTime = genesisState.genesisTime,
         eth1Block = genesisState.eth1_data.block_hash,
         totalDeposits = genesisState.eth1_data.deposit_count
@@ -619,7 +619,7 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.async.} =
 proc handleMissingBlocks(node: BeaconNode) =
   let missingBlocks = node.quarantine.checkMissing()
   if missingBlocks.len > 0:
-    info "Requesting detected missing blocks", blocks = shortLog(missingBlocks)
+    debug "Requesting detected missing blocks", blocks = shortLog(missingBlocks)
     node.requestManager.fetchAncestorBlocks(missingBlocks)
 
 proc onSecond(node: BeaconNode) =
@@ -639,7 +639,7 @@ proc runOnSecondLoop(node: BeaconNode) {.async.} =
     let finished = chronos.now(chronos.Moment)
     let processingTime = finished - afterSleep
     ticks_delay.set(sleepTime.nanoseconds.float / nanosecondsIn1s)
-    debug "onSecond task completed", sleepTime, processingTime
+    trace "onSecond task completed", sleepTime, processingTime
 
 proc startSyncManager(node: BeaconNode) =
   func getLocalHeadSlot(): Slot =
@@ -845,12 +845,12 @@ proc installMessageValidators(node: BeaconNode) =
 
 proc stop*(node: BeaconNode) =
   bnStatus = BeaconNodeStatus.Stopping
-  info "Graceful shutdown"
+  notice "Graceful shutdown"
   if not node.config.inProcessValidators:
     node.vcProcess.close()
   waitFor node.network.stop()
   node.db.close()
-  info "Database closed"
+  notice "Database closed"
 
 proc run*(node: BeaconNode) =
   if bnStatus == BeaconNodeStatus.Starting:
@@ -907,7 +907,7 @@ proc initializeNetworking(node: BeaconNode) {.async.} =
 
   await node.network.start()
 
-  info "Networking initialized",
+  notice "Networking initialized",
     enr = node.network.announcedENR.toURI,
     libp2p = shortLog(node.network.switch.peerInfo)
 
@@ -917,7 +917,7 @@ proc start(node: BeaconNode) =
     finalizedHead = node.chainDag.finalizedHead
     genesisTime = node.beaconClock.fromNow(toBeaconTime(Slot 0))
 
-  info "Starting beacon node",
+  notice "Starting beacon node",
     version = fullVersionStr,
     nim = shortNimBanner(),
     timeSinceFinalization =
@@ -1202,14 +1202,14 @@ programMain:
       when defined(windows):
         # workaround for https://github.com/nim-lang/Nim/issues/4057
         setupForeignThreadGc()
-      info "Shutting down after having received SIGINT"
+      notice "Shutting down after having received SIGINT"
       bnStatus = BeaconNodeStatus.Stopping
     setControlCHook(controlCHandler)
 
     when useInsecureFeatures:
       if config.metricsEnabled:
         let metricsAddress = config.metricsAddress
-        info "Starting metrics HTTP server",
+        notice "Starting metrics HTTP server",
           address = metricsAddress, port = config.metricsPort
         metrics.startHttpServer($metricsAddress, config.metricsPort)
 
@@ -1282,7 +1282,7 @@ programMain:
           mapIt(deposits.value, LaunchPadDeposit.init(config.runtimePreset, it))
 
         Json.saveFile(depositDataPath, launchPadDeposits)
-        info "Deposit data written", filename = depositDataPath
+        notice "Deposit data written", filename = depositDataPath
 
         walletPath.wallet.nextAccount += deposits.value.len
         let status = saveWallet(walletPath)

beacon_chain/block_pools/chain_dag.nim

@@ -487,7 +487,7 @@ proc putState*(dag: ChainDAGRef, state: StateData) =
   if dag.db.containsState(state.data.root):
     return
 
-  info "Storing state"
+  debug "Storing state"
   # Ideally we would save the state and the root lookup cache in a single
   # transaction to prevent database inconsistencies, but the state loading code
   # is resilient against one or the other going missing
@@ -626,7 +626,7 @@ proc updateStateData*(
 
     return
 
-  debug "UpdateStateData miss",
+  debug "UpdateStateData cache miss",
     bs, stateBlock = state.blck, stateSlot = state.data.data.slot
 
   # Either the state is too new or was created by applying a different block.
@@ -676,7 +676,7 @@ proc updateStateData*(
 
   beacon_state_rewinds.inc()
 
-  debug "State reloaded from database",
+  trace "State reloaded from database",
     blocks = ancestors.len,
     slots = state.data.data.slot - startSlot,
     stateRoot = shortLog(state.data.root),
@@ -707,7 +707,7 @@ proc updateHead*(
     newHead = shortLog(newHead)
 
   if dag.head == newHead:
-    debug "No head block update"
+    trace "No head block update"
 
     return
 
@@ -730,7 +730,7 @@ proc updateHead*(
   dag.head = newHead
 
   if not lastHead.isAncestorOf(newHead):
-    info "Updated head block with reorg",
+    notice "Updated head block with chain reorg",
       lastHead = shortLog(lastHead),
       headParent = shortLog(newHead.parent),
       stateRoot = shortLog(dag.headState.data.root),
@@ -743,7 +743,7 @@ proc updateHead*(
     quarantine.clearQuarantine()
     beacon_reorgs_total.inc()
   else:
-    info "Updated head block",
+    debug "Updated head block",
       stateRoot = shortLog(dag.headState.data.root),
       headBlock = shortLog(dag.headState.blck),
       stateSlot = shortLog(dag.headState.data.data.slot),
@@ -818,7 +818,7 @@ proc updateHead*(
 
     dag.finalizedHead = finalizedHead
 
-    info "Reached new finalization checkpoint",
+    notice "Reached new finalization checkpoint",
       finalizedHead = shortLog(finalizedHead),
       heads = dag.heads.len
 

beacon_chain/block_pools/clearance.nim

@@ -88,7 +88,7 @@ proc addResolvedBlock(
     foundHead = blockRef
     dag.heads.add(foundHead)
 
-  info "Block resolved",
+  debug "Block resolved",
     blck = shortLog(signedBlock.message),
     blockRoot = shortLog(blockRoot),
     heads = dag.heads.len()
@@ -165,7 +165,7 @@ proc addRawBlock*(
     if parent.slot >= blck.slot:
       # A block whose parent is newer than the block itself is clearly invalid -
       # discard it immediately
-      notice "Invalid block slot",
+      debug "Invalid block slot",
         parentBlock = shortLog(parent)
 
       return err((EVRESULT_REJECT, Invalid))
@@ -211,7 +211,7 @@ proc addRawBlock*(
 
     if not state_transition(dag.runtimePreset, dag.clearanceState.data, signedBlock,
                             cache, dag.updateFlags + {slotProcessed}, restore):
-      notice "Invalid block"
+      info "Invalid block"
 
       return err((EVRESULT_REJECT, Invalid))
 
@@ -329,7 +329,7 @@ proc isValidBeaconBlock*(
           signed_beacon_block.message.proposer_index and
         blck.message.slot == signed_beacon_block.message.slot and
         blck.signature.toRaw() != signed_beacon_block.signature.toRaw():
-      debug "block isn't first block with valid signature received for the proposer",
+      notice "block isn't first block with valid signature received for the proposer",
         blckRef = slotBlockRef,
         existing_block = shortLog(blck.message)
       return err((EVRESULT_IGNORE, Invalid))
@@ -348,7 +348,7 @@ proc isValidBeaconBlock*(
     debug "parent unknown, putting block in quarantine",
       current_slot = shortLog(current_slot)
     if not quarantine.add(dag, signed_beacon_block):
-      debug "Block quarantine full"
+      warn "Block quarantine full"
     return err((EVRESULT_IGNORE, MissingParent))
 
   # [REJECT] The current finalized_checkpoint is an ancestor of block -- i.e.
@@ -378,12 +378,12 @@ proc isValidBeaconBlock*(
     proposer = getProposer(dag, parent_ref, signed_beacon_block.message.slot)
 
   if proposer.isNone:
-    notice "cannot compute proposer for message"
+    warn "cannot compute proposer for message"
     return err((EVRESULT_IGNORE, Invalid)) # basically an internal issue
 
   if proposer.get()[0] !=
       ValidatorIndex(signed_beacon_block.message.proposer_index):
-    debug "block had unexpected proposer",
+    notice "block had unexpected proposer",
       expected_proposer = proposer.get()[0]
     return err((EVRESULT_REJECT, Invalid))
 

beacon_chain/deposit_contract.nim

@@ -139,7 +139,7 @@ proc sendDeposits*(deposits: seq[LaunchPadDeposit],
                    web3Url, privateKey: string,
                    depositContractAddress: Eth1Address,
                    delayGenerator: DelayGenerator = nil) {.async.} =
-  info "Sending deposits",
+  notice "Sending deposits",
     web3 = web3Url,
     depositContract = depositContractAddress
 
@@ -197,7 +197,7 @@ proc main() {.async.} =
       mapIt(deposits.value, LaunchPadDeposit.init(runtimePreset, it))
 
     Json.saveFile(string cfg.outDepositsFile, launchPadDeposits)
-    info "Deposit data written", filename = cfg.outDepositsFile
+    notice "Deposit data written", filename = cfg.outDepositsFile
     quit 0
 
   var deposits: seq[LaunchPadDeposit]

beacon_chain/eth2_network.nim

@@ -822,7 +822,7 @@ proc runDiscoveryLoop*(node: Eth2Node) {.async.} =
         debug "Failed to decode discovery's node address",
               node = $discnode, errMsg = res.error
 
-    debug "Discovery tick", wanted_peers = node.wantedPeers,
+    trace "Discovery tick", wanted_peers = node.wantedPeers,
           space = node.peerPool.shortLogSpace(),
           acquired = node.peerPool.shortLogAcquired(),
           available = node.peerPool.shortLogAvailable(),
@@ -832,9 +832,10 @@ proc runDiscoveryLoop*(node: Eth2Node) {.async.} =
           new_peers = newPeers
 
     if newPeers == 0:
-      warn "Could not discover any new nodes in network, waiting",
-            discovered = len(discoveredNodes), new_peers = newPeers,
-            wanted_peers = node.wantedPeers
+      if node.peerPool.lenSpace() <= node.wantedPeers shr 2:
+        warn "Less than 25% wanted peers and could not discover new nodes",
+              discovered = len(discoveredNodes), new_peers = newPeers,
+              wanted_peers = node.wantedPeers
       await sleepAsync(5.seconds)
     else:
       await sleepAsync(1.seconds)
@@ -980,7 +981,7 @@ proc start*(node: Eth2Node) {.async.} =
     node.discovery.start()
     traceAsyncErrors node.runDiscoveryLoop()
   else:
-    debug "Discovery disabled, trying bootstrap nodes",
+    notice "Discovery disabled; trying bootstrap nodes",
       nodes = node.discovery.bootstrapRecords.len
     for enr in node.discovery.bootstrapRecords:
       let tr = enr.toTypedRecord()
@@ -1232,7 +1233,7 @@ proc createEth2Node*(
     announcedAddresses = if extIp.isNone(): @[]
                          else: @[tcpEndPoint(extIp.get(), extTcpPort)]
 
-  info "Initializing networking", hostAddress,
+  notice "Initializing networking", hostAddress,
                                   announcedAddresses
 
   let keys = getPersistentNetKeys(rng[], conf)

beacon_chain/eth2_processor.nim

@@ -301,7 +301,7 @@ proc attestationValidator*(
 
   # Potential under/overflows are fine; would just create odd metrics and logs
   let delay = wallTime - attestation.data.slot.toBeaconTime
-  debug "Attestation received", delay
+  trace "Attestation received", delay
   let v = self.attestationPool[].validateAttestation(
       attestation, wallTime, committeeIndex)
   if v.isErr():

beacon_chain/fork_choice/fork_choice.nim

@@ -343,7 +343,7 @@ proc find_head*(
   ? self.proto_array.find_head(new_head, justified_root)
 
   {.noSideEffect.}:
-    debug "Fork choice requested",
+    trace "Fork choice requested",
       justified_epoch = justified_epoch,
       justified_root = shortLog(justified_root),
       finalized_epoch = finalized_epoch,

beacon_chain/keystore_management.nim

@@ -157,7 +157,7 @@ proc generateDeposits*(preset: RuntimePreset,
                        secretsDir: string): Result[seq[DepositData], KeystoreGenerationError] =
   var deposits: seq[DepositData]
 
-  info "Generating deposits", totalNewValidators, validatorsDir, secretsDir
+  notice "Generating deposits", totalNewValidators, validatorsDir, secretsDir
 
   let withdrawalKeyPath = makeKeyPath(0, withdrawalKeyKind)
   # TODO: Explain why we are using an empty password
@@ -256,7 +256,7 @@ proc importKeystoresFromDir*(rng: var BrHmacDrbgContext,
       let keystore = try:
         Json.loadFile(file, Keystore)
       except SerializationError as e:
-        trace "Invalid keystore", err = e.formatMsg(file)
+        warn "Invalid keystore", err = e.formatMsg(file)
         continue
       except IOError as e:
         warn "Failed to read keystore file", file, err = e.msg
@@ -292,7 +292,7 @@ proc importKeystoresFromDir*(rng: var BrHmacDrbgContext,
                                       privKey.value, pubKey,
                                       keystore.path)
             if status.isOk:
-              info "Keystore imported", file
+              notice "Keystore imported", file
             else:
               error "Failed to import keystore", file, err = status.error
           else:
@@ -398,7 +398,7 @@ proc pickPasswordAndSaveWallet(rng: var BrHmacDrbgContext,
       if status.isErr:
         return err("failure to create wallet file due to " & status.error)
 
-      info "Wallet file written", path = outWalletFile
+      notice "Wallet file written", path = outWalletFile
       return ok WalletPathPair(wallet: wallet, path: outWalletFile)
     finally:
       burnMem(password)