RA: Log CAA reuse/recheck at order finalize time (#6643)

- Log counts of Authzs where CAA was rechecked/reused.
- Move the CAA recheck duration to a single variable in the RA.
- Add new method `InfoObject` to our logger.

Fixes #6560
Part of #6623

log/log.go

@@ -30,6 +30,7 @@ type Logger interface {
 	Warningf(format string, a ...interface{})
 	Info(msg string)
 	Infof(format string, a ...interface{})
+	InfoObject(string, interface{})
 	Debug(msg string)
 	Debugf(format string, a ...interface{})
 	AuditPanic()
@@ -315,6 +316,17 @@ func (log *impl) Infof(format string, a ...interface{}) {
 	log.Info(fmt.Sprintf(format, a...))
 }
 
+// InfoObject logs an INFO level JSON-serialized object message.
+func (log *impl) InfoObject(msg string, obj interface{}) {
+	jsonObj, err := json.Marshal(obj)
+	if err != nil {
+		log.auditAtLevel(syslog.LOG_ERR, fmt.Sprintf("Object could not be serialized to JSON. Raw: %+v", obj))
+		return
+	}
+
+	log.Infof("%s JSON=%s", msg, jsonObj)
+}
+
 // Debug level messages pass through normally.
 func (log *impl) Debug(msg string) {
 	log.w.logAtLevel(syslog.LOG_DEBUG, msg)

ra/ra.go

@@ -54,6 +54,12 @@ import (
 var (
 	errIncompleteGRPCRequest  = errors.New("incomplete gRPC request message")
 	errIncompleteGRPCResponse = errors.New("incomplete gRPC response message")
+
+	// caaRecheckDuration is the amount of time after a CAA check that we will
+	// recheck the CAA records for a domain. Per Baseline Requirements, we must
+	// recheck CAA records within 8 hours of issuance. We set this to 7 hours to
+	// stay on the safe side.
+	caaRecheckDuration = -7 * time.Hour
 )
 
 type caaChecker interface {
@@ -329,6 +335,20 @@ type certificateRevocationEvent struct {
 	Error string `json:",omitempty"`
 }
 
+// finalizationCAACheckEvent is a struct for holding information logged as JSON
+// to the info log as the result of an issuance event. It is logged when the RA
+// performs the final CAA check of a certificate finalization request.
+type finalizationCAACheckEvent struct {
+	// Requester is the associated account ID.
+	Requester int64 `json:",omitempty"`
+	// Reused is a count of Authz where the original CAA check was performed in
+	// the last 7 hours.
+	Reused int `json:",omitempty"`
+	// Rechecked is a count of Authz where a new CAA check was performed because
+	// the original check was older than 7 hours.
+	Rechecked int `json:",omitempty"`
+}
+
 // noRegistrationID is used for the regID parameter to GetThreshold when no
 // registration-based overrides are necessary.
 const noRegistrationID = -1
@@ -722,7 +742,8 @@ func (ra *RegistrationAuthorityImpl) checkOrderAuthorizations(
 	names = core.UniqueLowerNames(names)
 
 	// Check the authorizations to ensure validity for the names required.
-	if err = ra.checkAuthorizationsCAA(ctx, names, authzs, ra.clk.Now()); err != nil {
+	err = ra.checkAuthorizationsCAA(ctx, int64(acctID), names, authzs, ra.clk.Now())
+	if err != nil {
 		return nil, err
 	}
 
@@ -757,6 +778,7 @@ func validatedBefore(authz *core.Authorization, caaRecheckTime time.Time) (bool,
 // If it returns an error, it will be of type BoulderError.
 func (ra *RegistrationAuthorityImpl) checkAuthorizationsCAA(
 	ctx context.Context,
+	acctID int64,
 	names []string,
 	authzs map[string]*core.Authorization,
 	now time.Time) error {
@@ -772,14 +794,14 @@ func (ra *RegistrationAuthorityImpl) checkAuthorizationsCAA(
 	// check to see if the authorized challenge `AttemptedAt`
 	// (`Validated`) value from the database is before our caaRecheckTime.
 	// Set the recheck time to 7 hours ago.
-	caaRecheckAfter := now.Add(-7 * time.Hour)
+	caaRecheckAfter := now.Add(caaRecheckDuration)
 
 	// Set a CAA recheck time based on the assumption of a 30 day authz
 	// lifetime. This has been deprecated in favor of a new check based
 	// off the Validated time stored in the database, but we want to check
 	// both for a time and increment a stat if this code path is hit for
 	// compliance safety.
-	caaRecheckTime := now.Add(ra.authorizationLifetime).Add(-7 * time.Hour)
+	caaRecheckTime := now.Add(ra.authorizationLifetime).Add(caaRecheckDuration)
 
 	for _, name := range names {
 		authz := authzs[name]
@@ -818,6 +840,13 @@ func (ra *RegistrationAuthorityImpl) checkAuthorizationsCAA(
 		)
 	}
 
+	caaEvent := &finalizationCAACheckEvent{
+		Requester: acctID,
+		Reused:    len(authzs) - len(recheckAuthzs),
+		Rechecked: len(recheckAuthzs),
+	}
+	ra.log.InfoObject("FinalizationCaaCheck", caaEvent)
+
 	return nil
 }
 

ra/ra_test.go

@@ -1755,22 +1755,22 @@ func TestRecheckCAADates(t *testing.T) {
 	// NOTE: The names provided here correspond to authorizations in the
 	// `mockSAWithRecentAndOlder`
 	names := []string{"recent.com", "older.com", "older2.com", "wildcard.com", "*.wildcard.com"}
-	err := ra.checkAuthorizationsCAA(context.Background(), names, authzs, fc.Now())
+	err := ra.checkAuthorizationsCAA(context.Background(), Registration.Id, names, authzs, fc.Now())
 	// We expect that there is no error rechecking authorizations for these names
 	if err != nil {
 		t.Errorf("expected nil err, got %s", err)
 	}
 
 	// Should error if a authorization has `!= 1` challenge
-	err = ra.checkAuthorizationsCAA(context.Background(), []string{"twochallenges.com"}, authzs, fc.Now())
+	err = ra.checkAuthorizationsCAA(context.Background(), Registration.Id, []string{"twochallenges.com"}, authzs, fc.Now())
 	test.AssertEquals(t, err.Error(), "authorization has incorrect number of challenges. 1 expected, 2 found for: id twochal")
 
 	// Should error if a authorization has `!= 1` challenge
-	err = ra.checkAuthorizationsCAA(context.Background(), []string{"nochallenges.com"}, authzs, fc.Now())
+	err = ra.checkAuthorizationsCAA(context.Background(), Registration.Id, []string{"nochallenges.com"}, authzs, fc.Now())
 	test.AssertEquals(t, err.Error(), "authorization has incorrect number of challenges. 1 expected, 0 found for: id nochal")
 
 	// Should error if authorization's challenge has no validated timestamp
-	err = ra.checkAuthorizationsCAA(context.Background(), []string{"novalidationtime.com"}, authzs, fc.Now())
+	err = ra.checkAuthorizationsCAA(context.Background(), Registration.Id, []string{"novalidationtime.com"}, authzs, fc.Now())
 	test.AssertEquals(t, err.Error(), "authorization's challenge has no validated timestamp for: id noval")
 
 	// Test to make sure the authorization lifetime codepath was not used
@@ -3152,6 +3152,109 @@ func TestIssueCertificateAuditLog(t *testing.T) {
 	}
 }
 
+func TestIssueCertificateCAACheckLog(t *testing.T) {
+	_, sa, ra, fc, cleanUp := initAuthorities(t)
+	defer cleanUp()
+
+	// Set up order and authz expiries.
+	ra.orderLifetime = 24 * time.Hour
+	ra.authorizationLifetime = 15 * time.Hour
+
+	exp := fc.Now().Add(24 * time.Hour)
+	recent := fc.Now().Add(-1 * time.Hour)
+	older := fc.Now().Add(-8 * time.Hour)
+
+	// Make some valid authzs for four names. Half of them were validated
+	// recently and half were validated in excess of our CAA recheck time.
+	names := []string{"not-example.com", "www.not-example.com", "still.not-example.com", "definitely.not-example.com"}
+	var authzIDs []int64
+	for i, name := range names {
+		attemptedAt := older
+		if i%2 == 0 {
+			attemptedAt = recent
+		}
+		authzIDs = append(authzIDs, createFinalizedAuthorization(t, sa, name, exp, core.ChallengeTypeHTTP01, attemptedAt))
+	}
+
+	// Create a pending order for all of the names.
+	order, err := sa.NewOrderAndAuthzs(context.Background(), &sapb.NewOrderAndAuthzsRequest{
+		NewOrder: &sapb.NewOrderRequest{
+			RegistrationID:   Registration.Id,
+			Expires:          exp.UnixNano(),
+			Names:            names,
+			V2Authorizations: authzIDs,
+		},
+	})
+	test.AssertNotError(t, err, "Could not add test order with finalized authz IDs")
+
+	// Generate a CSR covering the order names with a random RSA key.
+	testKey, err := rsa.GenerateKey(rand.Reader, 2048)
+	test.AssertNotError(t, err, "error generating test key")
+	csr, err := x509.CreateCertificateRequest(rand.Reader, &x509.CertificateRequest{
+		PublicKey:          testKey.PublicKey,
+		SignatureAlgorithm: x509.SHA256WithRSA,
+		Subject:            pkix.Name{CommonName: "not-example.com"},
+		DNSNames:           names,
+	}, testKey)
+	test.AssertNotError(t, err, "Could not create test order CSR")
+
+	// Create a mock certificate for the fake CA to return.
+	template := &x509.Certificate{
+		SerialNumber: big.NewInt(12),
+		Subject: pkix.Name{
+			CommonName: "not-example.com",
+		},
+		DNSNames:              names,
+		NotBefore:             time.Now(),
+		NotAfter:              time.Now().AddDate(0, 0, 1),
+		BasicConstraintsValid: true,
+		ExtKeyUsage:           []x509.ExtKeyUsage{x509.ExtKeyUsageServerAuth, x509.ExtKeyUsageClientAuth},
+	}
+	cert, err := x509.CreateCertificate(rand.Reader, template, template, testKey.Public(), testKey)
+	test.AssertNotError(t, err, "Failed to create mock cert for test CA")
+
+	// Set up the RA's CA with a mock that returns the cert from above.
+	ra.CA = &mocks.MockCA{
+		PEM: pem.EncodeToMemory(&pem.Block{
+			Bytes: cert,
+		}),
+	}
+
+	// Cast the RA's mock log so we can ensure its cleared and can access the
+	// matched log lines.
+	mockLog := ra.log.(*blog.Mock)
+	mockLog.Clear()
+
+	// Finalize the order with the CSR.
+	order.Status = string(core.StatusReady)
+	_, err = ra.FinalizeOrder(context.Background(), &rapb.FinalizeOrderRequest{
+		Order: order,
+		Csr:   csr,
+	})
+	test.AssertNotError(t, err, "Error finalizing test order")
+
+	// Get the logged lines from the mock logger.
+	loglines := mockLog.GetAllMatching("FinalizationCaaCheck JSON=")
+	// There should be exactly 1 matching log line.
+	test.AssertEquals(t, len(loglines), 1)
+
+	// Strip away the stuff before 'JSON='.
+	jsonContent := strings.TrimPrefix(loglines[0], "INFO: FinalizationCaaCheck JSON=")
+
+	// Unmarshal the JSON into an event object.
+	var event finalizationCAACheckEvent
+	err = json.Unmarshal([]byte(jsonContent), &event)
+	// The JSON should unmarshal without error.
+	test.AssertNotError(t, err, "Error unmarshalling logged JSON issuance event.")
+	// The event requester should be the expected registration ID.
+	test.AssertEquals(t, event.Requester, Registration.Id)
+	// The event should have the expected number of Authzs where CAA was reused.
+	test.AssertEquals(t, event.Reused, 2)
+	// The event should have the expected number of Authzs where CAA was
+	// rechecked.
+	test.AssertEquals(t, event.Rechecked, 2)
+}
+
 // TestUpdateMissingAuthorization tests the race condition where a challenge is
 // updated to valid concurrently with another attempt to have the challenge
 // updated. Previously this would return a `berrors.InternalServer` error when