[FAB-4830] cauthdsl signature verify err unlogged

We have seen in a number of bug reports, such as FAB-4827 that the
output provided by cauthdsl in the logs is cryptic, and hard to debug
from.  Additionally, the error returned by the signature verification is
not actually logged, which makes conclusive debugging nearly impossible.

This CR reworks the logging messages to be more uniform, less cryptic,
and logs the particular err which was ignored.

Change-Id: I229ee62be881d5d136a4532174990386d644853e
Signed-off-by: Jason Yellick <[email protected]>

Author: Jason Yellick

common/cauthdsl/cauthdsl.go

@@ -18,11 +18,14 @@ package cauthdsl
 
 import (
 	"fmt"
+	"time"
 
 	"github.com/hyperledger/fabric/common/flogging"
 	"github.com/hyperledger/fabric/msp"
 	cb "github.com/hyperledger/fabric/protos/common"
 	mb "github.com/hyperledger/fabric/protos/msp"
+
+	"github.com/op/go-logging"
 )
 
 var cauthdslLogger = flogging.MustGetLogger("cauthdsl")
@@ -45,7 +48,8 @@ func compile(policy *cb.SignaturePolicy, identities []*mb.MSPPrincipal, deserial
 
 		}
 		return func(signedData []*cb.SignedData, used []bool) bool {
-			cauthdslLogger.Debugf("Gate evaluation starts: (%v)", t)
+			grepKey := time.Now().UnixNano()
+			cauthdslLogger.Debugf("%p gate %d evaluation starts", signedData, grepKey)
 			verified := int32(0)
 			_used := make([]bool, len(used))
 			for _, policy := range policies {
@@ -57,44 +61,50 @@ func compile(policy *cb.SignaturePolicy, identities []*mb.MSPPrincipal, deserial
 			}
 
 			if verified >= t.NOutOf.N {
-				cauthdslLogger.Debugf("Gate evaluation succeeds: (%v)", t)
+				cauthdslLogger.Debugf("%p gate %d evaluation succeeds", signedData, grepKey)
 			} else {
-				cauthdslLogger.Debugf("Gate evaluation fails: (%v)", t)
+				cauthdslLogger.Debugf("%p gate %d evaluation fails", signedData, grepKey)
 			}
 
 			return verified >= t.NOutOf.N
 		}, nil
 	case *cb.SignaturePolicy_SignedBy:
 		if t.SignedBy < 0 || t.SignedBy >= int32(len(identities)) {
-			return nil, fmt.Errorf("Identity index out of range, requested %v, but identies length is %d", t.SignedBy, len(identities))
+			return nil, fmt.Errorf("identity index out of range, requested %v, but identies length is %d", t.SignedBy, len(identities))
 		}
 		signedByID := identities[t.SignedBy]
 		return func(signedData []*cb.SignedData, used []bool) bool {
-			cauthdslLogger.Debugf("Principal evaluation starts: (%v) (used %v)", t, used)
+			cauthdslLogger.Debugf("%p signed by %d principal evaluation starts (used %v)", signedData, t.SignedBy, used)
 			for i, sd := range signedData {
 				if used[i] {
+					cauthdslLogger.Debugf("%p skipping identity %d because it has already been used", signedData, i)
 					continue
 				}
+				if cauthdslLogger.IsEnabledFor(logging.DEBUG) {
+					// Unlike most places, this is a huge print statement, and worth checking log level before create garbage
+					cauthdslLogger.Debugf("%p processing identity %d with bytes of %x", signedData, i, sd.Identity)
+				}
 				identity, err := deserializer.DeserializeIdentity(sd.Identity)
 				if err != nil {
-					cauthdslLogger.Errorf("Principal deserialization failed: (%s) for identity %v", err, sd.Identity)
+					cauthdslLogger.Errorf("Principal deserialization failure (%s) for identity %x", err, sd.Identity)
 					continue
 				}
 				err = identity.SatisfiesPrincipal(signedByID)
-				if err == nil {
-					cauthdslLogger.Debugf("Principal matched by identity: (%v) for %v", t, sd.Identity)
-					err = identity.Verify(sd.Data, sd.Signature)
-					if err == nil {
-						used[i] = true
-						cauthdslLogger.Debugf("Principal evaluation succeeds: (%v) (used %v)", t, used)
-						return true
-					}
-					cauthdslLogger.Debugf("Invalid signature for identity: (%v)", t)
-				} else {
-					cauthdslLogger.Debugf("Identity (%v) does not satisfy principal: %s", sd.Identity, err)
+				if err != nil {
+					cauthdslLogger.Debugf("%p identity %d does not satisfy principal: %s", signedData, i, err)
+					continue
+				}
+				cauthdslLogger.Debugf("%p principal matched by identity %d", signedData, i)
+				err = identity.Verify(sd.Data, sd.Signature)
+				if err != nil {
+					cauthdslLogger.Debugf("%p signature for identity %d is invalid: %s", signedData, i, err)
+					continue
 				}
+				cauthdslLogger.Debugf("%p principal evaluation succeeds for identity %d", signedData, i)
+				used[i] = true
+				return true
 			}
-			cauthdslLogger.Debugf("Principal evaluation fails: (%v) %v", t, used)
+			cauthdslLogger.Debugf("%p principal evaluation fails", signedData)
 			return false
 		}, nil
 	default:

common/cauthdsl/cauthdsl_test.go

@@ -26,9 +26,14 @@ import (
 	mb "github.com/hyperledger/fabric/protos/msp"
 
 	"github.com/golang/protobuf/proto"
+	logging "github.com/op/go-logging"
 	"github.com/stretchr/testify/assert"
 )
 
+func init() {
+	logging.SetLevel(logging.DEBUG, "")
+}
+
 var invalidSignature = []byte("badsigned")
 
 type mockIdentity struct {