Improve logging

firewall/interception.go

@@ -67,7 +67,7 @@ func handlePacket(ctx context.Context, pkt packet.Packet) {
 	// Add context tracer and set context on packet.
 	traceCtx, tracer := log.AddTracer(ctx)
 	if tracer != nil {
-		defer tracer.Submit()
+		// The trace is submitted in `network.Connection.packetHandler()`.
 		tracer.Tracef("filter: handling packet: %s", pkt)
 	}
 	pkt.SetCtx(traceCtx)
@@ -193,6 +193,7 @@ func initialHandler(conn *network.Connection, pkt packet.Packet) {
 	// reroute dns requests to nameserver
 	if conn.Process().Pid != os.Getpid() && pkt.IsOutbound() && pkt.Info().DstPort == 53 && !pkt.Info().Src.Equal(pkt.Info().Dst) {
 		conn.Verdict = network.VerdictRerouteToNameserver
+		conn.Reason.Msg = "redirecting rogue dns query"
 		conn.Internal = true
 		conn.StopFirewallHandler()
 		issueVerdict(conn, pkt, 0, true)
@@ -241,6 +242,7 @@ func initialHandler(conn *network.Connection, pkt packet.Packet) {
 }
 
 func defaultHandler(conn *network.Connection, pkt packet.Packet) {
+	// TODO: `pkt` has an active trace log, which we currently don't submit.
 	issueVerdict(conn, pkt, 0, true)
 }
 

nameserver/nameserver.go

@@ -254,7 +254,13 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 		// Request was blocked by the firewall.
 		switch conn.Verdict {
 		case network.VerdictBlock, network.VerdictDrop, network.VerdictFailed:
-			tracer.Infof("nameserver: %s request for %s from %s", conn.Verdict.Verb(), q.ID(), conn.Process())
+			tracer.Infof(
+				"nameserver: returning %s response (%s) for %s to %s",
+				conn.Verdict.Verb(),
+				dns.RcodeToString[rrCache.RCode],
+				q.ID(),
+				conn.Process(),
+			)
 			return reply(conn, conn)
 		}
 	}
@@ -268,6 +274,12 @@ func handleRequest(ctx context.Context, w dns.ResponseWriter, request *dns.Msg)
 	}
 
 	// Reply with successful response.
-	tracer.Infof("nameserver: returning %s response for %s to %s", conn.Verdict.Verb(), q.ID(), conn.Process())
+	tracer.Infof(
+		"nameserver: returning %s response (%s) for %s to %s",
+		conn.Verdict.Verb(),
+		dns.RcodeToString[rrCache.RCode],
+		q.ID(),
+		conn.Process(),
+	)
 	return reply(rrCache, conn, rrCache)
 }

network/connection.go

@@ -520,6 +520,7 @@ func (conn *Connection) packetHandler() {
 		}
 
 		conn.Unlock()
+
 		// submit trace logs
 		log.Tracer(pkt.Ctx()).Submit()
 	}

resolver/resolver-tcp.go

@@ -419,7 +419,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 {
-				mgr.logConnectionError(err, conn, connClosing)
+				mgr.logConnectionError(err, conn, connClosing, false)
 				return true
 			}
 
@@ -500,14 +500,14 @@ func (mgr *tcpResolverConnMgr) msgReader(
 	for {
 		msg, err := conn.ReadMsg()
 		if err != nil {
-			mgr.logConnectionError(err, conn, connClosing)
+			mgr.logConnectionError(err, conn, connClosing, true)
 			return nil
 		}
 		mgr.responses <- msg
 	}
 }
 
-func (mgr *tcpResolverConnMgr) logConnectionError(err error, conn *dns.Conn, connClosing *abool.AtomicBool) {
+func (mgr *tcpResolverConnMgr) logConnectionError(err error, conn *dns.Conn, connClosing *abool.AtomicBool, reading bool) {
 	// Check if we are the first to see an error.
 	if connClosing.SetToIf(false, true) {
 		// Get amount of in flight queries.
@@ -516,14 +516,23 @@ func (mgr *tcpResolverConnMgr) logConnectionError(err error, conn *dns.Conn, con
 		mgr.tr.Unlock()
 
 		// Log error.
-		if errors.Is(err, io.EOF) {
+		switch {
+		case 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 {
+		case reading:
+			log.Warningf(
+				"resolver: read error from %s (%s) with %d in-flight queries: %s",
+				mgr.tr.resolver.GetName(),
+				conn.RemoteAddr(),
+				inFlightQueries,
+				err,
+			)
+		default:
 			log.Warningf(
 				"resolver: write error to %s (%s) with %d in-flight queries: %s",
 				mgr.tr.resolver.GetName(),