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 {