Truncate ledger debug trace for large values

Some RWSet values are large, for example default chaincode is about 5MB.
Having 5MB of binary data dumped to debug is not helpful.  This
change will truncate the RWSets in the debug trace after 2000 characters.

Change-Id: I66de491edb396fc0b8bc95628a1e975151ea7904
Signed-off-by: denyeart <enyeart@us.ibm.com>

core/ledger/kvledger/kv_ledger.go

@@ -62,6 +62,9 @@ type KVLedger struct {
 
 // NewKVLedger constructs new `KVLedger`
 func NewKVLedger(conf *Conf) (*KVLedger, error) {
+
+	logger.Debugf("Creating KVLedger using config: ", conf)
+
 	attrsToIndex := []blkstorage.IndexableAttr{
 		blkstorage.IndexableAttrBlockHash,
 		blkstorage.IndexableAttrBlockNum,
@@ -153,9 +156,13 @@ func (l *KVLedger) Commit() error {
 	if l.pendingBlockToCommit == nil {
 		panic(fmt.Errorf(`Nothing to commit. RemoveInvalidTransactionsAndPrepare() method should have been called and should not have thrown error`))
 	}
+
+	logger.Debugf("Committing block to storage")
 	if err := l.blockStore.AddBlock(l.pendingBlockToCommit); err != nil {
 		return err
 	}
+
+	logger.Debugf("Committing block to state database")
 	if err := l.txtmgmt.Commit(); err != nil {
 		panic(fmt.Errorf(`Error during commit to txmgr:%s`, err))
 	}

core/ledger/kvledger/txmgmt/lockbasedtxmgmt/lockbased_tx_simulator.go

@@ -21,6 +21,7 @@ import (
 	"reflect"
 
 	"github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt"
+	logging "github.com/op/go-logging"
 )
 
 type kvReadCache struct {
@@ -61,19 +62,42 @@ func (s *LockBasedTxSimulator) GetState(ns string, key string) ([]byte, error) {
 	// check if it was written
 	kvWrite, ok := nsRWs.writeMap[key]
 	if ok {
-		logger.Debugf("Returing value for key=[%s:%s] from write set", ns, key, kvWrite.Value)
+		// trace the first 500 bytes of value only, in case it is huge
+		if logger.IsEnabledFor(logging.DEBUG) {
+			if len(kvWrite.Value) < 500 {
+				logger.Debugf("Returing value for key=[%s:%s] from write set", ns, key, kvWrite.Value)
+			} else {
+				logger.Debugf("Returing value for key=[%s:%s] from write set", ns, key, kvWrite.Value[0:500])
+			}
+		}
 		return kvWrite.Value, nil
 	}
 	// check if it was read
 	readCache, ok := nsRWs.readMap[key]
 	if ok {
-		logger.Debugf("Returing value for key=[%s:%s] from read set", ns, key, readCache.cachedValue)
+		// trace the first 500 bytes of value only, in case it is huge
+		if logger.IsEnabledFor(logging.DEBUG) {
+			if len(readCache.cachedValue) < 500 {
+				logger.Debugf("Returing value for key=[%s:%s] from read set", ns, key, readCache.cachedValue)
+			} else {
+				logger.Debugf("Returing value for key=[%s:%s] from read set", ns, key, readCache.cachedValue[0:500])
+			}
+		}
 		return readCache.cachedValue, nil
 	}
 
 	// read from storage
 	value, version, err := s.txmgr.getCommittedValueAndVersion(ns, key)
-	logger.Debugf("Read state from storage key=[%s:%s], value=[%#v], version=[%d]", ns, key, value, version)
+
+	// trace the first 500 bytes of value only, in case it is huge
+	if logger.IsEnabledFor(logging.DEBUG) {
+		if len(value) < 500 {
+			logger.Debugf("Read state from storage key=[%s:%s], value=[%#v], version=[%d]", ns, key, value, version)
+		} else {
+			logger.Debugf("Read state from storage key=[%s:%s], value=[%#v...], version=[%d]", ns, key, value[0:500], version)
+		}
+	}
+
 	if err != nil {
 		return nil, err
 	}
@@ -129,7 +153,17 @@ func (s *LockBasedTxSimulator) getTxReadWriteSet() *txmgmt.TxReadWriteSet {
 		nsRWs := &txmgmt.NsReadWriteSet{NameSpace: ns, Reads: reads, Writes: writes}
 		txRWSet.NsRWs = append(txRWSet.NsRWs, nsRWs)
 	}
-	logger.Debugf("txRWSet = [%s]", txRWSet)
+
+	// trace the first 2000 characters of RWSet only, in case it is huge
+	if logger.IsEnabledFor(logging.DEBUG) {
+		txRWSetString := txRWSet.String()
+		if len(txRWSetString) < 2000 {
+			logger.Debugf("txRWSet = [%s]", txRWSetString)
+		} else {
+			logger.Debugf("txRWSet = [%s...]", txRWSetString[0:2000])
+		}
+	}
+
 	return txRWSet
 }
 
@@ -145,6 +179,7 @@ func getSortedKeys(m interface{}) []string {
 
 // GetTxSimulationResults implements method in interface `ledger.TxSimulator`
 func (s *LockBasedTxSimulator) GetTxSimulationResults() ([]byte, error) {
+	logger.Debugf("Simulation completed, getting simulation results")
 	return s.getTxReadWriteSet().Marshal()
 }
 

core/ledger/kvledger/txmgmt/lockbasedtxmgmt/lockbased_txmgr.go

@@ -131,7 +131,16 @@ func (txmgr *LockBasedTxMgr) ValidateAndPrepare(block *protos.Block2) (*protos.B
 			return nil, nil, err
 		}
 
-		logger.Debugf("validating txRWSet:[%s]", txRWSet)
+		// trace the first 2000 characters of RWSet only, in case it is huge
+		if logger.IsEnabledFor(logging.DEBUG) {
+			txRWSetString := txRWSet.String()
+			if len(txRWSetString) < 2000 {
+				logger.Debugf("validating txRWSet:[%s]", txRWSetString)
+			} else {
+				logger.Debugf("validating txRWSet:[%s...]", txRWSetString[0:2000])
+			}
+		}
+
 		if valid, err = txmgr.validateTx(txRWSet); err != nil {
 			return nil, nil, err
 		}
@@ -155,7 +164,17 @@ func (txmgr *LockBasedTxMgr) Shutdown() {
 }
 
 func (txmgr *LockBasedTxMgr) validateTx(txRWSet *txmgmt.TxReadWriteSet) (bool, error) {
-	logger.Debugf("Validating txRWSet:%s", txRWSet)
+
+	// trace the first 2000 characters of RWSet only, in case it is huge
+	if logger.IsEnabledFor(logging.DEBUG) {
+		txRWSetString := txRWSet.String()
+		if len(txRWSetString) < 2000 {
+			logger.Debugf("Validating txRWSet:%s", txRWSetString)
+		} else {
+			logger.Debugf("Validating txRWSet:%s...", txRWSetString[0:2000])
+		}
+	}
+
 	var err error
 	var currentVersion uint64