From b39b8a8fd5c026182f2bc4468c410a4fbee26e51 Mon Sep 17 00:00:00 2001 From: denyeart Date: Mon, 27 Feb 2017 18:34:00 -0500 Subject: [PATCH] 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 --- core/committer/txvalidator/validator.go | 4 +-- core/common/ccprovider/ccprovider.go | 2 +- core/common/validation/msgvalidation.go | 30 +++++++++---------- core/endorser/endorser.go | 4 +-- .../historyleveldb/historyleveldb.go | 6 ++-- core/ledger/kvledger/kv_ledger.go | 9 +++--- .../statedb/statecouchdb/statecouchdb.go | 19 +----------- .../statedb/stateleveldb/stateleveldb.go | 11 ++----- .../lockbased_query_executer.go | 2 +- .../statebasedval/state_based_validator.go | 10 ------- core/ledger/util/couchdb/couchdb.go | 24 ++++----------- core/scc/escc/endorser_onevalidsignature.go | 4 +-- core/scc/vscc/validator_onevalidsignature.go | 4 +-- gossip/state/state.go | 2 +- orderer/multichain/manager.go | 2 +- peer/node/start.go | 5 +++- 16 files changed, 48 insertions(+), 90 deletions(-) diff --git a/core/committer/txvalidator/validator.go b/core/committer/txvalidator/validator.go index 78c043936bb..427f4fd85ba 100644 --- a/core/committer/txvalidator/validator.go +++ b/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) diff --git a/core/common/ccprovider/ccprovider.go b/core/common/ccprovider/ccprovider.go index 47896a2c833..1d99ffecd3d 100644 --- a/core/common/ccprovider/ccprovider.go +++ b/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 } diff --git a/core/common/validation/msgvalidation.go b/core/common/validation/msgvalidation.go index 9827b399843..578af502419 100644 --- a/core/common/validation/msgvalidation.go +++ b/core/common/validation/msgvalidation.go @@ -32,7 +32,7 @@ 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) @@ -40,7 +40,7 @@ func validateChaincodeProposalMessage(prop *pb.Proposal, hdr *common.Header) (*p 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,7 +145,7 @@ 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() @@ -153,7 +153,7 @@ func checkSignatureFromCreator(creatorBytes []byte, sig []byte, msg []byte, Chai 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) @@ -161,7 +161,7 @@ func checkSignatureFromCreator(creatorBytes []byte, sig []byte, msg []byte, Chai 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) diff --git a/core/endorser/endorser.go b/core/endorser/endorser.go index 2ace3999391..3b7a94b34fd 100644 --- a/core/endorser/endorser.go +++ b/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 diff --git a/core/ledger/kvledger/history/historydb/historyleveldb/historyleveldb.go b/core/ledger/kvledger/history/historydb/historyleveldb/historyleveldb.go index 1d790035b98..7d9c7b7c19d 100644 --- a/core/ledger/kvledger/history/historydb/historyleveldb/historyleveldb.go +++ b/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 } diff --git a/core/ledger/kvledger/kv_ledger.go b/core/ledger/kvledger/kv_ledger.go index 1ea7f25920b..8df93beaf08 100644 --- a/core/ledger/kvledger/kv_ledger.go +++ b/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)) } diff --git a/core/ledger/kvledger/txmgmt/statedb/statecouchdb/statecouchdb.go b/core/ledger/kvledger/txmgmt/statedb/statecouchdb/statecouchdb.go index cc23b6e67e2..3d8f21b8753 100644 --- a/core/ledger/kvledger/txmgmt/statedb/statecouchdb/statecouchdb.go +++ b/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 { diff --git a/core/ledger/kvledger/txmgmt/statedb/stateleveldb/stateleveldb.go b/core/ledger/kvledger/txmgmt/statedb/stateleveldb/stateleveldb.go index 544d1a1b633..6bf8939aa0c 100644 --- a/core/ledger/kvledger/txmgmt/statedb/stateleveldb/stateleveldb.go +++ b/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 { diff --git a/core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr/lockbased_query_executer.go b/core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr/lockbased_query_executer.go index c5446015848..38e6aa314cc 100644 --- a/core/ledger/kvledger/txmgmt/txmgr/lockbasedtxmgr/lockbased_query_executer.go +++ b/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() } diff --git a/core/ledger/kvledger/txmgmt/validator/statebasedval/state_based_validator.go b/core/ledger/kvledger/txmgmt/validator/statebasedval/state_based_validator.go index 67f76249b66..895badd437a 100644 --- a/core/ledger/kvledger/txmgmt/validator/statebasedval/state_based_validator.go +++ b/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 diff --git a/core/ledger/util/couchdb/couchdb.go b/core/ledger/util/couchdb/couchdb.go index 406dc794a7b..9d7ba27f2e1 100644 --- a/core/ledger/util/couchdb/couchdb.go +++ b/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 diff --git a/core/scc/escc/endorser_onevalidsignature.go b/core/scc/escc/endorser_onevalidsignature.go index 14d6fa68390..ee3428e2e71 100644 --- a/core/scc/escc/endorser_onevalidsignature.go +++ b/core/scc/escc/endorser_onevalidsignature.go @@ -70,7 +70,7 @@ func (e *EndorserOneValidSignature) Invoke(stub shim.ChaincodeStubInterface) pb. return shim.Error(fmt.Sprintf("Incorrect number of arguments (expected a maximum of 7, provided %d)", len(args))) } - logger.Infof("ESCC starts: %d args", len(args)) + logger.Debugf("ESCC starts: %d args", len(args)) // handle the header var hdr []byte @@ -163,6 +163,6 @@ func (e *EndorserOneValidSignature) Invoke(stub shim.ChaincodeStubInterface) pb. fmt.Println("GetProposalResponse get empty Response") } - logger.Infof("ESCC exits successfully") + logger.Debugf("ESCC exits successfully") return shim.Success(prBytes) } diff --git a/core/scc/vscc/validator_onevalidsignature.go b/core/scc/vscc/validator_onevalidsignature.go index 440d156e048..0dda484a905 100644 --- a/core/scc/vscc/validator_onevalidsignature.go +++ b/core/scc/vscc/validator_onevalidsignature.go @@ -69,7 +69,7 @@ func (vscc *ValidatorOneValidSignature) Invoke(stub shim.ChaincodeStubInterface) return shim.Error("No policy supplied") } - logger.Infof("VSCC invoked") + logger.Debugf("VSCC invoked") // get the envelope... env, err := utils.GetEnvelopeFromBlock(args[1]) @@ -144,7 +144,7 @@ func (vscc *ValidatorOneValidSignature) Invoke(stub shim.ChaincodeStubInterface) } } - logger.Infof("VSCC exists successfully") + logger.Debugf("VSCC exists successfully") return shim.Success(nil) } diff --git a/gossip/state/state.go b/gossip/state/state.go index e6789154f3c..950f9541d8d 100644 --- a/gossip/state/state.go +++ b/gossip/state/state.go @@ -409,6 +409,6 @@ func (s *GossipStateProviderImpl) commitBlock(block *common.Block, seqNum uint64 s.logger.Errorf("Unable to serialize node meta state, error = %s", err) } - s.logger.Debug("Commit success, created a block!") + s.logger.Debugf("Channel [%s]: Created block [%d] with %d transaction(s)", s.chainID, block.Header.Number, len(block.Data.Data)) return nil } diff --git a/orderer/multichain/manager.go b/orderer/multichain/manager.go index ef16d870776..e79f4148c21 100644 --- a/orderer/multichain/manager.go +++ b/orderer/multichain/manager.go @@ -198,7 +198,7 @@ func (ml *multiLedger) newChain(configtx *cb.Envelope) { cs := newChainSupport(createStandardFilters(ledgerResources), ledgerResources, ml.consenters, ml.signer) chainID := ledgerResources.ChainID() - logger.Debugf("Created and starting new chain %s", chainID) + logger.Infof("Created and starting new chain %s", chainID) newChains[string(chainID)] = cs cs.start() diff --git a/peer/node/start.go b/peer/node/start.go index c41eb90cce9..3630fecdb08 100644 --- a/peer/node/start.go +++ b/peer/node/start.go @@ -198,7 +198,7 @@ func serve(args []string) error { scc.DeploySysCCs(cid) }) - logger.Infof("Starting peer with ID=%s, network ID=%s, address=%s", + logger.Infof("Starting peer with ID=[%s], network ID=[%s], address=[%s]", peerEndpoint.Id, viper.GetString("peer.networkId"), peerEndpoint.Address) // Start the grpc server. Done in a goroutine so we can deploy the @@ -244,6 +244,9 @@ func serve(args []string) error { }() } + logger.Infof("Started peer with ID=[%s], network ID=[%s], address=[%s]", + peerEndpoint.Id, viper.GetString("peer.networkId"), peerEndpoint.Address) + // sets the logging level for the 'error' and 'msp' modules to the // values from core.yaml. they can also be updated dynamically using // "peer logging setlevel "