From 0ff764773130c39eeb019e781991d410dca2899c Mon Sep 17 00:00:00 2001 From: Marcin Szamotulski Date: Mon, 22 Nov 2021 14:08:39 +0100 Subject: [PATCH] Added StartupTracer Use a standard Tracer to log information when node starts. --- cardano-node/cardano-node.cabal | 1 + cardano-node/src/Cardano/Node/Run.hs | 137 +++++------- cardano-node/src/Cardano/Tracing/Startup.hs | 234 ++++++++++++++++++++ cardano-node/src/Cardano/Tracing/Tracers.hs | 8 + 4 files changed, 296 insertions(+), 84 deletions(-) create mode 100644 cardano-node/src/Cardano/Tracing/Startup.hs diff --git a/cardano-node/cardano-node.cabal b/cardano-node/cardano-node.cabal index aa422ca26f9..828a28bae3d 100644 --- a/cardano-node/cardano-node.cabal +++ b/cardano-node/cardano-node.cabal @@ -84,6 +84,7 @@ library Cardano.Tracing.Peer Cardano.Tracing.Queries Cardano.Tracing.Render + Cardano.Tracing.Startup Cardano.Tracing.Tracers Cardano.Tracing.OrphanInstances.Byron Cardano.Tracing.OrphanInstances.Common diff --git a/cardano-node/src/Cardano/Node/Run.hs b/cardano-node/src/Cardano/Node/Run.hs index 64062f51765..964d1d1fe48 100644 --- a/cardano-node/src/Cardano/Node/Run.hs +++ b/cardano-node/src/Cardano/Node/Run.hs @@ -17,7 +17,7 @@ module Cardano.Node.Run ) where import Cardano.Prelude hiding (ByteString, atomically, take, trace, STM) -import Prelude (String) +import Prelude (String, id) import Data.IP (toSockAddr) import qualified Control.Concurrent.Async as Async @@ -43,8 +43,7 @@ import qualified System.Posix.Signals as Signals import System.Win32.File #endif -import Cardano.BM.Data.LogItem (LOContent (..), LogObject (..), PrivacyAnnotation (..), - mkLOMeta, LOMeta) +import Cardano.BM.Data.LogItem (LogObject (..)) import Cardano.BM.Data.Tracer (ToLogObject (..), TracingVerbosity (..)) import Cardano.BM.Data.Transformers (setHostname) import Cardano.BM.Trace @@ -52,7 +51,7 @@ import Paths_cardano_node (version) import qualified Cardano.Crypto.Libsodium as Crypto -import Cardano.Node.Configuration.Logging (LoggingLayer (..), Severity (..), +import Cardano.Node.Configuration.Logging (LoggingLayer (..), createLoggingLayer, nodeBasicInfo, shutdownLoggingLayer) import Cardano.Node.Configuration.POM (NodeConfiguration (..), PartialNodeConfiguration (..), SomeNetworkP2PMode (..), @@ -62,9 +61,9 @@ import Cardano.Node.Types import Cardano.Tracing.Config (TraceOptions (..), TraceSelection (..)) import Cardano.Tracing.Constraints (TraceConstraints) import Cardano.Tracing.Metrics (HasKESInfo (..), HasKESMetricsData (..)) +import Cardano.Tracing.Startup import qualified Ouroboros.Consensus.Config as Consensus -import Ouroboros.Consensus.Config.SupportsNode (ConfigSupportsNode (..), getNetworkMagic) import Ouroboros.Consensus.Node (RunNode, RunNodeArgs (..) , StdRunNodeArgs (..), NetworkP2PMode (..)) import qualified Ouroboros.Consensus.Node as Node (getChainDB, run) @@ -88,7 +87,7 @@ import Cardano.Api import qualified Cardano.Api.Protocol.Types as Protocol import Cardano.Node.Configuration.Socket (SocketOrSocketInfo (..), - gatherConfiguredSockets, getSocketOrSocketInfoAddr, renderSocketConfigError) + gatherConfiguredSockets, getSocketOrSocketInfoAddr) import qualified Cardano.Node.Configuration.TopologyP2P as TopologyP2P import Cardano.Node.Configuration.TopologyP2P import qualified Cardano.Node.Configuration.Topology as TopologyNonP2P @@ -239,8 +238,7 @@ handleSimpleNode -- otherwise the node won't actually start. -> IO () handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do - meta <- mkLOMeta Notice Public - logP2PWarning meta + logStartupWarnings let pInfo = Protocol.protocolInfo runP tracer = toLogObject trace @@ -252,9 +250,8 @@ handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do case result of Right triplet -> return triplet Left error -> do - traceNamedObject - (appendName "error" trace) - (meta, LogMessage (Text.pack (renderSocketConfigError error))) + traceWith (startupTracer nodeTracers) + $ StartupSocketConfigError error throwIO error dbPath <- canonDbPath nc @@ -290,22 +287,17 @@ handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do ipv4 <- traverse getSocketOrSocketInfoAddr publicIPv4SocketOrAddr ipv6 <- traverse getSocketOrSocketInfoAddr publicIPv6SocketOrAddr - traceNamedObject - (appendName "addresses" trace) - (meta, LogMessage . Text.pack . show $ catMaybes [ipv4, ipv6]) - traceNamedObject - (appendName "diffusion-mode" trace) - (meta, LogMessage . Text.pack . show . ncDiffusionMode $ nc) - traceNamedObject - (appendName "local-socket" trace) - (meta, LogMessage . Text.pack . show $ localSocketOrPath) - traceNamedObject - (appendName "node-to-node-versions" trace) - (meta, LogMessage . Text.pack . show . supportedNodeToNodeVersions $ Proxy @blk) - traceNamedObject - (appendName "node-to-client-versions" trace) - (meta, LogMessage . Text.pack . show . supportedNodeToClientVersions $ Proxy @blk) - + traceWith (startupTracer nodeTracers) + (StartupInfo (catMaybes [ipv4, ipv6]) + localSocketOrPath + ( limitToLatestReleasedVersion fst + . supportedNodeToNodeVersions + $ Proxy @blk + ) + ( limitToLatestReleasedVersion snd + . supportedNodeToClientVersions + $ Proxy @blk + )) withShutdownHandling nc trace $ \sfds -> let nodeArgs = RunNodeArgs @@ -321,31 +313,22 @@ handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do } in case p2pMode of EnabledP2PMode -> do + traceWith (startupTracer nodeTracers) + (StartupP2PInfo (ncDiffusionMode nc)) nt <- TopologyP2P.readTopologyFileOrError nc let (localRoots, publicRoots) = producerAddresses nt - traceNamedObject - (appendName "topology-file" trace) - (meta, LogMessage (Text.pack "Successfully read topology configuration file")) - traceNamedObject - (appendName "local-roots" trace) - (meta, LogMessage . Text.pack . show $ localRoots) - traceNamedObject - (appendName "public-roots" trace) - (meta, LogMessage . Text.pack . show $ publicRoots) - traceNamedObject - (appendName "use-ledger-after-slot" trace) - (meta, LogMessage . Text.pack . show $ useLedgerAfterSlot nt) + traceWith (startupTracer nodeTracers) + $ NetworkConfig localRoots + publicRoots + (useLedgerAfterSlot nt) (localRootsVar :: StrictTVar IO [(Int, Map RelayAccessPoint PeerAdvertise)]) <- newTVarIO localRoots publicRootsVar <- newTVarIO publicRoots useLedgerVar <- newTVarIO (useLedgerAfterSlot nt) #ifdef UNIX _ <- Signals.installHandler Signals.sigHUP - (updateTopologyConfiguration meta localRootsVar publicRootsVar useLedgerVar) + (updateTopologyConfiguration localRootsVar publicRootsVar useLedgerVar) Nothing - traceNamedObject - (appendName "signal-handler" trace) - (meta, LogMessage (Text.pack "Installed signal handler")) #endif void $ Node.run @@ -400,17 +383,15 @@ handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do , srnMaybeMempoolCapacityOverride = ncMaybeMempoolCapacityOverride nc } where - logP2PWarning :: LOMeta -> IO () - logP2PWarning meta = + logStartupWarnings :: IO () + logStartupWarnings = case p2pMode of DisabledP2PMode -> return () - EnabledP2PMode -> - traceNamedObject - (appendName "p2p-mode" trace) - (meta, LogMessage $ Text.pack - ( "P2P MODE: unsupported and unverified version of " - <> "`cardano-node` which enables p2p networking" - )) + EnabledP2PMode -> do + traceWith (startupTracer nodeTracers) P2PWarning + when (not $ ncTestEnableDevelopmentNetworkProtocols nc) + $ traceWith (startupTracer nodeTracers) + P2PWarningDevelopementNetworkProtocols createTracers :: NodeConfiguration @@ -419,12 +400,6 @@ handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do -> IO () createTracers NodeConfiguration { ncValidateDB } tr tracer = do - let ProtocolInfo{ pInfoConfig = cfg } = Protocol.protocolInfo runP - - meta <- mkLOMeta Notice Public - traceNamedObject (appendName "networkMagic" tr) - (meta, LogMessage ("NetworkMagic " <> show (unNetworkMagic . getNetworkMagic $ Consensus.configBlock cfg))) - startTime <- getCurrentTime traceNodeBasicInfo tr =<< nodeBasicInfo nc scp startTime traceCounter "nodeStartTime" tr (ceiling $ utcTimeToPOSIXSeconds startTime) @@ -437,47 +412,41 @@ handleSimpleNode scp runP p2pMode trace nodeTracers nc onKernel = do traceNamedObject (appendName nm tr) (mt, content) #ifdef UNIX - updateTopologyConfiguration :: LOMeta - -> StrictTVar IO [(Int, Map RelayAccessPoint PeerAdvertise)] + updateTopologyConfiguration :: StrictTVar IO [(Int, Map RelayAccessPoint PeerAdvertise)] -> StrictTVar IO [RelayAccessPoint] -> StrictTVar IO UseLedgerAfter -> Signals.Handler - updateTopologyConfiguration meta localRootsVar publicRootsVar useLedgerVar = + updateTopologyConfiguration localRootsVar publicRootsVar useLedgerVar = Signals.Catch $ do - traceNamedObject - (appendName "signal-handler" trace) - (meta, LogMessage (Text.pack "SIGHUP signal received - Performing topology configuration update")) - + traceWith (startupTracer nodeTracers) NetworkConfigUpdate result <- try $ readTopologyFileOrError nc - case result of Left (FatalError err) -> - traceNamedObject - (appendName "topology-file" trace) - (meta, LogMessage (Text.pack "Error reading topology configuration file:" <> err)) + traceWith (startupTracer nodeTracers) + $ NetworkConfigUpdateError + $ pack "Error reading topology configuration file:" <> err Right nt -> do - traceNamedObject - (appendName "topology-file" trace) - (meta, LogMessage (Text.pack "Successfully read topology configuration file")) - let (localRoots, publicRoots) = producerAddresses nt - + traceWith (startupTracer nodeTracers) + $ NetworkConfig localRoots publicRoots (useLedgerAfterSlot nt) atomically $ do writeTVar localRootsVar localRoots writeTVar publicRootsVar publicRoots writeTVar useLedgerVar (useLedgerAfterSlot nt) - - traceNamedObject - (appendName "local-roots" trace) - (meta, LogMessage . Text.pack . show $ localRoots) - traceNamedObject - (appendName "public-roots" trace) - (meta, LogMessage . Text.pack . show $ publicRoots) - traceNamedObject - (appendName "use-ledger-after-slot" trace) - (meta, LogMessage . Text.pack . show $ useLedgerAfterSlot nt) #endif + limitToLatestReleasedVersion :: forall k v. + Ord k + => ((Maybe NodeToNodeVersion, Maybe NodeToClientVersion) -> Maybe k) + -> Map k v + -> Map k v + limitToLatestReleasedVersion prj = + if ncTestEnableDevelopmentNetworkProtocols nc then id + else + case prj $ latestReleasedNodeVersion (Proxy @blk) of + Nothing -> id + Just version_ -> Map.takeWhileAntitone (<= version_) + -------------------------------------------------------------------------------- -- Helper functions -------------------------------------------------------------------------------- diff --git a/cardano-node/src/Cardano/Tracing/Startup.hs b/cardano-node/src/Cardano/Tracing/Startup.hs new file mode 100644 index 00000000000..2ad42ec204f --- /dev/null +++ b/cardano-node/src/Cardano/Tracing/Startup.hs @@ -0,0 +1,234 @@ +{-# LANGUAGE FlexibleContexts #-} +{-# LANGUAGE MultiParamTypeClasses #-} +{-# LANGUAGE UndecidableInstances #-} + +module Cardano.Tracing.Startup where + +import Prelude + +import Data.Aeson (Value (..), (.=)) +import qualified Data.Aeson as Aeson +import Data.List (intercalate) +import Data.Map (Map) +import qualified Data.Map as Map +import Data.Text (Text) +import qualified Data.Text as Text + +import Cardano.Slotting.Slot (SlotNo (..)) +import Cardano.Node.Configuration.TopologyP2P (UseLedger (..)) +import Cardano.Node.Configuration.Socket +import Cardano.Tracing.OrphanInstances.Network () + +import Cardano.BM.Tracing (HasPrivacyAnnotation (..), + HasSeverityAnnotation (..), Severity (..), ToObject (..), + Transformable (..)) +import Cardano.BM.Data.Tracer (HasTextFormatter (..), mkObject, + trStructuredText) + +import Ouroboros.Consensus.Node.NetworkProtocolVersion + (BlockNodeToClientVersion, BlockNodeToNodeVersion) + +import Ouroboros.Network.Magic (NetworkMagic (..)) +import Ouroboros.Network.NodeToClient (LocalAddress (..), + LocalSocket, NodeToClientVersion) +import Ouroboros.Network.NodeToNode (DiffusionMode (..), + NodeToNodeVersion) +import Ouroboros.Network.PeerSelection.LedgerPeers (UseLedgerAfter (..)) +import Ouroboros.Network.PeerSelection.Types (PeerAdvertise) +import Ouroboros.Network.PeerSelection.RelayAccessPoint (RelayAccessPoint) + +import qualified Network.Socket as Socket + + +data StartupTrace blk = + -- | Log startup information. + -- + StartupInfo + [SocketOrSocketInfo Socket.SockAddr Socket.SockAddr] + -- ^ node-to-node addresses + (Maybe (SocketOrSocketInfo LocalSocket LocalAddress)) + -- ^ node-to-client socket path + (Map NodeToNodeVersion (BlockNodeToNodeVersion blk)) + -- ^ supported node-to-node versions + (Map NodeToClientVersion (BlockNodeToClientVersion blk)) + -- ^ supported node-to-client versions + + -- | Log peer-to-peer diffusion mode + | StartupP2PInfo DiffusionMode + + | StartupNetworkMagic NetworkMagic + + | StartupSocketConfigError SocketConfigError + + + -- | Log that the network configuration is being updated. + -- + | NetworkConfigUpdate + + -- | Log network configuration update error. + -- + | NetworkConfigUpdateError Text + + -- | Log peer-to-peer network configuration, either on startup or when its + -- updated. + -- + | NetworkConfig [(Int, Map RelayAccessPoint PeerAdvertise)] + [RelayAccessPoint] + UseLedgerAfter + + -- | Warn when 'EnableP2P' is set. + | P2PWarning + + -- | Warn that peer-to-peer requires + -- 'TestEnableDevelopmentNetworkProtocols' to be set. + -- + | P2PWarningDevelopementNetworkProtocols + + +instance HasSeverityAnnotation (StartupTrace blk) where + getSeverityAnnotation (StartupSocketConfigError _) = Error + getSeverityAnnotation (NetworkConfigUpdateError _) = Error + getSeverityAnnotation P2PWarning = Warning + getSeverityAnnotation P2PWarningDevelopementNetworkProtocols = Warning + getSeverityAnnotation _ = Info +instance HasPrivacyAnnotation (StartupTrace blk) where +instance ( Show (BlockNodeToNodeVersion blk) + , Show (BlockNodeToClientVersion blk) + ) + => Transformable Text IO (StartupTrace blk) where + trTransformer = trStructuredText +instance ( Show (BlockNodeToNodeVersion blk) + , Show (BlockNodeToClientVersion blk) + ) + => HasTextFormatter (StartupTrace blk) where + formatText a _ = ppStartupInfoTrace a +instance ( Show (BlockNodeToNodeVersion blk) + , Show (BlockNodeToClientVersion blk) + ) + => ToObject (StartupTrace blk) where + toObject _verb (StartupInfo addresses + localSocket + supportedNodeToNodeVersions + supportedNodeToClientVersions) + = mkObject + [ "nodeAddresses" .= Aeson.toJSON (map ppN2NSocketInfo addresses) + , "localSocket" .= case localSocket of + Nothing -> Aeson.Null + Just a -> String (Text.pack . ppN2CSocketInfo $ a) + , "nodeToNodeVersions" .= + Aeson.toJSON (map show . Map.assocs $ supportedNodeToNodeVersions) + , "nodeToClientVersions" .= + Aeson.toJSON (map show . Map.assocs $ supportedNodeToClientVersions) + ] + toObject _verb (StartupP2PInfo diffusionMode) + = mkObject [ "diffusionMode" .= String (Text.pack . show $ diffusionMode) ] + toObject _verb (StartupNetworkMagic networkMagic) = + mkObject [ "networkMagic" .= String ( Text.pack . show . unNetworkMagic + $ networkMagic) ] + toObject _verb (StartupSocketConfigError err) = + mkObject [ "error" .= String (Text.pack . show $ err) ] + toObject _verb NetworkConfigUpdate = + mkObject [ "message" .= String "ntework configuration update" ] + toObject _verb (NetworkConfigUpdateError err) = + mkObject [ "error" .= String err ] + toObject _verb (NetworkConfig localRoots publicRoots useLedgerAfter) = + mkObject [ "localRoots" .= Aeson.toJSON localRoots + , "publicRoots" .= Aeson.toJSON publicRoots + , "useLedgerAfter" .= UseLedger useLedgerAfter + ] + toObject _verb P2PWarning = + mkObject [ "message" .= String p2pWarningMessage ] + toObject _verb P2PWarningDevelopementNetworkProtocols = + mkObject [ "message" .= String p2pWarningDevelopmentNetworkProtocolsMessage ] + + + +-- | Pretty print 'StartupInfoTrace' +-- +ppStartupInfoTrace :: ( Show (BlockNodeToNodeVersion blk) + , Show (BlockNodeToClientVersion blk) + ) + => StartupTrace blk + -> Text +ppStartupInfoTrace (StartupInfo addresses + localSocket + supportedNodeToNodeVersions + supportedNodeToClientVersions) + = Text.pack + $ "\n" ++ intercalate "\n" + [ "node addresses: " ++ intercalate ", " (map ppN2NSocketInfo addresses) + , "local socket: " ++ maybe "NONE" ppN2CSocketInfo localSocket + , "node-to-node versions:\n" + ++ intercalate "\n" + (map (\(v, bv) -> show v ++ "\t" ++ show bv) + . Map.assocs + $ supportedNodeToNodeVersions) + , "node-to-client versions:\n" + ++ intercalate "\n" + (map (\(v, bv) -> show v ++ "\t" ++ show bv) + . Map.assocs + $ supportedNodeToClientVersions) + ] + +ppStartupInfoTrace (StartupP2PInfo diffusionMode) = + case diffusionMode of + InitiatorAndResponderDiffusionMode -> "initiator and responder diffusion mode" + InitiatorOnlyDiffusionMode -> "initaitor only diffusion mode" + +ppStartupInfoTrace (StartupNetworkMagic networkMagic) = + "network magic: " <> Text.pack (show $ unNetworkMagic networkMagic) + +ppStartupInfoTrace (StartupSocketConfigError err) = + Text.pack $ renderSocketConfigError err + +ppStartupInfoTrace NetworkConfigUpdate = "Performing topology configuration update" +ppStartupInfoTrace (NetworkConfigUpdateError err) = err +ppStartupInfoTrace (NetworkConfig localRoots publicRoots useLedgerAfter) = + Text.pack + $ intercalate "\n" + [ "\nLocal Root Groups:" + , " " ++ intercalate "\n " (map (\(x,y) -> show (x, Map.assocs y)) + localRoots) + , "Public Roots:" + , " " ++ intercalate "\n " (map show publicRoots) + , case useLedgerAfter of + UseLedgerAfter slotNo -> "Get root peers from the ledger after slot " + ++ show (unSlotNo slotNo) + DontUseLedger -> "Don't use ledger to get root peers." + ] + +ppStartupInfoTrace P2PWarning = p2pWarningMessage + +ppStartupInfoTrace P2PWarningDevelopementNetworkProtocols = + p2pWarningDevelopmentNetworkProtocolsMessage + + +p2pWarningMessage :: Text +p2pWarningMessage = + "unsupported and unverified version of " + <> "`cardano-node` with peer-to-peer networking capabilities" + +p2pWarningDevelopmentNetworkProtocolsMessage :: Text +p2pWarningDevelopmentNetworkProtocolsMessage = + "peer-to-peer requires TestEnableDevelopmentNetworkProtocols to be set to True" + + +-- +-- Utils +-- + +-- | Pretty print 'SocketOrSocketInfo'. +-- +ppSocketInfo :: Show sock + => (info -> String) + -> SocketOrSocketInfo sock info -> String +ppSocketInfo ppInfo (SocketInfo addr) = ppInfo addr +ppSocketInfo _ppInfo (ActualSocket sock) = show sock + +ppN2CSocketInfo :: SocketOrSocketInfo LocalSocket LocalAddress + -> String +ppN2CSocketInfo = ppSocketInfo getFilePath + +ppN2NSocketInfo :: SocketOrSocketInfo Socket.SockAddr Socket.SockAddr + -> String +ppN2NSocketInfo = ppSocketInfo show diff --git a/cardano-node/src/Cardano/Tracing/Tracers.hs b/cardano-node/src/Cardano/Tracing/Tracers.hs index 2bcfe56a121..c4e6ceac93a 100644 --- a/cardano-node/src/Cardano/Tracing/Tracers.hs +++ b/cardano-node/src/Cardano/Tracing/Tracers.hs @@ -106,6 +106,7 @@ import Cardano.Tracing.ConvertTxId (ConvertTxId) import Cardano.Tracing.Kernel import Cardano.Tracing.Metrics import Cardano.Tracing.Queries +import Cardano.Tracing.Startup import Cardano.Node.Configuration.Logging -- For tracing instances @@ -138,6 +139,7 @@ data Tracers peer localPeer blk p2p = Tracers LocalAddress NodeToClientVersion IO , diffusionTracersExtra :: Diffusion.ExtraTracers p2p + , startupTracer :: Tracer IO (StartupTrace blk) } data ForgeTracers = ForgeTracers @@ -163,6 +165,7 @@ nullTracersP2P = Tracers , nodeToNodeTracers = NodeToNode.nullTracers , diffusionTracers = Diffusion.nullTracers , diffusionTracersExtra = Diffusion.P2PTracers P2P.nullTracers + , startupTracer = nullTracer } nullTracersNonP2P :: Tracers peer localPeer blk Diffusion.NonP2P @@ -173,6 +176,7 @@ nullTracersNonP2P = Tracers , nodeToNodeTracers = NodeToNode.nullTracers , diffusionTracers = Diffusion.nullTracers , diffusionTracersExtra = Diffusion.NonP2PTracers NonP2P.nullTracers + , startupTracer = nullTracer } indexGCType :: ChainDB.TraceGCEvent a -> Int @@ -307,6 +311,9 @@ mkTracers blockConfig tOpts@(TracingOn trSel) tr nodeKern ekgDirect enableP2P = , nodeToNodeTracers = nodeToNodeTracers' trSel verb tr , diffusionTracers , diffusionTracersExtra = diffusionTracersExtra' enableP2P + -- TODO: startupTracer should ignore severity level (i.e. it should always + -- be printed)! + , startupTracer = toLogObject' verb $ appendName "nodeconfig" tr } where diffusionTracers = Diffusion.Tracers @@ -437,6 +444,7 @@ mkTracers _ TracingOff _ _ _ enableP2P = case enableP2P of EnabledP2PMode -> Diffusion.P2PTracers P2P.nullTracers DisabledP2PMode -> Diffusion.NonP2PTracers NonP2P.nullTracers + , startupTracer = nullTracer } --------------------------------------------------------------------------------