diff --git a/firewall/interception.go b/firewall/interception.go index eed0e3e9..55281a48 100644 --- a/firewall/interception.go +++ b/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) } diff --git a/nameserver/nameserver.go b/nameserver/nameserver.go index 0a4fb434..4c7aa4c1 100644 --- a/nameserver/nameserver.go +++ b/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) } diff --git a/network/connection.go b/network/connection.go index f17b4e2e..2b34d9c3 100644 --- a/network/connection.go +++ b/network/connection.go @@ -520,6 +520,7 @@ func (conn *Connection) packetHandler() { } conn.Unlock() + // submit trace logs log.Tracer(pkt.Ctx()).Submit() } diff --git a/resolver/resolver-tcp.go b/resolver/resolver-tcp.go index 8fec2024..88dada68 100644 --- a/resolver/resolver-tcp.go +++ b/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(),