[FAB-7548] Improve debug for pvt data p2

Improve debug messages for private data.
Grepping debug log for "private" will now return
very useful information.

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

Author: denyeart

core/ledger/pvtdatastorage/store_impl.go

@@ -84,15 +84,15 @@ func (s *store) Prepare(blockNum uint64, pvtData []*ledger.TxPvtData) error {
 		if value, err = encodePvtRwSet(txPvtData.WriteSet); err != nil {
 			return err
 		}
-		logger.Debugf("Adding private data to batch blockNum=%d, tranNum=%d", blockNum, txPvtData.SeqInBlock)
+		logger.Debugf("Adding private data to LevelDB batch for block [%d], tran [%d]", blockNum, txPvtData.SeqInBlock)
 		batch.Put(key, value)
 	}
 	batch.Put(pendingCommitKey, emptyValue)
 	if err := s.db.WriteBatch(batch, true); err != nil {
 		return err
 	}
 	s.batchPending = true
-	logger.Debugf("Saved private data for block [%d]", blockNum)
+	logger.Debugf("Saved %d private data write sets for block [%d]", len(pvtData), blockNum)
 	return nil
 }
 
@@ -102,7 +102,7 @@ func (s *store) Commit() error {
 		return &ErrIllegalCall{"No pending batch to commit"}
 	}
 	committingBlockNum := s.nextBlockNum()
-	logger.Debugf("Committing pvt data for block = %d", committingBlockNum)
+	logger.Debugf("Committing private data for block [%d]", committingBlockNum)
 	batch := leveldbhelper.NewUpdateBatch()
 	batch.Delete(pendingCommitKey)
 	batch.Put(lastCommittedBlkkey, encodeBlockNum(committingBlockNum))
@@ -112,7 +112,7 @@ func (s *store) Commit() error {
 	s.batchPending = false
 	s.isEmpty = false
 	s.lastCommittedBlock = committingBlockNum
-	logger.Debugf("Committed pvt data for block = %d", committingBlockNum)
+	logger.Debugf("Committed private data for block [%d]", committingBlockNum)
 	return nil
 }
 
@@ -124,7 +124,7 @@ func (s *store) Rollback() error {
 		return &ErrIllegalCall{"No pending batch to rollback"}
 	}
 	rollingbackBlockNum := s.nextBlockNum()
