diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs index 385eb454044..9cfa307f237 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/ChainDB.hs @@ -49,6 +49,7 @@ import qualified Ouroboros.Consensus.Storage.LedgerDB.Types as LedgerDB import qualified Ouroboros.Consensus.Storage.VolatileDB as VolDB import qualified Ouroboros.Consensus.Storage.VolatileDB.Impl as VolDb import Ouroboros.Consensus.Util.Condense (condense) +import Ouroboros.Consensus.Util.Enclose import qualified Data.Aeson.KeyMap as KeyMap import qualified Ouroboros.Network.AnchoredFragment as AF @@ -203,9 +204,11 @@ sevTraceAddBlockEvent ChainDB.IgnoreInvalidBlock {} = Info sevTraceAddBlockEvent ChainDB.AddedBlockToQueue {} = Debug sevTraceAddBlockEvent ChainDB.BlockInTheFuture {} = Info sevTraceAddBlockEvent ChainDB.AddedBlockToVolatileDB {} = Debug +sevTraceAddBlockEvent ChainDB.PoppedBlockFromQueue {} = Debug sevTraceAddBlockEvent ChainDB.TryAddToCurrentChain {} = Debug sevTraceAddBlockEvent ChainDB.TrySwitchToAFork {} = Info sevTraceAddBlockEvent ChainDB.StoreButDontChange {} = Debug +sevTraceAddBlockEvent ChainDB.ChangingSelection {} = Debug sevTraceAddBlockEvent (ChainDB.AddedToCurrentChain events _ _ _) = maximumDef Notice (map sevLedgerEvent events) sevTraceAddBlockEvent (ChainDB.SwitchedToAFork events _ _ _) = @@ -234,6 +237,8 @@ namesForChainDBAddBlock (ChainDB.IgnoreInvalidBlock {}) = ["IgnoreInvalidBlock"] namesForChainDBAddBlock (ChainDB.AddedBlockToQueue {}) = ["AddedBlockToQueue"] +namesForChainDBAddBlock (ChainDB.PoppedBlockFromQueue {}) = + ["PoppedBlockFromQueue"] namesForChainDBAddBlock (ChainDB.BlockInTheFuture {}) = ["BlockInTheFuture"] namesForChainDBAddBlock (ChainDB.AddedBlockToVolatileDB {}) = @@ -248,6 +253,8 @@ namesForChainDBAddBlock (ChainDB.AddedToCurrentChain {}) = ["AddedToCurrentChain"] namesForChainDBAddBlock (ChainDB.SwitchedToAFork {}) = ["SwitchedToAFork"] +namesForChainDBAddBlock (ChainDB.ChangingSelection {}) = + ["ChangingSelection"] namesForChainDBAddBlock (ChainDB.AddBlockValidation ev') = "AddBlockValidation" : namesForChainDBAddBlockValidation ev' namesForChainDBAddBlock (ChainDB.ChainSelectionForFutureBlock {}) = @@ -285,8 +292,18 @@ instance ( LogFormatting (Header blk) "Ignoring block already in DB: " <> renderRealPointAsPhrase pt forHuman (ChainDB.IgnoreInvalidBlock pt _reason) = "Ignoring previously seen invalid block: " <> renderRealPointAsPhrase pt - forHuman (ChainDB.AddedBlockToQueue pt sz) = - "Block added to queue: " <> renderRealPointAsPhrase pt <> " queue size " <> condenseT sz + forHuman (ChainDB.AddedBlockToQueue pt edgeSz) = + case edgeSz of + RisingEdge -> + "About to add block to queue: " <> renderRealPointAsPhrase pt + FallingEdgeWith sz -> + "Block added to queue: " <> renderRealPointAsPhrase pt <> " queue size " <> condenseT sz + forHuman (ChainDB.PoppedBlockFromQueue edgePt) = + case edgePt of + RisingEdge -> + "Popping block from queue" + FallingEdgeWith pt -> + "Popped block from queue: " <> renderRealPointAsPhrase pt forHuman (ChainDB.BlockInTheFuture pt slot) = "Ignoring block from future: " <> renderRealPointAsPhrase pt <> ", slot " <> condenseT slot forHuman (ChainDB.StoreButDontChange pt) = @@ -295,6 +312,8 @@ instance ( LogFormatting (Header blk) "Block fits onto the current chain: " <> renderRealPointAsPhrase pt forHuman (ChainDB.TrySwitchToAFork pt _) = "Block fits onto some fork: " <> renderRealPointAsPhrase pt + forHuman (ChainDB.ChangingSelection pt) = + "Changing selection to: " <> renderPointAsPhrase pt forHuman (ChainDB.AddedToCurrentChain es _ _ c) = "Chain extended, new tip: " <> renderPointAsPhrase (AF.headPoint c) <> Text.concat [ "\nEvent: " <> showT e | e <- es ] @@ -302,8 +321,10 @@ instance ( LogFormatting (Header blk) "Switched to a fork, new tip: " <> renderPointAsPhrase (AF.headPoint c) <> Text.concat [ "\nEvent: " <> showT e | e <- es ] forHuman (ChainDB.AddBlockValidation ev') = forHuman ev' - forHuman (ChainDB.AddedBlockToVolatileDB pt _ _) = - "Chain added block " <> renderRealPointAsPhrase pt + forHuman (ChainDB.AddedBlockToVolatileDB pt _ _ enclosing) = + case enclosing of + RisingEdge -> "Chain about to add block " <> renderRealPointAsPhrase pt + FallingEdgeWith () -> "Chain added block " <> renderRealPointAsPhrase pt forHuman (ChainDB.ChainSelectionForFutureBlock pt) = "Chain selection run for block previously from future: " <> renderRealPointAsPhrase pt forHuman (ChainDB.PipeliningEvent ev') = forHuman ev' @@ -317,10 +338,13 @@ instance ( LogFormatting (Header blk) mconcat [ "kind" .= String "IgnoreInvalidBlock" , "block" .= forMachine dtal pt , "reason" .= showT reason ] - forMachine dtal (ChainDB.AddedBlockToQueue pt sz) = + forMachine dtal (ChainDB.AddedBlockToQueue pt edgeSz) = mconcat [ "kind" .= String "AddedBlockToQueue" , "block" .= forMachine dtal pt - , "queueSize" .= toJSON sz ] + , case edgeSz of RisingEdge -> "risingEdge" .= True; FallingEdgeWith sz -> "queueSize" .= toJSON sz ] + forMachine dtal (ChainDB.PoppedBlockFromQueue edgePt) = + mconcat [ "kind" .= String "TraceAddBlockEvent.PoppedBlockFromQueue" + , case edgePt of RisingEdge -> "risingEdge" .= True; FallingEdgeWith pt -> "block" .= forMachine dtal pt ] forMachine dtal (ChainDB.BlockInTheFuture pt slot) = mconcat [ "kind" .= String "BlockInTheFuture" , "block" .= forMachine dtal pt @@ -334,6 +358,9 @@ instance ( LogFormatting (Header blk) forMachine dtal (ChainDB.TrySwitchToAFork pt _) = mconcat [ "kind" .= String "TraceAddBlockEvent.TrySwitchToAFork" , "block" .= forMachine dtal pt ] + forMachine dtal (ChainDB.ChangingSelection pt) = + mconcat [ "kind" .= String "TraceAddBlockEvent.ChangingSelection" + , "block" .= forMachine dtal pt ] forMachine dtal (ChainDB.AddedToCurrentChain events _ base extended) = mconcat $ [ "kind" .= String "AddedToCurrentChain" @@ -354,10 +381,11 @@ instance ( LogFormatting (Header blk) | not (null events) ] forMachine dtal (ChainDB.AddBlockValidation ev') = kindContext "AddBlockEvent" $ forMachine dtal ev' - forMachine dtal (ChainDB.AddedBlockToVolatileDB pt (BlockNo bn) _) = - mconcat [ "kind" .= String "AddedBlockToVolatileDB" - , "block" .= forMachine dtal pt - , "blockNo" .= showT bn ] + forMachine dtal (ChainDB.AddedBlockToVolatileDB pt (BlockNo bn) _ enclosing) = + mconcat $ [ "kind" .= String "AddedBlockToVolatileDB" + , "block" .= forMachine dtal pt + , "blockNo" .= showT bn ] + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] forMachine dtal (ChainDB.ChainSelectionForFutureBlock pt) = mconcat [ "kind" .= String "TChainSelectionForFutureBlock" , "block" .= forMachine dtal pt ] @@ -387,16 +415,19 @@ instance ( LogFormatting (Header blk) instance ( ConvertRawHash (Header blk) , HasHeader (Header blk) ) => LogFormatting (ChainDB.TracePipeliningEvent blk) where - forHuman (ChainDB.SetTentativeHeader hdr) = - "Set tentative header to " <> renderPointAsPhrase (blockPoint hdr) + forHuman (ChainDB.SetTentativeHeader hdr enclosing) = + case enclosing of + RisingEdge -> "About to set tentative header to " <> renderPointAsPhrase (blockPoint hdr) + FallingEdgeWith () -> "Set tentative header to " <> renderPointAsPhrase (blockPoint hdr) forHuman (ChainDB.TrapTentativeHeader hdr) = "Discovered trap tentative header " <> renderPointAsPhrase (blockPoint hdr) forHuman (ChainDB.OutdatedTentativeHeader hdr) = "Tentative header is now outdated " <> renderPointAsPhrase (blockPoint hdr) - forMachine dtals (ChainDB.SetTentativeHeader hdr) = - mconcat [ "kind" .= String "SetTentativeHeader" - , "block" .= renderPointForDetails dtals (blockPoint hdr) ] + forMachine dtals (ChainDB.SetTentativeHeader hdr enclosing) = + mconcat $ [ "kind" .= String "SetTentativeHeader" + , "block" .= renderPointForDetails dtals (blockPoint hdr) ] + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] forMachine dtals (ChainDB.TrapTentativeHeader hdr) = mconcat [ "kind" .= String "TrapTentativeHeader" , "block" .= renderPointForDetails dtals (blockPoint hdr) ] diff --git a/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs b/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs index 841667aef9b..7b03460b30a 100644 --- a/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs +++ b/cardano-node/src/Cardano/Node/Tracing/Tracers/Consensus.hs @@ -111,6 +111,7 @@ import Ouroboros.Consensus.MiniProtocol.LocalTxSubmission.Server import Ouroboros.Consensus.Node.Run (SerialiseNodeToNodeConstraints, estimateBlockSize) import Ouroboros.Consensus.Node.Tracers import qualified Ouroboros.Consensus.Protocol.Ledger.HotKey as HotKey +import Ouroboros.Consensus.Util.Enclose @@ -249,10 +250,10 @@ docChainSyncClientEvent' = Documented [ -------------------------------------------------------------------------------- severityChainSyncServerEvent :: TraceChainSyncServerEvent blk -> SeverityS -severityChainSyncServerEvent TraceChainSyncServerRead {} = Info -severityChainSyncServerEvent TraceChainSyncServerReadBlocked {} = Info -severityChainSyncServerEvent TraceChainSyncRollForward {} = Info -severityChainSyncServerEvent TraceChainSyncRollBackward {} = Info +severityChainSyncServerEvent (TraceChainSyncServerUpdate _tip _upd _blocking enclosing) = + case enclosing of + RisingEdge -> Info + FallingEdgeWith () -> Debug namesForChainSyncServerEvent :: TraceChainSyncServerEvent blk -> [Text] namesForChainSyncServerEvent ev = @@ -260,47 +261,39 @@ namesForChainSyncServerEvent ev = namesForChainSyncServerEvent' :: TraceChainSyncServerEvent blk -> [Text] -namesForChainSyncServerEvent' TraceChainSyncServerRead {} = +namesForChainSyncServerEvent' (TraceChainSyncServerUpdate _tip _update NonBlocking _enclosing) = ["ServerRead"] -namesForChainSyncServerEvent' TraceChainSyncServerReadBlocked {} = +namesForChainSyncServerEvent' (TraceChainSyncServerUpdate _tip _update Blocking _enclosing) = ["ServerReadBlocked"] -namesForChainSyncServerEvent' TraceChainSyncRollForward {} = - ["RollForward"] -namesForChainSyncServerEvent' TraceChainSyncRollBackward {} = - ["RollBackward"] instance ConvertRawHash blk => LogFormatting (TraceChainSyncServerEvent blk) where - forMachine _dtal (TraceChainSyncServerRead tip (AddBlock _hdr)) = - mconcat + forMachine _dtal (TraceChainSyncServerUpdate tip (AddBlock _hdr) NonBlocking enclosing) = + mconcat $ [ "kind" .= String "ChainSyncServerRead.AddBlock" , tipToObject tip ] - forMachine _dtal (TraceChainSyncServerRead tip (RollBack _pt)) = - mconcat + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] + forMachine _dtal (TraceChainSyncServerUpdate tip (RollBack _pt) NonBlocking enclosing) = + mconcat $ [ "kind" .= String "ChainSyncServerRead.RollBack" , tipToObject tip ] - forMachine _dtal (TraceChainSyncServerReadBlocked tip (AddBlock _hdr)) = - mconcat + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] + forMachine _dtal (TraceChainSyncServerUpdate tip (AddBlock _pt) Blocking enclosing) = + mconcat $ [ "kind" .= String "ChainSyncServerReadBlocked.AddBlock" , tipToObject tip ] - forMachine _dtal (TraceChainSyncServerReadBlocked tip (RollBack _pt)) = - mconcat + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] + forMachine _dtal (TraceChainSyncServerUpdate tip (RollBack _pt) Blocking enclosing) = + mconcat $ [ "kind" .= String "ChainSyncServerReadBlocked.RollBack" , tipToObject tip ] - forMachine dtal (TraceChainSyncRollForward point) = - mconcat [ "kind" .= String "ChainSyncServerRead.RollForward" - , "point" .= forMachine dtal point - ] - forMachine dtal (TraceChainSyncRollBackward point) = - mconcat [ "kind" .= String "ChainSyncServerRead.ChainSyncRollBackward" - , "point" .= forMachine dtal point - ] + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] - asMetrics (TraceChainSyncRollForward _point) = + asMetrics (TraceChainSyncServerUpdate _tip (AddBlock _hdr) _blocking FallingEdge) = [CounterM "cardano.node.chainSync.rollForward" Nothing] asMetrics _ = [] @@ -912,22 +905,24 @@ severityForge' :: TraceLabelCreds (TraceForgeEvent blk) -> SeverityS severityForge' (TraceLabelCreds _t e) = severityForge'' e severityForge'' :: TraceForgeEvent blk -> SeverityS -severityForge'' TraceStartLeadershipCheck {} = Info -severityForge'' TraceSlotIsImmutable {} = Error -severityForge'' TraceBlockFromFuture {} = Error -severityForge'' TraceBlockContext {} = Debug -severityForge'' TraceNoLedgerState {} = Error -severityForge'' TraceLedgerState {} = Debug -severityForge'' TraceNoLedgerView {} = Error -severityForge'' TraceLedgerView {} = Debug -severityForge'' TraceForgeStateUpdateError {} = Error -severityForge'' TraceNodeCannotForge {} = Error -severityForge'' TraceNodeNotLeader {} = Info -severityForge'' TraceNodeIsLeader {} = Info -severityForge'' TraceForgedBlock {} = Info -severityForge'' TraceDidntAdoptBlock {} = Error -severityForge'' TraceForgedInvalidBlock {} = Error -severityForge'' TraceAdoptedBlock {} = Info +severityForge'' TraceStartLeadershipCheck {} = Info +severityForge'' TraceSlotIsImmutable {} = Error +severityForge'' TraceBlockFromFuture {} = Error +severityForge'' TraceBlockContext {} = Debug +severityForge'' TraceNoLedgerState {} = Error +severityForge'' TraceLedgerState {} = Debug +severityForge'' TraceNoLedgerView {} = Error +severityForge'' TraceLedgerView {} = Debug +severityForge'' TraceForgeStateUpdateError {} = Error +severityForge'' TraceNodeCannotForge {} = Error +severityForge'' TraceNodeNotLeader {} = Info +severityForge'' TraceNodeIsLeader {} = Info +severityForge'' TraceForgeTickedLedgerState {} = Debug +severityForge'' TraceForgingMempoolSnapshot {} = Debug +severityForge'' TraceForgedBlock {} = Info +severityForge'' TraceDidntAdoptBlock {} = Error +severityForge'' TraceForgedInvalidBlock {} = Error +severityForge'' TraceAdoptedBlock {} = Info severityForge''' :: TraceLabelCreds TraceStartLeadershipCheckPlus -> SeverityS severityForge''' _ = Info @@ -940,22 +935,24 @@ namesForForge' :: TraceLabelCreds (TraceForgeEvent blk) -> [Text] namesForForge' (TraceLabelCreds _t e) = namesForForge'' e namesForForge'' :: TraceForgeEvent blk -> [Text] -namesForForge'' TraceStartLeadershipCheck {} = ["StartLeadershipCheck"] -namesForForge'' TraceSlotIsImmutable {} = ["SlotIsImmutable"] -namesForForge'' TraceBlockFromFuture {} = ["BlockFromFuture"] -namesForForge'' TraceBlockContext {} = ["BlockContext"] -namesForForge'' TraceNoLedgerState {} = ["NoLedgerState"] -namesForForge'' TraceLedgerState {} = ["LedgerState"] -namesForForge'' TraceNoLedgerView {} = ["NoLedgerView"] -namesForForge'' TraceLedgerView {} = ["LedgerView"] -namesForForge'' TraceForgeStateUpdateError {} = ["ForgeStateUpdateError"] -namesForForge'' TraceNodeCannotForge {} = ["NodeCannotForge"] -namesForForge'' TraceNodeNotLeader {} = ["NodeNotLeader"] -namesForForge'' TraceNodeIsLeader {} = ["NodeIsLeader"] -namesForForge'' TraceForgedBlock {} = ["ForgedBlock"] -namesForForge'' TraceDidntAdoptBlock {} = ["DidntAdoptBlock"] -namesForForge'' TraceForgedInvalidBlock {} = ["ForgedInvalidBlock"] -namesForForge'' TraceAdoptedBlock {} = ["AdoptedBlock"] +namesForForge'' TraceStartLeadershipCheck {} = ["StartLeadershipCheck"] +namesForForge'' TraceSlotIsImmutable {} = ["SlotIsImmutable"] +namesForForge'' TraceBlockFromFuture {} = ["BlockFromFuture"] +namesForForge'' TraceBlockContext {} = ["BlockContext"] +namesForForge'' TraceNoLedgerState {} = ["NoLedgerState"] +namesForForge'' TraceLedgerState {} = ["LedgerState"] +namesForForge'' TraceNoLedgerView {} = ["NoLedgerView"] +namesForForge'' TraceLedgerView {} = ["LedgerView"] +namesForForge'' TraceForgeStateUpdateError {} = ["ForgeStateUpdateError"] +namesForForge'' TraceNodeCannotForge {} = ["NodeCannotForge"] +namesForForge'' TraceNodeNotLeader {} = ["NodeNotLeader"] +namesForForge'' TraceNodeIsLeader {} = ["NodeIsLeader"] +namesForForge'' TraceForgeTickedLedgerState {} = ["ForgeTickedLedgerState"] +namesForForge'' TraceForgingMempoolSnapshot {} = ["ForgingMempoolSnapshot"] +namesForForge'' TraceForgedBlock {} = ["ForgedBlock"] +namesForForge'' TraceDidntAdoptBlock {} = ["DidntAdoptBlock"] +namesForForge'' TraceForgedInvalidBlock {} = ["ForgedInvalidBlock"] +namesForForge'' TraceAdoptedBlock {} = ["AdoptedBlock"] namesForForge''' :: TraceLabelCreds TraceStartLeadershipCheckPlus -> [Text] namesForForge''' (TraceLabelCreds _ TraceStartLeadershipCheckPlus {}) = @@ -1045,6 +1042,20 @@ instance ( tx ~ GenTx blk [ "kind" .= String "TraceNodeIsLeader" , "slot" .= toJSON (unSlotNo slotNo) ] + forMachine dtal (TraceForgeTickedLedgerState slotNo prevPt) = + mconcat + [ "kind" .= String "TraceForgeTickedLedgerState" + , "slot" .= toJSON (unSlotNo slotNo) + , "prev" .= renderPointForDetails dtal prevPt + ] + forMachine dtal (TraceForgingMempoolSnapshot slotNo prevPt mpHash mpSlot) = + mconcat + [ "kind" .= String "TraceForgingMempoolSnapshot" + , "slot" .= toJSON (unSlotNo slotNo) + , "prev" .= renderPointForDetails dtal prevPt + , "mempoolHash" .= String (renderChainHash @blk (renderHeaderHash (Proxy @blk)) mpHash) + , "mempoolSlot" .= toJSON (unSlotNo mpSlot) + ] forMachine _dtal (TraceForgedBlock slotNo _ blk _) = mconcat [ "kind" .= String "TraceForgedBlock" @@ -1133,6 +1144,20 @@ instance ( tx ~ GenTx blk "Not leading slot " <> showT (unSlotNo slotNo) forHuman (TraceNodeIsLeader slotNo) = "Leading slot " <> showT (unSlotNo slotNo) + forHuman (TraceForgeTickedLedgerState slotNo prevPt) = + "While forging in slot " + <> showT (unSlotNo slotNo) + <> " we ticked the ledger state ahead from " + <> renderPointAsPhrase prevPt + forHuman (TraceForgingMempoolSnapshot slotNo prevPt mpHash mpSlot) = + "While forging in slot " + <> showT (unSlotNo slotNo) + <> " we acquired a mempool snapshot valid against " + <> renderPointAsPhrase prevPt + <> " from a mempool that was prepared for " + <> renderChainHash @blk (renderHeaderHash (Proxy @blk)) mpHash + <> " ticked to slot " + <> showT (unSlotNo mpSlot) forHuman (TraceForgedBlock slotNo _ _ _) = "Forged block in slot " <> showT (unSlotNo slotNo) forHuman (TraceDidntAdoptBlock slotNo _) = @@ -1189,6 +1214,8 @@ instance ( tx ~ GenTx blk [IntM "cardano.node.nodeNotLeader" (fromIntegral $ unSlotNo slot)] asMetrics (TraceNodeIsLeader slot) = [IntM "cardano.node.nodeIsLeader" (fromIntegral $ unSlotNo slot)] + asMetrics TraceForgeTickedLedgerState {} = [] + asMetrics TraceForgingMempoolSnapshot {} = [] asMetrics (TraceForgedBlock slot _ _ _) = [IntM "cardano.node.forgedSlotLast" (fromIntegral $ unSlotNo slot)] asMetrics (TraceDidntAdoptBlock slot _) = diff --git a/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs b/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs index 8179454976f..59e91cff967 100644 --- a/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs +++ b/cardano-node/src/Cardano/Tracing/OrphanInstances/Consensus.hs @@ -46,7 +46,8 @@ import Ouroboros.Consensus.Mempool.API (MempoolSize (..), TraceEventMe import Ouroboros.Consensus.MiniProtocol.BlockFetch.Server (TraceBlockFetchServerEvent (..)) import Ouroboros.Consensus.MiniProtocol.ChainSync.Client (TraceChainSyncClientEvent (..)) -import Ouroboros.Consensus.MiniProtocol.ChainSync.Server (TraceChainSyncServerEvent (..)) +import Ouroboros.Consensus.MiniProtocol.ChainSync.Server + (BlockingType (..), TraceChainSyncServerEvent (..)) import Ouroboros.Consensus.MiniProtocol.LocalTxSubmission.Server (TraceLocalTxSubmissionServerEvent (..)) import Ouroboros.Consensus.Node.Run (RunNode, estimateBlockSize) @@ -63,6 +64,7 @@ import qualified Ouroboros.Consensus.Storage.VolatileDB.Impl as VolDb import Ouroboros.Network.BlockFetch.ClientState (TraceLabelPeer (..)) import Ouroboros.Consensus.Util.Condense +import Ouroboros.Consensus.Util.Enclose import Ouroboros.Consensus.Util.Orphans () import qualified Ouroboros.Network.AnchoredFragment as AF @@ -98,11 +100,13 @@ instance HasSeverityAnnotation (ChainDB.TraceEvent blk) where ChainDB.IgnoreBlockAlreadyInVolatileDB {} -> Info ChainDB.IgnoreInvalidBlock {} -> Info ChainDB.AddedBlockToQueue {} -> Debug + ChainDB.PoppedBlockFromQueue {} -> Debug ChainDB.BlockInTheFuture {} -> Info ChainDB.AddedBlockToVolatileDB {} -> Debug ChainDB.TryAddToCurrentChain {} -> Debug ChainDB.TrySwitchToAFork {} -> Info ChainDB.StoreButDontChange {} -> Debug + ChainDB.ChangingSelection {} -> Debug ChainDB.AddedToCurrentChain events _ _ _ -> maximumDef Notice (map getSeverityAnnotation events) ChainDB.SwitchedToAFork events _ _ _ -> @@ -241,6 +245,8 @@ instance HasSeverityAnnotation (TraceForgeEvent blk) where getSeverityAnnotation TraceNodeCannotForge {} = Error getSeverityAnnotation TraceNodeNotLeader {} = Info getSeverityAnnotation TraceNodeIsLeader {} = Info + getSeverityAnnotation TraceForgeTickedLedgerState {} = Debug + getSeverityAnnotation TraceForgingMempoolSnapshot {} = Debug getSeverityAnnotation TraceForgedBlock {} = Info getSeverityAnnotation TraceDidntAdoptBlock {} = Error getSeverityAnnotation TraceForgedInvalidBlock {} = Error @@ -371,6 +377,20 @@ instance ( tx ~ GenTx blk "Not leading slot " <> showT (unSlotNo slotNo) TraceNodeIsLeader slotNo -> const $ "Leading slot " <> showT (unSlotNo slotNo) + TraceForgeTickedLedgerState slotNo prevPt -> const $ + "While forging in slot " + <> showT (unSlotNo slotNo) + <> " we ticked the ledger state ahead from " + <> renderPointAsPhrase prevPt + TraceForgingMempoolSnapshot slotNo prevPt mpHash mpSlot -> const $ + "While forging in slot " + <> showT (unSlotNo slotNo) + <> " we acquired a mempool snapshot valid against " + <> renderPointAsPhrase prevPt + <> " from a mempool that was prepared for " + <> renderChainHash (Text.decodeLatin1 . toRawHash (Proxy @blk)) mpHash + <> " ticked to slot " + <> showT (unSlotNo mpSlot) TraceForgedBlock slotNo _ _ _ -> const $ "Forged block in slot " <> showT (unSlotNo slotNo) TraceDidntAdoptBlock slotNo _ -> const $ @@ -423,8 +443,18 @@ instance ( ConvertRawHash blk "Ignoring block already in DB: " <> renderRealPointAsPhrase pt ChainDB.IgnoreInvalidBlock pt _reason -> "Ignoring previously seen invalid block: " <> renderRealPointAsPhrase pt - ChainDB.AddedBlockToQueue pt sz -> - "Block added to queue: " <> renderRealPointAsPhrase pt <> " queue size " <> condenseT sz + ChainDB.AddedBlockToQueue pt edgeSz -> + case edgeSz of + RisingEdge -> + "About to add block to queue: " <> renderRealPointAsPhrase pt + FallingEdgeWith sz -> + "Block added to queue: " <> renderRealPointAsPhrase pt <> " queue size " <> condenseT sz + ChainDB.PoppedBlockFromQueue edgePt -> + case edgePt of + RisingEdge -> + "Popping block from queue" + FallingEdgeWith pt -> + "Popped block from queue: " <> renderRealPointAsPhrase pt ChainDB.BlockInTheFuture pt slot -> "Ignoring block from future: " <> renderRealPointAsPhrase pt <> ", slot " <> condenseT slot ChainDB.StoreButDontChange pt -> @@ -433,6 +463,8 @@ instance ( ConvertRawHash blk "Block fits onto the current chain: " <> renderRealPointAsPhrase pt ChainDB.TrySwitchToAFork pt _ -> "Block fits onto some fork: " <> renderRealPointAsPhrase pt + ChainDB.ChangingSelection pt -> + "Changing selection to: " <> renderPointAsPhrase pt ChainDB.AddedToCurrentChain es _ _ c -> "Chain extended, new tip: " <> renderPointAsPhrase (AF.headPoint c) <> Text.concat [ "\nEvent: " <> showT e | e <- es ] @@ -461,12 +493,15 @@ instance ( ConvertRawHash blk in "Pushing ledger state for block " <> renderRealPointAsPhrase curr <> ". Progress: " <> showProgressT (fromIntegral atDiff) (fromIntegral toDiff) <> "%" - ChainDB.AddedBlockToVolatileDB pt _ _ -> - "Chain added block " <> renderRealPointAsPhrase pt + ChainDB.AddedBlockToVolatileDB pt _ _ enclosing -> case enclosing of + RisingEdge -> "Chain about to add block " <> renderRealPointAsPhrase pt + FallingEdgeWith () -> "Chain added block " <> renderRealPointAsPhrase pt ChainDB.ChainSelectionForFutureBlock pt -> "Chain selection run for block previously from future: " <> renderRealPointAsPhrase pt ChainDB.PipeliningEvent ev' -> case ev' of - ChainDB.SetTentativeHeader hdr -> "Set tentative header to " <> renderPointAsPhrase (blockPoint hdr) + ChainDB.SetTentativeHeader hdr enclosing -> case enclosing of + RisingEdge -> "About to set tentative header to " <> renderPointAsPhrase (blockPoint hdr) + FallingEdgeWith () -> "Set tentative header to " <> renderPointAsPhrase (blockPoint hdr) ChainDB.TrapTentativeHeader hdr -> "Discovered trap tentative header " <> renderPointAsPhrase (blockPoint hdr) ChainDB.OutdatedTentativeHeader hdr -> "Tentative header is now outdated" <> renderPointAsPhrase (blockPoint hdr) @@ -790,10 +825,13 @@ instance ( ConvertRawHash blk mconcat [ "kind" .= String "TraceAddBlockEvent.IgnoreInvalidBlock" , "block" .= toObject verb pt , "reason" .= show reason ] - ChainDB.AddedBlockToQueue pt sz -> + ChainDB.AddedBlockToQueue pt edgeSz -> mconcat [ "kind" .= String "TraceAddBlockEvent.AddedBlockToQueue" , "block" .= toObject verb pt - , "queueSize" .= toJSON sz ] + , case edgeSz of RisingEdge -> "risingEdge" .= True; FallingEdgeWith sz -> "queueSize" .= toJSON sz ] + ChainDB.PoppedBlockFromQueue edgePt -> + mconcat [ "kind" .= String "TraceAddBlockEvent.PoppedBlockFromQueue" + , case edgePt of RisingEdge -> "risingEdge" .= True; FallingEdgeWith pt -> "block" .= toObject verb pt ] ChainDB.BlockInTheFuture pt slot -> mconcat [ "kind" .= String "TraceAddBlockEvent.BlockInTheFuture" , "block" .= toObject verb pt @@ -807,6 +845,9 @@ instance ( ConvertRawHash blk ChainDB.TrySwitchToAFork pt _ -> mconcat [ "kind" .= String "TraceAddBlockEvent.TrySwitchToAFork" , "block" .= toObject verb pt ] + ChainDB.ChangingSelection pt -> + mconcat [ "kind" .= String "TraceAddBlockEvent.ChangingSelection" + , "block" .= toObject verb pt ] ChainDB.AddedToCurrentChain events _ base extended -> mconcat $ [ "kind" .= String "TraceAddBlockEvent.AddedToCurrentChain" @@ -852,18 +893,20 @@ instance ( ConvertRawHash blk , "targetBlock" .= renderRealPoint goal ] - ChainDB.AddedBlockToVolatileDB pt (BlockNo bn) _ -> - mconcat [ "kind" .= String "TraceAddBlockEvent.AddedBlockToVolatileDB" - , "block" .= toObject verb pt - , "blockNo" .= show bn ] + ChainDB.AddedBlockToVolatileDB pt (BlockNo bn) _isEBB enclosing -> + mconcat $ [ "kind" .= String "TraceAddBlockEvent.AddedBlockToVolatileDB" + , "block" .= toObject verb pt + , "blockNo" .= show bn ] + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] ChainDB.ChainSelectionForFutureBlock pt -> mconcat [ "kind" .= String "TraceAddBlockEvent.ChainSelectionForFutureBlock" , "block" .= toObject verb pt ] ChainDB.PipeliningEvent ev' -> case ev' of - ChainDB.SetTentativeHeader hdr -> - mconcat [ "kind" .= String "TraceAddBlockEvent.PipeliningEvent.SetTentativeHeader" - , "block" .= renderPointForVerbosity verb (blockPoint hdr) - ] + ChainDB.SetTentativeHeader hdr enclosing -> + mconcat $ [ "kind" .= String "TraceAddBlockEvent.PipeliningEvent.SetTentativeHeader" + , "block" .= renderPointForVerbosity verb (blockPoint hdr) + ] + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] ChainDB.TrapTentativeHeader hdr -> mconcat [ "kind" .= String "TraceAddBlockEvent.PipeliningEvent.TrapTentativeHeader" , "block" .= renderPointForVerbosity verb (blockPoint hdr) @@ -1196,36 +1239,31 @@ instance (ConvertRawHash blk, LedgerSupportsProtocol blk) instance ConvertRawHash blk => ToObject (TraceChainSyncServerEvent blk) where - toObject verb ev = case ev of - TraceChainSyncServerRead tip AddBlock{} -> - mconcat + toObject _verb ev = case ev of + TraceChainSyncServerUpdate tip AddBlock{} NonBlocking enclosing -> + mconcat $ [ "kind" .= String "ChainSyncServerEvent.TraceChainSyncServerRead.AddBlock" , tipToObject tip ] - TraceChainSyncServerRead tip RollBack{} -> - mconcat + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] + TraceChainSyncServerUpdate tip RollBack{} NonBlocking enclosing -> + mconcat $ [ "kind" .= String "ChainSyncServerEvent.TraceChainSyncServerRead.RollBack" , tipToObject tip ] - TraceChainSyncServerReadBlocked tip AddBlock{} -> - mconcat + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] + TraceChainSyncServerUpdate tip AddBlock{} Blocking enclosing -> + mconcat $ [ "kind" .= String "ChainSyncServerEvent.TraceChainSyncServerReadBlocked.AddBlock" , tipToObject tip ] - TraceChainSyncServerReadBlocked tip RollBack{} -> - mconcat + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] + TraceChainSyncServerUpdate tip RollBack{} Blocking enclosing -> + mconcat $ [ "kind" .= String "ChainSyncServerEvent.TraceChainSyncServerReadBlocked.RollBack" , tipToObject tip ] - - TraceChainSyncRollForward point -> - mconcat [ "kind" .= String "ChainSyncServerEvent.TraceChainSyncRollForward" - , "point" .= toObject verb point - ] - TraceChainSyncRollBackward point -> - mconcat [ "kind" .= String "ChainSyncServerEvent.TraceChainSyncRollBackward" - , "point" .= toObject verb point - ] + <> [ "risingEdge" .= True | RisingEdge <- [enclosing] ] instance ( Show (ApplyTxErr blk), ToObject (ApplyTxErr blk), ToObject (GenTx blk), ToJSON (GenTxId blk), LedgerSupportsMempool blk @@ -1349,6 +1387,20 @@ instance ( tx ~ GenTx blk [ "kind" .= String "TraceNodeIsLeader" , "slot" .= toJSON (unSlotNo slotNo) ] + toObject verb (TraceForgeTickedLedgerState slotNo prevPt) = + mconcat + [ "kind" .= String "TraceForgeTickedLedgerState" + , "slot" .= toJSON (unSlotNo slotNo) + , "prev" .= renderPointForVerbosity verb prevPt + ] + toObject verb (TraceForgingMempoolSnapshot slotNo prevPt mpHash mpSlot) = + mconcat + [ "kind" .= String "TraceForgingMempoolSnapshot" + , "slot" .= toJSON (unSlotNo slotNo) + , "prev" .= renderPointForVerbosity verb prevPt + , "mempoolHash" .= String (renderChainHash @blk (renderHeaderHash (Proxy @blk)) mpHash) + , "mempoolSlot" .= toJSON (unSlotNo mpSlot) + ] toObject _verb (TraceForgedBlock slotNo _ blk _) = mconcat [ "kind" .= String "TraceForgedBlock" diff --git a/cardano-node/src/Cardano/Tracing/Tracers.hs b/cardano-node/src/Cardano/Tracing/Tracers.hs index 9260e1d8b69..7808119790e 100644 --- a/cardano-node/src/Cardano/Tracing/Tracers.hs +++ b/cardano-node/src/Cardano/Tracing/Tracers.hs @@ -76,10 +76,11 @@ import qualified Ouroboros.Consensus.Node.Run as Consensus (RunNode) import qualified Ouroboros.Consensus.Node.Tracers as Consensus import Ouroboros.Consensus.Protocol.Abstract (ValidationErr) import qualified Ouroboros.Consensus.Protocol.Ledger.HotKey as HotKey +import Ouroboros.Consensus.Util.Enclose import qualified Ouroboros.Network.AnchoredFragment as AF -import Ouroboros.Network.Block (BlockNo (..), HasHeader (..), Point, StandardHash, - blockNo, pointSlot, unBlockNo) +import Ouroboros.Network.Block (BlockNo (..), ChainUpdate (..), + HasHeader (..), Point, StandardHash, blockNo, pointSlot, unBlockNo) import Ouroboros.Network.BlockFetch.ClientState (TraceFetchClientState (..), TraceLabelPeer (..)) import Ouroboros.Network.BlockFetch.Decision (FetchDecision, FetchDecline (..)) @@ -609,7 +610,7 @@ sendEKGDirectDouble ekgDirect name val = do -------------------------------------------------------------------------------- isRollForward :: TraceChainSyncServerEvent blk -> Bool -isRollForward (TraceChainSyncRollForward _) = True +isRollForward (TraceChainSyncServerUpdate _tip (AddBlock _hdr) _blocking FallingEdge) = True isRollForward _ = False mkConsensusTracers @@ -983,6 +984,8 @@ teeForge ft tverb tr = Tracer $ Consensus.TraceNodeCannotForge {} -> teeForge' (ftTraceNodeCannotForge ft) Consensus.TraceNodeNotLeader{} -> teeForge' (ftTraceNodeNotLeader ft) Consensus.TraceNodeIsLeader{} -> teeForge' (ftTraceNodeIsLeader ft) + Consensus.TraceForgeTickedLedgerState{} -> nullTracer + Consensus.TraceForgingMempoolSnapshot{} -> nullTracer Consensus.TraceForgedBlock{} -> teeForge' (ftForged ft) Consensus.TraceDidntAdoptBlock{} -> teeForge' (ftDidntAdoptBlock ft) Consensus.TraceForgedInvalidBlock{} -> teeForge' (ftForgedInvalid ft) @@ -1023,6 +1026,10 @@ teeForge' tr = LogValue "nodeNotLeader" $ PureI $ fromIntegral $ unSlotNo slot Consensus.TraceNodeIsLeader slot -> LogValue "nodeIsLeader" $ PureI $ fromIntegral $ unSlotNo slot + Consensus.TraceForgeTickedLedgerState slot _prevPt -> + LogValue "forgeTickedLedgerState" $ PureI $ fromIntegral $ unSlotNo slot + Consensus.TraceForgingMempoolSnapshot slot _prevPt _mpHash _mpSlotNo -> + LogValue "forgingMempoolSnapshot" $ PureI $ fromIntegral $ unSlotNo slot Consensus.TraceForgedBlock slot _ _ _ -> LogValue "forgedSlotLast" $ PureI $ fromIntegral $ unSlotNo slot Consensus.TraceDidntAdoptBlock slot _ ->