Improve DNS related logging

Author: mholt

dnsutil.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/miekg/dns"
+	"go.uber.org/zap"
 )
 
 // Code in this file adapted from go-acme/lego, July 2020:
@@ -19,19 +20,21 @@ import (
 
 // findZoneByFQDN determines the zone apex for the given fqdn by recursing
 // up the domain labels until the nameserver returns a SOA record in the
-// answer section.
-func findZoneByFQDN(fqdn string, nameservers []string) (string, error) {
+// answer section. The logger must be non-nil.
+func findZoneByFQDN(logger *zap.Logger, fqdn string, nameservers []string) (string, error) {
 	if !strings.HasSuffix(fqdn, ".") {
 		fqdn += "."
 	}
-	soa, err := lookupSoaByFqdn(fqdn, nameservers)
+	soa, err := lookupSoaByFqdn(logger, fqdn, nameservers)
 	if err != nil {
 		return "", err
 	}
 	return soa.zone, nil
 }
 
-func lookupSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error) {
+func lookupSoaByFqdn(logger *zap.Logger, fqdn string, nameservers []string) (*soaCacheEntry, error) {
+	logger = logger.Named("soa_lookup")
+
 	if !strings.HasSuffix(fqdn, ".") {
 		fqdn += "."
 	}
@@ -41,10 +44,11 @@ func lookupSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error)
 
 	// prefer cached version if fresh
 	if ent := fqdnSOACache[fqdn]; ent != nil && !ent.isExpired() {
+		logger.Debug("using cached SOA result", zap.String("entry", ent.zone))
 		return ent, nil
 	}
 
-	ent, err := fetchSoaByFqdn(fqdn, nameservers)
+	ent, err := fetchSoaByFqdn(logger, fqdn, nameservers)
 	if err != nil {
 		return nil, err
 	}
@@ -62,7 +66,7 @@ func lookupSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error)
 	return ent, nil
 }
 
