Clean up peer logging - serviceability

Clean up peer logging for improved serviceability.

INFO level log had a lot of debug information, making it impossible
to find important INFO information and errors through the noise.
Changed most of the debug information to use DEBUG level.

After this change, during normal transaction processing there
will be a single entry in info log per block with messages
like this:

Channel [myc1]: Created block [1] with 43 transaction(s)
Channel [myc1]: Created block [2] with 14 transaction(s)
Channel [myc1]: Created block [3] with 26 transaction(s)

This will make it easy to spot any anomilies in the logs, while
still tracking block progress.

Confirmed there are good INFO messages for important events
such as peer initialization and channel creation.

Removed data content from debug messages for enhanced privacy.

Change-Id: I3a0b2f3a07d5c7dcf388a609d11cfa3bcf7bb065
Signed-off-by: denyeart <[email protected]>

Author: denyeart

core/committer/txvalidator/validator.go

@@ -233,7 +233,7 @@ func (v *vsccValidatorImpl) VSCCValidateTx(payload *common.Payload, envBytes []b
 	// VSCCValidateTx should
 	if hdrExt.ChaincodeId.Name == "lccc" {
 		// TODO: until FAB-1934 is in, we need to stop here
-		logger.Infof("Invocation of LCCC detected, no further VSCC validation necessary")
+		logger.Debugf("Invocation of LCCC detected, no further VSCC validation necessary")
 		return nil
 	}
 
@@ -257,7 +257,7 @@ func (v *vsccValidatorImpl) VSCCValidateTx(payload *common.Payload, envBytes []b
 	cccid := v.ccprovider.GetCCContext(chainID, vscc, version, vscctxid, true, nil, nil)
 
 	// invoke VSCC
-	logger.Info("Invoking VSCC txid", txid, "chaindID", chainID)
+	logger.Debug("Invoking VSCC txid", txid, "chaindID", chainID)
 	res, _, err := v.ccprovider.ExecuteChaincode(ctxt, cccid, args)
 	if err != nil {
 		logger.Errorf("Invoke VSCC failed for transaction txid=%s, error %s", txid, err)

core/common/ccprovider/ccprovider.go

@@ -206,7 +206,7 @@ func NewCCContext(cid, name, version, txid string, syscc bool, signedProp *pb.Si
 
 	cccid := &CCContext{cid, name, version, txid, syscc, signedProp, prop, canName}
 
-	ccproviderLogger.Infof("NewCCCC (chain=%s,chaincode=%s,version=%s,txid=%s,syscc=%t,proposal=%p,canname=%s", cid, name, version, txid, syscc, prop, cccid.canonicalName)
+	ccproviderLogger.Debugf("NewCCCC (chain=%s,chaincode=%s,version=%s,txid=%s,syscc=%t,proposal=%p,canname=%s", cid, name, version, txid, syscc, prop, cccid.canonicalName)
 
 	return cccid
 }

core/common/validation/msgvalidation.go

@@ -32,15 +32,15 @@ var putilsLogger = logging.MustGetLogger("protoutils")
 
 // validateChaincodeProposalMessage checks the validity of a Proposal message of type CHAINCODE
 func validateChaincodeProposalMessage(prop *pb.Proposal, hdr *common.Header) (*pb.ChaincodeHeaderExtension, error) {
-	putilsLogger.Infof("validateChaincodeProposalMessage starts for proposal %p, header %p", prop, hdr)
+	putilsLogger.Debugf("validateChaincodeProposalMessage starts for proposal %p, header %p", prop, hdr)
 
 	// 4) based on the header type (assuming it's CHAINCODE), look at the extensions
 	chaincodeHdrExt, err := utils.GetChaincodeHeaderExtension(hdr)
 	if err != nil {
 		return nil, errors.New("Invalid header extension for type CHAINCODE")
 	}
 
-	putilsLogger.Infof("validateChaincodeProposalMessage info: header extension references chaincode %s", chaincodeHdrExt.ChaincodeId)
+	putilsLogger.Debugf("validateChaincodeProposalMessage info: header extension references chaincode %s", chaincodeHdrExt.ChaincodeId)
 
 	//    - ensure that the chaincodeID is correct (?)
 	// TODO: should we even do this? If so, using which interface?
@@ -64,7 +64,7 @@ func validateChaincodeProposalMessage(prop *pb.Proposal, hdr *common.Header) (*p
 // this function returns Header and ChaincodeHeaderExtension messages since they
 // have been unmarshalled and validated
 func ValidateProposalMessage(signedProp *pb.SignedProposal) (*pb.Proposal, *common.Header, *pb.ChaincodeHeaderExtension, error) {
-	putilsLogger.Infof("ValidateProposalMessage starts for signed proposal %p", signedProp)
+	putilsLogger.Debugf("ValidateProposalMessage starts for signed proposal %p", signedProp)
 
 	// extract the Proposal message from signedProp
 	prop, err := utils.GetProposal(signedProp.ProposalBytes)
@@ -127,7 +127,7 @@ func ValidateProposalMessage(signedProp *pb.SignedProposal) (*pb.Proposal, *comm
 // this function returns nil if the creator
 // is a valid cert and the signature is valid
 func checkSignatureFromCreator(creatorBytes []byte, sig []byte, msg []byte, ChainID string) error {
-	putilsLogger.Infof("checkSignatureFromCreator starts")
+	putilsLogger.Debugf("checkSignatureFromCreator starts")
 
 	// check for nil argument
 	if creatorBytes == nil || sig == nil || msg == nil {
@@ -145,23 +145,23 @@ func checkSignatureFromCreator(creatorBytes []byte, sig []byte, msg []byte, Chai
 		return fmt.Errorf("Failed to deserialize creator identity, err %s", err)
 	}
 
-	putilsLogger.Infof("checkSignatureFromCreator info: creator is %s", creator.GetIdentifier())
+	putilsLogger.Debugf("checkSignatureFromCreator info: creator is %s", creator.GetIdentifier())
 
 	// ensure that creator is a valid certificate
 	err = creator.Validate()
 	if err != nil {
 		return fmt.Errorf("The creator certificate is not valid, err %s", err)
 	}
 
-	putilsLogger.Infof("checkSignatureFromCreator info: creator is valid")
+	putilsLogger.Debugf("checkSignatureFromCreator info: creator is valid")
 
 	// validate the signature
 	err = creator.Verify(msg, sig)
 	if err != nil {
 		return fmt.Errorf("The creator's signature over the proposal is not valid, err %s", err)
 	}
 
-	putilsLogger.Infof("checkSignatureFromCreator exists successfully")
+	putilsLogger.Debugf("checkSignatureFromCreator exists successfully")
 
 	return nil
 }
@@ -200,7 +200,7 @@ func validateChannelHeader(cHdr *common.ChannelHeader) error {
 		return fmt.Errorf("invalid header type %s", common.HeaderType(cHdr.Type))
 	}
 
-	putilsLogger.Infof("validateChannelHeader info: header type %d", common.HeaderType(cHdr.Type))
+	putilsLogger.Debugf("validateChannelHeader info: header type %d", common.HeaderType(cHdr.Type))
 
 	// TODO: validate chainID in cHdr.ChainID
 
@@ -249,7 +249,7 @@ func validateCommonHeader(hdr *common.Header) (*common.ChannelHeader, *common.Si
 // validateConfigTransaction validates the payload of a
 // transaction assuming its type is CONFIG
 func validateConfigTransaction(data []byte, hdr *common.Header) error {
-	putilsLogger.Infof("validateConfigTransaction starts for data %p, header %s", data, hdr)
+	putilsLogger.Debugf("validateConfigTransaction starts for data %p, header %s", data, hdr)
 
 	// check for nil argument
 	if data == nil || hdr == nil {
@@ -264,7 +264,7 @@ func validateConfigTransaction(data []byte, hdr *common.Header) error {
 // validateEndorserTransaction validates the payload of a
 // transaction assuming its type is ENDORSER_TRANSACTION
 func validateEndorserTransaction(data []byte, hdr *common.Header) error {
-	putilsLogger.Infof("validateEndorserTransaction starts for data %p, header %s", data, hdr)
+	putilsLogger.Debugf("validateEndorserTransaction starts for data %p, header %s", data, hdr)
 
 	// check for nil argument
 	if data == nil || hdr == nil {
@@ -290,7 +290,7 @@ func validateEndorserTransaction(data []byte, hdr *common.Header) error {
 		return errors.New("At least one TransactionAction is required")
 	}
 
-	putilsLogger.Infof("validateEndorserTransaction info: there are %d actions", len(tx.Actions))
+	putilsLogger.Debugf("validateEndorserTransaction info: there are %d actions", len(tx.Actions))
 
 	for _, act := range tx.Actions {
 		// check for nil argument
@@ -311,7 +311,7 @@ func validateEndorserTransaction(data []byte, hdr *common.Header) error {
 			return err
 		}
 
-		putilsLogger.Infof("validateEndorserTransaction info: signature header is valid")
+		putilsLogger.Debugf("validateEndorserTransaction info: signature header is valid")
 
 		// if the type is ENDORSER_TRANSACTION we unmarshal a ChaincodeActionPayload
 		ccActionPayload, err := utils.GetChaincodeActionPayload(act.Payload)
@@ -346,7 +346,7 @@ func validateEndorserTransaction(data []byte, hdr *common.Header) error {
 
 // ValidateTransaction checks that the transaction envelope is properly formed
 func ValidateTransaction(e *common.Envelope) (*common.Payload, pb.TxValidationCode) {
-	putilsLogger.Infof("ValidateTransactionEnvelope starts for envelope %p", e)
+	putilsLogger.Debugf("ValidateTransactionEnvelope starts for envelope %p", e)
 
 	// check for nil argument
 	if e == nil {
@@ -361,7 +361,7 @@ func ValidateTransaction(e *common.Envelope) (*common.Payload, pb.TxValidationCo
 		return nil, pb.TxValidationCode_BAD_PAYLOAD
 	}
 
-	putilsLogger.Infof("Header is %s", payload.Header)
+	putilsLogger.Debugf("Header is %s", payload.Header)
 
 	// validate the header
 	chdr, shdr, err := validateCommonHeader(payload.Header)
@@ -396,7 +396,7 @@ func ValidateTransaction(e *common.Envelope) (*common.Payload, pb.TxValidationCo
 		}
 
 		err = validateEndorserTransaction(payload.Data, payload.Header)
-		putilsLogger.Infof("ValidateTransactionEnvelope returns err %s", err)
+		putilsLogger.Debugf("ValidateTransactionEnvelope returns err %s", err)
 
 		if err != nil {
 			putilsLogger.Errorf("validateEndorserTransaction returns err %s", err)

core/endorser/endorser.go

@@ -227,7 +227,7 @@ func (e *Endorser) getCDSFromLCCC(ctx context.Context, chainID string, txid stri
 
 //endorse the proposal by calling the ESCC
 func (e *Endorser) endorseProposal(ctx context.Context, chainID string, txid string, signedProp *pb.SignedProposal, proposal *pb.Proposal, response *pb.Response, simRes []byte, event *pb.ChaincodeEvent, visibility []byte, ccid *pb.ChaincodeID, txsim ledger.TxSimulator, cd *ccprovider.ChaincodeData) (*pb.ProposalResponse, error) {
-	endorserLogger.Infof("endorseProposal starts for chainID %s, ccid %s", chainID, ccid)
+	endorserLogger.Debugf("endorseProposal starts for chainID %s, ccid %s", chainID, ccid)
 
 	// 1) extract the name of the escc that is requested to endorse this chaincode
 	var escc string
@@ -243,7 +243,7 @@ func (e *Endorser) endorseProposal(ctx context.Context, chainID string, txid str
 		escc = "escc"
 	}
 
-	endorserLogger.Infof("endorseProposal info: escc for cid %s is %s", ccid, escc)
+	endorserLogger.Debugf("endorseProposal info: escc for cid %s is %s", ccid, escc)
 
 	// marshalling event bytes
 	var err error

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

@@ -89,8 +89,8 @@ func (historyDB *historyDB) Commit(block *common.Block) error {
 
 	dbBatch := leveldbhelper.NewUpdateBatch()
 
-	logger.Debugf("Updating history database for blockNo [%v] with [%d] transactions",
-		blockNo, len(block.Data.Data))
+	logger.Debugf("Channel [%s]: Updating history database for blockNo [%v] with [%d] transactions",
+		historyDB.dbName, blockNo, len(block.Data.Data))
 
 	//TODO add check for invalid trans in bit array
 	for _, envBytes := range block.Data.Data {
@@ -157,7 +157,7 @@ func (historyDB *historyDB) Commit(block *common.Block) error {
 		return err
 	}
 
-	logger.Debugf("Updates committed to history database for blockNo [%v]", blockNo)
+	logger.Debugf("Channel [%s]: Updates committed to history database for blockNo [%v]", historyDB.dbName, blockNo)
 	return nil
 }
 

core/ledger/kvledger/kv_ledger.go

@@ -212,25 +212,26 @@ func (l *kvLedger) Commit(block *common.Block) error {
 	var err error
 	blockNo := block.Header.Number
 
-	logger.Debugf("Validating block [%d]", blockNo)
+	logger.Debugf("Channel [%s]: Validating block [%d]", l.ledgerID, blockNo)
 	err = l.txtmgmt.ValidateAndPrepare(block, true)
 	if err != nil {
 		return err
 	}
 
-	logger.Debugf("Committing block [%d] to storage", blockNo)
+	logger.Debugf("Channel [%s]: Committing block [%d] to storage", l.ledgerID, blockNo)
 	if err = l.blockStore.AddBlock(block); err != nil {
 		return err
 	}
+	logger.Infof("Channel [%s]: Created block [%d] with %d transaction(s)", l.ledgerID, block.Header.Number, len(block.Data.Data))
 
-	logger.Debugf("Committing block [%d] transactions to state database", blockNo)
+	logger.Debugf("Channel [%s]: Committing block [%d] transactions to state database", l.ledgerID, blockNo)
 	if err = l.txtmgmt.Commit(); err != nil {
 		panic(fmt.Errorf(`Error during commit to txmgr:%s`, err))
 	}
 
 	// History database could be written in parallel with state and/or async as a future optimization
 	if ledgerconfig.IsHistoryDBEnabled() {
-		logger.Debugf("Committing block [%d] transactions to history database", blockNo)
+		logger.Debugf("Channel [%s]: Committing block [%d] transactions to history database", l.ledgerID, blockNo)
 		if err := l.historyDB.Commit(block); err != nil {
 			panic(fmt.Errorf(`Error during commit to history db:%s`, err))
 		}

core/ledger/kvledger/txmgmt/statedb/statecouchdb/statecouchdb.go

@@ -122,15 +122,6 @@ func (vdb *VersionedDB) GetState(namespace string, key string) (*statedb.Version
 		return nil, nil
 	}
 
-	// trace the first 200 bytes of value only, in case it is huge
-	if couchDoc.JSONValue != nil && logger.IsEnabledFor(logging.DEBUG) {
-		if len(couchDoc.JSONValue) < 200 {
-			logger.Debugf("getCommittedValueAndVersion() Read docBytes %s", couchDoc.JSONValue)
-		} else {
-			logger.Debugf("getCommittedValueAndVersion() Read docBytes %s...", couchDoc.JSONValue[0:200])
-		}
-	}
-
 	//remove the data wrapper and return the value and version
 	returnValue, returnVersion := removeDataWrapper(couchDoc.JSONValue, couchDoc.Attachments)
 
@@ -248,15 +239,7 @@ func (vdb *VersionedDB) ApplyUpdates(batch *statedb.UpdateBatch, height *version
 		updates := batch.GetUpdates(ns)
 		for k, vv := range updates {
 			compositeKey := constructCompositeKey(ns, k)
-
-			// trace the first 200 characters of versioned value only, in case it is huge
-			if logger.IsEnabledFor(logging.DEBUG) {
-				versionedValueDump := fmt.Sprintf("%#v", vv)
-				if len(versionedValueDump) > 200 {
-					versionedValueDump = versionedValueDump[0:200] + "..."
-				}
-				logger.Debugf("Applying key=%#v, versionedValue=%s", compositeKey, versionedValueDump)
-			}
+			logger.Debugf("Channel [%s]: Applying key=[%#v]", vdb.dbName, compositeKey)
 
 			//convert nils to deletes
 			if vv.Value == nil {

core/ledger/kvledger/txmgmt/statedb/stateleveldb/stateleveldb.go

@@ -19,7 +19,6 @@ package stateleveldb
 import (
 	"bytes"
 	"errors"
-	"fmt"
 
 	"github.com/hyperledger/fabric/common/ledger/util/leveldbhelper"
 	"github.com/hyperledger/fabric/core/ledger/kvledger/txmgmt/statedb"
@@ -134,14 +133,8 @@ func (vdb *versionedDB) ApplyUpdates(batch *statedb.UpdateBatch, height *version
 		updates := batch.GetUpdates(ns)
 		for k, vv := range updates {
 			compositeKey := constructCompositeKey(ns, k)
-			// trace the first 200 characters of versioned value only, in case it is huge
-			if logger.IsEnabledFor(logging.DEBUG) {
-				versionedValueDump := fmt.Sprintf("%#v", vv)
-				if len(versionedValueDump) > 200 {
-					versionedValueDump = versionedValueDump[0:200] + "..."
-				}
-				logger.Debugf("Applying key=%#v, versionedValue=%s", compositeKey, versionedValueDump)
-			}
+			logger.Debugf("Channel [%s]: Applying key=[%#v]", vdb.dbName, compositeKey)
+
 			if vv.Value == nil {
 				dbBatch.Delete(compositeKey)
 			} else {

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

@@ -59,6 +59,6 @@ func (q *lockBasedQueryExecutor) ExecuteQuery(namespace, query string) (ledger.R
 
 // Done implements method in interface `ledger.QueryExecutor`
 func (q *lockBasedQueryExecutor) Done() {
-	logger.Debugf("Done query executer/ tx simulator [%s]", q.id)
+	logger.Debugf("Done with transaction simulation / query execution [%s]", q.id)
 	q.helper.done()
 }

core/ledger/kvledger/txmgmt/validator/statebasedval/state_based_validator.go

@@ -57,16 +57,6 @@ func (v *Validator) validateEndorserTX(envBytes []byte, doMVCCValidation bool, u
 		return nil, peer.TxValidationCode_INVALID_OTHER_REASON, nil
 	}
 
-	// trace the first 1000 characters of RWSet only, in case it is huge
-	if logger.IsEnabledFor(logging.DEBUG) {
-		txRWSetString := txRWSet.String()
-		if len(txRWSetString) < 1000 {
-			logger.Debugf("validating txRWSet:[%s]", txRWSetString)
-		} else {
-			logger.Debugf("validating txRWSet:[%s...]", txRWSetString[0:1000])
-		}
-	}
-
 	var txResult peer.TxValidationCode = peer.TxValidationCode_VALID
 
 	//mvccvalidation, may invalidate transaction

core/ledger/util/couchdb/couchdb.go

@@ -390,7 +390,7 @@ func (dbclient *CouchDatabase) EnsureFullCommit() (*DBOperationResponse, error)
 //SaveDoc method provides a function to save a document, id and byte array
 func (dbclient *CouchDatabase) SaveDoc(id string, rev string, couchDoc *CouchDoc) (string, error) {
 
-	logger.Debugf("Entering SaveDoc()")
+	logger.Debugf("Entering SaveDoc()  id=[%s]", id)
 	if !utf8.ValidString(id) {
 		return "", fmt.Errorf("doc id [%x] not a valid utf8 string", id)
 	}
@@ -405,8 +405,6 @@ func (dbclient *CouchDatabase) SaveDoc(id string, rev string, couchDoc *CouchDoc
 	// id can contain a '/', so encode separately
 	saveURL = &url.URL{Opaque: saveURL.String() + "/" + encodePathElement(id)}
 
-	logger.Debugf("  id=%s,  value=%s, attachments=%d", id, string(couchDoc.JSONValue), len(couchDoc.Attachments))
-
 	if rev == "" {
 
 		//See if the document already exists, we need the rev for save
@@ -560,7 +558,7 @@ func getRevisionHeader(resp *http.Response) (string, error) {
 //ReadDoc method provides function to retrieve a document from the database by id
 func (dbclient *CouchDatabase) ReadDoc(id string) (*CouchDoc, string, error) {
 	var couchDoc CouchDoc
-	logger.Debugf("Entering ReadDoc()  id=%s", id)
+	logger.Debugf("Entering ReadDoc()  id=[%s]", id)
 	if !utf8.ValidString(id) {
 		return nil, "", fmt.Errorf("doc id [%x] not a valid utf8 string", id)
 	}
@@ -581,13 +579,13 @@ func (dbclient *CouchDatabase) ReadDoc(id string) (*CouchDoc, string, error) {
 
 	resp, couchDBReturn, err := dbclient.couchInstance.handleRequest(http.MethodGet, readURL.String(), nil, "", "")
 	if err != nil {
-		fmt.Printf("couchDBReturn=%v", couchDBReturn)
 		if couchDBReturn != nil && couchDBReturn.StatusCode == 404 {
 			logger.Debug("Document not found (404), returning nil value instead of 404 error")
 			// non-existent document should return nil value instead of a 404 error
 			// for details see https://github.com/hyperledger-archives/fabric/issues/936
 			return nil, "", nil
 		}
+		logger.Debugf("couchDBReturn=%v\n", couchDBReturn)
 		return nil, "", err
 	}
 	defer resp.Body.Close()
@@ -679,7 +677,6 @@ func (dbclient *CouchDatabase) ReadDoc(id string) (*CouchDoc, string, error) {
 		return nil, "", err
 	}
 
-	logger.Debugf("Read document, id=%s, value=%s", id, string(couchDoc.JSONValue))
 	logger.Debugf("Exiting ReadDoc()")
 	return &couchDoc, revision, nil
 }
@@ -973,18 +970,9 @@ func (couchInstance *CouchInstance) handleRequest(method, connectURL string, dat
 	}
 
 	if logger.IsEnabledFor(logging.DEBUG) {
-		dump, err2 := httputil.DumpRequestOut(req, true)
-		if err2 != nil {
-			log.Fatal(err2)
-		}
-		// trace the first 200 bytes of http request only, in case it is huge
-		if dump != nil {
-			if len(dump) <= 200 {
-				logger.Debugf("HTTP Request: %s", dump)
-			} else {
-				logger.Debugf("HTTP Request: %s...", dump[0:200])
-			}
-		}
+		dump, _ := httputil.DumpRequestOut(req, false)
+		// compact debug log by replacing carriage return / line feed with dashes to separate http headers
+		logger.Debugf("HTTP Request: %s", bytes.Replace(dump, []byte{0x0d, 0x0a}, []byte{0x20, 0x7c, 0x20}, -1))
 	}
 
 	//Create the http client