Refine logging of migrations and tx ingestion (stellar#237)

Downgrade Tx ingestion logging to Debug (otherwise we flood the logs during the migration)

Make sure we log whenever a migration is applied

cmd/soroban-rpc/internal/daemon/daemon.go

@@ -296,7 +296,11 @@ func (d *Daemon) mustInitializeStorage(cfg *config.Config) (*feewindow.FeeWindow
 		cfg.NetworkPassphrase,
 		cfg.HistoryRetentionWindow,
 	)
-	feewindows := feewindow.NewFeeWindows(cfg.ClassicFeeStatsLedgerRetentionWindow, cfg.SorobanFeeStatsLedgerRetentionWindow, cfg.NetworkPassphrase)
+	feewindows := feewindow.NewFeeWindows(
+		cfg.ClassicFeeStatsLedgerRetentionWindow,
+		cfg.SorobanFeeStatsLedgerRetentionWindow,
+		cfg.NetworkPassphrase,
+	)
 
 	readTxMetaCtx, cancelReadTxMeta := context.WithTimeout(context.Background(), cfg.IngestionTimeout)
 	defer cancelReadTxMeta()
@@ -315,7 +319,7 @@ func (d *Daemon) mustInitializeStorage(cfg *config.Config) (*feewindow.FeeWindow
 			initialSeq = currentSeq
 			d.logger.WithFields(supportlog.F{
 				"seq": currentSeq,
-			}).Info("initializing in-memory store")
+			}).Info("initializing in-memory store and applying DB data migrations")
 		} else if (currentSeq-initialSeq)%inMemoryInitializationLedgerLogPeriod == 0 {
 			d.logger.WithFields(supportlog.F{
 				"seq": currentSeq,
@@ -346,7 +350,7 @@ func (d *Daemon) mustInitializeStorage(cfg *config.Config) (*feewindow.FeeWindow
 	if currentSeq != 0 {
 		d.logger.WithFields(supportlog.F{
 			"seq": currentSeq,
-		}).Info("finished initializing in-memory store")
+		}).Info("finished initializing in-memory store and applying DB data migrations")
 	}
 
 	return feewindows, eventStore

cmd/soroban-rpc/internal/db/ledger.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 
 	sq "github.com/Masterminds/squirrel"
+
 	"github.com/stellar/go/xdr"
 
 	"github.com/stellar/soroban-rpc/cmd/soroban-rpc/internal/ledgerbucketwindow"

cmd/soroban-rpc/internal/db/migration.go

@@ -115,9 +115,13 @@ type guardedMigration struct {
 	db              *DB
 	migration       MigrationApplier
 	alreadyMigrated bool
+	logger          *log.Entry
+	applyLogged     bool
 }
 
-func newGuardedDataMigration(ctx context.Context, uniqueMigrationName string, factory migrationApplierFactory, db *DB) (Migration, error) {
+func newGuardedDataMigration(
+	ctx context.Context, uniqueMigrationName string, logger *log.Entry, factory migrationApplierFactory, db *DB,
+) (Migration, error) {
 	migrationDB := &DB{
 		cache:            db.cache,
 		SessionInterface: db.SessionInterface.Clone(),
@@ -132,7 +136,7 @@ func newGuardedDataMigration(ctx context.Context, uniqueMigrationName string, fa
 		return nil, err
 	}
 	latestLedger, err := NewLedgerEntryReader(db).GetLatestLedgerSequence(ctx)
-	if err != nil && err != ErrEmptyDB {
+	if errors.Is(err, ErrEmptyDB) {
 		err = errors.Join(err, migrationDB.Rollback())
 		return nil, fmt.Errorf("failed to get latest ledger sequence: %w", err)
 	}
@@ -146,6 +150,7 @@ func newGuardedDataMigration(ctx context.Context, uniqueMigrationName string, fa
 		db:              migrationDB,
 		migration:       applier,
 		alreadyMigrated: previouslyMigrated,
+		logger:          logger,
 	}
 	return guardedMigration, nil
 }
@@ -156,6 +161,10 @@ func (g *guardedMigration) Apply(ctx context.Context, meta xdr.LedgerCloseMeta)
 		// but, just in case.
 		return nil
 	}
+	if !g.applyLogged {
+		g.logger.WithField("ledger", meta.LedgerSequence()).Info("applying migration")
+		g.applyLogged = true
+	}
 	return g.migration.Apply(ctx, meta)
 }
 
@@ -177,19 +186,20 @@ func (g *guardedMigration) Commit(ctx context.Context) error {
 	return g.db.Commit()
 }
 
-func (g *guardedMigration) Rollback(ctx context.Context) error {
+func (g *guardedMigration) Rollback(_ context.Context) error {
 	return g.db.Rollback()
 }
 
 func BuildMigrations(ctx context.Context, logger *log.Entry, db *DB, cfg *config.Config) (Migration, error) {
 	migrationName := "TransactionsTable"
+	logger = logger.WithField("migration", migrationName)
 	factory := newTransactionTableMigration(
 		ctx,
-		logger.WithField("migration", migrationName),
+		logger,
 		cfg.HistoryRetentionWindow,
 		cfg.NetworkPassphrase,
 	)
-	m, err := newGuardedDataMigration(ctx, migrationName, factory, db)
+	m, err := newGuardedDataMigration(ctx, migrationName, logger, factory, db)
 	if err != nil {
 		return nil, fmt.Errorf("creating guarded transaction migration: %w", err)
 	}

cmd/soroban-rpc/internal/db/transaction.go

@@ -111,7 +111,7 @@ func (txn *transactionHandler) InsertTransactions(lcm xdr.LedgerCloseMeta) error
 	_, err = query.RunWith(txn.stmtCache).Exec()
 
 	L.WithField("duration", time.Since(start)).
-		Infof("Ingested %d transaction lookups", len(transactions))
+		Debugf("Ingested %d transaction lookups", len(transactions))
 
 	return err
 }