diff --git a/dnsutil.go b/dnsutil.go index a87a1a9..81fc192 100644 --- a/dnsutil.go +++ b/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) } diff --git a/dnsutil_test.go b/dnsutil_test.go index 4890d23..0df6992 100644 --- a/dnsutil_test.go +++ b/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) diff --git a/solvers.go b/solvers.go index 1d920f2..9da675f 100644 --- a/solvers.go +++ b/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