From 76344f97850a2a54a6d4bb27c66b16bb364b916f Mon Sep 17 00:00:00 2001 From: Stanislav Chzhen Date: Mon, 2 Sep 2024 18:03:37 +0300 Subject: [PATCH 1/6] Pull request 2274: AGDNS-2374-slog-scripts Squashed commit of the following: commit 257bd542f78d6e06a6b4783a050b573240a2b5ca Author: Stanislav Chzhen Date: Mon Sep 2 17:33:12 2024 +0300 scripts: slog --- scripts/blocked-services/main.go | 11 +++++--- scripts/translations/download.go | 44 ++++++++++++++++++++------------ scripts/translations/main.go | 19 +++++++++----- 3 files changed, 48 insertions(+), 26 deletions(-) diff --git a/scripts/blocked-services/main.go b/scripts/blocked-services/main.go index bb0b97cc..43ac4fae 100644 --- a/scripts/blocked-services/main.go +++ b/scripts/blocked-services/main.go @@ -4,8 +4,10 @@ package main import ( + "context" "encoding/json" "fmt" + "log/slog" "net/http" "net/url" "os" @@ -14,10 +16,13 @@ import ( "text/template" "time" - "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" ) func main() { + ctx := context.Background() + l := slogutil.New(nil) + urlStr := "https://adguardteam.github.io/HostlistsRegistry/assets/services.json" if v, ok := os.LookupEnv("URL"); ok { urlStr = v @@ -33,7 +38,7 @@ func main() { resp, err := c.Get(urlStr) check(err) - defer log.OnCloserError(resp.Body, log.ERROR) + defer slogutil.CloseAndLog(ctx, l, resp.Body, slog.LevelError) if resp.StatusCode != http.StatusOK { panic(fmt.Errorf("expected code %d, got %d", http.StatusOK, resp.StatusCode)) @@ -64,7 +69,7 @@ func main() { 0o644, ) check(err) - defer log.OnCloserError(f, log.ERROR) + defer slogutil.CloseAndLog(ctx, l, f, slog.LevelError) err = tmpl.Execute(f, hlSvcs) check(err) diff --git a/scripts/translations/download.go b/scripts/translations/download.go index a7efc420..b7927f2d 100644 --- a/scripts/translations/download.go +++ b/scripts/translations/download.go @@ -1,25 +1,26 @@ package main import ( + "context" "flag" "fmt" "io" + "log/slog" "net/http" "net/url" "os" "path/filepath" "slices" - "strings" "sync" "time" "github.com/AdguardTeam/golibs/errors" "github.com/AdguardTeam/golibs/ioutil" - "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" ) // download and save all translations. -func (c *twoskyClient) download() (err error) { +func (c *twoskyClient) download(ctx context.Context, l *slog.Logger) (err error) { var numWorker int flagSet := flag.NewFlagSet("download", flag.ExitOnError) @@ -50,7 +51,7 @@ func (c *twoskyClient) download() (err error) { for range numWorker { wg.Add(1) - go downloadWorker(wg, failed, client, uriCh) + go downloadWorker(ctx, l, wg, failed, client, uriCh) } for _, lang := range c.langs { @@ -62,13 +63,13 @@ func (c *twoskyClient) download() (err error) { close(uriCh) wg.Wait() - printFailedLocales(failed) + printFailedLocales(ctx, l, failed) return nil } // printFailedLocales prints sorted list of failed downloads, if any. -func printFailedLocales(failed *sync.Map) { +func printFailedLocales(ctx context.Context, l *slog.Logger, failed *sync.Map) { keys := []string{} failed.Range(func(k, _ any) bool { s, ok := k.(string) @@ -86,12 +87,14 @@ func printFailedLocales(failed *sync.Map) { } slices.Sort(keys) - log.Info("failed locales: %s", strings.Join(keys, " ")) + l.InfoContext(ctx, "failed", "locales", keys) } // downloadWorker downloads translations by received urls and saves them. // Where failed is a map for storing failed downloads. func downloadWorker( + ctx context.Context, + l *slog.Logger, wg *sync.WaitGroup, failed *sync.Map, client *http.Client, @@ -103,9 +106,9 @@ func downloadWorker( q := uri.Query() code := q.Get("language") - err := saveToFile(client, uri, code) + err := saveToFile(ctx, l, client, uri, code) if err != nil { - log.Error("download: worker: %s", err) + l.ErrorContext(ctx, "download worker", slogutil.KeyError, err) failed.Store(code, struct{}{}) } } @@ -113,12 +116,16 @@ func downloadWorker( // saveToFile downloads translation by url and saves it to a file, or returns // error. -func saveToFile(client *http.Client, uri *url.URL, code string) (err error) { - data, err := getTranslation(client, uri.String()) +func saveToFile( + ctx context.Context, + l *slog.Logger, + client *http.Client, + uri *url.URL, + code string, +) (err error) { + data, err := getTranslation(ctx, l, client, uri.String()) if err != nil { - log.Info("%s", data) - - return fmt.Errorf("getting translation: %s", err) + return fmt.Errorf("getting translation %q: %s", code, err) } name := filepath.Join(localesDir, code+".json") @@ -134,13 +141,18 @@ func saveToFile(client *http.Client, uri *url.URL, code string) (err error) { // getTranslation returns received translation data and error. If err is not // nil, data may contain a response from server for inspection. -func getTranslation(client *http.Client, url string) (data []byte, err error) { +func getTranslation( + ctx context.Context, + l *slog.Logger, + client *http.Client, + url string, +) (data []byte, err error) { resp, err := client.Get(url) if err != nil { return nil, fmt.Errorf("requesting: %w", err) } - defer log.OnCloserError(resp.Body, log.ERROR) + defer slogutil.CloseAndLog(ctx, l, resp.Body, slog.LevelError) if resp.StatusCode != http.StatusOK { err = fmt.Errorf("url: %q; status code: %s", url, http.StatusText(resp.StatusCode)) diff --git a/scripts/translations/main.go b/scripts/translations/main.go index c5b1ef1e..33a57b19 100644 --- a/scripts/translations/main.go +++ b/scripts/translations/main.go @@ -6,8 +6,10 @@ import ( "bufio" "bytes" "cmp" + "context" "encoding/json" "fmt" + "log/slog" "net/url" "os" "os/exec" @@ -18,7 +20,7 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/aghos" "github.com/AdguardTeam/golibs/errors" - "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" "golang.org/x/exp/maps" ) @@ -63,6 +65,9 @@ type textLabel string type locales map[textLabel]string func main() { + ctx := context.Background() + l := slogutil.New(nil) + if len(os.Args) == 1 { usage("need a command") } @@ -83,9 +88,9 @@ func main() { cli, err = conf.toClient() check(err) - err = cli.download() + err = cli.download(ctx, l) case "unused": - err = unused(conf.LocalizableFiles[0]) + err = unused(ctx, l, conf.LocalizableFiles[0]) case "upload": cli, err = conf.toClient() check(err) @@ -322,7 +327,7 @@ func summary(langs languages) (err error) { } // unused prints unused text labels. -func unused(basePath string) (err error) { +func unused(ctx context.Context, l *slog.Logger, basePath string) (err error) { defer func() { err = errors.Annotate(err, "unused: %w") }() baseLoc, err := readLocales(basePath) @@ -331,7 +336,7 @@ func unused(basePath string) (err error) { } locDir := filepath.Clean(localesDir) - js, err := findJS(locDir) + js, err := findJS(ctx, l, locDir) if err != nil { return err } @@ -340,10 +345,10 @@ func unused(basePath string) (err error) { } // findJS returns list of JavaScript and JSON files or error. -func findJS(locDir string) (fileNames []string, err error) { +func findJS(ctx context.Context, l *slog.Logger, locDir string) (fileNames []string, err error) { walkFn := func(name string, _ os.FileInfo, err error) error { if err != nil { - log.Info("warning: accessing a path %q: %s", name, err) + l.WarnContext(ctx, "accessing a path", slogutil.KeyError, err) return nil } From b443cf35c40510cbe9de2e491b3024aed8374dcb Mon Sep 17 00:00:00 2001 From: Stanislav Chzhen Date: Mon, 9 Sep 2024 13:31:54 +0300 Subject: [PATCH 2/6] Pull request 2275: AGDNS-2374-slog-stats Squashed commit of the following: commit 45b2fc6a05a4f7775d2b6fa056c81d53d4f402d7 Author: Stanislav Chzhen Date: Thu Sep 5 18:07:06 2024 +0300 all: imp code commit 022c90496a46b0a0423dd2cb1c02a3473ba5d224 Author: Stanislav Chzhen Date: Wed Sep 4 19:32:35 2024 +0300 stats: imp code commit bb3c0c8002c34bec7440cd93b7833f7022eef0d8 Author: Stanislav Chzhen Date: Wed Sep 4 19:10:36 2024 +0300 all: imp code commit 363a16f6bb2faa1d9b890b4967684129208af62e Author: Stanislav Chzhen Date: Wed Sep 4 17:45:31 2024 +0300 all: imp code commit a3c96e3d211cc5e11ba09e334748f65a44b8960a Author: Stanislav Chzhen Date: Mon Sep 2 20:44:11 2024 +0300 stats: imp code commit 2c0ffd91fddd286254b53be790146a2931b7b55b Author: Stanislav Chzhen Date: Mon Sep 2 19:47:11 2024 +0300 all: slog stats --- internal/aghhttp/aghhttp.go | 30 ++++++++ internal/home/dns.go | 2 + internal/stats/http.go | 46 ++++++++--- internal/stats/http_test.go | 2 + internal/stats/stats.go | 106 ++++++++++++++++---------- internal/stats/stats_internal_test.go | 4 + internal/stats/stats_test.go | 8 +- internal/stats/unit.go | 13 ++-- 8 files changed, 149 insertions(+), 62 deletions(-) diff --git a/internal/aghhttp/aghhttp.go b/internal/aghhttp/aghhttp.go index 88dfe7a7..48694a8e 100644 --- a/internal/aghhttp/aghhttp.go +++ b/internal/aghhttp/aghhttp.go @@ -2,13 +2,16 @@ package aghhttp import ( + "context" "fmt" "io" + "log/slog" "net/http" "github.com/AdguardTeam/AdGuardHome/internal/version" "github.com/AdguardTeam/golibs/httphdr" "github.com/AdguardTeam/golibs/log" + "github.com/AdguardTeam/golibs/logutil/slogutil" ) // HTTP scheme constants. @@ -31,12 +34,39 @@ func OK(w http.ResponseWriter) { } // Error writes formatted message to w and also logs it. +// +// TODO(s.chzhen): Remove it. func Error(r *http.Request, w http.ResponseWriter, code int, format string, args ...any) { text := fmt.Sprintf(format, args...) log.Error("%s %s %s: %s", r.Method, r.Host, r.URL, text) http.Error(w, text, code) } +// ErrorAndLog writes formatted message to w and also logs it with the specified +// logging level. +func ErrorAndLog( + ctx context.Context, + l *slog.Logger, + r *http.Request, + w http.ResponseWriter, + code int, + format string, + args ...any, +) { + text := fmt.Sprintf(format, args...) + l.ErrorContext( + ctx, + "http error", + "host", r.Host, + "method", r.Method, + "raddr", r.RemoteAddr, + "request_uri", r.RequestURI, + slogutil.KeyError, text, + ) + + http.Error(w, text, code) +} + // UserAgent returns the ID of the service as a User-Agent string. It can also // be used as the value of the Server HTTP header. func UserAgent() (ua string) { 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..7415e0db 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" ) @@ -51,6 +50,8 @@ type StatsResp struct { func (s *StatsCtx) handleStats(w http.ResponseWriter, r *http.Request) { start := time.Now() + ctx := r.Context() + var ( resp *StatsResp ok bool @@ -62,12 +63,17 @@ 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.DebugContext( + ctx, + "prepared data", + "elapsed", timeutil.Duration{Duration: time.Since(start)}, + ) if !ok { // Don't bring the message to the lower case since it's a part of UI // text for the moment. - aghhttp.Error(r, w, http.StatusInternalServerError, "Couldn't get statistics data") + const msg = "Couldn't get statistics data" + aghhttp.ErrorAndLog(ctx, s.logger, r, w, http.StatusInternalServerError, msg) return } @@ -146,16 +152,18 @@ func (s *StatsCtx) handleGetStatsConfig(w http.ResponseWriter, r *http.Request) // // Deprecated: Remove it when migration to the new API is over. func (s *StatsCtx) handleStatsConfig(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() + reqData := configResp{} err := json.NewDecoder(r.Body).Decode(&reqData) if err != nil { - aghhttp.Error(r, w, http.StatusBadRequest, "json decode: %s", err) + aghhttp.ErrorAndLog(ctx, s.logger, r, w, http.StatusBadRequest, "json decode: %s", err) return } if !checkInterval(reqData.IntervalDays) { - aghhttp.Error(r, w, http.StatusBadRequest, "Unsupported interval") + aghhttp.ErrorAndLog(ctx, s.logger, r, w, http.StatusBadRequest, "Unsupported interval") return } @@ -173,17 +181,19 @@ func (s *StatsCtx) handleStatsConfig(w http.ResponseWriter, r *http.Request) { // handlePutStatsConfig is the handler for the PUT /control/stats/config/update // HTTP API. func (s *StatsCtx) handlePutStatsConfig(w http.ResponseWriter, r *http.Request) { + ctx := r.Context() + reqData := getConfigResp{} err := json.NewDecoder(r.Body).Decode(&reqData) if err != nil { - aghhttp.Error(r, w, http.StatusBadRequest, "json decode: %s", err) + aghhttp.ErrorAndLog(ctx, s.logger, r, w, http.StatusBadRequest, "json decode: %s", err) return } engine, err := aghnet.NewIgnoreEngine(reqData.Ignored) if err != nil { - aghhttp.Error(r, w, http.StatusUnprocessableEntity, "ignored: %s", err) + aghhttp.ErrorAndLog(ctx, s.logger, r, w, http.StatusUnprocessableEntity, "ignored: %s", err) return } @@ -191,13 +201,21 @@ func (s *StatsCtx) handlePutStatsConfig(w http.ResponseWriter, r *http.Request) ivl := time.Duration(reqData.Interval) * time.Millisecond err = validateIvl(ivl) if err != nil { - aghhttp.Error(r, w, http.StatusUnprocessableEntity, "unsupported interval: %s", err) + aghhttp.ErrorAndLog( + ctx, + s.logger, + r, + w, + http.StatusUnprocessableEntity, + "unsupported interval: %s", + err, + ) return } if reqData.Enabled == aghalg.NBNull { - aghhttp.Error(r, w, http.StatusUnprocessableEntity, "enabled is null") + aghhttp.ErrorAndLog(ctx, s.logger, r, w, http.StatusUnprocessableEntity, "enabled is null") return } @@ -216,7 +234,15 @@ func (s *StatsCtx) handlePutStatsConfig(w http.ResponseWriter, r *http.Request) func (s *StatsCtx) handleStatsReset(w http.ResponseWriter, r *http.Request) { err := s.clear() if err != nil { - aghhttp.Error(r, w, http.StatusInternalServerError, "stats: %s", err) + aghhttp.ErrorAndLog( + r.Context(), + s.logger, + r, + w, + http.StatusInternalServerError, + "stats: %s", + err, + ) } } 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..c6de4c66 100644 --- a/internal/stats/stats.go +++ b/internal/stats/stats.go @@ -3,8 +3,10 @@ package stats import ( + "context" "fmt" "io" + "log/slog" "net/netip" "os" "sync" @@ -14,7 +16,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 +45,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 +102,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 +160,7 @@ func New(conf Config) (s *StatsCtx, err error) { } s = &StatsCtx{ + logger: conf.Logger, currMu: &sync.RWMutex{}, httpRegister: conf.HTTPRegister, configModified: conf.ConfigModified, @@ -178,21 +189,21 @@ func New(conf Config) (s *StatsCtx, err error) { tx, err := s.db.Load().Begin(true) if err != nil { - return nil, fmt.Errorf("stats: opening a transaction: %w", err) + return nil, fmt.Errorf("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 } @@ -228,8 +239,6 @@ func (s *StatsCtx) Start() { // Close implements the [io.Closer] interface for *StatsCtx. func (s *StatsCtx) Close() (err error) { - defer func() { err = errors.Annotate(err, "stats: closing: %w") }() - db := s.db.Swap(nil) if db == nil { return nil @@ -237,7 +246,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 +263,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 +278,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 +287,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 +342,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 +357,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 +371,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 +380,29 @@ 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") + const lines = `AdGuard Home cannot be initialized due to an incompatible file system. +Please read the explanation here: https://github.com/AdguardTeam/AdGuardHome/wiki/Getting-Started#limitations` + + // TODO(s.chzhen): Use passed context. + slogutil.PrintLines( + context.TODO(), + s.logger, + slog.LevelError, + "opening database", + lines, + ) } 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,34 +442,37 @@ 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 } delErr := tx.DeleteBucket(idToUnitName(id - limit)) + if delErr != nil { // TODO(e.burkov): Improve the algorithm of deleting the oldest bucket // to avoid the error. - if errors.Is(delErr, bbolt.ErrBucketNotFound) { - log.Debug("stats: warning: deleting unit: %s", delErr) - } else { + lvl := slog.LevelWarn + if !errors.Is(delErr, bbolt.ErrBucketNotFound) { isCommitable = false - log.Error("stats: deleting unit: %s", delErr) + lvl = slog.LevelError } + + s.logger.Log(context.TODO(), lvl, "deleting bucket", slogutil.KeyError, delErr) } return true, 0 @@ -467,7 +488,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 +498,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 +520,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 +534,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 +569,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 +589,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 +598,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 +606,8 @@ 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. + panic(fmt.Errorf("loaded %d units when the desired number is %d", unitsLen, 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..dbf857d6 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" @@ -21,10 +22,6 @@ import ( "github.com/stretchr/testify/require" ) -func TestMain(m *testing.M) { - testutil.DiscardLogOutput(m) -} - // constUnitID is the UnitIDGenFunc which always return 0. func constUnitID() (id uint32) { return 0 } @@ -55,6 +52,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 +169,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 +221,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 { From 6fe4b9440d393786e6a797d49f54ca983ecde534 Mon Sep 17 00:00:00 2001 From: Eugene Burkov Date: Tue, 10 Sep 2024 15:14:48 +0300 Subject: [PATCH 3/6] Pull request 2276: Update Go & tools Squashed commit of the following: commit 74629880756659d22989a69bd7631a246207d3b7 Author: Eugene Burkov Date: Tue Sep 10 14:35:51 2024 +0300 all: fix docs commit 238ff1d418f1aef2b0056be96ce83484341c3fea Author: Eugene Burkov Date: Tue Sep 10 14:28:27 2024 +0300 all: upd go & tools --- .github/workflows/build.yml | 2 +- .github/workflows/lint.yml | 2 +- CHANGELOG.md | 8 +- Makefile | 2 +- README.md | 2 +- bamboo-specs/release.yaml | 6 +- bamboo-specs/test.yaml | 4 +- go.mod | 2 +- internal/tools/go.mod | 45 +++++++-- internal/tools/go.sum | 192 ++++++++++++++++++++++++++++++------ scripts/make/go-lint.sh | 4 +- 11 files changed, 220 insertions(+), 49 deletions(-) diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index eb173124..f36a61ec 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -1,7 +1,7 @@ 'name': 'build' 'env': - 'GO_VERSION': '1.22.6' + 'GO_VERSION': '1.23.1' 'NODE_VERSION': '16' 'on': diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index 469396ce..f5e99131 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -1,7 +1,7 @@ 'name': 'lint' 'env': - 'GO_VERSION': '1.22.6' + 'GO_VERSION': '1.23.1' 'on': 'push': diff --git a/CHANGELOG.md b/CHANGELOG.md index ac1da18c..88573283 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,6 +27,11 @@ See also the [v0.107.53 GitHub milestone][ms-v0.107.53]. NOTE: Add new changes BELOW THIS COMMENT. --> +### Security + +- Go version has been updated to prevent the possibility of exploiting the Go + vulnerabilities fixed in [1.23.1][go-1.23.1]. + ### Added - Support for 64-bit RISC-V architecture ([#5704]). @@ -36,7 +41,6 @@ NOTE: Add new changes BELOW THIS COMMENT. - Upstream server URL domain names requirements has been relaxed and now follow the same rules as their domain specifications. -- Go version has been updated to [1.22.6][go-1.22.6]. ### Fixed @@ -49,7 +53,7 @@ NOTE: Add new changes BELOW THIS COMMENT. [#7154]: https://github.com/AdguardTeam/AdGuardHome/pull/7154 [#7155]: https://github.com/AdguardTeam/AdGuardHome/pull/7155 -[go-1.22.6]: https://groups.google.com/g/golang-announce/c/X4q_-Wf-5g4 +[go-1.23.1]: https://groups.google.com/g/golang-announce/c/K-cEzDeCtpc