Skip to content

Commit 294f89e

Browse files
randy-crorandy-cro
committed
add debug logs (to be removed)
1 parent 22489fd commit 294f89e

File tree

4 files changed

+81
-9
lines changed

4 files changed

+81
-9
lines changed

‎baseapp/abci.go‎

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -911,6 +911,7 @@ func (app *BaseApp) FinalizeBlock(req *abci.RequestFinalizeBlock) (res *abci.Res
911911
}()
912912

913913
if app.optimisticExec.Initialized() {
914+
app.logger.Error("BASEAPP::::FinalizeBlock: Using optimistic execution", "height", req.Height)
914915
// check if the hash we got is the same as the one we are executing
915916
aborted := app.optimisticExec.AbortIfNeeded(req)
916917
// Wait for the OE to finish, regardless of whether it was aborted or not
@@ -919,21 +920,27 @@ func (app *BaseApp) FinalizeBlock(req *abci.RequestFinalizeBlock) (res *abci.Res
919920
// only return if we are not aborting
920921
if !aborted {
921922
if res != nil {
923+
app.logger.Error("BASEAPP::::FinalizeBlock (OE): About to compute app hash", "height", req.Height)
922924
res.AppHash = app.workingHash()
925+
app.logger.Error("BASEAPP::::FinalizeBlock (OE): App hash set in response", "height", req.Height, "app_hash", fmt.Sprintf("%X", res.AppHash))
923926
}
924927

925928
return res, err
926929
}
927930

931+
app.logger.Error("BASEAPP::::FinalizeBlock: Optimistic execution was aborted", "height", req.Height)
928932
// if it was aborted, we need to reset the state
929933
app.finalizeBlockState = nil
930934
app.optimisticExec.Reset()
931935
}
932936

933937
// if no OE is running, just run the block (this is either a block replay or a OE that got aborted)
938+
app.logger.Error("BASEAPP::::FinalizeBlock: About to run internalFinalizeBlock", "height", req.Height)
934939
res, err = app.internalFinalizeBlock(context.Background(), req)
935940
if res != nil {
941+
app.logger.Error("BASEAPP::::FinalizeBlock: About to compute app hash", "height", req.Height)
936942
res.AppHash = app.workingHash()
943+
app.logger.Error("BASEAPP::::FinalizeBlock: App hash set in response", "height", req.Height, "app_hash", fmt.Sprintf("%X", res.AppHash))
937944
}
938945

939946
return res, err
@@ -1020,14 +1027,16 @@ func (app *BaseApp) Commit() (*abci.ResponseCommit, error) {
10201027
// state transitions will be flushed to disk and as a result, but we already have
10211028
// an application Merkle root.
10221029
func (app *BaseApp) workingHash() []byte {
1030+
app.logger.Error("BASEAPP::::=== COMPUTING APP HASH - workingHash() called ===")
1031+
10231032
// Write the FinalizeBlock state into branched storage and commit the MultiStore.
10241033
// The write to the FinalizeBlock state writes all state transitions to the root
10251034
// MultiStore (app.cms) so when Commit() is called it persists those values.
10261035
app.finalizeBlockState.ms.Write()
10271036

10281037
// Get the hash of all writes in order to return the apphash to the comet in finalizeBlock.
10291038
commitHash := app.cms.WorkingHash()
1030-
app.logger.Debug("hash of all writes", "workingHash", fmt.Sprintf("%X", commitHash))
1039+
app.logger.Error("BASEAPP::::=== APP HASH COMPUTED ===", "workingHash", fmt.Sprintf("%X", commitHash))
10311040

10321041
return commitHash
10331042
}

‎store/rootmulti/store.go‎

Lines changed: 17 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -564,7 +564,23 @@ func (rs *Store) WorkingHash() []byte {
564564
return storeInfos[i].Name < storeInfos[j].Name
565565
})
566566

567-
return types.CommitInfo{StoreInfos: storeInfos}.Hash()
567+
appHash := types.CommitInfo{StoreInfos: storeInfos}.Hash()
568+
569+
// Log all individual store hashes for debugging
570+
if rs.logger != nil {
571+
rs.logger.Error("STORE::::Computing app hash from store hashes", "num_stores", len(storeInfos), "app_hash", fmt.Sprintf("%X", appHash))
572+
for _, si := range storeInfos {
573+
rs.logger.Error("STORE::::Individual store hash", "store_name", si.Name, "hash", fmt.Sprintf("%X", si.GetHash()))
574+
}
575+
} else {
576+
// Fallback if logger is nil
577+
fmt.Printf("STORE::::Computing app hash from store hashes num_stores=%d app_hash=%X\n", len(storeInfos), appHash)
578+
for _, si := range storeInfos {
579+
fmt.Printf("STORE::::Individual store hash store_name=%s hash=%X\n", si.Name, si.GetHash())
580+
}
581+
}
582+
583+
return appHash
568584
}
569585

570586
// CacheWrap implements CacheWrapper/Store/CommitStore.

‎x/staking/cache/cache.go‎

Lines changed: 40 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -395,56 +395,91 @@ func (c *ValidatorsQueueCache) checkReloadUnbondingDelegationsQueue(ctx context.
395395
return nil
396396
}
397397

