clean up attestation logging

beacon_chain/attestation_pool.nim

@@ -162,7 +162,7 @@ proc addResolved(pool: var AttestationPool, blck: BlockRef, attestation: Attesta
   # voted for..
   if blck.slot > attestation.data.slot:
     notice "Invalid attestation (too new!)",
-      attestationData = shortLog(attestation.data),
+      attestation = shortLog(attestation),
       blockSlot = shortLog(blck.slot)
     return
 
@@ -174,10 +174,8 @@ proc addResolved(pool: var AttestationPool, blck: BlockRef, attestation: Attesta
 
   if not validate(state, attestation):
     notice "Invalid attestation",
-      attestationData = shortLog(attestation.data),
+      attestation = shortLog(attestation),
       current_epoch = get_current_epoch(state),
-      target_epoch = attestation.data.target.epoch,
-      stateSlot = state.slot,
       cat = "filtering"
     return
 
@@ -231,11 +229,10 @@ proc addResolved(pool: var AttestationPool, blck: BlockRef, attestation: Attesta
         pool.updateLatestVotes(state, attestationSlot, participants, a.blck)
 
         info "Attestation resolved",
-          attestationData = shortLog(attestation.data),
+          attestation = shortLog(attestation),
           validations = a.validations.len(),
           current_epoch = get_current_epoch(state),
-          target_epoch = attestation.data.target.epoch,
-          stateSlot = state.slot,
+          blockSlot = shortLog(blck.slot),
           cat = "filtering"
 
         found = true
@@ -251,11 +248,10 @@ proc addResolved(pool: var AttestationPool, blck: BlockRef, attestation: Attesta
     pool.updateLatestVotes(state, attestationSlot, participants, blck)
 
     info "Attestation resolved",
-      attestationData = shortLog(attestation.data),
+      attestation = shortLog(attestation),
       current_epoch = get_current_epoch(state),
-      target_epoch = attestation.data.target.epoch,
-      stateSlot = state.slot,
       validations = 1,
+      blockSlot = shortLog(blck.slot),
       cat = "filtering"
 
 proc add*(pool: var AttestationPool, attestation: Attestation) =

beacon_chain/beacon_node.nim

@@ -393,9 +393,8 @@ proc sendAttestation(node: BeaconNode,
       ".ssz", attestation)
 
   info "Attestation sent",
-    attestationData = shortLog(attestationData),
+    attestation = shortLog(attestation),
     validator = shortLog(validator),
-    signature = shortLog(validatorSignature),
     indexInCommittee = indexInCommittee,
     cat = "consensus"
 
@@ -501,15 +500,17 @@ proc onAttestation(node: BeaconNode, attestation: Attestation) =
   # 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),
-    cat = "consensus" # Tag "consensus|attestation"?
-
   let
     wallSlot = node.beaconClock.now().toSlot()
     head = node.blockPool.head
 
+  debug "Attestation received",
+    attestation = shortLog(attestation),
+    headRoot = shortLog(head.blck.root),
+    headSlot = shortLog(head.blck.slot),
+    wallSlot = shortLog(wallSlot.slot),
+    cat = "consensus" # Tag "consensus|attestation"?
+
   if not wallSlot.afterGenesis or wallSlot.slot < head.blck.slot:
     warn "Received attestation before genesis or head - clock is wrong?",
       afterGenesis = wallSlot.afterGenesis,

beacon_chain/spec/datatypes.nim

@@ -599,6 +599,7 @@ func shortLog*(v: BeaconBlock): auto =
 func shortLog*(v: AttestationData): auto =
   (
     slot: shortLog(v.slot),
+    index: v.index,
     beacon_block_root: shortLog(v.beacon_block_root),
     source_epoch: shortLog(v.source.epoch),
     source_root: shortLog(v.source.root),
@@ -606,10 +607,18 @@ func shortLog*(v: AttestationData): auto =
     target_root: shortLog(v.target.root)
   )
 
+func shortLog*(v: Attestation): auto =
+  (
+    aggregation_bits: v.aggregation_bits,
+    data: shortLog(v.data),
+    signature: shortLog(v.signature)
+  )
+
 chronicles.formatIt Slot: it.shortLog
 chronicles.formatIt Epoch: it.shortLog
 chronicles.formatIt BeaconBlock: it.shortLog
 chronicles.formatIt AttestationData: it.shortLog
+chronicles.formatIt Attestation: it.shortLog
 
 import json_serialization
 export json_serialization

beacon_chain/spec/state_transition_epoch.nim

@@ -167,7 +167,7 @@ proc process_justification_and_finalization*(
                  root: get_block_root(state, previous_epoch))
     state.justification_bits.setBit 1
 
-    debug "Justified with previous epoch",
+    trace "Justified with previous epoch",
       current_epoch = current_epoch,
       checkpoint = shortLog(state.current_justified_checkpoint),
       cat = "justification"
@@ -181,7 +181,7 @@ proc process_justification_and_finalization*(
                  root: get_block_root(state, current_epoch))
     state.justification_bits.setBit 0
 
-    debug "Justified with current epoch",
+    trace "Justified with current epoch",
       current_epoch = current_epoch,
       checkpoint = shortLog(state.current_justified_checkpoint),
       cat = "justification"
@@ -195,7 +195,7 @@ proc process_justification_and_finalization*(
      old_previous_justified_checkpoint.epoch + 3 == current_epoch:
     state.finalized_checkpoint = old_previous_justified_checkpoint
 
-    debug "Finalized with rule 234",
+    trace "Finalized with rule 234",
       current_epoch = current_epoch,
       checkpoint = shortLog(state.finalized_checkpoint),
       cat = "finalization"
@@ -206,7 +206,7 @@ proc process_justification_and_finalization*(
      old_previous_justified_checkpoint.epoch + 2 == current_epoch:
     state.finalized_checkpoint = old_previous_justified_checkpoint
 
-    debug "Finalized with rule 23",
+    trace "Finalized with rule 23",
       current_epoch = current_epoch,
       checkpoint = shortLog(state.finalized_checkpoint),
       cat = "finalization"
@@ -217,7 +217,7 @@ proc process_justification_and_finalization*(
      old_current_justified_checkpoint.epoch + 2 == current_epoch:
     state.finalized_checkpoint = old_current_justified_checkpoint
 
-    debug "Finalized with rule 123",
+    trace "Finalized with rule 123",
       current_epoch = current_epoch,
       checkpoint = shortLog(state.finalized_checkpoint),
       cat = "finalization"
@@ -228,7 +228,7 @@ proc process_justification_and_finalization*(
      old_current_justified_checkpoint.epoch + 1 == current_epoch:
     state.finalized_checkpoint = old_current_justified_checkpoint
 
-    debug "Finalized with rule 12",
+    trace "Finalized with rule 12",
       current_epoch = current_epoch,
       checkpoint = shortLog(state.finalized_checkpoint),
       cat = "finalization"