Log fewer spurious CT submission errors. (letsencrypt#3447)

jsha · cpu · commit d2a28264dd85 · 2018-02-16T09:26:12.000-05:00
With the CT policy changes, we cancel any outstanding requests in a
group once we've gotten a successful response from any log in that
group. That means various function calls will return early with an error
code indicating cancellation. We want to avoid logging such error codes,
because they were not really errors, they were intentional.

This change introduces a small utility package called "canceled", which
checks for both context.Canceled and the gRPC return code indicating
cancelled.
diff --git a/canceled/canceled.go b/canceled/canceled.go
@@ -0,0 +1,16 @@
+package canceled
+
+import (
+	"context"
+
+	"google.golang.org/grpc"
+	"google.golang.org/grpc/codes"
+)
+
+// Is returns true if err is non-nil and is either context.Canceled, or has a
+// grpc code of Canceled. This is useful because cancelations propagate through
+// gRPC boundaries, and if we choose to treat in-process cancellations a certain
+// way, we usually want to treat cross-process cancellations the same way.
+func Is(err error) bool {
+	return err == context.Canceled || grpc.Code(err) == codes.Canceled
+}
diff --git a/canceled/canceled_test.go b/canceled/canceled_test.go
@@ -0,0 +1,22 @@
+package canceled
+
+import (
+	"context"
+	"errors"
+	"testing"
+
+	"google.golang.org/grpc"
+	"google.golang.org/grpc/codes"
+)
+
+func TestCanceled(t *testing.T) {
+	if !Is(context.Canceled) {
+		t.Errorf("Expected context.Canceled to be canceled, but wasn't.")
+	}
+	if !Is(grpc.Errorf(codes.Canceled, "hi")) {
+		t.Errorf("Expected gRPC cancellation to be cancelled, but wasn't.")
+	}
+	if Is(errors.New("hi")) {
+		t.Errorf("Expected random error to not be cancelled, but was.")
+	}
+}
diff --git a/ctpolicy/ctpolicy.go b/ctpolicy/ctpolicy.go
@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 
+	"github.com/letsencrypt/boulder/canceled"
 	"github.com/letsencrypt/boulder/cmd"
 	"github.com/letsencrypt/boulder/core"
 	blog "github.com/letsencrypt/boulder/log"
@@ -50,7 +51,7 @@ func (ctp *CTPolicy) race(ctx context.Context, cert core.CertDER, group []cmd.Lo
 			})
 			if err != nil {
 				// Only log the error if it is not a result of canceling subCtx
-				if err != context.Canceled {
+				if !canceled.Is(err) {
 					ctp.log.Warning(fmt.Sprintf("ct submission to %q failed: %s", l.URI, err))
 				}
 				results <- result{err: err}
@@ -76,7 +77,7 @@ func (ctp *CTPolicy) race(ctx context.Context, cert core.CertDER, group []cmd.Lo
 			// back from another log.
 		}
 	}
-	return nil, errors.New("all submissions for group failed")
+	return nil, errors.New("all submissions failed")
 }
 
 // GetSCTs attempts to retrieve a SCT from each configured grouping of logs and returns
@@ -85,12 +86,15 @@ func (ctp *CTPolicy) GetSCTs(ctx context.Context, cert core.CertDER) ([]core.SCT
 	results := make(chan result, len(ctp.groups))
 	subCtx, cancel := context.WithCancel(ctx)
 	defer cancel()
-	for _, g := range ctp.groups {
-		go func(g []cmd.LogDescription) {
+	for i, g := range ctp.groups {
+		go func(i int, g []cmd.LogDescription) {
 			sct, err := ctp.race(subCtx, cert, g)
 			// Only one of these will be non-nil
-			results <- result{sct: sct, err: err}
-		}(g)
+			if err != nil {
+				results <- result{err: fmt.Errorf("CT log group %d: %s", i, err)}
+			}
+			results <- result{sct: sct}
+		}(i, g)
 	}
 
 	var ret []core.SCTDER
diff --git a/ctpolicy/ctpolicy_test.go b/ctpolicy/ctpolicy_test.go
@@ -3,6 +3,7 @@ package ctpolicy
 import (
 	"context"
 	"errors"
+	"regexp"
 	"testing"
 	"time"
 
@@ -38,12 +39,12 @@ func TestGetSCTs(t *testing.T) {
 	expired, cancel := context.WithDeadline(context.Background(), time.Now())
 	defer cancel()
 	testCases := []struct {
-		name   string
-		mock   core.Publisher
-		groups [][]cmd.LogDescription
-		ctx    context.Context
-		result []core.SCTDER
-		err    error
+		name      string
+		mock      core.Publisher
+		groups    [][]cmd.LogDescription
+		ctx       context.Context
+		result    []core.SCTDER
+		errRegexp *regexp.Regexp
 	}{
 		{
 			name: "basic success case",
@@ -74,8 +75,8 @@ func TestGetSCTs(t *testing.T) {
 					{URI: "ghi", Key: "jkl"},
 				},
 			},
-			ctx: context.Background(),
-			err: errors.New("all submissions for group failed"),
+			ctx:       context.Background(),
+			errRegexp: regexp.MustCompile("CT log group .: all submissions failed"),
 		},
 		{
 			name: "parent context timeout failure case",
@@ -90,8 +91,8 @@ func TestGetSCTs(t *testing.T) {
 					{URI: "ghi", Key: "jkl"},
 				},
 			},
-			ctx: expired,
-			err: context.DeadlineExceeded,
+			ctx:       expired,
+			errRegexp: regexp.MustCompile("CT log group .: context deadline exceeded"),
 		},
 	}
 
@@ -101,8 +102,10 @@ func TestGetSCTs(t *testing.T) {
 			ret, err := ctp.GetSCTs(tc.ctx, []byte{0})
 			if tc.result != nil {
 				test.AssertDeepEquals(t, ret, tc.result)
-			} else if tc.err != nil {
-				test.AssertDeepEquals(t, err, tc.err)
+			} else if tc.errRegexp != nil {
+				if !tc.errRegexp.MatchString(err.Error()) {
+					t.Errorf("Error %q did not match expected regexp %q", err, tc.errRegexp)
+				}
 			}
 		})
 	}
diff --git a/publisher/publisher.go b/publisher/publisher.go
@@ -17,6 +17,7 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"golang.org/x/net/context"
 
+	"github.com/letsencrypt/boulder/canceled"
 	"github.com/letsencrypt/boulder/core"
 	blog "github.com/letsencrypt/boulder/log"
 	"github.com/letsencrypt/boulder/metrics"
@@ -221,8 +222,10 @@ func (pub *Impl) SubmitToSingleCTWithResult(ctx context.Context, req *pubpb.Requ
 		core.SerialToString(cert.SerialNumber),
 		ctLog)
 	if err != nil {
-		pub.log.AuditErr(
-			fmt.Sprintf("Failed to submit certificate to CT log at %s: %s", ctLog.uri, err))
+		if !canceled.Is(err) {
+			pub.log.AuditErr(
+				fmt.Sprintf("Failed to submit certificate to CT log at %s: %s", ctLog.uri, err))
+		}
 		return nil, err
 	}
 
