[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
This commit is contained in:
Mamy Ratsimbazafy
Mamy André-Ratsimbazafy
parent
6be5805462
commit
0b68f3dc63
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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()
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
Loading…
Reference in New Issue