fix startup time casts, log fixes

beacon_chain/beacon_node.nim

@@ -414,12 +414,23 @@ proc onAttestation(node: BeaconNode, attestation: Attestation) =
     attestationData = shortLog(attestation.data),
     signature = shortLog(attestation.signature)
 
+  let
+    wallSlot = node.beaconClock.now().toSlot()
+    head = node.blockPool.head
+
+  if not wallSlot.afterGenesis or wallSlot.slot < head.blck.slot:
+    warn "Received attestation before genesis or head - clock is wrong?",
+      afterGenesis = wallSlot.afterGenesis,
+      wallSlot = shortLog(wallSlot.slot),
+      headSlot = shortLog(head.blck.slot)
+    return
+
   # TODO seems reasonable to use the latest head state here.. needs thinking
   #      though - maybe we should use the state from the block pointed to by
   #      the attestation for some of the check? Consider interop with block
   #      production!
   node.blockPool.withState(node.stateCache,
-      BlockSlot(blck: node.blockPool.head.blck, slot: node.beaconClock.now().toSlot())):
+      BlockSlot(blck: head.blck, slot: wallSlot.slot)):
     var stateCache = get_empty_per_epoch_cache()
     node.attestationPool.add(state, attestation)
 
@@ -580,27 +591,39 @@ proc onSlotStart(node: BeaconNode, lastSlot, scheduledSlot: Slot) {.gcsafe, asyn
 
   let
     # The slot we should be at, according to the clock
-    slot = node.beaconClock.now().toSlot()
+    beaconTime = node.beaconClock.now()
-    nextSlot = slot + 1
+    wallSlot = beaconTime.toSlot()
 
   debug "Slot start",
     lastSlot = shortLog(lastSlot),
     scheduledSlot = shortLog(scheduledSlot),
-    slot = shortLog(slot)
+    beaconTime = shortLog(beaconTime)
 
-  if slot < lastSlot:
+  if not wallSlot.afterGenesis or (wallSlot.slot < lastSlot):
     # This can happen if the system clock changes time for example, and it's
     # pretty bad
     # TODO shut down? time either was or is bad, and PoS relies on accuracy..
     warn "Beacon clock time moved back, rescheduling slot actions",
-      slot = shortLog(slot),
+      beaconTime = shortLog(beaconTime),
+      lastSlot = shortLog(lastSlot),
       scheduledSlot = shortLog(scheduledSlot)
 
+    let
+      slot = Slot(
+        if wallSlot.afterGenesis:
+          max(1'u64, wallSlot.slot.uint64)
+        else: GENESIS_SLOT.uint64 + 1)
+      nextSlot = slot + 1
+
     addTimer(saturate(node.beaconClock.fromNow(nextSlot))) do (p: pointer):
       asyncCheck node.onSlotStart(slot, nextSlot)
 
     return
 
+  let
+    slot = wallSlot.slot # afterGenesis == true!
+    nextSlot = slot + 1
+
   if slot > lastSlot + SLOTS_PER_EPOCH:
     # We've fallen behind more than an epoch - there's nothing clever we can
     # do here really, except skip all the work and try again later.
@@ -730,13 +753,14 @@ proc run*(node: BeaconNode) =
     node.onAttestation(attestation)
 
   let
-    slot = node.beaconClock.now().toSlot()
+    wallSlot = node.beaconClock.now().toSlot()
     startSlot =
-      if slot >= GENESIS_SLOT: slot + 1
+      if wallSlot.afterGenesis: wallSlot.slot + 1
       else: GENESIS_SLOT + 1
     fromNow = saturate(node.beaconClock.fromNow(startSlot))
 
   info "Scheduling first slot action",
+    beaconTime = shortLog(node.beaconClock.now()),
     nextSlot = shortLog(startSlot),
     fromNow = shortLog(fromNow)
 
@@ -764,8 +788,8 @@ proc start(node: BeaconNode, headState: BeaconState) =
   waitFor node.connectToNetwork()
 
   info "Starting beacon node",
-    slotsSinceFinalization =
+    timeSinceFinalization =
-      int64(node.blockPool.finalizedHead.slot) -
+      int64(node.blockPool.finalizedHead.slot.toBeaconTime()) -
       int64(node.beaconClock.now()),
     stateSlot = shortLog(headState.slot),
     SHARD_COUNT,

beacon_chain/block_pool.nim

@@ -297,7 +297,7 @@ proc add*(
 
 proc getRef*(pool: BlockPool, root: Eth2Digest): BlockRef =
   ## Retrieve a resolved block reference, if available
-  result = pool.blocks.getOrDefault(root)
+  pool.blocks.getOrDefault(root)
 
 proc get*(pool: BlockPool, blck: BlockRef): BlockData =
   ## Retrieve the associated block body of a block reference

beacon_chain/spec/datatypes.nim

@@ -569,35 +569,44 @@ func shortLog*(s: Slot): uint64 =
 func shortLog*(e: Epoch): uint64 =
   e - GENESIS_EPOCH
 
-func shortLog*(v: BeaconBlock): tuple[
+func shortLog*(v: BeaconBlock): auto =
-    slot: uint64, parent_root: string, state_root: string,
+  (
-    #[ eth1_data ]#
+    slot: shortLog(v.slot),
-    proposer_slashings_len: int, attester_slashings_len: int,
+    parent_root: shortLog(v.parent_root),
-    attestations_len: int,
+    state_root: shortLog(v.state_root),
-    deposits_len: int,
+    proposer_slashings_len: v.body.proposer_slashings.len(),
-    voluntary_exits_len: int,
+    attester_slashings_len: v.body.attester_slashings.len(),
-    transfers_len: int,
+    attestations_len: v.body.attestations.len(),
-    signature: string
+    deposits_len: v.body.deposits.len(),
-  ] = (
+    voluntary_exits_len: v.body.voluntary_exits.len(),
-    shortLog(v.slot), shortLog(v.parent_root),
+    transfers_len: v.body.transfers.len(),
-    shortLog(v.state_root), v.body.proposer_slashings.len(),
+    signature: shortLog(v.signature)
-    v.body.attester_slashings.len(), v.body.attestations.len(),
+  )
-    v.body.deposits.len(), v.body.voluntary_exits.len(), v.body.transfers.len(),
+
-    shortLog(v.signature)
+func shortLog*(v: Crosslink): auto =
+  (
+    shard: v.shard,
+    parent_root: shortLog(v.parent_root),
+    start_epoch: shortLog(v.start_epoch),
+    end_epoch: shortLog(v.end_epoch),
+    data_root: shortLog(v.data_root)
   )
 
 func shortLog*(v: AttestationData): auto =
   (
-      shortLog(v.beacon_block_root),
+    beacon_block_root: shortLog(v.beacon_block_root),
-      shortLog(v.source.epoch), shortLog(v.target.root),
+    source_epoch: shortLog(v.source.epoch),
-      shortLog(v.source.root),
+    source_root: shortLog(v.source.root),
-      v.crosslink
+    target_epoch: shortLog(v.target.epoch),
+    target_root: shortLog(v.target.root),
+    crosslink: shortLog(v.crosslink)
   )
 
 chronicles.formatIt Slot: it.shortLog
 chronicles.formatIt Epoch: it.shortLog
 chronicles.formatIt BeaconBlock: it.shortLog
 chronicles.formatIt AttestationData: it.shortLog
+chronicles.formatIt CrossLink: it.shortLog
 
 static:
   # Ensure that get_crosslink_committee(...) can access all committees, which

beacon_chain/time.nim

@@ -38,13 +38,17 @@ proc init*(T: type BeaconClock, state: BeaconState): T =
 
   T(genesis: unixGenesis - unixGenesisOffset)
 
-func toSlot*(t: BeaconTime): Slot =
+func toSlot*(t: BeaconTime): tuple[afterGenesis: bool, slot: Slot] =
-  Slot(uint64(t) div SECONDS_PER_SLOT)
+  let ti = t.int64
+  if ti >= 0:
+    (true, Slot(uint64(ti) div SECONDS_PER_SLOT))
+  else:
+    (false, Slot(uint64(-ti) div SECONDS_PER_SLOT))
 
 func toBeaconTime*(c: BeaconClock, t: Time): BeaconTime =
-  BeaconTime(times.seconds(t - c.genesis).int64)
+  BeaconTime(times.seconds(t - c.genesis))
 
-func toSlot*(c: BeaconClock, t: Time): Slot =
+func toSlot*(c: BeaconClock, t: Time): tuple[afterGenesis: bool, slot: Slot] =
   c.toBeaconTime(t).toSlot()
 
 func toBeaconTime*(s: Slot, offset = chronos.seconds(0)): BeaconTime =
@@ -71,7 +75,7 @@ proc saturate*(d: tuple[inFuture: bool, offset: Duration]): Duration =
 proc addTimer*(fromNow: Duration, cb: CallbackFunc, udata: pointer = nil) =
   addTimer(Moment.now() + fromNow, cb, udata)
 
-proc shortLog*(d: Duration): string =
+func shortLog*(d: Duration): string =
   let dd = int64(d.milliseconds())
   if dd < 1000:
     $dd & "ms"
@@ -89,3 +93,5 @@ proc shortLog*(d: Duration): string =
     if (let frac = mins mod 60; frac > 0):
       tmp &= $frac & "m"
     tmp
+
+func shortLog*(v: BeaconTime): int64 = v.int64