Merge "Clean up peer logging - serviceability"

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