From 3df93d223047da8ac9c3a0273b996259ac093c09 Mon Sep 17 00:00:00 2001 From: Daniel McCarney Date: Fri, 18 May 2018 18:28:45 -0400 Subject: [PATCH] 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 | 43 +++++++++++++++----------- va/caa_test.go | 82 +++++++++++++++++++++++++++++++++++++++++++++----- 2 files changed, 100 insertions(+), 25 deletions(-) diff --git a/va/caa.go b/va/caa.go index 0b605f762..c0c483651 100644 --- a/va/caa.go +++ b/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 -// CAA records were present. The second is a bool indicating whether issuance -// for the identifier is valid. Any errors encountered are returned as the third -// return value (or nil). +// checkCAARecords returns four values: the first is a bool indicating whether +// CAA records were present after filtering for known/supported CAA tags. The +// second is a bool indicating whether issuance for the identifier is valid. The +// 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) - return present, valid, nil + present, valid := va.validateCAASet(caaSet, wildcard) + return present, valid, records, nil } // validateCAASet checks a provided *CAASet. When the wildcard argument is true diff --git a/va/caa_test.go b/va/caa_test.go index f41130987..8a4f23c56 100644 --- a/va/caa_test.go +++ b/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()) + } }