Improve dns resolving and logging

firewall/dns.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"net"
 	"strings"
-	"time"
 
 	"github.com/miekg/dns"
 	"github.com/safing/portbase/database"
@@ -16,9 +15,19 @@ import (
 	"github.com/safing/portmaster/resolver"
 )
 
-func filterDNSSection(entries []dns.RR, p *profile.LayeredProfile, resolverScope netutils.IPScope, sysResolver bool) ([]dns.RR, []string, int, string) {
+func filterDNSSection(
+	ctx context.Context,
+	entries []dns.RR,
+	p *profile.LayeredProfile,
+	resolverScope netutils.IPScope,
+	sysResolver bool,
+) ([]dns.RR, []string, int, string) {
+
+	// Will be filled 1:1 most of the time.
 	goodEntries := make([]dns.RR, 0, len(entries))
-	filteredRecords := make([]string, 0, len(entries))
+
+	// Will stay empty most of the time.
+	var filteredRecords []string
 
 	// keeps track of the number of valid and allowed
 	// A and AAAA records.
@@ -44,13 +53,16 @@ func filterDNSSection(entries []dns.RR, p *profile.LayeredProfile, resolverScope
 			switch {
 			case ipScope.IsLocalhost():
 				// No DNS should return localhost addresses
-				filteredRecords = append(filteredRecords, rr.String())
+				filteredRecords = append(filteredRecords, formatRR(rr))
 				interveningOptionKey = profile.CfgOptionRemoveOutOfScopeDNSKey
+				log.Tracer(ctx).Tracef("filter: RR violates resolver scope: %s", formatRR(rr))
 				continue
+
 			case resolverScope.IsGlobal() && ipScope.IsLAN() && !sysResolver:
 				// No global DNS should return LAN addresses
-				filteredRecords = append(filteredRecords, rr.String())
+				filteredRecords = append(filteredRecords, formatRR(rr))
 				interveningOptionKey = profile.CfgOptionRemoveOutOfScopeDNSKey
+				log.Tracer(ctx).Tracef("filter: RR violates resolver scope: %s", formatRR(rr))
 				continue
 			}
 		}
@@ -59,16 +71,21 @@ func filterDNSSection(entries []dns.RR, p *profile.LayeredProfile, resolverScope
 			// filter by flags
 			switch {
 			case p.BlockScopeInternet() && ipScope.IsGlobal():
-				filteredRecords = append(filteredRecords, rr.String())
+				filteredRecords = append(filteredRecords, formatRR(rr))
 				interveningOptionKey = profile.CfgOptionBlockScopeInternetKey
+				log.Tracer(ctx).Tracef("filter: RR is in blocked scope Internet: %s", formatRR(rr))
 				continue
+
 			case p.BlockScopeLAN() && ipScope.IsLAN():
-				filteredRecords = append(filteredRecords, rr.String())
+				filteredRecords = append(filteredRecords, formatRR(rr))
 				interveningOptionKey = profile.CfgOptionBlockScopeLANKey
+				log.Tracer(ctx).Tracef("filter: RR is in blocked scope LAN: %s", formatRR(rr))
 				continue
+
 			case p.BlockScopeLocal() && ipScope.IsLocalhost():
-				filteredRecords = append(filteredRecords, rr.String())
+				filteredRecords = append(filteredRecords, formatRR(rr))
 				interveningOptionKey = profile.CfgOptionBlockScopeLocalKey
+				log.Tracer(ctx).Tracef("filter: RR is in blocked scope Localhost: %s", formatRR(rr))
 				continue
 			}
 
@@ -83,9 +100,13 @@ func filterDNSSection(entries []dns.RR, p *profile.LayeredProfile, resolverScope
 	return goodEntries, filteredRecords, allowedAddressRecords, interveningOptionKey
 }
 
-func filterDNSResponse(conn *network.Connection, rrCache *resolver.RRCache, sysResolver bool) *resolver.RRCache {
+func filterDNSResponse(
-	p := conn.Process().Profile()
+	ctx context.Context,
-
+	conn *network.Connection,
+	p *profile.LayeredProfile,
+	rrCache *resolver.RRCache,
+	sysResolver bool,
+) *resolver.RRCache {
 	// do not modify own queries
 	if conn.Process().Pid == ownPID {
 		return rrCache
@@ -96,20 +117,20 @@ func filterDNSResponse(conn *network.Connection, rrCache *resolver.RRCache, sysR
 		return rrCache
 	}
 
-	// duplicate entry
-	rrCache = rrCache.ShallowCopy()
-	rrCache.FilteredEntries = make([]string, 0)
-
 	var filteredRecords []string
 	var validIPs int
 	var interveningOptionKey string
 
-	rrCache.Answer, filteredRecords, validIPs, interveningOptionKey = filterDNSSection(rrCache.Answer, p, rrCache.Resolver.IPScope, sysResolver)
+	rrCache.Answer, filteredRecords, validIPs, interveningOptionKey = filterDNSSection(ctx, rrCache.Answer, p, rrCache.Resolver.IPScope, sysResolver)
-	rrCache.FilteredEntries = append(rrCache.FilteredEntries, filteredRecords...)
+	if len(filteredRecords) > 0 {
+		rrCache.FilteredEntries = append(rrCache.FilteredEntries, filteredRecords...)
+	}
 
-	// we don't count the valid IPs in the extra section
+	// Don't count the valid IPs in the extra section.
-	rrCache.Extra, filteredRecords, _, _ = filterDNSSection(rrCache.Extra, p, rrCache.Resolver.IPScope, sysResolver)
+	rrCache.Extra, filteredRecords, _, _ = filterDNSSection(ctx, rrCache.Extra, p, rrCache.Resolver.IPScope, sysResolver)
-	rrCache.FilteredEntries = append(rrCache.FilteredEntries, filteredRecords...)
+	if len(filteredRecords) > 0 {
+		rrCache.FilteredEntries = append(rrCache.FilteredEntries, filteredRecords...)
+	}
 
 	if len(rrCache.FilteredEntries) > 0 {
 		rrCache.Filtered = true
@@ -142,9 +163,15 @@ func FilterResolvedDNS(
 	q *resolver.Query,
 	rrCache *resolver.RRCache,
 ) *resolver.RRCache {
+	// Check if we have a process and profile.
+	layeredProfile := conn.Process().Profile()
+	if layeredProfile == nil {
+		log.Tracer(ctx).Warning("unknown process or profile")
+		return nil
+	}
 
 	// special grant for connectivity domains
-	if checkConnectivityDomain(ctx, conn, nil) {
+	if checkConnectivityDomain(ctx, conn, layeredProfile, nil) {
 		// returns true if check triggered
 		return rrCache
 	}
@@ -152,33 +179,35 @@ func FilterResolvedDNS(
 	// Only filter criticial things if request comes from the system resolver.
 	sysResolver := conn.Process().IsSystemResolver()
 
-	updatedRR := filterDNSResponse(conn, rrCache, sysResolver)
+	// Filter dns records and return if the query is blocked.
-	if updatedRR == nil {
+	rrCache = filterDNSResponse(ctx, conn, layeredProfile, rrCache, sysResolver)
-		return nil
+	if conn.Verdict == network.VerdictBlock {
+		return rrCache
 	}
 
-	if !sysResolver && mayBlockCNAMEs(ctx, conn) {
+	// Block by CNAMEs.
-		return nil
+	if !sysResolver {
+		mayBlockCNAMEs(ctx, conn, layeredProfile)
 	}
 
-	return updatedRR
+	return rrCache
 }
 
-func mayBlockCNAMEs(ctx context.Context, conn *network.Connection) bool {
+func mayBlockCNAMEs(ctx context.Context, conn *network.Connection, p *profile.LayeredProfile) bool {
 	// if we have CNAMEs and the profile is configured to filter them
 	// we need to re-check the lists and endpoints here
-	if conn.Process().Profile().FilterCNAMEs() {
+	if p.FilterCNAMEs() {
 		conn.Entity.ResetLists()
 		conn.Entity.EnableCNAMECheck(ctx, true)
 
-		result, reason := conn.Process().Profile().MatchEndpoint(ctx, conn.Entity)
+		result, reason := p.MatchEndpoint(ctx, conn.Entity)
 		if result == endpoints.Denied {
 			conn.BlockWithContext(reason.String(), profile.CfgOptionFilterCNAMEKey, reason.Context())
 			return true
 		}
 
 		if result == endpoints.NoMatch {
-			result, reason = conn.Process().Profile().MatchFilterLists(ctx, conn.Entity)
+			result, reason = p.MatchFilterLists(ctx, conn.Entity)
 			if result == endpoints.Denied {
 				conn.BlockWithContext(reason.String(), profile.CfgOptionFilterCNAMEKey, reason.Context())
 				return true
@@ -278,3 +307,8 @@ func UpdateIPsAndCNAMEs(q *resolver.Query, rrCache *resolver.RRCache, conn *netw
 		}
 	}
 }
+
+// formatRR is a friendlier alternative to miekg/dns.RR.String().
+func formatRR(rr dns.RR) string {
+	return strings.ReplaceAll(rr.String(), "\t", " ")
+}

firewall/interception.go

@@ -144,15 +144,14 @@ func getConnection(pkt packet.Packet) (*network.Connection, error) {
 
 	// Transform and log result.
 	conn := newConn.(*network.Connection)
-	switch {
+	sharedIndicator := ""
-	case created && shared:
+	if shared {
-		log.Tracer(pkt.Ctx()).Tracef("filter: created new connection %s (shared)", conn.ID)
+		sharedIndicator = " (shared)"
-	case created:
+	}
-		log.Tracer(pkt.Ctx()).Tracef("filter: created new connection %s", conn.ID)
+	if created {
-	case shared:
+		log.Tracer(pkt.Ctx()).Tracef("filter: created new connection %s%s", conn.ID, sharedIndicator)
-		log.Tracer(pkt.Ctx()).Tracef("filter: assigned connection %s (shared)", conn.ID)
+	} else {
-	default:
+		log.Tracer(pkt.Ctx()).Tracef("filter: assigned connection %s%s", conn.ID, sharedIndicator)
-		log.Tracer(pkt.Ctx()).Tracef("filter: assigned connection %s", conn.ID)
 	}
 
 	return conn, nil

nameserver/nameserver.go

@@ -189,8 +189,8 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 
 	// Resolve request.
 	rrCache, err = resolver.Resolve(ctx, q)
+	// Handle error.
 	if err != nil {
-		// React to special errors.
 		switch {
 		case errors.Is(err, resolver.ErrNotFound):
 			tracer.Tracef("nameserver: %s", err)
@@ -214,31 +214,34 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 			return reply(nsutil.ServerFailure("internal error: " + err.Error()))
 		}
 	}
-	if rrCache == nil {
+	// Handle special cases.
+	switch {
+	case rrCache == nil:
 		tracer.Warning("nameserver: received successful, but empty reply from resolver")
 		return reply(nsutil.ServerFailure("internal error: empty reply"))
+	case rrCache.RCode == dns.RcodeNameError:
+		return reply(nsutil.NxDomain("no answer found (NXDomain)"))
 	}
 
 	tracer.Trace("nameserver: deciding on resolved dns")
 	rrCache = firewall.FilterResolvedDNS(ctx, conn, q, rrCache)
-	if rrCache == nil {
-		// Check again if there is a responder from the firewall.
-		if responder, ok := conn.Reason.Context.(nsutil.Responder); ok {
-			tracer.Infof("nameserver: handing over request for %s to filter responder: %s", q.ID(), conn.Reason.Msg)
-			return reply(responder)
-		}
 
-		// Request was blocked by the firewall.
+	// Check again if there is a responder from the firewall.
-		switch conn.Verdict {
+	if responder, ok := conn.Reason.Context.(nsutil.Responder); ok {
-		case network.VerdictBlock, network.VerdictDrop, network.VerdictFailed:
+		tracer.Infof("nameserver: handing over request for %s to special filter responder: %s", q.ID(), conn.Reason.Msg)
-			tracer.Infof(
+		return reply(responder)
-				"nameserver: returning %s response for %s to %s",
+	}
-				conn.Verdict.Verb(),
+
-				q.ID(),
+	// Check if there is a Verdict to act upon.
-				conn.Process(),
+	switch conn.Verdict {
-			)
+	case network.VerdictBlock, network.VerdictDrop, network.VerdictFailed:
-			return reply(conn, conn)
+		tracer.Infof(
-		}
+			"nameserver: returning %s response for %s to %s",
+			conn.Verdict.Verb(),
+			q.ID(),
+			conn.Process(),
+		)
+		return reply(conn, conn, rrCache)
 	}
 
 	// Revert back to non-standard question format, if we had to convert.
@@ -247,10 +250,15 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 	}
 
 	// Reply with successful response.
+	noAnswerIndicator := ""
+	if len(rrCache.Answer) == 0 {
+		noAnswerIndicator = "/no answer"
+	}
 	tracer.Infof(
-		"nameserver: returning %s response (%s) for %s to %s",
+		"nameserver: returning %s response (%s%s) for %s to %s",
 		conn.Verdict.Verb(),
 		dns.RcodeToString[rrCache.RCode],
+		noAnswerIndicator,
 		q.ID(),
 		conn.Process(),
 	)

network/dns.go

@@ -57,9 +57,12 @@ func SaveOpenDNSRequest(conn *Connection) {
 
 	key := getDNSRequestCacheKey(conn.process.Pid, conn.Entity.Domain)
 	if existingConn, ok := openDNSRequests[key]; ok {
+		// End previous request and save it.
 		existingConn.Lock()
-		defer existingConn.Unlock()
 		existingConn.Ended = conn.Started
+		existingConn.Unlock()
+		existingConn.Save()
+
 		return
 	}
 

resolver/resolve.go

@@ -341,6 +341,7 @@ resolveLoop:
 			}
 
 			// resolve
+			log.Tracer(ctx).Tracef("resolver: sending query for %s to %s", q.ID(), resolver.Info.ID())
 			rrCache, err = resolver.Conn.Query(ctx, q)
 			if err != nil {
 				switch {
@@ -416,9 +417,11 @@ resolveLoop:
 		return nil, err
 	}
 
-	// Save the new entry if cache is enabled.
+	// Adjust TTLs.
+	rrCache.Clean(minTTL)
+
+	// Save the new entry if cache is enabled and the record may be cached.
 	if !q.NoCaching && rrCache.Cacheable() {
-		rrCache.Clean(minTTL)
 		err = rrCache.Save()
 		if err != nil {
 			log.Tracer(ctx).Warningf("resolver: failed to cache RR for %s: %s", q.ID(), err)

resolver/rrcache.go

@@ -315,9 +315,12 @@ func (rrCache *RRCache) GetExtraRRs(ctx context.Context, query *dns.Msg) (extra
 	// 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)))
+			extra = addExtra(ctx, extra, fmt.Sprintf("%d RRs have been filtered:", len(rrCache.FilteredEntries)))
 		} else {
-			extra = addExtra(ctx, extra, fmt.Sprintf("%d record has been filtered", len(rrCache.FilteredEntries)))
+			extra = addExtra(ctx, extra, fmt.Sprintf("%d RR has been filtered:", len(rrCache.FilteredEntries)))
+		}
+		for _, filteredRecord := range rrCache.FilteredEntries {
+			extra = addExtra(ctx, extra, filteredRecord)
 		}
 	}