From 595a9511edd083d82c97699faca1af02700a8776 Mon Sep 17 00:00:00 2001 From: Samantha Date: Fri, 10 Feb 2023 11:23:16 -0500 Subject: [PATCH] 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 | 12 ++++++ ra/ra.go | 35 ++++++++++++++-- ra/ra_test.go | 111 ++++++++++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 151 insertions(+), 7 deletions(-) diff --git a/log/log.go b/log/log.go index dae33eff4..08f75cf2c 100644 --- a/log/log.go +++ b/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) diff --git a/ra/ra.go b/ra/ra.go index f464cab85..b55bcd92b 100644 --- a/ra/ra.go +++ b/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 } diff --git a/ra/ra_test.go b/ra/ra_test.go index df65c49eb..7db679450 100644 --- a/ra/ra_test.go +++ b/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