diff --git a/core/ledger/pvtdatastorage/store_impl.go b/core/ledger/pvtdatastorage/store_impl.go index e8808c4af71..a7a270cf027 100644 --- a/core/ledger/pvtdatastorage/store_impl.go +++ b/core/ledger/pvtdatastorage/store_impl.go @@ -84,7 +84,7 @@ 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) @@ -92,7 +92,7 @@ func (s *store) Prepare(blockNum uint64, pvtData []*ledger.TxPvtData) error { 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,7 +138,7 @@ 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 } @@ -146,7 +146,7 @@ func (s *store) Rollback() error { // 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 } diff --git a/core/transientstore/store.go b/core/transientstore/store.go index c9544a07397..2e1eaaa5a17 100644 --- a/core/transientstore/store.go +++ b/core/transientstore/store.go @@ -12,6 +12,7 @@ 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" @@ -19,6 +20,8 @@ import ( "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) diff --git a/gossip/privdata/coordinator.go b/gossip/privdata/coordinator.go index fed00baeff2..604b1efa2f3 100644 --- a/gossip/privdata/coordinator.go +++ b/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,