diff --git a/internal/aghhttp/aghhttp.go b/internal/aghhttp/aghhttp.go index 88dfe7a7..59381042 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, + lvl slog.Level, + r *http.Request, + w http.ResponseWriter, + code int, + format string, + args ...any, +) { + text := fmt.Sprintf(format, args...) + l.Log( + ctx, + lvl, + "http error", + "method", r.Method, + "host", r.Host, + "url", r.URL, + 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/stats/http.go b/internal/stats/http.go index 4c9320d1..be59b9b7 100644 --- a/internal/stats/http.go +++ b/internal/stats/http.go @@ -4,6 +4,7 @@ package stats import ( "encoding/json" + "log/slog" "net/http" "time" @@ -50,6 +51,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 @@ -61,12 +64,23 @@ func (s *StatsCtx) handleStats(w http.ResponseWriter, r *http.Request) { resp, ok = s.getData(uint32(s.limit.Hours())) }() - s.logger.Debug("prepared data", "elapsed", timeutil.Duration{Duration: 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") + aghhttp.ErrorAndLog( + ctx, + s.logger, + slog.LevelError, + r, + w, + http.StatusInternalServerError, "Couldn't get statistics data", + ) return } @@ -145,16 +159,35 @@ 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, + slog.LevelError, + 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, + slog.LevelError, + r, + w, + http.StatusBadRequest, + "Unsupported interval", + ) return } @@ -172,17 +205,37 @@ 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, + slog.LevelError, + 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, + slog.LevelError, + r, + w, + http.StatusUnprocessableEntity, + "ignored: %s", + err, + ) return } @@ -190,13 +243,30 @@ 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, + slog.LevelError, + 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, + slog.LevelError, + r, + w, + http.StatusUnprocessableEntity, + "enabled is null", + ) return } @@ -215,7 +285,16 @@ 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, + slog.LevelError, + r, + w, + http.StatusInternalServerError, + "stats: %s", + err, + ) } } diff --git a/internal/stats/stats.go b/internal/stats/stats.go index feb17f86..b77c2aaf 100644 --- a/internal/stats/stats.go +++ b/internal/stats/stats.go @@ -189,7 +189,7 @@ 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 := s.deleteOldUnits(tx, id-uint32(s.limit.Hours())-1) @@ -239,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 @@ -392,7 +390,13 @@ func (s *StatsCtx) openDB() (err error) { 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) + slogutil.PrintLines( + context.TODO(), + s.logger, + slog.LevelError, + "opening database", + lines, + ) } return err @@ -458,16 +462,17 @@ func (s *StatsCtx) flushDB(id, limit uint32, ptr *unit) (cont bool, sleepFor tim } delErr := tx.DeleteBucket(idToUnitName(id - limit)) + 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) { - s.logger.Warn(msg, slogutil.KeyError, delErr) - } else { + logFunc := s.logger.Warn + if !errors.Is(delErr, bbolt.ErrBucketNotFound) { isCommitable = false - s.logger.Error(msg, slogutil.KeyError, delErr) + logFunc = s.logger.Error } + + logFunc("deleting bucket", slogutil.KeyError, delErr) } return true, 0 diff --git a/internal/stats/stats_test.go b/internal/stats/stats_test.go index 6e7d1710..dbf857d6 100644 --- a/internal/stats/stats_test.go +++ b/internal/stats/stats_test.go @@ -22,11 +22,6 @@ import ( "github.com/stretchr/testify/require" ) -// TODO(s.chzhen): Remove once [aghhttp.Error] starts using slog. -func TestMain(m *testing.M) { - testutil.DiscardLogOutput(m) -} - // constUnitID is the UnitIDGenFunc which always return 0. func constUnitID() (id uint32) { return 0 }