[FAB-12103] Improve ledger debug

Improve ledger debug based on serviceability findings.

- Remove unnecessary debug.
- Add info logging for state and history rebuild.
- Add couchdb database name to couchdb debug.

Change-Id: Ia39b63d55529ed9ee40325b3a03a8bf78cb667ed
Signed-off-by: David Enyeart <enyeart@us.ibm.com>

Author: denyeart

core/ledger/kvledger/history/historydb/historyleveldb/historyleveldb.go

@@ -196,6 +196,14 @@ func (historyDB *historyDB) ShouldRecover(lastAvailableBlock uint64) (bool, uint
 // CommitLostBlock implements method in interface kvledger.Recoverer
 func (historyDB *historyDB) CommitLostBlock(blockAndPvtdata *ledger.BlockAndPvtData) error {
 	block := blockAndPvtdata.Block
+
+	// log every 1000th block at Info level so that history rebuild progress can be tracked in production envs.
+	if block.Header.Number%1000 == 0 {
+		logger.Infof("Recommitting block [%d] to history database", block.Header.Number)
+	} else {
+		logger.Debugf("Recommitting block [%d] to history database", block.Header.Number)
+	}
+
 	if err := historyDB.Commit(block); err != nil {
 		return err
 	}

core/ledger/kvledger/kv_ledger.go

@@ -140,7 +140,7 @@ func (l *kvLedger) recoverDBs() error {
 //recommitLostBlocks retrieves blocks in specified range and commit the write set to either
 //state DB or history DB or both
 func (l *kvLedger) recommitLostBlocks(firstBlockNum uint64, lastBlockNum uint64, recoverables ...recoverable) error {
-	logger.Debugf("recommitLostBlocks() - firstBlockNum=%d, lastBlockNum=%d, recoverables=%#v", firstBlockNum, lastBlockNum, recoverables)
+	logger.Infof("Recommitting lost blocks - firstBlockNum=%d, lastBlockNum=%d, recoverables=%#v", firstBlockNum, lastBlockNum, recoverables)
 	var err error
 	var blockAndPvtdata *ledger.BlockAndPvtData
 	for blockNumber := firstBlockNum; blockNumber <= lastBlockNum; blockNumber++ {
@@ -153,6 +153,7 @@ func (l *kvLedger) recommitLostBlocks(firstBlockNum uint64, lastBlockNum uint64,
 			}
 		}
 	}
+	logger.Infof("Recommitted lost blocks - firstBlockNum=%d, lastBlockNum=%d, recoverables=%#v", firstBlockNum, lastBlockNum, recoverables)
 	return nil
 }
 

core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr/collection_val.go

@@ -28,7 +28,6 @@ func newCollNameValidator(queryHelper *queryHelper) *collNameValidator {
 }
 
 func (v *collNameValidator) validateCollName(ns, coll string) error {
-	logger.Debugf("validateCollName() begin - ns=[%s], coll=[%s]", ns, coll)
 	if !v.cache.isPopulatedFor(ns) {
 		conf, err := v.retrieveCollConfigFromStateDB(ns)
 		if err != nil {
@@ -42,7 +41,6 @@ func (v *collNameValidator) validateCollName(ns, coll string) error {
 			Coll: coll,
 		}
 	}
-	logger.Debugf("validateCollName() validated successfully - ns=[%s], coll=[%s]", ns, coll)
 	return nil
 }
 

core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr/lockbased_txmgr.go

@@ -224,7 +224,14 @@ func (txmgr *LockBasedTxMgr) CommitLostBlock(blockAndPvtdata *ledger.BlockAndPvt
 	if err := txmgr.ValidateAndPrepare(blockAndPvtdata, false); err != nil {
 		return err
 	}
-	logger.Debugf("Committing block %d to state database", block.Header.Number)
+
+	// log every 1000th block at Info level so that statedb rebuild progress can be tracked in production envs.
+	if block.Header.Number%1000 == 0 {
+		logger.Infof("Recommitting block [%d] to state database", block.Header.Number)
+	} else {
+		logger.Debugf("Recommitting block [%d] to state database", block.Header.Number)
+	}
+
 	return txmgr.Commit()
 }