Skip to content

Commit e799ab3

Browse files
CmdvCmdv
committed
1903 - extend logging
1 parent 5b131e9 commit e799ab3

34 files changed

+857
-523
lines changed

‎cardano-db-sync/cardano-db-sync.cabal‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -143,6 +143,7 @@ library
143143
Cardano.DbSync.Util.Bech32
144144
Cardano.DbSync.Util.Cbor
145145
Cardano.DbSync.Util.Constraint
146+
Cardano.DbSync.Util.Logging
146147

147148
Paths_cardano_db_sync
148149

‎cardano-db-sync/src/Cardano/DbSync.hs‎

Lines changed: 51 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ module Cardano.DbSync (
2424
extractSyncOptions,
2525
) where
2626

27-
import Cardano.BM.Trace (Trace, logError, logInfo, logWarning)
27+
import Cardano.BM.Trace (Trace)
2828
import qualified Cardano.Crypto as Crypto
2929
import qualified Cardano.Db as DB
3030
import qualified Cardano.Db as Db
@@ -44,6 +44,7 @@ import Cardano.DbSync.Sync (runSyncNodeClient)
4444
import Cardano.DbSync.Tracing.ToObjectOrphans ()
4545
import Cardano.DbSync.Types
4646
import Cardano.DbSync.Util.Constraint (queryIsJsonbInSchema)
47+
import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logErrorCtx, logInfoCtx, logWarningCtx)
4748
import Cardano.Prelude hiding (Nat, (%))
4849
import Cardano.Slotting.Slot (EpochNo (..))
4950
import Control.Concurrent.Async
@@ -79,41 +80,49 @@ runDbSync ::
7980
Bool ->
8081
IO ()
8182
runDbSync metricsSetters knownMigrations iomgr trce params syncNodeConfigFromFile abortOnPanic = do
82-
logInfo trce $ textShow syncOpts
83+
let logCtx = initLogCtx "runDbSync" "Cardano.DbSync"
84+
logInfoCtx trce $ logCtx {lcMessage = "Current sync options: " <> textShow syncOpts}
8385

8486
-- Read the PG connection info
8587
pgConfig <- runOrThrowIO (Db.readPGPass $ enpPGPassSource params)
8688

8789
mErrors <- liftIO $ Db.validateMigrations dbMigrationDir knownMigrations
8890
whenJust mErrors $ \(unknown, stage4orNewStage3) ->
8991
if stage4orNewStage3
90-
then logWarning trce $ Db.renderMigrationValidateError unknown
92+
then logWarningCtx trce $ logCtx {lcMessage = Db.renderMigrationValidateError unknown}
9193
else do
9294
let msg = Db.renderMigrationValidateError unknown
93-
logError trce msg
95+
logErrorCtx trce $ logCtx {lcMessage = msg}
9496
throwIO unknown
9597

96-
logInfo trce "Schema migration files validated"
98+
logInfoCtx trce $ logCtx {lcMessage = "Schema migration files validated"}
9799

98100
let runMigration mode = do
99101
msg <- Db.getMaintenancePsqlConf pgConfig
100-
logInfo trce $ "Running database migrations in mode " <> textShow mode
101-
logInfo trce msg
102-
when (mode `elem` [Db.Indexes, Db.Full]) $ logWarning trce indexesMsg
102+
logInfoCtx trce $ logCtx {lcMessage = "Running database migrations in mode " <> textShow mode}
103+
logInfoCtx trce $ logCtx {lcMessage = msg}
104+
when (mode `elem` [Db.Indexes, Db.Full]) $ logWarningCtx trce $ logCtx {lcMessage = indexesMsg}
103105
Db.runMigrations pgConfig True dbMigrationDir (Just $ Db.LogFileDir "/tmp") mode (txOutConfigToTableType txOutConfig)
104106
(ranMigrations, unofficial) <- if enpForceIndexes params then runMigration Db.Full else runMigration Db.Initial
105107
unless (null unofficial) $
106-
logWarning trce $
107-
"Unofficial migration scripts found: "
108-
<> textShow unofficial
108+
logWarningCtx trce $
109+
logCtx {lcMessage = "Unofficial migration scripts found: " <> textShow unofficial}
109110

