all: slog rdns whois

internal/client/addrproc.go

@@ -2,6 +2,7 @@ package client
 
 import (
 	"context"
+	"log/slog"
 	"net/netip"
 	"sync"
 	"time"
@@ -11,6 +12,7 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/whois"
 	"github.com/AdguardTeam/golibs/errors"
 	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil"
 )
 
@@ -38,6 +40,10 @@ func (EmptyAddrProc) Close() (_ error) { return nil }
 
 // DefaultAddrProcConfig is the configuration structure for address processors.
 type DefaultAddrProcConfig struct {
+	// BaseLogger is used to create loggers with custom prefixes for sources of
+	// information about runtime clients.  It must not be nil.
+	BaseLogger *slog.Logger
+
 	// DialContext is used to create TCP connections to WHOIS servers.
 	// DialContext must not be nil if [DefaultAddrProcConfig.UseWHOIS] is true.
 	DialContext aghnet.DialContextFunc
@@ -147,6 +153,7 @@ func NewDefaultAddrProc(c *DefaultAddrProcConfig) (p *DefaultAddrProc) {
 
 	if c.UseRDNS {
 		p.rdns = rdns.New(&rdns.Config{
+			Logger:    c.BaseLogger.With(slogutil.KeyPrefix, "rdns"),
 			Exchanger: c.Exchanger,
 			CacheSize: defaultCacheSize,
 			CacheTTL:  defaultIPTTL,
@@ -154,7 +161,7 @@ func NewDefaultAddrProc(c *DefaultAddrProcConfig) (p *DefaultAddrProc) {
 	}
 
 	if c.UseWHOIS {
-		p.whois = newWHOIS(c.DialContext)
+		p.whois = newWHOIS(c.BaseLogger.With(slogutil.KeyPrefix, "whois"), c.DialContext)
 	}
 
 	go p.process(c.CatchPanics)
@@ -168,7 +175,7 @@ func NewDefaultAddrProc(c *DefaultAddrProcConfig) (p *DefaultAddrProc) {
 
 // newWHOIS returns a whois.Interface instance using the given function for
 // dialing.
-func newWHOIS(dialFunc aghnet.DialContextFunc) (w whois.Interface) {
+func newWHOIS(logger *slog.Logger, dialFunc aghnet.DialContextFunc) (w whois.Interface) {
 	// TODO(s.chzhen):  Consider making configurable.
 	const (
 		// defaultTimeout is the timeout for WHOIS requests.
@@ -186,6 +193,7 @@ func newWHOIS(dialFunc aghnet.DialContextFunc) (w whois.Interface) {
 	)
 
 	return whois.New(&whois.Config{
+		Logger:          logger,
 		DialContext:     dialFunc,
 		ServerAddr:      whois.DefaultServer,
 		Port:            whois.DefaultPort,
@@ -227,9 +235,11 @@ func (p *DefaultAddrProc) process(catchPanics bool) {
 
 	log.Info("clients: processing addresses")
 
+	ctx := context.TODO()
+
 	for ip := range p.clientIPs {
-		host := p.processRDNS(ip)
+		host := p.processRDNS(ctx, ip)
-		info := p.processWHOIS(ip)
+		info := p.processWHOIS(ctx, ip)
 
 		p.addrUpdater.UpdateAddress(ip, host, info)
 	}
@@ -239,7 +249,7 @@ func (p *DefaultAddrProc) process(catchPanics bool) {
 
 // processRDNS resolves the clients' IP addresses using reverse DNS.  host is
 // empty if there were errors or if the information hasn't changed.
-func (p *DefaultAddrProc) processRDNS(ip netip.Addr) (host string) {
+func (p *DefaultAddrProc) processRDNS(ctx context.Context, ip netip.Addr) (host string) {
 	start := time.Now()
 	log.Debug("clients: processing %s with rdns", ip)
 	defer func() {
@@ -251,7 +261,7 @@ func (p *DefaultAddrProc) processRDNS(ip netip.Addr) (host string) {
 		return
 	}
 
-	host, changed := p.rdns.Process(ip)
+	host, changed := p.rdns.Process(ctx, ip)
 	if !changed {
 		host = ""
 	}
@@ -268,7 +278,7 @@ func (p *DefaultAddrProc) shouldResolve(ip netip.Addr) (ok bool) {
 // processWHOIS looks up the information about clients' IP addresses in the
 // WHOIS databases.  info is nil if there were errors or if the information
 // hasn't changed.
-func (p *DefaultAddrProc) processWHOIS(ip netip.Addr) (info *whois.Info) {
+func (p *DefaultAddrProc) processWHOIS(ctx context.Context, ip netip.Addr) (info *whois.Info) {
 	start := time.Now()
 	log.Debug("clients: processing %s with whois", ip)
 	defer func() {
@@ -277,7 +287,7 @@ func (p *DefaultAddrProc) processWHOIS(ip netip.Addr) (info *whois.Info) {
 
 	// TODO(s.chzhen):  Move the timeout logic from WHOIS configuration to the
 	// context.
-	info, changed := p.whois.Process(context.Background(), ip)
+	info, changed := p.whois.Process(ctx, ip)
 	if !changed {
 		info = nil
 	}

internal/client/addrproc_test.go

@@ -13,6 +13,7 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/client"
 	"github.com/AdguardTeam/AdGuardHome/internal/whois"
 	"github.com/AdguardTeam/golibs/errors"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil"
 	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/AdguardTeam/golibs/testutil/fakenet"
@@ -99,6 +100,7 @@ func TestDefaultAddrProc_Process_rDNS(t *testing.T) {
 			updInfoCh := make(chan *whois.Info, 1)
 
 			p := client.NewDefaultAddrProc(&client.DefaultAddrProcConfig{
+				BaseLogger: slogutil.NewDiscardLogger(),
 				DialContext: func(_ context.Context, _, _ string) (conn net.Conn, err error) {
 					panic("not implemented")
 				},
@@ -208,6 +210,7 @@ func TestDefaultAddrProc_Process_WHOIS(t *testing.T) {
 			updInfoCh := make(chan *whois.Info, 1)
 
 			p := client.NewDefaultAddrProc(&client.DefaultAddrProcConfig{
+				BaseLogger: slogutil.NewDiscardLogger(),
 				DialContext: func(_ context.Context, _, _ string) (conn net.Conn, err error) {
 					return whoisConn, nil
 				},

internal/dnsforward/dnsforward.go

@@ -685,6 +685,7 @@ func (s *Server) setupAddrProc() {
 		s.addrProc = client.EmptyAddrProc{}
 	} else {
 		c := s.conf.AddrProcConf
+		c.BaseLogger = s.logger
 		c.DialContext = s.DialContext
 		c.PrivateSubnets = s.privateNets
 		c.UsePrivateRDNS = s.conf.UsePrivateRDNS

internal/rdns/rdns.go

@@ -2,11 +2,14 @@
 package rdns
 
 import (
+	"context"
+	"fmt"
+	"log/slog"
 	"net/netip"
 	"time"
 
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/bluele/gcache"
 )
 
@@ -14,7 +17,7 @@ import (
 type Interface interface {
 	// Process makes rDNS request and returns domain name.  changed indicates
 	// that domain name was updated since last request.
-	Process(ip netip.Addr) (host string, changed bool)
+	Process(ctx context.Context, ip netip.Addr) (host string, changed bool)
 }
 
 // Empty is an empty [Interface] implementation which does nothing.
@@ -24,7 +27,7 @@ type Empty struct{}
 var _ Interface = (*Empty)(nil)
 
 // Process implements the [Interface] interface for Empty.
-func (Empty) Process(_ netip.Addr) (host string, changed bool) {
+func (Empty) Process(_ context.Context, _ netip.Addr) (host string, changed bool) {
 	return "", false
 }
 
@@ -37,6 +40,10 @@ type Exchanger interface {
 
 // Config is the configuration structure for Default.
 type Config struct {
+	// Logger is used for logging the operation of the reverse DNS lookup
+	// queries.  It must not be nil.
+	Logger *slog.Logger
+
 	// Exchanger resolves IP addresses to domain names.
 	Exchanger Exchanger
 
@@ -50,6 +57,10 @@ type Config struct {
 
 // Default is the default rDNS query processor.
 type Default struct {
+	// logger is used for logging the operation of the reverse DNS lookup
+	// queries.  It must not be nil.
+	logger *slog.Logger
+
 	// cache is the cache containing IP addresses of clients.  An active IP
 	// address is resolved once again after it expires.  If IP address couldn't
 	// be resolved, it stays here for some time to prevent further attempts to
@@ -66,6 +77,7 @@ type Default struct {
 // New returns a new default rDNS query processor.  conf must not be nil.
 func New(conf *Config) (r *Default) {
 	return &Default{
+		logger:    conf.Logger,
 		cache:     gcache.New(conf.CacheSize).LRU().Build(),
 		exchanger: conf.Exchanger,
 		cacheTTL:  conf.CacheTTL,
@@ -76,15 +88,15 @@ func New(conf *Config) (r *Default) {
 var _ Interface = (*Default)(nil)
 
 // Process implements the [Interface] interface for Default.
-func (r *Default) Process(ip netip.Addr) (host string, changed bool) {
+func (r *Default) Process(ctx context.Context, ip netip.Addr) (host string, changed bool) {
-	fromCache, expired := r.findInCache(ip)
+	fromCache, expired := r.findInCache(ctx, ip)
 	if !expired {
 		return fromCache, false
 	}
 
 	host, ttl, err := r.exchanger.Exchange(ip)
 	if err != nil {
-		log.Debug("rdns: resolving %q: %s", ip, err)
+		r.logger.DebugContext(ctx, "resolving ip", "ip", ip, slogutil.KeyError, err)
 	}
 
 	ttl = max(ttl, r.cacheTTL)
@@ -96,7 +108,7 @@ func (r *Default) Process(ip netip.Addr) (host string, changed bool) {
 
 	err = r.cache.Set(ip, item)
 	if err != nil {
-		log.Debug("rdns: cache: adding item %q: %s", ip, err)
+		r.logger.DebugContext(ctx, "adding item to cache", "item", ip, slogutil.KeyError, err)
 	}
 
 	// TODO(e.burkov):  The name doesn't change if it's neither stored in cache
@@ -106,11 +118,16 @@ func (r *Default) Process(ip netip.Addr) (host string, changed bool) {
 
 // findInCache finds domain name in the cache.  expired is true if host is not
 // valid anymore.
-func (r *Default) findInCache(ip netip.Addr) (host string, expired bool) {
+func (r *Default) findInCache(ctx context.Context, ip netip.Addr) (host string, expired bool) {
 	val, err := r.cache.Get(ip)
 	if err != nil {
 		if !errors.Is(err, gcache.KeyNotFoundError) {
-			log.Debug("rdns: cache: retrieving %q: %s", ip, err)
+			r.logger.DebugContext(
+				ctx,
+				"retrieving item from cache",
+				"item", ip,
+				slogutil.KeyError, err,
+			)
 		}
 
 		return "", true
@@ -118,7 +135,12 @@ func (r *Default) findInCache(ip netip.Addr) (host string, expired bool) {
 
 	item, ok := val.(*cacheItem)
 	if !ok {
-		log.Debug("rdns: cache: %q bad type %T", ip, val)
+		r.logger.DebugContext(
+			ctx,
+			"bad type of cache item",
+			"item", ip,
+			"type", fmt.Sprintf("%T", val),
+		)
 
 		return "", true
 	}

internal/rdns/rdns_test.go

@@ -1,6 +1,7 @@
 package rdns_test
 
 import (
+	"context"
 	"net/netip"
 	"testing"
 	"time"
@@ -8,10 +9,14 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/aghtest"
 	"github.com/AdguardTeam/AdGuardHome/internal/rdns"
 	"github.com/AdguardTeam/golibs/netutil"
+	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
+// testTimeout is a common timeout for tests and contexts.
+const testTimeout = 1 * time.Second
+
 func TestDefault_Process(t *testing.T) {
 	ip1 := netip.MustParseAddr("1.2.3.4")
 	revAddr1, err := netutil.IPToReversedAddr(ip1.AsSlice())
@@ -71,14 +76,14 @@ func TestDefault_Process(t *testing.T) {
 				Exchanger: &aghtest.Exchanger{OnExchange: onExchange},
 			})
 
-			got, changed := r.Process(tc.addr)
+			got, changed := r.Process(testutil.ContextWithTimeout(t, testTimeout), tc.addr)
 			require.True(t, changed)
 
 			assert.Equal(t, tc.want, got)
 			assert.Equal(t, 1, hit)
 
 			// From cache.
-			got, changed = r.Process(tc.addr)
+			got, changed = r.Process(testutil.ContextWithTimeout(t, testTimeout), tc.addr)
 			require.False(t, changed)
 
 			assert.Equal(t, tc.want, got)
@@ -101,7 +106,7 @@ func TestDefault_Process(t *testing.T) {
 			Exchanger: zeroTTLExchanger,
 		})
 
-		got, changed := r.Process(ip1)
+		got, changed := r.Process(testutil.ContextWithTimeout(t, testTimeout), ip1)
 		require.True(t, changed)
 		assert.Equal(t, revAddr1, got)
 
@@ -110,13 +115,13 @@ func TestDefault_Process(t *testing.T) {
 		}
 
 		require.EventuallyWithT(t, func(t *assert.CollectT) {
-			got, changed = r.Process(ip1)
+			got, changed = r.Process(context.TODO(), ip1)
 			assert.True(t, changed)
 			assert.Equal(t, revAddr2, got)
 		}, 2*cacheTTL, time.Millisecond*100)
 
 		assert.Never(t, func() (changed bool) {
-			_, changed = r.Process(ip1)
+			_, changed = r.Process(context.TODO(), ip1)
 
 			return changed
 		}, 2*cacheTTL, time.Millisecond*100)

internal/whois/whois.go

@@ -7,6 +7,7 @@ import (
 	"context"
 	"fmt"
 	"io"
+	"log/slog"
 	"net"
 	"net/netip"
 	"strconv"
@@ -16,7 +17,7 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/aghnet"
 	"github.com/AdguardTeam/golibs/errors"
 	"github.com/AdguardTeam/golibs/ioutil"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil"
 	"github.com/bluele/gcache"
 )
@@ -49,6 +50,10 @@ func (Empty) Process(_ context.Context, _ netip.Addr) (info *Info, changed bool)
 
 // Config is the configuration structure for Default.
 type Config struct {
+	// Logger is used for logging the operation of the WHOIS lookup queries.  It
+	// must not be nil.
+	Logger *slog.Logger
+
 	// DialContext is used to create TCP connections to WHOIS servers.
 	DialContext aghnet.DialContextFunc
 
@@ -80,6 +85,10 @@ type Config struct {
 
 // Default is the default WHOIS information processor.
 type Default struct {
+	// logger is used for logging the operation of the WHOIS lookup queries.  It
+	// must not be nil.
+	logger *slog.Logger
+
 	// cache is the cache containing IP addresses of clients.  An active IP
 	// address is resolved once again after it expires.  If IP address couldn't
 	// be resolved, it stays here for some time to prevent further attempts to
@@ -115,6 +124,7 @@ type Default struct {
 // nil.
 func New(conf *Config) (w *Default) {
 	return &Default{
+		logger:          conf.Logger,
 		serverAddr:      conf.ServerAddr,
 		dialContext:     conf.DialContext,
 		timeout:         conf.Timeout,
@@ -239,7 +249,13 @@ func (w *Default) queryAll(ctx context.Context, target string) (info map[string]
 			return nil, err
 		}
 
-		log.Debug("whois: received response (%d bytes) from %q about %q", len(data), server, target)
+		w.logger.DebugContext(
+			ctx,
+			"received response",
+			"size", len(data),
+			"source", server,
+			"target", target,
+		)
 
 		info = whoisParse(data, w.maxInfoLen)
 		redir, ok := info["whois"]
@@ -256,7 +272,7 @@ func (w *Default) queryAll(ctx context.Context, target string) (info map[string]
 			server = redir
 		}
 
-		log.Debug("whois: redirected to %q about %q", redir, target)
+		w.logger.DebugContext(ctx, "redirected", "destination", redir, "target", target)
 	}
 
 	return nil, fmt.Errorf("whois: redirect loop")
@@ -272,7 +288,7 @@ func (w *Default) Process(ctx context.Context, ip netip.Addr) (wi *Info, changed
 		return nil, false
 	}
 
-	wi, expired := w.findInCache(ip)
+	wi, expired := w.findInCache(ctx, ip)
 	if wi != nil && !expired {
 		// Don't return an empty struct so that the frontend doesn't get
 		// confused.
@@ -299,13 +315,13 @@ func (w *Default) requestInfo(
 		item := toCacheItem(info, w.cacheTTL)
 		err := w.cache.Set(ip, item)
 		if err != nil {
-			log.Debug("whois: cache: adding item %q: %s", ip, err)
+			w.logger.DebugContext(ctx, "adding item to cache", "item", ip, slogutil.KeyError, err)
 		}
 	}()
 
 	kv, err := w.queryAll(ctx, ip.String())
 	if err != nil {
-		log.Debug("whois: querying %q: %s", ip, err)
+		w.logger.DebugContext(ctx, "querying", "target", ip, slogutil.KeyError, err)
 
 		return nil, true
 	}
@@ -327,11 +343,16 @@ func (w *Default) requestInfo(
 }
 
 // findInCache finds Info in the cache.  expired indicates that Info is valid.
-func (w *Default) findInCache(ip netip.Addr) (wi *Info, expired bool) {
+func (w *Default) findInCache(ctx context.Context, ip netip.Addr) (wi *Info, expired bool) {
 	val, err := w.cache.Get(ip)
 	if err != nil {
 		if !errors.Is(err, gcache.KeyNotFoundError) {
-			log.Debug("whois: cache: retrieving info about %q: %s", ip, err)
+			w.logger.DebugContext(
+				ctx,
+				"retrieving item from cache",
+				"item", ip,
+				slogutil.KeyError, err,
+			)
 		}
 
 		return nil, false
@@ -339,7 +360,12 @@ func (w *Default) findInCache(ip netip.Addr) (wi *Info, expired bool) {
 
 	item, ok := val.(*cacheItem)
 	if !ok {
-		log.Debug("whois: cache: %q bad type %T", ip, val)
+		w.logger.DebugContext(
+			ctx,
+			"bad type of cache item",
+			"item", ip,
+			"type", fmt.Sprintf("%T", val),
+		)
 
 		return nil, false
 	}

internal/whois/whois_test.go

@@ -9,6 +9,7 @@ import (
 	"time"
 
 	"github.com/AdguardTeam/AdGuardHome/internal/whois"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/testutil/fakenet"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -119,6 +120,7 @@ func TestDefault_Process(t *testing.T) {
 			}
 
 			w := whois.New(&whois.Config{
+				Logger:  slogutil.NewDiscardLogger(),
 				Timeout: 5 * time.Second,
 				DialContext: func(_ context.Context, _, _ string) (_ net.Conn, _ error) {
 					hit = 0