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) }