Pull request 1893: all: imp logs; upd dnsproxy

Updates #5285.

Squashed commit of the following:

commit 8e7d17505492b6983ba9e713455b98652938d73d
Author: Ainar Garipov <A.Garipov@AdGuard.COM>
Date:   Wed Jun 28 13:33:14 2023 +0300

    all: imp logs; upd dnsproxy
This commit is contained in:
Ainar Garipov
2023-06-28 13:46:04 +03:00
parent cf7c12c97b
commit 6889837785
10 changed files with 112 additions and 53 deletions

View File

@@ -145,10 +145,13 @@ func (s *Server) handleDNSRequest(_ *proxy.Proxy, pctx *proxy.DNSContext) error
// processRecursion checks the incoming request and halts its handling by
// answering NXDOMAIN if s has tried to resolve it recently.
func (s *Server) processRecursion(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing recursion")
defer log.Debug("dnsforward: finished processing recursion")
pctx := dctx.proxyCtx
if msg := pctx.Req; msg != nil && s.recDetector.check(*msg) {
log.Debug("recursion detected resolving %q", msg.Question[0].Name)
log.Debug("dnsforward: recursion detected resolving %q", msg.Question[0].Name)
pctx.Res = s.genNXDomain(pctx.Req)
return resultCodeFinish
@@ -158,10 +161,13 @@ func (s *Server) processRecursion(dctx *dnsContext) (rc resultCode) {
}
// processInitial terminates the following processing for some requests if
// needed and enriches the ctx with some client-specific information.
// needed and enriches dctx with some client-specific information.
//
// TODO(e.burkov): Decompose into less general processors.
func (s *Server) processInitial(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing initial")
defer log.Debug("dnsforward: finished processing initial")
pctx := dctx.proxyCtx
q := pctx.Req.Question[0]
qt := q.Qtype
@@ -282,6 +288,9 @@ func (s *Server) onDHCPLeaseChanged(flags int) {
//
// See https://www.ietf.org/archive/id/draft-ietf-add-ddr-10.html.
func (s *Server) processDDRQuery(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing ddr")
defer log.Debug("dnsforward: finished processing ddr")
if !s.conf.HandleDDR {
return resultCodeSuccess
}
@@ -375,6 +384,9 @@ func (s *Server) makeDDRResponse(req *dns.Msg) (resp *dns.Msg) {
// processDetermineLocal determines if the client's IP address is from locally
// served network and saves the result into the context.
func (s *Server) processDetermineLocal(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing local detection")
defer log.Debug("dnsforward: finished processing local detection")
rc = resultCodeSuccess
var ip net.IP
@@ -405,6 +417,9 @@ func (s *Server) dhcpHostToIP(host string) (ip netip.Addr, ok bool) {
//
// TODO(a.garipov): Adapt to AAAA as well.
func (s *Server) processDHCPHosts(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing dhcp hosts")
defer log.Debug("dnsforward: finished processing dhcp hosts")
pctx := dctx.proxyCtx
req := pctx.Req
q := req.Question[0]
@@ -544,6 +559,9 @@ func extractARPASubnet(domain string) (pref netip.Prefix, err error) {
// processRestrictLocal responds with NXDOMAIN to PTR requests for IP addresses
// in locally served network from external clients.
func (s *Server) processRestrictLocal(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing local restriction")
defer log.Debug("dnsforward: finished processing local restriction")
pctx := dctx.proxyCtx
req := pctx.Req
q := req.Question[0]
@@ -613,6 +631,9 @@ func (s *Server) ipToDHCPHost(ip netip.Addr) (host string, ok bool) {
// processDHCPAddrs responds to PTR requests if the target IP is leased by the
// DHCP server.
func (s *Server) processDHCPAddrs(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing dhcp addrs")
defer log.Debug("dnsforward: finished processing dhcp addrs")
pctx := dctx.proxyCtx
if pctx.Res != nil {
return resultCodeSuccess
@@ -658,6 +679,9 @@ func (s *Server) processDHCPAddrs(dctx *dnsContext) (rc resultCode) {
// processLocalPTR responds to PTR requests if the target IP is detected to be
// inside the local network and the query was not answered from DHCP.
func (s *Server) processLocalPTR(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing local ptr")
defer log.Debug("dnsforward: finished processing local ptr")
pctx := dctx.proxyCtx
if pctx.Res != nil {
return resultCodeSuccess
@@ -692,6 +716,9 @@ func (s *Server) processLocalPTR(dctx *dnsContext) (rc resultCode) {
// Apply filtering logic
func (s *Server) processFilteringBeforeRequest(ctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing filtering before req")
defer log.Debug("dnsforward: finished processing filtering before req")
if ctx.proxyCtx.Res != nil {
// Go on since the response is already set.
return resultCodeSuccess
@@ -725,6 +752,9 @@ func ipStringFromAddr(addr net.Addr) (ipStr string) {
// processUpstream passes request to upstream servers and handles the response.
func (s *Server) processUpstream(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing upstream")
defer log.Debug("dnsforward: finished processing upstream")
pctx := dctx.proxyCtx
req := pctx.Req
q := req.Question[0]
@@ -871,6 +901,9 @@ func (s *Server) setCustomUpstream(pctx *proxy.DNSContext, clientID string) {
// Apply filtering logic after we have received response from upstream servers
func (s *Server) processFilteringAfterResponse(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing filtering after req")
defer log.Debug("dnsforward: finished processing filtering after req")
pctx := dctx.proxyCtx
switch res := dctx.result; res.Reason {
case filtering.NotFilteredAllowList:

View File

@@ -58,7 +58,7 @@ type hostToIPTable = map[string]netip.Addr
// TODO(e.burkov): Use the [DHCP] interface instead.
type ipToHostTable = map[netip.Addr]string
// DHCP is an interface for accesing DHCP lease data needed in this package.
// DHCP is an interface for accessing DHCP lease data needed in this package.
type DHCP interface {
// HostByIP returns the hostname of the DHCP client with the given IP
// address. The address will be netip.Addr{} if there is no such client,
@@ -236,7 +236,7 @@ func (s *Server) Close() {
s.dnsProxy = nil
if err := s.ipset.close(); err != nil {
log.Error("closing ipset: %s", err)
log.Error("dnsforward: closing ipset: %s", err)
}
}
@@ -464,7 +464,7 @@ func (s *Server) setupResolvers(localAddrs []string) (err error) {
return err
}
log.Debug("upstreams to resolve PTR for local addresses: %v", localAddrs)
log.Debug("dnsforward: upstreams to resolve ptr for local addresses: %v", localAddrs)
var upsConfig *proxy.UpstreamConfig
upsConfig, err = proxy.ParseUpstreamsConfig(
@@ -677,7 +677,9 @@ func (s *Server) Reconfigure(conf *ServerConfig) error {
s.serverLock.Lock()
defer s.serverLock.Unlock()
log.Print("Start reconfiguring the server")
log.Info("dnsforward: starting reconfiguring server")
defer log.Info("dnsforward: finished reconfiguring server")
err := s.stopLocked()
if err != nil {
return fmt.Errorf("could not reconfigure the server: %w", err)
@@ -729,13 +731,13 @@ func (s *Server) IsBlockedClient(ip netip.Addr, clientID string) (blocked bool,
// Allow if at least one of the checks allows in allowlist mode, but block
// if at least one of the checks blocks in blocklist mode.
if allowlistMode && blockedByIP && blockedByClientID {
log.Debug("client %v (id %q) is not in access allowlist", ip, clientID)
log.Debug("dnsforward: client %v (id %q) is not in access allowlist", ip, clientID)
// Return now without substituting the empty rule for the
// clientID because the rule can't be empty here.
return true, rule
} else if !allowlistMode && (blockedByIP || blockedByClientID) {
log.Debug("client %v (id %q) is in access blocklist", ip, clientID)
log.Debug("dnsforward: client %v (id %q) is in access blocklist", ip, clientID)
blocked = true
}

View File

@@ -110,6 +110,9 @@ func ipsFromAnswer(ans []dns.RR) (ip4s, ip6s []net.IP) {
// process adds the resolved IP addresses to the domain's ipsets, if any.
func (c *ipsetCtx) process(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: ipset: started processing")
defer log.Debug("dnsforward: ipset: finished processing")
if c.skipIpsetProcessing(dctx) {
return resultCodeSuccess
}
@@ -125,12 +128,12 @@ func (c *ipsetCtx) process(dctx *dnsContext) (rc resultCode) {
n, err := c.ipsetMgr.Add(host, ip4s, ip6s)
if err != nil {
// Consider ipset errors non-critical to the request.
log.Error("ipset: adding host ips: %s", err)
log.Error("dnsforward: ipset: adding host ips: %s", err)
return resultCodeSuccess
}
log.Debug("ipset: added %d new ipset entries", n)
log.Debug("dnsforward: ipset: added %d new ipset entries", n)
return resultCodeSuccess
}

View File

@@ -17,60 +17,78 @@ import (
// Write Stats data and logs
func (s *Server) processQueryLogsAndStats(dctx *dnsContext) (rc resultCode) {
log.Debug("dnsforward: started processing querylog and stats")
defer log.Debug("dnsforward: finished processing querylog and stats")
elapsed := time.Since(dctx.startTime)
pctx := dctx.proxyCtx
shouldLog := true
msg := pctx.Req
q := msg.Question[0]
q := pctx.Req.Question[0]
host := strings.ToLower(strings.TrimSuffix(q.Name, "."))
// don't log ANY request if refuseAny is enabled
if q.Qtype == dns.TypeANY && s.conf.RefuseAny {
shouldLog = false
}
ip, _ := netutil.IPAndPortFromAddr(pctx.Addr)
ip = slices.Clone(ip)
s.serverLock.RLock()
defer s.serverLock.RUnlock()
s.anonymizer.Load()(ip)
log.Debug("client ip: %s", ip)
log.Debug("dnsforward: client ip for stats and querylog: %s", ip)
ipStr := ip.String()
ids := []string{ipStr, dctx.clientID}
qt, cl := q.Qtype, q.Qclass
// Synchronize access to s.queryLog and s.stats so they won't be suddenly
// uninitialized while in use. This can happen after proxy server has been
// stopped, but its workers haven't yet exited.
if shouldLog &&
s.queryLog != nil &&
// TODO(s.chzhen): Use dnsforward.dnsContext when it will start
// containing persistent client.
s.queryLog.ShouldLog(host, q.Qtype, q.Qclass, ids) {
s.serverLock.RLock()
defer s.serverLock.RUnlock()
if s.shouldLog(host, qt, cl, ids) {
s.logQuery(dctx, pctx, elapsed, ip)
} else {
log.Debug(
"dnsforward: request %s %s from %s ignored; not logging",
dns.Type(q.Qtype),
"dnsforward: request %s %s %q from %s ignored; not adding to querylog",
dns.Class(cl),
dns.Type(qt),
host,
ip,
)
}
if s.stats != nil &&
// TODO(s.chzhen): Use dnsforward.dnsContext when it will start
// containing persistent client.
s.stats.ShouldCount(host, q.Qtype, q.Qclass, ids) {
if s.shouldCountStat(host, qt, cl, ids) {
s.updateStats(dctx, elapsed, *dctx.result, ipStr)
} else {
log.Debug(
"dnsforward: request %s %s %q from %s ignored; not counting in stats",
dns.Class(cl),
dns.Type(qt),
host,
ip,
)
}
return resultCodeSuccess
}
// shouldLog returns true if the query with the given data should be logged in
// the query log. s.serverLock is expected to be locked.
func (s *Server) shouldLog(host string, qt, cl uint16, ids []string) (ok bool) {
if qt == dns.TypeANY && s.conf.RefuseAny {
return false
}
// TODO(s.chzhen): Use dnsforward.dnsContext when it will start containing
// persistent client.
return s.queryLog != nil && s.queryLog.ShouldLog(host, qt, cl, ids)
}
// shouldCountStat returns true if the query with the given data should be
// counted in the statistics. s.serverLock is expected to be locked.
func (s *Server) shouldCountStat(host string, qt, cl uint16, ids []string) (ok bool) {
// TODO(s.chzhen): Use dnsforward.dnsContext when it will start containing
// persistent client.
return s.stats != nil && s.stats.ShouldCount(host, qt, cl, ids)
}
// logQuery pushes the request details into the query log.
func (s *Server) logQuery(
dctx *dnsContext,