VA: Log observed CAA records. (#3726)

This is a quick first pass at audit logging the *dns.CAA records in JSON format from within the VA's IsCAAValid function. This will provide more information for post-hoc analysis of CAA decisions.

va/caa.go

@@ -1,6 +1,7 @@
 package va
 
 import (
+	"encoding/json"
 	"fmt"
 	"strings"
 	"sync"
@@ -40,12 +41,18 @@ func (va *ValidationAuthorityImpl) IsCAAValid(
 func (va *ValidationAuthorityImpl) checkCAA(
 	ctx context.Context,
 	identifier core.AcmeIdentifier) *probs.ProblemDetails {
-	present, valid, err := va.checkCAARecords(ctx, identifier)
+	present, valid, records, err := va.checkCAARecords(ctx, identifier)
 	if err != nil {
 		return probs.DNS("%v", err)
 	}
-	va.log.AuditInfof("Checked CAA records for %s, [Present: %t, Valid for issuance: %t]",
+
-		identifier.Value, present, valid)
+	recordsStr, err := json.Marshal(&records)
+	if err != nil {
+		return probs.CAA("CAA records for %s were malformed", identifier.Value)
+	}
+
+	va.log.AuditInfof("Checked CAA records for %s, [Present: %t, Valid for issuance: %t] Records=%s",
+		identifier.Value, present, valid, recordsStr)
 	if !valid {
 		return probs.CAA("CAA record for %s prevents issuance", identifier.Value)
 	}
@@ -104,17 +111,17 @@ type caaResult struct {
 	err     error
 }
 
-func parseResults(results []caaResult) (*CAASet, error) {
+func parseResults(results []caaResult) (*CAASet, []*dns.CAA, error) {
 	// Return first result
 	for _, res := range results {
 		if res.err != nil {
-			return nil, res.err
+			return nil, nil, res.err
 		}
 		if len(res.records) > 0 {
-			return newCAASet(res.records), nil
+			return newCAASet(res.records), res.records, nil
 		}
 	}
-	return nil, nil
+	return nil, nil, nil
 }
 
 func (va *ValidationAuthorityImpl) parallelCAALookup(ctx context.Context, name string) []caaResult {
@@ -135,7 +142,7 @@ func (va *ValidationAuthorityImpl) parallelCAALookup(ctx context.Context, name s
 	return results
 }
 
-func (va *ValidationAuthorityImpl) getCAASet(ctx context.Context, hostname string) (*CAASet, error) {
+func (va *ValidationAuthorityImpl) getCAASet(ctx context.Context, hostname string) (*CAASet, []*dns.CAA, error) {
 	hostname = strings.TrimRight(hostname, ".")
 
 	// See RFC 6844 "Certification Authority Processing" for pseudocode, as
@@ -155,13 +162,15 @@ func (va *ValidationAuthorityImpl) getCAASet(ctx context.Context, hostname strin
 // validates them. If the identifier argument's value has a wildcard prefix then
 // the prefix is stripped and validation will be performed against the base
 // domain, honouring any issueWild CAA records encountered as apppropriate.
-// checkCAARecords returns three values: the first is a bool indicating whether
+// checkCAARecords returns four values: the first is a bool indicating whether
-// CAA records were present. The second is a bool indicating whether issuance
+// CAA records were present after filtering for known/supported CAA tags. The
-// for the identifier is valid. Any errors encountered are returned as the third
+// second is a bool indicating whether issuance for the identifier is valid. The
-// return value (or nil).
+// unmodified *dns.CAA records that were processed/filtered are returned as the
+// third argument. Any  errors encountered are returned as the fourth return
+// value (or nil).
 func (va *ValidationAuthorityImpl) checkCAARecords(
 	ctx context.Context,
-	identifier core.AcmeIdentifier) (present, valid bool, err error) {
+	identifier core.AcmeIdentifier) (bool, bool, []*dns.CAA, error) {
 	hostname := strings.ToLower(identifier.Value)
 	// If this is a wildcard name, remove the prefix
 	var wildcard bool
@@ -169,12 +178,12 @@ func (va *ValidationAuthorityImpl) checkCAARecords(
 		hostname = strings.TrimPrefix(identifier.Value, `*.`)
 		wildcard = true
 	}
-	caaSet, err := va.getCAASet(ctx, hostname)
+	caaSet, records, err := va.getCAASet(ctx, hostname)
 	if err != nil {
-		return false, false, err
+		return false, false, nil, err
 	}
-	present, valid = va.validateCAASet(caaSet, wildcard)
+	present, valid := va.validateCAASet(caaSet, wildcard)
-	return present, valid, nil
+	return present, valid, records, nil
 }
 
 // validateCAASet checks a provided *CAASet. When the wildcard argument is true

va/caa_test.go

@@ -14,6 +14,7 @@ import (
 	"github.com/letsencrypt/boulder/probs"
 	"github.com/letsencrypt/boulder/test"
 
+	blog "github.com/letsencrypt/boulder/log"
 	vapb "github.com/letsencrypt/boulder/va/proto"
 )
 
@@ -280,8 +281,10 @@ func TestCAAChecking(t *testing.T) {
 	va, _ := setup(nil, 0)
 	va.dnsClient = caaMockDNS{}
 	for _, caaTest := range testCases {
+		mockLog := va.log.(*blog.Mock)
+		mockLog.Clear()
 		t.Run(caaTest.Name, func(t *testing.T) {
-			present, valid, err := va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: caaTest.Domain})
+			present, valid, _, err := va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: caaTest.Domain})
 			if err != nil {
 				t.Errorf("checkCAARecords error for %s: %s", caaTest.Domain, err)
 			}
@@ -294,27 +297,84 @@ func TestCAAChecking(t *testing.T) {
 		})
 	}
 
-	present, valid, err := va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.com"})
+	present, valid, _, err := va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.com"})
 	test.AssertError(t, err, "servfail.com")
 	test.Assert(t, !present, "Present should be false")
 	test.Assert(t, !valid, "Valid should be false")
 
-	_, _, err = va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.com"})
+	_, _, _, err = va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.com"})
 	if err == nil {
 		t.Errorf("Should have returned error on CAA lookup, but did not: %s", "servfail.com")
 	}
 
-	present, valid, err = va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.present.com"})
+	present, valid, _, err = va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.present.com"})
 	test.AssertError(t, err, "servfail.present.com")
 	test.Assert(t, !present, "Present should be false")
 	test.Assert(t, !valid, "Valid should be false")
 
-	_, _, err = va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.present.com"})
+	_, _, _, err = va.checkCAARecords(ctx, core.AcmeIdentifier{Type: "dns", Value: "servfail.present.com"})
 	if err == nil {
 		t.Errorf("Should have returned error on CAA lookup, but did not: %s", "servfail.present.com")
 	}
 }
 
+func TestCAALogging(t *testing.T) {
+	va, _ := setup(nil, 0)
+	va.dnsClient = caaMockDNS{}
+
+	testCases := []struct {
+		Name            string
+		Domain          string
+		ExpectedLogline string
+	}{
+		{
+			Domain:          "reserved.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for reserved.com, [Present: true, Valid for issuance: false] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":0,\"Tag\":\"issue\",\"Value\":\"ca.com\"}]",
+		},
+		{
+			Domain:          "mixedcase.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for mixedcase.com, [Present: true, Valid for issuance: false] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":0,\"Tag\":\"iSsUe\",\"Value\":\"ca.com\"}]",
+		},
+		{
+			Domain:          "critical.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for critical.com, [Present: true, Valid for issuance: false] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":1,\"Tag\":\"issue\",\"Value\":\"ca.com\"}]",
+		},
+		{
+			Domain:          "present.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for present.com, [Present: true, Valid for issuance: true] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":0,\"Tag\":\"issue\",\"Value\":\"letsencrypt.org\"}]",
+		},
+		{
+			Domain:          "multi-crit-present.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for multi-crit-present.com, [Present: true, Valid for issuance: true] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":1,\"Tag\":\"issue\",\"Value\":\"ca.com\"},{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":1,\"Tag\":\"issue\",\"Value\":\"letsencrypt.org\"}]",
+		},
+		{
+			Domain:          "present-with-parameter.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for present-with-parameter.com, [Present: true, Valid for issuance: true] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":0,\"Tag\":\"issue\",\"Value\":\"  letsencrypt.org  ;foo=bar;baz=bar\"}]",
+		},
+		{
+			Domain:          "satisfiable-wildcard-override.com",
+			ExpectedLogline: "INFO: [AUDIT] Checked CAA records for satisfiable-wildcard-override.com, [Present: true, Valid for issuance: false] Records=[{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":0,\"Tag\":\"issue\",\"Value\":\"ca.com\"},{\"Hdr\":{\"Name\":\"\",\"Rrtype\":0,\"Class\":0,\"Ttl\":0,\"Rdlength\":0},\"Flag\":0,\"Tag\":\"issuewild\",\"Value\":\"letsencrypt.org\"}]",
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.Domain, func(t *testing.T) {
+			mockLog := va.log.(*blog.Mock)
+			mockLog.Clear()
+
+			_ = va.checkCAA(ctx, core.AcmeIdentifier{Type: core.IdentifierDNS, Value: tc.Domain})
+
+			caaLogLines := mockLog.GetAllMatching(`Checked CAA records for`)
+			if len(caaLogLines) != 1 {
+				t.Errorf("checkCAARecords didn't audit log CAA record info. Instead got:\n%s\n",
+					strings.Join(mockLog.GetAllMatching(`.*`), "\n"))
+			} else {
+				test.AssertEquals(t, caaLogLines[0], tc.ExpectedLogline)
+			}
+		})
+	}
+}
+
 // TestIsCAAValidErrMessage tests that an error result from `va.IsCAAValid`
 // includes the domain name that was being checked in the failure detail.
 func TestIsCAAValidErrMessage(t *testing.T) {
@@ -355,18 +415,24 @@ func TestCAAFailure(t *testing.T) {
 
 func TestParseResults(t *testing.T) {
 	r := []caaResult{}
-	s, err := parseResults(r)
+	s, records, err := parseResults(r)
 	test.Assert(t, s == nil, "set is not nil")
 	test.Assert(t, err == nil, "error is not nil")
+	test.Assert(t, records == nil, "records is not nil")
 	test.AssertNotError(t, err, "no error should be returned")
 	r = []caaResult{{nil, errors.New("")}, {[]*dns.CAA{{Value: "test"}}, nil}}
-	s, err = parseResults(r)
+	s, records, err = parseResults(r)
 	test.Assert(t, s == nil, "set is not nil")
 	test.AssertEquals(t, err.Error(), "")
 	expected := dns.CAA{Value: "other-test"}
+	test.AssertEquals(t, len(records), 0)
 	r = []caaResult{{[]*dns.CAA{&expected}, nil}, {[]*dns.CAA{{Value: "test"}}, nil}}
-	s, err = parseResults(r)
+	s, records, err = parseResults(r)
 	test.AssertEquals(t, len(s.Unknown), 1)
 	test.Assert(t, s.Unknown[0] == &expected, "Incorrect record returned")
 	test.AssertNotError(t, err, "no error should be returned")
+	test.AssertEquals(t, len(records), len(r[0].records))
+	for i, rec := range records {
+		test.AssertEquals(t, rec.String(), r[0].records[i].String())
+	}
 }