Pull request 2286: AGDNS-2374-slog-safesearch

Squashed commit of the following: commit 1909dfed99b8815c1215c709efcae77a70b52ea3 Merge: 3856fda5f 2c64ab5a5 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Wed Oct 9 16:21:38 2024 +0300 Merge branch 'master' into AGDNS-2374-slog-safesearch commit 3856fda5f38a89d2df86bd8701e79d7f3fc02bb7 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Tue Oct 8 20:04:34 2024 +0300 home: imp code commit de774009aa82bf45022fd9c359296e7ab45bf93d Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Mon Oct 7 16:41:58 2024 +0300 all: imp code commit 038bae59d51497de1db7153e00e779db30f79721 Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Thu Oct 3 20:24:48 2024 +0300 all: imp code commit 792975e248bb04bce5a8ec767441fcf253c6d00f Author: Stanislav Chzhen <s.chzhen@adguard.com> Date: Thu Oct 3 15:46:40 2024 +0300 all: slog safesearch
2024-10-09 16:31:03 +03:00
parent 2c64ab5a51
commit 6363f8a2e7
12 changed files with 237 additions and 122 deletions
--- a/internal/filtering/safesearch.go
+++ b/internal/filtering/safesearch.go
@@ -1,15 +1,17 @@
 package filtering

+import "context"
+
 // SafeSearch interface describes a service for search engines hosts rewrites.
 type SafeSearch interface {
 	// CheckHost checks host with safe search filter.  CheckHost must be safe
 	// for concurrent use.  qtype must be either [dns.TypeA] or [dns.TypeAAAA].
-	CheckHost(host string, qtype uint16) (res Result, err error)
+	CheckHost(ctx context.Context, host string, qtype uint16) (res Result, err error)

 	// Update updates the configuration of the safe search filter.  Update must
 	// be safe for concurrent use.  An implementation of Update may ignore some
 	// fields, but it must document which.
-	Update(conf SafeSearchConfig) (err error)
+	Update(ctx context.Context, conf SafeSearchConfig) (err error)
 }

 // SafeSearchConfig is a struct with safe search related settings.
@@ -40,10 +42,13 @@ func (d *DNSFilter) checkSafeSearch(
 		return Result{}, nil
 	}

+	// TODO(s.chzhen):  Pass context.
+	ctx := context.TODO()
+
 	clientSafeSearch := setts.ClientSafeSearch
 	if clientSafeSearch != nil {
-		return clientSafeSearch.CheckHost(host, qtype)
+		return clientSafeSearch.CheckHost(ctx, host, qtype)
 	}

-	return d.safeSearch.CheckHost(host, qtype)
+	return d.safeSearch.CheckHost(ctx, host, qtype)
 }
--- a/internal/filtering/safesearch/safesearch.go
+++ b/internal/filtering/safesearch/safesearch.go
@@ -3,9 +3,11 @@ package safesearch

 import (
 	"bytes"
+	"context"
 	"encoding/binary"
 	"encoding/gob"
 	"fmt"
+	"log/slog"
 	"net/netip"
 	"strings"
 	"sync"
@@ -14,13 +16,20 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering"
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering/rulelist"
 	"github.com/AdguardTeam/golibs/cache"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/urlfilter"
 	"github.com/AdguardTeam/urlfilter/filterlist"
 	"github.com/AdguardTeam/urlfilter/rules"
+	"github.com/c2h5oh/datasize"
 	"github.com/miekg/dns"
 )

+// Attribute keys and values for logging.
+const (
+	LogPrefix    = "safesearch"
+	LogKeyClient = "client"
+)
+
 // Service is a enum with service names used as search providers.
 type Service string

@@ -57,9 +66,32 @@ func isServiceProtected(s filtering.SafeSearchConfig, service Service) (ok bool)
 	}
 }

