status-im
/
nimbus-eth2
mirror of https://github.com/status-im/nimbus-eth2.git
2
0
Fork 0
Code Issues Projects Releases Wiki Activity

Revisiting log levels (#1788) 

* Update log level - https://github.com/status-im/nim-beacon-chain/issues/1779 https://github.com/status-im/nim-beacon-chain/issues/1785

* Address review comments

* Document the logging strategy [skip ci]
This commit is contained in:
Mamy Ratsimbazafy 2020-10-01 20:56:42 +02:00 committed by GitHub
parent 13d4831664
commit 0280d6c73e
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
19 changed files with 120 additions and 74 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
beacon_chain/attestation_pool.nim
View File

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

20
beacon_chain/beacon_node.nim
View File

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

14
beacon_chain/block_pools/chain_dag.nim
View File

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

14
beacon_chain/block_pools/clearance.nim
View File

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

4
beacon_chain/deposit_contract.nim
View File

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

13
beacon_chain/eth2_network.nim
View File

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

2
beacon_chain/eth2_processor.nim
View File

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

2
beacon_chain/fork_choice/fork_choice.nim
View File

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

8
beacon_chain/keystore_management.nim
View File

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

15
beacon_chain/mainchain_monitor.nim
View File

@ -319,7 +319,7 @@ proc getBlockNumber(p: DataProviderRef, hash: BlockHash): Future[Eth1BlockNumber
return 0 return 0
return Eth1BlockNumber(blk.number) return Eth1BlockNumber(blk.number)
except CatchableError as exc: except CatchableError as exc:
notice "Failed to get Eth1 block number from hash", debug "Failed to get Eth1 block number from hash",
hash = $hash, err = exc.msg hash = $hash, err = exc.msg
raise exc raise exc
@ -374,7 +374,7 @@ proc readJsonDeposits(depositsList: JsonNode): seq[Eth1Block] =
method fetchDepositData*(p: Web3DataProviderRef, method fetchDepositData*(p: Web3DataProviderRef,
fromBlock, toBlock: Eth1BlockNumber): Future[seq[Eth1Block]] fromBlock, toBlock: Eth1BlockNumber): Future[seq[Eth1Block]]
{.async, locks: 0.} = {.async, locks: 0.} =
info "Obtaining deposit log events", fromBlock, toBlock debug "Obtaining deposit log events", fromBlock, toBlock
return readJsonDeposits(await p.ns.getJsonLogs(DepositEvent, return readJsonDeposits(await p.ns.getJsonLogs(DepositEvent,
fromBlock = some blockId(fromBlock), fromBlock = some blockId(fromBlock),
toBlock = some blockId(toBlock))) toBlock = some blockId(toBlock)))
@ -413,7 +413,7 @@ method onBlockHeaders*(p: Web3DataProviderRef,
if p.blockHeadersSubscription != nil: if p.blockHeadersSubscription != nil:
await p.blockHeadersSubscription.unsubscribe() await p.blockHeadersSubscription.unsubscribe()
info "Waiting for new Eth1 block headers" debug "Waiting for new Eth1 block headers"
p.blockHeadersSubscription = await p.web3.subscribeForBlockHeaders( p.blockHeadersSubscription = await p.web3.subscribeForBlockHeaders(
blockHeaderHandler, errorHandler) blockHeaderHandler, errorHandler)
@ -554,7 +554,7 @@ proc findGenesisBlockInRange(m: MainchainMonitor,
let candidateGenesisTime = genesis_time_from_eth1_timestamp( let candidateGenesisTime = genesis_time_from_eth1_timestamp(
m.preset, candidateBlock.timestamp.uint64) m.preset, candidateBlock.timestamp.uint64)
info "Probing possible genesis block", notice "Probing possible genesis block",
`block` = candidateBlock.number.uint64, `block` = candidateBlock.number.uint64,
candidateGenesisTime candidateGenesisTime
@ -596,7 +596,7 @@ proc checkForGenesisLoop(m: MainchainMonitor) {.async.} =
genesisCandidateIdx = genesisCandidateIdx.get genesisCandidateIdx = genesisCandidateIdx.get
genesisCandidate = m.eth1Chain.blocks[genesisCandidateIdx] genesisCandidate = m.eth1Chain.blocks[genesisCandidateIdx]
info "Generating state for candidate block for genesis", notice "Generating state for candidate block for genesis",
blockNum = genesisCandidate.number, blockNum = genesisCandidate.number,
blockHash = genesisCandidate.voteData.block_hash, blockHash = genesisCandidate.voteData.block_hash,
potentialDeposits = genesisCandidate.voteData.deposit_count potentialDeposits = genesisCandidate.voteData.deposit_count
@ -635,7 +635,7 @@ proc checkForGenesisLoop(m: MainchainMonitor) {.async.} =
m.signalGenesis candidateState m.signalGenesis candidateState
return return
else: else:
info "Eth2 genesis candidate block rejected", notice "Eth2 genesis candidate block rejected",
`block` = shortLog(genesisCandidate), `block` = shortLog(genesisCandidate),
validDeposits = genesisCandidate.knownGoodDepositsCount.get, validDeposits = genesisCandidate.knownGoodDepositsCount.get,
needed = m.preset.MIN_GENESIS_ACTIVE_VALIDATOR_COUNT needed = m.preset.MIN_GENESIS_ACTIVE_VALIDATOR_COUNT
@ -734,7 +734,7 @@ proc processDeposits(m: MainchainMonitor,
voteData: latestEth1Data) voteData: latestEth1Data)
else: else:
template logBlockProcessed(blk) = template logBlockProcessed(blk) =
info "Eth1 block processed", debug "Eth1 block processed",
`block` = shortLog(blk), totalDeposits = blk.voteData.deposit_count `block` = shortLog(blk), totalDeposits = blk.voteData.deposit_count
await dataProvider.fetchBlockDetails(eth1Blocks[0]) await dataProvider.fetchBlockDetails(eth1Blocks[0])
@ -828,4 +828,3 @@ proc getEth1BlockHash*(url: string, blockId: RtBlockIdentifier): Future[BlockHas
await web3.close() await web3.close()
{.pop.} {.pop.}

4
beacon_chain/spec/beaconstate.nim
View File

@ -172,7 +172,7 @@ proc slash_validator*(state: var BeaconState, slashed_index: ValidatorIndex,
initiate_validator_exit(state, slashed_index, cache) initiate_validator_exit(state, slashed_index, cache)
let validator = addr state.validators[slashed_index] let validator = addr state.validators[slashed_index]
debug "slash_validator: ejecting validator via slashing (validator_leaving)", notice "slash_validator: ejecting validator via slashing (validator_leaving)",
index = slashed_index, index = slashed_index,
num_validators = state.validators.len, num_validators = state.validators.len,
current_epoch = get_current_epoch(state), current_epoch = get_current_epoch(state),
@ -388,7 +388,7 @@ proc process_registry_updates*(state: var BeaconState,
if is_active_validator(validator, get_current_epoch(state)) and if is_active_validator(validator, get_current_epoch(state)) and
validator.effective_balance <= EJECTION_BALANCE: validator.effective_balance <= EJECTION_BALANCE:
debug "Registry updating: ejecting validator due to low balance (validator_leaving)", notice "Registry updating: ejecting validator due to low balance (validator_leaving)",
index = index, index = index,
num_validators = state.validators.len, num_validators = state.validators.len,
current_epoch = get_current_epoch(state), current_epoch = get_current_epoch(state),

2
beacon_chain/spec/state_transition_block.nim
View File

@ -102,7 +102,7 @@ proc process_randao(
if not verify_epoch_signature( if not verify_epoch_signature(
state.fork, state.genesis_validators_root, epoch, proposer_pubkey, state.fork, state.genesis_validators_root, epoch, proposer_pubkey,
body.randao_reveal): body.randao_reveal):
notice "Randao mismatch", proposer_pubkey = shortLog(proposer_pubkey), debug "Randao mismatch", proposer_pubkey = shortLog(proposer_pubkey),
epoch, epoch,
signature = shortLog(body.randao_reveal), signature = shortLog(body.randao_reveal),
slot = state.slot slot = state.slot

12
beacon_chain/sync_manager.nim
View File

@ -702,7 +702,7 @@ proc syncStep[A, B](man: SyncManager[A, B], index: int, peer: A) {.async.} =
if peerAge >= man.maxStatusAge: if peerAge >= man.maxStatusAge:
# Peer's status information is very old, its time to update it # Peer's status information is very old, its time to update it
man.workers[index].status = SyncWorkerStatus.UpdatingStatus man.workers[index].status = SyncWorkerStatus.UpdatingStatus
debug "Updating peer's status information", wall_clock_slot = wallSlot, trace "Updating peer's status information", wall_clock_slot = wallSlot,
remote_head_slot = peerSlot, local_head_slot = headSlot, remote_head_slot = peerSlot, local_head_slot = headSlot,
peer = peer, peer_score = peer.getScore(), index = index, peer = peer, peer_score = peer.getScore(), index = index,
peer_speed = peer.netKbps(), topics = "syncman" peer_speed = peer.netKbps(), topics = "syncman"
@ -742,7 +742,7 @@ proc syncStep[A, B](man: SyncManager[A, B], index: int, peer: A) {.async.} =
peerSlot = newPeerSlot peerSlot = newPeerSlot
if headAge <= man.maxHeadAge: if headAge <= man.maxHeadAge:
debug "We are in sync with network, exiting", wall_clock_slot = wallSlot, info "We are in sync with network", wall_clock_slot = wallSlot,
remote_head_slot = peerSlot, local_head_slot = headSlot, remote_head_slot = peerSlot, local_head_slot = headSlot,
peer = peer, peer_score = peer.getScore(), index = index, peer = peer, peer_score = peer.getScore(), index = index,
peer_speed = peer.netKbps(), topics = "syncman" peer_speed = peer.netKbps(), topics = "syncman"
@ -752,7 +752,7 @@ proc syncStep[A, B](man: SyncManager[A, B], index: int, peer: A) {.async.} =
return return
if headSlot >= peerSlot - man.maxHeadAge: if headSlot >= peerSlot - man.maxHeadAge:
debug "We are in sync with peer, refreshing peer's status information", debug "We are in sync with peer; refreshing peer's status information",
wall_clock_slot = wallSlot, remote_head_slot = peerSlot, wall_clock_slot = wallSlot, remote_head_slot = peerSlot,
local_head_slot = headSlot, peer = peer, peer_score = peer.getScore(), local_head_slot = headSlot, peer = peer, peer_score = peer.getScore(),
index = index, peer_speed = peer.netKbps(), topics = "syncman" index = index, peer_speed = peer.netKbps(), topics = "syncman"
@ -942,7 +942,7 @@ proc syncLoop[A, B](man: SyncManager[A, B]) {.async.} =
man.syncSpeed = 0.0 man.syncSpeed = 0.0
else: else:
if (lsm2.slot - lsm1.slot == 0'u64) and (pending > 1): if (lsm2.slot - lsm1.slot == 0'u64) and (pending > 1):
debug "Syncing process is not progressing, reset the queue", info "Syncing process is not progressing, reset the queue",
pending_workers_count = pending, pending_workers_count = pending,
to_slot = man.queue.outSlot, to_slot = man.queue.outSlot,
local_head_slot = lsm1.slot, topics = "syncman" local_head_slot = lsm1.slot, topics = "syncman"
@ -950,7 +950,7 @@ proc syncLoop[A, B](man: SyncManager[A, B]) {.async.} =
else: else:
man.syncSpeed = speed(lsm1, lsm2) man.syncSpeed = speed(lsm1, lsm2)
debug "Synchronization loop tick", wall_head_slot = wallSlot, trace "Synchronization loop tick", wall_head_slot = wallSlot,
local_head_slot = headSlot, queue_start_slot = man.queue.startSlot, local_head_slot = headSlot, queue_start_slot = man.queue.startSlot,
queue_last_slot = man.queue.lastSlot, queue_last_slot = man.queue.lastSlot,
sync_speed = man.syncSpeed, pending_workers_count = pending, sync_speed = man.syncSpeed, pending_workers_count = pending,
@ -964,7 +964,7 @@ proc syncLoop[A, B](man: SyncManager[A, B]) {.async.} =
let (map, sleeping, waiting, pending) = man.getWorkersStats() let (map, sleeping, waiting, pending) = man.getWorkersStats()
debug "Current syncing state", workers_map = map, trace "Current syncing state", workers_map = map,
sleeping_workers_count = sleeping, sleeping_workers_count = sleeping,
waiting_workers_count = waiting, waiting_workers_count = waiting,
pending_workers_count = pending, pending_workers_count = pending,

6
beacon_chain/sync_protocol.nim
View File

@ -110,7 +110,7 @@ p2pProtocol BeaconSync(version = 1,
await peer.handleStatus(peer.networkState, await peer.handleStatus(peer.networkState,
ourStatus, theirStatus.get()) ourStatus, theirStatus.get())
else: else:
warn "Status response not received in time", debug "Status response not received in time",
peer, error = theirStatus.error peer, error = theirStatus.error
proc status(peer: Peer, proc status(peer: Peer,
@ -189,7 +189,7 @@ p2pProtocol BeaconSync(version = 1,
debug "Received Goodbye message", reason = disconnectReasonName(reason), peer debug "Received Goodbye message", reason = disconnectReasonName(reason), peer
proc setStatusMsg(peer: Peer, statusMsg: StatusMsg) = proc setStatusMsg(peer: Peer, statusMsg: StatusMsg) =
debug "Peer status", peer, statusMsg trace "Peer status", peer, statusMsg
peer.state(BeaconSync).statusMsg = statusMsg peer.state(BeaconSync).statusMsg = statusMsg
peer.state(BeaconSync).statusLastTime = Moment.now() peer.state(BeaconSync).statusLastTime = Moment.now()
@ -220,7 +220,7 @@ proc handleStatus(peer: Peer,
ourStatus: StatusMsg, ourStatus: StatusMsg,
theirStatus: StatusMsg) {.async, gcsafe.} = theirStatus: StatusMsg) {.async, gcsafe.} =
if theirStatus.forkDigest != state.forkDigest: if theirStatus.forkDigest != state.forkDigest:
notice "Irrelevant peer", peer, theirStatus, ourStatus debug "Irrelevant peer", peer, theirStatus, ourStatus
await peer.disconnect(IrrelevantNetwork) await peer.disconnect(IrrelevantNetwork)
else: else:
peer.setStatusMsg(theirStatus) peer.setStatusMsg(theirStatus)

2
beacon_chain/validator_api.nim
View File

@ -348,7 +348,7 @@ proc installValidatorApiHandlers*(rpcServer: RpcServer, node: BeaconNode) =
payload: SignedAggregateAndProof) -> bool: payload: SignedAggregateAndProof) -> bool:
debug "post_v1_validator_aggregate_and_proofs" debug "post_v1_validator_aggregate_and_proofs"
node.network.broadcast(node.topicAggregateAndProofs, payload) node.network.broadcast(node.topicAggregateAndProofs, payload)
info "Aggregated attestation sent", notice "Aggregated attestation sent",
attestation = shortLog(payload.message.aggregate) attestation = shortLog(payload.message.aggregate)
rpcServer.rpc("get_v1_validator_duties_attester") do ( rpcServer.rpc("get_v1_validator_duties_attester") do (

8
beacon_chain/validator_client.nim
View File

@ -141,7 +141,7 @@ proc onSlotStart(vc: ValidatorClient, lastSlot, scheduledSlot: Slot) {.gcsafe, a
.checkSlashableBlockProposal(public_key, slot) .checkSlashableBlockProposal(public_key, slot)
if notSlashable.isOk: if notSlashable.isOk:
let validator = vc.attachedValidators.validators[public_key] let validator = vc.attachedValidators.validators[public_key]
info "Proposing block", slot = slot, public_key = public_key notice "Proposing block", slot = slot, public_key = public_key
let randao_reveal = await validator.genRandaoReveal( let randao_reveal = await validator.genRandaoReveal(
vc.fork, vc.beaconGenesis.genesis_validators_root, slot) vc.fork, vc.beaconGenesis.genesis_validators_root, slot)
var newBlock = SignedBeaconBlock( var newBlock = SignedBeaconBlock(
@ -179,7 +179,7 @@ proc onSlotStart(vc: ValidatorClient, lastSlot, scheduledSlot: Slot) {.gcsafe, a
vc.attestationsForEpoch[epoch].contains slot: vc.attestationsForEpoch[epoch].contains slot:
var validatorToAttestationDataRoot: Table[ValidatorPubKey, Eth2Digest] var validatorToAttestationDataRoot: Table[ValidatorPubKey, Eth2Digest]
for a in vc.attestationsForEpoch[epoch][slot]: for a in vc.attestationsForEpoch[epoch][slot]:
info "Attesting", slot = slot, public_key = a.public_key notice "Attesting", slot = slot, public_key = a.public_key
let validator = vc.attachedValidators.validators[a.public_key] let validator = vc.attachedValidators.validators[a.public_key]
let ad = await vc.client.get_v1_validator_attestation(slot, a.committee_index) let ad = await vc.client.get_v1_validator_attestation(slot, a.committee_index)
@ -232,13 +232,13 @@ proc onSlotStart(vc: ValidatorClient, lastSlot, scheduledSlot: Slot) {.gcsafe, a
if is_aggregator(a.committee_length, slot_signature) and if is_aggregator(a.committee_length, slot_signature) and
validatorToAttestationDataRoot.contains(a.public_key): validatorToAttestationDataRoot.contains(a.public_key):
info "Aggregating", slot = slot, public_key = a.public_key notice "Aggregating", slot = slot, public_key = a.public_key
let aa = await vc.client.get_v1_validator_aggregate_attestation( let aa = await vc.client.get_v1_validator_aggregate_attestation(
slot, validatorToAttestationDataRoot[a.public_key]) slot, validatorToAttestationDataRoot[a.public_key])
let aap = AggregateAndProof(aggregator_index: a.validator_index.uint64, let aap = AggregateAndProof(aggregator_index: a.validator_index.uint64,
aggregate: aa, selection_proof: slot_signature) aggregate: aa, selection_proof: slot_signature)
let sig = await signAggregateAndProof(validator, let sig = await signAggregateAndProof(validator,
aap, vc.fork, vc.beaconGenesis.genesis_validators_root) aap, vc.fork, vc.beaconGenesis.genesis_validators_root)
var signedAP = SignedAggregateAndProof(message: aap, signature: sig) var signedAP = SignedAggregateAndProof(message: aap, signature: sig)
discard await vc.client.post_v1_validator_aggregate_and_proofs(signedAP) discard await vc.client.post_v1_validator_aggregate_and_proofs(signedAP)

12
beacon_chain/validator_duties.nim
View File

@ -40,7 +40,7 @@ proc saveValidatorKey*(keyName, key: string, conf: BeaconNodeConf) =
let outputFile = validatorsDir / keyName let outputFile = validatorsDir / keyName
createDir validatorsDir createDir validatorsDir
writeFile(outputFile, key) writeFile(outputFile, key)
info "Imported validator key", file = outputFile notice "Imported validator key", file = outputFile
proc checkValidatorInRegistry(state: BeaconState, proc checkValidatorInRegistry(state: BeaconState,
pubKey: ValidatorPubKey) = pubKey: ValidatorPubKey) =
@ -60,7 +60,7 @@ proc addLocalValidator*(node: BeaconNode,
proc addLocalValidators*(node: BeaconNode) = proc addLocalValidators*(node: BeaconNode) =
for validatorKey in node.config.validatorKeys: for validatorKey in node.config.validatorKeys:
node.addLocalValidator node.chainDag.headState.data.data, validatorKey node.addLocalValidator node.chainDag.headState.data.data, validatorKey
info "Local validators attached ", count = node.attachedValidators.count notice "Local validators attached ", count = node.attachedValidators.count
proc addRemoteValidators*(node: BeaconNode) = proc addRemoteValidators*(node: BeaconNode) =
# load all the validators from the child process - loop until `end` # load all the validators from the child process - loop until `end`
@ -77,7 +77,7 @@ proc addRemoteValidators*(node: BeaconNode) =
outStream: node.vcProcess.outputStream, outStream: node.vcProcess.outputStream,
pubKeyStr: $key)) pubKeyStr: $key))
node.attachedValidators.addRemoteValidator(key, v) node.attachedValidators.addRemoteValidator(key, v)
info "Remote validators attached ", count = node.attachedValidators.count notice "Remote validators attached ", count = node.attachedValidators.count
proc getAttachedValidator*(node: BeaconNode, proc getAttachedValidator*(node: BeaconNode,
pubkey: ValidatorPubKey): AttachedValidator = pubkey: ValidatorPubKey): AttachedValidator =
@ -340,7 +340,7 @@ proc handleAttestations(node: BeaconNode, head: BlockRef, slot: Slot) =
# TODO the oldest attestations allowed are those that are older than the # TODO the oldest attestations allowed are those that are older than the
# finalized epoch.. also, it seems that posting very old attestations # finalized epoch.. also, it seems that posting very old attestations
# is risky from a slashing perspective. More work is needed here. # is risky from a slashing perspective. More work is needed here.
notice "Skipping attestation, head is too recent", warn "Skipping attestation, head is too recent",
headSlot = shortLog(head.slot), headSlot = shortLog(head.slot),
slot = shortLog(slot) slot = shortLog(slot)
return return
@ -485,7 +485,7 @@ proc broadcastAggregatedAttestations(
message: aggregateAndProof.get, message: aggregateAndProof.get,
signature: sig) signature: sig)
node.network.broadcast(node.topicAggregateAndProofs, signedAP) node.network.broadcast(node.topicAggregateAndProofs, signedAP)
info "Aggregated attestation sent", notice "Aggregated attestation sent",
attestation = shortLog(signedAP.message.aggregate), attestation = shortLog(signedAP.message.aggregate),
validator = shortLog(curr[0].v) validator = shortLog(curr[0].v)
@ -514,7 +514,7 @@ proc handleValidatorDuties*(
# TODO maybe even collect all work synchronously to avoid unnecessary # TODO maybe even collect all work synchronously to avoid unnecessary
# state rewinds while waiting for async operations like validator # state rewinds while waiting for async operations like validator
# signature.. # signature..
notice "Catching up", notice "Catching up on validator duties",
curSlot = shortLog(curSlot), curSlot = shortLog(curSlot),
lastSlot = shortLog(lastSlot), lastSlot = shortLog(lastSlot),
slot = shortLog(slot) slot = shortLog(slot)

4
beacon_chain/validator_pool.nim
View File

@ -26,13 +26,13 @@ proc addLocalValidator*(pool: var ValidatorPool,
kind: inProcess, kind: inProcess,
privKey: privKey) privKey: privKey)
pool.validators[pubKey] = v pool.validators[pubKey] = v
info "Local validator attached", pubKey, validator = shortLog(v) notice "Local validator attached", pubKey, validator = shortLog(v)
proc addRemoteValidator*(pool: var ValidatorPool, proc addRemoteValidator*(pool: var ValidatorPool,
pubKey: ValidatorPubKey, pubKey: ValidatorPubKey,
v: AttachedValidator) = v: AttachedValidator) =
pool.validators[pubKey] = v pool.validators[pubKey] = v
info "Remote validator attached", pubKey, validator = shortLog(v) notice "Remote validator attached", pubKey, validator = shortLog(v)
proc getValidator*(pool: ValidatorPool, proc getValidator*(pool: ValidatorPool,
validatorKey: ValidatorPubKey): AttachedValidator = validatorKey: ValidatorPubKey): AttachedValidator =

46
docs/logging.md Normal file
View File

@ -0,0 +1,46 @@
# Logging strategy
This document describes the overall logging strategy of NBC.
This is a suggested guideline, rare events can have a higher logging level
than suggested in the guideline for example at beacon node start or stop.
The main objectives are:
- INFO log level or higher should be suitable for long-term use, i.e. running for months or weeks. Logs are the users' main interface their beacon node and validators. In particular it should not be a denial-of-service vector, either by leading to high CPU usage of the console or filling disk space at an unsustainable rate.
- INFO logs or higher should be target at users, logs only relevant to devs should be relegated to DEBUG or TRACE or commented out.
- DEBUG log level should still be readable by visual inspection during a slot time (6 seconds).
Here is the suggestion of content per log level
- Fatal: Node will crash
- Error: Bugs or critical unexpected behaviors
- node cannot proceed with task
- node consistency is compromised
- Warning: Errors that can be expected or handled
- networking issue,
- node cannot proceed with task but can recover or work in degraded mode (invalid bootstrap address, out of Infura requests)
- Notice: Important user and validator info and one-time events
- node start/quit,
- log about validator funds,
- own PoS attestations,
- own PoS blocks,
- chain reached finality,
- validators have been slashed (i.e. might indicate malicious activity or network/chain split)
- Info: standard user target
- Networking or consensus information
- Debug: dev and debugging users
- Common networking activity (new peers, kick peers, timeouts),
- consensus/proof-of-stake various processing,
- Trace: dev only
- Keep-alive,
- routine tasks schedules
- "spammy" tasks that clutter debugging (attestations received, status/control messages)
Logs done at high frequency should be summarized even at trace level to avoid drowning other subsystems.
For example they can use an uint8 counter with
```
proc myHighFreqProc() =
var counter {.threadvar.}: uint8
if counter == 255:
trace "Total of 255 myHighFreqProc call"
counter += 1
```