[FAB-5732] Improve policy logging

The policy ogs can be quite cryptic to the uninitiated.  In particular,
because one policy may invoke others, and a subset of the 'others' may
fail benignly, the logs can look full of errors, even when there is
nothing wrong.

This CR tries to address this in two ways, first, by adding a message to
the implicit meta policy evaluation warning that the errors may be
benign.  Secondly, by adding a policy logger wrapper around policies,
which indicate the fully qualified path of the policy being evaluated.
And finally, the implicit meta policies are enhanced to say which
policies were evaluated when there are not enough sub-policies which
evaluate successfully.

Change-Id: I032ef0d8e0a0d85f574ab313f0137cb4c6556d4a
Signed-off-by: Jason Yellick <jyellick@us.ibm.com>

Author: Jason Yellick

common/policies/implicitmeta.go

@@ -1,32 +1,28 @@
 /*
-Copyright IBM Corp. 2016 All Rights Reserved.
+Copyright IBM Corp. All Rights Reserved.
 
-Licensed under the Apache License, Version 2.0 (the "License");
-you may not use this file except in compliance with the License.
-You may obtain a copy of the License at
-
-                 http://www.apache.org/licenses/LICENSE-2.0
-
-Unless required by applicable law or agreed to in writing, software
-distributed under the License is distributed on an "AS IS" BASIS,
-WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
-See the License for the specific language governing permissions and
-limitations under the License.
+SPDX-License-Identifier: Apache-2.0
 */
 
 package policies
 
 import (
+	"bytes"
 	"fmt"
 
 	cb "github.com/hyperledger/fabric/protos/common"
 
 	"github.com/golang/protobuf/proto"
+	"github.com/op/go-logging"
 )
 
 type implicitMetaPolicy struct {
 	threshold   int
 	subPolicies []Policy
+
+	// Only used for logging
+	managers      map[string]*ManagerImpl
+	subPolicyName string
 }
 
 // NewPolicy creates a new policy based on the policy bytes
@@ -61,14 +57,36 @@ func newImplicitMetaPolicy(data []byte, managers map[string]*ManagerImpl) (*impl
 	}
 
 	return &implicitMetaPolicy{
-		subPolicies: subPolicies,
-		threshold:   threshold,
+		subPolicies:   subPolicies,
+		threshold:     threshold,
+		managers:      managers,
+		subPolicyName: definition.SubPolicy,
 	}, nil
 }
 
 // Evaluate takes a set of SignedData and evaluates whether this set of signatures satisfies the policy
 func (imp *implicitMetaPolicy) Evaluate(signatureSet []*cb.SignedData) error {
+	logger.Debugf("This is an implicit meta policy, it will trigger other policy evaluations, whose failures may be benign")
 	remaining := imp.threshold
+
+	defer func() {
+		if remaining != 0 {
+			// This log message may be large and expensive to construct, so worth checking the log level
+			if logger.IsEnabledFor(logging.DEBUG) {
+				var b bytes.Buffer
+				b.WriteString(fmt.Sprintf("Evaluation Failed: Only %d policies were satisfied, but needed %d of [ ", remaining, imp.threshold))
+				for m := range imp.managers {
+					b.WriteString(m)
+					b.WriteString(".")
+					b.WriteString(imp.subPolicyName)
+					b.WriteString(" ")
+				}
+				b.WriteString("]")
+				logger.Debugf(b.String())
+			}
+		}
+	}()
+
 	for _, policy := range imp.subPolicies {
 		if policy.Evaluate(signatureSet) == nil {
 			remaining--

common/policies/policy.go

@@ -155,7 +155,7 @@ func NewManagerImpl(path string, providers map[int32]Provider, root *cb.ConfigGr
 type rejectPolicy string
 
 func (rp rejectPolicy) Evaluate(signedData []*cb.SignedData) error {
-	return fmt.Errorf("No such policy type: %s", rp)
+	return fmt.Errorf("No such policy: '%s'", rp)
 }
 
 // Manager returns the sub-policy manager for a given path and whether it exists
@@ -176,6 +176,26 @@ func (pm *ManagerImpl) Manager(path []string) (Manager, bool) {
 	return m.Manager(path[1:])
 }
 
+type policyLogger struct {
+	policy     Policy
+	policyName string
+}
+
+func (pl *policyLogger) Evaluate(signatureSet []*cb.SignedData) error {
+	if logger.IsEnabledFor(logging.DEBUG) {
+		logger.Debugf("== Evaluating %T Policy %s ==", pl.policy, pl.policyName)
+		defer logger.Debugf("== Done Evaluating %T Policy %s", pl.policy, pl.policyName)
+	}
+
+	err := pl.policy.Evaluate(signatureSet)
+	if err != nil {
+		logger.Debugf("Signature set did not satisfy policy %s", pl.policyName)
+	} else {
+		logger.Debugf("Signature set satisfies policy %s", pl.policyName)
+	}
+	return err
+}
+
 // GetPolicy returns a policy and true if it was the policy requested, or false if it is the default reject policy
 func (pm *ManagerImpl) GetPolicy(id string) (Policy, bool) {
 	if id == "" {
@@ -204,8 +224,9 @@ func (pm *ManagerImpl) GetPolicy(id string) (Policy, bool) {
 		}
 		return rejectPolicy(relpath), false
 	}
-	if logger.IsEnabledFor(logging.DEBUG) {
-		logger.Debugf("Returning policy %s from manager %s for evaluation", relpath, pm.path)
-	}
-	return policy, true
+
+	return &policyLogger{
+		policy:     policy,
+		policyName: PathSeparator + pm.path + PathSeparator + relpath,
+	}, true
 }