+// DefaultConfig is the configuration structure for [Default].
+type DefaultConfig struct {
+	// Logger is used for logging the operation of the safe search filter.
+	Logger *slog.Logger
+
+	// ClientName is the name of the persistent client associated with the safe
+	// search filter, if there is one.
+	ClientName string
+
+	// CacheSize is the size of the filter results cache.
+	CacheSize uint
+
+	// CacheTTL is the Time to Live duration for cached items.
+	CacheTTL time.Duration
+
+	// ServicesConfig contains safe search settings for services.  It must not
+	// be nil.
+	ServicesConfig filtering.SafeSearchConfig
+}
+
 // Default is the default safe search filter that uses filtering rules with the
 // dnsrewrite modifier.
 type Default struct {
+	// logger is used for logging the operation of the safe search filter.
+	logger *slog.Logger
+
 	// mu protects engine.
 	mu *sync.RWMutex

@@ -67,33 +99,28 @@ type Default struct {
 	// engine may be nil, which means that this safe search filter is disabled.
 	engine *urlfilter.DNSEngine

-	cache     cache.Cache
-	logPrefix string
-	cacheTTL  time.Duration
+	// cache stores safe search filtering results.
+	cache cache.Cache
+
+	// cacheTTL is the Time to Live duration for cached items.
+	cacheTTL time.Duration
 }

-// NewDefault returns an initialized default safe search filter.  name is used
-// for logging.
-func NewDefault(
-	conf filtering.SafeSearchConfig,
-	name string,
-	cacheSize uint,
-	cacheTTL time.Duration,
-) (ss *Default, err error) {
+// NewDefault returns an initialized default safe search filter.  ctx is used
+// to log the initial refresh.
+func NewDefault(ctx context.Context, conf *DefaultConfig) (ss *Default, err error) {
 	ss = &Default{
-		mu: &sync.RWMutex{},
-
+		logger: conf.Logger,
+		mu:     &sync.RWMutex{},
 		cache: cache.New(cache.Config{
 			EnableLRU: true,
-			MaxSize:   cacheSize,
+			MaxSize:   conf.CacheSize,
 		}),
-		// Use %s, because the client safe-search names already contain double
-		// quotes.
-		logPrefix: fmt.Sprintf("safesearch %s: ", name),
-		cacheTTL:  cacheTTL,
+		cacheTTL: conf.CacheTTL,
 	}

-	err = ss.resetEngine(rulelist.URLFilterIDSafeSearch, conf)
+	// TODO(s.chzhen):  Move to [Default.InitialRefresh].
+	err = ss.resetEngine(ctx, rulelist.URLFilterIDSafeSearch, conf.ServicesConfig)
 	if err != nil {
 		// Don't wrap the error, because it's informative enough as is.
 		return nil, err
@@ -102,29 +129,15 @@ func NewDefault(
 	return ss, nil
 }

-// log is a helper for logging  that includes the name of the safe search
-// filter.  level must be one of [log.DEBUG], [log.INFO], and [log.ERROR].
-func (ss *Default) log(level log.Level, msg string, args ...any) {
-	switch level {
-	case log.DEBUG:
-		log.Debug(ss.logPrefix+msg, args...)
-	case log.INFO:
-		log.Info(ss.logPrefix+msg, args...)
-	case log.ERROR:
-		log.Error(ss.logPrefix+msg, args...)
-	default:
-		panic(fmt.Errorf("safesearch: unsupported logging level %d", level))
-	}
-}
-
 // resetEngine creates new engine for provided safe search configuration and
 // sets it in ss.
 func (ss *Default) resetEngine(
+	ctx context.Context,
 	listID int,
 	conf filtering.SafeSearchConfig,
 ) (err error) {
 	if !conf.Enabled {
-		ss.log(log.INFO, "disabled")
+		ss.logger.DebugContext(ctx, "disabled")

 		return nil
 	}
@@ -149,7 +162,7 @@ func (ss *Default) resetEngine(

 	ss.engine = urlfilter.NewDNSEngine(rs)

-	ss.log(log.INFO, "reset %d rules", ss.engine.RulesCount)
+	ss.logger.InfoContext(ctx, "reset rules", "count", ss.engine.RulesCount)

 	return nil
 }
@@ -158,10 +171,14 @@ func (ss *Default) resetEngine(
 var _ filtering.SafeSearch = (*Default)(nil)

 // CheckHost implements the [filtering.SafeSearch] interface for *Default.
-func (ss *Default) CheckHost(host string, qtype rules.RRType) (res filtering.Result, err error) {
+func (ss *Default) CheckHost(
+	ctx context.Context,
+	host string,
+	qtype rules.RRType,
+) (res filtering.Result, err error) {
 	start := time.Now()
 	defer func() {
-		ss.log(log.DEBUG, "lookup for %q finished in %s", host, time.Since(start))
+		ss.logger.DebugContext(ctx, "lookup finished", "host", host, "elapsed", time.Since(start))
 	}()

 	switch qtype {
@@ -172,9 +189,9 @@ func (ss *Default) CheckHost(host string, qtype rules.RRType) (res filtering.Res
 	}

 	// Check cache. Return cached result if it was found
-	cachedValue, isFound := ss.getCachedResult(host, qtype)
+	cachedValue, isFound := ss.getCachedResult(ctx, host, qtype)
 	if isFound {
-		ss.log(log.DEBUG, "found in cache: %q", host)
+		ss.logger.DebugContext(ctx, "found in cache", "host", host)

 		return cachedValue, nil
 	}
@@ -186,7 +203,7 @@ func (ss *Default) CheckHost(host string, qtype rules.RRType) (res filtering.Res

 	fltRes, err := ss.newResult(rewrite, qtype)
 	if err != nil {
-		ss.log(log.DEBUG, "looking up addresses for %q: %s", host, err)
+		ss.logger.ErrorContext(ctx, "looking up addresses", "host", host, slogutil.KeyError, err)

 		return filtering.Result{}, err
 	}
@@ -195,7 +212,7 @@ func (ss *Default) CheckHost(host string, qtype rules.RRType) (res filtering.Res

 	// TODO(a.garipov): Consider switch back to resolving CNAME records IPs and
 	// saving results to cache.
-	ss.setCacheResult(host, qtype, res)
+	ss.setCacheResult(ctx, host, qtype, res)

 	return res, nil
 }
@@ -255,7 +272,12 @@ func (ss *Default) newResult(

 // setCacheResult stores data in cache for host.  qtype is expected to be either
 // [dns.TypeA] or [dns.TypeAAAA].
-func (ss *Default) setCacheResult(host string, qtype rules.RRType, res filtering.Result) {
+func (ss *Default) setCacheResult(
+	ctx context.Context,
+	host string,
+	qtype rules.RRType,
+	res filtering.Result,
+) {
 	expire := uint32(time.Now().Add(ss.cacheTTL).Unix())
 	exp := make([]byte, 4)
 	binary.BigEndian.PutUint32(exp, expire)
@@ -263,7 +285,7 @@ func (ss *Default) setCacheResult(host string, qtype rules.RRType, res filtering

 	err := gob.NewEncoder(buf).Encode(res)
 	if err != nil {
-		ss.log(log.ERROR, "cache encoding: %s", err)
+		ss.logger.ErrorContext(ctx, "cache encoding", slogutil.KeyError, err)

 		return
 	}
@@ -271,12 +293,18 @@ func (ss *Default) setCacheResult(host string, qtype rules.RRType, res filtering
 	val := buf.Bytes()
 	_ = ss.cache.Set([]byte(dns.Type(qtype).String()+" "+host), val)

-	ss.log(log.DEBUG, "stored in cache: %q, %d bytes", host, len(val))
+	ss.logger.DebugContext(
+		ctx,
+		"stored in cache",
+		"host", host,
+		"entry_size", datasize.ByteSize(len(val)),
+	)
 }

 // getCachedResult returns stored data from cache for host.  qtype is expected
 // to be either [dns.TypeA] or [dns.TypeAAAA].
 func (ss *Default) getCachedResult(
+	ctx context.Context,
 	host string,
 	qtype rules.RRType,
 ) (res filtering.Result, ok bool) {
@@ -298,7 +326,7 @@ func (ss *Default) getCachedResult(

 	err := gob.NewDecoder(buf).Decode(&res)
 	if err != nil {
-		ss.log(log.ERROR, "cache decoding: %s", err)
+		ss.logger.ErrorContext(ctx, "cache decoding", slogutil.KeyError, err)

 		return filtering.Result{}, false
 	}
@@ -308,11 +336,11 @@ func (ss *Default) getCachedResult(

 // Update implements the [filtering.SafeSearch] interface for *Default.  Update
 // ignores the CustomResolver and Enabled fields.
-func (ss *Default) Update(conf filtering.SafeSearchConfig) (err error) {
+func (ss *Default) Update(ctx context.Context, conf filtering.SafeSearchConfig) (err error) {
 	ss.mu.Lock()
 	defer ss.mu.Unlock()

-	err = ss.resetEngine(rulelist.URLFilterIDSafeSearch, conf)
+	err = ss.resetEngine(ctx, rulelist.URLFilterIDSafeSearch, conf)
 	if err != nil {
 		// Don't wrap the error, because it's informative enough as is.
 		return err
--- a/internal/filtering/safesearch/safesearch_internal_test.go
+++ b/internal/filtering/safesearch/safesearch_internal_test.go
@@ -6,6 +6,8 @@ import (
 	"time"

 	"github.com/AdguardTeam/AdGuardHome/internal/filtering"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
+	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/AdguardTeam/urlfilter/rules"
 	"github.com/miekg/dns"
 	"github.com/stretchr/testify/assert"
@@ -21,6 +23,9 @@ const (
 	testCacheTTL  = 30 * time.Minute
 )

+// testTimeout is the common timeout for tests and contexts.
+const testTimeout = 1 * time.Second
+
 var defaultSafeSearchConf = filtering.SafeSearchConfig{
 	Enabled:    true,
 	Bing:       true,
@@ -35,7 +40,12 @@ var defaultSafeSearchConf = filtering.SafeSearchConfig{
 var yandexIP = netip.AddrFrom4([4]byte{213, 180, 193, 56})

 func newForTest(t testing.TB, ssConf filtering.SafeSearchConfig) (ss *Default) {
-	ss, err := NewDefault(ssConf, "", testCacheSize, testCacheTTL)
+	ss, err := NewDefault(testutil.ContextWithTimeout(t, testTimeout), &DefaultConfig{
+		Logger:         slogutil.NewDiscardLogger(),
+		ServicesConfig: ssConf,
+		CacheSize:      testCacheSize,
+		CacheTTL:       testCacheTTL,
+	})
 	require.NoError(t, err)

 	return ss
@@ -52,16 +62,17 @@ func TestSafeSearchCacheYandex(t *testing.T) {
 	const domain = "yandex.ru"

 	ss := newForTest(t, filtering.SafeSearchConfig{Enabled: false})
+	ctx := testutil.ContextWithTimeout(t, testTimeout)

 	// Check host with disabled safesearch.
-	res, err := ss.CheckHost(domain, testQType)
+	res, err := ss.CheckHost(ctx, domain, testQType)
 	require.NoError(t, err)

 	assert.False(t, res.IsFiltered)
 	assert.Empty(t, res.Rules)

 	ss = newForTest(t, defaultSafeSearchConf)
-	res, err = ss.CheckHost(domain, testQType)
+	res, err = ss.CheckHost(ctx, domain, testQType)
 	require.NoError(t, err)

 	// For yandex we already know valid IP.
@@ -70,7 +81,7 @@ func TestSafeSearchCacheYandex(t *testing.T) {
 	assert.Equal(t, res.Rules[0].IP, yandexIP)

 	// Check cache.
-	cachedValue, isFound := ss.getCachedResult(domain, testQType)
+	cachedValue, isFound := ss.getCachedResult(ctx, domain, testQType)
 	require.True(t, isFound)
 	require.Len(t, cachedValue.Rules, 1)

--- a/internal/filtering/safesearch/safesearch_test.go
+++ b/internal/filtering/safesearch/safesearch_test.go
@@ -10,15 +10,15 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering"
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering/rulelist"
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering/safesearch"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/miekg/dns"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )

-func TestMain(m *testing.M) {
-	testutil.DiscardLogOutput(m)
-}
+// testTimeout is the common timeout for tests and contexts.
+const testTimeout = 1 * time.Second

 // Common test constants.
 const (
@@ -47,7 +47,13 @@ var yandexIP = netip.AddrFrom4([4]byte{213, 180, 193, 56})

 func TestDefault_CheckHost_yandex(t *testing.T) {
 	conf := testConf
-	ss, err := safesearch.NewDefault(conf, "", testCacheSize, testCacheTTL)
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	ss, err := safesearch.NewDefault(ctx, &safesearch.DefaultConfig{
+		Logger:         slogutil.NewDiscardLogger(),
+		ServicesConfig: conf,
+		CacheSize:      testCacheSize,
+		CacheTTL:       testCacheTTL,
+	})
 	require.NoError(t, err)

 	hosts := []string{
@@ -82,7 +88,7 @@ func TestDefault_CheckHost_yandex(t *testing.T) {
 			for _, host := range hosts {
 				// Check host for each domain.
 				var res filtering.Result
-				res, err = ss.CheckHost(host, tc.qt)
+				res, err = ss.CheckHost(ctx, host, tc.qt)
 				require.NoError(t, err)

 				assert.True(t, res.IsFiltered)
@@ -103,7 +109,13 @@ func TestDefault_CheckHost_yandex(t *testing.T) {
 }

 func TestDefault_CheckHost_google(t *testing.T) {
-	ss, err := safesearch.NewDefault(testConf, "", testCacheSize, testCacheTTL)
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	ss, err := safesearch.NewDefault(ctx, &safesearch.DefaultConfig{
+		Logger:         slogutil.NewDiscardLogger(),
+		ServicesConfig: testConf,
+		CacheSize:      testCacheSize,
+		CacheTTL:       testCacheTTL,
+	})
 	require.NoError(t, err)

 	// Check host for each domain.
@@ -118,7 +130,7 @@ func TestDefault_CheckHost_google(t *testing.T) {
 	} {
 		t.Run(host, func(t *testing.T) {
 			var res filtering.Result
-			res, err = ss.CheckHost(host, testQType)
+			res, err = ss.CheckHost(ctx, host, testQType)
 			require.NoError(t, err)

 			assert.True(t, res.IsFiltered)
@@ -149,13 +161,19 @@ func (r *testResolver) LookupIP(
 }

 func TestDefault_CheckHost_duckduckgoAAAA(t *testing.T) {
-	ss, err := safesearch.NewDefault(testConf, "", testCacheSize, testCacheTTL)
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	ss, err := safesearch.NewDefault(ctx, &safesearch.DefaultConfig{
+		Logger:         slogutil.NewDiscardLogger(),
+		ServicesConfig: testConf,
+		CacheSize:      testCacheSize,
+		CacheTTL:       testCacheTTL,
+	})
 	require.NoError(t, err)

 	// The DuckDuckGo safe-search addresses are resolved through CNAMEs, but
 	// DuckDuckGo doesn't have a safe-search IPv6 address.  The result should be
 	// the same as the one for Yandex IPv6.  That is, a NODATA response.
-	res, err := ss.CheckHost("www.duckduckgo.com", dns.TypeAAAA)
+	res, err := ss.CheckHost(ctx, "www.duckduckgo.com", dns.TypeAAAA)
 	require.NoError(t, err)

 	assert.True(t, res.IsFiltered)
@@ -166,32 +184,38 @@ func TestDefault_CheckHost_duckduckgoAAAA(t *testing.T) {

 func TestDefault_Update(t *testing.T) {
 	conf := testConf
-	ss, err := safesearch.NewDefault(conf, "", testCacheSize, testCacheTTL)
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	ss, err := safesearch.NewDefault(ctx, &safesearch.DefaultConfig{
+		Logger:         slogutil.NewDiscardLogger(),
+		ServicesConfig: conf,
+		CacheSize:      testCacheSize,
+		CacheTTL:       testCacheTTL,
+	})
 	require.NoError(t, err)

-	res, err := ss.CheckHost("www.yandex.com", testQType)
+	res, err := ss.CheckHost(ctx, "www.yandex.com", testQType)
 	require.NoError(t, err)

 	assert.True(t, res.IsFiltered)

-	err = ss.Update(filtering.SafeSearchConfig{
+	err = ss.Update(ctx, filtering.SafeSearchConfig{
 		Enabled: true,
 		Google:  false,
 	})
 	require.NoError(t, err)

-	res, err = ss.CheckHost("www.yandex.com", testQType)
+	res, err = ss.CheckHost(ctx, "www.yandex.com", testQType)
 	require.NoError(t, err)

 	assert.False(t, res.IsFiltered)

-	err = ss.Update(filtering.SafeSearchConfig{
+	err = ss.Update(ctx, filtering.SafeSearchConfig{
 		Enabled: false,
 		Google:  true,
 	})
 	require.NoError(t, err)

-	res, err = ss.CheckHost("www.yandex.com", testQType)
+	res, err = ss.CheckHost(ctx, "www.yandex.com", testQType)
 	require.NoError(t, err)

 	assert.False(t, res.IsFiltered)
--- a/internal/filtering/safesearchhttp.go
+++ b/internal/filtering/safesearchhttp.go
@@ -51,7 +51,7 @@ func (d *DNSFilter) handleSafeSearchSettings(w http.ResponseWriter, r *http.Requ
 	}

 	conf := *req
-	err = d.safeSearch.Update(conf)
+	err = d.safeSearch.Update(r.Context(), conf)
 	if err != nil {
 		aghhttp.Error(r, w, http.StatusBadRequest, "updating: %s", err)