Merge branch 'develop' into feature/ui-revamp

cmds/portmaster-core/main.go

@@ -18,7 +18,7 @@ import (
 
 func main() {
 	// set information
-	info.Set("Portmaster", "0.5.4", "AGPLv3", true)
+	info.Set("Portmaster", "0.5.6", "AGPLv3", true)
 
 	// enable SPN client mode
 	conf.EnableClient(true)

core/base/databases.go

@@ -20,7 +20,6 @@ func registerDatabases() error {
 		Name:        "core",
 		Description: "Holds core data, such as settings and profiles",
 		StorageType: DefaultDatabaseStorageType,
-		PrimaryAPI:  "",
 	})
 	if err != nil {
 		return err
@@ -30,7 +29,6 @@ func registerDatabases() error {
 		Name:        "cache",
 		Description: "Cached data, such as Intelligence and DNS Records",
 		StorageType: DefaultDatabaseStorageType,
-		PrimaryAPI:  "",
 	})
 	if err != nil {
 		return err
@@ -40,7 +38,6 @@ func registerDatabases() error {
 	//   Name:        "history",
 	//   Description: "Historic event data",
 	//   StorageType: DefaultDatabaseStorageType,
-	//   PrimaryAPI:  "",
 	// })
 	// if err != nil {
 	//   return err

core/control.go

@@ -69,7 +69,6 @@ func registerControlDatabase() error {
 		Name:        "control",
 		Description: "Control Interface for the Portmaster",
 		StorageType: "injected",
-		PrimaryAPI:  "",
 	})
 	if err != nil {
 		return err

firewall/bypassing.go

@@ -13,7 +13,9 @@ import (
 func PreventBypassing(conn *network.Connection) (endpoints.EPResult, string, nsutil.Responder) {
 	// Block firefox canary domain to disable DoH
 	if strings.ToLower(conn.Entity.Domain) == "use-application-dns.net." {
-		return endpoints.Denied, "blocked canary domain to prevent enabling DNS-over-HTTPs", nsutil.NxDomain()
+		return endpoints.Denied,
+			"blocked canary domain to prevent enabling of DNS-over-HTTPs",
+			nsutil.NxDomain()
 	}
 
 	return endpoints.NoMatch, "", nil

firewall/interception/nfqexp/nfqexp.go

@@ -28,7 +28,7 @@ type Queue struct {
 }
 
 // New opens a new nfQueue.
-func New(qid uint16, v6 bool) (*Queue, error) {
+func New(qid uint16, v6 bool) (*Queue, error) { //nolint:gocognit
 	afFamily := unix.AF_INET
 	if v6 {
 		afFamily = unix.AF_INET6

intel/block_reason.go

@@ -1,6 +1,7 @@
 package intel
 
 import (
+	"context"
 	"encoding/json"
 	"fmt"
 	"strings"
@@ -63,34 +64,34 @@ func (br ListBlockReason) MarshalJSON() ([]byte, error) {
 	})
 }
 
-// GetExtraRR implements the nsutil.RRProvider interface
+// GetExtraRRs implements the nsutil.RRProvider interface
 // and adds additional TXT records justifying the reason
 // the request was blocked.
-func (br ListBlockReason) GetExtraRR(_ *dns.Msg, _ string, _ interface{}) []dns.RR {
+func (br ListBlockReason) GetExtraRRs(ctx context.Context, _ *dns.Msg) []dns.RR {
 	rrs := make([]dns.RR, 0, len(br))
 
 	for _, lm := range br {
-		blockedBy, err := dns.NewRR(fmt.Sprintf(
+		blockedBy, err := nsutil.MakeMessageRecord(log.InfoLevel, fmt.Sprintf(
-			`%s 0 IN TXT "blocked by filter lists %s"`,
+			"%s is blocked by filter lists %s",
 			lm.Entity,
 			strings.Join(lm.ActiveLists, ", "),
 		))
 		if err == nil {
 			rrs = append(rrs, blockedBy)
 		} else {
-			log.Errorf("intel: failed to create TXT RR for block reason: %s", err)
+			log.Tracer(ctx).Errorf("intel: failed to create TXT RR for block reason: %s", err)
 		}
 
 		if len(lm.InactiveLists) > 0 {
-			wouldBeBlockedBy, err := dns.NewRR(fmt.Sprintf(
+			wouldBeBlockedBy, err := nsutil.MakeMessageRecord(log.InfoLevel, fmt.Sprintf(
-				`%s 0 IN TXT "would be blocked by filter lists %s"`,
+				"%s would be blocked by filter lists %s",
 				lm.Entity,
 				strings.Join(lm.InactiveLists, ", "),
 			))
 			if err == nil {
 				rrs = append(rrs, wouldBeBlockedBy)
 			} else {
-				log.Errorf("intel: failed to create TXT RR for block reason: %s", err)
+				log.Tracer(ctx).Errorf("intel: failed to create TXT RR for block reason: %s", err)
 			}
 		}
 	}

intel/filterlists/database.go

@@ -135,10 +135,20 @@ func processListFile(ctx context.Context, filter *scopedBloom, file *updater.Fil
 func persistRecords(startJob func(func() error), records <-chan record.Record) {
 	var cnt int
 	start := time.Now()
+	logProgress := func() {
+		if cnt == 0 {
+			// protection against panic
+			return
+		}
+
+		timePerEntity := time.Since(start) / time.Duration(cnt)
+		speed := float64(time.Second) / float64(timePerEntity)
+		log.Debugf("processed %d entities in %s with %s / entity (%.2f entities/second)", cnt, time.Since(start), timePerEntity, speed)
+	}
 
 	batch := database.NewInterface(&database.Options{Local: true, Internal: true})
-	var processBatch func() error
 
+	var processBatch func() error
 	processBatch = func() error {
 		batchPut := batch.PutMany("cache")
 		for r := range records {
@@ -148,9 +158,7 @@ func persistRecords(startJob func(func() error), records <-chan record.Record) {
 			cnt++
 
 			if cnt%10000 == 0 {
-				timePerEntity := time.Since(start) / time.Duration(cnt)
+				logProgress()
-				speed := float64(time.Second) / float64(timePerEntity)
-				log.Debugf("processed %d entities %s with %s / entity (%.2f entits/second)", cnt, time.Since(start), timePerEntity, speed)
 			}
 
 			if cnt%1000 == 0 {
@@ -164,6 +172,10 @@ func persistRecords(startJob func(func() error), records <-chan record.Record) {
 			}
 		}
 
+		// log final batch
+		if cnt%10000 != 0 { // avoid duplicate logging
+			logProgress()
+		}
 		return batchPut(nil)
 	}
 
@@ -185,6 +197,7 @@ func normalizeEntry(entry *listEntry) {
 func processEntry(ctx context.Context, filter *scopedBloom, entry *listEntry, records chan<- record.Record) error {
 	normalizeEntry(entry)
 
+	// Only add the entry to the bloom filter if it has any sources.
 	if len(entry.Sources) > 0 {
 		filter.add(entry.Type, entry.Entity)
 	}
@@ -196,6 +209,12 @@ func processEntry(ctx context.Context, filter *scopedBloom, entry *listEntry, re
 		UpdatedAt: time.Now().Unix(),
 	}
 
+	// If the entry is a "delete" update, actually delete it to save space.
+	if entry.Whitelist {
+		r.CreateMeta()
+		r.Meta().Delete()
+	}
+
 	key := makeListCacheKey(strings.ToLower(r.Type), r.Value)
 	r.SetKey(key)
 

intel/filterlists/updater.go

@@ -129,57 +129,20 @@ func performUpdate(ctx context.Context) error {
 	return nil
 }
 
-func removeAllObsoleteFilterEntries(_ context.Context) error {
+func removeAllObsoleteFilterEntries(ctx context.Context) error {
 	log.Debugf("intel/filterlists: cleanup task started, removing obsolete filter list entries ...")
-	for {
+	n, err := cache.Purge(ctx, query.New(filterListKeyPrefix).Where(
-		done, err := removeObsoleteFilterEntries(10000)
+		// TODO(ppacher): remember the timestamp we started the last update
+		// and use that rather than "one hour ago"
+		query.Where("UpdatedAt", query.LessThan, time.Now().Add(-time.Hour).Unix()),
+	))
 	if err != nil {
 		return err
 	}
 
-		if done {
+	log.Debugf("intel/filterlists: successfully removed %d obsolete entries", n)
 	return nil
 }
-	}
-}
-
-func removeObsoleteFilterEntries(batchSize int) (bool, error) {
-	iter, err := cache.Query(
-		query.New(filterListKeyPrefix).Where(
-			// TODO(ppacher): remember the timestamp we started the last update
-			// and use that rather than "one hour ago"
-			query.Where("UpdatedAt", query.LessThan, time.Now().Add(-time.Hour).Unix()),
-		),
-	)
-	if err != nil {
-		return false, err
-	}
-
-	keys := make([]string, 0, batchSize)
-
-	var cnt int
-	for r := range iter.Next {
-		cnt++
-		keys = append(keys, r.Key())
-
-		if cnt == batchSize {
-			break
-		}
-	}
-	iter.Cancel()
-
-	for _, key := range keys {
-		if err := cache.Delete(key); err != nil {
-			log.Errorf("intel/filterlists: failed to remove stale cache entry %q: %s", key, err)
-		}
-	}
-
-	log.Debugf("intel/filterlists: successfully removed %d obsolete entries", cnt)
-
-	// if we removed less entries that the batch size we
-	// are done and no more entries exist
-	return cnt < batchSize, nil
-}
 
 // getUpgradableFiles returns a slice of filterlists files
 // that should be updated. The files MUST be updated and

nameserver/nameserver.go

@@ -3,7 +3,6 @@ package nameserver
 import (
 	"context"
 	"errors"
-	"fmt"
 	"net"
 	"strings"
 
@@ -28,11 +27,10 @@ var (
 	dnsServer *dns.Server
 
 	listenAddress = "0.0.0.0:53"
-	localhostRRs  []dns.RR
 )
 
 func init() {
-	module = modules.Register("nameserver", prep, start, stop, "core", "resolver")
+	module = modules.Register("nameserver", nil, start, stop, "core", "resolver")
 	subsystems.Register(
 		"dns",
 		"Secure DNS",
@@ -43,22 +41,6 @@ func init() {
 	)
 }
 
-func prep() error {
-	localhostIPv4, err := dns.NewRR("localhost. 17 IN A 127.0.0.1")
-	if err != nil {
-		return err
-	}
-
-	localhostIPv6, err := dns.NewRR("localhost. 17 IN AAAA ::1")
-	if err != nil {
-		return err
-	}
-
-	localhostRRs = []dns.RR{localhostIPv4, localhostIPv6}
-
-	return nil
-}
-
 func start() error {
 	dnsServer = &dns.Server{Addr: listenAddress, Net: "udp"}
 	dns.HandleFunc(".", handleRequestAsWorker)
@@ -89,12 +71,6 @@ func stop() error {
 	return nil
 }
 
-func returnServerFailure(w dns.ResponseWriter, query *dns.Msg) {
-	m := new(dns.Msg)
-	m.SetRcode(query, dns.RcodeServerFailure)
-	_ = writeDNSResponse(w, m)
-}
-
 func handleRequestAsWorker(w dns.ResponseWriter, query *dns.Msg) {
 	err := module.RunWorker("dns request", func(ctx context.Context) error {
 		return handleRequest(ctx, w, query)
@@ -104,86 +80,86 @@ func handleRequestAsWorker(w dns.ResponseWriter, query *dns.Msg) {
 	}
 }
 
-func handleRequest(ctx context.Context, w dns.ResponseWriter, query *dns.Msg) error { //nolint:gocognit // TODO
+func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg) error { //nolint:gocognit // TODO
-	// only process first question, that's how everyone does it.
+	// Only process first question, that's how everyone does it.
-	question := query.Question[0]
+	question := request.Question[0]
 	q := &resolver.Query{
 		FQDN:  question.Name,
 		QType: dns.Type(question.Qtype),
 	}
 
-	// return with server failure if offline
+	// Get remote address of request.
-	if netenv.GetOnlineStatus() == netenv.StatusOffline &&
-		!netenv.IsConnectivityDomain(q.FQDN) {
-		log.Tracer(ctx).Debugf("resolver: not resolving %s, device is offline", q.FQDN)
-		returnServerFailure(w, query)
-		return nil
-	}
-
-	// check class
-	if question.Qclass != dns.ClassINET {
-		// we only serve IN records, return nxdomain
-		log.Warningf("nameserver: only IN record requests are supported but received Qclass %d, returning NXDOMAIN", question.Qclass)
-		sendResponse(w, query, 0, "qclass not served", nsutil.Refused())
-		return nil
-	}
-
-	// handle request for localhost
-	if strings.HasSuffix(q.FQDN, "localhost.") {
-		m := new(dns.Msg)
-		m.SetReply(query)
-		m.Answer = localhostRRs
-		if err := writeDNSResponse(w, m); err != nil {
-			log.Warningf("nameserver: failed to handle request to %s: %s", q.FQDN, err)
-		}
-		return nil
-	}
-
-	// get remote address
 	remoteAddr, ok := w.RemoteAddr().(*net.UDPAddr)
 	if !ok {
 		log.Warningf("nameserver: failed to get remote address of request for %s%s, ignoring", q.FQDN, q.QType)
 		return nil
 	}
 
-	// check if the request is local
+	// Start context tracer for context-aware logging.
-	local, err := netenv.IsMyIP(remoteAddr.IP)
-	if err != nil {
-		log.Warningf("nameserver: failed to check if request for %s%s is local: %s", q.FQDN, q.QType, err)
-		return nil
-	}
-	if !local {
-		log.Warningf("nameserver: external request for %s%s, ignoring", q.FQDN, q.QType)
-		return nil
-	}
-
-	// check if valid domain name
-	if !netutils.IsValidFqdn(q.FQDN) {
-		log.Debugf("nameserver: domain name %s is invalid, returning nxdomain", q.FQDN)
-		sendResponse(w, query, 0, "invalid FQDN", nsutil.Refused())
-		return nil
-	}
-
-	// start tracer
 	ctx, tracer := log.AddTracer(ctx)
 	defer tracer.Submit()
-	tracer.Tracef("nameserver: handling new request for %s%s from %s:%d, getting connection", q.FQDN, q.QType, remoteAddr.IP, remoteAddr.Port)
+	tracer.Tracef("nameserver: handling new request for %s from %s:%d", q.ID(), remoteAddr.IP, remoteAddr.Port)
 
-	// TODO: if there are 3 request for the same domain/type in a row, delete all caches of that domain
+	// Check if there are more than one question.
+	if len(request.Question) > 1 {
+		tracer.Warningf("nameserver: received more than one question from (%s:%d), first question is %s", remoteAddr.IP, remoteAddr.Port, q.ID())
+	}
 
-	// get connection
+	// Setup quick reply function.
+	reply := func(responder nsutil.Responder, rrProviders ...nsutil.RRProvider) error {
+		return sendResponse(ctx, w, request, responder, rrProviders...)
+	}
+
+	// Return with server failure if offline.
+	if netenv.GetOnlineStatus() == netenv.StatusOffline &&
+		!netenv.IsConnectivityDomain(q.FQDN) {
+		tracer.Debugf("nameserver: not resolving %s, device is offline", q.FQDN)
+		return reply(nsutil.ServerFailure("resolving disabled, device is offline"))
+	}
+
+	// Check the Query Class.
+	if question.Qclass != dns.ClassINET {
+		// we only serve IN records, return nxdomain
+		tracer.Warningf("nameserver: only IN record requests are supported but received Qclass %d, returning NXDOMAIN", question.Qclass)
+		return reply(nsutil.Refused("unsupported qclass"))
+	}
+
+	// Handle request for localhost.
+	if strings.HasSuffix(q.FQDN, "localhost.") {
+		tracer.Tracef("nameserver: returning localhost records")
+		return reply(nsutil.Localhost())
+	}
+
+	// Authenticate request - only requests from the local host, but with any of its IPs, are allowed.
+	local, err := netenv.IsMyIP(remoteAddr.IP)
+	if err != nil {
+		tracer.Warningf("nameserver: failed to check if request for %s%s is local: %s", q.FQDN, q.QType, err)
+		return nil // Do no reply, drop request immediately.
+	}
+	if !local {
+		tracer.Warningf("nameserver: external request for %s%s, ignoring", q.FQDN, q.QType)
+		return nil // Do no reply, drop request immediately.
+	}
+
+	// Validate domain name.
+	if !netutils.IsValidFqdn(q.FQDN) {
+		tracer.Debugf("nameserver: domain name %s is invalid, refusing", q.FQDN)
+		return reply(nsutil.Refused("invalid domain"))
+	}
+
+	// Get connection for this request. This identifies the process behind the request.
 	conn := network.NewConnectionFromDNSRequest(ctx, q.FQDN, nil, packet.IPv4, remoteAddr.IP, uint16(remoteAddr.Port))
 
-	// once we decided on the connection we might need to save it to the database
+	// Once we decided on the connection we might need to save it to the database,
-	// so we defer that check right now.
+	// so we defer that check for now.
 	defer func() {
 		switch conn.Verdict {
-		// we immediately save blocked, dropped or failed verdicts so
+		// We immediately save blocked, dropped or failed verdicts so
-		// the pop up in the UI.
+		// they pop up in the UI.
 		case network.VerdictBlock, network.VerdictDrop, network.VerdictFailed:
 			conn.Save()
 
-		// for undecided or accepted connections we don't save them yet because
+		// For undecided or accepted connections we don't save them yet, because
 		// that will happen later anyway.
 		case network.VerdictUndecided, network.VerdictAccept,
 			network.VerdictRerouteToNameserver, network.VerdictRerouteToTunnel:
@@ -194,104 +170,80 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, query *dns.Msg) er
 		}
 	}()
 
-	// TODO: this has been obsoleted due to special profiles
+	// Check request with the privacy filter before resolving.
-	if conn.Process().Profile() == nil {
-		tracer.Infof("nameserver: failed to find process for request %s, returning NXDOMAIN", conn)
-		// NOTE(ppacher): saving unknown process connection might end up in a lot of
-		// processes. Consider disabling that via config.
-		conn.Failed("Unknown process")
-		sendResponse(w, query, conn.Verdict, conn.Reason, conn.ReasonContext)
-		return nil
-	}
-
-	// save security level to query
-	q.SecurityLevel = conn.Process().Profile().SecurityLevel()
-
-	// check profile before we even get intel and rr
 	firewall.DecideOnConnection(ctx, conn, nil)
 
-	switch conn.Verdict {
+	// Check if there is a responder from the firewall.
-	case network.VerdictBlock:
+	// In special cases, the firewall might want to respond the query itself.
-		tracer.Infof("nameserver: %s blocked, returning nxdomain", conn)
-		sendResponse(w, query, conn.Verdict, conn.Reason, conn.ReasonContext)
-		return nil
-	case network.VerdictDrop, network.VerdictFailed:
-		tracer.Infof("nameserver: %s dropped, not replying", conn)
-		return nil
-	}
-
-	// the firewall now decided on the connection and set it to accept
-	// If we have a reason context and that context implements nsutil.Responder
-	// we may need to responde with something else.
 	// A reason for this might be that the request is sink-holed to a forced
-	// ip address in which case we "Accept" it but handle the resolving
+	// IP address in which case we "accept" it, but let the firewall handle
-	// differently.
+	// the resolving as it wishes.
 	if responder, ok := conn.ReasonContext.(nsutil.Responder); ok {
-		tracer.Infof("nameserver: %s handing over to reason-responder: %s", q.FQDN, conn.Reason)
+		// Save the request as open, as we don't know if there will be a connection or not.
-		reply := responder.ReplyWithDNS(query, conn.Reason, conn.ReasonContext)
-		if err := w.WriteMsg(reply); err != nil {
-			tracer.Warningf("nameserver: failed to return response %s%s to %s: %s", q.FQDN, q.QType, conn.Process(), err)
-		} else {
-			tracer.Debugf("nameserver: returning response %s%s to %s", q.FQDN, q.QType, conn.Process())
-		}
-
-		// save dns request as open
 		network.SaveOpenDNSRequest(conn)
 
-		return nil
+		tracer.Infof("nameserver: handing over request for %s to special filter responder: %s", q.ID(), conn.Reason)
+		return reply(responder)
 	}
 
-	// resolve
+	// Check if there is Verdict to act upon.
+	switch conn.Verdict {
+	case network.VerdictBlock, network.VerdictDrop, network.VerdictFailed:
+		tracer.Infof("nameserver: request for %s from %s %s", q.ID(), conn.Process(), conn.Verdict.Verb())
+		return reply(conn, conn)
+	}
+
+	// Save security level to query, so that the resolver can react to configuration.
+	q.SecurityLevel = conn.Process().Profile().SecurityLevel()
+
+	// Resolve request.
 	rrCache, err := resolver.Resolve(ctx, q)
 	if err != nil {
-		// TODO: analyze nxdomain requests, malware could be trying DGA-domains
+		// React to special errors.
-		tracer.Debugf("nameserver: %s requested %s%s: %s", conn.Process(), q.FQDN, q.QType, err)
+		switch {
-
+		case errors.Is(err, resolver.ErrNotFound):
-		if errors.Is(err, resolver.ErrBlocked) {
+			tracer.Tracef("nameserver: %s", err)
-			conn.Block(err.Error())
+			return reply(nsutil.NxDomain("nxdomain: " + err.Error()))
-		} else {
+		case errors.Is(err, resolver.ErrBlocked):
-			conn.Failed("failed to resolve: " + err.Error())
+			tracer.Tracef("nameserver: %s", err)
+			return reply(nsutil.ZeroIP("blocked: " + err.Error()))
+		case errors.Is(err, resolver.ErrLocalhost):
+			tracer.Tracef("nameserver: returning localhost records")
+			return reply(nsutil.Localhost())
+		default:
+			tracer.Warningf("nameserver: failed to resolve %s: %s", q.ID(), err)
+			return reply(nsutil.ServerFailure("internal error: " + err.Error()))
 		}
-
+	}
-		sendResponse(w, query, conn.Verdict, conn.Reason, conn.ReasonContext)
+	if rrCache == nil {
-		return nil
+		tracer.Warning("nameserver: received successful, but empty reply from resolver")
+		return reply(nsutil.ServerFailure("internal error: empty reply"))
 	}
 
 	tracer.Trace("nameserver: deciding on resolved dns")
 	rrCache = firewall.DecideOnResolvedDNS(ctx, conn, q, rrCache)
 	if rrCache == nil {
-		sendResponse(w, query, conn.Verdict, conn.Reason, conn.ReasonContext)
+		// Check again if there is a responder from the firewall.
-		return nil
+		if responder, ok := conn.ReasonContext.(nsutil.Responder); ok {
-	}
+			// Save the request as open, as we don't know if there will be a connection or not.
-
-	// reply to query
-	m := new(dns.Msg)
-	m.SetReply(query)
-	m.Answer = rrCache.Answer
-	m.Ns = rrCache.Ns
-	m.Extra = rrCache.Extra
-
-	if err := writeDNSResponse(w, m); err != nil {
-		tracer.Warningf("nameserver: failed to return response %s%s to %s: %s", q.FQDN, q.QType, conn.Process(), err)
-	} else {
-		tracer.Debugf("nameserver: returning response %s%s to %s", q.FQDN, q.QType, conn.Process())
-	}
-
-	// save dns request as open
 			network.SaveOpenDNSRequest(conn)
 
-	return nil
+			tracer.Infof("nameserver: handing over request for %s to filter responder: %s", q.ID(), conn.Reason)
+			return reply(responder)
 		}
 
-func writeDNSResponse(w dns.ResponseWriter, m *dns.Msg) (err error) {
+		// Request was blocked by the firewall.
-	defer func() {
+		switch conn.Verdict {
-		// recover from panic
+		case network.VerdictBlock, network.VerdictDrop, network.VerdictFailed:
-		if panicErr := recover(); panicErr != nil {
+			tracer.Infof("nameserver: %s request for %s from %s", conn.Verdict.Verb(), q.ID(), conn.Process())
-			err = fmt.Errorf("panic: %s", panicErr)
+			return reply(conn, conn)
-			log.Warningf("nameserver: panic caused by this msg: %#v", m)
+		}
 	}
-	}()
 
-	err = w.WriteMsg(m)
+	// Save dns request as open.
-	return
+	defer network.SaveOpenDNSRequest(conn)
+
+	// Reply with successful response.
+	tracer.Infof("nameserver: returning %s response for %s to %s", conn.Verdict.Verb(), q.ID(), conn.Process())
+	return reply(rrCache, conn, rrCache)
 }

nameserver/nsutil/nsutil.go

@@ -1,6 +1,11 @@
 package nsutil
 
 import (
+	"context"
+	"errors"
+	"fmt"
+	"strings"
+
 	"github.com/miekg/dns"
 	"github.com/safing/portbase/log"
 )
@@ -13,35 +18,35 @@ import (
 type Responder interface {
 	// ReplyWithDNS is called when a DNS response to a DNS message is
 	// crafted because the request is either denied or blocked.
-	ReplyWithDNS(query *dns.Msg, reason string, reasonCtx interface{}) *dns.Msg
+	ReplyWithDNS(ctx context.Context, request *dns.Msg) *dns.Msg
 }
 
 // RRProvider defines the interface that any block/deny reason interface
 // may implement to support adding additional DNS resource records to
 // the DNS responses extra (additional) section.
 type RRProvider interface {
-	// GetExtraRR is called when a DNS response to a DNS message is
+	// GetExtraRRs is called when a DNS response to a DNS message is
 	// crafted because the request is either denied or blocked.
-	GetExtraRR(query *dns.Msg, reason string, reasonCtx interface{}) []dns.RR
+	GetExtraRRs(ctx context.Context, request *dns.Msg) []dns.RR
 }
 
 // ResponderFunc is a convenience type to use a function
 // directly as a Responder.
-type ResponderFunc func(query *dns.Msg, reason string, reasonCtx interface{}) *dns.Msg
+type ResponderFunc func(ctx context.Context, request *dns.Msg) *dns.Msg
 
 // ReplyWithDNS implements the Responder interface and calls rf.
-func (rf ResponderFunc) ReplyWithDNS(query *dns.Msg, reason string, reasonCtx interface{}) *dns.Msg {
+func (rf ResponderFunc) ReplyWithDNS(ctx context.Context, request *dns.Msg) *dns.Msg {
-	return rf(query, reason, reasonCtx)
+	return rf(ctx, request)
 }
 
 // ZeroIP is a ResponderFunc than replies with either 0.0.0.0 or :: for
 // each A or AAAA question respectively.
-func ZeroIP() ResponderFunc {
+func ZeroIP(msgs ...string) ResponderFunc {
-	return func(query *dns.Msg, _ string, _ interface{}) *dns.Msg {
+	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
-		m := new(dns.Msg)
+		reply := new(dns.Msg)
 		hasErr := false
 
-		for _, question := range query.Question {
+		for _, question := range request.Question {
 			var rr dns.RR
 			var err error
 
@@ -53,40 +58,131 @@ func ZeroIP() ResponderFunc {
 			}
 
 			if err != nil {
-				log.Errorf("nameserver: failed to create zero-ip response for %s: %s", question.Name, err)
+				log.Tracer(ctx).Errorf("nameserver: failed to create zero-ip response for %s: %s", question.Name, err)
 				hasErr = true
 			} else {
-				m.Answer = append(m.Answer, rr)
+				reply.Answer = append(reply.Answer, rr)
 			}
 		}
 
-		if hasErr && len(m.Answer) == 0 {
+		switch {
-			m.SetRcode(query, dns.RcodeServerFailure)
+		case hasErr && len(reply.Answer) == 0:
+			reply.SetRcode(request, dns.RcodeServerFailure)
+		case len(reply.Answer) == 0:
+			reply.SetRcode(request, dns.RcodeNameError)
+		default:
+			reply.SetRcode(request, dns.RcodeSuccess)
+		}
+
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
+
+		return reply
+	}
+}
+
+// Localhost is a ResponderFunc than replies with localhost IP addresses.
+func Localhost(msgs ...string) ResponderFunc {
+	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
+		reply := new(dns.Msg)
+		hasErr := false
+
+		for _, question := range request.Question {
+			var rr dns.RR
+			var err error
+
+			switch question.Qtype {
+			case dns.TypeA:
+				rr, err = dns.NewRR("localhost. 0 IN A 127.0.0.1")
+			case dns.TypeAAAA:
+				rr, err = dns.NewRR("localhost. 0 IN AAAA ::1")
+			}
+
+			if err != nil {
+				log.Tracer(ctx).Errorf("nameserver: failed to create localhost response for %s: %s", question.Name, err)
+				hasErr = true
 			} else {
-			m.SetRcode(query, dns.RcodeSuccess)
+				reply.Answer = append(reply.Answer, rr)
+			}
 		}
 
-		return m
+		switch {
+		case hasErr && len(reply.Answer) == 0:
+			reply.SetRcode(request, dns.RcodeServerFailure)
+		case len(reply.Answer) == 0:
+			reply.SetRcode(request, dns.RcodeNameError)
+		default:
+			reply.SetRcode(request, dns.RcodeSuccess)
+		}
+
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
+
+		return reply
 	}
 }
 
 // NxDomain returns a ResponderFunc that replies with NXDOMAIN.
-func NxDomain() ResponderFunc {
+func NxDomain(msgs ...string) ResponderFunc {
-	return func(query *dns.Msg, _ string, _ interface{}) *dns.Msg {
+	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
-		return new(dns.Msg).SetRcode(query, dns.RcodeNameError)
+		reply := new(dns.Msg).SetRcode(request, dns.RcodeNameError)
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
+		return reply
 	}
 }
 
 // Refused returns a ResponderFunc that replies with REFUSED.
-func Refused() ResponderFunc {
+func Refused(msgs ...string) ResponderFunc {
-	return func(query *dns.Msg, _ string, _ interface{}) *dns.Msg {
+	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
-		return new(dns.Msg).SetRcode(query, dns.RcodeRefused)
+		reply := new(dns.Msg).SetRcode(request, dns.RcodeRefused)
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
+		return reply
 	}
 }
 
-// ServeFail returns a ResponderFunc that replies with SERVFAIL.
+// ServerFailure returns a ResponderFunc that replies with SERVFAIL.
-func ServeFail() ResponderFunc {
+func ServerFailure(msgs ...string) ResponderFunc {
-	return func(query *dns.Msg, _ string, _ interface{}) *dns.Msg {
+	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
-		return new(dns.Msg).SetRcode(query, dns.RcodeServerFailure)
+		reply := new(dns.Msg).SetRcode(request, dns.RcodeServerFailure)
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
+		return reply
+	}
+}
+
+// MakeMessageRecord creates an informational resource record that can be added
+// to the extra section of a reply.
+func MakeMessageRecord(level log.Severity, msg string) (dns.RR, error) { //nolint:interfacer
+	rr, err := dns.NewRR(fmt.Sprintf(
+		`%s.portmaster. 0 IN TXT "%s"`,
+		strings.ToLower(level.String()),
+		msg,
+	))
+	if err != nil {
+		return nil, err
+	}
+	if rr == nil {
+		return nil, errors.New("record is nil")
+	}
+	return rr, nil
+}
+
+// AddMessagesToReply creates information resource records using
+// MakeMessageRecord and immediately adds them to the extra section of the given
+// reply. If an error occurs, the resource record will not be added, and the
+// error will be logged.
+func AddMessagesToReply(ctx context.Context, reply *dns.Msg, level log.Severity, msgs ...string) {
+	for _, msg := range msgs {
+		// Ignore empty messages.
+		if msg == "" {
+			continue
+		}
+
+		// Create resources record.
+		rr, err := MakeMessageRecord(level, msg)
+		if err != nil {
+			log.Tracer(ctx).Warningf("nameserver: failed to add message to reply: %s", err)
+			continue
+		}
+
+		// Add to extra section of the reply.
+		reply.Extra = append(reply.Extra, rr)
 	}
 }

nameserver/response.go

@@ -1,36 +1,66 @@
 package nameserver
 
 import (
+	"context"
+	"fmt"
+
 	"github.com/miekg/dns"
 	"github.com/safing/portbase/log"
 	"github.com/safing/portmaster/nameserver/nsutil"
-	"github.com/safing/portmaster/network"
 )
 
-// sendResponse sends a response to query using w. If reasonCtx is not
+// sendResponse sends a response to query using w. The response message is
-// nil and implements either the Responder or RRProvider interface then
+// created by responder. If addExtraRRs is not nil and implements the
-// those functions are used to craft a DNS response. If reasonCtx is nil
+// RRProvider interface then it will be also used to add more RRs in the
-// or does not implement the Responder interface and verdict is not set
+// extra section.
-// to failed a ZeroIP response will be sent. If verdict is set to failed
+func sendResponse(
-// then a ServFail will be sent instead.
+	ctx context.Context,
-func sendResponse(w dns.ResponseWriter, query *dns.Msg, verdict network.Verdict, reason string, reasonCtx interface{}) {
+	w dns.ResponseWriter,
-	responder, ok := reasonCtx.(nsutil.Responder)
+	request *dns.Msg,
-	if !ok {
+	responder nsutil.Responder,
-		if verdict == network.VerdictFailed {
+	rrProviders ...nsutil.RRProvider,
-			responder = nsutil.ServeFail()
+) error {
-		} else {
+	// Have the Responder craft a DNS reply.
-			responder = nsutil.ZeroIP()
+	reply := responder.ReplyWithDNS(ctx, request)
-		}
+	if reply == nil {
+		// Dropping query.
+		return nil
 	}
 
-	reply := responder.ReplyWithDNS(query, reason, reasonCtx)
+	// Add extra RRs through a custom RRProvider.
-
+	for _, rrProvider := range rrProviders {
-	if extra, ok := reasonCtx.(nsutil.RRProvider); ok {
+		if rrProvider != nil {
-		rrs := extra.GetExtraRR(query, reason, reasonCtx)
+			rrs := rrProvider.GetExtraRRs(ctx, request)
 			reply.Extra = append(reply.Extra, rrs...)
 		}
+	}
 
+	// Write reply.
 	if err := writeDNSResponse(w, reply); err != nil {
-		log.Errorf("nameserver: failed to send response: %s", err)
+		return fmt.Errorf("nameserver: failed to send response: %w", err)
+	}
+
+	return nil
+}
+
+func writeDNSResponse(w dns.ResponseWriter, m *dns.Msg) (err error) {
+	defer func() {
+		// recover from panic
+		if panicErr := recover(); panicErr != nil {
+			err = fmt.Errorf("panic: %s", panicErr)
+			log.Warningf("nameserver: panic caused by this msg: %#v", m)
+		}
+	}()
+
+	err = w.WriteMsg(m)
+	if err != nil {
+		// If we receive an error we might have exceeded the message size with all
+		// our extra information records. Retry again without the extra section.
+		m.Extra = nil
+		noExtraErr := w.WriteMsg(m)
+		if noExtraErr == nil {
+			log.Warningf("nameserver: failed to write dns message with extra section: %s", err)
 		}
 	}
+	return
+}

network/database.go

@@ -129,7 +129,6 @@ func registerAsDatabase() error {
 		Name:        "network",
 		Description: "Network and Firewall Data",
 		StorageType: "injected",
-		PrimaryAPI:  "",
 	})
 	if err != nil {
 		return err

network/dns.go

@@ -2,10 +2,14 @@ package network
 
 import (
 	"context"
+	"fmt"
 	"strconv"
 	"sync"
 	"time"
 
+	"github.com/miekg/dns"
+	"github.com/safing/portbase/log"
+	"github.com/safing/portmaster/nameserver/nsutil"
 	"github.com/safing/portmaster/process"
 )
 
@@ -88,3 +92,48 @@ func writeOpenDNSRequestsToDB() {
 		conn.Unlock()
 	}
 }
+
+// ReplyWithDNS creates a new reply to the given request with the data from the RRCache, and additional informational records.
+func (conn *Connection) ReplyWithDNS(ctx context.Context, request *dns.Msg) *dns.Msg {
+	// Select request responder.
+	switch conn.Verdict {
+	case VerdictBlock:
+		return nsutil.ZeroIP().ReplyWithDNS(ctx, request)
+	case VerdictDrop:
+		return nil // Do not respond to request.
+	case VerdictFailed:
+		return nsutil.ZeroIP().ReplyWithDNS(ctx, request)
+	default:
+		reply := nsutil.ServerFailure().ReplyWithDNS(ctx, request)
+		nsutil.AddMessagesToReply(ctx, reply, log.ErrorLevel, "INTERNAL ERROR: incorrect use of Connection DNS Responder")
+		return reply
+	}
+}
+
+// GetExtraRRs returns a slice of RRs with additional informational records.
+func (conn *Connection) GetExtraRRs(ctx context.Context, request *dns.Msg) []dns.RR {
+	// Select level to add the verdict record with.
+	var level log.Severity
+	switch conn.Verdict {
+	case VerdictFailed:
+		level = log.ErrorLevel
+	default:
+		level = log.InfoLevel
+	}
+
+	// Create resource record with verdict and reason.
+	rr, err := nsutil.MakeMessageRecord(level, fmt.Sprintf("%s: %s", conn.Verdict.Verb(), conn.Reason))
+	if err != nil {
+		log.Tracer(ctx).Warningf("filter: failed to add informational record to reply: %s", err)
+		return nil
+	}
+	extra := []dns.RR{rr}
+
+	// Add additional records from ReasonContext.
+	if rrProvider, ok := conn.ReasonContext.(nsutil.RRProvider); ok {
+		rrs := rrProvider.GetExtraRRs(ctx, request)
+		extra = append(extra, rrs...)
+	}
+
+	return extra
+}

network/status.go

@@ -39,6 +39,30 @@ func (v Verdict) String() string {
 	}
 }
 
+// Verb returns the verdict as a past tense verb.
+func (v Verdict) Verb() string {
+	switch v {
+	case VerdictUndecided:
+		return "undecided"
+	case VerdictUndeterminable:
+		return "undeterminable"
+	case VerdictAccept:
+		return "accepted"
+	case VerdictBlock:
+		return "blocked"
+	case VerdictDrop:
+		return "dropped"
+	case VerdictRerouteToNameserver:
+		return "rerouted to nameserver"
+	case VerdictRerouteToTunnel:
+		return "rerouted to tunnel"
+	case VerdictFailed:
+		return "failed"
+	default:
+		return "invalid"
+	}
+}
+
 // Packer Directions
 const (
 	Inbound  = true

resolver/config.go

@@ -32,8 +32,8 @@ var (
 		// `dot://1.0.0.2:853?verify=cloudflare-dns.com&name=Cloudflare&blockedif=zeroip`,
 
 		// AdGuard (encrypted DNS, default flavor)
-		// `dot://176.103.130.130:853?verify=dns.adguard.com&name=AdGuard&blockedif=zeroip`,
+		// `dot://94.140.14.14:853?verify=dns.adguard.com&name=AdGuard&blockedif=zeroip`,
-		// `dot://176.103.130.131:853?verify=dns.adguard.com&name=AdGuard&blockedif=zeroip`,
+		// `dot://94.140.15.15:853?verify=dns.adguard.com&name=AdGuard&blockedif=zeroip`,
 
 		// Foundation for Applied Privacy (encrypted DNS)
 		// `dot://94.130.106.88:853?verify=dot1.applied-privacy.net&name=AppliedPrivacy`,
@@ -48,8 +48,8 @@ var (
 		// `dns://1.0.0.2:53?name=Cloudflare&blockedif=zeroip`,
 
 		// AdGuard (plain DNS, default flavor)
-		// `dns://176.103.130.130&name=AdGuard&blockedif=zeroip`,
+		// `dns://94.140.14.14&name=AdGuard&blockedif=zeroip`,
-		// `dns://176.103.130.131&name=AdGuard&blockedif=zeroip`,
+		// `dns://94.140.15.15&name=AdGuard&blockedif=zeroip`,
 	}
 
 	CfgOptionNameServersKey   = "dns/nameservers"
@@ -96,7 +96,7 @@ IP:
 	always use the IP address and _not_ the domain name!
 
 Port:
-	always add the port!
+	optionally define a custom port
 
 Parameters:
 	name: give your DNS Server a name that is used for messages and logs

resolver/namerecord.go

@@ -28,6 +28,7 @@ type NameRecord struct {
 
 	Domain   string
 	Question string
+	RCode    int
 	Answer   []string
 	Ns       []string
 	Extra    []string
@@ -35,6 +36,7 @@ type NameRecord struct {
 
 	Server      string
 	ServerScope int8
+	ServerInfo  string
 }
 
 func makeNameRecordKey(domain string, question string) string {
@@ -85,48 +87,13 @@ func (rec *NameRecord) Save() error {
 	return recordDatabase.PutNew(rec)
 }
 
-func clearNameCache(_ context.Context, _ interface{}) error {
+func clearNameCache(ctx context.Context, _ interface{}) error {
-	log.Debugf("resolver: name cache clearing started...")
+	log.Debugf("resolver: dns cache clearing started...")
-	for {
+	n, err := recordDatabase.Purge(ctx, query.New(nameRecordsKeyPrefix))
-		done, err := removeNameEntries(10000)
 	if err != nil {
 		return err
 	}
 
-		if done {
+	log.Debugf("resolver: cleared %d entries in dns cache", n)
 	return nil
 }
-	}
-}
-
-func removeNameEntries(batchSize int) (bool, error) {
-	iter, err := recordDatabase.Query(query.New(nameRecordsKeyPrefix))
-	if err != nil {
-		return false, err
-	}
-
-	keys := make([]string, 0, batchSize)
-
-	var cnt int
-	for r := range iter.Next {
-		cnt++
-		keys = append(keys, r.Key())
-
-		if cnt == batchSize {
-			break
-		}
-	}
-	iter.Cancel()
-
-	for _, key := range keys {
-		if err := recordDatabase.Delete(key); err != nil {
-			log.Warningf("resolver: failed to remove name cache entry %q: %s", key, err)
-		}
-	}
-
-	log.Debugf("resolver: successfully removed %d name cache entries", cnt)
-
-	// if we removed less entries that the batch size we
-	// are done and no more entries exist
-	return cnt < batchSize, nil
-}

resolver/resolve.go

@@ -47,6 +47,7 @@ var (
 
 const (
 	minTTL     = 60 // 1 Minute
+	refreshTTL = minTTL / 2
 	minMDnsTTL = 60           // 1 Minute
 	maxTTL     = 24 * 60 * 60 // 24 hours
 )
@@ -120,6 +121,9 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
 	}
 
 	// log
+	// try adding a context tracer
+	ctx, tracer := log.AddTracer(ctx)
+	defer tracer.Submit()
 	log.Tracer(ctx).Tracef("resolver: resolving %s%s", q.FQDN, q.QType)
 
 	// check query compliance
@@ -130,8 +134,7 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
 	// check the cache
 	if !q.NoCaching {
 		rrCache = checkCache(ctx, q)
-		if rrCache != nil {
+		if rrCache != nil && !rrCache.Expired() {
-			rrCache.MixAnswers()
 			return rrCache, nil
 		}
 
@@ -140,8 +143,7 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
 		if markRequestFinished == nil {
 			// we waited for another request, recheck the cache!
 			rrCache = checkCache(ctx, q)
-			if rrCache != nil {
+			if rrCache != nil && !rrCache.Expired() {
-				rrCache.MixAnswers()
 				return rrCache, nil
 			}
 			log.Tracer(ctx).Debugf("resolver: waited for another %s%s query, but cache missed!", q.FQDN, q.QType)
@@ -149,17 +151,22 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
 		} else {
 			// we are the first!
 			defer markRequestFinished()
-
 		}
 	}
 
-	return resolveAndCache(ctx, q)
+	return resolveAndCache(ctx, q, rrCache)
 }
 
 func checkCache(ctx context.Context, q *Query) *RRCache {
+	// Never ask cache for connectivity domains.
+	if netenv.IsConnectivityDomain(q.FQDN) {
+		return nil
+	}
+
+	// Get data from cache.
 	rrCache, err := GetRRCache(q.FQDN, q.QType)
 
-	// failed to get from cache
+	// Return if entry is not in cache.
 	if err != nil {
 		if err != database.ErrNotFound {
 			log.Tracer(ctx).Warningf("resolver: getting RRCache %s%s from database failed: %s", q.FQDN, q.QType.String(), err)
@@ -167,21 +174,21 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
 		return nil
 	}
 
-	// get resolver that rrCache was resolved with
+	// Get the resolver that the rrCache was resolved with.
 	resolver := getActiveResolverByIDWithLocking(rrCache.Server)
 	if resolver == nil {
 		log.Tracer(ctx).Debugf("resolver: ignoring RRCache %s%s because source server %s has been removed", q.FQDN, q.QType.String(), rrCache.Server)
 		return nil
 	}
 
-	// check compliance of resolver
+	// Check compliance of the resolver, return if non-compliant.
 	err = resolver.checkCompliance(ctx, q)
 	if err != nil {
 		log.Tracer(ctx).Debugf("resolver: cached entry for %s%s does not comply to query parameters: %s", q.FQDN, q.QType.String(), err)
 		return nil
 	}
 
-	// check if we want to reset the cache
+	// Check if we want to reset the cache for this entry.
 	if shouldResetCache(q) {
 		err := DeleteNameRecord(q.FQDN, q.QType.String())
 		switch {
@@ -195,27 +202,39 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
 		return nil
 	}
 
-	// check if expired
+	// Check if the cache has already expired.
+	// We still return the cache, if it isn't NXDomain, as it will be used if the
+	// new query fails.
 	if rrCache.Expired() {
-		if netenv.IsConnectivityDomain(rrCache.Domain) {
+		if rrCache.RCode == dns.RcodeSuccess {
-			// do not use cache, resolve immediately
+			return rrCache
+		}
 		return nil
 	}
 
+	// Check if the cache will expire soon and start an async request.
+	if rrCache.ExpiresSoon() {
+		// Set flag that we are refreshing this entry.
 		rrCache.Lock()
 		rrCache.requestingNew = true
 		rrCache.Unlock()
 
 		log.Tracer(ctx).Tracef(
-			"resolver: using expired RR from cache (since %s), refreshing async now",
+			"resolver: cache for %s will expire in %s, refreshing async now",
-			time.Since(time.Unix(rrCache.TTL, 0)),
+			q.ID(),
+			time.Until(time.Unix(rrCache.TTL, 0)).Round(time.Second),
 		)
 
 		// resolve async
 		module.StartWorker("resolve async", func(ctx context.Context) error {
-			_, err := resolveAndCache(ctx, q)
+			ctx, tracer := log.AddTracer(ctx)
+			defer tracer.Submit()
+			tracer.Debugf("resolver: resolving %s async", q.ID())
+			_, err := resolveAndCache(ctx, q, nil)
 			if err != nil {
-				log.Warningf("resolver: async query for %s%s failed: %s", q.FQDN, q.QType, err)
+				tracer.Warningf("resolver: async query for %s failed: %s", q.ID(), err)
+			} else {
+				tracer.Debugf("resolver: async query for %s succeeded", q.ID())
 			}
 			return nil
 		})
@@ -225,7 +244,7 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
 
 	log.Tracer(ctx).Tracef(
 		"resolver: using cached RR (expires in %s)",
-		time.Until(time.Unix(rrCache.TTL, 0)),
+		time.Until(time.Unix(rrCache.TTL, 0)).Round(time.Second),
 	)
 	return rrCache
 }
@@ -290,7 +309,7 @@ retry:
 	}
 }
 
-func resolveAndCache(ctx context.Context, q *Query) (rrCache *RRCache, err error) { //nolint:gocognit
+func resolveAndCache(ctx context.Context, q *Query, oldCache *RRCache) (rrCache *RRCache, err error) { //nolint:gocognit,gocyclo
 	// get resolvers
 	resolvers, tryAll := GetResolversInScope(ctx, q)
 	if len(resolvers) == 0 {
@@ -358,31 +377,51 @@ resolveLoop:
 				// Defensive: This should normally not happen.
 				continue
 			}
+			// Check if request succeeded and whether we should try another resolver.
+			if rrCache.RCode != dns.RcodeSuccess && tryAll {
+				continue
+			}
 			break resolveLoop
 		}
 	}
 
-	// check for error
+	// Post-process errors
 	if err != nil {
 		// tried all resolvers, possibly twice
 		if i > 1 {
-			return nil, fmt.Errorf("all %d query-compliant resolvers failed, last error: %s", len(resolvers), err)
+			err = fmt.Errorf("all %d query-compliant resolvers failed, last error: %s", len(resolvers), err)
 		}
+	} else if rrCache == nil /* defensive */ {
+		err = ErrNotFound
+	}
+
+	// Check if we want to use an older cache instead.
+	if oldCache != nil {
+		oldCache.isBackup = true
+
+		switch {
+		case err != nil:
+			// There was an error during resolving, return the old cache entry instead.
+			log.Tracer(ctx).Debugf("resolver: serving backup cache of %s because query failed: %s", q.ID(), err)
+			return oldCache, nil
+		case !rrCache.Cacheable():
+			// The new result is NXDomain, return the old cache entry instead.
+			log.Tracer(ctx).Debugf("resolver: serving backup cache of %s because fresh response is NXDomain", q.ID())
+			return oldCache, nil
+		}
+	}
+
+	// Return error, if there is one.
+	if err != nil {
 		return nil, err
 	}
 
-	// check for result
+	// Save the new entry if cache is enabled.
-	if rrCache == nil /* defensive */ {
+	if !q.NoCaching && rrCache.Cacheable() {
-		return nil, ErrNotFound
-	}
-
-	// cache if enabled
-	if !q.NoCaching {
-		// persist to database
 		rrCache.Clean(minTTL)
 		err = rrCache.Save()
 		if err != nil {
-			log.Warningf("resolver: failed to cache RR for %s%s: %s", q.FQDN, q.QType.String(), err)
+			log.Tracer(ctx).Warningf("resolver: failed to cache RR for %s: %s", q.ID(), err)
 		}
 	}
 

resolver/resolver-env.go

@@ -23,6 +23,7 @@ var (
 		Server:        ServerSourceEnv,
 		ServerType:    ServerTypeEnv,
 		ServerIPScope: netutils.SiteLocal,
+		ServerInfo:    "Portmaster environment",
 		Source:        ServerSourceEnv,
 		Conn:          &envResolverConn{},
 	}
@@ -110,10 +111,12 @@ func (er *envResolverConn) makeRRCache(q *Query, answers []dns.RR) *RRCache {
 	return &RRCache{
 		Domain:      q.FQDN,
 		Question:    q.QType,
+		RCode:       dns.RcodeSuccess,
 		Answer:      answers,
 		Extra:       []dns.RR{internalSpecialUseComment}, // Always add comment about this TLD.
 		Server:      envResolver.Server,
 		ServerScope: envResolver.ServerIPScope,
+		ServerInfo:  envResolver.ServerInfo,
 	}
 }
 

resolver/resolver-mdns.go

@@ -34,6 +34,7 @@ var (
 		Server:        ServerSourceMDNS,
 		ServerType:    ServerTypeDNS,
 		ServerIPScope: netutils.SiteLocal,
+		ServerInfo:    "mDNS resolver",
 		Source:        ServerSourceMDNS,
 		Conn:          &mDNSResolverConn{},
 	}
@@ -201,8 +202,10 @@ func handleMDNSMessages(ctx context.Context, messages chan *dns.Msg) error {
 					rrCache = &RRCache{
 						Domain:      question.Name,
 						Question:    dns.Type(question.Qtype),
+						RCode:       dns.RcodeSuccess,
 						Server:      mDNSResolver.Server,
 						ServerScope: mDNSResolver.ServerIPScope,
+						ServerInfo:  mDNSResolver.ServerInfo,
 					}
 				}
 			}
@@ -301,9 +304,11 @@ func handleMDNSMessages(ctx context.Context, messages chan *dns.Msg) error {
 				rrCache = &RRCache{
 					Domain:      v.Header().Name,
 					Question:    dns.Type(v.Header().Class),
+					RCode:       dns.RcodeSuccess,
 					Answer:      []dns.RR{v},
 					Server:      mDNSResolver.Server,
 					ServerScope: mDNSResolver.ServerIPScope,
+					ServerInfo:  mDNSResolver.ServerInfo,
 				}
 				rrCache.Clean(minMDnsTTL)
 				err := rrCache.Save()
@@ -416,7 +421,15 @@ func queryMulticastDNS(ctx context.Context, q *Query) (*RRCache, error) {
 		}
 	}
 
-	return nil, ErrNotFound
+	// Respond with NXDomain.
+	return &RRCache{
+		Domain:      q.FQDN,
+		Question:    q.QType,
+		RCode:       dns.RcodeNameError,
+		Server:      mDNSResolver.Server,
+		ServerScope: mDNSResolver.ServerIPScope,
+		ServerInfo:  mDNSResolver.ServerInfo,
+	}, nil
 }
 
 func cleanSavedQuestions() {

resolver/resolver-plain.go

@@ -81,11 +81,13 @@ func (pr *PlainResolver) Query(ctx context.Context, q *Query) (*RRCache, error)
 	newRecord := &RRCache{
 		Domain:      q.FQDN,
 		Question:    q.QType,
+		RCode:       reply.Rcode,
 		Answer:      reply.Answer,
 		Ns:          reply.Ns,
 		Extra:       reply.Extra,
 		Server:      pr.resolver.Server,
 		ServerScope: pr.resolver.ServerIPScope,
+		ServerInfo:  pr.resolver.ServerInfo,
 	}
 
 	// TODO: check if reply.Answer is valid

resolver/resolver-tcp.go

@@ -3,6 +3,8 @@ package resolver
 import (
 	"context"
 	"crypto/tls"
+	"errors"
+	"io"
 	"net"
 	"sync/atomic"
 	"time"
@@ -26,6 +28,8 @@ type TCPResolver struct {
 	dnsClient *dns.Client
 
 	clientStarted   *abool.AtomicBool
+	clientHeartbeat chan struct{}
+	clientCancel    func()
 	connInstanceID  *uint32
 	queries         chan *dns.Msg
 	inFlightQueries map[uint16]*InFlightQuery
@@ -46,11 +50,13 @@ func (ifq *InFlightQuery) MakeCacheRecord(reply *dns.Msg) *RRCache {
 	return &RRCache{
 		Domain:      ifq.Query.FQDN,
 		Question:    ifq.Query.QType,
+		RCode:       reply.Rcode,
 		Answer:      reply.Answer,
 		Ns:          reply.Ns,
 		Extra:       reply.Extra,
 		Server:      ifq.Resolver.Server,
 		ServerScope: ifq.Resolver.ServerIPScope,
+		ServerInfo:  ifq.Resolver.ServerInfo,
 	}
 }
 
@@ -67,10 +73,12 @@ func NewTCPResolver(resolver *Resolver) *TCPResolver {
 			Timeout:      defaultConnectTimeout,
 			WriteTimeout: tcpWriteTimeout,
 		},
+		clientStarted:   abool.New(),
+		clientHeartbeat: make(chan struct{}),
+		clientCancel:    func() {},
 		connInstanceID:  &instanceID,
 		queries:         make(chan *dns.Msg, 100),
 		inFlightQueries: make(map[uint16]*InFlightQuery),
-		clientStarted:   abool.New(),
 	}
 }
 
@@ -145,6 +153,7 @@ func (tr *TCPResolver) Query(ctx context.Context, q *Query) (*RRCache, error) {
 	// submit to client
 	inFlight := tr.submitQuery(ctx, q)
 	if inFlight == nil {
+		tr.checkClientStatus()
 		return nil, ErrTimeout
 	}
 
@@ -152,6 +161,7 @@ func (tr *TCPResolver) Query(ctx context.Context, q *Query) (*RRCache, error) {
 	select {
 	case reply = <-inFlight.Response:
 	case <-time.After(defaultRequestTimeout):
+		tr.checkClientStatus()
 		return nil, ErrTimeout
 	}
 
@@ -167,6 +177,22 @@ func (tr *TCPResolver) Query(ctx context.Context, q *Query) (*RRCache, error) {
 	return inFlight.MakeCacheRecord(reply), nil
 }
 
+func (tr *TCPResolver) checkClientStatus() {
+	// Get client cancel function before waiting in order to not immediately
+	// cancel a new client.
+	tr.Lock()
+	cancelClient := tr.clientCancel
+	tr.Unlock()
+
+	// Check if the client is alive with the heartbeat, if not shut it down.
+	select {
+	case tr.clientHeartbeat <- struct{}{}:
+	case <-time.After(defaultRequestTimeout):
+		log.Warningf("resolver: heartbeat failed for %s dns client, stopping", tr.resolver.GetName())
+		cancelClient()
+	}
+}
+
 type tcpResolverConnMgr struct {
 	tr        *TCPResolver
 	responses chan *dns.Msg
@@ -184,8 +210,14 @@ func (tr *TCPResolver) startClient() {
 }
 
 func (mgr *tcpResolverConnMgr) run(workerCtx context.Context) error {
-	mgr.tr.clientStarted.Set()
 	defer mgr.shutdown()
+	mgr.tr.clientStarted.Set()
+
+	// Create additional cancel function for this worker.
+	workerCtx, cancelWorker := context.WithCancel(workerCtx)
+	mgr.tr.Lock()
+	mgr.tr.clientCancel = cancelWorker
+	mgr.tr.Unlock()
 
 	// connection lifecycle loop
 	for {
@@ -208,7 +240,7 @@ func (mgr *tcpResolverConnMgr) run(workerCtx context.Context) error {
 		}
 
 		// create connection
-		conn, connClosing, connCtx, cancelConnCtx := mgr.establishConnection(workerCtx)
+		conn, connClosing, connCtx, cancelConnCtx := mgr.establishConnection()
 		if conn == nil {
 			mgr.failCnt++
 			continue
@@ -293,7 +325,7 @@ func (mgr *tcpResolverConnMgr) waitForWork(workerCtx context.Context) (proceed b
 	return true
 }
 
-func (mgr *tcpResolverConnMgr) establishConnection(workerCtx context.Context) (
+func (mgr *tcpResolverConnMgr) establishConnection() (
 	conn *dns.Conn,
 	connClosing *abool.AtomicBool,
 	connCtx context.Context,
@@ -313,10 +345,21 @@ func (mgr *tcpResolverConnMgr) establishConnection(workerCtx context.Context) (
 		log.Debugf("resolver: failed to connect to %s (%s)", mgr.tr.resolver.GetName(), mgr.tr.resolver.ServerAddress)
 		return nil, nil, nil, nil
 	}
-	connCtx, cancelConnCtx = context.WithCancel(workerCtx)
+	connCtx, cancelConnCtx = context.WithCancel(context.Background())
 	connClosing = abool.New()
 
-	log.Debugf("resolver: connected to %s (%s)", mgr.tr.resolver.GetName(), conn.RemoteAddr())
+	// Get amount of in waiting queries.
+	mgr.tr.Lock()
+	waitingQueries := len(mgr.tr.inFlightQueries)
+	mgr.tr.Unlock()
+
+	// Log that a connection to the resolver was established.
+	log.Debugf(
+		"resolver: connected to %s (%s) with %d queries waiting",
+		mgr.tr.resolver.GetName(),
+		conn.RemoteAddr(),
+		waitingQueries,
+	)
 
 	// start reader
 	module.StartServiceWorker("dns client reader", 10*time.Millisecond, func(workerCtx context.Context) error {
@@ -348,6 +391,9 @@ func (mgr *tcpResolverConnMgr) queryHandler( //nolint:golint // context.Context
 
 	for {
 		select {
+		case <-mgr.tr.clientHeartbeat:
+			// respond to alive checks
+
 		case <-workerCtx.Done():
 			// module shutdown
 			return false
@@ -372,9 +418,7 @@ func (mgr *tcpResolverConnMgr) queryHandler( //nolint:golint // context.Context
 			_ = conn.SetWriteDeadline(time.Now().Add(mgr.tr.dnsClient.WriteTimeout))
 			err := conn.WriteMsg(msg)
 			if err != nil {
-				if connClosing.SetToIf(false, true) {
+				mgr.logConnectionError(err, conn, connClosing)
-					log.Warningf("resolver: write error to %s (%s): %s", mgr.tr.resolver.GetName(), conn.RemoteAddr(), err)
-				}
 				return true
 			}
 
@@ -434,6 +478,10 @@ func (mgr *tcpResolverConnMgr) handleQueryResponse(conn *dns.Conn, msg *dns.Msg)
 
 	// persist to database
 	rrCache := inFlight.MakeCacheRecord(msg)
+	if !rrCache.Cacheable() {
+		return
+	}
+
 	rrCache.Clean(minTTL)
 	err := rrCache.Save()
 	if err != nil {
@@ -455,11 +503,37 @@ func (mgr *tcpResolverConnMgr) msgReader(
 	for {
 		msg, err := conn.ReadMsg()
 		if err != nil {
-			if connClosing.SetToIf(false, true) {
+			mgr.logConnectionError(err, conn, connClosing)
-				log.Warningf("resolver: read error from %s (%s): %s", mgr.tr.resolver.GetName(), conn.RemoteAddr(), err)
-			}
 			return nil
 		}
 		mgr.responses <- msg
 	}
 }
+
+func (mgr *tcpResolverConnMgr) logConnectionError(err error, conn *dns.Conn, connClosing *abool.AtomicBool) {
+	// Check if we are the first to see an error.
+	if connClosing.SetToIf(false, true) {
+		// Get amount of in flight queries.
+		mgr.tr.Lock()
+		inFlightQueries := len(mgr.tr.inFlightQueries)
+		mgr.tr.Unlock()
+
+		// Log error.
+		if errors.Is(err, io.EOF) {
+			log.Debugf(
+				"resolver: connection to %s (%s) was closed with %d in-flight queries",
+				mgr.tr.resolver.GetName(),
+				conn.RemoteAddr(),
+				inFlightQueries,
+			)
+		} else {
+			log.Warningf(
+				"resolver: write error to %s (%s) with %d in-flight queries: %s",
+				mgr.tr.resolver.GetName(),
+				conn.RemoteAddr(),
+				inFlightQueries,
+				err,
+			)
+		}
+	}
+}

resolver/resolver.go

@@ -60,6 +60,7 @@ type Resolver struct {
 	ServerIP      net.IP
 	ServerIPScope int8
 	ServerPort    uint16
+	ServerInfo    string
 
 	// Special Options
 	VerifyDomain string

resolver/resolvers.go

@@ -90,6 +90,16 @@ func createResolver(resolverURL, source string) (*Resolver, bool, error) {
 		return nil, false, fmt.Errorf("invalid resolver IP")
 	}
 
+	// Add default port for scheme if it is missing.
+	if u.Port() == "" {
+		switch u.Scheme {
+		case ServerTypeDNS, ServerTypeTCP:
+			u.Host += ":53"
+		case ServerTypeDoT:
+			u.Host += ":853"
+		}
+	}
+
 	scope := netutils.ClassifyIP(ip)
 	if scope == netutils.HostLocal {
 		return nil, true, nil // skip
@@ -128,6 +138,13 @@ func createResolver(resolverURL, source string) (*Resolver, bool, error) {
 		UpstreamBlockDetection: blockType,
 	}
 
+	u.RawQuery = "" // Remove options from parsed URL
+	if new.Name != "" {
+		new.ServerInfo = fmt.Sprintf("%s (%s, from %s)", new.Name, u, source)
+	} else {
+		new.ServerInfo = fmt.Sprintf("%s (from %s)", u, source)
+	}
+
 	new.Conn = resolverConnFactory(new)
 	return new, false, nil
 }

resolver/reverse.go

@@ -14,7 +14,7 @@ func ResolveIPAndValidate(ctx context.Context, ip string, securityLevel uint8) (
 	// get reversed DNS address
 	reverseIP, err := dns.ReverseAddr(ip)
 	if err != nil {
-		log.Tracef("resolver: failed to get reverse address of %s: %s", ip, err)
+		log.Tracer(ctx).Tracef("resolver: failed to get reverse address of %s: %s", ip, err)
 		return "", ErrInvalid
 	}
 

resolver/rrcache.go

@@ -1,6 +1,7 @@
 package resolver
 
 import (
+	"context"
 	"fmt"
 	"math/rand"
 	"net"
@@ -8,6 +9,7 @@ import (
 	"time"
 
 	"github.com/safing/portbase/log"
+	"github.com/safing/portmaster/nameserver/nsutil"
 	"github.com/safing/portmaster/netenv"
 
 	"github.com/miekg/dns"
@@ -20,17 +22,20 @@ type RRCache struct {
 
 	Domain   string   // constant
 	Question dns.Type // constant
+	RCode    int      // constant
 
-	Answer []dns.RR // might be mixed
+	Answer []dns.RR // constant
 	Ns     []dns.RR // constant
 	Extra  []dns.RR // constant
 	TTL    int64    // constant
 
 	Server      string // constant
 	ServerScope int8   // constant
+	ServerInfo  string // constant
 
 	servedFromCache bool     // mutable
 	requestingNew   bool     // mutable
+	isBackup        bool     // mutable
 	Filtered        bool     // mutable
 	FilteredEntries []string // mutable
 
@@ -47,19 +52,16 @@ func (rrCache *RRCache) Expired() bool {
 	return rrCache.TTL <= time.Now().Unix()
 }
 
-// MixAnswers randomizes the answer records to allow dumb clients (who only look at the first record) to reliably connect.
+// ExpiresSoon returns whether the record will expire soon and should already be refreshed.
-func (rrCache *RRCache) MixAnswers() {
+func (rrCache *RRCache) ExpiresSoon() bool {
-	rrCache.Lock()
+	return rrCache.TTL <= time.Now().Unix()+refreshTTL
-	defer rrCache.Unlock()
-
-	for i := range rrCache.Answer {
-		j := rand.Intn(i + 1)
-		rrCache.Answer[i], rrCache.Answer[j] = rrCache.Answer[j], rrCache.Answer[i]
-	}
 }
 
 // Clean sets all TTLs to 17 and sets cache expiry with specified minimum.
 func (rrCache *RRCache) Clean(minExpires uint32) {
+	rrCache.Lock()
+	defer rrCache.Unlock()
+
 	var lowestTTL uint32 = 0xFFFFFFFF
 	var header *dns.RR_Header
 
@@ -83,8 +85,8 @@ func (rrCache *RRCache) Clean(minExpires uint32) {
 
 	// shorten caching
 	switch {
-	case rrCache.IsNXDomain():
+	case rrCache.RCode != dns.RcodeSuccess:
-		// NXDomain
+		// Any sort of error.
 		lowestTTL = 10
 	case netenv.IsConnectivityDomain(rrCache.Domain):
 		// Responses from these domains might change very quickly depending on the environment.
@@ -126,9 +128,11 @@ func (rrCache *RRCache) ToNameRecord() *NameRecord {
 	new := &NameRecord{
 		Domain:      rrCache.Domain,
 		Question:    rrCache.Question.String(),
+		RCode:       rrCache.RCode,
 		TTL:         rrCache.TTL,
 		Server:      rrCache.Server,
 		ServerScope: rrCache.ServerScope,
+		ServerInfo:  rrCache.ServerInfo,
 	}
 
 	// stringify RR entries
@@ -145,8 +149,27 @@ func (rrCache *RRCache) ToNameRecord() *NameRecord {
 	return new
 }
 
+// rcodeIsCacheable returns whether a record with the given RCode should be cached.
+func rcodeIsCacheable(rCode int) bool {
+	switch rCode {
+	case dns.RcodeSuccess, dns.RcodeNameError, dns.RcodeRefused:
+		return true
+	default:
+		return false
+	}
+}
+
+// Cacheable returns whether the record should be cached.
+func (rrCache *RRCache) Cacheable() bool {
+	return rcodeIsCacheable(rrCache.RCode)
+}
+
 // Save saves the RRCache to the database as a NameRecord.
 func (rrCache *RRCache) Save() error {
+	if !rrCache.Cacheable() {
+		return nil
+	}
+
 	return rrCache.ToNameRecord().Save()
 }
 
@@ -162,6 +185,7 @@ func GetRRCache(domain string, question dns.Type) (*RRCache, error) {
 		return nil, err
 	}
 
+	rrCache.RCode = nameRecord.RCode
 	rrCache.TTL = nameRecord.TTL
 	for _, entry := range nameRecord.Answer {
 		rrCache.Answer = parseRR(rrCache.Answer, entry)
@@ -175,6 +199,7 @@ func GetRRCache(domain string, question dns.Type) (*RRCache, error) {
 
 	rrCache.Server = nameRecord.Server
 	rrCache.ServerScope = nameRecord.ServerScope
+	rrCache.ServerInfo = nameRecord.ServerInfo
 	rrCache.servedFromCache = true
 	return rrCache, nil
 }
@@ -211,6 +236,9 @@ func (rrCache *RRCache) Flags() string {
 	if rrCache.requestingNew {
 		s += "R"
 	}
+	if rrCache.isBackup {
+		s += "B"
+	}
 	if rrCache.Filtered {
 		s += "F"
 	}
@@ -221,16 +249,12 @@ func (rrCache *RRCache) Flags() string {
 	return ""
 }
 
-// IsNXDomain returnes whether the result is nxdomain.
-func (rrCache *RRCache) IsNXDomain() bool {
-	return len(rrCache.Answer) == 0
-}
-
 // ShallowCopy returns a shallow copy of the cache. slices are not copied, but referenced.
 func (rrCache *RRCache) ShallowCopy() *RRCache {
 	return &RRCache{
 		Domain:   rrCache.Domain,
 		Question: rrCache.Question,
+		RCode:    rrCache.RCode,
 		Answer:   rrCache.Answer,
 		Ns:       rrCache.Ns,
 		Extra:    rrCache.Extra,
@@ -238,11 +262,81 @@ func (rrCache *RRCache) ShallowCopy() *RRCache {
 
 		Server:      rrCache.Server,
 		ServerScope: rrCache.ServerScope,
+		ServerInfo:  rrCache.ServerInfo,
 
 		updated:         rrCache.updated,
 		servedFromCache: rrCache.servedFromCache,
 		requestingNew:   rrCache.requestingNew,
+		isBackup:        rrCache.isBackup,
 		Filtered:        rrCache.Filtered,
 		FilteredEntries: rrCache.FilteredEntries,
 	}
 }
+
+// ReplyWithDNS creates a new reply to the given query with the data from the RRCache, and additional informational records.
+func (rrCache *RRCache) ReplyWithDNS(ctx context.Context, request *dns.Msg) *dns.Msg {
+	// reply to query
+	reply := new(dns.Msg)
+	reply.SetRcode(request, rrCache.RCode)
+	reply.Ns = rrCache.Ns
+	reply.Extra = rrCache.Extra
+
+	if len(rrCache.Answer) > 0 {
+		// Copy answers, as we randomize their order a little.
+		reply.Answer = make([]dns.RR, len(rrCache.Answer))
+		copy(reply.Answer, rrCache.Answer)
+
+		// Randomize the order of the answer records a little to allow dumb clients
+		// (who only look at the first record) to reliably connect.
+		for i := range reply.Answer {
+			j := rand.Intn(i + 1)
+			reply.Answer[i], reply.Answer[j] = reply.Answer[j], reply.Answer[i]
+		}
+	}
+
+	return reply
+}
+
+// GetExtraRRs returns a slice of RRs with additional informational records.
+func (rrCache *RRCache) GetExtraRRs(ctx context.Context, query *dns.Msg) (extra []dns.RR) {
+	// Add cache status and source of data.
+	if rrCache.servedFromCache {
+		extra = addExtra(ctx, extra, "served from cache, resolved by "+rrCache.ServerInfo)
+	} else {
+		extra = addExtra(ctx, extra, "freshly resolved by "+rrCache.ServerInfo)
+	}
+
+	// Add expiry and cache information.
+	if rrCache.Expired() {
+		extra = addExtra(ctx, extra, fmt.Sprintf("record expired since %s", time.Since(time.Unix(rrCache.TTL, 0)).Round(time.Second)))
+	} else {
+		extra = addExtra(ctx, extra, fmt.Sprintf("record valid for %s", time.Until(time.Unix(rrCache.TTL, 0)).Round(time.Second)))
+	}
+	if rrCache.requestingNew {
+		extra = addExtra(ctx, extra, "async request to refresh the cache has been started")
+	}
+	if rrCache.isBackup {
+		extra = addExtra(ctx, extra, "this record is served because a fresh request failed")
+	}
+
+	// Add information about filtered entries.
+	if rrCache.Filtered {
+		if len(rrCache.FilteredEntries) > 1 {
+			extra = addExtra(ctx, extra, fmt.Sprintf("%d records have been filtered", len(rrCache.FilteredEntries)))
+		} else {
+			extra = addExtra(ctx, extra, fmt.Sprintf("%d record has been filtered", len(rrCache.FilteredEntries)))
+		}
+	}
+
+	return extra
+}
+
+func addExtra(ctx context.Context, extra []dns.RR, msg string) []dns.RR {
+	rr, err := nsutil.MakeMessageRecord(log.InfoLevel, msg)
+	if err != nil {
+		log.Tracer(ctx).Warningf("resolver: failed to add informational record to reply: %s", err)
+		return extra
+	}
+	extra = append(extra, rr)
+	return extra
+}

resolver/scopes.go

@@ -158,7 +158,7 @@ addNextResolver:
 	for _, resolver := range addResolvers {
 		// check for compliance
 		if err := resolver.checkCompliance(ctx, q); err != nil {
-			log.Tracef("skipping non-compliant resolver %s: %s", resolver.GetName(), err)
+			log.Tracer(ctx).Tracef("skipping non-compliant resolver %s: %s", resolver.GetName(), err)
 			continue
 		}