-	logger.Debugf("Rolling back pvt data for block = %d", rollingbackBlockNum)
+	logger.Debugf("Rolling back private data for block [%d]", rollingbackBlockNum)
 
 	if pendingBatchKeys, err = s.retrievePendingBatchKeys(); err != nil {
 		return err
@@ -138,15 +138,15 @@ func (s *store) Rollback() error {
 		return err
 	}
 	s.batchPending = false
-	logger.Debugf("Rolled back pvt data for block = %d", rollingbackBlockNum)
+	logger.Debugf("Rolled back private data for block [%d]", rollingbackBlockNum)
 	return nil
 }
 
 // GetPvtDataByBlockNum implements the function in the interface `Store`.
 // If the store is empty or the last committed block number is smaller then the
 // requested block number, an 'ErrOutOfRange' is thrown
 func (s *store) GetPvtDataByBlockNum(blockNum uint64, filter ledger.PvtNsCollFilter) ([]*ledger.TxPvtData, error) {
-	logger.Debugf("GetPvtDataByBlockNum(): blockNum=%d, filter=%#v", blockNum, filter)
+	logger.Debugf("Get private data for block [%d], filter=%#v", blockNum, filter)
 	if s.isEmpty {
 		return nil, &ErrOutOfRange{"The store is empty"}
 	}
@@ -156,7 +156,7 @@ func (s *store) GetPvtDataByBlockNum(blockNum uint64, filter ledger.PvtNsCollFil
 	}
 	var pvtData []*ledger.TxPvtData
 	startKey, endKey := getKeysForRangeScanByBlockNum(blockNum)
-	logger.Debugf("GetPvtDataByBlockNum(): startKey=%#v, endKey=%#v", startKey, endKey)
+	logger.Debugf("Querying private data storage for write sets using startKey=%#v, endKey=%#v", startKey, endKey)
 	itr := s.db.GetIterator(startKey, endKey)
 	defer itr.Release()
 
@@ -167,7 +167,7 @@ func (s *store) GetPvtDataByBlockNum(blockNum uint64, filter ledger.PvtNsCollFil
 		if pvtWSet, err = decodePvtRwSet(itr.Value()); err != nil {
 			return nil, err
 		}
-		logger.Debugf("Retrieving pvtdata for bNum=%d, tNum=%d", bNum, tNum)
+		logger.Debugf("Retrieved private data write set for block [%d] tran [%d]", bNum, tNum)
 		filteredWSet := TrimPvtWSet(pvtWSet, filter)
 		pvtData = append(pvtData, &ledger.TxPvtData{SeqInBlock: tNum, WriteSet: filteredWSet})
 	}
@@ -177,7 +177,7 @@ func (s *store) GetPvtDataByBlockNum(blockNum uint64, filter ledger.PvtNsCollFil
 // InitLastCommittedBlock implements the function in the interface `Store`
 func (s *store) InitLastCommittedBlock(blockNum uint64) error {
 	if !(s.isEmpty && !s.batchPending) {
-		return &ErrIllegalCall{"The pvtdata store is not empty. InitLastCommittedBlock() function call is not allowed"}
+		return &ErrIllegalCall{"The private data store is not empty. InitLastCommittedBlock() function call is not allowed"}
 	}
 	batch := leveldbhelper.NewUpdateBatch()
 	batch.Put(lastCommittedBlkkey, encodeBlockNum(blockNum))
@@ -186,7 +186,7 @@ func (s *store) InitLastCommittedBlock(blockNum uint64) error {
 	}
 	s.isEmpty = false
 	s.lastCommittedBlock = blockNum
-	logger.Debugf("InitLastCommittedBlock set to = %d", blockNum)
+	logger.Debugf("InitLastCommittedBlock set to block [%d]", blockNum)
 	return nil
 }
 

core/transientstore/store.go

@@ -12,13 +12,16 @@ import (
 	"github.com/golang/protobuf/proto"
 	"github.com/hyperledger/fabric/protos/ledger/rwset"
 
+	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/common/ledger/util/leveldbhelper"
 	"github.com/hyperledger/fabric/common/util"
 	"github.com/hyperledger/fabric/core/ledger"
 	"github.com/hyperledger/fabric/core/ledger/pvtdatastorage"
 	"github.com/syndtr/goleveldb/leveldb/iterator"
 )
 
+var logger = flogging.MustGetLogger("transientstore")
+
 var emptyValue = []byte{}
 
 // ErrStoreEmpty is used to indicate that there are no entries in transient store
@@ -119,6 +122,9 @@ func (provider *storeProvider) Close() {
 // based on txid and the block height the private data was received at
 func (s *store) Persist(txid string, blockHeight uint64,
 	privateSimulationResults *rwset.TxPvtReadWriteSet) error {
+
+	logger.Debugf("Persisting private data to transient store for txid = %s", txid)
+
 	dbBatch := leveldbhelper.NewUpdateBatch()
 
 	// Create compositeKey with appropriate prefix, txid, uuid and blockHeight
@@ -161,6 +167,9 @@ func (s *store) Persist(txid string, blockHeight uint64,
 // GetTxPvtRWSetByTxid returns an iterator due to the fact that the txid may have multiple private
 // write sets persisted from different endorsers.
 func (s *store) GetTxPvtRWSetByTxid(txid string, filter ledger.PvtNsCollFilter) (RWSetScanner, error) {
+
+	logger.Debugf("Getting private data from transient store for transaction %s", txid)
+
 	// Construct startKey and endKey to do an range query
 	startKey := createTxidRangeStartKey(txid)
 	endKey := createTxidRangeEndKey(txid)
@@ -173,6 +182,9 @@ func (s *store) GetTxPvtRWSetByTxid(txid string, filter ledger.PvtNsCollFilter)
 // transient store. PurgeByTxids() is expected to be called by coordinator after
 // committing a block to ledger.
 func (s *store) PurgeByTxids(txids []string) error {
+
+	logger.Debug("Purging private data from transient store for committed txids")
+
 	dbBatch := leveldbhelper.NewUpdateBatch()
 
 	for _, txid := range txids {
@@ -216,6 +228,9 @@ func (s *store) PurgeByTxids(txids []string) error {
 // after successful block commit, PurgeByHeight() is still required to remove orphan entries (as
 // transaction that gets endorsed may not be submitted by the client for commit)
 func (s *store) PurgeByHeight(maxBlockNumToRetain uint64) error {
+
+	logger.Debugf("Purging orphaned private data from transient store received prior to block [%d]", maxBlockNumToRetain)
+
 	// Do a range query with 0 as startKey and maxBlockNumToRetain-1 as endKey
 	startKey := createPurgeIndexByHeightRangeStartKey(0)
 	endKey := createPurgeIndexByHeightRangeEndKey(maxBlockNumToRetain - 1)

gossip/privdata/coordinator.go

@@ -150,7 +150,7 @@ func (c *coordinator) StoreBlock(block *common.Block, privateDataSets util.PvtDa
 	}
 	logger.Infof("Received block [%d]", block.Header.Number)
 
-	logger.Debug("Validating block", block.Header.Number)
+	logger.Debugf("Validating block [%d]", block.Header.Number)
 	err := c.Validator.Validate(block)
 	if err != nil {
 		return errors.WithMessage(err, "Validation failed")
@@ -179,6 +179,7 @@ func (c *coordinator) StoreBlock(block *common.Block, privateDataSets util.PvtDa
 		logger.Debug("No missing collection private write sets to fetch from remote peers")
 	} else {
 		bFetchFromPeers = true
+		logger.Debug("Could not find all collection private write sets in local peer transient store.")
 		logger.Debug("Fetching", len(privateInfo.missingKeys), "collection private write sets from remote peers for a maximum duration of", retryThresh)
 	}
 	start := time.Now()
@@ -200,7 +201,7 @@ func (c *coordinator) StoreBlock(block *common.Block, privateDataSets util.PvtDa
 	// populate the private RWSets passed to the ledger
 	for seqInBlock, nsRWS := range ownedRWsets.bySeqsInBlock() {
 		rwsets := nsRWS.toRWSet()
-		logger.Debug("Added", len(rwsets.NsPvtRwset), "namespace private write sets to transaction", seqInBlock, "for block", block.Header.Number)
+		logger.Debugf("Added %d namespace private write sets for block [%d], tran [%d]", len(rwsets.NsPvtRwset), block.Header.Number, seqInBlock)
 		blockAndPvtData.BlockPvtData[seqInBlock] = &ledger.TxPvtData{
 			SeqInBlock: seqInBlock,
 			WriteSet:   rwsets,