From f31e19aaac606716371e38c25d83952d709395c6 Mon Sep 17 00:00:00 2001 From: Daniel Date: Tue, 1 Dec 2020 16:59:58 +0100 Subject: [PATCH 1/4] Improve logging --- firewall/interception.go | 4 +++- nameserver/nameserver.go | 16 ++++++++++++++-- network/connection.go | 1 + resolver/resolver-tcp.go | 19 ++++++++++++++----- 4 files changed, 32 insertions(+), 8 deletions(-) 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(), From 16e45081b9f18008aea78dc7e81d0af332574a1e Mon Sep 17 00:00:00 2001 From: Daniel Date: Tue, 1 Dec 2020 17:00:11 +0100 Subject: [PATCH 2/4] Increase write timeout for tcp resolver --- resolver/resolver-tcp.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/resolver/resolver-tcp.go b/resolver/resolver-tcp.go index 88dada68..a5e1ed30 100644 --- a/resolver/resolver-tcp.go +++ b/resolver/resolver-tcp.go @@ -16,7 +16,7 @@ import ( ) const ( - tcpWriteTimeout = 1 * time.Second + tcpWriteTimeout = 2 * time.Second ignoreQueriesAfter = 10 * time.Minute heartbeatTimeout = 15 * time.Second ) From 7b1a672d7fedad7e80ba5cbfe0b8240709fbd286 Mon Sep 17 00:00:00 2001 From: Daniel Date: Tue, 1 Dec 2020 17:00:35 +0100 Subject: [PATCH 3/4] Update getter fallback values in profile config --- profile/config.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/profile/config.go b/profile/config.go index 96d6880d..ac95d419 100644 --- a/profile/config.go +++ b/profile/config.go @@ -274,7 +274,7 @@ The lists are automatically updated every hour using incremental updates. Description: "Block connections that match enabled filter lists.", Help: filterListsHelp, OptType: config.OptTypeStringArray, - DefaultValue: []string{"TRAC", "MAL"}, + DefaultValue: []string{"TRAC", "MAL", "BAD"}, Annotations: config.Annotations{ config.DisplayHintAnnotation: "filter list", config.DisplayOrderAnnotation: cfgOptionFilterListsOrder, @@ -326,7 +326,7 @@ The lists are automatically updated every hour using incremental updates. if err != nil { return err } - cfgOptionFilterSubDomains = config.Concurrent.GetAsInt(CfgOptionFilterSubDomainsKey, int64(status.SecurityLevelOff)) + cfgOptionFilterSubDomains = config.Concurrent.GetAsInt(CfgOptionFilterSubDomainsKey, int64(status.SecurityLevelsAll)) cfgIntOptions[CfgOptionFilterSubDomainsKey] = cfgOptionFilterSubDomains // Block Scope Local @@ -367,7 +367,7 @@ The lists are automatically updated every hour using incremental updates. if err != nil { return err } - cfgOptionBlockScopeLAN = config.Concurrent.GetAsInt(CfgOptionBlockScopeLANKey, int64(status.SecurityLevelOff)) + cfgOptionBlockScopeLAN = config.Concurrent.GetAsInt(CfgOptionBlockScopeLANKey, int64(status.SecurityLevelsHighAndExtreme)) cfgIntOptions[CfgOptionBlockScopeLANKey] = cfgOptionBlockScopeLAN // Block Scope Internet @@ -407,7 +407,7 @@ The lists are automatically updated every hour using incremental updates. if err != nil { return err } - cfgOptionBlockP2P = config.Concurrent.GetAsInt(CfgOptionBlockP2PKey, int64(status.SecurityLevelsAll)) + cfgOptionBlockP2P = config.Concurrent.GetAsInt(CfgOptionBlockP2PKey, int64(status.SecurityLevelExtreme)) cfgIntOptions[CfgOptionBlockP2PKey] = cfgOptionBlockP2P // Block Inbound Connections From 30863d9fa317d704b88cc547d6b81603c3eb272d Mon Sep 17 00:00:00 2001 From: Daniel Date: Tue, 1 Dec 2020 17:01:09 +0100 Subject: [PATCH 4/4] Ensure profile settings are always validated on first use --- profile/profile-layered.go | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/profile/profile-layered.go b/profile/profile-layered.go index 897ffb22..4228bf39 100644 --- a/profile/profile-layered.go +++ b/profile/profile-layered.go @@ -61,6 +61,7 @@ func NewLayeredProfile(localProfile *Profile) *LayeredProfile { layers: make([]*Profile, 0, len(localProfile.LinkedProfiles)+1), LayerIDs: make([]string, 0, len(localProfile.LinkedProfiles)+1), globalValidityFlag: config.NewValidityFlag(), + RevisionCounter: 1, securityLevel: &securityLevelVal, } @@ -360,7 +361,7 @@ func (lp *LayeredProfile) wrapSecurityLevelOption(configKey string, globalConfig } func (lp *LayeredProfile) wrapBoolOption(configKey string, globalConfig config.BoolOption) config.BoolOption { - revCnt := lp.RevisionCounter + var revCnt uint64 = 0 var value bool var refreshLock sync.Mutex @@ -392,7 +393,7 @@ func (lp *LayeredProfile) wrapBoolOption(configKey string, globalConfig config.B } func (lp *LayeredProfile) wrapIntOption(configKey string, globalConfig config.IntOption) config.IntOption { - revCnt := lp.RevisionCounter + var revCnt uint64 = 0 var value int64 var refreshLock sync.Mutex @@ -441,7 +442,7 @@ func (lp *LayeredProfile) GetProfileSource(configKey string) string { For later: func (lp *LayeredProfile) wrapStringOption(configKey string, globalConfig config.StringOption) config.StringOption { - revCnt := lp.RevisionCounter + var revCnt uint64 = 0 var value string var refreshLock sync.Mutex