From e503a08d79219735d84a9c57f1b3276dd084675f Mon Sep 17 00:00:00 2001 From: Jason Yellick Date: Fri, 18 Aug 2017 11:25:41 -0400 Subject: [PATCH] [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 --- common/policies/implicitmeta.go | 46 +++++++++++++++++++++++---------- common/policies/policy.go | 31 ++++++++++++++++++---- 2 files changed, 58 insertions(+), 19 deletions(-) diff --git a/common/policies/implicitmeta.go b/common/policies/implicitmeta.go index 69285e16d0d..4de78116e15 100644 --- a/common/policies/implicitmeta.go +++ b/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-- diff --git a/common/policies/policy.go b/common/policies/policy.go index fd30661c0f0..e00e3600385 100644 --- a/common/policies/policy.go +++ b/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 }