-func fetchSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error) {
+func fetchSoaByFqdn(logger *zap.Logger, fqdn string, nameservers []string) (*soaCacheEntry, error) {
 	var err error
 	var in *dns.Msg
 
@@ -77,6 +81,7 @@ func fetchSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error) {
 		if in == nil {
 			continue
 		}
+		logger.Debug("fetched SOA", zap.String("msg", in.String()))
 
 		switch in.Rcode {
 		case dns.RcodeSuccess:
@@ -211,7 +216,9 @@ func populateNameserverPorts(servers []string) {
 }
 
 // checkDNSPropagation checks if the expected record has been propagated to all authoritative nameservers.
-func checkDNSPropagation(fqdn string, recType uint16, expectedValue string, checkAuthoritativeServers bool, resolvers []string) (bool, error) {
+func checkDNSPropagation(logger *zap.Logger, fqdn string, recType uint16, expectedValue string, checkAuthoritativeServers bool, resolvers []string) (bool, error) {
+	logger = logger.Named("propagation")
+
 	if !strings.HasSuffix(fqdn, ".") {
 		fqdn += "."
 	}
@@ -230,13 +237,14 @@ func checkDNSPropagation(fqdn string, recType uint16, expectedValue string, chec
 	}
 
 	if checkAuthoritativeServers {
-		authoritativeServers, err := lookupNameservers(fqdn, resolvers)
+		authoritativeServers, err := lookupNameservers(logger, fqdn, resolvers)
 		if err != nil {
 			return false, fmt.Errorf("looking up authoritative nameservers: %v", err)
 		}
 		populateNameserverPorts(authoritativeServers)
 		resolvers = authoritativeServers
 	}
+	logger.Debug("checking authoritative nameservers", zap.Strings("resolvers", resolvers))
 
 	return checkAuthoritativeNss(fqdn, recType, expectedValue, resolvers)
 }
@@ -285,10 +293,10 @@ func checkAuthoritativeNss(fqdn string, recType uint16, expectedValue string, na
 }
 
 // lookupNameservers returns the authoritative nameservers for the given fqdn.
-func lookupNameservers(fqdn string, resolvers []string) ([]string, error) {
+func lookupNameservers(logger *zap.Logger, fqdn string, resolvers []string) ([]string, error) {
 	var authoritativeNss []string
 
-	zone, err := findZoneByFQDN(fqdn, resolvers)
+	zone, err := findZoneByFQDN(logger, fqdn, resolvers)
 	if err != nil {
 		return nil, fmt.Errorf("could not determine the zone for '%s': %w", fqdn, err)
 	}

dnsutil_test.go

@@ -13,6 +13,8 @@ import (
 	"sort"
 	"strings"
 	"testing"
+
+	"go.uber.org/zap"
 )
 
 func TestLookupNameserversOK(t *testing.T) {
@@ -32,7 +34,7 @@ func TestLookupNameserversOK(t *testing.T) {
 		t.Run(test.fqdn, func(t *testing.T) {
 			t.Parallel()
 
-			nss, err := lookupNameservers(test.fqdn, recursiveNameservers(nil))
+			nss, err := lookupNameservers(zap.NewNop(), test.fqdn, recursiveNameservers(nil))
 			if err != nil {
 				t.Errorf("Expected no error, got: %v", err)
 			}
@@ -66,7 +68,7 @@ func TestLookupNameserversErr(t *testing.T) {
 		t.Run(test.desc, func(t *testing.T) {
 			t.Parallel()
 
-			_, err := lookupNameservers(test.fqdn, nil)
+			_, err := lookupNameservers(zap.NewNop(), test.fqdn, nil)
 			if err == nil {
 				t.Errorf("expected error, got none")
 			}
@@ -158,7 +160,7 @@ func TestFindZoneByFqdn(t *testing.T) {
 			}
 			clearFqdnCache()
 
-			zone, err := findZoneByFQDN(test.fqdn, test.nameservers)
+			zone, err := findZoneByFQDN(zap.NewNop(), test.fqdn, test.nameservers)
 			if test.expectedError != "" {
 				if err == nil {
 					t.Errorf("test %d: expected error, got none", i)

solvers.go

@@ -33,6 +33,7 @@ import (
 	"github.com/mholt/acmez"
 	"github.com/mholt/acmez/acme"
 	"github.com/miekg/dns"
+	"go.uber.org/zap"
 )
 
 // httpSolver solves the HTTP challenge. It must be
@@ -357,6 +358,9 @@ type DNSManager struct {
 	// that the solver doesn't follow CNAME/NS record.
 	OverrideDomain string
 
+	// An optional logger.
+	Logger *zap.Logger
+
 	// Remember DNS records while challenges are active; i.e.
 	// records we have presented and not yet cleaned up.
 	// This lets us clean them up quickly and efficiently.
@@ -373,7 +377,9 @@ type DNSManager struct {
 }
 
 func (m *DNSManager) createRecord(ctx context.Context, dnsName, recordType, recordValue string) (zoneRecord, error) {
-	zone, err := findZoneByFQDN(dnsName, recursiveNameservers(m.Resolvers))
+	logger := m.logger()
+
+	zone, err := findZoneByFQDN(logger, dnsName, recursiveNameservers(m.Resolvers))
 	if err != nil {
 		return zoneRecord{}, fmt.Errorf("could not determine zone for domain %q: %v", dnsName, err)
 	}
@@ -384,6 +390,14 @@ func (m *DNSManager) createRecord(ctx context.Context, dnsName, recordType, reco
 		TTL:   m.TTL,
 	}
 
+	logger.Debug("creating DNS record",
+		zap.String("dns_name", dnsName),
+		zap.String("zone", zone),
+		zap.String("record_name", rec.Name),
+		zap.String("record_type", rec.Type),
+		zap.String("record_value", rec.Value),
+		zap.Duration("record_ttl", rec.TTL))
+
 	results, err := m.DNSProvider.AppendRecords(ctx, zone, []libdns.Record{rec})
 	if err != nil {
 		return zoneRecord{}, fmt.Errorf("adding temporary record for zone %q: %w", zone, err)
@@ -398,32 +412,34 @@ func (m *DNSManager) createRecord(ctx context.Context, dnsName, recordType, reco
 // wait blocks until the TXT record created in Present() appears in
 // authoritative lookups, i.e. until it has propagated, or until
 // timeout, whichever is first.
-func (s *DNSManager) wait(ctx context.Context, zrec zoneRecord) error {
+func (m *DNSManager) wait(ctx context.Context, zrec zoneRecord) error {
+	logger := m.logger()
+
 	// if configured to, pause before doing propagation checks
 	// (even if they are disabled, the wait might be desirable on its own)
-	if s.PropagationDelay > 0 {
+	if m.PropagationDelay > 0 {
 		select {
-		case <-time.After(s.PropagationDelay):
+		case <-time.After(m.PropagationDelay):
 		case <-ctx.Done():
 			return ctx.Err()
 		}
 	}
 
 	// skip propagation checks if configured to do so
-	if s.PropagationTimeout == -1 {
+	if m.PropagationTimeout == -1 {
 		return nil
 	}
 
 	// timings
-	timeout := s.PropagationTimeout
+	timeout := m.PropagationTimeout
 	if timeout == 0 {
 		timeout = defaultDNSPropagationTimeout
 	}
 	const interval = 2 * time.Second
 
 	// how we'll do the checks
-	checkAuthoritativeServers := len(s.Resolvers) == 0
-	resolvers := recursiveNameservers(s.Resolvers)
+	checkAuthoritativeServers := len(m.Resolvers) == 0
+	resolvers := recursiveNameservers(m.Resolvers)
 
 	recType := dns.TypeTXT
 	if zrec.record.Type == "CNAME" {
@@ -440,8 +456,15 @@ func (s *DNSManager) wait(ctx context.Context, zrec zoneRecord) error {
 		case <-ctx.Done():
 			return ctx.Err()
 		}
+
+		logger.Debug("checking DNS propagation",
+			zap.String("fqdn", absName),
+			zap.String("record_type", zrec.record.Type),
+			zap.String("expected_value", zrec.record.Value),
+			zap.Strings("resolvers", resolvers))
+
 		var ready bool
-		ready, err = checkDNSPropagation(absName, recType, zrec.record.Value, checkAuthoritativeServers, resolvers)
+		ready, err = checkDNSPropagation(logger, absName, recType, zrec.record.Value, checkAuthoritativeServers, resolvers)
 		if err != nil {
 			return fmt.Errorf("checking DNS propagation of %q (relative=%s zone=%s resolvers=%v): %w", absName, zrec.record.Name, zrec.zone, resolvers, err)
 		}
@@ -464,25 +487,43 @@ type zoneRecord struct {
 // a context cancellation, and properly-implemented DNS providers should
 // honor cancellation, which would result in cleanup being aborted.
 // Cleanup must always occur.
-func (s *DNSManager) cleanUpRecord(_ context.Context, zrec zoneRecord) error {
+func (m *DNSManager) cleanUpRecord(_ context.Context, zrec zoneRecord) error {
+	logger := m.logger()
+
 	// clean up the record - use a different context though, since
 	// one common reason cleanup is performed is because a context
 	// was canceled, and if so, any HTTP requests by this provider
 	// should fail if the provider is properly implemented
 	// (see issue #200)
-	timeout := s.PropagationTimeout
+	timeout := m.PropagationTimeout
 	if timeout <= 0 {
 		timeout = defaultDNSPropagationTimeout
 	}
 	ctx, cancel := context.WithTimeout(context.Background(), timeout)
 	defer cancel()
-	_, err := s.DNSProvider.DeleteRecords(ctx, zrec.zone, []libdns.Record{zrec.record})
+
+	logger.Debug("deleting DNS record",
+		zap.String("zone", zrec.zone),
+		zap.String("record_id", zrec.record.ID),
+		zap.String("record_name", zrec.record.Name),
+		zap.String("record_type", zrec.record.Type),
+		zap.String("record_value", zrec.record.Value))
+
+	_, err := m.DNSProvider.DeleteRecords(ctx, zrec.zone, []libdns.Record{zrec.record})
 	if err != nil {
 		return fmt.Errorf("deleting temporary record for name %q in zone %q: %w", zrec.zone, zrec.record, err)
 	}
 	return nil
 }
 
+func (m *DNSManager) logger() *zap.Logger {
+	logger := m.Logger
+	if logger == nil {
+		logger = zap.NewNop()
+	}
+	return logger.Named("dns_manager")
+}
+
 const defaultDNSPropagationTimeout = 2 * time.Minute
 
 // dnsPresentMemory associates a created DNS record with its zone