From 0b68f3dc63acbaba566c35a113ceef7c142ee2ac Mon Sep 17 00:00:00 2001 From: Mamy Ratsimbazafy Date: Wed, 11 Sep 2019 21:45:04 -0400 Subject: [PATCH] [Interop branch] Log improvements - part 1 (#439) * use service/category/process for blockpool logs Only track fork choice logs in block pool (vs beacon_node) Reduce verbosity on usual event in block pool * rework beacon node logs * log for attestations in blockpool * log - att pool improvement * use logScope and topics cf review and discussion * use 7 letters for beacon_node [log] report peers at slot start + fix bracket prefix [Block pool] Attestation sent --- beacon_chain/attestation_pool.nim | 60 +++++++++++++-------- beacon_chain/beacon_node.nim | 89 ++++++++++++++++++------------- beacon_chain/block_pool.nim | 79 +++++++++++++++++---------- 3 files changed, 143 insertions(+), 85 deletions(-) diff --git a/beacon_chain/attestation_pool.nim b/beacon_chain/attestation_pool.nim index ac338c415..7f3d98388 100644 --- a/beacon_chain/attestation_pool.nim +++ b/beacon_chain/attestation_pool.nim @@ -5,6 +5,8 @@ import ./extras, ./beacon_chain_db, ./ssz, ./block_pool, beacon_node_types +logScope: topics = "attpool" + proc init*(T: type AttestationPool, blockPool: BlockPool): T = # TODO blockPool is only used when resolving orphaned attestations - it should # probably be removed as a dependency of AttestationPool (or some other @@ -32,7 +34,7 @@ proc combine*(tgt: var Attestation, src: Attestation, flags: UpdateFlags) = if skipValidation notin flags: tgt.signature.combine(src.signature) else: - debug "Ignoring overlapping attestations" + trace "Ignoring overlapping attestations" proc validate( state: BeaconState, attestation: Attestation): bool = @@ -79,6 +81,7 @@ proc slotIndex( # outcome. Some of these attestations will already have been added to blocks, # while others are fresh off the network. # TODO only the latest vote of each validator counts. Can we use that somehow? + logScope: pcs = "atp_slot_maintenance" doAssert attestationSlot >= pool.startingSlot, """ @@ -93,14 +96,16 @@ proc slotIndex( # to start counting at the last finalized epoch start slot - anything # earlier than that is thrown out by the above check info "First attestation!", - attestationSlot = $shortLog(attestationSlot) + attestationSlot = $shortLog(attestationSlot), + cat = "init" pool.startingSlot = state.finalized_checkpoint.epoch.compute_start_slot_of_epoch() if pool.startingSlot + pool.slots.len.uint64 <= attestationSlot: - debug "Growing attestation pool", + trace "Growing attestation pool", attestationSlot = $shortLog(attestationSlot), - startingSlot = $shortLog(pool.startingSlot) + startingSlot = $shortLog(pool.startingSlot), + cat = "caching" # Make sure there's a pool entry for every slot, even when there's a gap while pool.startingSlot + pool.slots.len.uint64 <= attestationSlot: @@ -110,9 +115,10 @@ proc slotIndex( state.finalized_checkpoint.epoch.compute_start_slot_of_epoch(): debug "Pruning attestation pool", startingSlot = $shortLog(pool.startingSlot), - finalizedSlot = - $shortLog( - state.finalized_checkpoint.epoch.compute_start_slot_of_epoch()) + finalizedSlot = $shortLog( + state.finalized_checkpoint + .epoch.compute_start_slot_of_epoch()), + cat = "pruning" # TODO there should be a better way to remove a whole epoch of stuff.. while pool.startingSlot < @@ -141,6 +147,8 @@ proc add*(pool: var AttestationPool, # perspective / spec intent # TODO should update the state correctly in here instead of forcing the caller # to do it... + logScope: pcs = "atp_add_attestation" + doAssert blck.root == attestation.data.beacon_block_root var cache = get_empty_per_epoch_cache() @@ -149,7 +157,8 @@ proc add*(pool: var AttestationPool, attestationData = shortLog(attestation.data), current_epoch = get_current_epoch(state), target_epoch = attestation.data.target.epoch, - stateSlot = state.slot + stateSlot = state.slot, + cat = "filtering" return # TODO inefficient data structures.. @@ -176,10 +185,11 @@ proc add*(pool: var AttestationPool, # TODO what if the new attestation is useful for creating bigger # sets by virtue of not overlapping with some other attestation # and therefore being useful after all? - debug "Ignoring subset attestation", + trace "Ignoring subset attestation", existingParticipants = get_attesting_indices_seq( state, a.data, v.aggregation_bits), - newParticipants = participants + newParticipants = participants, + cat = "filtering" found = true break @@ -187,12 +197,13 @@ proc add*(pool: var AttestationPool, # Attestations in the pool that are a subset of the new attestation # can now be removed per same logic as above - debug "Removing subset attestations", + trace "Removing subset attestations", existingParticipants = a.validations.filterIt( it.aggregation_bits.isSubsetOf(validation.aggregation_bits) ).mapIt(get_attesting_indices_seq( state, a.data, it.aggregation_bits)), - newParticipants = participants + newParticipants = participants, + cat = "pruning" a.validations.keepItIf( not it.aggregation_bits.isSubsetOf(validation.aggregation_bits)) @@ -205,7 +216,8 @@ proc add*(pool: var AttestationPool, validations = a.validations.len(), current_epoch = get_current_epoch(state), target_epoch = attestation.data.target.epoch, - stateSlot = state.slot + stateSlot = state.slot, + cat = "filtering" found = true @@ -224,7 +236,8 @@ proc add*(pool: var AttestationPool, current_epoch = get_current_epoch(state), target_epoch = attestation.data.target.epoch, stateSlot = state.slot, - validations = 1 + validations = 1, + cat = "filtering" proc addUnresolved*(pool: var AttestationPool, attestation: Attestation) = pool.unresolved[attestation.data.beacon_block_root] = @@ -235,14 +248,18 @@ proc addUnresolved*(pool: var AttestationPool, attestation: Attestation) = proc getAttestationsForBlock*( pool: AttestationPool, state: BeaconState, newBlockSlot: Slot): seq[Attestation] = + logScope: pcs = "retrieve_attestation" + if newBlockSlot < (GENESIS_SLOT + MIN_ATTESTATION_INCLUSION_DELAY): - debug "Too early for attestations", - newBlockSlot = shortLog(newBlockSlot) + debug "[Attestion Pool] Too early for attestations", + newBlockSlot = shortLog(newBlockSlot), + cat = "query" return if pool.slots.len == 0: # startingSlot not set yet! info "No attestations found (pool empty)", - newBlockSlot = shortLog(newBlockSlot) + newBlockSlot = shortLog(newBlockSlot), + cat = "query" return var cache = get_empty_per_epoch_cache() @@ -256,11 +273,11 @@ proc getAttestationsForBlock*( if attestationSlot < pool.startingSlot or attestationSlot >= pool.startingSlot + pool.slots.len.uint64: - info "No attestations", + info "No attestations matching the slot range", attestationSlot = shortLog(attestationSlot), startingSlot = shortLog(pool.startingSlot), - endingSlot = shortLog(pool.startingSlot + pool.slots.len.uint64) - + endingSlot = shortLog(pool.startingSlot + pool.slots.len.uint64), + cat = "query" return let @@ -277,7 +294,8 @@ proc getAttestationsForBlock*( ) if not validate(state, attestation): - warn "Attestation no longer validates..." + warn "Attestation no longer validates...", + cat = "query" continue # TODO what's going on here is that when producing a block, we need to diff --git a/beacon_chain/beacon_node.nim b/beacon_chain/beacon_node.nim index 71cc5fd71..67f2b3291 100644 --- a/beacon_chain/beacon_node.nim +++ b/beacon_chain/beacon_node.nim @@ -45,6 +45,8 @@ declareGauge beacon_pending_exits, "Number of pending voluntary exits in local o declareGauge beacon_previous_epoch_orphaned_blocks, "Number of blocks orphaned in the previous epoch" # On epoch transition declareCounter beacon_reorgs_total, "Total occurrences of reorganizations of the chain" # On fork choice +logScope: topics = "beacnde" + proc onBeaconBlock*(node: BeaconNode, blck: BeaconBlock) {.gcsafe.} func localValidatorsDir(conf: BeaconNodeConf): string = @@ -324,21 +326,10 @@ proc updateHead(node: BeaconNode, slot: Slot): BlockRef = let justifiedHead = node.blockPool.latestJustifiedBlock() - debug "Preparing for fork choice", - justifiedHeadRoot = shortLog(justifiedHead.blck.root), - justifiedHeadSlot = shortLog(justifiedHead.slot), - justifiedHeadEpoch = shortLog(justifiedHead.slot.compute_epoch_of_slot), - connectedPeers = node.network.peersCount - let newHead = node.blockPool.withState( node.justifiedStateCache, justifiedHead): lmdGhost(node.attestationPool, state, justifiedHead.blck) - info "Fork chosen", - newHeadSlot = shortLog(newHead.slot), - newHeadEpoch = shortLog(newHead.slot.computeEpochOfSlot), - newHeadBlockRoot = shortLog(newHead.root) - node.blockPool.updateHead(node.stateCache, newHead) beacon_head_slot.set slot.int64 beacon_head_root.set newHead.root.toGaugeValue @@ -351,6 +342,8 @@ proc sendAttestation(node: BeaconNode, attestationData: AttestationData, committeeLen: int, indexInCommittee: int) {.async.} = + logScope: pcs = "send_attestation" + let validatorSignature = await validator.signAttestation(attestationData, state) @@ -371,17 +364,21 @@ proc sendAttestation(node: BeaconNode, attestationData = shortLog(attestationData), validator = shortLog(validator), signature = shortLog(validatorSignature), - indexInCommittee = indexInCommittee + indexInCommittee = indexInCommittee, + cat = "consensus" proc proposeBlock(node: BeaconNode, validator: AttachedValidator, head: BlockRef, slot: Slot): Future[BlockRef] {.async.} = + logScope: pcs = "block_proposal" + if head.slot > slot: notice "Skipping proposal, we've already selected a newer head", headSlot = shortLog(head.slot), headBlockRoot = shortLog(head.root), - slot = shortLog(slot) + slot = shortLog(slot), + cat = "fastforward" return head if head.slot == slot: @@ -389,7 +386,8 @@ proc proposeBlock(node: BeaconNode, # block for - did someone else steal our slot? why didn't we discard it? warn "Found head at same slot as we're supposed to propose for!", headSlot = shortLog(head.slot), - headBlockRoot = shortLog(head.root) + headBlockRoot = shortLog(head.root), + cat = "consensus_conflict" # TODO investigate how and when this happens.. maybe it shouldn't be an # assert? doAssert false, "head slot matches proposal slot (!)" @@ -453,13 +451,15 @@ proc proposeBlock(node: BeaconNode, if newBlockRef == nil: warn "Unable to add proposed block to block pool", newBlock = shortLog(newBlock), - blockRoot = shortLog(blockRoot) + blockRoot = shortLog(blockRoot), + cat = "bug" return head info "Block proposed", blck = shortLog(newBlock), blockRoot = shortLog(newBlockRef.root), - validator = shortLog(validator) + validator = shortLog(validator), + cat = "consensus" node.network.broadcast(topicBeaconBlocks, newBlock) @@ -469,9 +469,12 @@ proc onAttestation(node: BeaconNode, attestation: Attestation) = # We received an attestation from the network but don't know much about it # yet - in particular, we haven't verified that it belongs to particular chain # we're on, or that it follows the rules of the protocol + logScope: pcs = "on_attestation" + debug "Attestation received", attestationData = shortLog(attestation.data), - signature = shortLog(attestation.signature) + signature = shortLog(attestation.signature), + cat = "consensus" # Tag "consensus|attestation"? if (let attestedBlock = node.blockPool.getOrResolve( attestation.data.beacon_block_root); attestedBlock != nil): @@ -483,7 +486,8 @@ proc onAttestation(node: BeaconNode, attestation: Attestation) = warn "Received attestation before genesis or head - clock is wrong?", afterGenesis = wallSlot.afterGenesis, wallSlot = shortLog(wallSlot.slot), - headSlot = shortLog(head.blck.slot) + headSlot = shortLog(head.blck.slot), + cat = "clock_drift" # Tag "attestation|clock_drift"? return # TODO seems reasonable to use the latest head state here.. needs thinking @@ -504,7 +508,9 @@ proc onBeaconBlock(node: BeaconNode, blck: BeaconBlock) = let blockRoot = signing_root(blck) debug "Block received", blck = shortLog(blck), - blockRoot = shortLog(blockRoot) + blockRoot = shortLog(blockRoot), + cat = "block_listener", + pcs = "receive_block" if node.blockPool.add(node.stateCache, blockRoot, blck).isNil: return @@ -519,6 +525,7 @@ proc onBeaconBlock(node: BeaconNode, blck: BeaconBlock) = proc handleAttestations(node: BeaconNode, head: BlockRef, slot: Slot) = ## Perform all attestations that the validators attached to this node should ## perform during the given slot + logScope: pcs = "on_attestation" if slot + SLOTS_PER_EPOCH < head.slot: # The latest block we know about is a lot newer than the slot we're being @@ -542,9 +549,10 @@ proc handleAttestations(node: BeaconNode, head: BlockRef, slot: Slot) = attestationHeadSlot = shortLog(attestationHead.slot), attestationSlot = shortLog(slot) - debug "Checking attestations", + trace "Checking attestations", attestationHeadRoot = shortLog(attestationHead.blck.root), - attestationSlot = shortLog(slot) + attestationSlot = shortLog(slot), + cat = "attestation" # Collect data to send before node.stateCache grows stale var attestations: seq[tuple[ @@ -601,10 +609,12 @@ proc handleProposal(node: BeaconNode, head: BlockRef, slot: Slot): if validator != nil: return await proposeBlock(node, validator, head, slot) - debug "Expecting proposal", + trace "Expecting block proposal", headRoot = shortLog(head.root), slot = shortLog(slot), - proposer = shortLog(state.validators[proposerIdx].pubKey) + proposer = shortLog(state.validators[proposerIdx].pubKey), + cat = "consensus", + pcs = "wait_for_proposal" return head @@ -615,6 +625,8 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn ## start work from ## scheduledSlot: the slot that we were aiming for, in terms of timing + logScope: pcs = "slot_start" + let # The slot we should be at, according to the clock beaconTime = node.beaconClock.now() @@ -623,7 +635,9 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn debug "Slot start", lastSlot = shortLog(lastSlot), scheduledSlot = shortLog(scheduledSlot), - beaconTime = shortLog(beaconTime) + beaconTime = shortLog(beaconTime), + peers = node.network.peersCount, + cat = "scheduling" if not wallSlot.afterGenesis or (wallSlot.slot < lastSlot): # This can happen if the system clock changes time for example, and it's @@ -632,7 +646,8 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn warn "Beacon clock time moved back, rescheduling slot actions", beaconTime = shortLog(beaconTime), lastSlot = shortLog(lastSlot), - scheduledSlot = shortLog(scheduledSlot) + scheduledSlot = shortLog(scheduledSlot), + cat = "clock_drift" # tag "scheduling|clock_drift"? let slot = Slot( @@ -661,7 +676,8 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn warn "Unable to keep up, skipping ahead without doing work", lastSlot = shortLog(lastSlot), slot = shortLog(slot), - scheduledSlot = shortLog(scheduledSlot) + scheduledSlot = shortLog(scheduledSlot), + cat = "overload" addTimer(saturate(node.beaconClock.fromNow(nextSlot))) do (p: pointer): # We pass the current slot here to indicate that work should be skipped! @@ -703,7 +719,8 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn notice "Catching up", curSlot = shortLog(curSlot), lastSlot = shortLog(lastSlot), - slot = shortLog(slot) + slot = shortLog(slot), + cat = "overload" # For every slot we're catching up, we'll propose then send # attestations - head should normally be advancing along the same branch @@ -738,9 +755,10 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn if attestationStart.inFuture: attestationStart.offset + halfSlot else: halfSlot - attestationStart.offset - debug "Waiting to send attestations", + trace "Waiting to send attestations", slot = shortLog(slot), - fromNow = shortLog(fromNow) + fromNow = shortLog(fromNow), + cat = "scheduling" await sleepAsync(fromNow) @@ -753,12 +771,6 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn let nextSlotStart = saturate(node.beaconClock.fromNow(nextSlot)) - info "Scheduling slot actions", - lastSlot = shortLog(slot), - slot = shortLog(slot), - nextSlot = shortLog(nextSlot), - fromNow = shortLog(nextSlotStart) - addTimer(nextSlotStart) do (p: pointer): asyncCheck node.onSlotStart(slot, nextSlot) @@ -789,7 +801,8 @@ proc run*(node: BeaconNode) = info "Scheduling first slot action", beaconTime = shortLog(node.beaconClock.now()), nextSlot = shortLog(startSlot), - fromNow = shortLog(fromNow) + fromNow = shortLog(fromNow), + cat = "scheduling" addTimer(fromNow) do (p: pointer): asyncCheck node.onSlotStart(startSlot - 1, startSlot) @@ -822,7 +835,9 @@ proc start(node: BeaconNode, headState: BeaconState) = SHARD_COUNT, SLOTS_PER_EPOCH, SECONDS_PER_SLOT, - SPEC_VERSION + SPEC_VERSION, + cat = "init", + pcs = "start_beacon_node" node.addLocalValidators(headState) node.run() diff --git a/beacon_chain/block_pool.nim b/beacon_chain/block_pool.nim index 8af3249f5..505556919 100644 --- a/beacon_chain/block_pool.nim +++ b/beacon_chain/block_pool.nim @@ -4,6 +4,8 @@ import beacon_node_types, spec/[crypto, datatypes, digest, helpers] +logScope: topics = "blkpool" + proc parent*(bs: BlockSlot): BlockSlot = BlockSlot( blck: if bs.slot > bs.blck.slot: bs.blck else: bs.blck.parent, @@ -145,6 +147,8 @@ proc add*( proc addResolvedBlock( pool: var BlockPool, state: var StateData, blockRoot: Eth2Digest, blck: BeaconBlock, parent: BlockRef): BlockRef = + logScope: pcs = "block_resolution" + let blockRef = BlockRef.init(blockRoot, blck) link(parent, blockRef) @@ -186,7 +190,8 @@ proc addResolvedBlock( blck = shortLog(blck), blockRoot = shortLog(blockRoot), justifiedRoot = shortLog(foundHead.get().justified.blck.root), - justifiedSlot = shortLog(foundHead.get().justified.slot) + justifiedSlot = shortLog(foundHead.get().justified.slot), + cat = "filtering" # Now that we have the new block, we should see if any of the previously # unresolved blocks magically become resolved @@ -207,11 +212,14 @@ proc add*( # TODO reevaluate passing the state in like this doAssert blockRoot == signing_root(blck) + logScope: pcs = "block_addition" + # Already seen this block?? if blockRoot in pool.blocks: debug "Block already exists", blck = shortLog(blck), - blockRoot = shortLog(blockRoot) + blockRoot = shortLog(blockRoot), + cat = "filtering" return pool.blocks[blockRoot] @@ -225,7 +233,8 @@ proc add*( debug "Old block, dropping", blck = shortLog(blck), tailSlot = shortLog(pool.tail.slot), - blockRoot = shortLog(blockRoot) + blockRoot = shortLog(blockRoot), + cat = "filtering" return @@ -247,7 +256,8 @@ proc add*( # TODO find a better way to log all this block data notice "Invalid block", blck = shortLog(blck), - blockRoot = shortLog(blockRoot) + blockRoot = shortLog(blockRoot), + cat = "filtering" return @@ -278,7 +288,8 @@ proc add*( # from that branch, so right now, we'll just do a blind guess debug "Unresolved block (parent missing)", blck = shortLog(blck), - blockRoot = shortLog(blockRoot) + blockRoot = shortLog(blockRoot), + cat = "filtering" let parentSlot = blck.slot - 1 @@ -424,17 +435,23 @@ proc maybePutState(pool: BlockPool, state: HashedBeaconState, blck: BlockRef) = # potentially save multiple states per slot if reorgs happen, meaning # we could easily see a state explosion # TODO this is out of sync with epoch def now, I think -- (slot + 1) mod foo. + logScope: pcs = "save_state_at_epoch_start" + + if state.data.slot mod SLOTS_PER_EPOCH == 0: if not pool.db.containsState(state.root): info "Storing state", stateSlot = shortLog(state.data.slot), - stateRoot = shortLog(state.root) + stateRoot = shortLog(state.root), + cat = "caching" pool.db.putState(state.root, state.data) # TODO this should be atomic with the above write.. pool.db.putStateRoot(blck.root, state.data.slot, state.root) proc rewindState(pool: BlockPool, state: var StateData, bs: BlockSlot): seq[BlockData] = + logScope: pcs = "replay_state" + var ancestors = @[pool.get(bs.blck)] # Common case: the last block applied is the parent of the block to apply: if not bs.blck.parent.isNil and state.blck.root == bs.blck.parent.root and @@ -471,7 +488,8 @@ proc rewindState(pool: BlockPool, state: var StateData, bs: BlockSlot): # database, which should never happen (at least we should have the # tail state in there!) error "Couldn't find ancestor state root!", - blockRoot = shortLog(bs.blck.root) + blockRoot = shortLog(bs.blck.root), + cat = "crash" doAssert false, "Oh noes, we passed big bang!" let @@ -484,16 +502,18 @@ proc rewindState(pool: BlockPool, state: var StateData, bs: BlockSlot): # database, which should never happen (at least we should have the # tail state in there!) error "Couldn't find ancestor state or block parent missing!", - blockRoot = shortLog(bs.blck.root) + blockRoot = shortLog(bs.blck.root), + cat = "crash" doAssert false, "Oh noes, we passed big bang!" - debug "Replaying state transitions", + trace "Replaying state transitions", stateSlot = shortLog(state.data.data.slot), ancestorStateRoot = shortLog(ancestor.data.state_root), ancestorStateSlot = shortLog(ancestorState.get().slot), slot = shortLog(bs.slot), blockRoot = shortLog(bs.blck.root), - ancestors = ancestors.len + ancestors = ancestors.len, + cat = "replay_state" state.data.data = ancestorState.get() state.data.root = stateRoot.get() @@ -566,10 +586,13 @@ proc updateHead*(pool: BlockPool, state: var StateData, blck: BlockRef) = ## of operations naturally becomes important here - after updating the head, ## blocks that were once considered potential candidates for a tree will ## now fall from grace, or no longer be considered resolved. + logScope: pcs = "fork_choice" + if pool.head.blck == blck: - debug "No head update this time", + info "No head block update", headBlockRoot = shortLog(blck.root), - headBlockSlot = shortLog(blck.slot) + headBlockSlot = shortLog(blck.slot), + cat = "fork_choice" return @@ -579,30 +602,30 @@ proc updateHead*(pool: BlockPool, state: var StateData, blck: BlockRef) = # Start off by making sure we have the right state updateStateData(pool, state, BlockSlot(blck: blck, slot: blck.slot)) - let justifiedSlot = - state.data.data.current_justified_checkpoint.epoch.compute_start_slot_of_epoch() + let justifiedSlot = state.data.data + .current_justified_checkpoint + .epoch + .compute_start_slot_of_epoch() pool.head = Head(blck: blck, justified: blck.findAncestorBySlot(justifiedSlot)) if lastHead.blck != blck.parent: - notice "Updated head with new parent", + info "Updated No head block (new parent)", lastHeadRoot = shortLog(lastHead.blck.root), parentRoot = shortLog(blck.parent.root), stateRoot = shortLog(state.data.root), headBlockRoot = shortLog(state.blck.root), stateSlot = shortLog(state.data.data.slot), - justifiedEpoch = - shortLog(state.data.data.current_justified_checkpoint.epoch), - finalizedEpoch = - shortLog(state.data.data.finalized_checkpoint.epoch) + justifiedEpoch = shortLog(state.data.data.current_justified_checkpoint.epoch), + finalizedEpoch = shortLog(state.data.data.finalized_checkpoint.epoch), + cat = "fork_choice" else: - info "Updated head", + info "Updated No head block", stateRoot = shortLog(state.data.root), headBlockRoot = shortLog(state.blck.root), stateSlot = shortLog(state.data.data.slot), - justifiedEpoch = - shortLog(state.data.data.current_justified_checkpoint.epoch), - finalizedEpoch = - shortLog(state.data.data.finalized_checkpoint.epoch) + justifiedEpoch = shortLog(state.data.data.current_justified_checkpoint.epoch), + finalizedEpoch = shortLog(state.data.data.finalized_checkpoint.epoch), + cat = "fork_choice" let # TODO there might not be a block at the epoch boundary - what then? @@ -618,7 +641,8 @@ proc updateHead*(pool: BlockPool, state: var StateData, blck: BlockRef) = finalizedBlockRoot = shortLog(finalizedHead.blck.root), finalizedBlockSlot = shortLog(finalizedHead.slot), headBlockRoot = shortLog(blck.root), - headBlockSlot = shortLog(blck.slot) + headBlockSlot = shortLog(blck.slot), + cat = "fork_choice" var cur = finalizedHead.blck while cur != pool.finalizedHead.blck: @@ -673,11 +697,12 @@ proc preInit*( let blockRoot = signing_root(blck) - notice "Creating new database from snapshot", + notice "New database from snapshot", blockRoot = shortLog(blockRoot), stateRoot = shortLog(blck.state_root), fork = state.fork, - validators = state.validators.len() + validators = state.validators.len(), + cat = "initialization" db.putState(state) db.putBlock(blck)