398-
c.logger(ctx).Info("Unbonding delegations queue is dirty. Reinitializing cache from store.")
398+
c.logger(ctx).Info("[DELEGATION_QUEUE] Unbonding delegations queue is dirty. Reinitializing cache from store.")
399399

400400
data, err := c.unbondingDelegationsQueue.loadFromStore(ctx)
401401
if err != nil {
402+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to load unbonding delegations from store", "error", err)
402403
return err
403404
}
404405

406+
c.logger(ctx).Info("[DELEGATION_QUEUE] Loaded unbonding delegations from store", "entriesCount", len(data))
407+
405408
if err := c.unbondingDelegationsQueue.clearUnsafe(ctx); err != nil {
409+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to clear unbonding delegations cache", "error", err)
406410
return err
407411
}
408412

409413
for key, value := range data {
410414
if err := c.unbondingDelegationsQueue.setEntryUnsafe(ctx, c.cdc, key, value); err != nil {
415+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to set unbonding delegation entry", "key", key, "error", err)
411416
return err
412417
}
413418
}
414419
c.unbondingDelegationsQueue.dirty.Store(false)
420+
c.logger(ctx).Info("[DELEGATION_QUEUE] Completed reloading unbonding delegations cache", "entriesCount", len(data))
415421
return nil
416422
}
417423

418424
func (c *ValidatorsQueueCache) GetUnbondingDelegationsQueue(ctx context.Context) (map[string][]types.DVPair, error) {
419425
if c.unbondingDelegationsQueue.full.Load() {
426+
c.logger(ctx).Error("[DELEGATION_QUEUE] Cache max size reached for unbonding delegations queue")
420427
return nil, types.ErrCacheMaxSizeReached
421428
}
422429

423430
if err := c.checkReloadUnbondingDelegationsQueue(ctx); err != nil {
431+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to reload unbonding delegations queue", "error", err)
432+
return nil, err
433+
}
434+
435+
result, err := c.unbondingDelegationsQueue.get(ctx, c.cdc)
436+
if err != nil {
437+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to get unbonding delegations queue", "error", err)
424438
return nil, err
425439
}
426440

427-
return c.unbondingDelegationsQueue.get(ctx, c.cdc)
441+
c.logger(ctx).Info("[DELEGATION_QUEUE] Retrieved unbonding delegations queue from cache", "entriesCount", len(result))
442+
return result, nil
428443
}
429444

430445
func (c *ValidatorsQueueCache) GetUnbondingDelegationsQueueEntry(ctx context.Context, endTime time.Time) ([]types.DVPair, error) {
431446
if c.unbondingDelegationsQueue.full.Load() {
447+
c.logger(ctx).Error("[DELEGATION_QUEUE] Cache max size reached for unbonding delegations entry")
432448
return nil, types.ErrCacheMaxSizeReached
433449
}
434450

435451
if err := c.checkReloadUnbondingDelegationsQueue(ctx); err != nil {
452+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to reload unbonding delegations for entry", "endTime", endTime, "error", err)
436453
return nil, err
437454
}
438455

439-
return c.unbondingDelegationsQueue.getEntry(ctx, c.cdc, sdk.FormatTimeString(endTime))
456+
key := sdk.FormatTimeString(endTime)
457+
result, err := c.unbondingDelegationsQueue.getEntry(ctx, c.cdc, key)
458+
if err != nil {
459+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to get unbonding delegations entry", "key", key, "error", err)
460+
return nil, err
461+
}
462+
463+
c.logger(ctx).Info("[DELEGATION_QUEUE] Retrieved unbonding delegations entry from cache", "key", key, "pairsCount", len(result))
464+
return result, nil
440465
}
441466

442467
func (c *ValidatorsQueueCache) SetUnbondingDelegationsQueueEntry(ctx context.Context, key string, delegations []types.DVPair) error {
443-
return c.unbondingDelegationsQueue.setEntry(ctx, c.cdc, key, delegations)
468+
c.logger(ctx).Info("[DELEGATION_QUEUE] Setting unbonding delegations entry in cache", "key", key, "pairsCount", len(delegations))
469+
err := c.unbondingDelegationsQueue.setEntry(ctx, c.cdc, key, delegations)
470+
if err != nil {
471+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to set unbonding delegations entry", "key", key, "error", err)
472+
}
473+
return err
444474
}
445475

446476
func (c *ValidatorsQueueCache) DeleteUnbondingDelegationQueueEntry(ctx context.Context, key string) error {
447-
return c.unbondingDelegationsQueue.deleteEntry(ctx, key)
477+
c.logger(ctx).Info("[DELEGATION_QUEUE] Deleting unbonding delegations entry from cache", "key", key)
478+
err := c.unbondingDelegationsQueue.deleteEntry(ctx, key)
479+
if err != nil {
480+
c.logger(ctx).Error("[DELEGATION_QUEUE] Failed to delete unbonding delegations entry", "key", key, "error", err)
481+
}
482+
return err
448483
}
449484

450485
// Redelegations Queue

‎x/staking/keeper/delegation.go‎

