va: log experiment results without base64 encoding (#8707)

Go's JSON marshaling encodes `[]byte` in base64. Previously, experiment
results were logging `*vapb.ValidationResult`, which contained `repeated
corepb.ValidationRecord`. In turn, `corepb.ValidationRecord` contains
three `[]byte` fields:

```proto
  repeated bytes addressesResolved = 3; // netip.Addr.MarshalText()
  bytes addressUsed = 4; // netip.Addr.MarshalText()
  repeated bytes addressesTried = 7; // netip.Addr.MarshalText()
```

By contrast, `core.ValidationRecord` (a non-protobuf struct), has fields
of type `netip.Addr`:

```go
	AddressesResolved []netip.Addr `json:"addressesResolved,omitempty"`
	AddressUsed       netip.Addr   `json:"addressUsed"`
	AddressesTried []netip.Addr `json:"addressesTried,omitempty"`
```

Those get serialized like `127.0.01`, which is what we want.

This PR reworks the `runExperiment` function so that instead of
receiving `remoteResult` (which could contain `*vapb.IsCAAValidResponse`
or `*vapb.ValidationResult`), it receives a problem and an (optional)
`core.ValidationRecord`. This allows us to more straightforwardly log
things without running into base64-encoding problems.

To test this I modified `TestExperimentalVAConcurrence` to use HTTP-01
validation, since the affected log fields don't show up under DNS-01
validation. I also tweaked `ipFakeDNS` to allow customizing the IP
address it returns.

Fixes #8701

Author: jsha

va/caa.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	corepb "github.com/letsencrypt/boulder/core/proto"
 	"net/url"
 	"regexp"
 	"strings"
@@ -105,25 +106,24 @@ func (va *ValidationAuthorityImpl) DoCAA(ctx context.Context, req *vapb.IsCAAVal
 		prob.Detail = fmt.Sprintf("While processing CAA for %s: %s", ident.Value, prob.Detail)
 	}
 
-	// Capture the local validation result for experimental resolver comparison
-	// before MPIC can influence the outcome.
-	localResult, err := bgrpc.CAAResultToPB(filterProblemDetails(prob), va.perspective, va.rir)
-	if err != nil {
-		return nil, err
-	}
-
 	if va.shouldRunExperiment() {
 		go va.runExperiment(
 			ctx,
 			opCAA,
-			proto.Clone(localResult).(*vapb.IsCAAValidResponse),
-			func(ctx context.Context) (remoteResult, error) {
-				return va.experimentalVA.DoCAA(ctx, req)
+			prob,
+			nil,
+			//nolint:unparam // core.ValidationRecord is always nil because we don't return those for CAA.
+			func(ctx context.Context) ([]core.ValidationRecord, *corepb.ProblemDetails, error) {
+				result, err := va.experimentalVA.DoCAA(ctx, req)
+				if err != nil {
+					return nil, nil, err
+				}
+				return nil, result.Problem, err
 			})
 	}
 
 	if prob != nil {
-		return localResult, nil
+		return bgrpc.CAAResultToPB(filterProblemDetails(prob), va.perspective, va.rir)
 	}
 
 	if va.isPrimaryVA() {

va/http_test.go

@@ -30,6 +30,9 @@ import (
 )
 
 type ipFakeDNS struct {
+	// If non-nil, this IP address will be returned by the appropriate method (LookupA / LookupAAAA) depending on
+	// whether it is IPv4 or IPv6. Otherwise those methods return 127.0.0.1 / ::1.
+	ip net.IP
 	bdns.Client
 }
 
@@ -46,14 +49,19 @@ func (c *ipFakeDNS) LookupA(_ context.Context, hostname string) (*bdns.Result[*d
 	if strings.HasSuffix(hostname, ".invalid") {
 		return wrapA()
 	}
+
+	ip := net.IPv4(127, 0, 0, 1)
+	if c.ip != nil && c.ip.To4() != nil {
+		ip = c.ip
+	}
 	// dual-homed host with an IPv6 and an IPv4 address
 	if hostname == "ipv4.and.ipv6.localhost" {
-		return wrapA(net.IPv4(127, 0, 0, 1))
+		return wrapA(ip)
 	}
 	if hostname == "ipv6.localhost" {
 		return wrapA()
 	}
-	return wrapA(net.IPv4(127, 0, 0, 1))
+	return wrapA(ip)
 }
 
 func (c *ipFakeDNS) LookupAAAA(_ context.Context, hostname string) (*bdns.Result[*dns.AAAA], string, error) {
@@ -65,12 +73,17 @@ func (c *ipFakeDNS) LookupAAAA(_ context.Context, hostname string) (*bdns.Result
 		return &bdns.Result[*dns.AAAA]{Final: rrs}, "ipFakeDNS", nil
 	}
 
+	ip := net.IPv6loopback
+	if c.ip != nil && c.ip.To4() == nil {
+		ip = c.ip
+	}
+
 	// dual-homed host with an IPv6 and an IPv4 address
 	if hostname == "ipv4.and.ipv6.localhost" {
-		return wrapAAAA(net.IPv6loopback)
+		return wrapAAAA(ip)
 	}
 	if hostname == "ipv6.localhost" {
-		return wrapAAAA(net.IPv6loopback)
+		return wrapAAAA(ip)
 	}
 	return wrapAAAA()
 }

va/va.go

@@ -306,14 +306,23 @@ func (va *ValidationAuthorityImpl) shouldRunExperiment() bool {
 // VA's result and records a concurrence metric. On disagreement, it logs a
 // structured event with both results. The primary argument must be non-nil.
 // Callers should invoke this in a goroutine.
-func (va *ValidationAuthorityImpl) runExperiment(ctx context.Context, operation string, primary remoteResult, experimentFunc func(context.Context) (remoteResult, error)) {
+//
+// The passed experimentFunc should return a list of validation records (or nil in the case of CAA),
+// followed by any ProblemDetails relevant (which will be nil on success), and any errors in validation.
+func (va *ValidationAuthorityImpl) runExperiment(
+	ctx context.Context,
+	operation string,
+	primaryProblem *probs.ProblemDetails,
+	primaryValidationRecords []core.ValidationRecord,
+	experimentFunc func(context.Context) ([]core.ValidationRecord, *corepb.ProblemDetails, error),
+) {
 	ctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), va.experimentalVATimeout)
 	defer cancel()
 
-	experimentResult, err := experimentFunc(ctx)
+	experimentValidationRecords, experimentProblem, err := experimentFunc(ctx)
 
-	primaryPassed := primary.GetProblem() == nil
-	experimentPassed := (err == nil) && (experimentResult.GetProblem() == nil)
+	primaryPassed := primaryProblem == nil
+	experimentPassed := err == nil && experimentProblem == nil
 
 	if primaryPassed == experimentPassed {
 		va.metrics.experimentConcurrence.WithLabelValues(operation, "true").Inc()
@@ -322,11 +331,11 @@ func (va *ValidationAuthorityImpl) runExperiment(ctx context.Context, operation
 	va.metrics.experimentConcurrence.WithLabelValues(operation, "false").Inc()
 
 	logArgs := map[string]any{
-		"operation":        operation,
-		"primaryPassed":    primaryPassed,
-		"primaryResult":    primary,
-		"experimentPassed": experimentPassed,
-		"experimentResult": experimentResult,
+		"operation":                   operation,
+		"primaryProblem":              primaryProblem,
+		"primaryValidationRecords":    primaryValidationRecords,
+		"experimentProblem":           experimentProblem,
+		"experimentValidationRecords": experimentValidationRecords,
 	}
 	if err != nil {
 		logArgs["experimentErr"] = err.Error()
@@ -835,9 +844,22 @@ func (va *ValidationAuthorityImpl) DoDCV(ctx context.Context, req *vapb.PerformV
 		go va.runExperiment(
 			ctx,
 			opDCV,
-			proto.Clone(localResult).(*vapb.ValidationResult),
-			func(ctx context.Context) (remoteResult, error) {
-				return va.experimentalVA.DoDCV(ctx, req)
+			prob,
+			records,
+			func(ctx context.Context) ([]core.ValidationRecord, *corepb.ProblemDetails, error) {
+				result, err := va.experimentalVA.DoDCV(ctx, req)
+				if err != nil {
+					return nil, nil, err
+				}
+				var loggableRecords []core.ValidationRecord
+				for _, record := range result.Records {
+					converted, err := bgrpc.PBToValidationRecord(record)
+					if err != nil {
+						return nil, nil, err
+					}
+					loggableRecords = append(loggableRecords, converted)
+				}
+				return loggableRecords, result.Problem, nil
 			})
 	}
 

va/va_test.go

@@ -394,46 +394,41 @@ func TestValidateMalformedChallenge(t *testing.T) {
 	test.AssertEquals(t, prob.Type, probs.MalformedProblem)
 }
 
-func setupWithExperimental(experimentalDNS bdns.Client) (*ValidationAuthorityImpl, *blog.Mock) {
-	va, mockLog := setup(nil, "", nil, &txtFakeDNS{})
-	expVA, _ := setup(nil, "", nil, experimentalDNS)
-	expVA.perspective = "Experimental"
-	va.experimentalVA = expVA
-	va.experimentalVASampleRate = 1.0
-	return va, mockLog
-}
-
 func TestExperimentalVAConcurrence(t *testing.T) {
-	t.Parallel()
+	testSrvIPv4 := httpSrv(t, expectedToken, false)
+	t.Cleanup(testSrvIPv4.Close)
 
 	tests := []struct {
 		name            string
+		primaryDNS      bdns.Client
 		experimentalDNS bdns.Client
-		domain          string
 		primaryProblem  bool
 		expectConcur    float64
 		expectDisagree  float64
 		expectLog       string
 	}{
 		{
 			name:            "both pass",
-			experimentalDNS: &txtFakeDNS{},
-			domain:          "good-dns01.com",
+			primaryDNS:      &ipFakeDNS{},
+			experimentalDNS: &ipFakeDNS{},
 			expectConcur:    1,
 			expectDisagree:  0,
 		},
 		{
 			name:            "primary passes experimental fails",
-			experimentalDNS: &bdns.MockClient{},
-			domain:          "good-dns01.com",
+			primaryDNS:      &ipFakeDNS{},
+			experimentalDNS: &ipFakeDNS{ip: net.IPv4(127, 0, 0, 99)},
 			expectConcur:    0,
 			expectDisagree:  1,
-			expectLog:       "Primary VA disagreed with experimental VA",
+			// The addressesResolved and addressUsed fields are checked here to make sure they are not accidentally
+			// base64-encoded (which can happen if we log the protobuf `corepb.ValidationRecord` instead of the nicely
+			// JSON-serializable struct `core.ValidationRecord`)
+			expectLog: `Primary VA disagreed with experimental VA.*"addressesResolved":\["127.0.0.1"\],"addressUsed":"127.0.0.1"`,
 		},
 		{
 			name:            "both fail",
-			experimentalDNS: &bdns.MockClient{},
-			domain:          "servfail.com",
+			primaryDNS:      &ipFakeDNS{ip: net.IPv4(127, 0, 0, 99)},
+			experimentalDNS: &ipFakeDNS{ip: net.IPv4(127, 0, 0, 99)},
 			primaryProblem:  true,
 			expectConcur:    1,
 			expectDisagree:  0,
@@ -442,15 +437,24 @@ func TestExperimentalVAConcurrence(t *testing.T) {
 
 	for _, tc := range tests {
 		t.Run(tc.name, func(t *testing.T) {
-			t.Parallel()
-			va, mockLog := setupWithExperimental(tc.experimentalDNS)
-			req := createValidationRequest(identifier.NewDNS(tc.domain), core.ChallengeTypeDNS01)
-			res, err := va.DoDCV(context.Background(), req)
+			va, mockLog := setup(testSrvIPv4, "", nil, tc.primaryDNS)
+			expVA, _ := setup(testSrvIPv4, "", nil, tc.experimentalDNS)
+			expVA.perspective = "Experimental"
+			va.experimentalVA = expVA
+			va.experimentalVASampleRate = 1.0
+			va.experimentalVATimeout = 10 * time.Second
+
+			ident := identifier.NewDNS("experiment.example.com")
+			req := createValidationRequest(ident, core.ChallengeTypeHTTP01)
+			ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+			defer cancel()
+
+			res, err := va.DoDCV(ctx, req)
 			test.AssertNotError(t, err, "DoDCV failed")
-			if tc.primaryProblem {
-				test.Assert(t, res.Problem != nil, "expected a problem")
-			} else {
-				test.Assert(t, res.Problem == nil, "expected no problem")
+			if tc.primaryProblem && res.Problem == nil {
+				t.Errorf("for primary validation, got: nil Problem, want: any non-nil Problem")
+			} else if !tc.primaryProblem && res.Problem != nil {
+				t.Errorf("for primary validation, got: %q, want: nil Problem", res.Problem)
 			}
 
 			time.Sleep(100 * time.Millisecond)
@@ -465,7 +469,10 @@ func TestExperimentalVAConcurrence(t *testing.T) {
 			}, tc.expectDisagree)
 
 			if tc.expectLog != "" {
-				test.AssertEquals(t, len(mockLog.GetAllMatching(tc.expectLog)), 1)
+				err := mockLog.ExpectMatch(tc.expectLog)
+				if err != nil {
+					t.Error(err)
+				}
 			}
 		})
 	}