Improve DNS related logging
This commit is contained in:
parent
6095ab8069
commit
98d2930e1d
28
dnsutil.go
28
dnsutil.go
@ -9,6 +9,7 @@ import (
|
|||||||
"time"
|
"time"
|
||||||
|
|
||||||
"github.com/miekg/dns"
|
"github.com/miekg/dns"
|
||||||
|
"go.uber.org/zap"
|
||||||
)
|
)
|
||||||
|
|
||||||
// Code in this file adapted from go-acme/lego, July 2020:
|
// 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
|
// findZoneByFQDN determines the zone apex for the given fqdn by recursing
|
||||||
// up the domain labels until the nameserver returns a SOA record in the
|
// up the domain labels until the nameserver returns a SOA record in the
|
||||||
// answer section.
|
// answer section. The logger must be non-nil.
|
||||||
func findZoneByFQDN(fqdn string, nameservers []string) (string, error) {
|
func findZoneByFQDN(logger *zap.Logger, fqdn string, nameservers []string) (string, error) {
|
||||||
if !strings.HasSuffix(fqdn, ".") {
|
if !strings.HasSuffix(fqdn, ".") {
|
||||||
fqdn += "."
|
fqdn += "."
|
||||||
}
|
}
|
||||||
soa, err := lookupSoaByFqdn(fqdn, nameservers)
|
soa, err := lookupSoaByFqdn(logger, fqdn, nameservers)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return "", err
|
return "", err
|
||||||
}
|
}
|
||||||
return soa.zone, nil
|
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, ".") {
|
if !strings.HasSuffix(fqdn, ".") {
|
||||||
fqdn += "."
|
fqdn += "."
|
||||||
}
|
}
|
||||||
@ -41,10 +44,11 @@ func lookupSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error)
|
|||||||
|
|
||||||
// prefer cached version if fresh
|
// prefer cached version if fresh
|
||||||
if ent := fqdnSOACache[fqdn]; ent != nil && !ent.isExpired() {
|
if ent := fqdnSOACache[fqdn]; ent != nil && !ent.isExpired() {
|
||||||
|
logger.Debug("using cached SOA result", zap.String("entry", ent.zone))
|
||||||
return ent, nil
|
return ent, nil
|
||||||
}
|
}
|
||||||
|
|
||||||
ent, err := fetchSoaByFqdn(fqdn, nameservers)
|
ent, err := fetchSoaByFqdn(logger, fqdn, nameservers)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return nil, err
|
return nil, err
|
||||||
}
|
}
|
||||||
@ -62,7 +66,7 @@ func lookupSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error)
|
|||||||
return ent, nil
|
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 err error
|
||||||
var in *dns.Msg
|
var in *dns.Msg
|
||||||
|
|
||||||
@ -77,6 +81,7 @@ func fetchSoaByFqdn(fqdn string, nameservers []string) (*soaCacheEntry, error) {
|
|||||||
if in == nil {
|
if in == nil {
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
|
logger.Debug("fetched SOA", zap.String("msg", in.String()))
|
||||||
|
|
||||||
switch in.Rcode {
|
switch in.Rcode {
|
||||||
case dns.RcodeSuccess:
|
case dns.RcodeSuccess:
|
||||||
@ -211,7 +216,9 @@ func populateNameserverPorts(servers []string) {
|
|||||||
}
|
}
|
||||||
|
|
||||||
// checkDNSPropagation checks if the expected record has been propagated to all authoritative nameservers.
|
// 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, ".") {
|
if !strings.HasSuffix(fqdn, ".") {
|
||||||
fqdn += "."
|
fqdn += "."
|
||||||
}
|
}
|
||||||
@ -230,13 +237,14 @@ func checkDNSPropagation(fqdn string, recType uint16, expectedValue string, chec
|
|||||||
}
|
}
|
||||||
|
|
||||||
if checkAuthoritativeServers {
|
if checkAuthoritativeServers {
|
||||||
authoritativeServers, err := lookupNameservers(fqdn, resolvers)
|
authoritativeServers, err := lookupNameservers(logger, fqdn, resolvers)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return false, fmt.Errorf("looking up authoritative nameservers: %v", err)
|
return false, fmt.Errorf("looking up authoritative nameservers: %v", err)
|
||||||
}
|
}
|
||||||
populateNameserverPorts(authoritativeServers)
|
populateNameserverPorts(authoritativeServers)
|
||||||
resolvers = authoritativeServers
|
resolvers = authoritativeServers
|
||||||
}
|
}
|
||||||
|
logger.Debug("checking authoritative nameservers", zap.Strings("resolvers", resolvers))
|
||||||
|
|
||||||
return checkAuthoritativeNss(fqdn, recType, expectedValue, 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.
|
// 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
|
var authoritativeNss []string
|
||||||
|
|
||||||
zone, err := findZoneByFQDN(fqdn, resolvers)
|
zone, err := findZoneByFQDN(logger, fqdn, resolvers)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return nil, fmt.Errorf("could not determine the zone for '%s': %w", fqdn, err)
|
return nil, fmt.Errorf("could not determine the zone for '%s': %w", fqdn, err)
|
||||||
}
|
}
|
||||||
|
@ -13,6 +13,8 @@ import (
|
|||||||
"sort"
|
"sort"
|
||||||
"strings"
|
"strings"
|
||||||
"testing"
|
"testing"
|
||||||
|
|
||||||
|
"go.uber.org/zap"
|
||||||
)
|
)
|
||||||
|
|
||||||
func TestLookupNameserversOK(t *testing.T) {
|
func TestLookupNameserversOK(t *testing.T) {
|
||||||
@ -32,7 +34,7 @@ func TestLookupNameserversOK(t *testing.T) {
|
|||||||
t.Run(test.fqdn, func(t *testing.T) {
|
t.Run(test.fqdn, func(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
nss, err := lookupNameservers(test.fqdn, recursiveNameservers(nil))
|
nss, err := lookupNameservers(zap.NewNop(), test.fqdn, recursiveNameservers(nil))
|
||||||
if err != nil {
|
if err != nil {
|
||||||
t.Errorf("Expected no error, got: %v", err)
|
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.Run(test.desc, func(t *testing.T) {
|
||||||
t.Parallel()
|
t.Parallel()
|
||||||
|
|
||||||
_, err := lookupNameservers(test.fqdn, nil)
|
_, err := lookupNameservers(zap.NewNop(), test.fqdn, nil)
|
||||||
if err == nil {
|
if err == nil {
|
||||||
t.Errorf("expected error, got none")
|
t.Errorf("expected error, got none")
|
||||||
}
|
}
|
||||||
@ -158,7 +160,7 @@ func TestFindZoneByFqdn(t *testing.T) {
|
|||||||
}
|
}
|
||||||
clearFqdnCache()
|
clearFqdnCache()
|
||||||
|
|
||||||
zone, err := findZoneByFQDN(test.fqdn, test.nameservers)
|
zone, err := findZoneByFQDN(zap.NewNop(), test.fqdn, test.nameservers)
|
||||||
if test.expectedError != "" {
|
if test.expectedError != "" {
|
||||||
if err == nil {
|
if err == nil {
|
||||||
t.Errorf("test %d: expected error, got none", i)
|
t.Errorf("test %d: expected error, got none", i)
|
||||||
|
65
solvers.go
65
solvers.go
@ -33,6 +33,7 @@ import (
|
|||||||
"github.com/mholt/acmez"
|
"github.com/mholt/acmez"
|
||||||
"github.com/mholt/acmez/acme"
|
"github.com/mholt/acmez/acme"
|
||||||
"github.com/miekg/dns"
|
"github.com/miekg/dns"
|
||||||
|
"go.uber.org/zap"
|
||||||
)
|
)
|
||||||
|
|
||||||
// httpSolver solves the HTTP challenge. It must be
|
// httpSolver solves the HTTP challenge. It must be
|
||||||
@ -357,6 +358,9 @@ type DNSManager struct {
|
|||||||
// that the solver doesn't follow CNAME/NS record.
|
// that the solver doesn't follow CNAME/NS record.
|
||||||
OverrideDomain string
|
OverrideDomain string
|
||||||
|
|
||||||
|
// An optional logger.
|
||||||
|
Logger *zap.Logger
|
||||||
|
|
||||||
// Remember DNS records while challenges are active; i.e.
|
// Remember DNS records while challenges are active; i.e.
|
||||||
// records we have presented and not yet cleaned up.
|
// records we have presented and not yet cleaned up.
|
||||||
// This lets us clean them up quickly and efficiently.
|
// 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) {
|
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 {
|
if err != nil {
|
||||||
return zoneRecord{}, fmt.Errorf("could not determine zone for domain %q: %v", dnsName, err)
|
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,
|
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})
|
results, err := m.DNSProvider.AppendRecords(ctx, zone, []libdns.Record{rec})
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return zoneRecord{}, fmt.Errorf("adding temporary record for zone %q: %w", zone, err)
|
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
|
// wait blocks until the TXT record created in Present() appears in
|
||||||
// authoritative lookups, i.e. until it has propagated, or until
|
// authoritative lookups, i.e. until it has propagated, or until
|
||||||
// timeout, whichever is first.
|
// 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
|
// if configured to, pause before doing propagation checks
|
||||||
// (even if they are disabled, the wait might be desirable on its own)
|
// (even if they are disabled, the wait might be desirable on its own)
|
||||||
if s.PropagationDelay > 0 {
|
if m.PropagationDelay > 0 {
|
||||||
select {
|
select {
|
||||||
case <-time.After(s.PropagationDelay):
|
case <-time.After(m.PropagationDelay):
|
||||||
case <-ctx.Done():
|
case <-ctx.Done():
|
||||||
return ctx.Err()
|
return ctx.Err()
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
// skip propagation checks if configured to do so
|
// skip propagation checks if configured to do so
|
||||||
if s.PropagationTimeout == -1 {
|
if m.PropagationTimeout == -1 {
|
||||||
return nil
|
return nil
|
||||||
}
|
}
|
||||||
|
|
||||||
// timings
|
// timings
|
||||||
timeout := s.PropagationTimeout
|
timeout := m.PropagationTimeout
|
||||||
if timeout == 0 {
|
if timeout == 0 {
|
||||||
timeout = defaultDNSPropagationTimeout
|
timeout = defaultDNSPropagationTimeout
|
||||||
}
|
}
|
||||||
const interval = 2 * time.Second
|
const interval = 2 * time.Second
|
||||||
|
|
||||||
// how we'll do the checks
|
// how we'll do the checks
|
||||||
checkAuthoritativeServers := len(s.Resolvers) == 0
|
checkAuthoritativeServers := len(m.Resolvers) == 0
|
||||||
resolvers := recursiveNameservers(s.Resolvers)
|
resolvers := recursiveNameservers(m.Resolvers)
|
||||||
|
|
||||||
recType := dns.TypeTXT
|
recType := dns.TypeTXT
|
||||||
if zrec.record.Type == "CNAME" {
|
if zrec.record.Type == "CNAME" {
|
||||||
@ -440,8 +456,15 @@ func (s *DNSManager) wait(ctx context.Context, zrec zoneRecord) error {
|
|||||||
case <-ctx.Done():
|
case <-ctx.Done():
|
||||||
return ctx.Err()
|
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
|
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 {
|
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)
|
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
|
// a context cancellation, and properly-implemented DNS providers should
|
||||||
// honor cancellation, which would result in cleanup being aborted.
|
// honor cancellation, which would result in cleanup being aborted.
|
||||||
// Cleanup must always occur.
|
// 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
|
// clean up the record - use a different context though, since
|
||||||
// one common reason cleanup is performed is because a context
|
// one common reason cleanup is performed is because a context
|
||||||
// was canceled, and if so, any HTTP requests by this provider
|
// was canceled, and if so, any HTTP requests by this provider
|
||||||
// should fail if the provider is properly implemented
|
// should fail if the provider is properly implemented
|
||||||
// (see issue #200)
|
// (see issue #200)
|
||||||
timeout := s.PropagationTimeout
|
timeout := m.PropagationTimeout
|
||||||
if timeout <= 0 {
|
if timeout <= 0 {
|
||||||
timeout = defaultDNSPropagationTimeout
|
timeout = defaultDNSPropagationTimeout
|
||||||
}
|
}
|
||||||
ctx, cancel := context.WithTimeout(context.Background(), timeout)
|
ctx, cancel := context.WithTimeout(context.Background(), timeout)
|
||||||
defer cancel()
|
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 {
|
if err != nil {
|
||||||
return fmt.Errorf("deleting temporary record for name %q in zone %q: %w", zrec.zone, zrec.record, err)
|
return fmt.Errorf("deleting temporary record for name %q in zone %q: %w", zrec.zone, zrec.record, err)
|
||||||
}
|
}
|
||||||
return nil
|
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
|
const defaultDNSPropagationTimeout = 2 * time.Minute
|
||||||
|
|
||||||
// dnsPresentMemory associates a created DNS record with its zone
|
// dnsPresentMemory associates a created DNS record with its zone
|
||||||
|
Loading…
Reference in New Issue
Block a user