Final feedback implementation and fixes

nameserver/nameserver.go

@@ -108,7 +108,7 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 	// Return with server failure if offline.
 	if netenv.GetOnlineStatus() == netenv.StatusOffline &&
 		!netenv.IsConnectivityDomain(q.FQDN) {
-		tracer.Debugf("resolver: not resolving %s, device is offline", q.FQDN)
+		tracer.Debugf("namserver: not resolving %s, device is offline", q.FQDN)
 		return reply(nsutil.ServerFailure("resolving disabled, device is offline"))
 	}
 
@@ -121,6 +121,7 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 
 	// Handle request for localhost.
 	if strings.HasSuffix(q.FQDN, "localhost.") {
+		tracer.Tracef("namserver: returning localhost records")
 		return reply(nsutil.Localhost(""))
 	}
 
@@ -196,15 +197,23 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 		// React to special errors.
 		switch {
 		case errors.Is(err, resolver.ErrNotFound):
-			return reply(nsutil.NxDomain(""), nil)
+			tracer.Tracef("namserver: NXDomain via error")
+			return reply(nsutil.NxDomain(""))
 		case errors.Is(err, resolver.ErrBlocked):
-			return reply(nsutil.ZeroIP(""), nil)
+			tracer.Tracef("namserver: block via error")
+			return reply(nsutil.ZeroIP(""))
 		case errors.Is(err, resolver.ErrLocalhost):
-			return reply(nsutil.Localhost(""), nil)
+			tracer.Tracef("namserver: returning localhost records")
+			return reply(nsutil.Localhost(""))
 		default:
-			return reply(nsutil.ServerFailure("internal error: "+err.Error()), nil)
+			tracer.Warningf("nameserver: failed to resolve %s: %s", q.ID(), err)
+			return reply(nsutil.ServerFailure("internal error: " + err.Error()))
 		}
 	}
+	if rrCache == 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)

nameserver/nsutil/nsutil.go

@@ -74,9 +74,7 @@ func ZeroIP(msgs ...string) ResponderFunc {
 			reply.SetRcode(request, dns.RcodeSuccess)
 		}
 
-		for _, msg := range msgs {
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
-			AddMessageToReply(ctx, reply, log.InfoLevel, msg)
-		}
 
 		return reply
 	}
@@ -116,9 +114,7 @@ func Localhost(msgs ...string) ResponderFunc {
 			reply.SetRcode(request, dns.RcodeSuccess)
 		}
 
-		for _, msg := range msgs {
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
-			AddMessageToReply(ctx, reply, log.InfoLevel, msg)
-		}
 
 		return reply
 	}
@@ -128,9 +124,7 @@ func Localhost(msgs ...string) ResponderFunc {
 func NxDomain(msgs ...string) ResponderFunc {
 	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
 		reply := new(dns.Msg).SetRcode(request, dns.RcodeNameError)
-		for _, msg := range msgs {
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
-			AddMessageToReply(ctx, reply, log.InfoLevel, msg)
-		}
 		return reply
 	}
 }
@@ -139,9 +133,7 @@ func NxDomain(msgs ...string) ResponderFunc {
 func Refused(msgs ...string) ResponderFunc {
 	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
 		reply := new(dns.Msg).SetRcode(request, dns.RcodeRefused)
-		for _, msg := range msgs {
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
-			AddMessageToReply(ctx, reply, log.InfoLevel, msg)
-		}
 		return reply
 	}
 }
@@ -150,9 +142,7 @@ func Refused(msgs ...string) ResponderFunc {
 func ServerFailure(msgs ...string) ResponderFunc {
 	return func(ctx context.Context, request *dns.Msg) *dns.Msg {
 		reply := new(dns.Msg).SetRcode(request, dns.RcodeServerFailure)
-		for _, msg := range msgs {
+		AddMessagesToReply(ctx, reply, log.InfoLevel, msgs...)
-			AddMessageToReply(ctx, reply, log.InfoLevel, msg)
-		}
 		return reply
 	}
 }
@@ -174,18 +164,25 @@ func MakeMessageRecord(level log.Severity, msg string) (dns.RR, error) { //nolin
 	return rr, nil
 }
 
-// AddMessageToReply creates an information resource records using
+// AddMessagesToReply creates information resource records using
-// MakeMessageRecord and immediately adds it the the extra section of the given
+// 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 AddMessageToReply(ctx context.Context, reply *dns.Msg, level log.Severity, msg string) {
+func AddMessagesToReply(ctx context.Context, reply *dns.Msg, level log.Severity, msgs ...string) {
-	if msg != "" {
+	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)
-			return
+			continue
 		}
 
+		// Add to extra section of the reply.
 		reply.Extra = append(reply.Extra, rr)
 	}
 }

nameserver/response.go

