VA: log internal DNS errors. (#4520)

When we get a DNS error that has an internal cause (like connection
refused), we return a generic message like "networking error" to the
user to avoid revealing details that would be confusing. However, when
debugging problems with our own services, it's useful to have the
underlying errors.

This adds a helper method in the VA and calls it from each place we use
DNS errors.

bdns/mocks.go

@@ -74,6 +74,8 @@ func (mock *MockDNSClient) LookupHost(_ context.Context, hostname string) ([]net
 	}
 	if hostname == "always.error" {
 		return []net.IP{}, &DNSError{dns.TypeA, "always.error", &net.OpError{
+			Op:  "read",
+			Net: "udp",
 			Err: errors.New("some net error"),
 		}, -1}
 	}

bdns/problem.go

@@ -17,6 +17,10 @@ type DNSError struct {
 	rCode      int
 }
 
+func (d DNSError) Underlying() error {
+	return d.underlying
+}
+
 func (d DNSError) Error() string {
 	var detail string
 	if d.underlying != nil {

va/caa.go

@@ -149,6 +149,9 @@ func (va *ValidationAuthorityImpl) parallelCAALookup(ctx context.Context, name s
 		wg.Add(1)
 		go func(name string, r *caaResult) {
 			r.records, r.err = va.dnsClient.LookupCAA(ctx, name)
+			if r.err != nil {
+				va.logDNSError(name, r.err)
+			}
 			wg.Done()
 		}(strings.Join(labels[i:], "."), &results[i])
 	}

va/dns.go

@@ -8,6 +8,7 @@ import (
 	"fmt"
 	"net"
 
+	"github.com/letsencrypt/boulder/bdns"
 	"github.com/letsencrypt/boulder/core"
 	berrors "github.com/letsencrypt/boulder/errors"
 	"github.com/letsencrypt/boulder/identifier"
@@ -23,6 +24,7 @@ import (
 func (va ValidationAuthorityImpl) getAddrs(ctx context.Context, hostname string) ([]net.IP, error) {
 	addrs, err := va.dnsClient.LookupHost(ctx, hostname)
 	if err != nil {
+		va.logDNSError(hostname, err)
 		return nil, berrors.DNSError("%v", err)
 	}
 
@@ -60,9 +62,8 @@ func (va *ValidationAuthorityImpl) validateDNS01(ctx context.Context, ident iden
 	// Look for the required record in the DNS
 	challengeSubdomain := fmt.Sprintf("%s.%s", core.DNSPrefix, ident.Value)
 	txts, err := va.dnsClient.LookupTXT(ctx, challengeSubdomain)
-
 	if err != nil {
-		va.log.Infof("Failed to lookup TXT records for %s. err=[%#v] errStr=[%s]", ident, err, err)
+		va.logDNSError(ident.Value, err)
 		return nil, probs.DNS(err.Error())
 	}
 
@@ -91,3 +92,23 @@ func (va *ValidationAuthorityImpl) validateDNS01(ctx context.Context, ident iden
 	return nil, probs.Unauthorized("Incorrect TXT record %q%s found at %s",
 		replaceInvalidUTF8([]byte(invalidRecord)), andMore, challengeSubdomain)
 }
+
+// logDNSError logs the provided error, but only if it's one of our DNS error
+// types, and only if it has an underlying error. This excludes "normal" DNS
+// errors like NXDOMAIN and SERVFAIL that we successfully received from our
+// resolver, but includes errors in communicating with our resolver.
+// We're interested in logging these separately because the problem document
+// that gets sent to the user (and logged) includes only a more generic message
+// like "networking error."
+func (va *ValidationAuthorityImpl) logDNSError(ident string, err error) {
+	if dnsErr, ok := err.(*bdns.DNSError); ok {
+		underlying := dnsErr.Underlying()
+		// Excluded canceled and deadline exceeded requests because those are
+		// expected and are generally the "fault" of the authoritative resolver, not
+		// ours.
+		if underlying != nil && underlying != context.Canceled && underlying != context.DeadlineExceeded {
+			va.log.Errf("For identifier %q: err=[%s], underlying=[%s]",
+				ident, err, underlying)
+		}
+	}
+}

va/http_test.go

@@ -307,6 +307,21 @@ func TestExtractRequestTarget(t *testing.T) {
 	}
 }
 
+// TestHTTPValidationDNSError attempts validation for a domain name that always
+// generates a DNS error, and checks that a log line with the detailed error is
+// generated.
+func TestHTTPValidationDNSError(t *testing.T) {
+	va, mockLog := setup(nil, 0, "", nil)
+
+	_, _, prob := va.fetchHTTP(ctx, "always.error", "/.well-known/acme-challenge/whatever")
+	test.AssertError(t, prob, "Expected validation fetch to fail")
+	matchingLines := mockLog.GetAllMatching(`read udp: some net error`)
+	if len(matchingLines) != 1 {
+		t.Errorf("Didn't see expected DNS error logged. Instead, got:\n%s",
+			strings.Join(mockLog.GetAllMatching(`.*`), "\n"))
+	}
+}
+
 func TestSetupHTTPValidation(t *testing.T) {
 	va, _ := setup(nil, 0, "", nil)