From 5b81db922a8e3cfd5e47086599c9f40f637807ce Mon Sep 17 00:00:00 2001 From: Pavel Zbitskiy Date: Fri, 12 Jul 2024 15:29:57 -0400 Subject: [PATCH 1/4] tests: debug logging for TestVotersReloadFromDiskAfterOneStateProofCommitted --- ledger/tracker.go | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/ledger/tracker.go b/ledger/tracker.go index 97098a572f..c80cf4c18f 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,15 +492,18 @@ 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("waiting for accounts writing to complete") tr.waitAccountsWriting() // this would block until the commitSyncerClosed channel get closed. <-tr.commitSyncerClosed + tr.log.Debugf("accounts writing completed") } for _, lt := range tr.trackers { @@ -507,6 +511,7 @@ func (tr *trackerRegistry) 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 +530,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 +655,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 } From 61509e6ade2207f8ae273fa02b9263d9e10c3a1a Mon Sep 17 00:00:00 2001 From: Pavel Zbitskiy Date: Fri, 12 Jul 2024 16:04:12 -0400 Subject: [PATCH 2/4] fix tracker.close() call without loggers set --- ledger/ledger.go | 1 + ledger/tracker.go | 1 + 2 files changed, 2 insertions(+) diff --git a/ledger/ledger.go b/ledger/ledger.go index 7459c23037..99a1a55892 100644 --- a/ledger/ledger.go +++ b/ledger/ledger.go @@ -215,6 +215,7 @@ func (l *Ledger) reloadLedger() error { blockListeners = append(blockListeners, l.notifier.listeners...) // close the trackers. + l.trackers.log = l.trackerLog() l.trackers.close() // init block queue diff --git a/ledger/tracker.go b/ledger/tracker.go index c80cf4c18f..7446911b15 100644 --- a/ledger/tracker.go +++ b/ledger/tracker.go @@ -492,6 +492,7 @@ func (tr *trackerRegistry) isBehindCommittingDeltas(latest basics.Round) bool { } func (tr *trackerRegistry) close() { + fmt.Printf("trackerRegistry: %v\n", tr.log) tr.log.Debugf("trackerRegistry is closing") if tr.ctxCancel != nil { tr.ctxCancel() From a5f278930a2539bc87ee7b524925228d4a4c7c41 Mon Sep 17 00:00:00 2001 From: Pavel Zbitskiy Date: Tue, 30 Jul 2024 11:10:01 -0400 Subject: [PATCH 3/4] fix tests missing trackers.log --- ledger/acctupdates_test.go | 14 +++++++++++++- ledger/blockqueue_test.go | 1 + ledger/ledger_test.go | 1 + ledger/tracker.go | 6 +++--- 4 files changed, 18 insertions(+), 4 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_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 7446911b15..96e42e949f 100644 --- a/ledger/tracker.go +++ b/ledger/tracker.go @@ -492,7 +492,6 @@ func (tr *trackerRegistry) isBehindCommittingDeltas(latest basics.Round) bool { } func (tr *trackerRegistry) close() { - fmt.Printf("trackerRegistry: %v\n", tr.log) tr.log.Debugf("trackerRegistry is closing") if tr.ctxCancel != nil { tr.ctxCancel() @@ -500,13 +499,14 @@ func (tr *trackerRegistry) close() { // close() is called from reloadLedger() when and trackerRegistry is not initialized yet if tr.commitSyncerClosed != nil { - tr.log.Debugf("waiting for accounts writing to complete") + 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("accounts writing completed") + tr.log.Debugf("trackerRegistry done waiting for accounts writing") } + tr.log.Debugf("trackerRegistry is closing trackers") for _, lt := range tr.trackers { lt.close() } From bdb590e0cd6b82a78b2fa714ec425fe8507e0bb7 Mon Sep 17 00:00:00 2001 From: Pavel Zbitskiy Date: Tue, 30 Jul 2024 13:21:08 -0400 Subject: [PATCH 4/4] do not close not initialized registry --- ledger/ledger.go | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/ledger/ledger.go b/ledger/ledger.go index 99a1a55892..2f10724fee 100644 --- a/ledger/ledger.go +++ b/ledger/ledger.go @@ -214,9 +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.log = l.trackerLog() - 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