filtering: slog

internal/filtering/blocked.go

@@ -1,8 +1,10 @@
 package filtering
 
 import (
+	"context"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"slices"
 	"time"
@@ -10,7 +12,7 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/aghhttp"
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering/rulelist"
 	"github.com/AdguardTeam/AdGuardHome/internal/schedule"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/urlfilter/rules"
 )
 
@@ -21,22 +23,28 @@ var serviceRules map[string][]*rules.NetworkRule
 var serviceIDs []string
 
 // initBlockedServices initializes package-level blocked service data.
-func initBlockedServices() {
-	l := len(blockedServices)
-	serviceIDs = make([]string, l)
-	serviceRules = make(map[string][]*rules.NetworkRule, l)
+func initBlockedServices(ctx context.Context, l *slog.Logger) {
+	svcLen := len(blockedServices)
+	serviceIDs = make([]string, svcLen)
+	serviceRules = make(map[string][]*rules.NetworkRule, svcLen)
 
 	for i, s := range blockedServices {
 		netRules := make([]*rules.NetworkRule, 0, len(s.Rules))
 		for _, text := range s.Rules {
 			rule, err := rules.NewNetworkRule(text, rulelist.URLFilterIDBlockedService)
-			if err != nil {
-				log.Error("parsing blocked service %q rule %q: %s", s.ID, text, err)
+			if err == nil {
+				netRules = append(netRules, rule)
 
 				continue
 			}
 
-			netRules = append(netRules, rule)
+			l.ErrorContext(
+				ctx,
+				"parsing blocked service rule",
+				"svc", s.ID,
+				"rule", text,
+				slogutil.KeyError, err,
+			)
 		}
 
 		serviceIDs[i] = s.ID
@@ -45,7 +53,7 @@ func initBlockedServices() {
 
 	slices.Sort(serviceIDs)
 
-	log.Debug("filtering: initialized %d services", l)
+	l.DebugContext(ctx, "initialized services", "svc_len", svcLen)
 }
 
 // BlockedServices is the configuration of blocked services.
@@ -105,7 +113,7 @@ func (d *DNSFilter) ApplyBlockedServicesList(setts *Settings, list []string) {
 	for _, name := range list {
 		rules, ok := serviceRules[name]
 		if !ok {
-			log.Error("unknown service name: %s", name)
+			d.logger.ErrorContext(context.TODO(), "unknown service name", "name", name)
 
 			continue
 		}
@@ -163,7 +171,7 @@ func (d *DNSFilter) handleBlockedServicesSet(w http.ResponseWriter, r *http.Requ
 		defer d.confMu.Unlock()
 
 		d.conf.BlockedServices.IDs = list
-		log.Debug("Updated blocked services list: %d", len(list))
+		d.logger.DebugContext(r.Context(), "updated blocked services list", "len", len(list))
 	}()
 
 	d.conf.ConfigModified()
@@ -212,7 +220,7 @@ func (d *DNSFilter) handleBlockedServicesUpdate(w http.ResponseWriter, r *http.R
 		d.conf.BlockedServices = bsvc
 	}()
 
-	log.Debug("updated blocked services schedule: %d", len(bsvc.IDs))
+	d.logger.DebugContext(r.Context(), "updated blocked services schedule", "len", len(bsvc.IDs))
 
 	d.conf.ConfigModified()
 }

internal/filtering/filtering.go

@@ -707,7 +707,7 @@ func (d *DNSFilter) processRewrites(host string, qtype uint16) (res Result) {
 		rewrites, matched = findRewrites(d.conf.Rewrites, host, qtype)
 	}
 
-	setRewriteResult(&res, host, rewrites, qtype)
+	d.setRewriteResult(ctx, &res, host, rewrites, qtype)
 
 	return res
 }
@@ -1030,8 +1030,8 @@ func makeResult(matchedRules []rules.Rule, reason Reason) (res Result) {
 }
 
 // InitModule manually initializes blocked services map.
-func InitModule() {
-	initBlockedServices()
+func InitModule(l *slog.Logger) {
+	initBlockedServices(context.TODO(), l)
 }
 
 // New creates properly initialized DNS Filter that is ready to be used.  c must
@@ -1086,7 +1086,7 @@ func New(c *Config, blockFilters []Filter) (d *DNSFilter, err error) {
 	d.conf = c
 	d.conf.filtersMu = &sync.RWMutex{}
 
-	err = d.prepareRewrites()
+	err = d.prepareRewrites(ctx)
 	if err != nil {
 		return nil, fmt.Errorf("rewrites: preparing: %w", err)
 	}

internal/filtering/hosts.go

@@ -1,12 +1,13 @@
 package filtering
 
 import (
+	"context"
 	"fmt"
 	"net/netip"
 
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering/rulelist"
 	"github.com/AdguardTeam/golibs/hostsfile"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil"
 	"github.com/AdguardTeam/urlfilter/rules"
 	"github.com/miekg/dns"
@@ -24,7 +25,7 @@ func (d *DNSFilter) matchSysHosts(
 		return Result{}, nil
 	}
 
-	vals, rs, matched := hostsRewrites(qtype, host, d.conf.EtcHosts)
+	vals, rs, matched := d.hostsRewrites(qtype, host, d.conf.EtcHosts)
 	if !matched {
 		return Result{}, nil
 	}
@@ -42,11 +43,13 @@ func (d *DNSFilter) matchSysHosts(
 }
 
 // hostsRewrites returns values and rules matched by qt and host within hs.
-func hostsRewrites(
+func (d *DNSFilter) hostsRewrites(
 	qtype uint16,
 	host string,
 	hs hostsfile.Storage,
 ) (vals []rules.RRValue, rls []*ResultRule, matched bool) {
+	ctx := context.TODO()
+
 	var isValidProto func(netip.Addr) (ok bool)
 	switch qtype {
 	case dns.TypeA:
@@ -56,7 +59,12 @@ func hostsRewrites(
 	case dns.TypePTR:
 		addr, err := netutil.IPFromReversedAddr(host)
 		if err != nil {
-			log.Debug("filtering: failed to parse PTR record %q: %s", host, err)
+			d.logger.DebugContext(
+				ctx,
+				"failed to parse PTR record",
+				"host", host,
+				slogutil.KeyError, err,
+			)
 
 			return nil, nil, false
 		}
@@ -73,7 +81,11 @@ func hostsRewrites(
 
 		return vals, rls, len(names) > 0
 	default:
-		log.Debug("filtering: unsupported qtype %d", qtype)
+		d.logger.DebugContext(
+			ctx,
+			"unsupported qtype",
+			"qtype", qtype,
+		)
 
 		return nil, nil, false
 	}

internal/filtering/http.go

@@ -17,7 +17,7 @@ import (
 	"github.com/AdguardTeam/AdGuardHome/internal/aghhttp"
 	"github.com/AdguardTeam/AdGuardHome/internal/filtering/rulelist"
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/AdguardTeam/golibs/netutil/urlutil"
 	"github.com/miekg/dns"
 )
@@ -148,6 +148,8 @@ func (d *DNSFilter) handleFilteringRemoveURL(w http.ResponseWriter, r *http.Requ
 		Whitelist bool   `json:"whitelist"`
 	}
 
+	ctx := r.Context()
+
 	req := request{}
 	err := json.NewDecoder(r.Body).Decode(&req)
 	if err != nil {
@@ -170,7 +172,12 @@ func (d *DNSFilter) handleFilteringRemoveURL(w http.ResponseWriter, r *http.Requ
 			return flt.URL == req.URL
 		})
 		if delIdx == -1 {
-			log.Error("deleting filter with url %q: %s", req.URL, errFilterNotExist)
+			d.logger.ErrorContext(
+				ctx,
+				"deleting filter",
+				"url", req.URL,
+				slogutil.KeyError, errFilterNotExist,
+			)
 
 			return
 		}
@@ -179,14 +186,20 @@ func (d *DNSFilter) handleFilteringRemoveURL(w http.ResponseWriter, r *http.Requ
 		p := deleted.Path(d.conf.DataDir)
 		err = os.Rename(p, p+".old")
 		if err != nil && !errors.Is(err, os.ErrNotExist) {
-			log.Error("deleting filter %d: renaming file %q: %s", deleted.ID, p, err)
+			d.logger.ErrorContext(
+				ctx,
+				"renaming filter file",
+				"id", deleted.ID,
+				"path", p,
+				slogutil.KeyError, err,
+			)
 
 			return
 		}
 
 		*filters = slices.Delete(*filters, delIdx, delIdx+1)
 
-		log.Info("deleted filter %d", deleted.ID)
+		d.logger.InfoContext(ctx, "deleted filter", "id", deleted.ID)
 	}()
 
 	d.conf.ConfigModified()

internal/filtering/rewritehttp.go

@@ -6,7 +6,6 @@ import (
 	"slices"
 
 	"github.com/AdguardTeam/AdGuardHome/internal/aghhttp"
-	"github.com/AdguardTeam/golibs/log"
 )
 
 // TODO(d.kolyshev): Use [rewrite.Item] instead.
@@ -50,7 +49,7 @@ func (d *DNSFilter) handleRewriteAdd(w http.ResponseWriter, r *http.Request) {
 		Answer: rwJSON.Answer,
 	}
 
-	err = rw.normalize()
+	err = rw.normalize(r.Context(), d.logger)
 	if err != nil {
 		// Shouldn't happen currently, since normalize only returns a non-nil
 		// error when a rewrite is nil, but be change-proof.
@@ -64,11 +63,12 @@ func (d *DNSFilter) handleRewriteAdd(w http.ResponseWriter, r *http.Request) {
 		defer d.confMu.Unlock()
 
 		d.conf.Rewrites = append(d.conf.Rewrites, rw)
-		log.Debug(
-			"rewrite: added element: %s -> %s [%d]",
-			rw.Domain,
-			rw.Answer,
-			len(d.conf.Rewrites),
+		d.logger.DebugContext(
+			r.Context(),
+			"added rewrite element",
+			"domain", rw.Domain,
+			"answer", rw.Answer,
+			"rewrites_len", len(d.conf.Rewrites),
 		)
 	}()
 
@@ -98,7 +98,12 @@ func (d *DNSFilter) handleRewriteDelete(w http.ResponseWriter, r *http.Request)
 
 		for _, ent := range d.conf.Rewrites {
 			if ent.equal(entDel) {
-				log.Debug("rewrite: removed element: %s -> %s", ent.Domain, ent.Answer)
+				d.logger.DebugContext(
+					r.Context(),
+					"removed rewrite element",
+					"domain", ent.Domain,
+					"answer", ent.Answer,
+				)
 
 				continue
 			}
@@ -138,7 +143,7 @@ func (d *DNSFilter) handleRewriteUpdate(w http.ResponseWriter, r *http.Request)
 		Answer: updateJSON.Update.Answer,
 	}
 
-	err = rwAdd.normalize()
+	err = rwAdd.normalize(r.Context(), d.logger)
 	if err != nil {
 		// Shouldn't happen currently, since normalize only returns a non-nil
 		// error when a rewrite is nil, but be change-proof.
@@ -166,6 +171,17 @@ func (d *DNSFilter) handleRewriteUpdate(w http.ResponseWriter, r *http.Request)
 
 	d.conf.Rewrites = slices.Replace(d.conf.Rewrites, index, index+1, rwAdd)
 
-	log.Debug("rewrite: removed element: %s -> %s", rwDel.Domain, rwDel.Answer)
-	log.Debug("rewrite: added element: %s -> %s", rwAdd.Domain, rwAdd.Answer)
+	ctx := r.Context()
+	d.logger.DebugContext(
+		ctx,
+		"removed rewrite element",
+		"domain", rwDel.Domain,
+		"answer", rwDel.Answer,
+	)
+	d.logger.DebugContext(
+		ctx,
+		"added rewrite element",
+		"domain", rwAdd.Domain,
+		"answer", rwAdd.Answer,
+	)
 }

internal/filtering/rewrites.go

@@ -1,13 +1,15 @@
 package filtering
 
 import (
+	"context"
 	"fmt"
+	"log/slog"
 	"net/netip"
 	"slices"
 	"strings"
 
 	"github.com/AdguardTeam/golibs/errors"
-	"github.com/AdguardTeam/golibs/log"
+	"github.com/AdguardTeam/golibs/logutil/slogutil"
 	"github.com/miekg/dns"
 )
 
@@ -58,7 +60,7 @@ func (rw *LegacyRewrite) matchesQType(qt uint16) (ok bool) {
 // to domain name case, IP length, and so on.
 //
 // If rw is nil, it returns an errors.
-func (rw *LegacyRewrite) normalize() (err error) {
+func (rw *LegacyRewrite) normalize(ctx context.Context, l *slog.Logger) (err error) {
 	if rw == nil {
 		return errors.Error("nil rewrite entry")
 	}
@@ -85,7 +87,7 @@ func (rw *LegacyRewrite) normalize() (err error) {
 
 	ip, err := netip.ParseAddr(rw.Answer)
 	if err != nil {
-		log.Debug("normalizing legacy rewrite: %s", err)
+		l.DebugContext(ctx, "normalizing legacy rewrite", slogutil.KeyError, err)
 		rw.Type = dns.TypeCNAME
 
 		return nil
@@ -136,9 +138,9 @@ func (rw *LegacyRewrite) Compare(b *LegacyRewrite) (res int) {
 }
 
 // prepareRewrites normalizes and validates all legacy DNS rewrites.
-func (d *DNSFilter) prepareRewrites() (err error) {
+func (d *DNSFilter) prepareRewrites(ctx context.Context) (err error) {
 	for i, r := range d.conf.Rewrites {
-		err = r.normalize()
+		err = r.normalize(ctx, d.logger)
 		if err != nil {
 			return fmt.Errorf("at index %d: %w", i, err)
 		}
@@ -191,7 +193,13 @@ func findRewrites(
 
 // setRewriteResult sets the Reason or IPList of res if necessary.  res must not
 // be nil.
-func setRewriteResult(res *Result, host string, rewrites []*LegacyRewrite, qtype uint16) {
+func (d *DNSFilter) setRewriteResult(
+	ctx context.Context,
+	res *Result,
+	host string,
+	rewrites []*LegacyRewrite,
+	qtype uint16,
+) {
 	for _, rw := range rewrites {
 		if rw.Type == qtype && (qtype == dns.TypeA || qtype == dns.TypeAAAA) {
 			if rw.IP == (netip.Addr{}) {
@@ -203,7 +211,7 @@ func setRewriteResult(res *Result, host string, rewrites []*LegacyRewrite, qtype
 
 			res.IPList = append(res.IPList, rw.IP)
 
-			log.Debug("rewrite: a/aaaa for %s is %s", host, rw.IP)
+			d.logger.DebugContext(ctx, "set a/aaaa rewrite", "host", host, "ans", rw.IP)
 		}
 	}
 }

internal/filtering/rewrites_internal_test.go

@@ -5,6 +5,7 @@ import (
 	"net/netip"
 	"testing"
 
+	"github.com/AdguardTeam/golibs/testutil"
 	"github.com/miekg/dns"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -88,7 +89,8 @@ func TestRewrites(t *testing.T) {
 		Answer: addr1v4.String(),
 	}}
 
-	require.NoError(t, d.prepareRewrites())
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	require.NoError(t, d.prepareRewrites(ctx))
 
 	testCases := []struct {
 		name       string
@@ -236,7 +238,8 @@ func TestRewritesLevels(t *testing.T) {
 		Type:   dns.TypeA,
 	}}
 
-	require.NoError(t, d.prepareRewrites())
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	require.NoError(t, d.prepareRewrites(ctx))
 
 	testCases := []struct {
 		name string
@@ -280,7 +283,8 @@ func TestRewritesExceptionCNAME(t *testing.T) {
 		Answer: "*.sub.host.com",
 	}}
 
-	require.NoError(t, d.prepareRewrites())
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	require.NoError(t, d.prepareRewrites(ctx))
 
 	testCases := []struct {
 		name string
@@ -342,7 +346,8 @@ func TestRewritesExceptionIP(t *testing.T) {
 		Type:   dns.TypeA,
 	}}
 
-	require.NoError(t, d.prepareRewrites())
+	ctx := testutil.ContextWithTimeout(t, testTimeout)
+	require.NoError(t, d.prepareRewrites(ctx))
 
 	testCases := []struct {
 		name       string

internal/home/home.go

@@ -619,7 +619,7 @@ func run(opts options, clientBuildFS fs.FS, done chan struct{}, sigHdlr *signalH
 	// Clients package uses filtering package's static data
 	// (filtering.BlockedSvcKnown()), so we have to initialize filtering static
 	// data first, but also to avoid relying on automatic Go init() function.
-	filtering.InitModule()
+	filtering.InitModule(slogLogger)
 
 	// TODO(s.chzhen):  Use it for the entire initialization process.
 	ctx := context.Background()