@@ -29,9 +29,11 @@ func sendResponse(
 
 	// Add extra RRs through a custom RRProvider.
 	for _, rrProvider := range rrProviders {
+		if rrProvider != nil {
 			rrs := rrProvider.GetExtraRRs(ctx, request)
 			reply.Extra = append(reply.Extra, rrs...)
 		}
+	}
 
 	// Write reply.
 	if err := writeDNSResponse(w, reply); err != nil {

network/dns.go

@@ -105,7 +105,7 @@ func (conn *Connection) ReplyWithDNS(ctx context.Context, request *dns.Msg) *dns
 		return nsutil.ZeroIP().ReplyWithDNS(ctx, request)
 	default:
 		reply := nsutil.ServerFailure().ReplyWithDNS(ctx, request)
-		nsutil.AddMessageToReply(ctx, reply, log.ErrorLevel, "INTERNAL ERROR: incorrect use of network.Connection's DNS Responder")
+		nsutil.AddMessagesToReply(ctx, reply, log.ErrorLevel, "INTERNAL ERROR: incorrect use of Connection DNS Responder")
 		return reply
 	}
 }

resolver/resolve.go

@@ -132,7 +132,6 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
 	if !q.NoCaching {
 		rrCache = checkCache(ctx, q)
 		if rrCache != nil && !rrCache.Expired() {
-			rrCache.MixAnswers()
 			return rrCache, nil
 		}
 
@@ -142,7 +141,6 @@ func Resolve(ctx context.Context, q *Query) (rrCache *RRCache, err error) {
 			// we waited for another request, recheck the cache!
 			rrCache = checkCache(ctx, q)
 			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)
@@ -221,7 +219,7 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
 		log.Tracer(ctx).Tracef(
 			"resolver: cache for %s will expire in %s, refreshing async now",
 			q.ID(),
-			time.Until(time.Unix(rrCache.TTL, 0)),
+			time.Until(time.Unix(rrCache.TTL, 0)).Round(time.Second),
 		)
 
 		// resolve async
@@ -231,6 +229,8 @@ func checkCache(ctx context.Context, q *Query) *RRCache {
 			_, err := resolveAndCache(ctx, q, nil)
 			if err != nil {
 				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
 		})
@@ -240,7 +240,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
 }
@@ -392,21 +392,32 @@ resolveLoop:
 	}
 
 	// 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.IsNXDomain():
 			// 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
+	}
 
 	// Save the new entry if cache is enabled.
 	if !q.NoCaching {
 		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/rrcache.go

@@ -23,7 +23,7 @@ type RRCache struct {
 	Domain   string   // constant
 	Question dns.Type // constant
 
-	Answer []dns.RR // might be mixed
+	Answer []dns.RR // constant
 	Ns     []dns.RR // constant
 	Extra  []dns.RR // constant
 	TTL    int64    // constant
@@ -34,6 +34,7 @@ type RRCache struct {
 
 	servedFromCache bool     // mutable
 	requestingNew   bool     // mutable
+	isBackup        bool     // mutable
 	Filtered        bool     // mutable
 	FilteredEntries []string // mutable
 
@@ -55,19 +56,11 @@ func (rrCache *RRCache) ExpiresSoon() bool {
 	return rrCache.TTL <= time.Now().Unix()+refreshTTL
 }
 
-// MixAnswers randomizes the answer records to allow dumb clients (who only look at the first record) to reliably connect.
+// Clean sets all TTLs to 17 and sets cache expiry with specified minimum.
-func (rrCache *RRCache) MixAnswers() {
+func (rrCache *RRCache) Clean(minExpires uint32) {
 	rrCache.Lock()
 	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) {
 	var lowestTTL uint32 = 0xFFFFFFFF
 	var header *dns.RR_Header
 
@@ -221,6 +214,9 @@ func (rrCache *RRCache) Flags() string {
 	if rrCache.requestingNew {
 		s += "R"
 	}
+	if rrCache.isBackup {
+		s += "B"
+	}
 	if rrCache.Filtered {
 		s += "F"
 	}
@@ -253,6 +249,7 @@ func (rrCache *RRCache) ShallowCopy() *RRCache {
 		updated:         rrCache.updated,
 		servedFromCache: rrCache.servedFromCache,
 		requestingNew:   rrCache.requestingNew,
+		isBackup:        rrCache.isBackup,
 		Filtered:        rrCache.Filtered,
 		FilteredEntries: rrCache.FilteredEntries,
 	}
@@ -263,13 +260,23 @@ func (rrCache *RRCache) ReplyWithDNS(ctx context.Context, request *dns.Msg) *dns
 	// reply to query
 	reply := new(dns.Msg)
 	reply.SetRcode(request, dns.RcodeSuccess)
-	reply.Answer = rrCache.Answer
 	reply.Ns = rrCache.Ns
 	reply.Extra = rrCache.Extra
 
-	// Set NXDomain return code.
 	if rrCache.IsNXDomain() {
+		// Set NXDomain return code if not the reply has no answers.
 		reply.Rcode = dns.RcodeNameError
+	} else {
+		// 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
@@ -286,13 +293,16 @@ func (rrCache *RRCache) GetExtraRRs(ctx context.Context, query *dns.Msg) (extra
 
 	// Add expiry and cache information.
 	if rrCache.Expired() {
-		extra = addExtra(ctx, extra, fmt.Sprintf("record expired since %s, requesting new", time.Since(time.Unix(rrCache.TTL, 0))))
+		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))))
+		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 {