diff --git a/internal/home/dns.go b/internal/home/dns.go index ed1f1675..41e521ce 100644 --- a/internal/home/dns.go +++ b/internal/home/dns.go @@ -20,6 +20,7 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/stats" "github.com/AdguardTeam/golibs/errors" "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" "github.com/AdguardTeam/golibs/netutil" "github.com/ameshkov/dnscrypt/v2" yaml "gopkg.in/yaml.v3" @@ -54,6 +55,7 @@ func initDNS(l *slog.Logger) (err error) { } statsConf := stats.Config{ + Logger: l.With(slogutil.KeyPrefix, "stats"), Filename: filepath.Join(statsDir, "stats.db"), Limit: config.Stats.Interval.Duration, ConfigModified: onConfigModified, diff --git a/internal/stats/http.go b/internal/stats/http.go index faec0d14..d151e74d 100644 --- a/internal/stats/http.go +++ b/internal/stats/http.go @@ -10,7 +10,6 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/aghalg" "github.com/AdguardTeam/AdGuardHome/internal/aghhttp" "github.com/AdguardTeam/AdGuardHome/internal/aghnet" - "github.com/AdguardTeam/golibs/log" "github.com/AdguardTeam/golibs/timeutil" ) @@ -62,7 +61,7 @@ func (s *StatsCtx) handleStats(w http.ResponseWriter, r *http.Request) { resp, ok = s.getData(uint32(s.limit.Hours())) }() - log.Debug("stats: prepared data in %v", time.Since(start)) + s.logger.Debug("prepared data", "elapsed", time.Since(start)) if !ok { // Don't bring the message to the lower case since it's a part of UI diff --git a/internal/stats/http_test.go b/internal/stats/http_test.go index 7e358a03..b53668d6 100644 --- a/internal/stats/http_test.go +++ b/internal/stats/http_test.go @@ -10,6 +10,7 @@ import ( "time" "github.com/AdguardTeam/AdGuardHome/internal/aghalg" + "github.com/AdguardTeam/golibs/logutil/slogutil" "github.com/AdguardTeam/golibs/testutil" "github.com/AdguardTeam/golibs/timeutil" "github.com/stretchr/testify/assert" @@ -24,6 +25,7 @@ func TestHandleStatsConfig(t *testing.T) { ) conf := Config{ + Logger: slogutil.NewDiscardLogger(), UnitID: func() (id uint32) { return 0 }, ConfigModified: func() {}, ShouldCountClient: func([]string) bool { return true }, diff --git a/internal/stats/stats.go b/internal/stats/stats.go index e9533ca2..b3372c7b 100644 --- a/internal/stats/stats.go +++ b/internal/stats/stats.go @@ -5,6 +5,7 @@ package stats import ( "fmt" "io" + "log/slog" "net/netip" "os" "sync" @@ -14,7 +15,7 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/aghhttp" "github.com/AdguardTeam/AdGuardHome/internal/aghnet" "github.com/AdguardTeam/golibs/errors" - "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" "github.com/AdguardTeam/golibs/timeutil" "go.etcd.io/bbolt" ) @@ -43,6 +44,10 @@ func validateIvl(ivl time.Duration) (err error) { // // Do not alter any fields of this structure after using it. type Config struct { + // Logger is used for logging the operation of the statistics management. + // It must not be nil. + Logger *slog.Logger + // UnitID is the function to generate the identifier for current unit. If // nil, the default function is used, see newUnitID. UnitID UnitIDGenFunc @@ -96,6 +101,10 @@ type Interface interface { // StatsCtx collects the statistics and flushes it to the database. Its default // flushing interval is one hour. type StatsCtx struct { + // logger is used for logging the operation of the statistics management. + // It must not be nil. + logger *slog.Logger + // currMu protects curr. currMu *sync.RWMutex // curr is the actual statistics collection result. @@ -150,6 +159,7 @@ func New(conf Config) (s *StatsCtx, err error) { } s = &StatsCtx{ + logger: conf.Logger, currMu: &sync.RWMutex{}, httpRegister: conf.HTTPRegister, configModified: conf.ConfigModified, @@ -181,18 +191,18 @@ func New(conf Config) (s *StatsCtx, err error) { return nil, fmt.Errorf("stats: opening a transaction: %w", err) } - deleted := deleteOldUnits(tx, id-uint32(s.limit.Hours())-1) - udb = loadUnitFromDB(tx, id) + deleted := s.deleteOldUnits(tx, id-uint32(s.limit.Hours())-1) + udb = s.loadUnitFromDB(tx, id) err = finishTxn(tx, deleted > 0) if err != nil { - log.Error("stats: %s", err) + s.logger.Error("finishing transacation", slogutil.KeyError, err) } s.curr = newUnit(id) s.curr.deserialize(udb) - log.Debug("stats: initialized") + s.logger.Debug("initialized") return s, nil } @@ -237,7 +247,7 @@ func (s *StatsCtx) Close() (err error) { defer func() { cerr := db.Close() if cerr == nil { - log.Debug("stats: database closed") + s.logger.Debug("database closed") } err = errors.WithDeferred(err, cerr) @@ -254,7 +264,7 @@ func (s *StatsCtx) Close() (err error) { udb := s.curr.serialize() - return udb.flushUnitToDB(tx, s.curr.id) + return s.flushUnitToDB(udb, tx, s.curr.id) } // Update implements the [Interface] interface for *StatsCtx. e must not be @@ -269,7 +279,7 @@ func (s *StatsCtx) Update(e *Entry) { err := e.validate() if err != nil { - log.Debug("stats: updating: validating entry: %s", err) + s.logger.Debug("validating entry", slogutil.KeyError, err) return } @@ -278,7 +288,7 @@ func (s *StatsCtx) Update(e *Entry) { defer s.currMu.Unlock() if s.curr == nil { - log.Error("stats: current unit is nil") + s.logger.Error("current unit is nil") return } @@ -333,8 +343,8 @@ func (s *StatsCtx) TopClientsIP(maxCount uint) (ips []netip.Addr) { // deleteOldUnits walks the buckets available to tx and deletes old units. It // returns the number of deletions performed. -func deleteOldUnits(tx *bbolt.Tx, firstID uint32) (deleted int) { - log.Debug("stats: deleting old units until id %d", firstID) +func (s *StatsCtx) deleteOldUnits(tx *bbolt.Tx, firstID uint32) (deleted int) { + s.logger.Debug("deleting old units up to", "unit", firstID) // TODO(a.garipov): See if this is actually necessary. Looks like a rather // bizarre solution. @@ -348,12 +358,12 @@ func deleteOldUnits(tx *bbolt.Tx, firstID uint32) (deleted int) { err = tx.DeleteBucket(name) if err != nil { - log.Debug("stats: deleting bucket: %s", err) + s.logger.Debug("deleting bucket", slogutil.KeyError, err) return nil } - log.Debug("stats: deleted unit %d (name %x)", nameID, name) + s.logger.Debug("deleted unit", "name_id", nameID, "name", fmt.Sprintf("%x", name)) deleted++ @@ -362,7 +372,7 @@ func deleteOldUnits(tx *bbolt.Tx, firstID uint32) (deleted int) { err := tx.ForEach(walk) if err != nil && !errors.Is(err, errStop) { - log.Debug("stats: deleting units: %s", err) + s.logger.Debug("deleting units", slogutil.KeyError, err) } return deleted @@ -371,20 +381,19 @@ func deleteOldUnits(tx *bbolt.Tx, firstID uint32) (deleted int) { // openDB returns an error if the database can't be opened from the specified // file. It's safe for concurrent use. func (s *StatsCtx) openDB() (err error) { - log.Debug("stats: opening database") + s.logger.Debug("opening database") var db *bbolt.DB db, err = bbolt.Open(s.filename, 0o644, nil) if err != nil { if err.Error() == "invalid argument" { - log.Error("AdGuard Home cannot be initialized due to an incompatible file system.\nPlease read the explanation here: https://github.com/AdguardTeam/AdGuardHome/wiki/Getting-Started#limitations") + s.logger.Error("AdGuard Home cannot be initialized due to an incompatible file system.\nPlease read the explanation here: https://github.com/AdguardTeam/AdGuardHome/wiki/Getting-Started#limitations") } return err } - // Use defer to unlock the mutex as soon as possible. - defer log.Debug("stats: database opened") + defer s.logger.Debug("database opened") s.db.Store(db) @@ -424,21 +433,22 @@ func (s *StatsCtx) flushDB(id, limit uint32, ptr *unit) (cont bool, sleepFor tim isCommitable := true tx, err := db.Begin(true) if err != nil { - log.Error("stats: opening transaction: %s", err) + s.logger.Error("opening transaction", slogutil.KeyError, err) return true, 0 } defer func() { if err = finishTxn(tx, isCommitable); err != nil { - log.Error("stats: %s", err) + s.logger.Error("finishing transaction", slogutil.KeyError, err) } }() s.curr = newUnit(id) - flushErr := ptr.serialize().flushUnitToDB(tx, ptr.id) + udb := ptr.serialize() + flushErr := s.flushUnitToDB(udb, tx, ptr.id) if flushErr != nil { - log.Error("stats: flushing unit: %s", flushErr) + s.logger.Error("flushing unit", slogutil.KeyError, flushErr) isCommitable = false } @@ -446,11 +456,12 @@ func (s *StatsCtx) flushDB(id, limit uint32, ptr *unit) (cont bool, sleepFor tim if delErr != nil { // TODO(e.burkov): Improve the algorithm of deleting the oldest bucket // to avoid the error. + msg := "deleting bucket" if errors.Is(delErr, bbolt.ErrBucketNotFound) { - log.Debug("stats: warning: deleting unit: %s", delErr) + s.logger.Warn(msg, slogutil.KeyError, delErr) } else { isCommitable = false - log.Error("stats: deleting unit: %s", delErr) + s.logger.Error(msg, slogutil.KeyError, delErr) } } @@ -467,7 +478,7 @@ func (s *StatsCtx) periodicFlush() { cont, sleepFor = s.flush() } - log.Debug("periodic flushing finished") + s.logger.Debug("periodic flushing finished") } // setLimit sets the limit. s.lock is expected to be locked. @@ -477,16 +488,16 @@ func (s *StatsCtx) setLimit(limit time.Duration) { if limit != 0 { s.enabled = true s.limit = limit - log.Debug("stats: set limit: %d days", limit/timeutil.Day) + s.logger.Debug("setting limit in days", "num", limit/timeutil.Day) return } s.enabled = false - log.Debug("stats: disabled") + s.logger.Debug("disabled") if err := s.clear(); err != nil { - log.Error("stats: %s", err) + s.logger.Error("clearing", slogutil.KeyError, err) } } @@ -499,7 +510,7 @@ func (s *StatsCtx) clear() (err error) { var tx *bbolt.Tx tx, err = db.Begin(true) if err != nil { - log.Error("stats: opening a transaction: %s", err) + s.logger.Error("opening transaction", slogutil.KeyError, err) } else if err = finishTxn(tx, false); err != nil { // Don't wrap the error since it's informative enough as is. return err @@ -513,21 +524,21 @@ func (s *StatsCtx) clear() (err error) { } // All active transactions are now closed. - log.Debug("stats: database closed") + s.logger.Debug("database closed") } err = os.Remove(s.filename) if err != nil { - log.Error("stats: %s", err) + s.logger.Error("removing", slogutil.KeyError, err) } err = s.openDB() if err != nil { - log.Error("stats: opening database: %s", err) + s.logger.Error("opening database", slogutil.KeyError, err) } // Use defer to unlock the mutex as soon as possible. - defer log.Debug("stats: cleared") + defer s.logger.Debug("cleared") s.currMu.Lock() defer s.currMu.Unlock() @@ -548,7 +559,7 @@ func (s *StatsCtx) loadUnits(limit uint32) (units []*unitDB, curID uint32) { // taken into account. tx, err := db.Begin(true) if err != nil { - log.Error("stats: opening transaction: %s", err) + s.logger.Error("opening transaction", slogutil.KeyError, err) return nil, 0 } @@ -568,7 +579,7 @@ func (s *StatsCtx) loadUnits(limit uint32) (units []*unitDB, curID uint32) { units = make([]*unitDB, 0, limit) firstID := curID - limit + 1 for i := firstID; i != curID; i++ { - u := loadUnitFromDB(tx, i) + u := s.loadUnitFromDB(tx, i) if u == nil { u = &unitDB{NResult: make([]uint64, resultLast)} } @@ -577,7 +588,7 @@ func (s *StatsCtx) loadUnits(limit uint32) (units []*unitDB, curID uint32) { err = finishTxn(tx, false) if err != nil { - log.Error("stats: %s", err) + s.logger.Error("finishing transaction", slogutil.KeyError, err) } if cur != nil { @@ -585,7 +596,9 @@ func (s *StatsCtx) loadUnits(limit uint32) (units []*unitDB, curID uint32) { } if unitsLen := len(units); unitsLen != int(limit) { - log.Fatalf("loaded %d units whilst the desired number is %d", unitsLen, limit) + // Should not happen. + s.logger.Error("number of loaded units not equal to limit", "loaded", unitsLen, "limit", limit) + units = units[:limit] } return units, curID diff --git a/internal/stats/stats_internal_test.go b/internal/stats/stats_internal_test.go index 3423c7ad..e7ed446a 100644 --- a/internal/stats/stats_internal_test.go +++ b/internal/stats/stats_internal_test.go @@ -8,6 +8,7 @@ import ( "testing" "time" + "github.com/AdguardTeam/golibs/logutil/slogutil" "github.com/AdguardTeam/golibs/testutil" "github.com/AdguardTeam/golibs/timeutil" "github.com/stretchr/testify/assert" @@ -18,6 +19,7 @@ func TestStats_races(t *testing.T) { var r uint32 idGen := func() (id uint32) { return atomic.LoadUint32(&r) } conf := Config{ + Logger: slogutil.NewDiscardLogger(), ShouldCountClient: func([]string) bool { return true }, UnitID: idGen, Filename: filepath.Join(t.TempDir(), "./stats.db"), @@ -94,6 +96,7 @@ func TestStatsCtx_FillCollectedStats_daily(t *testing.T) { ) s, err := New(Config{ + Logger: slogutil.NewDiscardLogger(), ShouldCountClient: func([]string) bool { return true }, Filename: filepath.Join(t.TempDir(), "./stats.db"), Limit: time.Hour, @@ -151,6 +154,7 @@ func TestStatsCtx_DataFromUnits_month(t *testing.T) { const hoursInMonth = 720 s, err := New(Config{ + Logger: slogutil.NewDiscardLogger(), ShouldCountClient: func([]string) bool { return true }, Filename: filepath.Join(t.TempDir(), "./stats.db"), Limit: time.Hour, diff --git a/internal/stats/stats_test.go b/internal/stats/stats_test.go index 2f7c526a..e5af7031 100644 --- a/internal/stats/stats_test.go +++ b/internal/stats/stats_test.go @@ -13,6 +13,7 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/aghnet" "github.com/AdguardTeam/AdGuardHome/internal/stats" + "github.com/AdguardTeam/golibs/logutil/slogutil" "github.com/AdguardTeam/golibs/netutil" "github.com/AdguardTeam/golibs/testutil" "github.com/AdguardTeam/golibs/timeutil" @@ -55,6 +56,7 @@ func TestStats(t *testing.T) { handlers := map[string]http.Handler{} conf := stats.Config{ + Logger: slogutil.NewDiscardLogger(), ShouldCountClient: func([]string) bool { return true }, Filename: filepath.Join(t.TempDir(), "stats.db"), Limit: timeutil.Day, @@ -171,6 +173,7 @@ func TestLargeNumbers(t *testing.T) { handlers := map[string]http.Handler{} conf := stats.Config{ + Logger: slogutil.NewDiscardLogger(), ShouldCountClient: func([]string) bool { return true }, Filename: filepath.Join(t.TempDir(), "stats.db"), Limit: timeutil.Day, @@ -222,6 +225,7 @@ func TestShouldCount(t *testing.T) { require.NoError(t, err) s, err := stats.New(stats.Config{ + Logger: slogutil.NewDiscardLogger(), Enabled: true, Filename: filepath.Join(t.TempDir(), "stats.db"), Limit: timeutil.Day, diff --git a/internal/stats/unit.go b/internal/stats/unit.go index 621f1cda..e9aeb87b 100644 --- a/internal/stats/unit.go +++ b/internal/stats/unit.go @@ -10,7 +10,7 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/aghnet" "github.com/AdguardTeam/golibs/errors" - "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" "go.etcd.io/bbolt" "golang.org/x/exp/maps" ) @@ -277,13 +277,14 @@ func (u *unit) serialize() (udb *unitDB) { } } -func loadUnitFromDB(tx *bbolt.Tx, id uint32) (udb *unitDB) { +// loadUnitFromDB loads unit by id from the database. +func (s *StatsCtx) loadUnitFromDB(tx *bbolt.Tx, id uint32) (udb *unitDB) { bkt := tx.Bucket(idToUnitName(id)) if bkt == nil { return nil } - log.Tracef("Loading unit %d", id) + s.logger.Debug("loading unit", "id", id) var buf bytes.Buffer buf.Write(bkt.Get([]byte{0})) @@ -291,7 +292,7 @@ func loadUnitFromDB(tx *bbolt.Tx, id uint32) (udb *unitDB) { err := gob.NewDecoder(&buf).Decode(udb) if err != nil { - log.Error("gob Decode: %s", err) + s.logger.Error("gob decode", slogutil.KeyError, err) return nil } @@ -339,8 +340,8 @@ func (u *unit) add(e *Entry) { } // flushUnitToDB puts udb to the database at id. -func (udb *unitDB) flushUnitToDB(tx *bbolt.Tx, id uint32) (err error) { - log.Debug("stats: flushing unit with id %d and total of %d", id, udb.NTotal) +func (s *StatsCtx) flushUnitToDB(udb *unitDB, tx *bbolt.Tx, id uint32) (err error) { + s.logger.Debug("flushing unit", "id", id, "req_num", udb.NTotal) bkt, err := tx.CreateBucketIfNotExists(idToUnitName(id)) if err != nil {