Merge "Truncate ledger debug trace for large values"

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