Use pre-authorized ports for dns queries, improve logging

intel/clients.go

@@ -2,12 +2,24 @@ package intel
 
 import (
 	"crypto/tls"
+	"net"
 	"sync"
 	"time"
 
 	"github.com/miekg/dns"
 )
 
+var (
+	localAddrFactory func(network string) net.Addr
+)
+
+// SetLocalAddrFactory supplied the intel package with a function to set local addresses for connections.
+func SetLocalAddrFactory(laf func(network string) net.Addr) {
+	if localAddrFactory == nil {
+		localAddrFactory = laf
+	}
+}
+
 type clientManager struct {
 	dnsClient *dns.Client
 	factory   func() *dns.Client
@@ -21,10 +33,13 @@ type clientManager struct {
 
 func newDNSClientManager(resolver *Resolver) *clientManager {
 	return &clientManager{
-		ttl: -1 * time.Minute,
+		// ttl: 1 * time.Minute,
 		factory: func() *dns.Client {
 			return &dns.Client{
 				Timeout: 5 * time.Second,
+				Dialer: &net.Dialer{
+					LocalAddr: localAddrFactory("udp"),
+				},
 			}
 		},
 	}
@@ -32,11 +47,14 @@ func newDNSClientManager(resolver *Resolver) *clientManager {
 
 func newTCPClientManager(resolver *Resolver) *clientManager {
 	return &clientManager{
-		ttl: -15 * time.Minute,
+		// ttl: 5 * time.Minute,
 		factory: func() *dns.Client {
 			return &dns.Client{
 				Net:     "tcp",
 				Timeout: 5 * time.Second,
+				Dialer: &net.Dialer{
+					LocalAddr: localAddrFactory("tcp"),
+				},
 			}
 		},
 	}
@@ -44,7 +62,7 @@ func newTCPClientManager(resolver *Resolver) *clientManager {
 
 func newTLSClientManager(resolver *Resolver) *clientManager {
 	return &clientManager{
-		ttl: -15 * time.Minute,
+		// ttl: 5 * time.Minute,
 		factory: func() *dns.Client {
 			return &dns.Client{
 				Net: "tcp-tls",
@@ -55,6 +73,9 @@ func newTLSClientManager(resolver *Resolver) *clientManager {
 					// Rand: io.Reader,
 				},
 				Timeout: 5 * time.Second,
+				Dialer: &net.Dialer{
+					LocalAddr: localAddrFactory("tcp"),
+				},
 			}
 		},
 	}
@@ -62,7 +83,7 @@ func newTLSClientManager(resolver *Resolver) *clientManager {
 
 func newHTTPSClientManager(resolver *Resolver) *clientManager {
 	return &clientManager{
-		ttl: -15 * time.Minute,
+		// ttl: 5 * time.Minute,
 		factory: func() *dns.Client {
 			new := &dns.Client{
 				Net: "https",
@@ -72,6 +93,9 @@ func newHTTPSClientManager(resolver *Resolver) *clientManager {
 					// Rand: io.Reader,
 				},
 				Timeout: 5 * time.Second,
+				Dialer: &net.Dialer{
+					LocalAddr: localAddrFactory("tcp"),
+				},
 			}
 			if resolver.VerifyDomain != "" {
 				new.TLSConfig.ServerName = resolver.VerifyDomain
@@ -85,7 +109,7 @@ func (cm *clientManager) getDNSClient() *dns.Client {
 	cm.lock.Lock()
 	defer cm.lock.Unlock()
 
-	if cm.dnsClient == nil || time.Now().After(cm.refreshAfter) {
+	if cm.dnsClient == nil || cm.ttl == 0 || time.Now().After(cm.refreshAfter) {
 		cm.dnsClient = cm.factory()
 		cm.refreshAfter = time.Now().Add(cm.ttl)
 	}

intel/config.go

@@ -8,18 +8,19 @@ import (
 var (
 	configuredNameServers config.StringArrayOption
 	defaultNameServers    = []string{
+		"dns|1.1.1.1:53",                     // Cloudflare
+		"dns|1.0.0.1:53",                     // Cloudflare
+		"dns|9.9.9.9:53",                     // Quad9
 		"tls|1.1.1.1:853|cloudflare-dns.com", // Cloudflare
 		"tls|1.0.0.1:853|cloudflare-dns.com", // Cloudflare
 		"tls|9.9.9.9:853|dns.quad9.net",      // Quad9
 		// "https|cloudflare-dns.com/dns-query", // HTTPS still experimental
-		"dns|1.1.1.1:53", // Cloudflare
-		"dns|1.0.0.1:53", // Cloudflare
-		"dns|9.9.9.9:53", // Quad9
 	}
 
 	nameserverRetryRate         config.IntOption
 	doNotUseMulticastDNS        status.SecurityLevelOption
 	doNotUseAssignedNameservers status.SecurityLevelOption
+	doNotUseInsecureProtocols   status.SecurityLevelOption
 	doNotResolveSpecialDomains  status.SecurityLevelOption
 )
 
@@ -73,7 +74,7 @@ func prep() error {
 		ExpertiseLevel:  config.ExpertiseLevelExpert,
 		OptType:         config.OptTypeInt,
 		ExternalOptType: "security level",
-		DefaultValue:    6,
+		DefaultValue:    4,
 		ValidationRegex: "^(7|6|4)$",
 	})
 	if err != nil {
@@ -81,6 +82,21 @@ func prep() error {
 	}
 	doNotUseAssignedNameservers = status.ConfigIsActiveConcurrent("intel/doNotUseAssignedNameservers")
 
+	err = config.Register(&config.Option{
+		Name:            "Do not resolve insecurely",
+		Key:             "intel/doNotUseInsecureProtocols",
+		Description:     "Do not resolve domains with insecure protocols, ie. plain DNS",
+		ExpertiseLevel:  config.ExpertiseLevelExpert,
+		OptType:         config.OptTypeInt,
+		ExternalOptType: "security level",
+		DefaultValue:    4,
+		ValidationRegex: "^(7|6|4)$",
+	})
+	if err != nil {
+		return err
+	}
+	doNotUseInsecureProtocols = status.ConfigIsActiveConcurrent("intel/doNotUseInsecureProtocols")
+
 	err = config.Register(&config.Option{
 		Name:            "Do not resolve special domains",
 		Key:             "intel/doNotResolveSpecialDomains",

intel/main.go

@@ -1,6 +1,8 @@
 package intel
 
 import (
+	"context"
+
 	"github.com/miekg/dns"
 
 	"github.com/Safing/portbase/log"
@@ -24,12 +26,16 @@ func start() error {
 }
 
 // GetIntelAndRRs returns intel and DNS resource records for the given domain.
-func GetIntelAndRRs(domain string, qtype dns.Type, securityLevel uint8) (intel *Intel, rrs *RRCache) {
+func GetIntelAndRRs(ctx context.Context, domain string, qtype dns.Type, securityLevel uint8) (intel *Intel, rrs *RRCache) {
+	log.Tracer(ctx).Trace("intel: getting intel")
 	intel, err := GetIntel(domain)
 	if err != nil {
+		log.Tracer(ctx).Warningf("intel: failed to get intel: %s", err)
 		log.Errorf("intel: failed to get intel: %s", err)
 		intel = nil
 	}
-	rrs = Resolve(domain, qtype, securityLevel)
+
+	log.Tracer(ctx).Tracef("intel: getting records")
+	rrs = Resolve(ctx, domain, qtype, securityLevel)
 	return
 }

intel/mdns.go

@@ -3,6 +3,7 @@
 package intel
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"net"
@@ -262,7 +263,9 @@ func listenForDNSPackets(conn *net.UDPConn, messages chan *dns.Msg) {
 	}
 }
 
-func queryMulticastDNS(fqdn string, qtype dns.Type) (*RRCache, error) {
+func queryMulticastDNS(ctx context.Context, fqdn string, qtype dns.Type) (*RRCache, error) {
+	log.Tracer(ctx).Trace("intel: resolving with mDNS")
+
 	q := new(dns.Msg)
 	q.SetQuestion(fqdn, uint16(qtype))
 	// request unicast response

intel/resolve.go

@@ -3,6 +3,7 @@
 package intel
 
 import (
+	"context"
 	"fmt"
 	"math/rand"
 	"net"
@@ -69,7 +70,7 @@ import (
 // special -> local scopes, local
 
 // Resolve resolves the given query for a domain and type and returns a RRCache object or nil, if the query failed.
-func Resolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCache {
+func Resolve(ctx context.Context, fqdn string, qtype dns.Type, securityLevel uint8) *RRCache {
 	fqdn = dns.Fqdn(fqdn)
 
 	// use this to time how long it takes resolve this domain
@@ -82,15 +83,17 @@ func Resolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCache {
 		switch err {
 		case database.ErrNotFound:
 		default:
+			log.Tracer(ctx).Warningf("intel: getting RRCache %s%s from database failed: %s", fqdn, qtype.String(), err)
 			log.Warningf("intel: getting RRCache %s%s from database failed: %s", fqdn, qtype.String(), err)
 		}
-		return resolveAndCache(fqdn, qtype, securityLevel)
+		return resolveAndCache(ctx, fqdn, qtype, securityLevel)
 	}
 
 	if rrCache.TTL <= time.Now().Unix() {
-		log.Tracef("intel: serving cache, requesting new. TTL=%d, now=%d", rrCache.TTL, time.Now().Unix())
+		log.Tracer(ctx).Tracef("intel: serving from cache, requesting new. TTL=%d, now=%d", rrCache.TTL, time.Now().Unix())
+		// log.Tracef("intel: serving cache, requesting new. TTL=%d, now=%d", rrCache.TTL, time.Now().Unix())
 		rrCache.requestingNew = true
-		go resolveAndCache(fqdn, qtype, securityLevel)
+		go resolveAndCache(nil, fqdn, qtype, securityLevel)
 	}
 
 	// randomize records to allow dumb clients (who only look at the first record) to reliably connect
@@ -102,8 +105,8 @@ func Resolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCache {
 	return rrCache
 }
 
-func resolveAndCache(fqdn string, qtype dns.Type, securityLevel uint8) (rrCache *RRCache) {
+func resolveAndCache(ctx context.Context, fqdn string, qtype dns.Type, securityLevel uint8) (rrCache *RRCache) {
-	// log.Tracef("intel: resolving %s%s", fqdn, qtype.String())
+	log.Tracer(ctx).Tracef("intel: resolving %s%s", fqdn, qtype.String())
 
 	// dedup requests
 	dupKey := fmt.Sprintf("%s%s", fqdn, qtype.String())
@@ -116,7 +119,8 @@ func resolveAndCache(fqdn string, qtype dns.Type, securityLevel uint8) (rrCache
 		dupReqLock.Unlock()
 	} else {
 		dupReqLock.Unlock()
-		log.Tracef("intel: waiting for duplicate query for %s to complete", dupKey)
+		log.Tracer(ctx).Tracef("intel: waiting for duplicate query for %s to complete", dupKey)
+		// log.Tracef("intel: waiting for duplicate query for %s to complete", dupKey)
 		mutex.Lock()
 		// wait until duplicate request is finished, then fetch current RRCache and return
 		mutex.Unlock()
@@ -136,7 +140,7 @@ func resolveAndCache(fqdn string, qtype dns.Type, securityLevel uint8) (rrCache
 	}()
 
 	// resolve
-	rrCache = intelligentResolve(fqdn, qtype, securityLevel)
+	rrCache = intelligentResolve(ctx, fqdn, qtype, securityLevel)
 	if rrCache == nil {
 		return nil
 	}
@@ -148,7 +152,7 @@ func resolveAndCache(fqdn string, qtype dns.Type, securityLevel uint8) (rrCache
 	return rrCache
 }
 
-func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCache {
+func intelligentResolve(ctx context.Context, fqdn string, qtype dns.Type, securityLevel uint8) *RRCache {
 
 	// TODO: handle being offline
 	// TODO: handle multiple network connections
@@ -178,7 +182,7 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 	if domainInScopes(preDottedFqdn, localReverseScopes) {
 		// try local resolvers
 		for _, resolver := range localResolvers {
-			rrCache, ok := tryResolver(resolver, lastFailBoundary, fqdn, qtype, securityLevel)
+			rrCache, ok := tryResolver(ctx, resolver, lastFailBoundary, fqdn, qtype, securityLevel)
 			if ok && rrCache != nil && !rrCache.IsNXDomain() {
 				return rrCache
 			}
@@ -188,8 +192,9 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 			return nil
 		}
 		// try mdns
-		rrCache, err := queryMulticastDNS(fqdn, qtype)
+		rrCache, err := queryMulticastDNS(ctx, fqdn, qtype)
 		if err != nil {
+			log.Tracer(ctx).Warningf("intel: failed to query mdns: %s", err)
 			log.Errorf("intel: failed to query mdns: %s", err)
 		}
 		return rrCache
@@ -199,7 +204,7 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 	for _, scope := range localScopes {
 		if strings.HasSuffix(preDottedFqdn, scope.Domain) {
 			for _, resolver := range scope.Resolvers {
-				rrCache, ok := tryResolver(resolver, lastFailBoundary, fqdn, qtype, securityLevel)
+				rrCache, ok := tryResolver(ctx, resolver, lastFailBoundary, fqdn, qtype, securityLevel)
 				if ok && rrCache != nil && !rrCache.IsNXDomain() {
 					return rrCache
 				}
@@ -214,8 +219,9 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 			return nil
 		}
 		// try mdns
-		rrCache, err := queryMulticastDNS(fqdn, qtype)
+		rrCache, err := queryMulticastDNS(ctx, fqdn, qtype)
 		if err != nil {
+			log.Tracer(ctx).Warningf("intel: failed to query mdns: %s", err)
 			log.Errorf("intel: failed to query mdns: %s", err)
 		}
 		return rrCache
@@ -226,7 +232,7 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 		}
 		// try local resolvers
 		for _, resolver := range localResolvers {
-			rrCache, ok := tryResolver(resolver, lastFailBoundary, fqdn, qtype, securityLevel)
+			rrCache, ok := tryResolver(ctx, resolver, lastFailBoundary, fqdn, qtype, securityLevel)
 			if ok {
 				return rrCache
 			}
@@ -234,13 +240,14 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 	default:
 		// try global resolvers
 		for _, resolver := range globalResolvers {
-			rrCache, ok := tryResolver(resolver, lastFailBoundary, fqdn, qtype, securityLevel)
+			rrCache, ok := tryResolver(ctx, resolver, lastFailBoundary, fqdn, qtype, securityLevel)
 			if ok {
 				return rrCache
 			}
 		}
 	}
 
+	log.Tracer(ctx).Warningf("intel: failed to resolve %s%s: all resolvers failed (or were skipped to fulfill the security level)", fqdn, qtype.String())
 	log.Criticalf("intel: failed to resolve %s%s: all resolvers failed (or were skipped to fulfill the security level)", fqdn, qtype.String())
 	return nil
 
@@ -248,24 +255,29 @@ func intelligentResolve(fqdn string, qtype dns.Type, securityLevel uint8) *RRCac
 
 }
 
-func tryResolver(resolver *Resolver, lastFailBoundary int64, fqdn string, qtype dns.Type, securityLevel uint8) (*RRCache, bool) {
+func tryResolver(ctx context.Context, resolver *Resolver, lastFailBoundary int64, fqdn string, qtype dns.Type, securityLevel uint8) (*RRCache, bool) {
-	// skip if not allowed in current security level
+	log.Tracer(ctx).Tracef("intel: resolving with %s", resolver)
-	if resolver.AllowedSecurityLevel < status.ActiveSecurityLevel() || resolver.AllowedSecurityLevel < securityLevel {
+
-		log.Tracef("intel: skipping resolver %s, because it isn't allowed to operate on the current security level: %d|%d", resolver, status.ActiveSecurityLevel(), securityLevel)
+	// skip if not security level denies insecure protocols
+	if doNotUseInsecureProtocols(securityLevel) && resolver.ServerType == "dns" {
+		log.Tracer(ctx).Tracef("intel: skipping resolver %s, because it isn't allowed to operate on the current security level: %d|%d", resolver, status.ActiveSecurityLevel(), securityLevel)
 		return nil, false
 	}
+
 	// skip if not security level denies assigned dns servers
 	if doNotUseAssignedNameservers(securityLevel) && resolver.Source == "dhcp" {
-		log.Tracef("intel: skipping resolver %s, because assigned nameservers are not allowed on the current security level: %d|%d", resolver, status.ActiveSecurityLevel(), securityLevel)
+		log.Tracer(ctx).Tracef("intel: skipping resolver %s, because assigned nameservers are not allowed on the current security level: %d|%d", resolver, status.ActiveSecurityLevel(), securityLevel)
 		return nil, false
 	}
 	// check if failed recently
 	if atomic.LoadInt64(resolver.LastFail) > lastFailBoundary {
+		log.Tracer(ctx).Tracef("intel: skipping resolver %s, because it failed recently", resolver)
 		return nil, false
 	}
 	// TODO: put SkipFqdnBeforeInit back into !resolver.Initialized.IsSet() as soon as Go1.9 arrives and we can use a custom resolver
 	// skip resolver if initializing and fqdn is set to skip
 	if fqdn == resolver.SkipFqdnBeforeInit {
+		log.Tracer(ctx).Tracef("intel: skipping resolver %s, because %s is set to be skipped before init", resolver, fqdn)
 		return nil, false
 	}
 	// check if resolver is already initialized
@@ -285,15 +297,16 @@ func tryResolver(resolver *Resolver, lastFailBoundary int64, fqdn string, qtype
 		}
 	}
 	// resolve
-	log.Tracef("intel: trying to resolve %s%s with %s", fqdn, qtype.String(), resolver.Server)
+	rrCache, err := query(ctx, resolver, fqdn, qtype)
-	rrCache, err := query(resolver, fqdn, qtype)
 	if err != nil {
 		// check if failing is disabled
 		if atomic.LoadInt64(resolver.LastFail) == -1 {
-			log.Tracef("intel: non-failing resolver %s failed (%s), moving to next", resolver, err)
+			log.Tracer(ctx).Tracef("intel: non-failing resolver %s failed, moving to next: %s", resolver, err)
+			// log.Tracef("intel: non-failing resolver %s failed (%s), moving to next", resolver, err)
 			return nil, false
 		}
-		log.Warningf("intel: resolver %s failed (%s), moving to next", resolver, err)
+		log.Tracer(ctx).Warningf("intel: resolver %s failed, moving to next: %s", resolver, err)
+		log.Warningf("intel: resolver %s failed, moving to next: %s", resolver, err)
 		resolver.LockReason.Lock()
 		resolver.FailReason = err.Error()
 		resolver.LockReason.Unlock()
@@ -306,7 +319,7 @@ func tryResolver(resolver *Resolver, lastFailBoundary int64, fqdn string, qtype
 	return rrCache, true
 }
 
-func query(resolver *Resolver, fqdn string, qtype dns.Type) (*RRCache, error) {
+func query(ctx context.Context, resolver *Resolver, fqdn string, qtype dns.Type) (*RRCache, error) {
 
 	q := new(dns.Msg)
 	q.SetQuestion(fqdn, uint16(qtype))
@@ -322,7 +335,7 @@ func query(resolver *Resolver, fqdn string, qtype dns.Type) (*RRCache, error) {
 
 		// error handling
 		if err != nil {
-			log.Tracef("intel: query to %s encountered error: %s", resolver.Server, err)
+			log.Tracer(ctx).Tracef("intel: query to %s encountered error: %s", resolver.Server, err)
 
 			// TODO: handle special cases
 			// 1. connect: network is unreachable
@@ -330,7 +343,7 @@ func query(resolver *Resolver, fqdn string, qtype dns.Type) (*RRCache, error) {
 
 			// temporary error
 			if nerr, ok := err.(net.Error); ok && nerr.Timeout() {
-				log.Tracef("intel: retrying to resolve %s%s with %s, error was: %s", fqdn, qtype.String(), resolver.Server, err)
+				log.Tracer(ctx).Tracef("intel: retrying to resolve %s%s with %s, error is temporary", fqdn, qtype, resolver.Server)
 				continue
 			}
 
@@ -343,8 +356,6 @@ func query(resolver *Resolver, fqdn string, qtype dns.Type) (*RRCache, error) {
 	}
 
 	if err != nil {
-		err = fmt.Errorf("resolving %s%s failed: %s", fqdn, qtype.String(), err)
-		log.Warning(err.Error())
 		return nil, err
 	}
 

intel/resolver.go

@@ -16,7 +16,6 @@ import (
 
 	"github.com/Safing/portmaster/network/environment"
 	"github.com/Safing/portmaster/network/netutils"
-	"github.com/Safing/portmaster/status"
 )
 
 // Resolver holds information about an active resolver.
@@ -33,7 +32,6 @@ type Resolver struct {
 	clientManager *clientManager
 
 	Search             *[]string
-	AllowedSecurityLevel uint8
 	SkipFqdnBeforeInit string
 
 	// atomic
@@ -149,7 +147,7 @@ configuredServersLoop:
 			var lastFail int64
 			new := &Resolver{
 				Server:        server,
-				ServerType:    parts[0],
+				ServerType:    strings.ToLower(parts[0]),
 				ServerAddress: parts[1],
 				ServerIP:      ip,
 				ServerIPScope: netutils.ClassifyIP(ip),
@@ -159,13 +157,12 @@ configuredServersLoop:
 				Initialized:   abool.NewBool(false),
 			}
 
-			switch strings.ToLower(parts[0]) {
+			switch new.ServerType {
 			case "dns":
 				new.clientManager = newDNSClientManager(new)
 			case "tcp":
 				new.clientManager = newTCPClientManager(new)
 			case "tls":
-				new.AllowedSecurityLevel = status.SecurityLevelFortress
 				if len(parts) < 3 {
 					log.Warningf("intel: nameserver missing verification domain as third parameter: %s", server)
 					continue configuredServersLoop
@@ -173,7 +170,6 @@ configuredServersLoop:
 				new.VerifyDomain = parts[2]
 				new.clientManager = newTLSClientManager(new)
 			case "https":
-				new.AllowedSecurityLevel = status.SecurityLevelFortress
 				new.SkipFqdnBeforeInit = dns.Fqdn(strings.Split(parts[1], ":")[0])
 				if len(parts) > 2 {
 					new.VerifyDomain = parts[2]
@@ -212,7 +208,6 @@ assignedServersLoop:
 				LastFail:      &lastFail,
 				Source:        "dhcp",
 				Initialized:   abool.NewBool(false),
-				AllowedSecurityLevel: status.SecurityLevelSecure,
 			}
 			new.clientManager = newDNSClientManager(new)
 

intel/reverse.go

@@ -18,7 +18,7 @@ func ResolveIPAndValidate(ip string, securityLevel uint8) (domain string, err er
 	}
 
 	// get PTR record
-	rrCache := Resolve(rQ, dns.Type(dns.TypePTR), securityLevel)
+	rrCache := Resolve(nil, rQ, dns.Type(dns.TypePTR), securityLevel)
 	if rrCache == nil {
 		return "", errors.New("querying for PTR record failed (may be NXDomain)")
 	}
@@ -42,9 +42,9 @@ func ResolveIPAndValidate(ip string, securityLevel uint8) (domain string, err er
 
 	// get forward record
 	if strings.Contains(ip, ":") {
-		rrCache = Resolve(ptrName, dns.Type(dns.TypeAAAA), securityLevel)
+		rrCache = Resolve(nil, ptrName, dns.Type(dns.TypeAAAA), securityLevel)
 	} else {
-		rrCache = Resolve(ptrName, dns.Type(dns.TypeA), securityLevel)
+		rrCache = Resolve(nil, ptrName, dns.Type(dns.TypeA), securityLevel)
 	}
 	if rrCache == nil {
 		return "", errors.New("querying for A/AAAA record failed (may be NXDomain)")

nameserver/nameserver.go

@@ -3,6 +3,7 @@
 package nameserver
 
 import (
+	"context"
 	"net"
 	"time"
 
@@ -73,6 +74,21 @@ func handleRequest(w dns.ResponseWriter, query *dns.Msg) {
 	fqdn := dns.Fqdn(question.Name)
 	qtype := dns.Type(question.Qtype)
 
+	// check class
+	if question.Qclass != dns.ClassINET {
+		// we only serve IN records, return nxdomain
+		nxDomain(w, query)
+		return
+	}
+
+	// handle request for localhost
+	if fqdn == "localhost." {
+		m := new(dns.Msg)
+		m.SetReply(query)
+		m.Answer = localhostIPs
+		w.WriteMsg(m)
+	}
+
 	// get addresses
 	remoteAddr, ok := w.RemoteAddr().(*net.UDPAddr)
 	if !ok {
@@ -91,28 +107,25 @@ func handleRequest(w dns.ResponseWriter, query *dns.Msg) {
 		return
 	}
 
-	log.Tracef("nameserver: handling request for %s%s from %s:%d", fqdn, qtype, remoteAddr.IP, remoteAddr.Port)
+	// check if valid domain name
-
+	if !netutils.IsValidFqdn(fqdn) {
-	// TODO: if there are 3 request for the same domain/type in a row, delete all caches of that domain
+		log.Debugf("nameserver: domain name %s is invalid, returning nxdomain", fqdn)
-
-	// check class
-	if question.Qclass != dns.ClassINET {
-		// we only serve IN records, return nxdomain
 		nxDomain(w, query)
 		return
 	}
 
-	// handle request for localhost
+	// start tracer
-	if fqdn == "localhost." {
+	ctx := log.AddTracer(context.Background())
-		m := new(dns.Msg)
+	log.Tracer(ctx).Tracef("nameserver: handling new request for %s%s from %s:%d", fqdn, qtype, remoteAddr.IP, remoteAddr.Port)
-		m.SetReply(query)
-		m.Answer = localhostIPs
-		w.WriteMsg(m)
-	}
 
-	// check if valid domain name
+	// TODO: if there are 3 request for the same domain/type in a row, delete all caches of that domain
-	if !netutils.IsValidFqdn(fqdn) {
+
-		log.Tracef("nameserver: domain name %s is invalid, returning nxdomain", fqdn)
+	// get connection
+	// start = time.Now()
+	comm, err := network.GetCommunicationByDNSRequest(ctx, remoteAddr.IP, uint16(remoteAddr.Port), fqdn)
+	// log.Tracef("nameserver: took %s to get comms (and maybe process)", time.Since(start))
+	if err != nil {
+		log.ErrorTracef(ctx, "nameserver: could not identify process of %s:%d, returning nxdomain: %s", remoteAddr.IP, remoteAddr.Port, err)
 		nxDomain(w, query)
 		return
 	}
@@ -122,44 +135,29 @@ func handleRequest(w dns.ResponseWriter, query *dns.Msg) {
 	lms := algs.LmsScoreOfDomain(fqdn)
 	// log.Tracef("nameserver: domain %s has lms score of %f", fqdn, lms)
 	if lms < 10 {
-		log.Tracef("nameserver: possible data tunnel: %s has lms score of %f, returning nxdomain", fqdn, lms)
+		log.WarningTracef(ctx, "nameserver: possible data tunnel by %s: %s has lms score of %f, returning nxdomain", comm.Process(), fqdn, lms)
 		nxDomain(w, query)
 		return
 	}
 
-	// [1/2] use this to time how long it takes to get process info
-	// timed := time.Now()
-
-	// get connection
-	// start = time.Now()
-	comm, err := network.GetCommunicationByDNSRequest(remoteAddr.IP, uint16(remoteAddr.Port), fqdn)
-	// log.Tracef("nameserver: took %s to get comms (and maybe process)", time.Since(start))
-	if err != nil {
-		log.Warningf("nameserver: someone is requesting %s, but could not identify process: %s, returning nxdomain", fqdn, err)
-		nxDomain(w, query)
-		return
-	}
-
-	// [2/2] use this to time how long it takes to get process info
-	// log.Tracef("nameserver: took %s to get connection/process of %s request", time.Now().Sub(timed).String(), fqdn)
-
 	// check profile before we even get intel and rr
 	// start = time.Now()
 	firewall.DecideOnCommunicationBeforeIntel(comm, fqdn)
 	// log.Tracef("nameserver: took %s to make decision", time.Since(start))
 
 	if comm.GetVerdict() == network.VerdictBlock || comm.GetVerdict() == network.VerdictDrop {
+		log.InfoTracef(ctx, "nameserver: %s denied before intel, returning nxdomain", comm)
 		nxDomain(w, query)
 		return
 	}
 
 	// get intel and RRs
 	// start = time.Now()
-	domainIntel, rrCache := intel.GetIntelAndRRs(fqdn, qtype, comm.Process().ProfileSet().SecurityLevel())
+	domainIntel, rrCache := intel.GetIntelAndRRs(ctx, fqdn, qtype, comm.Process().ProfileSet().SecurityLevel())
 	// log.Tracef("nameserver: took %s to get intel and RRs", time.Since(start))
 	if rrCache == nil {
 		// TODO: analyze nxdomain requests, malware could be trying DGA-domains
-		log.Infof("nameserver: %s tried to query %s, but is nxdomain", comm.Process().String(), fqdn)
+		log.WarningTracef(ctx, "nameserver: %s requested %s%s, is nxdomain", comm.Process(), fqdn, qtype)
 		nxDomain(w, query)
 		return
 	}
@@ -174,6 +172,7 @@ func handleRequest(w dns.ResponseWriter, query *dns.Msg) {
 	firewall.DecideOnCommunicationAfterIntel(comm, fqdn, rrCache)
 	switch comm.GetVerdict() {
 	case network.VerdictUndecided, network.VerdictBlock, network.VerdictDrop:
+		log.InfoTracef(ctx, "nameserver: %s denied after intel, returning nxdomain", comm)
 		nxDomain(w, query)
 		return
 	}
@@ -181,6 +180,7 @@ func handleRequest(w dns.ResponseWriter, query *dns.Msg) {
 	// filter DNS response
 	rrCache = firewall.FilterDNSResponse(comm, fqdn, rrCache)
 	if rrCache == nil {
+		log.InfoTracef(ctx, "nameserver: %s implicitly denied by filtering the dns response, returning nxdomain", comm)
 		nxDomain(w, query)
 		return
 	}
@@ -224,4 +224,5 @@ func handleRequest(w dns.ResponseWriter, query *dns.Msg) {
 	m.Ns = rrCache.Ns
 	m.Extra = rrCache.Extra
 	w.WriteMsg(m)
+	log.DebugTracef(ctx, "nameserver: returning response %s%s to %s", fqdn, qtype, comm.Process())
 }