110-
if ranMigrations
111-
then logInfo trce "All migrations were executed"
112-
else logInfo trce "Some migrations were not executed. They need to run when syncing has started."
111+
logInfoCtx trce $
112+
logCtx
113+
{ lcMessage =
114+
if ranMigrations
115+
then "All migrations were executed"
116+
else "Some migrations were not executed. They need to run when syncing has started."
117+
}
113118

114-
if enpForceIndexes params
115-
then logInfo trce "All user indexes were created"
116-
else logInfo trce "New user indexes were not created. They may be created later if necessary."
119+
logInfoCtx trce $
120+
logCtx
121+
{ lcMessage =
122+
if enpForceIndexes params
123+
then "All user indexes were created"
124+
else "New user indexes were not created. They may be created later if necessary."
125+
}
117126

118127
let connectionString = Db.toConnectionString pgConfig
119128

@@ -162,12 +171,16 @@ runSyncNode ::
162171
SyncOptions ->
163172
IO ()
164173
runSyncNode metricsSetters trce iomgr dbConnString ranMigrations runMigrationFnc syncNodeConfigFromFile syncNodeParams syncOptions = do
174+
let logCtx = initLogCtx "runSyncNode" "Cardano.DbSync"
165175
whenJust maybeLedgerDir $
166176
\enpLedgerStateDir -> do
167177
createDirectoryIfMissing True (unLedgerStateDir enpLedgerStateDir)
168-
logInfo trce $ "Using byron genesis file from: " <> (show . unGenesisFile $ dncByronGenesisFile syncNodeConfigFromFile)
169-
logInfo trce $ "Using shelley genesis file from: " <> (show . unGenesisFile $ dncShelleyGenesisFile syncNodeConfigFromFile)
170-
logInfo trce $ "Using alonzo genesis file from: " <> (show . unGenesisFile $ dncAlonzoGenesisFile syncNodeConfigFromFile)
178+
logInfoCtx trce $
179+
logCtx {lcMessage = "Using byron genesis file from: " <> (show . unGenesisFile $ dncByronGenesisFile syncNodeConfigFromFile)}
180+
logInfoCtx trce $
181+
logCtx {lcMessage = "Using shelley genesis file from: " <> (show . unGenesisFile $ dncShelleyGenesisFile syncNodeConfigFromFile)}
182+
logInfoCtx trce $
183+
logCtx {lcMessage = "Using alonzo genesis file from: " <> (show . unGenesisFile $ dncAlonzoGenesisFile syncNodeConfigFromFile)}
171184

172185
let useLedger = shouldUseLedger (sioLedger $ dncInsertOptions syncNodeConfigFromFile)
173186

@@ -193,16 +206,16 @@ runSyncNode metricsSetters trce iomgr dbConnString ranMigrations runMigrationFnc
193206

194207
-- Warn the user that jsonb datatypes are being removed from the database schema.
195208
when (isJsonbInSchema && removeJsonbFromSchemaConfig) $ do
196-
liftIO $ logWarning trce "Removing jsonb datatypes from the database. This can take time."
209+
liftIO $ logWarningCtx trce $ logCtx {lcMessage = "Removing jsonb datatypes from the database. This can take time."}
197210
liftIO $ runRemoveJsonbFromSchema syncEnv
198211

199212
-- Warn the user that jsonb datatypes are being added to the database schema.
200213
when (not isJsonbInSchema && not removeJsonbFromSchemaConfig) $ do
201-
liftIO $ logWarning trce "Adding jsonb datatypes back to the database. This can take time."
214+
liftIO $ logWarningCtx trce $ logCtx {lcMessage = "Adding jsonb datatypes back to the database. This can take time."}
202215
liftIO $ runAddJsonbToSchema syncEnv
203216
liftIO $ runExtraMigrationsMaybe syncEnv
204217
unless useLedger $ liftIO $ do
205-
logInfo trce "Migrating to a no ledger schema"
218+
logInfoCtx trce $ logCtx {lcMessage = "Migrating to a no ledger schema"}
206219
Db.noLedgerMigrations backend trce
207220
insertValidateGenesisDist syncEnv (dncNetworkName syncNodeConfigFromFile) genCfg (useShelleyInit syncNodeConfigFromFile)
208221

