From 7fa3d8b5389f965825625a88143443bebe71e6b6 Mon Sep 17 00:00:00 2001 From: Samantha Date: Tue, 26 Nov 2024 13:43:32 -0500 Subject: [PATCH] VA: Use performValidation for IsCAAValid remote checks --- features/features.go | 9 +- test/config-next/va.json | 1 - va/caa.go | 183 ++++----------------------------------- va/caa_test.go | 69 +++++++-------- va/va.go | 56 +++++------- va/va_test.go | 47 +++++----- 6 files changed, 98 insertions(+), 267 deletions(-) diff --git a/features/features.go b/features/features.go index 36ca9db76e1..36f375a06f6 100644 --- a/features/features.go +++ b/features/features.go @@ -47,16 +47,9 @@ type Config struct { // EnforceMultiCAA causes the VA to kick off remote CAA rechecks when true. // When false, no remote CAA rechecks will be performed. The primary VA will - // make a valid/invalid decision with the results. The primary VA will - // return an early decision if MultiCAAFullResults is false. + // make a valid/invalid decision with the results. EnforceMultiCAA bool - // MultiCAAFullResults will cause the main VA to block and wait for all of - // the remote VA CAA recheck results instead of returning early if the - // number of failures is greater than the number allowed by MPIC. - // Only used when EnforceMultiCAA is true. - MultiCAAFullResults bool - // MultipleCertificateProfiles, when enabled, triggers the following // behavior: // - SA.NewOrderAndAuthzs: upon receiving a NewOrderRequest with a diff --git a/test/config-next/va.json b/test/config-next/va.json index cb43965c702..514317f2a91 100644 --- a/test/config-next/va.json +++ b/test/config-next/va.json @@ -39,7 +39,6 @@ }, "features": { "EnforceMultiCAA": true, - "MultiCAAFullResults": true, "DOH": true }, "remoteVAs": [ diff --git a/va/caa.go b/va/caa.go index 7d29b06cfb1..eec7913d4ac 100644 --- a/va/caa.go +++ b/va/caa.go @@ -3,7 +3,6 @@ package va import ( "context" "fmt" - "math/rand/v2" "net/url" "regexp" "strings" @@ -11,13 +10,13 @@ import ( "time" "github.com/miekg/dns" + "google.golang.org/protobuf/proto" "github.com/letsencrypt/boulder/bdns" "github.com/letsencrypt/boulder/core" corepb "github.com/letsencrypt/boulder/core/proto" berrors "github.com/letsencrypt/boulder/errors" "github.com/letsencrypt/boulder/features" - bgrpc "github.com/letsencrypt/boulder/grpc" "github.com/letsencrypt/boulder/identifier" "github.com/letsencrypt/boulder/probs" vapb "github.com/letsencrypt/boulder/va/proto" @@ -80,14 +79,6 @@ func (va *ValidationAuthorityImpl) IsCAAValid(ctx context.Context, req *vapb.IsC va.log.AuditObject("CAA check result", logEvent) }() - var remoteCAAResults chan *remoteVAResult - if features.Get().EnforceMultiCAA { - if remoteVACount := len(va.remoteVAs); remoteVACount > 0 { - remoteCAAResults = make(chan *remoteVAResult, remoteVACount) - go va.performRemoteCAACheck(ctx, req, remoteCAAResults) - } - } - internalErr = va.checkCAA(ctx, acmeID, params) // Stop the clock for local check latency. @@ -97,31 +88,23 @@ func (va *ValidationAuthorityImpl) IsCAAValid(ctx context.Context, req *vapb.IsC logEvent.InternalError = internalErr.Error() prob = detailedError(internalErr) prob.Detail = fmt.Sprintf("While processing CAA for %s: %s", req.Domain, prob.Detail) - } else if remoteCAAResults != nil { - if !features.Get().EnforceMultiCAA && features.Get().MultiCAAFullResults { - // If we're not going to enforce multi CAA but we are logging the - // differentials then collect and log the remote results in a separate go - // routine to avoid blocking the primary VA. - go func() { - _ = va.processRemoteCAAResults( - req.Domain, - req.AccountURIID, - string(challType), - remoteCAAResults) - }() - } else if features.Get().EnforceMultiCAA { - remoteProb := va.processRemoteCAAResults( - req.Domain, - req.AccountURIID, - string(challType), - remoteCAAResults) - - // If the remote result was a non-nil problem then fail the CAA check - if remoteProb != nil { - prob = remoteProb - va.log.Infof("CAA check failed due to remote failures: identifier=%v err=%s", - req.Domain, remoteProb) + } + + if features.Get().EnforceMultiCAA { + op := func(ctx context.Context, remoteva RemoteVA, req proto.Message) (remoteResult, error) { + checkRequest, ok := req.(*vapb.IsCAAValidRequest) + if !ok { + return nil, fmt.Errorf("got type %T, want *vapb.IsCAAValidRequest", req) } + result, err := remoteva.IsCAAValid(ctx, checkRequest) + return result, err + } + remoteProb := va.performRemoteValidation(ctx, op, req) + // If the remote result was a non-nil problem then fail the CAA check + if remoteProb != nil { + prob = remoteProb + va.log.Infof("CAA check failed due to remote failures: identifier=%v err=%s", + req.Domain, remoteProb) } } @@ -139,138 +122,6 @@ func (va *ValidationAuthorityImpl) IsCAAValid(ctx context.Context, req *vapb.IsC } } -// processRemoteCAAResults evaluates a primary VA result, and a channel of -// remote VA problems to produce a single overall validation result based on -// configured feature flags. The overall result is calculated based on the VA's -// configured `maxRemoteFailures` value. -// -// If the `MultiCAAFullResults` feature is enabled then -// `processRemoteCAAResults` will expect to read a result from the -// `remoteResultsChan` channel for each VA and will not produce an overall -// result until all remote VAs have responded. In this case -// `logRemoteDifferentials` will also be called to describe the differential -// between the primary and all of the remote VAs. -// -// If the `MultiCAAFullResults` feature flag is not enabled then -// `processRemoteCAAResults` will potentially return before all remote VAs have -// had a chance to respond. This happens if the success or failure threshold is -// met. This doesn't allow for logging the differential between the primary and -// remote VAs but is more performant. -func (va *ValidationAuthorityImpl) processRemoteCAAResults( - domain string, - acctID int64, - challengeType string, - remoteResultsChan <-chan *remoteVAResult) *probs.ProblemDetails { - - required := len(va.remoteVAs) - va.maxRemoteFailures - good := 0 - bad := 0 - - var remoteResults []*remoteVAResult - var firstProb *probs.ProblemDetails - // Due to channel behavior this could block indefinitely and we rely on gRPC - // honoring the context deadline used in client calls to prevent that from - // happening. - for result := range remoteResultsChan { - // Add the result to the slice - remoteResults = append(remoteResults, result) - if result.Problem == nil { - good++ - } else { - bad++ - // Store the first non-nil problem to return later (if `MultiCAAFullResults` - // is enabled). - if firstProb == nil { - firstProb = result.Problem - } - } - - // If MultiCAAFullResults isn't enabled then return early whenever the - // success or failure threshold is met. - if !features.Get().MultiCAAFullResults { - if good >= required { - return nil - } else if bad > va.maxRemoteFailures { - modifiedProblem := *result.Problem - modifiedProblem.Detail = "During secondary CAA checking: " + firstProb.Detail - return &modifiedProblem - } - } - - // If we haven't returned early because of MultiCAAFullResults being - // enabled we need to break the loop once all of the VAs have returned a - // result. - if len(remoteResults) == len(va.remoteVAs) { - break - } - } - // If we are using `features.MultiCAAFullResults` then we haven't returned - // early and can now log the differential between what the primary VA saw and - // what all of the remote VAs saw. - va.logRemoteResults( - domain, - acctID, - challengeType, - remoteResults) - - // Based on the threshold of good/bad return nil or a problem. - if good >= required { - return nil - } else if bad > va.maxRemoteFailures { - modifiedProblem := *firstProb - modifiedProblem.Detail = "During secondary CAA checking: " + firstProb.Detail - va.metrics.prospectiveRemoteCAACheckFailures.Inc() - return &modifiedProblem - } - - // This condition should not occur - it indicates the good/bad counts didn't - // meet either the required threshold or the maxRemoteFailures threshold. - return probs.ServerInternal("Too few remote IsCAAValid RPC results") -} - -// performRemoteCAACheck calls `isCAAValid` for each of the configured remoteVAs -// in a random order. The provided `results` chan should have an equal size to -// the number of remote VAs. The CAA checks will be performed in separate -// go-routines. If the result `error` from a remote `isCAAValid` RPC is nil or a -// nil `ProblemDetails` instance it is written directly to the `results` chan. -// If the err is a canceled error it is treated as a nil error. Otherwise the -// error/problem is written to the results channel as-is. -func (va *ValidationAuthorityImpl) performRemoteCAACheck( - ctx context.Context, - req *vapb.IsCAAValidRequest, - results chan<- *remoteVAResult) { - for _, i := range rand.Perm(len(va.remoteVAs)) { - remoteVA := va.remoteVAs[i] - go func(rva RemoteVA) { - result := &remoteVAResult{ - VAHostname: rva.Address, - } - res, err := rva.IsCAAValid(ctx, req) - if err != nil { - if core.IsCanceled(err) { - // Handle the cancellation error. - result.Problem = probs.ServerInternal("Remote VA IsCAAValid RPC canceled") - } else { - // Handle validation error. - va.log.Errf("Remote VA %q.IsCAAValid failed: %s", rva.Address, err) - result.Problem = probs.ServerInternal("Remote VA IsCAAValid RPC failed") - } - } else if res.Problem != nil { - prob, err := bgrpc.PBToProblemDetails(res.Problem) - if err != nil { - va.log.Infof("Remote VA %q.IsCAAValid returned malformed problem: %s", rva.Address, err) - result.Problem = probs.ServerInternal( - fmt.Sprintf("Remote VA IsCAAValid RPC returned malformed result: %s", err)) - } else { - va.log.Infof("Remote VA %q.IsCAAValid returned problem: %s", rva.Address, prob) - result.Problem = prob - } - } - results <- result - }(remoteVA) - } -} - // checkCAA performs a CAA lookup & validation for the provided identifier. If // the CAA lookup & validation fail a problem is returned. func (va *ValidationAuthorityImpl) checkCAA( diff --git a/va/caa_test.go b/va/caa_test.go index 3a9c091a487..9d7d0189159 100644 --- a/va/caa_test.go +++ b/va/caa_test.go @@ -594,8 +594,7 @@ func TestDisabledMultiCAARechecking(t *testing.T) { va, _ := setupWithRemotes(nil, "local", remoteVAs, nil) features.Set(features.Config{ - EnforceMultiCAA: false, - MultiCAAFullResults: false, + EnforceMultiCAA: false, }) defer features.Reset() @@ -714,7 +713,7 @@ func TestMultiCAARechecking(t *testing.T) { name: "functional localVA, 1 broken RVA, no CAA records", domains: "present-dns-only.com", localDNSClient: caaMockDNS{}, - expectedDiffLogSubstring: `RemoteSuccesses":2,"RemoteFailures":[{"VAHostname":"broken","Problem":{"type":"dns","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":2,"RemoteFailures":1`, remoteVAs: []remoteConf{ {ua: brokenUA, rir: arin, dns: caaBrokenDNS{}}, {ua: remoteUA, rir: ripe}, @@ -731,9 +730,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "functional localVA, 2 broken RVA, no CAA records", domains: "present-dns-only.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.DNSProblem, - expectedDiffLogSubstring: `RemoteSuccesses":1,"RemoteFailures":[{"VAHostname":"broken","Problem":{"type":"dns","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":1,"RemoteFailures":2`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: brokenUA, rir: arin, dns: caaBrokenDNS{}}, @@ -751,9 +750,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "functional localVA, all broken RVAs, no CAA records", domains: "present-dns-only.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.DNSProblem, - expectedDiffLogSubstring: `RemoteSuccesses":0,"RemoteFailures":[{"VAHostname":"broken","Problem":{"type":"dns","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":0,"RemoteFailures":3`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: brokenUA, rir: arin, dns: caaBrokenDNS{}}, @@ -788,7 +787,7 @@ func TestMultiCAARechecking(t *testing.T) { { name: "functional localVA, 1 broken RVA, CAA issue type present", domains: "present.com", - expectedDiffLogSubstring: `RemoteSuccesses":2,"RemoteFailures":[{"VAHostname":"broken","Problem":{"type":"dns","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":2,"RemoteFailures":1`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: brokenUA, rir: arin, dns: caaBrokenDNS{}}, @@ -806,9 +805,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "functional localVA, 2 broken RVA, CAA issue type present", domains: "present.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.DNSProblem, - expectedDiffLogSubstring: `RemoteSuccesses":1,"RemoteFailures":[{"VAHostname":"broken","Problem":{"type":"dns","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":1,"RemoteFailures":2`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: brokenUA, rir: arin, dns: caaBrokenDNS{}}, @@ -826,9 +825,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "functional localVA, all broken RVAs, CAA issue type present", domains: "present.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.DNSProblem, - expectedDiffLogSubstring: `RemoteSuccesses":0,"RemoteFailures":[{"VAHostname":"broken","Problem":{"type":"dns","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":0,"RemoteFailures":3`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: brokenUA, rir: arin, dns: caaBrokenDNS{}}, @@ -844,9 +843,8 @@ func TestMultiCAARechecking(t *testing.T) { }, }, { - // The localVA kicks off the background goroutines before doing its - // own check. But if its own check fails, it doesn't wait for their - // results. + // The localVA returns early with a problem before kicking off the + // remote checks. name: "all VAs functional, CAA issue type forbids issuance", domains: "unsatisfiable.com", expectedProbSubstring: "CAA record for unsatisfiable.com prevents issuance", @@ -861,7 +859,7 @@ func TestMultiCAARechecking(t *testing.T) { { name: "1 hijacked RVA, CAA issue type present", domains: "present.com", - expectedDiffLogSubstring: `RemoteSuccesses":2,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":2,"RemoteFailures":1`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -872,9 +870,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "2 hijacked RVAs, CAA issue type present", domains: "present.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.CAAProblem, - expectedDiffLogSubstring: `RemoteSuccesses":1,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":1,"RemoteFailures":2`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -885,9 +883,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "3 hijacked RVAs, CAA issue type present", domains: "present.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.CAAProblem, - expectedDiffLogSubstring: `RemoteSuccesses":0,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":0,"RemoteFailures":3`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -898,7 +896,7 @@ func TestMultiCAARechecking(t *testing.T) { { name: "1 hijacked RVA, CAA issuewild type present", domains: "satisfiable-wildcard.com", - expectedDiffLogSubstring: `RemoteSuccesses":2,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":2,"RemoteFailures":1`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -909,9 +907,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "2 hijacked RVAs, CAA issuewild type present", domains: "satisfiable-wildcard.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.CAAProblem, - expectedDiffLogSubstring: `RemoteSuccesses":1,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":1,"RemoteFailures":2`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -922,9 +920,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "3 hijacked RVAs, CAA issuewild type present", domains: "satisfiable-wildcard.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.CAAProblem, - expectedDiffLogSubstring: `RemoteSuccesses":0,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":0,"RemoteFailures":3`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -935,7 +933,7 @@ func TestMultiCAARechecking(t *testing.T) { { name: "1 hijacked RVA, CAA issuewild type present, 1 failure allowed", domains: "satisfiable-wildcard.com", - expectedDiffLogSubstring: `RemoteSuccesses":2,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":2,"RemoteFailures":1`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -946,9 +944,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "2 hijacked RVAs, CAA issuewild type present, 1 failure allowed", domains: "satisfiable-wildcard.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.CAAProblem, - expectedDiffLogSubstring: `RemoteSuccesses":1,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":1,"RemoteFailures":2`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -959,9 +957,9 @@ func TestMultiCAARechecking(t *testing.T) { { name: "3 hijacked RVAs, CAA issuewild type present, 1 failure allowed", domains: "satisfiable-wildcard.com", - expectedProbSubstring: "During secondary CAA checking: While processing CAA", + expectedProbSubstring: "During secondary validation: While processing CAA", expectedProbType: probs.CAAProblem, - expectedDiffLogSubstring: `RemoteSuccesses":0,"RemoteFailures":[{"VAHostname":"hijacked","Problem":{"type":"caa","detail":"While processing CAA for`, + expectedDiffLogSubstring: `"RemoteSuccesses":0,"RemoteFailures":3`, localDNSClient: caaMockDNS{}, remoteVAs: []remoteConf{ {ua: hijackedUA, rir: arin, dns: caaHijackedDNS{}}, @@ -976,13 +974,8 @@ func TestMultiCAARechecking(t *testing.T) { va, mockLog := setupWithRemotes(nil, localUA, tc.remoteVAs, tc.localDNSClient) defer mockLog.Clear() - // MultiCAAFullResults: false is inherently flaky because of the - // non-deterministic nature of concurrent goroutine returns. We, - // boulder dev, made a decision to skip testing that path and - // eventually make MultiCAAFullResults: true the default. features.Set(features.Config{ - EnforceMultiCAA: true, - MultiCAAFullResults: true, + EnforceMultiCAA: true, }) defer features.Reset() @@ -1012,11 +1005,11 @@ func TestMultiCAARechecking(t *testing.T) { } } - gotRequestProbs := mockLog.GetAllMatching(".IsCAAValid returned problem: ") + gotRequestProbs := mockLog.GetAllMatching(" returned a problem: ") test.AssertEquals(t, len(gotRequestProbs), invalidRVACount) gotDifferential := mockLog.GetAllMatching("remoteVADifferentials JSON=.*") - if features.Get().MultiCAAFullResults && tc.expectedDiffLogSubstring != "" { + if tc.expectedDiffLogSubstring != "" { test.AssertEquals(t, len(gotDifferential), 1) test.AssertContains(t, gotDifferential[0], tc.expectedDiffLogSubstring) } else { diff --git a/va/va.go b/va/va.go index 41817dbe1d6..35d1b49513c 100644 --- a/va/va.go +++ b/va/va.go @@ -472,12 +472,13 @@ var _ remoteResult = (*vapb.IsCAAValidResponse)(nil) func (va *ValidationAuthorityImpl) performRemoteValidation( ctx context.Context, op remoteOperation, - req *vapb.PerformValidationRequest, + req proto.Message, ) *probs.ProblemDetails { remoteVACount := len(va.remoteVAs) if remoteVACount == 0 { return nil } + isCAAValidReq, isCAACheck := req.(*vapb.IsCAAValidRequest) type response struct { addr string @@ -526,6 +527,10 @@ func (va *ValidationAuthorityImpl) performRemoteValidation( va.log.Errf("Operation on Remote VA (%s) returned malformed problem: %s", resp.addr, err) currProb = probs.ServerInternal("Secondary validation RPC returned malformed result") } + if isCAACheck { + // We're checking CAA, log the problem. + va.log.Errf("Operation on Remote VA (%s) returned a problem: %s", resp.addr, err) + } } else { // The remote VA returned a successful result. passed = append(passed, resp.perspective) @@ -552,6 +557,11 @@ func (va *ValidationAuthorityImpl) performRemoteValidation( } } + if isCAACheck { + // We're checking CAA, log the results. + va.logRemoteResults(isCAAValidReq, len(passed), len(failed)) + } + if len(passed) >= required { return nil } else if len(failed) > va.maxRemoteFailures { @@ -564,25 +574,10 @@ func (va *ValidationAuthorityImpl) performRemoteValidation( } } -// logRemoteResults is called by `processRemoteCAAResults` when the -// `MultiCAAFullResults` feature flag is enabled. It produces a JSON log line -// that contains the results each remote VA returned. -func (va *ValidationAuthorityImpl) logRemoteResults( - domain string, - acctID int64, - challengeType string, - remoteResults []*remoteVAResult) { - - var successes, failures []*remoteVAResult - - for _, result := range remoteResults { - if result.Problem != nil { - failures = append(failures, result) - } else { - successes = append(successes, result) - } - } - if len(failures) == 0 { +// logRemoteResults is called by performRemoteValidation when the request passed +// is *vapb.IsCAAValidRequest. +func (va *ValidationAuthorityImpl) logRemoteResults(req *vapb.IsCAAValidRequest, passed int, failed int) { + if failed == 0 { // There's no point logging a differential line if everything succeeded. return } @@ -592,13 +587,13 @@ func (va *ValidationAuthorityImpl) logRemoteResults( AccountID int64 ChallengeType string RemoteSuccesses int - RemoteFailures []*remoteVAResult + RemoteFailures int }{ - Domain: domain, - AccountID: acctID, - ChallengeType: challengeType, - RemoteSuccesses: len(successes), - RemoteFailures: failures, + Domain: req.Domain, + AccountID: req.AccountURIID, + ChallengeType: req.ValidationMethod, + RemoteSuccesses: passed, + RemoteFailures: failed, } logJSON, err := json.Marshal(logOb) @@ -614,13 +609,6 @@ func (va *ValidationAuthorityImpl) logRemoteResults( va.log.Infof("remoteVADifferentials JSON=%s", string(logJSON)) } -// remoteVAResult is a struct that combines a problem details instance (that may -// be nil) with the remote VA hostname that produced it. -type remoteVAResult struct { - VAHostname string - Problem *probs.ProblemDetails -} - // performLocalValidation performs primary domain control validation and then // checks CAA. If either step fails, it immediately returns a bare error so // that our audit logging can include the underlying error. @@ -711,7 +699,7 @@ func (va *ValidationAuthorityImpl) PerformValidation(ctx context.Context, req *v } // Log the total validation latency. - logEvent.Latency = time.Since(start).Round(time.Millisecond).Seconds() + logEvent.Latency = va.clk.Since(start).Round(time.Millisecond).Seconds() va.log.AuditObject("Validation result", logEvent) }() diff --git a/va/va_test.go b/va/va_test.go index febdd7c0419..23c5b9d85c3 100644 --- a/va/va_test.go +++ b/va/va_test.go @@ -831,45 +831,53 @@ func TestDetailedError(t *testing.T) { } func TestLogRemoteDifferentials(t *testing.T) { + t.Parallel() + remoteConfs := []remoteConf{ {ua: pass, rir: arin}, {ua: pass, rir: ripe}, {ua: pass, rir: apnic}, } - egProbA := probs.DNS("root DNS servers closed at 4:30pm") - egProbB := probs.OrderNotReady("please take a number") - testCases := []struct { name string - remoteProbs []*remoteVAResult + req *vapb.IsCAAValidRequest + passed int + failed int expectedLog string }{ { name: "all results equal (nil)", - remoteProbs: []*remoteVAResult{ - {Problem: nil, VAHostname: "remoteA"}, - {Problem: nil, VAHostname: "remoteB"}, - {Problem: nil, VAHostname: "remoteC"}, + req: &vapb.IsCAAValidRequest{ + Domain: "example.com", + AccountURIID: 1999, + ValidationMethod: "blorpus-01", }, + passed: 0, + failed: 3, + expectedLog: `INFO: remoteVADifferentials JSON={"Domain":"example.com","AccountID":1999,"ChallengeType":"blorpus-01","RemoteSuccesses":0,"RemoteFailures":3}`, }, { name: "all results equal (not nil)", - remoteProbs: []*remoteVAResult{ - {Problem: egProbA, VAHostname: "remoteA"}, - {Problem: egProbA, VAHostname: "remoteB"}, - {Problem: egProbA, VAHostname: "remoteC"}, + req: &vapb.IsCAAValidRequest{ + Domain: "example.com", + AccountURIID: 1999, + ValidationMethod: "blorpus-01", }, - expectedLog: `INFO: remoteVADifferentials JSON={"Domain":"example.com","AccountID":1999,"ChallengeType":"blorpus-01","RemoteSuccesses":0,"RemoteFailures":[{"VAHostname":"remoteA","Problem":{"type":"dns","detail":"root DNS servers closed at 4:30pm","status":400}},{"VAHostname":"remoteB","Problem":{"type":"dns","detail":"root DNS servers closed at 4:30pm","status":400}},{"VAHostname":"remoteC","Problem":{"type":"dns","detail":"root DNS servers closed at 4:30pm","status":400}}]}`, + passed: 0, + failed: 3, + expectedLog: `INFO: remoteVADifferentials JSON={"Domain":"example.com","AccountID":1999,"ChallengeType":"blorpus-01","RemoteSuccesses":0,"RemoteFailures":3}`, }, { name: "differing results, some non-nil", - remoteProbs: []*remoteVAResult{ - {Problem: nil, VAHostname: "remoteA"}, - {Problem: egProbB, VAHostname: "remoteB"}, - {Problem: nil, VAHostname: "remoteC"}, + req: &vapb.IsCAAValidRequest{ + Domain: "example.com", + AccountURIID: 1999, + ValidationMethod: "blorpus-01", }, - expectedLog: `INFO: remoteVADifferentials JSON={"Domain":"example.com","AccountID":1999,"ChallengeType":"blorpus-01","RemoteSuccesses":2,"RemoteFailures":[{"VAHostname":"remoteB","Problem":{"type":"orderNotReady","detail":"please take a number","status":403}}]}`, + passed: 2, + failed: 1, + expectedLog: `INFO: remoteVADifferentials JSON={"Domain":"example.com","AccountID":1999,"ChallengeType":"blorpus-01","RemoteSuccesses":2,"RemoteFailures":1}`, }, } @@ -883,8 +891,7 @@ func TestLogRemoteDifferentials(t *testing.T) { localVA, mockLog := setupWithRemotes(ms.Server, pass, remoteConfs, nil) - localVA.logRemoteResults( - "example.com", 1999, "blorpus-01", tc.remoteProbs) + localVA.logRemoteResults(tc.req, tc.passed, tc.failed) lines := mockLog.GetAllMatching("remoteVADifferentials JSON=.*") if tc.expectedLog != "" {