diff --git a/internal/filtering/blocked.go b/internal/filtering/blocked.go index ca59a1b8..458ba40d 100644 --- a/internal/filtering/blocked.go +++ b/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() } diff --git a/internal/filtering/filtering.go b/internal/filtering/filtering.go index a4659d12..77cd8790 100644 --- a/internal/filtering/filtering.go +++ b/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) } diff --git a/internal/filtering/hosts.go b/internal/filtering/hosts.go index 4943b1af..ba5b3899 100644 --- a/internal/filtering/hosts.go +++ b/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 } diff --git a/internal/filtering/http.go b/internal/filtering/http.go index 99acdb16..dca039a0 100644 --- a/internal/filtering/http.go +++ b/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() diff --git a/internal/filtering/rewritehttp.go b/internal/filtering/rewritehttp.go index af2ddf1f..d6415a05 100644 --- a/internal/filtering/rewritehttp.go +++ b/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, + ) } diff --git a/internal/filtering/rewrites.go b/internal/filtering/rewrites.go index 5ac2ffcc..809859b8 100644 --- a/internal/filtering/rewrites.go +++ b/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) } } } diff --git a/internal/filtering/rewrites_internal_test.go b/internal/filtering/rewrites_internal_test.go index cdec8529..baa17a31 100644 --- a/internal/filtering/rewrites_internal_test.go +++ b/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 diff --git a/internal/home/home.go b/internal/home/home.go index e693fcd3..56de2186 100644 --- a/internal/home/home.go +++ b/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()