@@ -227,13 +240,17 @@ runSyncNode metricsSetters trce iomgr dbConnString ranMigrations runMigrationFnc
227240
maybeLedgerDir = enpMaybeLedgerStateDir syncNodeParams
228241

229242
logProtocolMagicId :: Trace IO Text -> Crypto.ProtocolMagicId -> ExceptT SyncNodeError IO ()
230-
logProtocolMagicId tracer pm =
243+
logProtocolMagicId tracer pm = do
244+
let logCtx = initLogCtx "logProtocolMagicId" "Cardano.DbSync"
231245
liftIO
232-
. logInfo tracer
233-
$ mconcat
234-
[ "NetworkMagic: "
235-
, textShow (Crypto.unProtocolMagicId pm)
236-
]
246+
. logInfoCtx tracer
247+
$ logCtx
248+
{ lcMessage =
249+
mconcat
250+
[ "NetworkMagic: "
251+
, textShow (Crypto.unProtocolMagicId pm)
252+
]
253+
}
237254

238255
-- -------------------------------------------------------------------------------------------------
239256

@@ -299,10 +316,11 @@ extractSyncOptions snp aop snc =
299316

300317
startupReport :: Trace IO Text -> Bool -> SyncNodeParams -> IO ()
301318
startupReport trce aop params = do
302-
logInfo trce $ mconcat ["Version number: ", Text.pack (showVersion version)]
303-
logInfo trce $ mconcat ["Git hash: ", Db.gitRev]
304-
logInfo trce $ mconcat ["Enviroment variable DbSyncAbortOnPanic: ", textShow aop]
305-
logInfo trce $ textShow params
319+
let logCtx = initLogCtx "runSyncNode" "Cardano.DbSync"
320+
logInfoCtx trce $ logCtx {lcMessage = mconcat ["Version number: ", Text.pack (showVersion version)]}
321+
logInfoCtx trce $ logCtx {lcMessage = mconcat ["Git hash: ", Db.gitRev]}
322+
logInfoCtx trce $ logCtx {lcMessage = mconcat ["Enviroment variable DbSyncAbortOnPanic: ", textShow aop]}
323+
logInfoCtx trce $ logCtx {lcMessage = textShow params}
306324

307325
txOutConfigToTableType :: TxOutConfig -> DB.TxOutTableType
308326
txOutConfigToTableType config = case config of

‎cardano-db-sync/src/Cardano/DbSync/Api.hs‎

Lines changed: 56 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,7 @@ module Cardano.DbSync.Api (
5151
convertToPoint,
5252
) where
5353

54-
import Cardano.BM.Trace (Trace, logInfo, logWarning)
54+
import Cardano.BM.Trace (Trace)
5555
import qualified Cardano.Chain.Genesis as Byron
5656
import Cardano.Crypto.ProtocolMagic (ProtocolMagicId (..))
5757
import qualified Cardano.Db as DB
@@ -73,6 +73,7 @@ import Cardano.DbSync.LocalStateQuery
7373
import Cardano.DbSync.Types
7474
import Cardano.DbSync.Util
7575
import Cardano.DbSync.Util.Constraint (dbConstraintNamesExists)
76+
import Cardano.DbSync.Util.Logging (LogContext (..), initLogCtx, logInfoCtx, logWarningCtx)
7677
import qualified Cardano.Ledger.BaseTypes as Ledger
7778
import qualified Cardano.Ledger.Shelley.Genesis as Shelley
7879
import Cardano.Prelude
@@ -101,7 +102,8 @@ import qualified Ouroboros.Network.Point as Point
101102

