bdns: remove logDNSError (#8445)

This had some special casing for the "id mismatch" error we were
tracking for a while. We've resolved that issue by switching to DoH and
now see 0 instances of "id mismatch." However, it's still been
occasionally useful to see the detailed DNS errors, so I'm keeping a
simplified log line.

Author: jsha

bdns/dns.go

@@ -3,7 +3,6 @@ package bdns
 import (
 	"context"
 	"crypto/tls"
-	"encoding/base64"
 	"errors"
 	"fmt"
 	"io"
@@ -48,10 +47,9 @@ type impl struct {
 	clk                      clock.Clock
 	log                      blog.Logger
 
-	queryTime         *prometheus.HistogramVec
-	totalLookupTime   *prometheus.HistogramVec
-	timeoutCounter    *prometheus.CounterVec
-	idMismatchCounter *prometheus.CounterVec
+	queryTime       *prometheus.HistogramVec
+	totalLookupTime *prometheus.HistogramVec
+	timeoutCounter  *prometheus.CounterVec
 }
 
 var _ Client = &impl{}
@@ -118,14 +116,6 @@ func New(
 		},
 		[]string{"qtype", "type", "resolver", "isTLD"},
 	)
-	idMismatchCounter := prometheus.NewCounterVec(
-		prometheus.CounterOpts{
-			Name: "dns_id_mismatch",
-			Help: "Counter of DNS ErrId errors sliced by query type and resolver",
-		},
-		[]string{"qtype", "resolver"},
-	)
-	stats.MustRegister(queryTime, totalLookupTime, timeoutCounter, idMismatchCounter)
 	return &impl{
 		dnsClient:                client,
 		servers:                  servers,
@@ -135,7 +125,6 @@ func New(
 		queryTime:                queryTime,
 		totalLookupTime:          totalLookupTime,
 		timeoutCounter:           timeoutCounter,
-		idMismatchCounter:        idMismatchCounter,
 		log:                      log,
 	}
 }
@@ -230,13 +219,11 @@ func (dnsClient *impl) exchangeOne(ctx context.Context, hostname string, qtype u
 				result = dns.RcodeToString[rsp.Rcode]
 			}
 			if err != nil {
-				logDNSError(dnsClient.log, chosenServer, hostname, m, rsp, err)
-				if err == dns.ErrId {
-					dnsClient.idMismatchCounter.With(prometheus.Labels{
-						"qtype":    qtypeStr,
-						"resolver": chosenServerIP,
-					}).Inc()
-				}
+				dnsClient.log.Infof("logDNSError chosenServer=[%s] hostname=[%s] queryType=[%s] err=[%s]",
+					chosenServer,
+					hostname,
+					qtypeStr,
+					err)
 			}
 			dnsClient.queryTime.With(prometheus.Labels{
 				"qtype":    qtypeStr,
@@ -469,68 +456,6 @@ func (dnsClient *impl) LookupCAA(ctx context.Context, hostname string) ([]*dns.C
 	return CAAs, response, ResolverAddrs{resolver}, nil
 }
 
-// logDNSError logs the provided err result from making a query for hostname to
-// the chosenServer. If the err is a `dns.ErrId` instance then the Base64
-// encoded bytes of the query (and if not-nil, the response) in wire format
-// is logged as well. This function is called from exchangeOne only for the case
-// where an error occurs querying a hostname that indicates a problem between
-// the VA and the chosenServer.
-func logDNSError(
-	logger blog.Logger,
-	chosenServer string,
-	hostname string,
-	msg, resp *dns.Msg,
-	underlying error) {
-	// We don't expect logDNSError to be called with a nil msg or err but
-	// if it happens return early. We allow resp to be nil.
-	if msg == nil || len(msg.Question) == 0 || underlying == nil {
-		return
-	}
-	queryType := dns.TypeToString[msg.Question[0].Qtype]
-
-	// If the error indicates there was a query/response ID mismatch then we want
-	// to log more detail.
-	if underlying == dns.ErrId {
-		packedMsgBytes, err := msg.Pack()
-		if err != nil {
-			logger.Errf("logDNSError failed to pack msg: %v", err)
-			return
-		}
-		encodedMsg := base64.StdEncoding.EncodeToString(packedMsgBytes)
-
-		var encodedResp string
-		var respQname string
-		if resp != nil {
-			packedRespBytes, err := resp.Pack()
-			if err != nil {
-				logger.Errf("logDNSError failed to pack resp: %v", err)
-				return
-			}
-			encodedResp = base64.StdEncoding.EncodeToString(packedRespBytes)
-			if len(resp.Answer) > 0 && resp.Answer[0].Header() != nil {
-				respQname = resp.Answer[0].Header().Name
-			}
-		}
-
-		logger.Infof(
-			"logDNSError ID mismatch chosenServer=[%s] hostname=[%s] respHostname=[%s] queryType=[%s] msg=[%s] resp=[%s] err=[%s]",
-			chosenServer,
-			hostname,
-			respQname,
-			queryType,
-			encodedMsg,
-			encodedResp,
-			underlying)
-	} else {
-		// Otherwise log a general DNS error
-		logger.Infof("logDNSError chosenServer=[%s] hostname=[%s] queryType=[%s] err=[%s]",
-			chosenServer,
-			hostname,
-			queryType,
-			underlying)
-	}
-}
-
 type dohExchanger struct {
 	clk       clock.Clock
 	hc        http.Client

bdns/mocks.go

@@ -125,7 +125,6 @@ func (mock *MockClient) LookupHost(_ context.Context, hostname string) ([]netip.
 		m.SetQuestion(dns.Fqdn(hostname), dns.TypeA)
 		m.AuthenticatedData = true
 		m.SetEdns0(4096, false)
-		logDNSError(mock.Log, "mock.server", hostname, m, nil, err)
 		return []netip.Addr{}, ResolverAddrs{"MockClient"}, &Error{dns.TypeA, hostname, err, -1, nil}
 	}
 	if hostname == "id.mismatch" {
@@ -139,7 +138,6 @@ func (mock *MockClient) LookupHost(_ context.Context, hostname string) ([]netip.
 		record.Hdr = dns.RR_Header{Name: dns.Fqdn(hostname), Rrtype: dns.TypeA, Class: dns.ClassINET, Ttl: 0}
 		record.A = net.ParseIP("127.0.0.1")
 		r.Answer = append(r.Answer, record)
-		logDNSError(mock.Log, "mock.server", hostname, m, r, err)
 		return []netip.Addr{}, ResolverAddrs{"MockClient"}, &Error{dns.TypeA, hostname, err, -1, nil}
 	}
 	// dual-homed host with an IPv6 and an IPv4 address

va/http_test.go

@@ -3,7 +3,6 @@ package va
 import (
 	"bytes"
 	"context"
-	"encoding/base64"
 	"errors"
 	"fmt"
 	mrand "math/rand/v2"
@@ -12,14 +11,11 @@ import (
 	"net/http/httptest"
 	"net/netip"
 	"net/url"
-	"regexp"
 	"strconv"
 	"strings"
 	"time"
 	"unicode/utf8"
 
-	"github.com/miekg/dns"
-
 	"github.com/letsencrypt/boulder/bdns"
 	"github.com/letsencrypt/boulder/core"
 	berrors "github.com/letsencrypt/boulder/errors"
@@ -413,64 +409,6 @@ 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, "", nil, nil)
-
-	_, _, prob := va.processHTTPValidation(ctx, identifier.NewDNS("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"))
-	}
-}
-
-// TestHTTPValidationDNSIdMismatchError tests that performing an HTTP-01
-// challenge with a domain name that always returns a DNS ID mismatch error from
-// the mock resolver results in valid query/response data being logged in
-// a format we can decode successfully.
-func TestHTTPValidationDNSIdMismatchError(t *testing.T) {
-	va, mockLog := setup(nil, "", nil, nil)
-
-	_, _, prob := va.processHTTPValidation(ctx, identifier.NewDNS("id.mismatch"), "/.well-known/acme-challenge/whatever")
-	test.AssertError(t, prob, "Expected validation fetch to fail")
-	matchingLines := mockLog.GetAllMatching(`logDNSError ID mismatch`)
-	if len(matchingLines) != 1 {
-		t.Errorf("Didn't see expected DNS error logged. Instead, got:\n%s",
-			strings.Join(mockLog.GetAllMatching(`.*`), "\n"))
-	}
-	expectedRegex := regexp.MustCompile(
-		`INFO: logDNSError ID mismatch ` +
-			`chosenServer=\[mock.server\] ` +
-			`hostname=\[id\.mismatch\] ` +
-			`respHostname=\[id\.mismatch\.\] ` +
-			`queryType=\[A\] ` +
-			`msg=\[([A-Za-z0-9+=/\=]+)\] ` +
-			`resp=\[([A-Za-z0-9+=/\=]+)\] ` +
-			`err\=\[dns: id mismatch\]`,
-	)
-
-	matches := expectedRegex.FindAllStringSubmatch(matchingLines[0], -1)
-	test.AssertEquals(t, len(matches), 1)
-	submatches := matches[0]
-	test.AssertEquals(t, len(submatches), 3)
-
-	msgBytes, err := base64.StdEncoding.DecodeString(submatches[1])
-	test.AssertNotError(t, err, "bad base64 encoded query msg")
-	msg := new(dns.Msg)
-	err = msg.Unpack(msgBytes)
-	test.AssertNotError(t, err, "bad packed query msg")
-
-	respBytes, err := base64.StdEncoding.DecodeString(submatches[2])
-	test.AssertNotError(t, err, "bad base64 encoded resp msg")
-	resp := new(dns.Msg)
-	err = resp.Unpack(respBytes)
-	test.AssertNotError(t, err, "bad packed response msg")
-}
-
 func TestSetupHTTPValidation(t *testing.T) {
 	va, _ := setup(nil, "", nil, nil)