From aa8e51bcf278922f9302028586e420da48056e16 Mon Sep 17 00:00:00 2001 From: Jason Yellick Date: Mon, 16 Jan 2017 17:09:40 -0500 Subject: [PATCH] [FAB-1681] Improve orderer logging https://jira.hyperledger.org/browse/FAB-1681 Some important orderer log messages lacked chainID and certain code paths lacked logging entirely. As more users are attempting to utilize the ordering service in more sophisticated ways (such as deploying chains) enhanced logging will be very beneficial. Change-Id: If6093428d162cfdba6071f3a9169747510bea93e Signed-off-by: Jason Yellick --- common/configtx/manager.go | 11 ++++++++++- common/policies/policy.go | 15 +++++++++++++-- orderer/common/broadcast/broadcast.go | 8 ++++++++ orderer/common/deliver/deliver.go | 4 +++- orderer/common/sharedconfig/sharedconfig.go | 3 +++ orderer/common/sigfilter/sigfilter.go | 7 +++++-- orderer/main.go | 1 + 7 files changed, 43 insertions(+), 6 deletions(-) diff --git a/common/configtx/manager.go b/common/configtx/manager.go index aac913c3c6f..766d14aac5c 100644 --- a/common/configtx/manager.go +++ b/common/configtx/manager.go @@ -25,8 +25,11 @@ import ( "errors" "github.com/golang/protobuf/proto" + logging "github.com/op/go-logging" ) +var logger = logging.MustGetLogger("common/configtx") + // Handler provides a hook which allows other pieces of code to participate in config proposals type Handler interface { // BeginConfig called when a config proposal is begun @@ -154,18 +157,21 @@ func makeConfigMap() map[cb.ConfigurationItem_ConfigurationType]map[string]*cb.C } func (cm *configurationManager) beginHandlers() { + logger.Debugf("Beginning new configuration for chain %s", cm.chainID) for ctype := range cb.ConfigurationItem_ConfigurationType_name { cm.handlers[cb.ConfigurationItem_ConfigurationType(ctype)].BeginConfig() } } func (cm *configurationManager) rollbackHandlers() { + logger.Debugf("Rolling back configuration for chain %s", cm.chainID) for ctype := range cb.ConfigurationItem_ConfigurationType_name { cm.handlers[cb.ConfigurationItem_ConfigurationType(ctype)].RollbackConfig() } } func (cm *configurationManager) commitHandlers() { + logger.Debugf("Committing configuration for chain %s", cm.chainID) for ctype := range cb.ConfigurationItem_ConfigurationType_name { cm.handlers[cb.ConfigurationItem_ConfigurationType(ctype)].CommitConfig() } @@ -220,6 +226,8 @@ func (cm *configurationManager) processConfig(configtx *cb.ConfigurationEnvelope // If a config item was modified, its LastModified must be set correctly, and it must satisfy the modification policy if isModified { + logger.Debugf("Proposed configuration item of type %v and key %t on chain %s has been modified", config.Type, config.Key, cm.chainID) + if config.LastModified != seq { return nil, fmt.Errorf("Key %v for type %v was modified, but its LastModified %d does not equal current configtx Sequence %d", config.Key, config.Type, config.LastModified, seq) } @@ -247,9 +255,10 @@ func (cm *configurationManager) processConfig(configtx *cb.ConfigurationEnvelope } // Ensure the type handler agrees the config is well formed + logger.Debugf("Proposing configuration item of type %v for key %s on chain %s", config.Type, config.Key, cm.chainID) err = cm.handlers[config.Type].ProposeConfig(config) if err != nil { - return nil, fmt.Errorf("Error proposing configuration item %s of type %d: %s", config.Key, config.Type, err) + return nil, fmt.Errorf("Error proposing configuration item of type %v for key %s on chain %s: %s", config.Type, config.Key, chainID, err) } configMap[config.Type][config.Key] = config diff --git a/common/policies/policy.go b/common/policies/policy.go index 21a8211fa1d..2dca80bc1b4 100644 --- a/common/policies/policy.go +++ b/common/policies/policy.go @@ -22,8 +22,11 @@ import ( cb "github.com/hyperledger/fabric/protos/common" "github.com/golang/protobuf/proto" + logging "github.com/op/go-logging" ) +var logger = logging.MustGetLogger("common/policies") + // Policy is used to determine if a signature is valid type Policy interface { // Evaluate takes a set of SignedData and evaluates whether this set of signatures satisfies the policy @@ -70,15 +73,21 @@ func (rp rejectPolicy) Evaluate(signedData []*cb.SignedData) error { func (pm *ManagerImpl) GetPolicy(id string) (Policy, bool) { policy, ok := pm.policies[id] if !ok { + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Returning dummy reject all policy because %s could not be found", id) + } return rejectPolicy(id), false } + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Returning policy %s for evaluation", id) + } return policy, true } // BeginConfig is used to start a new configuration proposal func (pm *ManagerImpl) BeginConfig() { if pm.pendingPolicies != nil { - panic("Programming error, cannot call begin in the middle of a proposal") + logger.Panicf("Programming error, cannot call begin in the middle of a proposal") } pm.pendingPolicies = make(map[string]Policy) } @@ -91,7 +100,7 @@ func (pm *ManagerImpl) RollbackConfig() { // CommitConfig is used to commit a new configuration proposal func (pm *ManagerImpl) CommitConfig() { if pm.pendingPolicies == nil { - panic("Programming error, cannot call commit without an existing proposal") + logger.Panicf("Programming error, cannot call commit without an existing proposal") } pm.policies = pm.pendingPolicies pm.pendingPolicies = nil @@ -120,5 +129,7 @@ func (pm *ManagerImpl) ProposeConfig(configItem *cb.ConfigurationItem) error { } pm.pendingPolicies[configItem.Key] = cPolicy + + logger.Debugf("Proposed new policy %s", configItem.Key) return nil } diff --git a/orderer/common/broadcast/broadcast.go b/orderer/common/broadcast/broadcast.go index 4d966f8fe21..05e29d38b9a 100644 --- a/orderer/common/broadcast/broadcast.go +++ b/orderer/common/broadcast/broadcast.go @@ -99,6 +99,10 @@ func (bh *handlerImpl) Handle(srv ab.AtomicBroadcast_BroadcastServer) error { continue } + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Broadcast is filtering message for chain %s", payload.Header.ChainHeader.ChainID) + } + // Normal transaction for existing chain _, filterErr := support.Filters().Apply(msg) @@ -112,6 +116,10 @@ func (bh *handlerImpl) Handle(srv ab.AtomicBroadcast_BroadcastServer) error { return srv.Send(&ab.BroadcastResponse{Status: cb.Status_SERVICE_UNAVAILABLE}) } + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Broadcast is successfully enqueued message for chain %s", payload.Header.ChainHeader.ChainID) + } + err = srv.Send(&ab.BroadcastResponse{Status: cb.Status_SUCCESS}) if err != nil { diff --git a/orderer/common/deliver/deliver.go b/orderer/common/deliver/deliver.go index 9f7dbab461a..7198a3b393c 100644 --- a/orderer/common/deliver/deliver.go +++ b/orderer/common/deliver/deliver.go @@ -104,7 +104,9 @@ func (ds *deliverServer) Handle(srv ab.AtomicBroadcast_DeliverServer) error { return err } - logger.Debugf("Received seekInfo %v", seekInfo) + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Received seekInfo %v for chain %s", seekInfo, payload.Header.ChainHeader.ChainID) + } cursor, number := chain.Reader().Iterator(seekInfo.Start) var stopNum uint64 diff --git a/orderer/common/sharedconfig/sharedconfig.go b/orderer/common/sharedconfig/sharedconfig.go index edcbf759da4..6aeabb9369a 100644 --- a/orderer/common/sharedconfig/sharedconfig.go +++ b/orderer/common/sharedconfig/sharedconfig.go @@ -167,6 +167,9 @@ func (pm *ManagerImpl) CommitConfig() { } pm.config = pm.pendingConfig pm.pendingConfig = nil + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Adopting new orderer shared config: %+v", pm.config) + } } // ProposeConfig is used to add new configuration to the configuration proposal diff --git a/orderer/common/sigfilter/sigfilter.go b/orderer/common/sigfilter/sigfilter.go index 98bcb240137..c4bdb0be10a 100644 --- a/orderer/common/sigfilter/sigfilter.go +++ b/orderer/common/sigfilter/sigfilter.go @@ -64,11 +64,14 @@ func (sf *sigFilter) Apply(message *cb.Envelope) (filter.Action, filter.Committe err = policy.Evaluate(signedData) if err == nil { - logger.Debugf("Accepting validly signed message") + logger.Debugf("Accepting validly signed message for policy %s", policy) return filter.Forward, nil } + } - logger.Debugf("Rejecting message which was not appropriately signed") + if logger.IsEnabledFor(logging.DEBUG) { + logger.Debugf("Rejecting message because it was not appropriately signed for any allowed policy among %s", sf.policySource()) + } return filter.Reject, nil } diff --git a/orderer/main.go b/orderer/main.go index 15861a8e96d..9a130cd510c 100644 --- a/orderer/main.go +++ b/orderer/main.go @@ -136,5 +136,6 @@ func main() { ) ab.RegisterAtomicBroadcastServer(grpcServer, server) + logger.Infof("Beginning to serve requests") grpcServer.Serve(lis) }