fix epoch logging (fixes #2283) (#2642)

Also put epoch first to disambiguate vs slot

beacon_chain/consensus_object_pools/block_pools_types.nim

@@ -9,9 +9,9 @@
 
 import
   # Standard library
-  std/[strformat, sets, tables, hashes],
+  std/[sets, tables, hashes],
   # Status libraries
-  stew/[endians2, byteutils], chronicles,
+  stew/[endians2], chronicles,
   eth/keys,
   # Internals
   ../spec/[datatypes, crypto, digest, signatures_batch],
@@ -154,20 +154,29 @@ type
 
     runtimePreset*: RuntimePreset
 
-    epochRefs*: array[32, (BlockRef, EpochRef)] ##\
+    epochRefs*: array[32, EpochRef] ##\
       ## Cached information about a particular epoch ending with the given
       ## block - we limit the number of held EpochRefs to put a cap on
       ## memory usage
 
+  EpochKey* = object
+    ## The epoch key fully determines the shuffling for proposers and
+    ## committees in a beacon state - the epoch level information in the state
+    ## is derived from the last known block in the particular history _before_
+    ## the beginning of that epoch, and then advanced with slot processing to
+    ## the epoch start - we call this block the "epoch ancestor" in other parts
+    ## of the code.
+    epoch*: Epoch
+    blck*: BlockRef
+
   EpochRef* = ref object
     dag*: ChainDAGRef
-    epoch*: Epoch
+    key*: EpochKey
     current_justified_checkpoint*: Checkpoint
     finalized_checkpoint*: Checkpoint
     eth1_data*: Eth1Data
     eth1_deposit_index*: uint64
-    beacon_proposers*: array[
-      SLOTS_PER_EPOCH, Option[ValidatorIndex]]
+    beacon_proposers*: array[SLOTS_PER_EPOCH, Option[ValidatorIndex]]
     shuffled_active_validator_indices*: seq[ValidatorIndex]
 
     # balances, as used in fork choice
@@ -195,37 +204,39 @@ type
 
 template head*(dag: ChainDagRef): BlockRef = dag.headState.blck
 
-func shortLog*(v: BlockSlot): string =
-  try:
-    if v.blck.isNil():
-      &"nil:0@{v.slot}"
-    elif v.blck.slot == v.slot:
-      &"{v.blck.root.data.toOpenArray(0, 3).toHex()}:{v.blck.slot}"
-    else: # There was a gap - log it
-      &"{v.blck.root.data.toOpenArray(0, 3).toHex()}:{v.blck.slot}@{v.slot}"
-  except ValueError as err:
-    err.msg # Shouldn't happen - but also shouldn't crash!
+template epoch*(e: EpochRef): Epoch = e.key.epoch
 
 func shortLog*(v: BlockRef): string =
-  try:
-    if v.isNil():
-      "BlockRef(nil)"
-    else:
-      &"{v.root.data.toOpenArray(0, 3).toHex()}:{v.slot}"
-  except ValueError as err:
-    err.msg # Shouldn't happen - but also shouldn't crash!
+  # epoch:root when logging epoch, root:slot when logging slot!
+  if v.isNil():
+    "nil:0"
+  else:
+    shortLog(v.root) & ":" & $v.slot
+
+func shortLog*(v: BlockSlot): string =
+  # epoch:root when logging epoch, root:slot when logging slot!
+  if v.blck.isNil():
+    "nil:0@" & $v.slot
+  elif v.blck.slot == v.slot:
+    shortLog(v.blck)
+  else: # There was a gap - log it
+    shortLog(v.blck) & "@" & $v.slot
+
+func shortLog*(v: EpochKey): string =
+  # epoch:root when logging epoch, root:slot when logging slot!
+  $v.epoch & ":" & shortLog(v.blck)
 
 func shortLog*(v: EpochRef): string =
-  try:
-    if v.isNil():
-      "EpochRef(nil)"
-    else:
-      &"(epoch ref: {v.epoch})"
-  except ValueError as err:
-    err.msg # Shouldn't happen - but also shouldn't crash!
+  # epoch:root when logging epoch, root:slot when logging slot!
+  if v.isNil():
+    "0:nil"
+  else:
+    shortLog(v.key)
 
 chronicles.formatIt BlockSlot: shortLog(it)
 chronicles.formatIt BlockRef: shortLog(it)
+chronicles.formatIt EpochKey: shortLog(it)
+chronicles.formatIt EpochRef: shortLog(it)
 
 func hash*(key: KeyedBlockRef): Hash =
   hash(key.data.root)

beacon_chain/consensus_object_pools/blockchain_dag.nim

@@ -143,7 +143,7 @@ func init*(
     epoch = state.get_current_epoch()
     epochRef = EpochRef(
       dag: dag, # This gives access to the validator pubkeys through an EpochRef
-      epoch: epoch,
+      key: state.blck.epochAncestor(epoch),
       eth1_data: getStateField(state, eth1_data),
       eth1_deposit_index: getStateField(state, eth1_deposit_index),
       current_justified_checkpoint:
@@ -242,7 +242,7 @@ func atEpochStart*(blck: BlockRef, epoch: Epoch): BlockSlot =
   ## Return the BlockSlot corresponding to the first slot in the given epoch
   atSlot(blck, epoch.compute_start_slot_at_epoch)
 
-func epochAncestor*(blck: BlockRef, epoch: Epoch): BlockSlot =
+func epochAncestor*(blck: BlockRef, epoch: Epoch): EpochKey =
   ## The state transition works by storing information from blocks in a
   ## "working" area until the epoch transition, then batching work collected
   ## during the epoch. Thus, last block in the ancestor epochs is the block
@@ -255,15 +255,15 @@ func epochAncestor*(blck: BlockRef, epoch: Epoch): BlockSlot =
   while blck.slot.epoch >= epoch and not blck.parent.isNil:
     blck = blck.parent
 
-  blck.atEpochStart(epoch)
+  EpochKey(epoch: epoch, blck: blck)
 
 func findEpochRef*(
     dag: ChainDAGRef, blck: BlockRef, epoch: Epoch): EpochRef = # may return nil!
   let ancestor = blck.epochAncestor(epoch)
   doAssert ancestor.blck != nil
   for i in 0..<dag.epochRefs.len:
-    if dag.epochRefs[i][0] == ancestor.blck and dag.epochRefs[i][1].epoch == epoch:
-      return dag.epochRefs[i][1]
+    if dag.epochRefs[i] != nil and dag.epochRefs[i].key == ancestor:
+      return dag.epochRefs[i]
 
   return nil
 
@@ -452,7 +452,7 @@ func getEpochRef*(
     dag: ChainDAGRef, state: StateData, cache: var StateCache): EpochRef =
   let
     blck = state.blck
-    epoch = getStateField(state, slot).epoch
+    epoch = state.get_current_epoch()
 
   var epochRef = dag.findEpochRef(blck, epoch)
   if epochRef == nil:
@@ -470,15 +470,13 @@ func getEpochRef*(
         oldest = 0
       for x in 0..<dag.epochRefs.len:
         let candidate = dag.epochRefs[x]
-        if candidate[1] == nil:
+        if candidate == nil:
           oldest = x
           break
-        if candidate[1].epoch < dag.epochRefs[oldest][1].epoch:
+        if candidate.key.epoch < dag.epochRefs[oldest].epoch:
           oldest = x
 
-      let
-        ancestor = blck.epochAncestor(epoch)
-      dag.epochRefs[oldest] = (ancestor.blck, epochRef)
+      dag.epochRefs[oldest] = epochRef
 
   epochRef
 
@@ -493,7 +491,8 @@ proc getEpochRef*(dag: ChainDAGRef, blck: BlockRef, epoch: Epoch): EpochRef =
   let
     ancestor = blck.epochAncestor(epoch)
 
-  dag.withState(dag.epochRefState, ancestor):
+  dag.withState(
+      dag.epochRefState, ancestor.blck.atEpochStart(ancestor.epoch)):
     dag.getEpochRef(stateData, cache)
 
 proc getFinalizedEpochRef*(dag: ChainDAGRef): EpochRef =
@@ -865,8 +864,9 @@ proc updateStateData*(
 
 proc delState(dag: ChainDAGRef, bs: BlockSlot) =
   # Delete state state and mapping for a particular block+slot
-  if not bs.slot.isEpoch:
+  if not isStateCheckpoint(bs):
     return # We only ever save epoch states
+
   if (let root = dag.db.getStateRoot(bs.blck.root, bs.slot); root.isSome()):
     dag.db.delState(root.get())
     dag.db.delStateRoot(bs.blck.root, bs.slot)
@@ -948,9 +948,9 @@ proc pruneStateCachesDAG*(dag: ChainDAGRef) =
     # After finalization, we can clear up the epoch cache and save memory -
     # it will be recomputed if needed
     for i in 0..<dag.epochRefs.len:
-      if dag.epochRefs[i][1] != nil and
-          dag.epochRefs[i][1].epoch < dag.finalizedHead.slot.epoch:
-        dag.epochRefs[i] = (nil, nil)
+      if dag.epochRefs[i] != nil and
+          dag.epochRefs[i].epoch < dag.finalizedHead.slot.epoch:
+        dag.epochRefs[i] = nil
   let epochRefPruneTick = Moment.now()
 
   dag.lastPrunePoint = dag.finalizedHead

beacon_chain/spec/datatypes/base.nim

@@ -811,10 +811,8 @@ func shortLog*(v: DepositData): auto =
   )
 
 func shortLog*(v: Checkpoint): auto =
-  (
-    epoch: shortLog(v.epoch),
-    root: shortLog(v.root),
-  )
+  # epoch:root when logging epoch, root:slot when logging slot!
+  $shortLog(v.epoch) & ":" & shortLog(v.root)
 
 func shortLog*(v: AttestationData): auto =
   (

tests/test_block_pool.nim

@@ -77,7 +77,7 @@ suite "BlockRef and helpers" & preset():
     let ancestor = cur.epochAncestor(cur.slot.epoch)
 
     check:
-      ancestor.slot.epoch == cur.slot.epoch
+      ancestor.epoch == cur.slot.epoch
       ancestor.blck != cur # should have selected a parent
 
       ancestor.blck.epochAncestor(cur.slot.epoch) == ancestor
@@ -395,7 +395,7 @@ suite "chain DAG finalization tests" & preset():
 
     block:
       for er in dag.epochRefs:
-        check: er[1] == nil or er[1].epoch >= dag.finalizedHead.slot.epoch
+        check: er == nil or er.epoch >= dag.finalizedHead.slot.epoch
 
     block:
       let tmpStateData = assignClone(dag.headState)