From 8eca278ffef1eee17a89e2d3d49ad9373e10bbac Mon Sep 17 00:00:00 2001
From: Pavel Zbitskiy <65323360+algorandskiy@users.noreply.github.com>
Date: Wed, 31 Jul 2024 10:26:20 -0400
Subject: [PATCH] tests: debug logging for
 TestVotersReloadFromDiskAfterOneStateProofCommitted (#6088)

---
 ledger/acctupdates_test.go | 14 +++++++++++++-
 ledger/blockqueue_test.go  |  1 +
 ledger/ledger.go           |  7 +++++--
 ledger/ledger_test.go      |  1 +
 ledger/tracker.go          |  9 +++++++++
 5 files changed, 29 insertions(+), 3 deletions(-)

diff --git a/ledger/acctupdates_test.go b/ledger/acctupdates_test.go
index 283fbcdc2e..a27a2be795 100644
--- a/ledger/acctupdates_test.go
+++ b/ledger/acctupdates_test.go
@@ -130,7 +130,18 @@ func makeMockLedgerForTrackerWithLogger(t testing.TB, inMemory bool, initialBloc
 			Totals: totals,
 		}
 	}
-	return &mockLedgerForTracker{dbs: dbs, log: l, filename: fileName, inMemory: inMemory, blocks: blocks, deltas: deltas, consensusParams: config.Consensus[consensusVersion], consensusVersion: consensusVersion, accts: accts[0]}
+	ml := &mockLedgerForTracker{
+		dbs:      dbs,
+		log:      l,
+		filename: fileName,
+		inMemory: inMemory,
+		blocks:   blocks,
+		deltas:   deltas, consensusParams: config.Consensus[consensusVersion],
+		consensusVersion: consensusVersion,
+		accts:            accts[0],
+		trackers:         trackerRegistry{log: l},
+	}
+	return ml
 
 }
 
@@ -160,6 +171,7 @@ func (ml *mockLedgerForTracker) fork(t testing.TB) *mockLedgerForTracker {
 		filename:         fn,
 		consensusParams:  ml.consensusParams,
 		consensusVersion: ml.consensusVersion,
+		trackers:         trackerRegistry{log: dblogger},
 	}
 	for k, v := range ml.accts {
 		newLedgerTracker.accts[k] = v
diff --git a/ledger/blockqueue_test.go b/ledger/blockqueue_test.go
index e74fbc0b3b..e72523be71 100644
--- a/ledger/blockqueue_test.go
+++ b/ledger/blockqueue_test.go
@@ -207,6 +207,7 @@ func TestBlockQueueSyncerDeletion(t *testing.T) {
 			l := &Ledger{
 				log:      log,
 				blockDBs: blockDBs,
+				trackers: trackerRegistry{log: log},
 			}
 			if test.tracker != nil {
 				l.trackers.trackers = append(l.trackers.trackers, test.tracker)
diff --git a/ledger/ledger.go b/ledger/ledger.go
index 7459c23037..2f10724fee 100644
--- a/ledger/ledger.go
+++ b/ledger/ledger.go
@@ -214,8 +214,11 @@ func (l *Ledger) reloadLedger() error {
 	blockListeners := make([]ledgercore.BlockListener, 0, len(l.notifier.listeners))
 	blockListeners = append(blockListeners, l.notifier.listeners...)
 
-	// close the trackers.
-	l.trackers.close()
+	// close the trackers if the registry was already initialized: opening a new ledger calls reloadLedger
+	// and there is nothing to close. Registry's logger is not initialized yet so close cannot log.
+	if l.trackers.trackers != nil {
+		l.trackers.close()
+	}
 
 	// init block queue
 	var err error
diff --git a/ledger/ledger_test.go b/ledger/ledger_test.go
index c97040f42c..f1ee8898c9 100644
--- a/ledger/ledger_test.go
+++ b/ledger/ledger_test.go
@@ -3415,6 +3415,7 @@ func TestLedgerRetainMinOffCatchpointInterval(t *testing.T) {
 			l := &Ledger{}
 			l.cfg = cfg
 			l.archival = cfg.Archival
+			l.trackers.log = logging.TestingLog(t)
 
 			for i := 1; i <= blocksToMake; i++ {
 				minBlockToKeep := l.notifyCommit(basics.Round(i))
diff --git a/ledger/tracker.go b/ledger/tracker.go
index 97098a572f..96e42e949f 100644
--- a/ledger/tracker.go
+++ b/ledger/tracker.go
@@ -467,6 +467,7 @@ func (tr *trackerRegistry) scheduleCommit(blockqRound, maxLookback basics.Round)
 			// Dropping this dcc allows the blockqueue syncer to continue persisting other blocks
 			// and ledger reads to proceed without being blocked by trackerMu lock.
 			tr.accountsWriting.Done()
+			tr.log.Debugf("trackerRegistry.scheduleCommit: deferredCommits channel is full, skipping commit for (%d-%d)", dcc.oldBase, dcc.oldBase+basics.Round(dcc.offset))
 		}
 	}
 }
@@ -491,22 +492,27 @@ func (tr *trackerRegistry) isBehindCommittingDeltas(latest basics.Round) bool {
 }
 
 func (tr *trackerRegistry) close() {
+	tr.log.Debugf("trackerRegistry is closing")
 	if tr.ctxCancel != nil {
 		tr.ctxCancel()
 	}
 
 	// close() is called from reloadLedger() when and trackerRegistry is not initialized yet
 	if tr.commitSyncerClosed != nil {
+		tr.log.Debugf("trackerRegistry is waiting for accounts writing to complete")
 		tr.waitAccountsWriting()
 		// this would block until the commitSyncerClosed channel get closed.
 		<-tr.commitSyncerClosed
+		tr.log.Debugf("trackerRegistry done waiting for accounts writing")
 	}
 
+	tr.log.Debugf("trackerRegistry is closing trackers")
 	for _, lt := range tr.trackers {
 		lt.close()
 	}
 	tr.trackers = nil
 	tr.accts = nil
+	tr.log.Debugf("trackerRegistry has closed")
 }
 
 // commitSyncer is the syncer go-routine function which perform the database updates. Internally, it dequeues deferredCommits and
@@ -525,11 +531,13 @@ func (tr *trackerRegistry) commitSyncer(deferredCommits chan *deferredCommitCont
 			}
 		case <-tr.ctx.Done():
 			// drain the pending commits queue:
+			tr.log.Debugf("commitSyncer is closing, draining the pending commits queue")
 			drained := false
 			for !drained {
 				select {
 				case <-deferredCommits:
 					tr.accountsWriting.Done()
+					tr.log.Debugf("commitSyncer drained a pending commit")
 				default:
 					drained = true
 				}
@@ -648,6 +656,7 @@ func (tr *trackerRegistry) commitRound(dcc *deferredCommitContext) error {
 		lt.postCommitUnlocked(tr.ctx, dcc)
 	}
 
+	tr.log.Debugf("commitRound completed for (%d-%d)", dbRound, dbRound+basics.Round(offset))
 	return nil
 }