102103
setConsistentLevel :: SyncEnv -> ConsistentLevel -> IO ()
103104
setConsistentLevel env cst = do
104-
logInfo (getTrace env) $ "Setting ConsistencyLevel to " <> textShow cst
105+
let logCtx = initLogCtx "setConsistentLevel" "Cardano.DbSync.Api"
106+
logInfoCtx (getTrace env) $ logCtx {lcMessage = "Setting ConsistencyLevel to " <> textShow cst}
105107
atomically $ writeTVar (envConsistentLevel env) cst
106108

107109
getConsistentLevel :: SyncEnv -> IO ConsistentLevel
@@ -158,10 +160,11 @@ getRanIndexes env = do
158160

159161
runIndexMigrations :: SyncEnv -> IO ()
160162
runIndexMigrations env = do
163+
let logCtx = initLogCtx "runIndexMigrations" "Cardano.DbSync.Api"
161164
haveRan <- readTVarIO $ envIndexes env
162165
unless haveRan $ do
163166
envRunDelayedMigration env DB.Indexes
164-
logInfo (getTrace env) "Indexes were created"
167+
logInfoCtx (getTrace env) $ logCtx {lcMessage = "Indexes were created"}
165168
atomically $ writeTVar (envIndexes env) True
166169

167170
initPruneConsumeMigration :: Bool -> Bool -> Bool -> Bool -> DB.PruneConsumeMigration
@@ -178,8 +181,9 @@ getPruneConsume = soptPruneConsumeMigration . envOptions
178181
runExtraMigrationsMaybe :: SyncEnv -> IO ()
179182
runExtraMigrationsMaybe syncEnv = do
180183
let pcm = getPruneConsume syncEnv
184+
logCtx = initLogCtx "runExtraMigrationsMaybe" "Cardano.DbSync.Api"
181185
txOutTableType = getTxOutTableType syncEnv
182-
logInfo (getTrace syncEnv) $ "runExtraMigrationsMaybe: " <> textShow pcm
186+
logInfoCtx (getTrace syncEnv) $ logCtx {lcMessage = "runExtraMigrationsMaybe: " <> textShow pcm}
183187
DB.runDbIohkNoLogging (envBackend syncEnv) $
184188
DB.runExtraMigrations
185189
(getTrace syncEnv)
@@ -306,12 +310,23 @@ getDbTipBlockNo env = do
306310
mblk <- getDbLatestBlockInfo (envBackend env)
307311
pure $ maybe Point.Origin (Point.At . bBlockNo) mblk
308312

309-
logDbState :: SyncEnv -> IO ()
310-
logDbState env = do
313+
getCurrentTipBlockNo :: SyncEnv -> IO (WithOrigin BlockNo)
314+
getCurrentTipBlockNo env = do
315+
maybeTip <- getDbLatestBlockInfo (envBackend env)
316+
case maybeTip of
317+
Just tip -> pure $ At (bBlockNo tip)
318+
Nothing -> pure Origin
319+
320+
logDbState :: SyncEnv -> LogContext -> IO ()
321+
logDbState env logCtx = do
311322
mblk <- getDbLatestBlockInfo (envBackend env)
312323
case mblk of
313-
Nothing -> logInfo tracer "Database is empty"
314-
Just tip -> logInfo tracer $ mconcat ["Database tip is at ", showTip tip]
324+
Nothing ->
325+
logInfoCtx tracer $
326+
logCtx {lcMessage = "Database is empty"}
327+
Just tip ->
328+
logInfoCtx tracer $
329+
logCtx {lcMessage = mconcat ["Database tip is at ", showTip tip]}
315330
where
316331
showTip :: TipInfo -> Text
317332
showTip tipInfo =
@@ -325,13 +340,6 @@ logDbState env = do
325340
tracer :: Trace IO Text
326341
tracer = getTrace env
327342