Lines changed: 14 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -514,16 +514,20 @@ func (k Keeper) InsertUBDQueue(ctx context.Context, ubd types.UnbondingDelegatio
514514

515515
timeSlice, err := k.GetUBDQueueTimeSlice(ctx, completionTime)
516516
if err != nil {
517+
k.Logger(ctx).Error("[DELEGATION_QUEUE] Failed to get UBD queue timeslice", "completionTime", completionTime, "error", err)
517518
return err
518519
}
519520

520521
if len(timeSlice) == 0 {
522+
k.Logger(ctx).Info("[DELEGATION_QUEUE] Inserting first UBD into queue", "completionTime", completionTime, "delegator", ubd.DelegatorAddress, "validator", ubd.ValidatorAddress)
521523
if err = k.SetUBDQueueTimeSlice(ctx, completionTime, []types.DVPair{dvPair}); err != nil {
524+
k.Logger(ctx).Error("[DELEGATION_QUEUE] Failed to set UBD queue timeslice", "completionTime", completionTime, "error", err)
522525
return err
523526
}
524527
return nil
525528
}
526529

530+
k.Logger(ctx).Info("[DELEGATION_QUEUE] Appending UBD to existing queue", "completionTime", completionTime, "existingCount", len(timeSlice), "delegator", ubd.DelegatorAddress, "validator", ubd.ValidatorAddress)
527531
timeSlice = append(timeSlice, dvPair)
528532
return k.SetUBDQueueTimeSlice(ctx, completionTime, timeSlice)
529533
}
@@ -545,9 +549,12 @@ func (k Keeper) UBDQueueIteratorAll(ctx context.Context) (corestore.Iterator, er
545549
func (k Keeper) DequeueAllMatureUBDQueue(ctx context.Context, currTime time.Time) (matureUnbonds []types.DVPair, err error) {
546550
unbondingDelegations, err := k.GetUBDs(ctx, currTime)
547551
if err != nil {
552+
k.Logger(ctx).Error("[DELEGATION_QUEUE] Failed to get unbonding delegations", "error", err, "currTime", currTime)
548553
return matureUnbonds, err
549554
}
550555

556+
k.Logger(ctx).Info("[DELEGATION_QUEUE] Dequeuing mature unbonding delegations", "currTime", currTime, "totalEntries", len(unbondingDelegations))
557+
551558
keys := make([]string, 0, len(unbondingDelegations))
552559

553560
for key := range unbondingDelegations {
@@ -561,27 +568,32 @@ func (k Keeper) DequeueAllMatureUBDQueue(ctx context.Context, currTime time.Time
561568
for _, key := range keys {
562569
t, err := sdk.ParseTime(key)
563570
if err != nil {
571+
k.Logger(ctx).Error("[DELEGATION_QUEUE] Failed to parse time key", "key", key, "error", err)
564572
return matureUnbonds, err
565573
}
566574

567575
if nonMature := t.After(currTime); nonMature {
576+
k.Logger(ctx).Info("[DELEGATION_QUEUE] Reached non-mature unbonding delegations", "time", t, "currTime", currTime, "processedCount", len(matureUnbonds))
568577
return matureUnbonds, nil
569578
}
570579
pairs := unbondingDelegations[key]
580+
k.Logger(ctx).Info("[DELEGATION_QUEUE] Processing mature unbonding delegation timeslice", "time", t, "pairsCount", len(pairs))
571581
matureUnbonds = append(matureUnbonds, pairs...)
572582

573583
err = store.Delete(types.GetUnbondingDelegationTimeKey(t))
574584
if err != nil {
585+
k.Logger(ctx).Error("[DELEGATION_QUEUE] Failed to delete unbonding delegation time key from store", "time", t, "error", err)
575586
return matureUnbonds, err
576587
}
577588

578589
if k.cache != nil {
579590
if err := k.cache.DeleteUnbondingDelegationQueueEntry(ctx, key); err != nil {
580-
k.Logger(ctx).Error("DeleteUnbondingDelegationQueueEntry in cache failed", "error", err)
591+
k.Logger(ctx).Error("[DELEGATION_QUEUE] DeleteUnbondingDelegationQueueEntry in cache failed", "error", err, "key", key)
581592
}
582593
}
583594
}
584595

596+
k.Logger(ctx).Info("[DELEGATION_QUEUE] Completed dequeuing mature unbonding delegations", "totalMature", len(matureUnbonds))
585597
return matureUnbonds, nil
586598
}
587599

@@ -991,7 +1003,7 @@ func (k Keeper) DequeueAllMatureRedelegationQueue(ctx context.Context, currTime
9911003

9921004
if k.cache != nil {
9931005
if err := k.cache.DeleteRedelegationsQueueEntry(ctx, key); err != nil {
994-
k.Logger(ctx).Error("DeleteRedelegationsQueueEntry in cache failed", "error", err)
1006+
k.Logger(ctx).Error("[DELEGATION_QUEUE] DeleteRedelegationsQueueEntry in cache failed", "error", err, "key", key)
9951007
}
9961008
}
9971009
}

0 commit comments

Comments
 (0)