diff --git a/cardano-db-sync/cardano-db-sync.cabal b/cardano-db-sync/cardano-db-sync.cabal index 03f3b5e6f..591aa8701 100644 --- a/cardano-db-sync/cardano-db-sync.cabal +++ b/cardano-db-sync/cardano-db-sync.cabal @@ -143,6 +143,7 @@ library Cardano.DbSync.Util.Bech32 Cardano.DbSync.Util.Cbor Cardano.DbSync.Util.Constraint + Cardano.DbSync.Util.Logging Paths_cardano_db_sync diff --git a/cardano-db-sync/src/Cardano/DbSync.hs b/cardano-db-sync/src/Cardano/DbSync.hs index 9df654d4c..a7555c6b2 100644 --- a/cardano-db-sync/src/Cardano/DbSync.hs +++ b/cardano-db-sync/src/Cardano/DbSync.hs @@ -24,7 +24,7 @@ module Cardano.DbSync ( extractSyncOptions, ) where -import Cardano.BM.Trace (Trace, logError, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Crypto as Crypto import qualified Cardano.Db as DB import qualified Cardano.Db as Db @@ -44,6 +44,7 @@ import Cardano.DbSync.Sync (runSyncNodeClient) import Cardano.DbSync.Tracing.ToObjectOrphans () import Cardano.DbSync.Types import Cardano.DbSync.Util.Constraint (queryIsJsonbInSchema) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx, logInfoCtx, logWarningCtx) import Cardano.Prelude hiding (Nat, (%)) import Cardano.Slotting.Slot (EpochNo (..)) import Control.Concurrent.Async @@ -79,7 +80,8 @@ runDbSync :: Bool -> IO () runDbSync metricsSetters knownMigrations iomgr trce params syncNodeConfigFromFile abortOnPanic = do - logInfo trce $ textShow syncOpts + let logCtx = initLogCtx "runDbSync" "Cardano.DbSync" + logInfoCtx trce $ logCtx {lcMessage = "Current sync options: " <> textShow syncOpts} -- Read the PG connection info pgConfig <- runOrThrowIO (Db.readPGPass $ enpPGPassSource params) @@ -87,33 +89,40 @@ runDbSync metricsSetters knownMigrations iomgr trce params syncNodeConfigFromFil mErrors <- liftIO $ Db.validateMigrations dbMigrationDir knownMigrations whenJust mErrors $ \(unknown, stage4orNewStage3) -> if stage4orNewStage3 - then logWarning trce $ Db.renderMigrationValidateError unknown + then logWarningCtx trce $ logCtx {lcMessage = Db.renderMigrationValidateError unknown} else do let msg = Db.renderMigrationValidateError unknown - logError trce msg + logErrorCtx trce $ logCtx {lcMessage = msg} throwIO unknown - logInfo trce "Schema migration files validated" + logInfoCtx trce $ logCtx {lcMessage = "Schema migration files validated"} let runMigration mode = do msg <- Db.getMaintenancePsqlConf pgConfig - logInfo trce $ "Running database migrations in mode " <> textShow mode - logInfo trce msg - when (mode `elem` [Db.Indexes, Db.Full]) $ logWarning trce indexesMsg + logInfoCtx trce $ logCtx {lcMessage = "Running database migrations in mode " <> textShow mode} + logInfoCtx trce $ logCtx {lcMessage = msg} + when (mode `elem` [Db.Indexes, Db.Full]) $ logWarningCtx trce $ logCtx {lcMessage = indexesMsg} Db.runMigrations pgConfig True dbMigrationDir (Just $ Db.LogFileDir "/tmp") mode (txOutConfigToTableType txOutConfig) (ranMigrations, unofficial) <- if enpForceIndexes params then runMigration Db.Full else runMigration Db.Initial unless (null unofficial) $ - logWarning trce $ - "Unofficial migration scripts found: " - <> textShow unofficial + logWarningCtx trce $ + logCtx {lcMessage = "Unofficial migration scripts found: " <> textShow unofficial} - if ranMigrations - then logInfo trce "All migrations were executed" - else logInfo trce "Some migrations were not executed. They need to run when syncing has started." + logInfoCtx trce $ + logCtx + { lcMessage = + if ranMigrations + then "All migrations were executed" + else "Some migrations were not executed. They need to run when syncing has started." + } - if enpForceIndexes params - then logInfo trce "All user indexes were created" - else logInfo trce "New user indexes were not created. They may be created later if necessary." + logInfoCtx trce $ + logCtx + { lcMessage = + if enpForceIndexes params + then "All user indexes were created" + else "New user indexes were not created. They may be created later if necessary." + } let connectionString = Db.toConnectionString pgConfig @@ -162,12 +171,16 @@ runSyncNode :: SyncOptions -> IO () runSyncNode metricsSetters trce iomgr dbConnString ranMigrations runMigrationFnc syncNodeConfigFromFile syncNodeParams syncOptions = do + let logCtx = initLogCtx "runSyncNode" "Cardano.DbSync" whenJust maybeLedgerDir $ \enpLedgerStateDir -> do createDirectoryIfMissing True (unLedgerStateDir enpLedgerStateDir) - logInfo trce $ "Using byron genesis file from: " <> (show . unGenesisFile $ dncByronGenesisFile syncNodeConfigFromFile) - logInfo trce $ "Using shelley genesis file from: " <> (show . unGenesisFile $ dncShelleyGenesisFile syncNodeConfigFromFile) - logInfo trce $ "Using alonzo genesis file from: " <> (show . unGenesisFile $ dncAlonzoGenesisFile syncNodeConfigFromFile) + logInfoCtx trce $ + logCtx {lcMessage = "Using byron genesis file from: " <> (show . unGenesisFile $ dncByronGenesisFile syncNodeConfigFromFile)} + logInfoCtx trce $ + logCtx {lcMessage = "Using shelley genesis file from: " <> (show . unGenesisFile $ dncShelleyGenesisFile syncNodeConfigFromFile)} + logInfoCtx trce $ + logCtx {lcMessage = "Using alonzo genesis file from: " <> (show . unGenesisFile $ dncAlonzoGenesisFile syncNodeConfigFromFile)} let useLedger = shouldUseLedger (sioLedger $ dncInsertOptions syncNodeConfigFromFile) @@ -193,16 +206,16 @@ runSyncNode metricsSetters trce iomgr dbConnString ranMigrations runMigrationFnc -- Warn the user that jsonb datatypes are being removed from the database schema. when (isJsonbInSchema && removeJsonbFromSchemaConfig) $ do - liftIO $ logWarning trce "Removing jsonb datatypes from the database. This can take time." + liftIO $ logWarningCtx trce $ logCtx {lcMessage = "Removing jsonb datatypes from the database. This can take time."} liftIO $ runRemoveJsonbFromSchema syncEnv -- Warn the user that jsonb datatypes are being added to the database schema. when (not isJsonbInSchema && not removeJsonbFromSchemaConfig) $ do - liftIO $ logWarning trce "Adding jsonb datatypes back to the database. This can take time." + liftIO $ logWarningCtx trce $ logCtx {lcMessage = "Adding jsonb datatypes back to the database. This can take time."} liftIO $ runAddJsonbToSchema syncEnv liftIO $ runExtraMigrationsMaybe syncEnv unless useLedger $ liftIO $ do - logInfo trce "Migrating to a no ledger schema" + logInfoCtx trce $ logCtx {lcMessage = "Migrating to a no ledger schema"} Db.noLedgerMigrations backend trce insertValidateGenesisDist syncEnv (dncNetworkName syncNodeConfigFromFile) genCfg (useShelleyInit syncNodeConfigFromFile) @@ -227,13 +240,17 @@ runSyncNode metricsSetters trce iomgr dbConnString ranMigrations runMigrationFnc maybeLedgerDir = enpMaybeLedgerStateDir syncNodeParams logProtocolMagicId :: Trace IO Text -> Crypto.ProtocolMagicId -> ExceptT SyncNodeError IO () -logProtocolMagicId tracer pm = +logProtocolMagicId tracer pm = do + let logCtx = initLogCtx "logProtocolMagicId" "Cardano.DbSync" liftIO - . logInfo tracer - $ mconcat - [ "NetworkMagic: " - , textShow (Crypto.unProtocolMagicId pm) - ] + . logInfoCtx tracer + $ logCtx + { lcMessage = + mconcat + [ "NetworkMagic: " + , textShow (Crypto.unProtocolMagicId pm) + ] + } -- ------------------------------------------------------------------------------------------------- @@ -299,10 +316,11 @@ extractSyncOptions snp aop snc = startupReport :: Trace IO Text -> Bool -> SyncNodeParams -> IO () startupReport trce aop params = do - logInfo trce $ mconcat ["Version number: ", Text.pack (showVersion version)] - logInfo trce $ mconcat ["Git hash: ", Db.gitRev] - logInfo trce $ mconcat ["Enviroment variable DbSyncAbortOnPanic: ", textShow aop] - logInfo trce $ textShow params + let logCtx = initLogCtx "runSyncNode" "Cardano.DbSync" + logInfoCtx trce $ logCtx {lcMessage = mconcat ["Version number: ", Text.pack (showVersion version)]} + logInfoCtx trce $ logCtx {lcMessage = mconcat ["Git hash: ", Db.gitRev]} + logInfoCtx trce $ logCtx {lcMessage = mconcat ["Enviroment variable DbSyncAbortOnPanic: ", textShow aop]} + logInfoCtx trce $ logCtx {lcMessage = textShow params} txOutConfigToTableType :: TxOutConfig -> DB.TxOutTableType txOutConfigToTableType config = case config of diff --git a/cardano-db-sync/src/Cardano/DbSync/Api.hs b/cardano-db-sync/src/Cardano/DbSync/Api.hs index 02f0b9745..a37b135da 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Api.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Api.hs @@ -51,7 +51,7 @@ module Cardano.DbSync.Api ( convertToPoint, ) where -import Cardano.BM.Trace (Trace, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Chain.Genesis as Byron import Cardano.Crypto.ProtocolMagic (ProtocolMagicId (..)) import qualified Cardano.Db as DB @@ -73,6 +73,7 @@ import Cardano.DbSync.LocalStateQuery import Cardano.DbSync.Types import Cardano.DbSync.Util import Cardano.DbSync.Util.Constraint (dbConstraintNamesExists) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import qualified Cardano.Ledger.BaseTypes as Ledger import qualified Cardano.Ledger.Shelley.Genesis as Shelley import Cardano.Prelude @@ -101,7 +102,8 @@ import qualified Ouroboros.Network.Point as Point setConsistentLevel :: SyncEnv -> ConsistentLevel -> IO () setConsistentLevel env cst = do - logInfo (getTrace env) $ "Setting ConsistencyLevel to " <> textShow cst + let logCtx = initLogCtx "setConsistentLevel" "Cardano.DbSync.Api" + logInfoCtx (getTrace env) $ logCtx {lcMessage = "Setting ConsistencyLevel to " <> textShow cst} atomically $ writeTVar (envConsistentLevel env) cst getConsistentLevel :: SyncEnv -> IO ConsistentLevel @@ -158,10 +160,11 @@ getRanIndexes env = do runIndexMigrations :: SyncEnv -> IO () runIndexMigrations env = do + let logCtx = initLogCtx "runIndexMigrations" "Cardano.DbSync.Api" haveRan <- readTVarIO $ envIndexes env unless haveRan $ do envRunDelayedMigration env DB.Indexes - logInfo (getTrace env) "Indexes were created" + logInfoCtx (getTrace env) $ logCtx {lcMessage = "Indexes were created"} atomically $ writeTVar (envIndexes env) True initPruneConsumeMigration :: Bool -> Bool -> Bool -> Bool -> DB.PruneConsumeMigration @@ -178,8 +181,9 @@ getPruneConsume = soptPruneConsumeMigration . envOptions runExtraMigrationsMaybe :: SyncEnv -> IO () runExtraMigrationsMaybe syncEnv = do let pcm = getPruneConsume syncEnv + logCtx = initLogCtx "runExtraMigrationsMaybe" "Cardano.DbSync.Api" txOutTableType = getTxOutTableType syncEnv - logInfo (getTrace syncEnv) $ "runExtraMigrationsMaybe: " <> textShow pcm + logInfoCtx (getTrace syncEnv) $ logCtx {lcMessage = "runExtraMigrationsMaybe: " <> textShow pcm} DB.runDbIohkNoLogging (envBackend syncEnv) $ DB.runExtraMigrations (getTrace syncEnv) @@ -306,12 +310,23 @@ getDbTipBlockNo env = do mblk <- getDbLatestBlockInfo (envBackend env) pure $ maybe Point.Origin (Point.At . bBlockNo) mblk -logDbState :: SyncEnv -> IO () -logDbState env = do +getCurrentTipBlockNo :: SyncEnv -> IO (WithOrigin BlockNo) +getCurrentTipBlockNo env = do + maybeTip <- getDbLatestBlockInfo (envBackend env) + case maybeTip of + Just tip -> pure $ At (bBlockNo tip) + Nothing -> pure Origin + +logDbState :: SyncEnv -> LogContext -> IO () +logDbState env logCtx = do mblk <- getDbLatestBlockInfo (envBackend env) case mblk of - Nothing -> logInfo tracer "Database is empty" - Just tip -> logInfo tracer $ mconcat ["Database tip is at ", showTip tip] + Nothing -> + logInfoCtx tracer $ + logCtx {lcMessage = "Database is empty"} + Just tip -> + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Database tip is at ", showTip tip]} where showTip :: TipInfo -> Text showTip tipInfo = @@ -325,13 +340,6 @@ logDbState env = do tracer :: Trace IO Text tracer = getTrace env -getCurrentTipBlockNo :: SyncEnv -> IO (WithOrigin BlockNo) -getCurrentTipBlockNo env = do - maybeTip <- getDbLatestBlockInfo (envBackend env) - case maybeTip of - Just tip -> pure $ At (bBlockNo tip) - Nothing -> pure Origin - mkSyncEnv :: Trace IO Text -> SqlBackend -> @@ -347,6 +355,7 @@ mkSyncEnv :: RunMigration -> IO SyncEnv mkSyncEnv trce backend connectionString syncOptions protoInfo nw nwMagic systemStart syncNodeConfigFromFile syncNP ranMigrations runMigrationFnc = do + let logCtx = initLogCtx "mkSyncEnv" "Cardano.DbSync.Api" dbCNamesVar <- newTVarIO =<< dbConstraintNamesExists backend cache <- if soptCache syncOptions @@ -384,9 +393,13 @@ mkSyncEnv trce backend connectionString syncOptions protoInfo nw nwMagic systemS syncOptions (Nothing, False) -> NoLedger <$> mkNoLedgerEnv trce protoInfo nw systemStart (Just _, False) -> do - logWarning trce $ - "Disabling the ledger doesn't require having a --state-dir." - <> " For more details view https://github.com/IntersectMBO/cardano-db-sync/blob/master/doc/configuration.md#ledger" + logWarningCtx trce $ + logCtx + { lcMessage = + "Disabling the ledger doesn't require having a --state-dir." + <> " For more details view " + <> " https://github.com/IntersectMBO/cardano-db-sync/blob/master/doc/configuration.md#ledger" + } NoLedger <$> mkNoLedgerEnv trce protoInfo nw systemStart -- This won't ever call because we error out this combination at parse time (Nothing, True) -> NoLedger <$> mkNoLedgerEnv trce protoInfo nw systemStart @@ -534,6 +547,7 @@ getBootstrapInProgress :: SqlBackend -> IO Bool getBootstrapInProgress trce bootstrapFlag sqlBackend = do + let logCtx = initLogCtx "getBootstrapInProgress" "Cardano.DbSync.Api" DB.runDbIohkNoLogging sqlBackend $ do ems <- DB.queryAllExtraMigrations let btsState = DB.bootstrapState ems @@ -547,26 +561,35 @@ getBootstrapInProgress trce bootstrapFlag sqlBackend = do liftIO $ DB.logAndThrowIO trce "Bootstrap flag not set, but still in progress" (True, DB.BootstrapNotStarted) -> do liftIO $ - logInfo trce $ - mconcat - [ "Syncing with bootstrap. " - , "This won't populate tx_out until the tip of the chain." - ] + logInfoCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Syncing with bootstrap. " + , "This won't populate tx_out until the tip of the chain." + ] + } DB.insertExtraMigration DB.BootstrapStarted pure True (True, DB.BootstrapInProgress) -> do liftIO $ - logInfo trce $ - mconcat - [ "Syncing with bootstrap is in progress. " - , "This won't populate tx_out until the tip of the chain." - ] + logInfoCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Syncing with bootstrap is in progress. " + , "This won't populate tx_out until the tip of the chain." + ] + } pure True (True, DB.BootstrapDone) -> do liftIO $ - logWarning trce $ - mconcat - [ "Bootstrap flag is set, but it will be ignored, " - , "since bootstrap is already done." - ] + logWarningCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Bootstrap flag is set, but it will be ignored, " + , "since bootstrap is already done." + ] + } pure False diff --git a/cardano-db-sync/src/Cardano/DbSync/Api/Ledger.hs b/cardano-db-sync/src/Cardano/DbSync/Api/Ledger.hs index 399541c49..f3433bea1 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Api/Ledger.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Api/Ledger.hs @@ -6,7 +6,6 @@ module Cardano.DbSync.Api.Ledger where -import Cardano.BM.Trace (logError, logInfo, logWarning) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types @@ -20,6 +19,7 @@ import Cardano.DbSync.Era.Util (liftLookupFail) import Cardano.DbSync.Error import Cardano.DbSync.Ledger.State import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx, logInfoCtx, logWarningCtx) import Cardano.Ledger.Allegra.Scripts (Timelock) import Cardano.Ledger.Alonzo.Scripts import Cardano.Ledger.Babbage.Core @@ -63,28 +63,30 @@ migrateBootstrapUTxO :: migrateBootstrapUTxO syncEnv = do case envLedgerEnv syncEnv of HasLedger lenv -> do - liftIO $ logInfo trce "Starting UTxO bootstrap migration" + liftIO $ logInfoCtx trce logCtx {lcMessage = "Starting UTxO bootstrap migration"} cls <- liftIO $ readCurrentStateUnsafe lenv count <- lift $ DB.deleteTxOut (getTxOutTableType syncEnv) when (count > 0) $ liftIO $ - logWarning trce $ - "Found and deleted " <> textShow count <> " tx_out." + logWarningCtx trce $ + logCtx {lcMessage = "Found and deleted " <> textShow count <> " tx_out."} storeUTxOFromLedger syncEnv cls lift $ DB.insertExtraMigration DB.BootstrapFinished - liftIO $ logInfo trce "UTxO bootstrap migration done" + liftIO $ logInfoCtx trce $ logCtx {lcMessage = "UTxO bootstrap migration done"} liftIO $ atomically $ writeTVar (envBootstrap syncEnv) False NoLedger _ -> - liftIO $ logWarning trce "Tried to bootstrap, but ledger state is not enabled. Please stop db-sync and restart without --disable-ledger-state" + liftIO $ logWarningCtx trce $ logCtx {lcMessage = "Tried to bootstrap, but ledger state is not enabled. Please stop db-sync and restart without --disable-ledger-state"} where + logCtx = initLogCtx "migrateBootstrapUTxO" "Cardano.DbSync.Api.Ledger" trce = getTrace syncEnv storeUTxOFromLedger :: (MonadBaseControl IO m, MonadIO m) => SyncEnv -> ExtLedgerState CardanoBlock -> ExceptT SyncNodeError (ReaderT SqlBackend m) () storeUTxOFromLedger env st = case ledgerState st of LedgerStateBabbage bts -> storeUTxO env (getUTxO bts) LedgerStateConway stc -> storeUTxO env (getUTxO stc) - _otherwise -> liftIO $ logError trce "storeUTxOFromLedger is only supported after Babbage" + _otherwise -> liftIO $ logErrorCtx trce logCtx {lcMessage = "storeUTxOFromLedger is only supported after Babbage"} where + logCtx = initLogCtx "storeUTxOFromLedger" "Cardano.DbSync.Api.Ledger" trce = getTrace env getUTxO st' = unUTxO $ Consensus.shelleyLedgerState st' ^. (nesEsL . esLStateL . lsUTxOStateL . utxosUtxoL) @@ -108,15 +110,19 @@ storeUTxO :: ExceptT SyncNodeError (ReaderT SqlBackend m) () storeUTxO env mp = do liftIO $ - logInfo trce $ - mconcat - [ "Inserting " - , textShow size - , " tx_out as pages of " - , textShow pageSize - ] + logInfoCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Inserting " + , textShow size + , " tx_out as pages of " + , textShow pageSize + ] + } mapM_ (storePage env pagePerc) . zip [0 ..] . chunksOf pageSize . Map.toList $ mp where + logCtx = initLogCtx "storeUTxO" "Cardano.DbSync.Api.Ledger" trce = getTrace env npages = size `div` pageSize pagePerc :: Float = if npages == 0 then 100.0 else 100.0 / fromIntegral npages @@ -138,13 +144,14 @@ storePage :: (Int, [(TxIn StandardCrypto, BabbageTxOut era)]) -> ExceptT SyncNodeError (ReaderT SqlBackend m) () storePage syncEnv percQuantum (n, ls) = do - when (n `mod` 10 == 0) $ liftIO $ logInfo trce $ "Bootstrap in progress " <> prc <> "%" + when (n `mod` 10 == 0) $ liftIO $ logInfoCtx trce $ logCtx {lcMessage = "Bootstrap in progress " <> prc <> "%"} txOuts <- mapM (prepareTxOut syncEnv) ls txOutIds <- lift . DB.insertManyTxOut False $ etoTxOut . fst <$> txOuts let maTxOuts = concatMap (mkmaTxOuts txOutTableType) $ zip txOutIds (snd <$> txOuts) void . lift $ DB.insertManyMaTxOut maTxOuts where + logCtx = initLogCtx "storePage" "Cardano.DbSync.Api.Ledger" txOutTableType = getTxOutTableType syncEnv trce = getTrace syncEnv prc = Text.pack $ showGFloat (Just 1) (max 0 $ min 100.0 (fromIntegral n * percQuantum)) "" diff --git a/cardano-db-sync/src/Cardano/DbSync/Cache.hs b/cardano-db-sync/src/Cardano/DbSync/Cache.hs index 67818311e..73e14b3fd 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Cache.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Cache.hs @@ -39,6 +39,7 @@ import Cardano.DbSync.Era.Shelley.Query import Cardano.DbSync.Era.Util import Cardano.DbSync.Error import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import qualified Cardano.Ledger.Address as Ledger import Cardano.Ledger.BaseTypes (Network) import Cardano.Ledger.Mary.Value @@ -280,35 +281,42 @@ queryPoolKeyOrInsert :: PoolKeyHash -> ReaderT SqlBackend m DB.PoolHashId queryPoolKeyOrInsert txt trce cache cacheUA logsWarning hsh = do + let logCtx = initLogCtx "queryPoolKeyOrInsert" "Cardano.DbSync.Cache" pk <- queryPoolKeyWithCache cache cacheUA hsh case pk of Right poolHashId -> pure poolHashId Left err -> do when logsWarning $ liftIO $ - logWarning trce $ - mconcat - [ "Failed with " - , textShow err - , " while trying to find pool " - , textShow hsh - , " for " - , txt - , ". We will assume that the pool exists and move on." - ] + logWarningCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Failed with " + , textShow err + , " while trying to find pool " + , textShow hsh + , " for " + , txt + , ". We will assume that the pool exists and move on." + ] + } insertPoolKeyWithCache cache cacheUA hsh queryMAWithCache :: MonadIO m => + Trace IO Text -> CacheStatus -> PolicyID StandardCrypto -> AssetName -> ReaderT SqlBackend m (Either (ByteString, ByteString) DB.MultiAssetId) -queryMAWithCache cache policyId asset = +queryMAWithCache trce cache policyId asset = do + let logCtx = initLogCtx "queryMAWithCache" "Cardano.DbSync.Cache" case cache of NoCache -> do let !policyBs = Generic.unScriptHash $ policyID policyId - let !assetNameBs = Generic.unAssetName asset + !assetNameBs = Generic.unAssetName asset + liftIO $ logInfoCtx trce $ logCtx {lcMessage = mconcat ["Querying MultiAssetId for ", textShow policyId, " ", textShow asset]} maybe (Left (policyBs, assetNameBs)) Right <$> DB.queryMultiAssetId policyBs assetNameBs ActiveCache ci -> do mp <- liftIO $ readTVarIO (cMultiAssets ci) diff --git a/cardano-db-sync/src/Cardano/DbSync/Database.hs b/cardano-db-sync/src/Cardano/DbSync/Database.hs index 4583b8204..807f4efe8 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Database.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Database.hs @@ -11,7 +11,6 @@ module Cardano.DbSync.Database ( runDbThread, ) where -import Cardano.BM.Trace (logDebug, logError, logInfo) import Cardano.DbSync.Api import Cardano.DbSync.Api.Types (ConsistentLevel (..), LedgerEnv (..), SyncEnv (..)) import Cardano.DbSync.DbAction @@ -23,6 +22,7 @@ import Cardano.DbSync.Metrics import Cardano.DbSync.Rollback import Cardano.DbSync.Types import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logDebugCtx, logErrorCtx, logExceptionCtx, logInfoCtx) import Cardano.Prelude hiding (atomically) import Cardano.Slotting.Slot (WithOrigin (..)) import Control.Concurrent.Class.MonadSTM.Strict @@ -44,16 +44,18 @@ runDbThread :: ThreadChannels -> IO () runDbThread syncEnv metricsSetters queue = do - logInfo trce "Running DB thread" - logException trce "runDBThread: " loop - logInfo trce "Shutting down DB thread" + let logCtx = initLogCtx "runDbThread" "DbSync.Database" + logInfoCtx trce $ logCtx {lcMessage = "Running DB thread"} + logExceptionCtx trce logCtx loop + logInfoCtx trce $ logCtx {lcMessage = "Shutting down DB thread"} where trce = getTrace syncEnv loop = do + let logCtx = initLogCtx "runDbThread Loop" "DbSync.Database" xs <- blockingFlushDbActionQueue queue when (length xs > 1) $ do - logDebug trce $ "runDbThread: " <> textShow (length xs) <> " blocks" + logDebugCtx trce $ logCtx {lcMessage = "runDbThread: " <> textShow (length xs) <> " blocks"} case hasRestart xs of Nothing -> do @@ -65,16 +67,16 @@ runDbThread syncEnv metricsSetters queue = do setDbSlotHeight metricsSetters $ bSlotNo block case eNextState of - Left err -> logError trce $ show err + Left err -> logErrorCtx trce $ logCtx {lcMessage = show err} Right Continue -> loop Right Done -> pure () Just resultVar -> do -- In this case the syncing thread has restarted, so ignore all blocks that are not -- inserted yet. - logInfo trce "Chain Sync client thread has restarted" + logInfoCtx trce $ logCtx {lcMessage = "Chain Sync client thread has restarted"} latestPoints <- getLatestPoints syncEnv currentTip <- getCurrentTipBlockNo syncEnv - logDbState syncEnv + logDbState syncEnv logCtx atomically $ putTMVar resultVar (latestPoints, currentTip) loop diff --git a/cardano-db-sync/src/Cardano/DbSync/Default.hs b/cardano-db-sync/src/Cardano/DbSync/Default.hs index 010ee9fcc..75b8db383 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Default.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Default.hs @@ -11,7 +11,6 @@ module Cardano.DbSync.Default ( insertListBlocks, ) where -import Cardano.BM.Trace (logInfo) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Ledger @@ -32,6 +31,7 @@ import Cardano.DbSync.Rollback import Cardano.DbSync.Types import Cardano.DbSync.Util import Cardano.DbSync.Util.Constraint (addConstraintsIfNotExist) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import qualified Cardano.Ledger.Alonzo.Scripts as Ledger import Cardano.Ledger.Shelley.AdaPots as Shelley import Cardano.Node.Configuration.Logging (Trace) @@ -76,12 +76,15 @@ applyAndInsertBlockMaybe syncEnv tracer cblk = do case eiBlockInDbAlreadyId of Left _ -> do liftIO - . logInfo tracer - $ mconcat - [ "Received block which is not in the db with " - , textShow (getHeaderFields cblk) - , ". Time to restore consistency." - ] + . logInfoCtx tracer + $ logCtx + { lcMessage = + mconcat + [ "Received block which is not in the db with " + , textShow (getHeaderFields cblk) + , ". Time to restore consistency." + ] + } rollbackFromBlockNo syncEnv (blockNo cblk) void $ migrateStakeDistr syncEnv (apOldLedger applyRes) insertBlock syncEnv cblk applyRes True tookSnapshot @@ -89,13 +92,14 @@ applyAndInsertBlockMaybe syncEnv tracer cblk = do Right blockId | Just (adaPots, slotNo, epochNo) <- getAdaPots applyRes -> do replaced <- lift $ DB.replaceAdaPots blockId $ mkAdaPots blockId slotNo epochNo adaPots if replaced - then liftIO $ logInfo tracer $ "Fixed AdaPots for " <> textShow epochNo - else liftIO $ logInfo tracer $ "Reached " <> textShow epochNo + then liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Fixed AdaPots for " <> textShow epochNo} + else liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Reached " <> textShow epochNo} Right _ | Just epochNo <- getNewEpoch applyRes -> - liftIO $ logInfo tracer $ "Reached " <> textShow epochNo + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Reached " <> textShow epochNo} _ -> pure () where + logCtx = initLogCtx "applyAndInsertBlockMaybe" "Cardano.DbSync.Default" mkApplyResult :: Bool -> IO (ApplyResult, Bool) mkApplyResult isCons = do case envLedgerEnv syncEnv of diff --git a/cardano-db-sync/src/Cardano/DbSync/Epoch.hs b/cardano-db-sync/src/Cardano/DbSync/Epoch.hs index 113c032e4..9e512d318 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Epoch.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Epoch.hs @@ -7,7 +7,7 @@ module Cardano.DbSync.Epoch ( epochHandler, ) where -import Cardano.BM.Trace (Trace, logError, logInfo) +import Cardano.BM.Trace (Trace, logError) import qualified Cardano.Chain.Block as Byron import qualified Cardano.Db as DB import Cardano.DbSync.Api (getTrace) @@ -21,6 +21,7 @@ import Cardano.DbSync.Types ( SyncState (SyncFollowing), ) import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import Cardano.Prelude hiding (from, on, replace) import Cardano.Slotting.Slot (unEpochNo) import Control.Monad.Logger (LoggingT) @@ -176,6 +177,7 @@ updateEpochWhenSyncing :: ReaderT SqlBackend m (Either SyncNodeError ()) updateEpochWhenSyncing syncEnv cache mEpochBlockDiff mLastMapEpochFromCache epochNo isBoundaryBlock = do let trce = getTrace syncEnv + logCtx = initLogCtx "updateEpochWhenSyncing" "Cardano.DbSync.Era.Universal.Epoch" isFirstEpoch = epochNo == 0 -- count boundary block in the first epoch additionalBlockCount = if isBoundaryBlock && isFirstEpoch then 1 else 0 @@ -202,11 +204,19 @@ updateEpochWhenSyncing syncEnv cache mEpochBlockDiff mLastMapEpochFromCache epoc mEpochID <- DB.queryForEpochId epochNo case mEpochID of Nothing -> do - liftIO . logInfo trce $ epochSucessMsg "Inserted" "updateEpochWhenSyncing" "Cache" lastMapEpochFromCache + liftIO . logInfoCtx trce $ + logCtx + { lcMessage = epochSucessMsg "Inserted" "updateEpochWhenSyncing" "Cache" lastMapEpochFromCache + , lcEpochNo = Just $ DB.epochNo lastMapEpochFromCache + } _ <- DB.insertEpoch lastMapEpochFromCache pure $ Right () Just epochId -> do - liftIO . logInfo trce $ epochSucessMsg "Replaced" "updateEpochWhenSyncing" "Cache" calculatedEpoch + liftIO . logInfoCtx trce $ + logCtx + { lcMessage = epochSucessMsg "Replaced" "updateEpochWhenSyncing" "Cache" calculatedEpoch + , lcEpochNo = Just $ DB.epochNo calculatedEpoch + } Right <$> replace epochId calculatedEpoch -- When syncing, on every block we update the Map epoch in cache. Making sure to handle restarts @@ -246,6 +256,7 @@ makeEpochWithDBQuery :: ReaderT SqlBackend m (Either SyncNodeError ()) makeEpochWithDBQuery syncEnv cache mInitEpoch epochNo callSiteMsg = do let trce = getTrace syncEnv + logCtx = initLogCtx "makeEpochWithDBQuery" "Cardano.DbSync.Era.Universal.Epoch" calcEpoch <- DB.queryCalcEpochEntry epochNo mEpochID <- DB.queryForEpochId epochNo let epochInitOrCalc = fromMaybe calcEpoch mInitEpoch @@ -253,12 +264,14 @@ makeEpochWithDBQuery syncEnv cache mInitEpoch epochNo callSiteMsg = do Nothing -> do _ <- writeToMapEpochCache syncEnv cache epochInitOrCalc _ <- DB.insertEpoch calcEpoch - liftIO . logInfo trce $ epochSucessMsg "Inserted " callSiteMsg "DB query" calcEpoch + liftIO . logInfoCtx trce $ + logCtx {lcMessage = epochSucessMsg "Inserted " callSiteMsg "DB query" calcEpoch} pure $ Right () Just epochId -> do -- write the newly calculated epoch to cache. _ <- writeToMapEpochCache syncEnv cache epochInitOrCalc - liftIO . logInfo trce $ epochSucessMsg "Replaced " callSiteMsg "DB query" calcEpoch + liftIO . logInfoCtx trce $ + logCtx {lcMessage = epochSucessMsg "Replaced " callSiteMsg "DB query" calcEpoch} Right <$> replace epochId calcEpoch -- Because we store a Map of epochs, at every iteration we take the newest epoch and it's values diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Genesis.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Genesis.hs index 8fcf8993c..2b621b456 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Genesis.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Genesis.hs @@ -10,7 +10,7 @@ module Cardano.DbSync.Era.Byron.Genesis ( insertValidateGenesisDist, ) where -import Cardano.BM.Trace (Trace, logInfo) +import Cardano.BM.Trace (Trace) import Cardano.Binary (serialize') import qualified Cardano.Chain.Common as Byron import qualified Cardano.Chain.Genesis as Byron @@ -26,6 +26,7 @@ import qualified Cardano.DbSync.Era.Byron.Util as Byron import Cardano.DbSync.Era.Util (liftLookupFail) import Cardano.DbSync.Error import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx, logInfoCtx) import Cardano.Prelude import Control.Monad.Trans.Control (MonadBaseControl) import Control.Monad.Trans.Except.Extra (newExceptT) @@ -50,6 +51,8 @@ insertValidateGenesisDist syncEnv (NetworkName networkName) cfg = do then newExceptT $ DB.runDbIohkLogging (envBackend syncEnv) tracer insertAction else newExceptT $ DB.runDbIohkNoLogging (envBackend syncEnv) insertAction where + logCtx = initLogCtx "insertValidateGenesisDist" "Cardano.DbSync.Era.Byron.Genesis" + tracer = getTrace syncEnv insertAction :: (MonadBaseControl IO m, MonadIO m) => ReaderT SqlBackend m (Either SyncNodeError ()) @@ -62,9 +65,10 @@ insertValidateGenesisDist syncEnv (NetworkName networkName) cfg = do Right bid -> validateGenesisDistribution syncEnv prunes disInOut tracer networkName cfg bid Left _ -> runExceptT $ do - liftIO $ logInfo tracer "Inserting Byron Genesis distribution" + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Inserting Byron Genesis distribution"} count <- lift DB.queryBlockCount - when (not disInOut && count > 0) $ + when (not disInOut && count > 0) $ do + liftIO $ logErrorCtx tracer $ logCtx {lcMessage = "Genesis data mismatch"} dbSyncNodeError "insertValidateGenesisDist: Genesis data mismatch." void . lift $ DB.insertMeta $ @@ -108,12 +112,16 @@ insertValidateGenesisDist syncEnv (NetworkName networkName) cfg = do , DB.blockOpCertCounter = Nothing } mapM_ (insertTxOutsByron syncEnv disInOut bid) $ genesisTxos cfg - liftIO . logInfo tracer $ - "Initial genesis distribution populated. Hash " - <> renderByteArray (configGenesisHash cfg) - + liftIO . logInfoCtx tracer $ + logCtx + { lcMessage = + "Initial genesis distribution populated. Hash " + <> renderByteArray (configGenesisHash cfg) + } supply <- lift $ DB.queryTotalSupply $ getTxOutTableType syncEnv - liftIO $ logInfo tracer ("Total genesis supply of Ada: " <> DB.renderAda supply) + liftIO $ + logInfoCtx tracer $ + logCtx {lcMessage = "Total genesis supply of Ada: " <> DB.renderAda supply} -- | Validate that the initial Genesis distribution in the DB matches the Genesis data. validateGenesisDistribution :: @@ -128,6 +136,7 @@ validateGenesisDistribution :: ReaderT SqlBackend m (Either SyncNodeError ()) validateGenesisDistribution syncEnv prunes disInOut tracer networkName cfg bid = runExceptT $ do + let logCtx = initLogCtx "validateGenesisDistribution" "Cardano.DbSync.Era.Byron.Genesis" meta <- liftLookupFail "validateGenesisDistribution" DB.queryMeta when (DB.metaStartTime meta /= Byron.configStartTime cfg) $ @@ -172,8 +181,8 @@ validateGenesisDistribution syncEnv prunes disInOut tracer networkName cfg bid = , DB.renderAda totalSupply ] liftIO $ do - logInfo tracer "Initial genesis distribution present and correct" - logInfo tracer ("Total genesis supply of Ada: " <> DB.renderAda totalSupply) + logInfoCtx tracer $ logCtx {lcMessage = "Initial genesis distribution present and correct"} + logInfoCtx tracer $ logCtx {lcMessage = "Total genesis supply of Ada: " <> DB.renderAda totalSupply} ------------------------------------------------------------------------------- diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Insert.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Insert.hs index 90e03c85f..ec7466fce 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Insert.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Byron/Insert.hs @@ -11,7 +11,7 @@ module Cardano.DbSync.Era.Byron.Insert ( resolveTxInputs, ) where -import Cardano.BM.Trace (Trace, logDebug, logInfo) +import Cardano.BM.Trace (Trace) import Cardano.Binary (serialize') import qualified Cardano.Chain.Block as Byron hiding (blockHash) import qualified Cardano.Chain.Common as Byron @@ -35,6 +35,7 @@ import Cardano.DbSync.Era.Util (liftLookupFail) import Cardano.DbSync.Error import Cardano.DbSync.Types import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logDebugCtx, logInfoCtx) import Cardano.Prelude import Cardano.Slotting.Slot (EpochNo (..), EpochSize (..)) import Control.Monad.Trans.Control (MonadBaseControl) @@ -78,6 +79,7 @@ insertABOBBoundary :: ExceptT SyncNodeError (ReaderT SqlBackend m) () insertABOBBoundary syncEnv blk details = do let tracer = getTrace syncEnv + logCtx = initLogCtx "insertABOBBoundary" "Cardano.DbSync.Era.Byron.Insert" cache = envCache syncEnv -- Will not get called in the OBFT part of the Byron era. pbid <- queryPrevBlockWithCache "insertABOBBoundary" cache (Byron.ebbPrevHash blk) @@ -128,13 +130,17 @@ insertABOBBoundary syncEnv blk details = do , ebdTime = sdSlotTime details } - liftIO . logInfo tracer $ - Text.concat - [ "insertABOBBoundary: epoch " - , textShow (Byron.boundaryEpoch $ Byron.boundaryHeader blk) - , ", hash " - , Byron.renderAbstractHash (Byron.boundaryHashAnnotated blk) - ] + liftIO . logInfoCtx tracer $ + logCtx + { lcEpochNo = Just epochNo + , lcMessage = + Text.concat + [ "insertABOBBoundary: epoch " + , textShow (Byron.boundaryEpoch $ Byron.boundaryHeader blk) + , ", hash " + , Byron.renderAbstractHash (Byron.boundaryHashAnnotated blk) + ] + } insertABlock :: (MonadBaseControl IO m, MonadIO m) => @@ -144,6 +150,7 @@ insertABlock :: SlotDetails -> ExceptT SyncNodeError (ReaderT SqlBackend m) () insertABlock syncEnv firstBlockOfEpoch blk details = do + let logCtx = initLogCtx "insertABlock" "Cardano.DbSync.Era.Byron.Insert" pbid <- queryPrevBlockWithCache "insertABlock" cache (Byron.blockPreviousHash blk) slid <- lift . DB.insertSlotLeader $ Byron.mkSlotLeader blk let txs = Byron.blockPayload blk @@ -189,32 +196,44 @@ insertABlock syncEnv firstBlockOfEpoch blk details = do } liftIO $ do - let epoch = unEpochNo (sdEpochNo details) + let epochNumber = unEpochNo (sdEpochNo details) slotWithinEpoch = unEpochSlot (sdEpochSlot details) followingClosely = getSyncStatus details == SyncFollowing when (followingClosely && slotWithinEpoch /= 0 && Byron.blockNumber blk `mod` 20 == 0) $ do - logInfo tracer $ - mconcat - [ "Insert Byron Block: continuing epoch " - , textShow epoch - , " (slot " - , textShow slotWithinEpoch - , "/" - , textShow (unEpochSize $ sdEpochSize details) - , ")" - ] + logInfoCtx tracer $ + logCtx + { lcEpochNo = Just epochNumber + , lcBlockNo = Just $ Byron.blockNumber blk + , lcSlotNo = Just slotWithinEpoch + , lcMessage = + mconcat + [ "Insert Byron Block: continuing epoch " + , textShow epochNumber + , " (slot " + , textShow slotWithinEpoch + , "/" + , textShow (unEpochSize $ sdEpochSize details) + , ")" + ] + } logger followingClosely tracer $ - mconcat - [ "Insert Byron Block: epoch " - , textShow (unEpochNo $ sdEpochNo details) - , ", slot " - , textShow (Byron.slotNumber blk) - , ", block " - , textShow (Byron.blockNumber blk) - , ", hash " - , renderByteArray (Byron.blockHash blk) - ] + logCtx + { lcEpochNo = Just epochNumber + , lcBlockNo = Just $ Byron.blockNumber blk + , lcSlotNo = Just slotWithinEpoch + , lcMessage = + mconcat + [ "Insert Byron Block: epoch " + , textShow (unEpochNo $ sdEpochNo details) + , ", slot " + , textShow (Byron.slotNumber blk) + , ", block " + , textShow (Byron.blockNumber blk) + , ", hash " + , renderByteArray (Byron.blockHash blk) + ] + } where tracer :: Trace IO Text tracer = getTrace syncEnv @@ -222,12 +241,12 @@ insertABlock syncEnv firstBlockOfEpoch blk details = do cache :: CacheStatus cache = envCache syncEnv - logger :: Bool -> Trace IO a -> a -> IO () + logger :: Bool -> Trace IO Text -> LogContext -> IO () logger followingClosely - | firstBlockOfEpoch = logInfo - | followingClosely = logInfo - | Byron.blockNumber blk `mod` 1000 == 0 = logInfo - | otherwise = logDebug + | firstBlockOfEpoch = logInfoCtx + | followingClosely = logInfoCtx + | Byron.blockNumber blk `mod` 1000 == 0 = logInfoCtx + | otherwise = logDebugCtx insertByronTx :: (MonadBaseControl IO m, MonadIO m) => diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Shelley/Genesis.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Shelley/Genesis.hs index 0dcde23af..6c9c11539 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Shelley/Genesis.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Shelley/Genesis.hs @@ -11,7 +11,7 @@ module Cardano.DbSync.Era.Shelley.Genesis ( insertValidateGenesisDist, ) where -import Cardano.BM.Trace (Trace, logError, logInfo) +import Cardano.BM.Trace (Trace, logError) import qualified Cardano.Db as DB import qualified Cardano.Db.Schema.Core.TxOut as C import qualified Cardano.Db.Schema.Variant.TxOut as V @@ -26,6 +26,7 @@ import Cardano.DbSync.Era.Universal.Insert.Pool (insertPoolRegister) import Cardano.DbSync.Era.Util (liftLookupFail) import Cardano.DbSync.Error import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import Cardano.Ledger.Address (serialiseAddr) import qualified Cardano.Ledger.Coin as Ledger import qualified Cardano.Ledger.Core as Core @@ -88,12 +89,13 @@ insertValidateGenesisDist syncEnv networkName cfg shelleyInitiation = do insertAction :: (MonadBaseControl IO m, MonadIO m) => Bool -> ReaderT SqlBackend m (Either SyncNodeError ()) insertAction prunes = do + let logCtx = initLogCtx "insertValidateGenesisDist" "Shelley" ebid <- DB.queryBlockId (configGenesisHash cfg) case ebid of Right bid -> validateGenesisDistribution syncEnv prunes networkName cfg bid expectedTxCount Left _ -> runExceptT $ do - liftIO $ logInfo tracer "Inserting Shelley Genesis distribution" + liftIO $ logInfoCtx tracer logCtx {lcMessage = "Inserting Shelley Genesis distribution"} emeta <- lift DB.queryMeta case emeta of Right _ -> pure () -- Metadata from Shelley era already exists. TODO Validate metadata. @@ -129,7 +131,7 @@ insertValidateGenesisDist syncEnv networkName cfg shelleyInitiation = do -- This means the previous block will have two blocks after it, resulting in a -- tree format, which is unavoidable. pid <- lift DB.queryLatestBlockId - liftIO $ logInfo tracer $ textShow pid + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = textShow pid} bid <- lift . DB.insertBlock $ DB.Block @@ -154,9 +156,8 @@ insertValidateGenesisDist syncEnv networkName cfg shelleyInitiation = do disInOut <- liftIO $ getDisableInOutState syncEnv unless disInOut $ do lift $ mapM_ (insertTxOuts syncEnv tracer bid) $ genesisUtxOs cfg - liftIO . logInfo tracer $ - "Initial genesis distribution populated. Hash " - <> renderByteArray (configGenesisHash cfg) + liftIO . logInfoCtx tracer $ + logCtx {lcMessage = "Initial genesis distribution populated. Hash " <> renderByteArray (configGenesisHash cfg)} when hasStakes $ insertStaking tracer useNoCache bid cfg @@ -170,11 +171,12 @@ validateGenesisDistribution :: DB.BlockId -> Word64 -> ReaderT SqlBackend m (Either SyncNodeError ()) -validateGenesisDistribution syncEnv prunes networkName cfg bid expectedTxCount = +validateGenesisDistribution syncEnv prunes networkName cfg bid expectedTxCount = do + let logCtx = initLogCtx "validateGenesisDistribution" "Shelley" runExceptT $ do let tracer = getTrace syncEnv txOutTableType = getTxOutTableType syncEnv - liftIO $ logInfo tracer "Validating Genesis distribution" + liftIO $ logInfoCtx tracer logCtx {lcMessage = "Validating Genesis distribution"} meta <- liftLookupFail "Shelley.validateGenesisDistribution" DB.queryMeta when (DB.metaStartTime meta /= configStartTime cfg) $ @@ -215,10 +217,8 @@ validateGenesisDistribution syncEnv prunes networkName cfg bid expectedTxCount = , textShow totalSupply ] liftIO $ do - logInfo tracer "Initial genesis distribution present and correct" - logInfo tracer ("Total genesis supply of Ada: " <> DB.renderAda totalSupply) - --- ----------------------------------------------------------------------------- + logInfoCtx tracer $ logCtx {lcMessage = "Initial genesis distribution present and correct"} + logInfoCtx tracer $ logCtx {lcMessage = "Total genesis supply of Ada: " <> DB.renderAda totalSupply} insertTxOuts :: (MonadBaseControl IO m, MonadIO m) => diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Adjust.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Adjust.hs index 942e6fc82..703933baa 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Adjust.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Adjust.hs @@ -7,7 +7,7 @@ module Cardano.DbSync.Era.Universal.Adjust ( adjustEpochRewards, ) where -import Cardano.BM.Trace (Trace, logInfo) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db as Db import Cardano.DbSync.Cache ( queryPoolKeyWithCache, @@ -16,6 +16,7 @@ import Cardano.DbSync.Cache ( import Cardano.DbSync.Cache.Types (CacheAction (..), CacheStatus) import qualified Cardano.DbSync.Era.Shelley.Generic.Rewards as Generic import Cardano.DbSync.Types (StakeCred) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import Cardano.Ledger.BaseTypes (Network) import Cardano.Prelude hiding (from, groupBy, on) import Cardano.Slotting.Slot (EpochNo (..)) @@ -57,13 +58,18 @@ adjustEpochRewards :: ReaderT SqlBackend m () adjustEpochRewards trce nw cache epochNo rwds creds = do let eraIgnored = Map.toList $ Generic.unRewards rwds - liftIO . logInfo trce $ - mconcat - [ "Removing " - , if null eraIgnored then "" else textShow (length eraIgnored) <> " rewards and " - , show (length creds) - , " orphaned rewards" - ] + logCtx = initLogCtx "adjustEpochRewards" "Cardano.DbSync.Era.Universal.Adjust" + liftIO . logInfoCtx trce $ + logCtx + { lcEpochNo = Just (unEpochNo epochNo) + , lcMessage = + mconcat + [ "Removing " + , if null eraIgnored then "" else textShow (length eraIgnored) <> " rewards and " + , show (length creds) + , " orphaned rewards" + ] + } forM_ eraIgnored $ \(cred, rewards) -> forM_ (Set.toList rewards) $ \rwd -> deleteReward trce nw cache epochNo (cred, rwd) diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Block.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Block.hs index 2eed5603c..af189605b 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Block.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Block.hs @@ -11,7 +11,7 @@ module Cardano.DbSync.Era.Universal.Block ( insertBlockUniversal, ) where -import Cardano.BM.Trace (Trace, logDebug, logInfo) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types (InsertOptions (..), SyncEnv (..), SyncOptions (..)) @@ -40,6 +40,7 @@ import qualified Cardano.Ledger.BaseTypes as Ledger import Cardano.Ledger.Keys import Cardano.Prelude +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logDebugCtx, logInfoCtx) import Control.Monad.Trans.Control (MonadBaseControl) import Control.Monad.Trans.Except.Extra (newExceptT) import Data.Either.Extra (eitherToMaybe) @@ -52,7 +53,7 @@ import Database.Persist.Sql (SqlBackend) insertBlockUniversal :: (MonadBaseControl IO m, MonadIO m) => SyncEnv -> - -- | Should log + -- | Is start event or rollback Bool -> -- | Within two minutes Bool -> @@ -63,7 +64,8 @@ insertBlockUniversal :: IsPoolMember -> ApplyResult -> ReaderT SqlBackend m (Either SyncNodeError ()) -insertBlockUniversal syncEnv shouldLog withinTwoMins withinHalfHour blk details isMember applyResult = do +insertBlockUniversal syncEnv isStartEventOrRollback withinTwoMins withinHalfHour blk details isMember applyResult = do + let logCtx = initLogCtx "insertBlockUniversal" "Cardano.DbSync.Era.Universal.Block" runExceptT $ do pbid <- case Generic.blkPreviousHash blk of Nothing -> liftLookupFail (renderErrorMessage (Generic.blkEra blk)) DB.queryGenesis -- this is for networks that fork from Byron on epoch 0. @@ -118,33 +120,43 @@ insertBlockUniversal syncEnv shouldLog withinTwoMins withinHalfHour blk details insertReverseIndex blkId minIds liftIO $ do - let epoch = unEpochNo epochNo - slotWithinEpoch = unEpochSlot (sdEpochSlot details) - + let slotWithinEpoch = unEpochSlot (sdEpochSlot details) when (withinTwoMins && slotWithinEpoch /= 0 && unBlockNo (Generic.blkBlockNo blk) `mod` 20 == 0) $ do - logInfo tracer $ - mconcat - [ renderInsertName (Generic.blkEra blk) - , ": continuing epoch " - , textShow epoch - , " (slot " - , textShow slotWithinEpoch - , "/" - , textShow (unEpochSize $ sdEpochSize details) - , ")" - ] + logInfoCtx tracer $ + logCtx + { lcBlockNo = Just (unBlockNo (Generic.blkBlockNo blk)) + , lcSlotNo = Just (unSlotNo (Generic.blkSlotNo blk)) + , lcEpochNo = Just (unEpochNo epochNo) + , lcMessage = + mconcat + [ renderInsertName (Generic.blkEra blk) + , ": continuing epoch " + , textShow $ unEpochNo epochNo + , " (slot " + , textShow slotWithinEpoch + , "/" + , textShow (unEpochSize $ sdEpochSize details) + , ")" + ] + } logger tracer $ - mconcat - [ renderInsertName (Generic.blkEra blk) - , ": epoch " - , textShow (unEpochNo epochNo) - , ", slot " - , textShow (unSlotNo $ Generic.blkSlotNo blk) - , ", block " - , textShow (unBlockNo $ Generic.blkBlockNo blk) - , ", hash " - , renderByteArray (Generic.blkHash blk) - ] + logCtx + { lcBlockNo = Just (unBlockNo (Generic.blkBlockNo blk)) + , lcSlotNo = Just (unSlotNo (Generic.blkSlotNo blk)) + , lcEpochNo = Just (unEpochNo epochNo) + , lcMessage = + mconcat + [ renderInsertName (Generic.blkEra blk) + , ": epoch " + , textShow (unEpochNo epochNo) + , ", slot " + , textShow (unSlotNo $ Generic.blkSlotNo blk) + , ", block " + , textShow (unBlockNo $ Generic.blkBlockNo blk) + , ", hash " + , renderByteArray (Generic.blkHash blk) + ] + } whenStrictJust (apNewEpoch applyResult) $ \newEpoch -> do insertOnNewEpoch syncEnv blkId (Generic.blkSlotNo blk) epochNo newEpoch @@ -161,12 +173,12 @@ insertBlockUniversal syncEnv shouldLog withinTwoMins withinHalfHour blk details where iopts = getInsertOptions syncEnv - logger :: Trace IO a -> a -> IO () + logger :: Trace IO Text -> LogContext -> IO () logger - | shouldLog = logInfo - | withinTwoMins = logInfo - | unBlockNo (Generic.blkBlockNo blk) `mod` 5000 == 0 = logInfo - | otherwise = logDebug + | isStartEventOrRollback = logInfoCtx + | withinTwoMins = logInfoCtx + | unBlockNo (Generic.blkBlockNo blk) `mod` 5000 == 0 = logInfoCtx + | otherwise = logDebugCtx renderInsertName :: Generic.BlockEra -> Text renderInsertName eraText = diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Epoch.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Epoch.hs index cc1f86205..cdd611a5f 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Epoch.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Epoch.hs @@ -22,7 +22,7 @@ module Cardano.DbSync.Era.Universal.Epoch ( sumRewardTotal, ) where -import Cardano.BM.Trace (Trace, logInfo) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types (InsertOptions (..), SyncEnv (..)) @@ -37,6 +37,7 @@ import Cardano.DbSync.Ledger.Event import Cardano.DbSync.Types import Cardano.DbSync.Util (whenDefault, whenStrictJust, whenStrictJustDefault) import Cardano.DbSync.Util.Constraint (constraintNameEpochStake, constraintNameReward) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import Cardano.Ledger.Address (RewardAccount (..)) import Cardano.Ledger.BaseTypes (Network, unEpochInterval) import qualified Cardano.Ledger.BaseTypes as Ledger @@ -205,12 +206,14 @@ insertStakeSlice syncEnv (Generic.Slice slice finalSlice) = do lift $ DB.updateSetComplete $ unEpochNo $ Generic.sliceEpochNo slice size <- lift $ DB.queryEpochStakeCount (unEpochNo $ Generic.sliceEpochNo slice) liftIO - . logInfo tracer - $ mconcat ["Inserted ", show size, " EpochStake for ", show (Generic.sliceEpochNo slice)] + . logInfoCtx tracer + $ logCtx {lcMessage = mconcat ["Inserted ", show size, " EpochStake for ", show (Generic.sliceEpochNo slice)]} where tracer :: Trace IO Text tracer = getTrace syncEnv + logCtx = initLogCtx "insertStakeSlice" "Cardano.DbSync.Era.Universal.Epoch" + network :: Network network = getNetwork syncEnv @@ -379,8 +382,9 @@ insertPoolDepositRefunds :: ExceptT SyncNodeError (ReaderT SqlBackend m) () insertPoolDepositRefunds syncEnv epochNo refunds = do insertRewards syncEnv nw epochNo epochNo (envCache syncEnv) (Map.toList rwds) - liftIO . logInfo tracer $ "Inserted " <> show (Generic.rewardsCount refunds) <> " deposit refund rewards" + liftIO . logInfoCtx tracer $ logCtx {lcMessage = "Inserted " <> show (Generic.rewardsCount refunds) <> " deposit refund rewards"} where + logCtx = initLogCtx "insertPoolDepositRefunds" "Cardano.DbSync.Era.Universal.Epoch" tracer = getTrace syncEnv rwds = Generic.unRewards refunds nw = getNetwork syncEnv diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Certificate.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Certificate.hs index 46aac293a..b7cf7f8c9 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Certificate.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Certificate.hs @@ -22,7 +22,7 @@ module Cardano.DbSync.Era.Universal.Insert.Certificate ( mkAdaPots, ) where -import Cardano.BM.Trace (Trace, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types (InsertOptions (..), SyncEnv (..)) @@ -38,6 +38,7 @@ import Cardano.DbSync.Era.Universal.Insert.Pool (IsPoolMember, insertPoolCert) import Cardano.DbSync.Error import Cardano.DbSync.Types import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logWarningCtx) import Cardano.Ledger.BaseTypes import qualified Cardano.Ledger.BaseTypes as Ledger import Cardano.Ledger.CertState @@ -80,7 +81,8 @@ insertCertificate syncEnv isMember mDeposits blkId txId epochNo slotNo redeemers Left (ShelleyTxCertGenesisDeleg _gen) -> when (ioShelley iopts) $ liftIO $ - logWarning tracer "insertCertificate: Unhandled DCertGenesis certificate" + logWarningCtx tracer $ + logCtx {lcMessage = "insertCertificate: Unhandled DCertGenesis certificate"} Right (ConwayTxCertDeleg deleg) -> insertConwayDelegCert syncEnv mDeposits txId idx mRedeemerId epochNo slotNo deleg Right (ConwayTxCertPool pool) -> @@ -98,6 +100,7 @@ insertCertificate syncEnv isMember mDeposits blkId txId epochNo slotNo redeemers ConwayUpdateDRep cred anchor -> lift $ insertDrepRegistration blkId txId idx cred Nothing (strictMaybeToMaybe anchor) where + logCtx = initLogCtx "insertCertificate" "Cardano.DbSync.Era.Universal.Insert.Certificate" tracer = getTrace syncEnv cache = envCache syncEnv iopts = getInsertOptions syncEnv diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/GovAction.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/GovAction.hs index 6de4a5362..8823b9a99 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/GovAction.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/GovAction.hs @@ -28,7 +28,7 @@ module Cardano.DbSync.Era.Universal.Insert.GovAction ( ) where -import Cardano.BM.Trace (Trace, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Crypto as Crypto import Cardano.Db (DbWord64 (..)) import qualified Cardano.Db as DB @@ -42,6 +42,7 @@ import Cardano.DbSync.Error import Cardano.DbSync.Ledger.State import Cardano.DbSync.Util import Cardano.DbSync.Util.Bech32 (serialiseDrepToBech32) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logWarningCtx) import Cardano.Ledger.BaseTypes import qualified Cardano.Ledger.BaseTypes as Ledger import Cardano.Ledger.CertState (DRep (..)) @@ -114,6 +115,7 @@ insertGovActionProposal trce cache blkId txId govExpiresAt mcgs (index, (govId, NewConstitution _ constitution -> lift $ void $ insertConstitution blkId (Just govActionProposalId) constitution _ -> pure () where + logCtx = initLogCtx "insertGovActionProposal" "Cardano.DbSync.Era.Universal.Insert.GovAction" mprevGovAction :: Maybe (GovActionId StandardCrypto) = case pProcGovAction pp of ParameterChange prv _ _ -> unGovPurposeId <$> strictMaybeToMaybe prv HardForkInitiation prv _ -> unGovPurposeId <$> strictMaybeToMaybe prv @@ -140,7 +142,9 @@ insertGovActionProposal trce cache blkId txId govExpiresAt mcgs (index, (govId, case findProposedCommittee govId cgs of Right (Just committee) -> void $ insertCommittee (Just govActionProposalId) committee other -> - liftIO $ logWarning trce $ textShow other <> ": Failed to find committee for " <> textShow pp + liftIO $ + logWarningCtx trce $ + logCtx {lcMessage = textShow other <> ": Failed to find committee for " <> textShow pp} insertCommittee :: (MonadIO m, MonadBaseControl IO m) => Maybe DB.GovActionProposalId -> Committee StandardConway -> ReaderT SqlBackend m DB.CommitteeId insertCommittee mgapId committee = do @@ -441,6 +445,7 @@ insertUpdateEnacted trce cache blkId epochNo enactedState = do , DB.epochStateEpochNo = unEpochNo epochNo } where + logCtx = initLogCtx "insertUpdateEnacted" "Cardano.DbSync.Era.Universal.Insert.GovAction" govIds = govStatePrevGovActionIds enactedState handleCommittee = do @@ -470,13 +475,16 @@ insertUpdateEnacted trce cache blkId epochNo enactedState = do -- This should never happen. Having a committee and an enacted action, means -- the committee came from a proposal which should be returned from the query. liftIO $ - logWarning trce $ - mconcat - [ "The impossible happened! Couldn't find the committee " - , textShow committee - , " which was enacted by a proposal " - , textShow committeeGaId - ] + logWarningCtx trce $ + logCtx + { lcMessage = + mconcat + [ "The impossible happened! Couldn't find the committee " + , textShow committee + , " which was enacted by a proposal " + , textShow committeeGaId + ] + } pure (Nothing, Nothing) (committeeId : _rest) -> pure (Just committeeId, Nothing) @@ -495,11 +503,14 @@ insertUpdateEnacted trce cache blkId epochNo enactedState = do constitutionId : rest -> do unless (null rest) $ liftIO $ - logWarning trce $ - mconcat - [ "Found multiple constitutions for proposal " - , textShow mConstitutionGaId - , ": " - , textShow constitutionIds - ] + logWarningCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Found multiple constitutions for proposal " + , textShow mConstitutionGaId + , ": " + , textShow constitutionIds + ] + } pure constitutionId diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Grouped.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Grouped.hs index dc6b61234..639331824 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Grouped.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Grouped.hs @@ -14,7 +14,7 @@ module Cardano.DbSync.Era.Universal.Insert.Grouped ( mkmaTxOuts, ) where -import Cardano.BM.Trace (Trace, logWarning) +import Cardano.BM.Trace (Trace) import Cardano.Db (DbLovelace (..), MinIds (..), minIdsCoreToText, minIdsVariantToText) import qualified Cardano.Db as DB import qualified Cardano.Db.Schema.Core.TxOut as C @@ -26,6 +26,7 @@ import qualified Cardano.DbSync.Era.Shelley.Generic as Generic import Cardano.DbSync.Era.Shelley.Query import Cardano.DbSync.Era.Util import Cardano.DbSync.Error +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx) import Cardano.Prelude import Control.Monad.Trans.Control (MonadBaseControl) import qualified Data.List as List @@ -157,7 +158,10 @@ prepareUpdates :: prepareUpdates trce eti = case etiTxOutId eti of Right txOutId -> pure $ Just (txOutId, DB.txInTxInId (etiTxIn eti)) Left _ -> do - liftIO $ logWarning trce $ "Failed to find output for " <> Text.pack (show eti) + let logCtx = initLogCtx "prepareUpdates" "Cardano.DbSync.Era.Universal.Insert.Grouped" + liftIO $ + logErrorCtx trce $ + logCtx {lcMessage = "Failed to find output for " <> Text.pack (show eti)} pure Nothing insertReverseIndex :: diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/LedgerEvent.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/LedgerEvent.hs index c4938e8f6..6846ca36f 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/LedgerEvent.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/LedgerEvent.hs @@ -10,7 +10,6 @@ module Cardano.DbSync.Era.Universal.Insert.LedgerEvent ( insertNewEpochLedgerEvents, ) where -import Cardano.BM.Trace (logInfo) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types (SyncEnv (..)) @@ -25,6 +24,7 @@ import Cardano.DbSync.Error import Cardano.DbSync.Ledger.Event import Cardano.DbSync.Types import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import qualified Cardano.Ledger.Address as Ledger import Cardano.Prelude import Cardano.Slotting.Slot (EpochNo (..)) @@ -47,6 +47,7 @@ insertNewEpochLedgerEvents :: insertNewEpochLedgerEvents syncEnv currentEpochNo@(EpochNo curEpoch) = mapM_ handler where + logCtx = initLogCtx "insertNewEpochLedgerEvents" "Cardano.DbSync.Era.Universal.Insert.LedgerEvent" tracer = getTrace syncEnv cache = envCache syncEnv ntw = getNetwork syncEnv @@ -72,19 +73,19 @@ insertNewEpochLedgerEvents syncEnv currentEpochNo@(EpochNo curEpoch) = insertEpochSyncTime en (toSyncState ss) (envEpochSyncTime syncEnv) sqlBackend <- lift ask persistantCacheSize <- liftIO $ statementCacheSize $ connStmtMap sqlBackend - liftIO . logInfo tracer $ "Persistant SQL Statement Cache size is " <> textShow persistantCacheSize + liftIO . logInfoCtx tracer $ logCtx {lcMessage = "Persistant SQL Statement Cache size is " <> textShow persistantCacheSize} stats <- liftIO $ textShowStats cache - liftIO . logInfo tracer $ stats - liftIO . logInfo tracer $ "Starting epoch " <> textShow (unEpochNo en) + liftIO . logInfoCtx tracer $ logCtx {lcMessage = stats} + liftIO . logInfoCtx tracer $ logCtx {lcMessage = "Starting epoch " <> textShow (unEpochNo en)} LedgerStartAtEpoch en -> -- This is different from the previous case in that the db-sync started -- in this epoch, for example after a restart, instead of after an epoch boundary. - liftIO . logInfo tracer $ "Starting at epoch " <> textShow (unEpochNo en) + liftIO . logInfoCtx tracer $ logCtx {lcMessage = "Starting at epoch " <> textShow (unEpochNo en)} LedgerDeltaRewards _e rwd -> do let rewards = Map.toList $ Generic.unRewards rwd insertRewards syncEnv ntw (subFromCurrentEpoch 2) currentEpochNo cache (Map.toList $ Generic.unRewards rwd) -- This event is only created when it's not empty, so we don't need to check for null here. - liftIO . logInfo tracer $ "Inserted " <> show (length rewards) <> " Delta rewards" + liftIO . logInfoCtx tracer $ logCtx {lcMessage = "Inserted " <> show (length rewards) <> " Delta rewards"} LedgerIncrementalRewards _ rwd -> do let rewards = Map.toList $ Generic.unRewards rwd insertRewards syncEnv ntw (subFromCurrentEpoch 1) (EpochNo $ curEpoch + 1) cache rewards @@ -97,8 +98,8 @@ insertNewEpochLedgerEvents syncEnv currentEpochNo@(EpochNo curEpoch) = LedgerGovInfo enacted dropped expired uncl -> do unless (Set.null uncl) $ liftIO $ - logInfo tracer $ - "Found " <> textShow (Set.size uncl) <> " unclaimed proposal refunds" + logInfoCtx tracer $ + logCtx {lcMessage = "Found " <> textShow (Set.size uncl) <> " unclaimed proposal refunds"} updateDropped cache (EpochNo curEpoch) (garGovActionId <$> (dropped <> expired)) let refunded = filter (\e -> Set.notMember (garGovActionId e) uncl) (enacted <> dropped <> expired) insertProposalRefunds tracer ntw (subFromCurrentEpoch 1) currentEpochNo cache refunded -- TODO: check if they are disjoint to avoid double entries. @@ -112,7 +113,7 @@ insertNewEpochLedgerEvents syncEnv currentEpochNo@(EpochNo curEpoch) = unless (Map.null rwd) $ do let rewards = Map.toList rwd insertRewardRests tracer ntw (subFromCurrentEpoch 1) currentEpochNo cache rewards - liftIO . logInfo tracer $ "Inserted " <> show (length rewards) <> " Mir rewards" + liftIO . logInfoCtx tracer $ logCtx {lcMessage = "Inserted " <> show (length rewards) <> " Mir rewards"} LedgerPoolReap en drs -> unless (Map.null $ Generic.unRewards drs) $ do insertPoolDepositRefunds syncEnv en drs diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Other.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Other.hs index 4099e8427..6b23ae43c 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Other.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Other.hs @@ -165,12 +165,13 @@ insertStakeAddressRefIfMissing trce cache addr = insertMultiAsset :: (MonadBaseControl IO m, MonadIO m) => + Trace IO Text -> CacheStatus -> PolicyID StandardCrypto -> AssetName -> ReaderT SqlBackend m DB.MultiAssetId -insertMultiAsset cache policy aName = do - mId <- queryMAWithCache cache policy aName +insertMultiAsset trce cache policy aName = do + mId <- queryMAWithCache trce cache policy aName case mId of Right maId -> pure maId Left (policyBs, assetNameBs) -> diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Tx.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Tx.hs index 8674e1f02..b76dbec84 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Tx.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Insert/Tx.hs @@ -350,7 +350,7 @@ insertMaTxMint :: DB.TxId -> MultiAsset StandardCrypto -> ExceptT SyncNodeError (ReaderT SqlBackend m) [DB.MaTxMint] -insertMaTxMint _tracer cache txId (MultiAsset mintMap) = +insertMaTxMint trce cache txId (MultiAsset mintMap) = concatMapM (lift . prepareOuter) $ Map.toList mintMap where prepareOuter :: @@ -366,7 +366,7 @@ insertMaTxMint _tracer cache txId (MultiAsset mintMap) = (AssetName, Integer) -> ReaderT SqlBackend m DB.MaTxMint prepareInner policy (aname, amount) = do - maId <- insertMultiAsset cache policy aname + maId <- insertMultiAsset trce cache policy aname pure $ DB.MaTxMint { DB.maTxMintIdent = maId @@ -380,7 +380,7 @@ insertMaTxOuts :: CacheStatus -> Map (PolicyID StandardCrypto) (Map AssetName Integer) -> ExceptT SyncNodeError (ReaderT SqlBackend m) [MissingMaTxOut] -insertMaTxOuts _tracer cache maMap = +insertMaTxOuts trce cache maMap = concatMapM (lift . prepareOuter) $ Map.toList maMap where prepareOuter :: @@ -396,7 +396,7 @@ insertMaTxOuts _tracer cache maMap = (AssetName, Integer) -> ReaderT SqlBackend m MissingMaTxOut prepareInner policy (aname, amount) = do - maId <- insertMultiAsset cache policy aname + maId <- insertMultiAsset trce cache policy aname pure $ MissingMaTxOut { mmtoIdent = maId diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Validate.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Validate.hs index d155df128..0ad8ab3fa 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Validate.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Universal/Validate.hs @@ -9,12 +9,13 @@ module Cardano.DbSync.Era.Universal.Validate ( validateEpochRewards, ) where -import Cardano.BM.Trace (Trace, logError, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import Cardano.Db (DbLovelace, RewardSource) import qualified Cardano.Db as Db import qualified Cardano.DbSync.Era.Shelley.Generic as Generic import Cardano.DbSync.Ledger.Event import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx, logInfoCtx, logWarningCtx) import Cardano.Ledger.Coin (Coin (..)) import Cardano.Ledger.Crypto (StandardCrypto) import Cardano.Ledger.Shelley.API (Network) @@ -57,27 +58,34 @@ validateEpochRewards :: Map StakeCred (Set (Ledger.Reward StandardCrypto)) -> ReaderT SqlBackend m () validateEpochRewards tracer network _earnedEpochNo spendableEpochNo rmap = do + let logCtx = initLogCtx "validateEpochRewards" "Cardano.DbSync.Era.Universal.Validate" actualCount <- Db.queryNormalEpochRewardCount (unEpochNo spendableEpochNo) if actualCount /= expectedCount then do - liftIO . logWarning tracer $ - mconcat - [ "validateEpochRewards: rewards spendable in epoch " - , textShow (unEpochNo spendableEpochNo) - , " expected total of " - , textShow expectedCount - , " but got " - , textShow actualCount - ] + liftIO . logWarningCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "validateEpochRewards: rewards spendable in epoch " + , textShow (unEpochNo spendableEpochNo) + , " expected total of " + , textShow expectedCount + , " but got " + , textShow actualCount + ] + } logFullRewardMap tracer spendableEpochNo network (convertPoolRewards rmap) else do - liftIO . logInfo tracer $ - mconcat - [ "Validate Epoch Rewards: total rewards that become spendable in epoch " - , textShow (unEpochNo spendableEpochNo) - , " are " - , textShow actualCount - ] + liftIO . logInfoCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "Validate Epoch Rewards: total rewards that become spendable in epoch " + , textShow (unEpochNo spendableEpochNo) + , " are " + , textShow actualCount + ] + } where expectedCount :: Word64 expectedCount = fromIntegral . sum $ map Set.size (Map.elems rmap) @@ -137,8 +145,8 @@ diffRewardMap :: IO () diffRewardMap tracer _nw dbMap ledgerMap = do when (Map.size diffMap > 0) $ do - logError tracer "diffRewardMap:" - mapM_ (logError tracer . render) $ Map.toList diffMap + let logCtx = initLogCtx "diffRewardMap" "Cardano.DbSync.Era.Universal.Validate" + logErrorCtx tracer logCtx {lcMessage = mconcat $ map render (Map.toList diffMap)} where keys :: [ByteString] keys = List.nubOrd (Map.keys dbMap ++ Map.keys ledgerMap) diff --git a/cardano-db-sync/src/Cardano/DbSync/Era/Util.hs b/cardano-db-sync/src/Cardano/DbSync/Era/Util.hs index e9a4a5430..76827cdd9 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Era/Util.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Era/Util.hs @@ -8,9 +8,10 @@ module Cardano.DbSync.Era.Util ( safeDecodeToJson, ) where -import Cardano.BM.Trace (Trace, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db as DB import Cardano.DbSync.Error +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logWarningCtx) import Cardano.Prelude import Control.Monad.Trans.Except.Extra (firstExceptT, newExceptT) import qualified Data.ByteString.Char8 as BS @@ -35,18 +36,17 @@ containsUnicodeNul = Text.isInfixOf "\\u000" safeDecodeToJson :: MonadIO m => Trace IO Text -> Text -> ByteString -> m (Maybe Text) safeDecodeToJson tracer tracePrefix jsonBs = do + let logCtx = initLogCtx "safeDecodeToJson" "Cardano.DbSync.Era.Util" ejson <- liftIO $ safeDecodeUtf8 jsonBs case ejson of Left err -> do - liftIO . logWarning tracer $ - mconcat - [tracePrefix, ": Could not decode to UTF8: ", textShow err] + liftIO . logWarningCtx tracer $ logCtx {lcMessage = mconcat [tracePrefix, ": Could not decode to UTF8: ", textShow err]} -- We have to insert pure Nothing Right json -> -- See https://github.com/IntersectMBO/cardano-db-sync/issues/297 if containsUnicodeNul json then do - liftIO $ logWarning tracer $ tracePrefix <> "was recorded as null, due to a Unicode NUL character found when trying to parse the json." + liftIO $ logWarningCtx tracer $ logCtx {lcMessage = tracePrefix <> "was recorded as null, due to a Unicode NUL character found when trying to parse the json."} pure Nothing else pure $ Just json diff --git a/cardano-db-sync/src/Cardano/DbSync/Fix/ConsumedBy.hs b/cardano-db-sync/src/Cardano/DbSync/Fix/ConsumedBy.hs index e340706e5..dcd58f3eb 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Fix/ConsumedBy.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Fix/ConsumedBy.hs @@ -2,7 +2,7 @@ module Cardano.DbSync.Fix.ConsumedBy (FixEntry, fixConsumedBy, fixEntriesConsumed) where -import Cardano.BM.Trace (Trace, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Chain.Block as Byron hiding (blockHash) import qualified Cardano.Chain.UTxO as Byron import qualified Cardano.Crypto as Crypto (serializeCborHash) @@ -14,6 +14,7 @@ import Cardano.DbSync.Era.Byron.Util (blockPayload, unTxHash) import Cardano.DbSync.Era.Util import Cardano.DbSync.Error import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logWarningCtx) import Cardano.Prelude hiding (length, (.)) import Database.Persist.SqlBackend.Internal import Ouroboros.Consensus.Byron.Ledger (ByronBlock (..)) @@ -35,14 +36,18 @@ fixBlock backend syncEnv bblk = case byronBlockRaw bblk of case mEntries of Right newEntries -> pure $ Just $ concat newEntries Left err -> do + let logCtx = initLogCtx "fixBlock" "Cardano.DbSync.Fix.ConsumedBy" liftIO $ - logWarning (getTrace syncEnv) $ - mconcat - [ "While fixing block " - , textShow bblk - , ", encountered error " - , textShow err - ] + logWarningCtx (getTrace syncEnv) $ + logCtx + { lcMessage = + mconcat + [ "While fixing block " + , textShow bblk + , ", encountered error " + , textShow err + ] + } pure Nothing fixTx :: MonadIO m => SyncEnv -> Byron.TxAux -> ExceptT SyncNodeError (ReaderT SqlBackend m) [FixEntry] diff --git a/cardano-db-sync/src/Cardano/DbSync/Fix/EpochStake.hs b/cardano-db-sync/src/Cardano/DbSync/Fix/EpochStake.hs index c1ff28caf..b793aebdc 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Fix/EpochStake.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Fix/EpochStake.hs @@ -3,7 +3,6 @@ module Cardano.DbSync.Fix.EpochStake where -import Cardano.BM.Trace (logInfo, logWarning) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types @@ -12,6 +11,7 @@ import Cardano.DbSync.Era.Universal.Epoch import Cardano.DbSync.Error import Cardano.DbSync.Ledger.State import Cardano.DbSync.Ledger.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import Cardano.Prelude import Control.Monad.Trans.Control import qualified Data.Map.Strict as Map @@ -24,7 +24,7 @@ migrateStakeDistr env mcls = (HasLedger lenv, Strict.Just cls) -> do ems <- lift DB.queryAllExtraMigrations runWhen (not $ DB.isStakeDistrComplete ems) $ do - liftIO $ logInfo trce "Starting Stake Distribution migration on table epoch_stake" + liftIO $ logInfoCtx trce $ logCtx {lcMessage = "Starting Stake Distribution migration on table epoch_stake"} let stakeSlice = getStakeSlice lenv cls True case stakeSlice of NoSlices -> @@ -44,6 +44,7 @@ migrateStakeDistr env mcls = lift $ DB.insertExtraMigration DB.StakeDistrEnded _ -> pure False where + logCtx = initLogCtx "migrateStakeDistr" "Cardano.DbSync.Fix.EpochStake" trce = getTrace env mkProgress isCompleted e = DB.EpochStakeProgress @@ -53,18 +54,21 @@ migrateStakeDistr env mcls = logInsert :: Int -> IO () logInsert n - | n == 0 = logInfo trce "No missing epoch_stake found" - | n > 100000 = logWarning trce $ "Found " <> textShow n <> " epoch_stake. This may take a while" - | otherwise = logInfo trce $ "Found " <> textShow n <> " epoch_stake" + | n == 0 = logInfoCtx trce $ logCtx {lcMessage = "No missing epoch_stake found"} + | n > 100000 = logWarningCtx trce $ logCtx {lcMessage = "Found " <> textShow n <> " epoch_stake. This may take a while"} + | otherwise = logInfoCtx trce $ logCtx {lcMessage = "Found " <> textShow n <> " epoch_stake"} logMinMax mmin mmax = - logInfo trce $ - mconcat - [ "Min epoch_stake at " - , textShow mmin - , " and max at " - , textShow mmax - ] + logInfoCtx trce $ + logCtx + { lcMessage = + mconcat + [ "Min epoch_stake at " + , textShow mmin + , " and max at " + , textShow mmax + ] + } runWhen :: Monad m => Bool -> m () -> m Bool runWhen a action = do diff --git a/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusDataBytes.hs b/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusDataBytes.hs index 29e189867..b253435b2 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusDataBytes.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusDataBytes.hs @@ -11,7 +11,7 @@ module Cardano.DbSync.Fix.PlutusDataBytes where -import Cardano.BM.Trace (Trace, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db.Version.V13_0 as DB_V_13_0 import Cardano.DbSync.Api import Cardano.DbSync.Era.Shelley.Generic.Block @@ -19,6 +19,7 @@ import Cardano.DbSync.Era.Shelley.Generic.Tx.Alonzo import Cardano.DbSync.Era.Shelley.Generic.Tx.Types import Cardano.DbSync.Error (bsBase16Encode) import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import qualified Cardano.Ledger.Alonzo.Tx as Alonzo import qualified Cardano.Ledger.Alonzo.TxWits as Alonzo import qualified Cardano.Ledger.Babbage.TxBody as Babbage @@ -92,13 +93,16 @@ getWrongPlutusData :: ReaderT SqlBackend m FixData getWrongPlutusData tracer = do liftIO $ - logInfo tracer $ - mconcat - [ "Starting the fixing Plutus Data bytes procedure. This may take a couple hours on mainnet if there are wrong values." - , " You can skip it using --skip-plutus-data-fix." - , " It will fix Datum and RedeemerData with wrong bytes. See more in Issue #1214 and #1278." - , " This procedure makes resyncing unnecessary." - ] + logInfoCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "Starting the fixing Plutus Data bytes procedure. This may take a couple hours on mainnet if there are wrong values." + , " You can skip it using --skip-plutus-data-fix." + , " It will fix Datum and RedeemerData with wrong bytes. See more in Issue #1214 and #1278." + , " This procedure makes resyncing unnecessary." + ] + } datumList <- findWrongPlutusData tracer @@ -121,6 +125,7 @@ getWrongPlutusData tracer = do (mapLeft Just . hashPlutusData . getRedeemerDataBytes) pure $ FixData datumList redeemerDataList where + logCtx = initLogCtx "getWrongPlutusData" "Cardano.DbSync.Fix.PlutusDataBytes" f queryRes = do (prevBlockHsh, mPrevSlotNo) <- queryRes prevSlotNo <- mPrevSlotNo @@ -148,34 +153,44 @@ findWrongPlutusData :: m [FixPlutusInfo] findWrongPlutusData tracer tableName qCount qPage qGetInfo getHash getBytes hashBytes = do liftIO $ - logInfo tracer $ - mconcat - ["Trying to find ", tableName, " with wrong bytes"] + logInfoCtx tracer $ + logCtx + { lcMessage = + mconcat + ["Trying to find ", tableName, " with wrong bytes"] + } count <- qCount liftIO $ - logInfo tracer $ - mconcat - ["There are ", textShow count, " ", tableName, ". Need to scan them all."] + logInfoCtx tracer $ + logCtx + { lcMessage = + mconcat + ["There are ", textShow count, " ", tableName, ". Need to scan them all."] + } datums <- findRec False 0 [] liftIO $ - logInfo tracer $ - Text.concat - [ "Found " - , textShow (length datums) - , " " - , tableName - , " with mismatch between bytes and hash." - ] + logInfoCtx tracer $ + logCtx + { lcMessage = + Text.concat + [ "Found " + , textShow (length datums) + , " " + , tableName + , " with mismatch between bytes and hash." + ] + } pure datums where + logCtx = initLogCtx "findWrongPlutusData" "Cardano.DbSync.Fix.PlutusDataBytes" showBytes = maybe "" bsBase16Encode findRec :: Bool -> Int64 -> [[FixPlutusInfo]] -> m [FixPlutusInfo] findRec printedSome offset acc = do when (mod offset (10 * limit) == 0 && offset > 0) $ liftIO $ - logInfo tracer $ - mconcat ["Checked ", textShow offset, " ", tableName] + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Checked ", textShow offset, " ", tableName]} ls <- qPage offset limit ls' <- filterM checkValidBytes ls ls'' <- mapMaybeM convertToFixPlutusInfo ls' @@ -184,11 +199,14 @@ findWrongPlutusData tracer tableName qCount qPage qGetInfo getHash getBytes hash then pure printedSome else do liftIO $ - logInfo tracer $ - Text.concat - [ "Found some wrong values already. The oldest ones are (hash, bytes): " - , textShow $ (\a -> (bsBase16Encode $ getHash a, showBytes $ getBytes a)) <$> take 5 ls' - ] + logInfoCtx tracer $ + logCtx + { lcMessage = + Text.concat + [ "Found some wrong values already. The oldest ones are (hash, bytes): " + , textShow $ (\a -> (bsBase16Encode $ getHash a, showBytes $ getBytes a)) <$> take 5 ls' + ] + } pure True let !newAcc = ls'' : acc if fromIntegral (length ls) < limit @@ -200,8 +218,8 @@ findWrongPlutusData tracer tableName qCount qPage qGetInfo getHash getBytes hash Left Nothing -> pure False Left (Just msg) -> do liftIO $ - logWarning tracer $ - Text.concat ["Invalid Binary Data for hash ", textShow actualHash, ": ", Text.pack msg] + logWarningCtx tracer $ + logCtx {lcMessage = Text.concat ["Invalid Binary Data for hash ", textShow actualHash, ": ", Text.pack msg]} pure False Right hashedBytes -> pure $ hashedBytes /= actualHash where @@ -227,6 +245,8 @@ fixPlutusData tracer cblk fds = do mapM_ (fixData True) $ fdDatum fds mapM_ (fixData False) $ fdRedeemerData fds where + logCtx = initLogCtx "fixPlutusData" "Cardano.DbSync.Fix.PlutusDataBytes" + fixData :: MonadIO m => Bool -> FixPlutusInfo -> ReaderT SqlBackend m () fixData isDatum fd = do case Map.lookup (fpHash fd) correctBytesMap of @@ -238,9 +258,12 @@ fixPlutusData tracer cblk fds = do DB_V_13_0.upateDatumBytes datumId correctBytes Nothing -> liftIO $ - logWarning tracer $ - mconcat - ["Datum", " not found in block"] + logWarningCtx tracer $ + logCtx + { lcMessage = + mconcat + ["Datum", " not found in block"] + } Just correctBytes -> do mRedeemerDataId <- DB_V_13_0.queryRedeemerData $ fpHash fd case mRedeemerDataId of @@ -248,9 +271,8 @@ fixPlutusData tracer cblk fds = do DB_V_13_0.upateRedeemerDataBytes redeemerDataId correctBytes Nothing -> liftIO $ - logWarning tracer $ - mconcat - ["RedeemerData", " not found in block"] + logWarningCtx tracer $ + logCtx {lcMessage = "RedeemerData not found in block"} correctBytesMap = Map.union (scrapDatumsBlock cblk) (scrapRedeemerDataBlock cblk) diff --git a/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusScripts.hs b/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusScripts.hs index 31c0724fa..773e318ce 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusScripts.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Fix/PlutusScripts.hs @@ -33,7 +33,7 @@ import qualified Cardano.Ledger.Core as Ledger import Cardano.Db (ScriptType (..), maybeToEither) import qualified Cardano.Db.Version.V13_0 as DB_V_13_0 -import Cardano.BM.Trace (Trace, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import Cardano.DbSync.Api import qualified Cardano.DbSync.Era.Shelley.Generic as Generic @@ -50,6 +50,7 @@ import Ouroboros.Consensus.Cardano.Block (HardForkBlock (BlockAllegra, BlockAlon import Ouroboros.Consensus.Shelley.Eras import Cardano.DbSync.Fix.PlutusDataBytes +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import Cardano.Ledger.Babbage.TxOut import Cardano.Ledger.Plutus.Language (Plutus (..)) @@ -77,14 +78,18 @@ getWrongPlutusScripts :: Trace IO Text -> ReaderT SqlBackend m FixPlutusScripts getWrongPlutusScripts tracer = do + let logCtx = initLogCtx "getWrongPlutusScripts" "Cardano.DbSync.Fix.PlutusScripts" liftIO $ - logInfo tracer $ - mconcat - [ "Starting the fixing Plutus Script procedure. This may take a couple minutes on mainnet if there are wrong values." - , " You can skip it using --skip-plutus-script-fix." - , " It will fix Script with wrong bytes. See more in Issue #1214 and #1348." - , " This procedure makes resyncing unnecessary." - ] + logInfoCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "Starting the fixing Plutus Script procedure. This may take a couple minutes on mainnet if there are wrong values." + , " You can skip it using --skip-plutus-script-fix." + , " It will fix Script with wrong bytes. See more in Issue #1214 and #1348." + , " This procedure makes resyncing unnecessary." + ] + } FixPlutusScripts <$> findWrongPlutusScripts tracer findWrongPlutusScripts :: @@ -137,11 +142,15 @@ fixPlutusScripts tracer cblk fpss = do DB_V_13_0.updateScriptBytes scriptId correctBytes Nothing -> liftIO $ - logWarning tracer $ - mconcat - ["Script", " not found in block"] + logWarningCtx tracer $ + logCtx + { lcMessage = + mconcat + ["Script", " not found in block"] + } correctBytesMap = scrapScriptBlock cblk + logCtx = initLogCtx "fixPlutusScripts" "Cardano.DbSync.Fix.PlutusScripts" scrapScriptBlock :: CardanoBlock -> Map ByteString ByteString scrapScriptBlock cblk = case cblk of diff --git a/cardano-db-sync/src/Cardano/DbSync/Ledger/State.hs b/cardano-db-sync/src/Cardano/DbSync/Ledger/State.hs index c0875e511..84e16d34c 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Ledger/State.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Ledger/State.hs @@ -37,7 +37,7 @@ module Cardano.DbSync.Ledger.State ( findProposedCommittee, ) where -import Cardano.BM.Trace (Trace, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import Cardano.Binary (Decoder, DecoderError) import qualified Cardano.Binary as Serialize import Cardano.DbSync.Config.Types @@ -76,6 +76,7 @@ import qualified Data.ByteString.Base16 as Base16 import Cardano.DbSync.Api.Types (InsertOptions (..), LedgerEnv (..), SyncOptions (..)) import Cardano.DbSync.Error (SyncNodeError (..), fromEitherSTM) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import Cardano.Ledger.BaseTypes (StrictMaybe) import Cardano.Ledger.Conway.Core as Shelley import Cardano.Ledger.Conway.Governance @@ -353,15 +354,19 @@ storeSnapshotAndCleanupMaybe env oldState appResult blkNo isCons syncState = saveCurrentLedgerState :: HasLedgerEnv -> CardanoLedgerState -> Maybe EpochNo -> IO () saveCurrentLedgerState env lState mEpochNo = do + let logCtx = initLogCtx "saveCurrentLedgerState" "Cardano.DbSync.Ledger.State" case mkLedgerStateFilename (leDir env) (clsState lState) mEpochNo of Origin -> pure () -- we don't store genesis At file -> do exists <- doesFileExist file if exists then - logInfo (leTrace env) $ - mconcat - ["File ", Text.pack file, " exists"] + logInfoCtx (leTrace env) $ + logCtx + { lcMessage = + mconcat + ["File ", Text.pack file, " exists"] + } else atomically $ writeTBQueue (leStateWriteQueue env) (file, lState) runLedgerStateWriteThread :: Trace IO Text -> LedgerEnv -> IO () @@ -374,6 +379,8 @@ ledgerStateWriteLoop :: Trace IO Text -> TBQueue (FilePath, CardanoLedgerState) ledgerStateWriteLoop tracer swQueue codecConfig = loop where + logCtx = initLogCtx "ledgerStateWriteLoop" "Cardano.DbSync.Ledger.State" + loop :: IO () loop = do (file, ledger) <- atomically $ readTBQueue swQueue -- Blocks until the queue has elements. @@ -395,14 +402,8 @@ ledgerStateWriteLoop tracer swQueue codecConfig = ) ledger endTime <- getCurrentTime - logInfo tracer $ - mconcat - [ "Asynchronously wrote a ledger snapshot to " - , Text.pack file - , " in " - , textShow (diffUTCTime endTime startTime) - , "." - ] + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Asynchronously wrote a ledger snapshot to ", Text.pack file, " in ", textShow (diffUTCTime endTime startTime), "."]} mkLedgerStateFilename :: LedgerStateDir -> ExtLedgerState CardanoBlock -> Maybe EpochNo -> WithOrigin FilePath mkLedgerStateFilename dir ledger mEpochNo = @@ -499,6 +500,7 @@ cleanupLedgerStateFiles env slotNo = do loadLedgerAtPoint :: HasLedgerEnv -> CardanoPoint -> IO (Either [LedgerStateFile] CardanoLedgerState) loadLedgerAtPoint hasLedgerEnv point = do + let logCtx = initLogCtx "loadLedgerAtPoint" "Cardano.DbSync.Ledger.State" mLedgerDB <- atomically $ readTVar $ leStateVar hasLedgerEnv -- First try to find the ledger in memory let mAnchoredSeq = rollbackLedger mLedgerDB @@ -513,11 +515,13 @@ loadLedgerAtPoint hasLedgerEnv point = do case mst of Right st -> do writeLedgerState hasLedgerEnv (Strict.Just . LedgerDB $ AS.Empty st) - logInfo (leTrace hasLedgerEnv) $ mconcat ["Found snapshot file for ", renderPoint point] + logInfoCtx (leTrace hasLedgerEnv) $ + logCtx {lcMessage = mconcat ["Found snapshot file for ", renderPoint point]} pure $ Right st Left lsfs -> pure $ Left lsfs Just anchoredSeq' -> do - logInfo (leTrace hasLedgerEnv) $ mconcat ["Found in memory ledger snapshot at ", renderPoint point] + logInfoCtx (leTrace hasLedgerEnv) $ + logCtx {lcMessage = mconcat ["Found in memory ledger snapshot at ", renderPoint point]} let ledgerDB' = LedgerDB anchoredSeq' let st = ledgerDbCurrent ledgerDB' deleteNewerFiles hasLedgerEnv point @@ -546,14 +550,15 @@ deleteNewerFiles env point = do deleteAndLogStateFile env "newer" newerFiles deleteAndLogFiles :: HasLedgerEnv -> Text -> [FilePath] -> IO () -deleteAndLogFiles env descr files = +deleteAndLogFiles env descr files = do + let logCtx = initLogCtx "deleteAndLogFiles" "Cardano.DbSync.Ledger.State" case files of [] -> pure () [fl] -> do - logInfo (leTrace env) $ mconcat ["Removing ", descr, " file ", Text.pack fl] + logInfoCtx (leTrace env) $ logCtx {lcMessage = mconcat ["Removing ", descr, " file ", Text.pack fl]} safeRemoveFile fl - _ -> do - logInfo (leTrace env) $ mconcat ["Removing ", descr, " files ", textShow files] + _otherwise -> do + logInfoCtx (leTrace env) $ logCtx {lcMessage = mconcat ["Removing ", descr, " files ", textShow files]} mapM_ safeRemoveFile files deleteAndLogStateFile :: HasLedgerEnv -> Text -> [LedgerStateFile] -> IO () @@ -585,24 +590,32 @@ findStateFromPoint env point = do logNewerFiles olderFiles pure $ Left olderFiles where + logCtx = initLogCtx "findStateFromPoint" "Cardano.DbSync.Ledger.State" + deleteLedgerFile :: Text -> LedgerStateFile -> IO () deleteLedgerFile err lsf = do - logWarning (leTrace env) $ - mconcat - [ "Failed to parse ledger state file " - , Text.pack (lsfFilePath lsf) - , " with error '" - , err - , "'. Deleting it." - ] + logWarningCtx (leTrace env) $ + logCtx + { lcMessage = + mconcat + [ "Failed to parse ledger state file " + , Text.pack (lsfFilePath lsf) + , " with error '" + , err + , "'. Deleting it." + ] + } safeRemoveFile $ lsfFilePath lsf logNewerFiles :: [LedgerStateFile] -> IO () logNewerFiles lsfs = - logWarning (leTrace env) $ - case lsfs of - [] -> "Rollback failed. No more ledger state files." - (x : _) -> mconcat ["Needs to Rollback further to slot ", textShow (unSlotNo $ lsfSlotNo x)] + logWarningCtx (leTrace env) $ + logCtx + { lcMessage = + case lsfs of + [] -> "Rollback failed. No more ledger state files." + (x : _) -> mconcat ["Needs to Rollback further to slot ", textShow (unSlotNo $ lsfSlotNo x)] + } -- Splits the files based on the comparison with the given point. It will return -- a list of newer files, a file at the given point if found and a list of older @@ -643,6 +656,8 @@ loadLedgerStateFromFile tracer config delete point lsf = do Left err -> when delete (safeRemoveFile $ lsfFilePath lsf) >> pure (Left err) Right st -> pure $ Right st where + logCtx = initLogCtx "loadLedgerStateFromFile" "Cardano.DbSync.Ledger.State" + safeReadFile :: FilePath -> IO (Either Text CardanoLedgerState) safeReadFile fp = do startTime <- getCurrentTime @@ -655,16 +670,19 @@ loadLedgerStateFromFile tracer config delete point lsf = do Left err -> pure $ Left $ textShow err Right ls -> do endTime <- getCurrentTime - logInfo tracer $ - mconcat - [ "Found snapshot file for " - , renderPoint point - , ". It took " - , textShow (diffUTCTime mediumTime startTime) - , " to read from disk and " - , textShow (diffUTCTime endTime mediumTime) - , " to parse." - ] + logInfoCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "Found snapshot file for " + , renderPoint point + , ". It took " + , textShow (diffUTCTime mediumTime startTime) + , " to read from disk and " + , textShow (diffUTCTime endTime mediumTime) + , " to parse." + ] + } pure $ Right ls codecConfig :: CodecConfig CardanoBlock diff --git a/cardano-db-sync/src/Cardano/DbSync/LocalStateQuery.hs b/cardano-db-sync/src/Cardano/DbSync/LocalStateQuery.hs index 11d31ad2b..19d69816d 100644 --- a/cardano-db-sync/src/Cardano/DbSync/LocalStateQuery.hs +++ b/cardano-db-sync/src/Cardano/DbSync/LocalStateQuery.hs @@ -10,10 +10,11 @@ module Cardano.DbSync.LocalStateQuery ( newStateQueryTMVar, ) where -import Cardano.BM.Trace (Trace, logInfo) +import Cardano.BM.Trace (Trace) import Cardano.DbSync.Error (SyncNodeError (..)) import Cardano.DbSync.StateQuery import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx, logInfoCtx) import qualified Cardano.Ledger.BaseTypes as Ledger import Cardano.Ledger.Crypto (StandardCrypto) import Cardano.Prelude hiding (atomically, (.)) @@ -30,6 +31,7 @@ import Control.Concurrent.Class.MonadSTM.Strict ( writeTVar, ) import qualified Data.Strict.Maybe as Strict +import Data.Text (pack) import Data.Time.Clock (getCurrentTime) import Ouroboros.Consensus.BlockchainTime.WallClock.Types (SystemStart (..)) import Ouroboros.Consensus.Cardano.Block (BlockQuery (QueryHardFork), CardanoEras) @@ -118,14 +120,16 @@ getHistoryInterpreter :: NoLedgerEnv -> IO CardanoInterpreter getHistoryInterpreter nlEnv = do + let logCtx = initLogCtx "getHistoryInterpreter" "DbSync.LocalStateQuery" respVar <- newEmptyTMVarIO atomically $ putTMVar reqVar (BlockQuery $ QueryHardFork GetInterpreter, respVar) res <- atomically $ takeTMVar respVar case res of - Left err -> - throwIO $ SNErrLocalStateQuery $ "getHistoryInterpreter: " <> Prelude.show err + Left err -> do + logErrorCtx tracer $ logCtx {lcMessage = pack $ Prelude.show err} + throwIO $ SNErrLocalStateQuery $ Prelude.show err Right interp -> do - logInfo tracer "getHistoryInterpreter: acquired" + logInfoCtx tracer $ logCtx {lcMessage = "Acquired"} atomically $ writeTVar interVar $ Strict.Just interp pure interp where diff --git a/cardano-db-sync/src/Cardano/DbSync/OffChain.hs b/cardano-db-sync/src/Cardano/DbSync/OffChain.hs index b89201791..bb08aca7f 100644 --- a/cardano-db-sync/src/Cardano/DbSync/OffChain.hs +++ b/cardano-db-sync/src/Cardano/DbSync/OffChain.hs @@ -17,7 +17,7 @@ module Cardano.DbSync.OffChain ( fetchOffChainVoteData, ) where -import Cardano.BM.Trace (Trace, logInfo) +import Cardano.BM.Trace (Trace) import Cardano.Db (runIohkLogging) import qualified Cardano.Db as DB import Cardano.DbSync.Api @@ -27,6 +27,7 @@ import Cardano.DbSync.OffChain.Http import Cardano.DbSync.OffChain.Query import qualified Cardano.DbSync.OffChain.Vote.Types as Vote import Cardano.DbSync.Types +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import Cardano.Prelude import Control.Concurrent.Class.MonadSTM.Strict ( StrictTBQueue (..), @@ -111,10 +112,10 @@ insertOffChainPoolResults trce resultQueue = do unless (null res) $ do let resLength = length res resErrorsLength = length $ filter isFetchError res - liftIO . logInfo trce $ - logInsertOffChainResults "Pool" resLength resErrorsLength + liftIO . logInfoCtx trce $ logCtx {lcMessage = logInsertOffChainResults "Pool" resLength resErrorsLength} mapM_ insert res where + logCtx = initLogCtx "insertOffChainPoolResults" "Cardano.DbSync.OffChain" insert :: (MonadBaseControl IO m, MonadIO m) => OffChainPoolResult -> ReaderT SqlBackend m () insert = \case OffChainPoolResultMetadata md -> void $ DB.insertCheckOffChainPoolData md @@ -135,10 +136,10 @@ insertOffChainVoteResults trce resultQueue = do unless (null res) $ do let resLength = length res resErrorsLength = length $ filter isFetchError res - liftIO . logInfo trce $ - logInsertOffChainResults "Voting Anchor" resLength resErrorsLength + liftIO . logInfoCtx trce $ logCtx {lcMessage = logInsertOffChainResults "Voting Anchor" resLength resErrorsLength} mapM_ insert res where + logCtx = initLogCtx "insertOffChainVoteResults" "Cardano.DbSync.OffChain" insert :: (MonadBaseControl IO m, MonadIO m) => OffChainVoteResult -> ReaderT SqlBackend m () insert = \case OffChainVoteResultMetadata md accessors -> do @@ -181,7 +182,7 @@ runFetchOffChainPoolThread :: SyncEnv -> IO () runFetchOffChainPoolThread syncEnv = do -- if dissable gov is active then don't run voting anchor thread when (ioOffChainPoolData iopts) $ do - logInfo trce "Running Offchain Pool fetch thread" + logInfoCtx trce $ logCtx {lcMessage = "Running Offchain Pool fetch thread"} runIohkLogging trce $ withPostgresqlConn (envConnectionString syncEnv) $ \backendPool -> liftIO $ @@ -194,6 +195,7 @@ runFetchOffChainPoolThread syncEnv = do now <- liftIO Time.getPOSIXTime mapM_ (queuePoolInsert <=< fetchOffChainPoolData trce manager now) poolq where + logCtx = initLogCtx "runFetchOffChainPoolThread" "Cardano.DbSync.OffChain" trce = getTrace syncEnv iopts = getInsertOptions syncEnv @@ -204,7 +206,7 @@ runFetchOffChainVoteThread :: SyncEnv -> IO () runFetchOffChainVoteThread syncEnv = do -- if dissable gov is active then don't run voting anchor thread when (ioGov iopts) $ do - logInfo trce "Running Offchain Vote Anchor fetch thread" + logInfoCtx trce $ logCtx {lcMessage = "Running Offchain Vote Anchor fetch thread"} runIohkLogging trce $ withPostgresqlConn (envConnectionString syncEnv) $ \backendVote -> liftIO $ @@ -216,6 +218,7 @@ runFetchOffChainVoteThread syncEnv = do now <- liftIO Time.getPOSIXTime mapM_ (queueVoteInsert <=< fetchOffChainVoteData gateways now) voteq where + logCtx = initLogCtx "runFetchOffChainVoteThread" "Cardano.DbSync.OffChain" trce = getTrace syncEnv iopts = getInsertOptions syncEnv gateways = dncIpfsGateway $ envSyncNodeConfig syncEnv diff --git a/cardano-db-sync/src/Cardano/DbSync/Rollback.hs b/cardano-db-sync/src/Cardano/DbSync/Rollback.hs index 1ba1d13f8..f1f2c1746 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Rollback.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Rollback.hs @@ -9,7 +9,7 @@ module Cardano.DbSync.Rollback ( unsafeRollback, ) where -import Cardano.BM.Trace (Trace, logInfo, logWarning) +import Cardano.BM.Trace (Trace) import qualified Cardano.Db as DB import Cardano.DbSync.Api import Cardano.DbSync.Api.Types (SyncEnv (..)) @@ -19,6 +19,7 @@ import Cardano.DbSync.Error import Cardano.DbSync.Types import Cardano.DbSync.Util import Cardano.DbSync.Util.Constraint (addConstraintsIfNotExist) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx) import Cardano.Prelude import Control.Monad.Extra (whenJust) import Control.Monad.Trans.Control (MonadBaseControl) @@ -36,17 +37,23 @@ rollbackFromBlockNo :: BlockNo -> ExceptT SyncNodeError (ReaderT SqlBackend m) () rollbackFromBlockNo syncEnv blkNo = do + let logCtx = initLogCtx "rollbackFromBlockNo" "Cardano.DbSync.Rollback" nBlocks <- lift $ DB.queryBlockCountAfterBlockNo (unBlockNo blkNo) True mres <- lift $ DB.queryBlockNoAndEpoch (unBlockNo blkNo) whenJust mres $ \(blockId, epochNo) -> do liftIO - . logInfo trce - $ mconcat - [ "Deleting " - , textShow nBlocks - , " numbered equal to or greater than " - , textShow blkNo - ] + . logInfoCtx trce + $ logCtx + { lcBlockNo = Just $ unBlockNo blkNo + , lcEpochNo = Just epochNo + , lcMessage = + mconcat + [ "Deleting " + , textShow nBlocks + , " numbered equal to or greater than " + , textShow blkNo + ] + } lift $ do deletedBlockCount <- DB.deleteBlocksBlockId trce txOutTableType blockId epochNo (Just (DB.pcmConsumedTxOut $ getPruneConsume syncEnv)) when (deletedBlockCount > 0) $ do @@ -57,7 +64,12 @@ rollbackFromBlockNo syncEnv blkNo = do lift $ rollbackCache cache blockId - liftIO . logInfo trce $ "Blocks deleted" + liftIO . logInfoCtx trce $ + logCtx + { lcEpochNo = Just epochNo + , lcBlockNo = Just $ unBlockNo blkNo + , lcMessage = "Blocks deleted" + } where trce = getTrace syncEnv cache = envCache syncEnv @@ -67,6 +79,7 @@ prepareRollback :: SyncEnv -> CardanoPoint -> Tip CardanoBlock -> IO (Either Syn prepareRollback syncEnv point serverTip = DB.runDbIohkNoLogging (envBackend syncEnv) $ runExceptT action where + logCtx = initLogCtx "prepareRollback" "Cardano.DbSync.Rollback" trce = getTrace syncEnv action :: MonadIO m => ExceptT SyncNodeError (ReaderT SqlBackend m) Bool @@ -76,39 +89,50 @@ prepareRollback syncEnv point serverTip = nBlocks <- lift DB.queryCountSlotNo if nBlocks == 0 then do - liftIO . logInfo trce $ "Starting from Genesis" + liftIO . logInfoCtx trce $ logCtx {lcMessage = "Starting from Genesis"} else do liftIO - . logInfo trce - $ mconcat - [ "Delaying delete of " - , textShow nBlocks - , " while rolling back to genesis." - , " Applying blocks until a new block is found." - , " The node is currently at " - , textShow serverTip - ] + . logInfoCtx trce + $ logCtx + { lcMessage = + mconcat + [ "Delaying delete of " + , textShow nBlocks + , " while rolling back to genesis." + , " Applying blocks until a new block is found." + , " The node is currently at " + , textShow serverTip + ] + } At blk -> do nBlocks <- lift $ DB.queryCountSlotNosGreaterThan (unSlotNo $ blockPointSlot blk) mBlockNo <- liftLookupFail "Rollback.prepareRollback" $ DB.queryBlockHashBlockNo (SBS.fromShort . getOneEraHash $ blockPointHash blk) liftIO - . logInfo trce - $ mconcat - [ "Delaying delete of " - , textShow nBlocks - , " blocks after " - , textShow mBlockNo - , " while rolling back to (" - , renderPoint point - , "). Applying blocks until a new block is found. The node is currently at " - , textShow serverTip - ] + . logInfoCtx trce + $ logCtx + { lcMessage = + mconcat + [ "Delaying delete of " + , textShow nBlocks + , " blocks after " + , textShow mBlockNo + , " while rolling back to (" + , renderPoint point + , "). Applying blocks until a new block is found. The node is currently at " + , textShow serverTip + ] + } pure False -- For testing and debugging. unsafeRollback :: Trace IO Text -> DB.TxOutTableType -> DB.PGConfig -> SlotNo -> IO (Either SyncNodeError ()) unsafeRollback trce txOutTableType config slotNo = do - logWarning trce $ "Starting a forced rollback to slot: " <> textShow (unSlotNo slotNo) + let logCtx = initLogCtx "unsafeRollback" "Cardano.DbSync.Rollback" + logWarningCtx trce $ + logCtx + { lcSlotNo = Just $ unSlotNo slotNo + , lcMessage = "Starting a forced rollback to slot: " <> textShow (unSlotNo slotNo) + } Right <$> DB.runDbNoLogging (DB.PGPassCached config) (void $ DB.deleteBlocksSlotNo trce txOutTableType slotNo Nothing) diff --git a/cardano-db-sync/src/Cardano/DbSync/Sync.hs b/cardano-db-sync/src/Cardano/DbSync/Sync.hs index 656f81b4e..ec25e2f0c 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Sync.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Sync.hs @@ -25,7 +25,7 @@ module Cardano.DbSync.Sync ( ) where import Cardano.BM.Data.Tracer (ToLogObject (..), ToObject) -import Cardano.BM.Trace (Trace, appendName, logInfo, logWarning) +import Cardano.BM.Trace (Trace, appendName) import qualified Cardano.BM.Trace as Logging import Cardano.Client.Subscription (subscribe) import Cardano.Db (runDbIohkLogging) @@ -42,6 +42,7 @@ import Cardano.DbSync.Metrics import Cardano.DbSync.Tracing.ToObjectOrphans () import Cardano.DbSync.Types import Cardano.DbSync.Util +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logExceptionCtx, logInfoCtx, logWarningCtx) import Cardano.Prelude hiding (Meta, Nat, (%)) import Cardano.Slotting.Slot (WithOrigin (..)) import qualified Codec.CBOR.Term as CBOR @@ -129,7 +130,7 @@ runSyncNodeClient :: SocketPath -> IO () runSyncNodeClient metricsSetters syncEnv iomgr trce tc (SocketPath socketPath) = do - logInfo trce $ "Connecting to node via " <> textShow socketPath + logInfoCtx trce $ logCtx {lcMessage = "Connecting to node via " <> textShow socketPath} void $ subscribe (localSnocket iomgr) @@ -139,6 +140,7 @@ runSyncNodeClient metricsSetters syncEnv iomgr trce tc (SocketPath socketPath) = clientSubscriptionParams (dbSyncProtocols syncEnv metricsSetters tc codecConfig) where + logCtx = initLogCtx "runSyncNodeClient" "Cardano.DbSync.Sync" codecConfig :: CodecConfig CardanoBlock codecConfig = configCodec $ getTopLevelConfig syncEnv @@ -198,6 +200,7 @@ dbSyncProtocols syncEnv metricsSetters tc codecConfig version bversion = (Logging.nullTracer, cTxMonitorCodec codecs, localTxMonitorPeerNull) } where + logCtx = initLogCtx "dbSyncProtocols" "Cardano.DbSync.Sync" codecs = clientCodecs codecConfig bversion version localChainSyncTracer :: Tracer IO (TraceSendRecv (ChainSync CardanoBlock (Point CardanoBlock) (Tip CardanoBlock))) @@ -214,11 +217,10 @@ dbSyncProtocols syncEnv metricsSetters tc codecConfig version bversion = case consumedFixed of Nothing -> oldActionFixes channel Just wrongEntriesSize | wrongEntriesSize == 0 -> do - logInfo tracer "Found no wrong consumed_by_tx_id entries" + logInfoCtx tracer $ logCtx {lcMessage = "Found no wrong consumed_by_tx_id entries"} oldActionFixes channel Just wrongEntriesSize -> do - logInfo tracer $ - mconcat ["Found ", textShow wrongEntriesSize, " consumed_by_tx_id wrong entries"] + logInfoCtx tracer $ logCtx {lcMessage = mconcat ["Found ", textShow wrongEntriesSize, " consumed_by_tx_id wrong entries"]} fixedEntries <- runPeer localChainSyncTracer @@ -227,8 +229,8 @@ dbSyncProtocols syncEnv metricsSetters tc codecConfig version bversion = ( Client.chainSyncClientPeer $ chainSyncClientFixConsumed backend syncEnv wrongEntriesSize ) - logInfo tracer $ - mconcat ["Fixed ", textShow fixedEntries, " consumed_by_tx_id wrong entries"] + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Fixed ", textShow fixedEntries, " consumed_by_tx_id wrong entries"]} pure False oldActionFixes channel = do @@ -274,22 +276,26 @@ dbSyncProtocols syncEnv metricsSetters tc codecConfig version bversion = localChainSyncPtcl :: RunMiniProtocolWithMinimalCtx 'InitiatorMode LocalAddress BSL.ByteString IO () Void localChainSyncPtcl = InitiatorProtocolOnly $ - MiniProtocolCb $ \_ctx channel -> - liftIO . logException tracer "ChainSyncWithBlocksPtcl: " $ do + MiniProtocolCb $ \_ctx channel -> do + let logCtx' = initLogCtx "localChainSyncPtcl" "Cardano.DbSync.Sync" + liftIO . logExceptionCtx tracer logCtx' {lcMessage = "ChainSyncWithBlocksPtcl "} $ do isInitComplete <- runAndSetDone tc $ initAction channel when isInitComplete $ do - logInfo tracer "Starting ChainSync client" + logInfoCtx tracer $ logCtx' {lcMessage = "Starting ChainSync client"} setConsistentLevel syncEnv Unchecked (latestPoints, currentTip) <- waitRestartState tc let (inMemory, onDisk) = List.span snd latestPoints - logInfo tracer $ - mconcat - [ "Suggesting intersection points from memory: " - , textShow (fst <$> inMemory) - , " and from disk: " - , textShow (fst <$> onDisk) - ] + logInfoCtx tracer $ + logCtx' + { lcMessage = + mconcat + [ "Suggesting intersection points from memory: " + , textShow (fst <$> inMemory) + , " and from disk: " + , textShow (fst <$> onDisk) + ] + } void $ runPipelinedPeer localChainSyncTracer @@ -424,7 +430,7 @@ chainSyncClient metricsSetters trce latestPoints currentTip tc = do mkClientStNext finish = ClientStNext { recvMsgRollForward = \blk tip -> - logException trce "recvMsgRollForward: " $ do + logExceptionCtx trce (logCtx {lcMessage = "recvMsgRollForward: "}) $ do setNodeBlockHeight metricsSetters (getTipBlockNo tip) newSize <- atomically $ do @@ -435,12 +441,14 @@ chainSyncClient metricsSetters trce latestPoints currentTip tc = do pure $ finish (At (blockNo blk)) tip Nothing , recvMsgRollBackward = \point tip -> - logException trce "recvMsgRollBackward: " $ do + logExceptionCtx trce (logCtx {lcMessage = "recvMsgRollBackward: "}) $ do -- This will get the current tip rather than what we roll back to -- but will only be incorrect for a short time span. (mPoints, newTip) <- waitRollback tc point tip pure $ finish newTip tip mPoints } + where + logCtx = initLogCtx "mkClientStNext" "Cardano.DbSync.Sync" drainThePipe :: Nat n -> @@ -465,10 +473,11 @@ drainThePipe n0 client = go n0 chainSyncClientFixConsumed :: SqlBackend -> SyncEnv -> Word64 -> ChainSyncClient CardanoBlock (Point CardanoBlock) (Tip CardanoBlock) IO Integer chainSyncClientFixConsumed backend syncEnv wrongTotalSize = Client.ChainSyncClient $ do - liftIO $ logInfo tracer "Starting chainsync to fix consumed_by_tx_id Byron entries. See issue https://github.com/IntersectMBO/cardano-db-sync/issues/1821. This makes resyncing unnecessary." + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Starting chainsync to fix consumed_by_tx_id Byron entries. See issue https://github.com/IntersectMBO/cardano-db-sync/issues/1821. This makes resyncing unnecessary."} pure $ Client.SendMsgFindIntersect [genesisPoint] clientStIntersect where tracer = getTrace syncEnv + logCtx = initLogCtx "chainSyncClientFixConsumed" "Cardano.DbSync.Sync" clientStIntersect = Client.ClientStIntersect { Client.recvMsgIntersectFound = \_blk _tip -> @@ -511,21 +520,22 @@ chainSyncClientFixConsumed backend syncEnv wrongTotalSize = Client.ChainSyncClie logSize :: Integer -> Integer -> IO () logSize lastSize newSize = do when (newSize `div` 200_000 > lastSize `div` 200_000) $ - logInfo tracer $ - mconcat ["Fixed ", textShow newSize, "/", textShow wrongTotalSize, " entries"] + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Fixed ", textShow newSize, "/", textShow wrongTotalSize, " entries"]} chainSyncClientFixData :: SqlBackend -> Trace IO Text -> FixData -> ChainSyncClient CardanoBlock (Point CardanoBlock) (Tip CardanoBlock) IO () chainSyncClientFixData backend tracer fixData = Client.ChainSyncClient $ do - liftIO $ logInfo tracer "Starting chainsync to fix Plutus Data. This will update database values in tables datum and redeemer_data." + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Starting chainsync to fix Plutus Data. This will update database values in tables datum and redeemer_data."} clientStIdle True (sizeFixData fixData) fixData where + logCtx = initLogCtx "chainSyncClientFixData" "Cardano.DbSync.Sync" updateSizeAndLog :: Int -> Int -> IO Int updateSizeAndLog lastSize currentSize = do let diffSize = lastSize - currentSize if lastSize >= currentSize && diffSize >= 200_000 then do - liftIO $ logInfo tracer $ mconcat ["Fixed ", textShow (sizeFixData fixData - currentSize), " Plutus Data"] + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = mconcat ["Fixed ", textShow (sizeFixData fixData - currentSize), " Plutus Data"]} pure currentSize else pure lastSize @@ -533,13 +543,13 @@ chainSyncClientFixData backend tracer fixData = Client.ChainSyncClient $ do clientStIdle shouldLog lastSize fds = do case spanFDOnNextPoint fds of Nothing -> do - liftIO $ logInfo tracer "Finished chainsync to fix Plutus Data." + liftIO $ logInfoCtx tracer logCtx {lcMessage = "Finished chainsync to fix Plutus Data."} pure $ Client.SendMsgDone () Just (point, fdOnPoint, fdRest) -> do when shouldLog $ liftIO $ - logInfo tracer $ - mconcat ["Starting fixing Plutus Data ", textShow point] + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Starting fixing Plutus Data ", textShow point]} newLastSize <- liftIO $ updateSizeAndLog lastSize (sizeFixData fds) let clientStIntersect = Client.ClientStIntersect @@ -549,14 +559,17 @@ chainSyncClientFixData backend tracer fixData = Client.ChainSyncClient $ do Client.SendMsgRequestNext (pure ()) (clientStNext newLastSize fdOnPoint fdRest) , Client.recvMsgIntersectNotFound = \tip -> Client.ChainSyncClient $ do liftIO $ - logWarning tracer $ - mconcat - [ "Node can't find block " - , textShow point - , ". It's probably behind, at " - , textShow tip - , ". Sleeping for 3 mins and retrying.." - ] + logWarningCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "Node can't find block " + , textShow point + , ". It's probably behind, at " + , textShow tip + , ". Sleeping for 3 mins and retrying.." + ] + } liftIO $ threadDelay $ 180 * 1_000_000 pure $ Client.SendMsgFindIntersect [point] clientStIntersect } @@ -577,15 +590,16 @@ chainSyncClientFixData backend tracer fixData = Client.ChainSyncClient $ do chainSyncClientFixScripts :: SqlBackend -> Trace IO Text -> FixPlutusScripts -> ChainSyncClient CardanoBlock (Point CardanoBlock) (Tip CardanoBlock) IO () chainSyncClientFixScripts backend tracer fps = Client.ChainSyncClient $ do - liftIO $ logInfo tracer "Starting chainsync to fix Plutus Scripts. This will update database values in tables script." + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Starting chainsync to fix Plutus Scripts. This will update database values in tables script."} clientStIdle True (sizeFixPlutusScripts fps) fps where + logCtx = initLogCtx "chainSyncClientFixScripts" "Cardano.DbSync.Sync" updateSizeAndLog :: Int -> Int -> IO Int updateSizeAndLog lastSize currentSize = do let diffSize = lastSize - currentSize if lastSize >= currentSize && diffSize >= 200_000 then do - liftIO $ logInfo tracer $ mconcat ["Fixed ", textShow (sizeFixPlutusScripts fps - currentSize), " Plutus Scripts"] + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = mconcat ["Fixed ", textShow (sizeFixPlutusScripts fps - currentSize), " Plutus Scripts"]} pure currentSize else pure lastSize @@ -593,13 +607,13 @@ chainSyncClientFixScripts backend tracer fps = Client.ChainSyncClient $ do clientStIdle shouldLog lastSize fps' = do case spanFPSOnNextPoint fps' of Nothing -> do - liftIO $ logInfo tracer "Finished chainsync to fix Plutus Scripts." + liftIO $ logInfoCtx tracer $ logCtx {lcMessage = "Finished chainsync to fix Plutus Scripts."} pure $ Client.SendMsgDone () Just (point, fpsOnPoint, fpsRest) -> do when shouldLog $ liftIO $ - logInfo tracer $ - mconcat ["Starting fixing Plutus Scripts ", textShow point] + logInfoCtx tracer $ + logCtx {lcMessage = mconcat ["Starting fixing Plutus Scripts ", textShow point]} newLastSize <- liftIO $ updateSizeAndLog lastSize (sizeFixPlutusScripts fps') let clientStIntersect = Client.ClientStIntersect @@ -609,14 +623,17 @@ chainSyncClientFixScripts backend tracer fps = Client.ChainSyncClient $ do Client.SendMsgRequestNext (pure ()) (clientStNext newLastSize fpsOnPoint fpsRest) , Client.recvMsgIntersectNotFound = \tip -> Client.ChainSyncClient $ do liftIO $ - logWarning tracer $ - mconcat - [ "Node can't find block " - , textShow point - , ". It's probably behind, at " - , textShow tip - , ". Sleeping for 3 mins and retrying.." - ] + logWarningCtx tracer $ + logCtx + { lcMessage = + mconcat + [ "Node can't find block " + , textShow point + , ". It's probably behind, at " + , textShow tip + , ". Sleeping for 3 mins and retrying.." + ] + } liftIO $ threadDelay $ 180 * 1_000_000 pure $ Client.SendMsgFindIntersect [point] clientStIntersect } diff --git a/cardano-db-sync/src/Cardano/DbSync/Util.hs b/cardano-db-sync/src/Cardano/DbSync/Util.hs index 961ad5546..bc24d97f4 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Util.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Util.hs @@ -14,9 +14,6 @@ module Cardano.DbSync.Util ( fmap3, getSyncStatus, isSyncedWithinSeconds, - liftedLogException, - logActionDuration, - logException, maybeFromStrict, maybeToStrict, nullMetricSetters, @@ -42,7 +39,6 @@ module Cardano.DbSync.Util ( whenFalseMempty, ) where -import Cardano.BM.Trace (Trace, logError, logInfo) import Cardano.Db (RewardSource (..)) import Cardano.DbSync.Config.Types () import Cardano.DbSync.Types @@ -50,8 +46,6 @@ import Cardano.Ledger.Coin (Coin (..)) import qualified Cardano.Ledger.Shelley.Rewards as Shelley import Cardano.Prelude hiding (catch) import Cardano.Slotting.Slot (SlotNo (..), WithOrigin (..)) -import Control.Exception.Lifted (catch) -import Control.Monad.Trans.Control (MonadBaseControl) import Data.ByteArray (ByteArrayAccess) import qualified Data.ByteArray import qualified Data.ByteString.Base16 as Base16 @@ -99,40 +93,6 @@ traverseMEither action xs = do (y : ys) -> action y >>= either (pure . Left) (const $ traverseMEither action ys) --- | Needed when debugging disappearing exceptions. -liftedLogException :: (MonadBaseControl IO m, MonadIO m) => Trace IO Text -> Text -> m a -> m a -liftedLogException tracer txt action = - action `catch` logger - where - logger :: MonadIO m => SomeException -> m a - logger e = - liftIO $ do - putStrLn $ "Caught exception: txt " ++ show e - logError tracer $ txt <> textShow e - throwIO e - --- | Log the runtime duration of an action. Mainly for debugging. -logActionDuration :: (MonadBaseControl IO m, MonadIO m) => Trace IO Text -> Text -> m a -> m a -logActionDuration tracer label action = do - before <- liftIO Time.getCurrentTime - a <- action - after <- liftIO Time.getCurrentTime - liftIO . logInfo tracer $ mconcat [label, ": duration ", textShow (Time.diffUTCTime after before)] - pure a - --- | ouroboros-network catches 'SomeException' and if a 'nullTracer' is passed into that --- code, the caught exception will not be logged. Therefore wrap all cardano-db-sync code that --- is called from network with an exception logger so at least the exception will be --- logged (instead of silently swallowed) and then rethrown. -logException :: Trace IO Text -> Text -> IO a -> IO a -logException tracer txt action = - action `catch` logger - where - logger :: SomeException -> IO a - logger e = do - logError tracer $ txt <> textShow e - throwIO e - -- | Eequired for testing or when disabling the metrics. nullMetricSetters :: MetricSetters nullMetricSetters = diff --git a/cardano-db-sync/src/Cardano/DbSync/Util/Constraint.hs b/cardano-db-sync/src/Cardano/DbSync/Util/Constraint.hs index af266a6e2..4659966e4 100644 --- a/cardano-db-sync/src/Cardano/DbSync/Util/Constraint.hs +++ b/cardano-db-sync/src/Cardano/DbSync/Util/Constraint.hs @@ -16,10 +16,10 @@ module Cardano.DbSync.Util.Constraint ( ) where import Cardano.BM.Data.Trace (Trace) -import Cardano.BM.Trace (logInfo) import Cardano.Db (ManualDbConstraints (..)) import qualified Cardano.Db as DB import Cardano.DbSync.Api.Types (SyncEnv (..)) +import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx) import Cardano.Prelude (MonadIO (..), Proxy (..), ReaderT (runReaderT), atomically) import Control.Concurrent.Class.MonadSTM.Strict (readTVarIO, writeTVar) import Control.Monad (unless) @@ -100,6 +100,7 @@ addRewardTableConstraint :: ReaderT SqlBackend m () addRewardTableConstraint trce = do let entityD = entityDef $ Proxy @DB.Reward + logCtx = initLogCtx "addRewardTableConstraint" "Cardano.DbSync.Util" DB.alterTable entityD ( DB.AddUniqueConstraint @@ -110,7 +111,7 @@ addRewardTableConstraint trce = do , FieldNameDB "pool_id" ] ) - liftIO $ logNewConstraint trce entityD (unConstraintNameDB constraintNameReward) + liftIO $ logNewConstraint trce logCtx entityD (unConstraintNameDB constraintNameReward) addEpochStakeTableConstraint :: forall m. @@ -119,6 +120,7 @@ addEpochStakeTableConstraint :: ReaderT SqlBackend m () addEpochStakeTableConstraint trce = do let entityD = entityDef $ Proxy @DB.EpochStake + logCtx = initLogCtx "addEpochStakeTableConstraint" "Cardano.DbSync.Util" DB.alterTable entityD ( DB.AddUniqueConstraint @@ -128,16 +130,20 @@ addEpochStakeTableConstraint trce = do , FieldNameDB "pool_id" ] ) - liftIO $ logNewConstraint trce entityD (unConstraintNameDB constraintNameEpochStake) + liftIO $ logNewConstraint trce logCtx entityD (unConstraintNameDB constraintNameEpochStake) logNewConstraint :: Trace IO Text -> + LogContext -> EntityDef -> Text -> IO () -logNewConstraint trce table constraintName = - logInfo trce $ - "The table " - <> unEntityNameDB (entityDB table) - <> " was given a new unique constraint called " - <> constraintName +logNewConstraint trce logCtx table constraintName = + logInfoCtx trce $ + logCtx + { lcMessage = + "The table " + <> unEntityNameDB (entityDB table) + <> " was given a new unique constraint called " + <> constraintName + } diff --git a/cardano-db-sync/src/Cardano/DbSync/Util/Logging.hs b/cardano-db-sync/src/Cardano/DbSync/Util/Logging.hs new file mode 100644 index 000000000..51d08fd63 --- /dev/null +++ b/cardano-db-sync/src/Cardano/DbSync/Util/Logging.hs @@ -0,0 +1,108 @@ +{-# LANGUAGE FlexibleContexts #-} +{-# LANGUAGE OverloadedStrings #-} + +module Cardano.DbSync.Util.Logging ( + LogContext (..), + logInfoCtx, + logWarningCtx, + logErrorCtx, + logDebugCtx, + initLogCtx, + liftedLogExceptionCtx, + logActionDurationCtx, + logExceptionCtx, +) where + +import Cardano.BM.Trace (Trace, logDebug, logError, logInfo, logWarning) +import Cardano.Prelude hiding (catch) +import Control.Exception.Lifted (catch) +import Control.Monad.Trans.Control (MonadBaseControl) +import Data.Text (pack) +import qualified Data.Time.Clock as Time +import Prelude hiding (show, unwords, (.)) + +data LogContext = LogContext + { lcFunction :: Text + , lcComponent :: Text + , lcBlockNo :: Maybe Word64 + , lcSlotNo :: Maybe Word64 + , lcEpochNo :: Maybe Word64 + , lcMessage :: Text + } + +-- TODO: We could select what to show here with a debug flag! +formatLogMessage :: LogContext -> Text +formatLogMessage ctx = + unwords + [ lcMessage ctx + , "[Function:" + , lcFunction ctx + , "| Component:" + , lcComponent ctx + , "| Block No:" + , maybe "None" (pack . show) (lcBlockNo ctx) + , "| Slot No:" + , maybe "None" (pack . show) (lcSlotNo ctx) + , "| Epoch No:" + , maybe "None" (pack . show) (lcEpochNo ctx) + , "]" + ] + +-- Wrapper functions using LogContext +logInfoCtx :: Trace IO Text -> LogContext -> IO () +logInfoCtx trce ctx = logInfo trce (formatLogMessage ctx) + +logWarningCtx :: Trace IO Text -> LogContext -> IO () +logWarningCtx trce ctx = logWarning trce (formatLogMessage ctx) + +logErrorCtx :: Trace IO Text -> LogContext -> IO () +logErrorCtx trce ctx = logError trce (formatLogMessage ctx) + +logDebugCtx :: Trace IO Text -> LogContext -> IO () +logDebugCtx trce ctx = logDebug trce (formatLogMessage ctx) + +initLogCtx :: Text -> Text -> LogContext +initLogCtx functionName componentName = + LogContext + { lcFunction = functionName + , lcComponent = componentName + , lcBlockNo = Nothing + , lcSlotNo = Nothing + , lcEpochNo = Nothing + , lcMessage = "" + } + +-- | Needed when debugging disappearing exceptions. +liftedLogExceptionCtx :: (MonadBaseControl IO m, MonadIO m) => Trace IO Text -> Text -> m a -> m a +liftedLogExceptionCtx tracer txt action = + action `catch` logger + where + logCtx = LogContext txt "Cardano.DbSync.Util" Nothing Nothing Nothing + + logger :: MonadIO m => SomeException -> m a + logger e = + liftIO $ do + logErrorCtx tracer $ logCtx ("Caught exception: txt " <> show e) + throwIO e + +-- | Log the runtime duration of an action. Mainly for debugging. +logActionDurationCtx :: (MonadBaseControl IO m, MonadIO m) => Trace IO Text -> LogContext -> m a -> m a +logActionDurationCtx tracer logCtx action = do + before <- liftIO Time.getCurrentTime + a <- action + after <- liftIO Time.getCurrentTime + liftIO . logInfoCtx tracer $ logCtx {lcMessage = mconcat ["duration: ", textShow (Time.diffUTCTime after before)]} + pure a + +-- | ouroboros-network catches 'SomeException' and if a 'nullTracer' is passed into that +-- code, the caught exception will not be logged. Therefore wrap all cardano-db-sync code that +-- is called from network with an exception logger so at least the exception will be +-- logged (instead of silently swallowed) and then rethrown. +logExceptionCtx :: Trace IO Text -> LogContext -> IO a -> IO a +logExceptionCtx tracer logCtx action = + action `catch` logger + where + logger :: SomeException -> IO a + logger e = do + logErrorCtx tracer $ logCtx {lcMessage = lcMessage logCtx <> textShow e} + throwIO e