[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 <jyellick@us.ibm.com>

Author: Jason Yellick

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

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
 }

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 {

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

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

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
 }

orderer/main.go

@@ -136,5 +136,6 @@ func main() {
 	)
 
 	ab.RegisterAtomicBroadcastServer(grpcServer, server)
+	logger.Infof("Beginning to serve requests")
 	grpcServer.Serve(lis)
 }