328-
getCurrentTipBlockNo :: SyncEnv -> IO (WithOrigin BlockNo)
329-
getCurrentTipBlockNo env = do
330-
maybeTip <- getDbLatestBlockInfo (envBackend env)
331-
case maybeTip of
332-
Just tip -> pure $ At (bBlockNo tip)
333-
Nothing -> pure Origin
334-
335343
mkSyncEnv ::
336344
Trace IO Text ->
337345
SqlBackend ->
@@ -347,6 +355,7 @@ mkSyncEnv ::
347355
RunMigration ->
348356
IO SyncEnv
349357
mkSyncEnv trce backend connectionString syncOptions protoInfo nw nwMagic systemStart syncNodeConfigFromFile syncNP ranMigrations runMigrationFnc = do
358+
let logCtx = initLogCtx "mkSyncEnv" "Cardano.DbSync.Api"
350359
dbCNamesVar <- newTVarIO =<< dbConstraintNamesExists backend
351360
cache <-
352361
if soptCache syncOptions
@@ -384,9 +393,13 @@ mkSyncEnv trce backend connectionString syncOptions protoInfo nw nwMagic systemS
384393
syncOptions
385394
(Nothing, False) -> NoLedger <$> mkNoLedgerEnv trce protoInfo nw systemStart
386395
(Just _, False) -> do
387-
logWarning trce $
388-
"Disabling the ledger doesn't require having a --state-dir."
389-
<> " For more details view https://github.com/IntersectMBO/cardano-db-sync/blob/master/doc/configuration.md#ledger"
396+
logWarningCtx trce $
397+
logCtx
398+
{ lcMessage =
399+
"Disabling the ledger doesn't require having a --state-dir."
400+
<> " For more details view "
401+
<> " https://github.com/IntersectMBO/cardano-db-sync/blob/master/doc/configuration.md#ledger"
402+
}
390403
NoLedger <$> mkNoLedgerEnv trce protoInfo nw systemStart
391404
-- This won't ever call because we error out this combination at parse time
392405
(Nothing, True) -> NoLedger <$> mkNoLedgerEnv trce protoInfo nw systemStart
@@ -534,6 +547,7 @@ getBootstrapInProgress ::
534547
SqlBackend ->
535548
IO Bool
536549
getBootstrapInProgress trce bootstrapFlag sqlBackend = do
550+
let logCtx = initLogCtx "getBootstrapInProgress" "Cardano.DbSync.Api"
537551
DB.runDbIohkNoLogging sqlBackend $ do
538552
ems <- DB.queryAllExtraMigrations
539553
let btsState = DB.bootstrapState ems
@@ -547,26 +561,35 @@ getBootstrapInProgress trce bootstrapFlag sqlBackend = do
547561
liftIO $ DB.logAndThrowIO trce "Bootstrap flag not set, but still in progress"
548562
(True, DB.BootstrapNotStarted) -> do
549563
liftIO $
550-
logInfo trce $
551-
mconcat
552-
[ "Syncing with bootstrap. "
553-
, "This won't populate tx_out until the tip of the chain."
554-
]
564+
logInfoCtx trce $
565+
logCtx
566+
{ lcMessage =
567+
mconcat
568+
[ "Syncing with bootstrap. "
569+
, "This won't populate tx_out until the tip of the chain."
570+
]
571+
}
555572
DB.insertExtraMigration DB.BootstrapStarted
556573
pure True
557574
(True, DB.BootstrapInProgress) -> do
558575
liftIO $
559-
logInfo trce $
560-
mconcat
561-
[ "Syncing with bootstrap is in progress. "
562-
, "This won't populate tx_out until the tip of the chain."
563-
]
576+
logInfoCtx trce $
577+
logCtx
578+
{ lcMessage =
579+
mconcat
580+
[ "Syncing with bootstrap is in progress. "
581+
, "This won't populate tx_out until the tip of the chain."
582+
]
583+
}
564584
pure True
565585
(True, DB.BootstrapDone) -> do
566586
liftIO $
567-
logWarning trce $
568-
mconcat
569-
[ "Bootstrap flag is set, but it will be ignored, "
570-
, "since bootstrap is already done."
571-
]
587+
logWarningCtx trce $
588+
logCtx
589+
{ lcMessage =
590+
mconcat
591+
[ "Bootstrap flag is set, but it will be ignored, "
592+
, "since bootstrap is already done."
593+
]
594+
}
572595
pure False

0 commit comments

Comments
 (0)