From e628d2db6f7e2e3db085a52e1d92f03b4e6600ca Mon Sep 17 00:00:00 2001 From: Wael Nasreddine Date: Mon, 16 Dec 2024 01:37:43 -0800 Subject: [PATCH] treewide: replace log15 with zerolog (#123) --- .golangci.yml | 1 + cmd/cmd.go | 4 +- cmd/maxprocs.go | 12 +- cmd/serve.go | 26 ++-- go.mod | 6 +- go.sum | 14 +- main.go | 24 ++-- nix/packages/ncps.nix | 2 +- pkg/cache/cache.go | 219 +++++++++++++++++------------ pkg/cache/cache_internal_test.go | 10 +- pkg/cache/cache_test.go | 9 +- pkg/cache/upstream/cache.go | 37 +++-- pkg/cache/upstream/cache_test.go | 9 +- pkg/database/query_test.go | 9 -- pkg/nar/url.go | 14 +- pkg/server/server.go | 90 ++++++------ pkg/server/server_internal_test.go | 10 +- pkg/server/server_test.go | 9 +- 18 files changed, 273 insertions(+), 232 deletions(-) diff --git a/.golangci.yml b/.golangci.yml index 8202644..e9588bf 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -38,6 +38,7 @@ linters: - wastedassign - whitespace - wsl + - zerologlint linters-settings: gci: # Section configuration to compare against. diff --git a/cmd/cmd.go b/cmd/cmd.go index 3f0f520..c05dabf 100644 --- a/cmd/cmd.go +++ b/cmd/cmd.go @@ -1,7 +1,7 @@ package cmd import ( - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "github.com/urfave/cli/v3" ) @@ -10,7 +10,7 @@ import ( //nolint:gochecknoglobals var Version = "dev" -func New(logger log15.Logger) *cli.Command { +func New(logger zerolog.Logger) *cli.Command { return &cli.Command{ Name: "ncps", Usage: "Nix Binary Cache Proxy Service", diff --git a/cmd/maxprocs.go b/cmd/maxprocs.go index a7dc22c..8d4b9bb 100644 --- a/cmd/maxprocs.go +++ b/cmd/maxprocs.go @@ -5,7 +5,7 @@ import ( "fmt" "time" - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "go.uber.org/automaxprocs/maxprocs" ) @@ -14,13 +14,13 @@ import ( // autoMaxProcs automatically configures Go's runtime.GOMAXPROCS based on the // given quota in a container. -func autoMaxProcs(ctx context.Context, d time.Duration, logger log15.Logger) error { - log := logger.New("operation", "auto-max-procs") +func autoMaxProcs(ctx context.Context, d time.Duration, logger zerolog.Logger) error { + log := logger.With().Str("operation", "auto-max-procs").Logger() infof := diffInfof(log) setMaxProcs := func() { if _, err := maxprocs.Set(maxprocs.Logger(infof)); err != nil { - log.Error("failed to set GOMAXPROCS", "error", err) + log.Error().Err(err).Msg("failed to set GOMAXPROCS") } } // set the gomaxprocs immediately. @@ -39,13 +39,13 @@ func autoMaxProcs(ctx context.Context, d time.Duration, logger log15.Logger) err } } -func diffInfof(logger log15.Logger) func(string, ...interface{}) { +func diffInfof(logger zerolog.Logger) func(string, ...interface{}) { var last string return func(format string, args ...interface{}) { msg := fmt.Sprintf(format, args...) if msg != last { - logger.Info(msg) + logger.Info().Msg(msg) last = msg } } diff --git a/cmd/serve.go b/cmd/serve.go index ec46573..dd6a309 100644 --- a/cmd/serve.go +++ b/cmd/serve.go @@ -9,8 +9,8 @@ import ( "regexp" "time" - "github.com/inconshreveable/log15/v3" "github.com/robfig/cron/v3" + "github.com/rs/zerolog" "github.com/urfave/cli/v3" "golang.org/x/sync/errgroup" @@ -23,12 +23,12 @@ import ( // ErrCacheMaxSizeRequired is returned if --cache-lru-schedule was given but not --cache-max-size. var ErrCacheMaxSizeRequired = errors.New("--cache-max-size is required when --cache-lru-schedule is specified") -func serveCommand(logger log15.Logger) *cli.Command { +func serveCommand(logger zerolog.Logger) *cli.Command { return &cli.Command{ Name: "serve", Aliases: []string{"s"}, Usage: "serve the nix binary cache over http", - Action: serveAction(logger.New("cmd", "serve")), + Action: serveAction(logger.With().Str("cmd", "serve").Logger()), Flags: []cli.Flag{ &cli.BoolFlag{ Name: "allow-delete", @@ -101,14 +101,14 @@ func serveCommand(logger log15.Logger) *cli.Command { } } -func serveAction(logger log15.Logger) cli.ActionFunc { +func serveAction(logger zerolog.Logger) cli.ActionFunc { return func(ctx context.Context, cmd *cli.Command) error { ctx, cancel := context.WithCancel(ctx) g, ctx := errgroup.WithContext(ctx) defer func() { if err := g.Wait(); err != nil { - logger.Error("error returned from g.Wait()", "error", err) + logger.Error().Err(err).Msg("error returned from g.Wait()") } }() @@ -141,7 +141,9 @@ func serveAction(logger log15.Logger) cli.ActionFunc { ReadHeaderTimeout: 10 * time.Second, } - logger.Info("Server started", "server-addr", cmd.String("server-addr")) + logger.Info(). + Str("server-addr", cmd.String("server-addr")). + Msg("Server started") if err := server.ListenAndServe(); err != nil { return fmt.Errorf("error starting the HTTP listener: %w", err) @@ -151,7 +153,7 @@ func serveAction(logger log15.Logger) cli.ActionFunc { } } -func getUpstreamCaches(_ context.Context, logger log15.Logger, cmd *cli.Command) ([]upstream.Cache, error) { +func getUpstreamCaches(_ context.Context, logger zerolog.Logger, cmd *cli.Command) ([]upstream.Cache, error) { ucSlice := cmd.StringSlice("upstream-cache") ucs := make([]upstream.Cache, 0, len(ucSlice)) @@ -183,7 +185,7 @@ func getUpstreamCaches(_ context.Context, logger log15.Logger, cmd *cli.Command) return ucs, nil } -func createCache(logger log15.Logger, cmd *cli.Command, ucs []upstream.Cache) (*cache.Cache, error) { +func createCache(logger zerolog.Logger, cmd *cli.Command, ucs []upstream.Cache) (*cache.Cache, error) { c, err := cache.New(logger, cmd.String("cache-hostname"), cmd.String("cache-data-path")) if err != nil { return nil, fmt.Errorf("error creating a new cache: %w", err) @@ -205,7 +207,9 @@ func createCache(logger log15.Logger, cmd *cli.Command, ucs []upstream.Cache) (* return nil, fmt.Errorf("error parsing the size: %w", err) } - logger.Info("setting up the cache max-size", "max-size", maxSize) + logger.Info(). + Uint64("max-size", maxSize). + Msg("setting up the cache max-size") c.SetMaxSize(maxSize) @@ -218,7 +222,9 @@ func createCache(logger log15.Logger, cmd *cli.Command, ucs []upstream.Cache) (* } } - logger.Info("setting up the cache timezone location", "time-zone", loc) + logger.Info(). + Str("time-zone", loc.String()). + Msg("setting up the cache timezone location") c.SetupCron(loc) diff --git a/go.mod b/go.mod index 27635ea..65375a7 100644 --- a/go.mod +++ b/go.mod @@ -4,12 +4,11 @@ go 1.23.3 require ( github.com/go-chi/chi/v5 v5.1.0 - github.com/inconshreveable/log15/v3 v3.0.0-testing.5 github.com/klauspost/compress v1.17.11 - github.com/mattn/go-colorable v0.1.13 github.com/mattn/go-sqlite3 v1.14.24 github.com/nix-community/go-nix v0.0.0-20241207090453-00891a7727c2 github.com/robfig/cron/v3 v3.0.1 + github.com/rs/zerolog v1.33.0 github.com/stretchr/testify v1.10.0 github.com/urfave/cli/v3 v3.0.0-beta1 go.uber.org/automaxprocs v1.6.0 @@ -19,10 +18,9 @@ require ( require ( github.com/davecgh/go-spew v1.1.1 // indirect - github.com/go-stack/stack v1.8.1 // indirect - github.com/inconshreveable/log15 v3.0.0-testing.5+incompatible // indirect github.com/klauspost/cpuid/v2 v2.2.9 // indirect github.com/kr/text v0.2.0 // indirect + github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-isatty v0.0.20 // indirect github.com/minio/sha256-simd v1.0.1 // indirect github.com/mr-tron/base58 v1.2.0 // indirect diff --git a/go.sum b/go.sum index efc417b..f063df2 100644 --- a/go.sum +++ b/go.sum @@ -1,14 +1,10 @@ +github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/go-chi/chi/v5 v5.1.0 h1:acVI1TYaD+hhedDJ3r54HyA6sExp3HfXq7QWEEY/xMw= github.com/go-chi/chi/v5 v5.1.0/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8= -github.com/go-stack/stack v1.8.1 h1:ntEHSVwIt7PNXNpgPmVfMrNhLtgjlmnZha2kOpuRiDw= -github.com/go-stack/stack v1.8.1/go.mod h1:dcoOX6HbPZSZptuspn9bctJ+N/CnF5gGygcUP3XYfe4= -github.com/inconshreveable/log15 v3.0.0-testing.5+incompatible h1:VryeOTiaZfAzwx8xBcID1KlJCeoWSIpsNbSk+/D2LNk= -github.com/inconshreveable/log15 v3.0.0-testing.5+incompatible/go.mod h1:cOaXtrgN4ScfRrD9Bre7U1thNq5RtJ8ZoP4iXVGRj6o= -github.com/inconshreveable/log15/v3 v3.0.0-testing.5 h1:h4e0f3kjgg+RJBlKOabrohjHe47D3bbAB9BgMrc3DYA= -github.com/inconshreveable/log15/v3 v3.0.0-testing.5/go.mod h1:3GQg1SVrLoWGfRv/kAZMsdyU5cp8eFc1P3cw+Wwku94= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/klauspost/compress v1.17.11 h1:In6xLpyWOi1+C7tXUUWv2ot1QvBjxevKAaI6IXrJmUc= github.com/klauspost/compress v1.17.11/go.mod h1:pMDklpSncoRMuLFrf1W9Ss9KT+0rH90U12bZKk7uwG0= github.com/klauspost/cpuid/v2 v2.2.9 h1:66ze0taIn2H33fBvCkXuv9BmCwDfafmiIVpKV9kKGuY= @@ -20,6 +16,7 @@ github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mattn/go-sqlite3 v1.14.24 h1:tpSp2G2KyMnnQu99ngJ47EIkWVmliIizyZBfPrBWDRM= @@ -34,12 +31,16 @@ github.com/multiformats/go-varint v0.0.7 h1:sWSGR+f/eu5ABZA2ZpYKBILXTTs9JWpdEM/n github.com/multiformats/go-varint v0.0.7/go.mod h1:r8PUYw/fD/SjBCiKOoDlGF6QawOELpZAu9eioSos/OU= github.com/nix-community/go-nix v0.0.0-20241207090453-00891a7727c2 h1:KVBAi/cviLGNx7EjhPog1a9dYVvmoI4Ha+ullP4Z5TI= github.com/nix-community/go-nix v0.0.0-20241207090453-00891a7727c2/go.mod h1:qgCw4bBKZX8qMgGeEZzGFVT3notl42dBjNqO2jut0M0= +github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/prashantv/gostub v1.1.0 h1:BTyx3RfQjRHnUWaGF9oQos79AlQ5k8WNktv7VGvVH4g= github.com/prashantv/gostub v1.1.0/go.mod h1:A5zLQHz7ieHGG7is6LLXLz7I8+3LZzsrV0P1IAHhP5U= github.com/robfig/cron/v3 v3.0.1 h1:WdRxkvbJztn8LMz/QEvLN5sBU+xKpSqwwUO1Pjr4qDs= github.com/robfig/cron/v3 v3.0.1/go.mod h1:eQICP3HwyT7UooqI/z+Ov+PtYAWygg1TEWWzGIFLtro= +github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8= +github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= github.com/spaolacci/murmur3 v1.1.0 h1:7c1g84S4BPRrfL5Xrdp6fOJ206sU9y293DDHaoy0bLI= github.com/spaolacci/murmur3 v1.1.0/go.mod h1:JwIasOWyU6f++ZhiEuf87xNszmSA2myDM2Kzu9HwQUA= github.com/stretchr/testify v1.10.0 h1:Xv5erBjTwe/5IxqUQTdXv5kgmIvbHo3QQyRwhJsOfJA= @@ -54,6 +55,7 @@ golang.org/x/sync v0.10.0 h1:3NQrjDixjgGwUOCaF8w2+VYHv0Ve/vGYSbdkTa98gmQ= golang.org/x/sync v0.10.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk= golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA= golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/term v0.27.0 h1:WP60Sv1nlK1T6SupCHbXzSaN0b9wUmsPoRS9b61A23Q= diff --git a/main.go b/main.go index 7a695d7..839c8c4 100644 --- a/main.go +++ b/main.go @@ -2,11 +2,12 @@ package main import ( "context" + "io" "log" "os" + "time" - "github.com/inconshreveable/log15/v3" - "github.com/mattn/go-colorable" + "github.com/rs/zerolog" "golang.org/x/term" "github.com/kalbasit/ncps/cmd" @@ -17,14 +18,7 @@ func main() { } func realMain() int { - logger := log15.New() - if term.IsTerminal(int(os.Stdout.Fd())) { - logger.SetHandler(log15.StreamHandler(colorable.NewColorableStdout(), log15.TerminalFormat())) - } else { - logger.SetHandler(log15.StreamHandler(os.Stdout, log15.JsonFormat())) - } - - c := cmd.New(logger) + c := cmd.New(newLogger()) if err := c.Run(context.Background(), os.Args); err != nil { log.Printf("error running the application: %s", err) @@ -34,3 +28,13 @@ func realMain() int { return 0 } + +func newLogger() zerolog.Logger { + var output io.Writer = os.Stdout + + if term.IsTerminal(int(os.Stdout.Fd())) { + output = zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339} + } + + return zerolog.New(output) +} diff --git a/nix/packages/ncps.nix b/nix/packages/ncps.nix index dad4bc0..31582c3 100644 --- a/nix/packages/ncps.nix +++ b/nix/packages/ncps.nix @@ -38,7 +38,7 @@ subPackages = [ "." ]; - vendorHash = "sha256-4X1wJ1v+GZchw4vzjd1U+llBXyYLMBHHWBccap5Mdn4="; + vendorHash = "sha256-RN64hl8Cy15gBpLXQX46VNhxbwf5PutFshcymEuudqA="; doCheck = true; diff --git a/pkg/cache/cache.go b/pkg/cache/cache.go index d6b2bad..17216a7 100644 --- a/pkg/cache/cache.go +++ b/pkg/cache/cache.go @@ -16,11 +16,11 @@ import ( "sync" "time" - "github.com/inconshreveable/log15/v3" "github.com/mattn/go-sqlite3" "github.com/nix-community/go-nix/pkg/narinfo" "github.com/nix-community/go-nix/pkg/narinfo/signature" "github.com/robfig/cron/v3" + "github.com/rs/zerolog" "github.com/kalbasit/ncps/pkg/cache/upstream" "github.com/kalbasit/ncps/pkg/database" @@ -65,7 +65,7 @@ const recordAgeIgnoreTouch = 5 * time.Minute // Cache represents the main cache service. type Cache struct { hostName string - logger log15.Logger + logger zerolog.Logger path string secretKey signature.SecretKey upstreamCaches []upstream.Cache @@ -91,7 +91,7 @@ type Cache struct { } // New returns a new Cache. -func New(logger log15.Logger, hostName, cachePath string) (*Cache, error) { +func New(logger zerolog.Logger, hostName, cachePath string) (*Cache, error) { c := &Cache{ logger: logger, upstreamJobs: make(map[string]chan struct{}), @@ -128,10 +128,15 @@ func (c *Cache) AddUpstreamCaches(ucs ...upstream.Cache) { return int(a.GetPriority() - b.GetPriority()) }) - c.logger.Info("the order of upstream caches has been determined by priority to be") + c.logger.Info().Msg("the order of upstream caches has been determined by priority to be") for idx, uc := range ucss { - c.logger.Info("upstream cache", "idx", idx, "hostname", uc.GetHostname(), "priority", uc.GetPriority()) + c.logger. + Info(). + Int("idx", idx). + Str("hostname", uc.GetHostname()). + Uint64("priority", uc.GetPriority()). + Msg("upstream cache") } c.upstreamCaches = ucss @@ -150,19 +155,21 @@ func (c *Cache) SetupCron(timezone *time.Location) { c.cron = cron.New(opts...) - c.logger.Info("cron setup complete") + c.logger.Info().Msg("cron setup complete") } // AddLRUCronJob adds a job for LRU. func (c *Cache) AddLRUCronJob(schedule cron.Schedule) { - c.logger.Info("adding a cronjob for LRU", "next-run", schedule.Next(time.Now())) + c.logger.Info(). + Time("next-run", schedule.Next(time.Now())). + Msg("adding a cronjob for LRU") c.cron.Schedule(schedule, cron.FuncJob(c.runLRU)) } // StartCron starts the cron scheduler in its own go-routine, or no-op if already started. func (c *Cache) StartCron() { - c.logger.Info("starting the cron scheduler") + c.logger.Info().Msg("starting the cron scheduler") c.cron.Start() } @@ -193,7 +200,7 @@ func (c *Cache) GetNar(ctx context.Context, narURL nar.URL) (int64, io.ReadClose doneC := c.prePullNar(log, &narURL, nil, nil, false) - log.Debug("pulling nar in a go-routing and will wait for it") + log.Debug().Msg("pulling nar in a go-routing and will wait for it") <-doneC if !c.hasNarInStore(log, &narURL) { @@ -233,7 +240,7 @@ func (c *Cache) DeleteNar(_ context.Context, narURL nar.URL) error { } func (c *Cache) pullNar( - log log15.Logger, + log zerolog.Logger, narURL *nar.URL, uc *upstream.Cache, narInfo *narinfo.NarInfo, @@ -250,11 +257,13 @@ func (c *Cache) pullNar( now := time.Now() - log.Info("downloading the nar from upstream") + log.Info().Msg("downloading the nar from upstream") resp, err := c.getNarFromUpstream(log, narURL, uc, narInfo, enableZSTD) if err != nil { - log.Error("error getting the narInfo from upstream caches", "error", err) + log.Error(). + Err(err). + Msg("error getting the narInfo from upstream caches") done() @@ -270,7 +279,7 @@ func (c *Cache) pullNar( written, err := c.putNarInStore(log, narURL, resp.Body) if err != nil { - log.Error("error storing the narInfo in the store", "error", err) + log.Error().Err(err).Msg("error storing the narInfo in the store") done() @@ -281,7 +290,7 @@ func (c *Cache) pullNar( narInfo.FileSize = uint64(written) } - log.Info("download of nar complete", "elapsed", time.Since(now)) + log.Info().Dur("elapsed", time.Since(now)).Msg("download of nar complete") done() } @@ -294,13 +303,13 @@ func (c *Cache) getNarInfoPathInStore(hash string) string { return filepath.Join(c.storeNarInfoPath(), helper.NarInfoFilePath(hash)) } -func (c *Cache) hasNarInStore(log log15.Logger, narURL *nar.URL) bool { +func (c *Cache) hasNarInStore(log zerolog.Logger, narURL *nar.URL) bool { return c.hasInStore(log, c.getNarPathInStore(narURL)) } func (c *Cache) getNarFromStore( ctx context.Context, - log log15.Logger, + log zerolog.Logger, narURL *nar.URL, ) (int64, io.ReadCloser, error) { size, r, err := c.getFromStore(log, c.getNarPathInStore(narURL)) @@ -316,7 +325,7 @@ func (c *Cache) getNarFromStore( defer func() { if err := tx.Rollback(); err != nil { if !errors.Is(err, sql.ErrTxDone) { - log.Error("error rolling back the transaction", "error", err) + log.Error().Err(err).Msg("error rolling back the transaction") } } }() @@ -345,7 +354,7 @@ func (c *Cache) getNarFromStore( } func (c *Cache) getNarFromUpstream( - log log15.Logger, + log zerolog.Logger, narURL *nar.URL, uc *upstream.Cache, narInfo *narinfo.NarInfo, @@ -379,7 +388,10 @@ func (c *Cache) getNarFromUpstream( resp, err := uc.GetNar(ctx, *narURL, mutators...) if err != nil { if !errors.Is(err, upstream.ErrNotFound) { - log.Error("error fetching the narInfo from upstream", "hostname", uc.GetHostname(), "error", err) + log.Error(). + Err(err). + Str("hostname", uc.GetHostname()). + Msg("error fetching the narInfo from upstream") } continue @@ -391,7 +403,7 @@ func (c *Cache) getNarFromUpstream( return nil, ErrNotFound } -func (c *Cache) putNarInStore(_ log15.Logger, narURL *nar.URL, r io.ReadCloser) (int64, error) { +func (c *Cache) putNarInStore(_ zerolog.Logger, narURL *nar.URL, r io.ReadCloser) (int64, error) { pattern := narURL.Hash + "-*.nar" if cext := narURL.Compression.String(); cext != "" { pattern += "." + cext @@ -427,7 +439,7 @@ func (c *Cache) putNarInStore(_ log15.Logger, narURL *nar.URL, r io.ReadCloser) return written, nil } -func (c *Cache) deleteNarFromStore(log log15.Logger, narURL *nar.URL) error { +func (c *Cache) deleteNarFromStore(log zerolog.Logger, narURL *nar.URL) error { if !c.hasNarInStore(log, narURL) { return ErrNotFound } @@ -450,7 +462,7 @@ func (c *Cache) GetNarInfo(ctx context.Context, hash string) (*narinfo.NarInfo, c.mu.RLock() defer c.mu.RUnlock() - log := c.logger.New("hash", hash) + log := c.logger.With().Str("hash", hash).Logger() var ( narInfo *narinfo.NarInfo @@ -468,7 +480,7 @@ func (c *Cache) GetNarInfo(ctx context.Context, hash string) (*narinfo.NarInfo, doneC := c.prePullNarInfo(log, hash) - log.Debug("pulling nar in a go-routing and will wait for it") + log.Debug().Msg("pulling nar in a go-routing and will wait for it") <-doneC if !c.hasNarInfoInStore(log, hash) { @@ -479,7 +491,7 @@ func (c *Cache) GetNarInfo(ctx context.Context, hash string) (*narinfo.NarInfo, } func (c *Cache) pullNarInfo( - log log15.Logger, + log zerolog.Logger, hash string, doneC chan struct{}, ) { @@ -495,7 +507,7 @@ func (c *Cache) pullNarInfo( uc, narInfo, err := c.getNarInfoFromUpstream(log, hash) if err != nil { - log.Error("error getting the narInfo from upstream caches", "error", err) + log.Error().Err(err).Msg("error getting the narInfo from upstream caches") done() @@ -504,7 +516,7 @@ func (c *Cache) pullNarInfo( narURL, err := nar.ParseURL(narInfo.URL) if err != nil { - log.Error("error parsing the nar URL", "nar-url", narInfo.URL, "error", err) + log.Error().Err(err).Str("nar-url", narInfo.URL).Msg("error parsing the nar URL") done() @@ -517,7 +529,7 @@ func (c *Cache) pullNarInfo( enableZSTD = true } - log = log.New("zstd-support", enableZSTD) + log = log.With().Bool("zstd-support", enableZSTD).Logger() // start a job to also pull the nar but don't wait for it to cme back narDoneC := c.prePullNar(log, &narURL, uc, narInfo, enableZSTD) @@ -530,7 +542,7 @@ func (c *Cache) pullNarInfo( } if err := c.signNarInfo(log, narInfo); err != nil { - log.Error("error signing the narinfo", "error", err) + log.Error().Err(err).Msg("error signing the narinfo") done() @@ -538,7 +550,7 @@ func (c *Cache) pullNarInfo( } if err := c.putNarInfoInStore(log, hash, narInfo); err != nil { - log.Error("error storing the narInfo in the store", "error", err) + log.Error().Err(err).Msg("error storing the narInfo in the store") done() @@ -546,14 +558,14 @@ func (c *Cache) pullNarInfo( } if err := c.storeInDatabase(log, hash, narInfo); err != nil { - log.Error("error storing the narinfo in the database", "error", err) + log.Error().Err(err).Msg("error storing the narinfo in the database") done() return } - log.Info("download of narinfo complete", "elapsed", time.Since(now)) + log.Info().Dur("elapsed", time.Since(now)).Msg("download of narinfo complete") done() } @@ -570,7 +582,7 @@ func (c *Cache) PutNarInfo(_ context.Context, hash string, r io.ReadCloser) erro r.Close() }() - log := c.logger.New("hash", hash) + log := c.logger.With().Str("hash", hash).Logger() narInfo, err := narinfo.Parse(r) if err != nil { @@ -593,17 +605,17 @@ func (c *Cache) DeleteNarInfo(ctx context.Context, hash string) error { c.mu.RLock() defer c.mu.RUnlock() - log := c.logger.New("hash", hash) + log := c.logger.With().Str("hash", hash).Logger() return c.deleteNarInfoFromStore(ctx, log, hash) } -func (c *Cache) prePullNarInfo(log log15.Logger, hash string) chan struct{} { +func (c *Cache) prePullNarInfo(log zerolog.Logger, hash string) chan struct{} { c.muUpstreamJobs.Lock() doneC, ok := c.upstreamJobs[hash] if ok { - log.Info("waiting for an in-progress download of narinfo to finish") + log.Info().Msg("waiting for an in-progress download of narinfo to finish") } else { doneC = make(chan struct{}) c.upstreamJobs[hash] = doneC @@ -616,7 +628,7 @@ func (c *Cache) prePullNarInfo(log log15.Logger, hash string) chan struct{} { } func (c *Cache) prePullNar( - log log15.Logger, + log zerolog.Logger, narURL *nar.URL, uc *upstream.Cache, narInfo *narinfo.NarInfo, @@ -636,7 +648,7 @@ func (c *Cache) prePullNar( return doneC } -func (c *Cache) signNarInfo(_ log15.Logger, narInfo *narinfo.NarInfo) error { +func (c *Cache) signNarInfo(_ zerolog.Logger, narInfo *narinfo.NarInfo) error { var sigs []signature.Signature for _, sig := range narInfo.Signatures { @@ -657,11 +669,11 @@ func (c *Cache) signNarInfo(_ log15.Logger, narInfo *narinfo.NarInfo) error { return nil } -func (c *Cache) hasNarInfoInStore(log log15.Logger, hash string) bool { +func (c *Cache) hasNarInfoInStore(log zerolog.Logger, hash string) bool { return c.hasInStore(log, c.getNarInfoPathInStore(hash)) } -func (c *Cache) getNarInfoFromStore(ctx context.Context, log log15.Logger, hash string) (*narinfo.NarInfo, error) { +func (c *Cache) getNarInfoFromStore(ctx context.Context, log zerolog.Logger, hash string) (*narinfo.NarInfo, error) { _, r, err := c.getFromStore(log, c.getNarInfoPathInStore(hash)) if err != nil { return nil, fmt.Errorf("error fetching the narinfo from the store: %w", err) @@ -676,11 +688,14 @@ func (c *Cache) getNarInfoFromStore(ctx context.Context, log log15.Logger, hash narURL, err := nar.ParseURL(ni.URL) if err != nil { - log.Error("error parsing the nar-url", "nar-url", ni.URL, "error", err) + log.Error(). + Err(err). + Str("nar-url", ni.URL). + Msg("error parsing the nar-url") // narinfo is invalid, remove it if err := c.purgeNarInfo(ctx, log, hash, &narURL); err != nil { - log.Error("error purging the narinfo", "error", err) + log.Error().Err(err).Msg("error purging the narinfo") } return nil, errNarInfoPurged @@ -689,7 +704,7 @@ func (c *Cache) getNarInfoFromStore(ctx context.Context, log log15.Logger, hash log = narURL.NewLogger(log) if !c.hasNarInStore(log, &narURL) && !c.hasUpstreamJob(narURL.Hash) { - log.Error("narinfo was requested but no nar was found requesting a purge") + log.Error().Msg("narinfo was requested but no nar was found requesting a purge") if err := c.purgeNarInfo(ctx, log, hash, &narURL); err != nil { return nil, fmt.Errorf("error purging the narinfo: %w", err) @@ -706,7 +721,7 @@ func (c *Cache) getNarInfoFromStore(ctx context.Context, log log15.Logger, hash defer func() { if err := tx.Rollback(); err != nil { if !errors.Is(err, sql.ErrTxDone) { - log.Error("error rolling back the transaction", "error", err) + log.Error().Err(err).Msg("error rolling back the transaction") } } }() @@ -734,7 +749,7 @@ func (c *Cache) getNarInfoFromStore(ctx context.Context, log log15.Logger, hash return ni, nil } -func (c *Cache) getNarInfoFromUpstream(log log15.Logger, hash string) (*upstream.Cache, *narinfo.NarInfo, error) { +func (c *Cache) getNarInfoFromUpstream(log zerolog.Logger, hash string) (*upstream.Cache, *narinfo.NarInfo, error) { // create a new context not associated with any request because we don't want // downstream HTTP request to cancel this. ctx := context.Background() @@ -743,7 +758,10 @@ func (c *Cache) getNarInfoFromUpstream(log log15.Logger, hash string) (*upstream narInfo, err := uc.GetNarInfo(ctx, hash) if err != nil { if !errors.Is(err, upstream.ErrNotFound) { - log.Error("error fetching the narInfo from upstream", "hostname", uc.GetHostname(), "error", err) + log.Error(). + Err(err). + Str("hostname", uc.GetHostname()). + Msg("error fetching the narInfo from upstream") } continue @@ -755,7 +773,7 @@ func (c *Cache) getNarInfoFromUpstream(log log15.Logger, hash string) (*upstream return nil, nil, ErrNotFound } -func (c *Cache) purgeNarInfo(ctx context.Context, log log15.Logger, hash string, narURL *nar.URL) error { +func (c *Cache) purgeNarInfo(ctx context.Context, log zerolog.Logger, hash string, narURL *nar.URL) error { tx, err := c.db.DB().Begin() if err != nil { return fmt.Errorf("error beginning a transaction: %w", err) @@ -764,7 +782,7 @@ func (c *Cache) purgeNarInfo(ctx context.Context, log log15.Logger, hash string, defer func() { if err := tx.Rollback(); err != nil { if !errors.Is(err, sql.ErrTxDone) { - log.Error("error rolling back the transaction", "error", err) + log.Error().Err(err).Msg("error rolling back the transaction") } } }() @@ -800,7 +818,7 @@ func (c *Cache) purgeNarInfo(ctx context.Context, log log15.Logger, hash string, return nil } -func (c *Cache) putNarInfoInStore(_ log15.Logger, hash string, narInfo *narinfo.NarInfo) error { +func (c *Cache) putNarInfoInStore(_ zerolog.Logger, hash string, narInfo *narinfo.NarInfo) error { f, err := os.CreateTemp(c.storeTMPPath(), hash+"-*.narinfo") if err != nil { return fmt.Errorf("error creating the temporary directory: %w", err) @@ -830,14 +848,14 @@ func (c *Cache) putNarInfoInStore(_ log15.Logger, hash string, narInfo *narinfo. return nil } -func (c *Cache) storeInDatabase(log log15.Logger, hash string, narInfo *narinfo.NarInfo) error { +func (c *Cache) storeInDatabase(log zerolog.Logger, hash string, narInfo *narinfo.NarInfo) error { // create a new context not associated with any request because we don't want // downstream HTTP request to cancel this. ctx := context.Background() - log = log.New("nar-url", narInfo.URL) + log = log.With().Str("nar-url", narInfo.URL).Logger() - log.Info("storing narinfo and nar record in the database") + log.Info().Msg("storing narinfo and nar record in the database") tx, err := c.db.DB().Begin() if err != nil { @@ -847,7 +865,7 @@ func (c *Cache) storeInDatabase(log log15.Logger, hash string, narInfo *narinfo. defer func() { if err := tx.Rollback(); err != nil { if !errors.Is(err, sql.ErrTxDone) { - log.Error("error rolling back the transaction", "error", err) + log.Error().Err(err).Msg("error rolling back the transaction") } } }() @@ -855,7 +873,7 @@ func (c *Cache) storeInDatabase(log log15.Logger, hash string, narInfo *narinfo. nir, err := c.db.WithTx(tx).CreateNarInfo(ctx, hash) if err != nil { if database.ErrorIsNo(err, sqlite3.ErrConstraint) { - log.Warn("narinfo record was not added to database because it already exists") + log.Warn().Msg("narinfo record was not added to database because it already exists") return nil } @@ -877,7 +895,7 @@ func (c *Cache) storeInDatabase(log log15.Logger, hash string, narInfo *narinfo. }) if err != nil { if database.ErrorIsNo(err, sqlite3.ErrConstraint) { - log.Warn("nar record was not added to database because it already exists") + log.Warn().Msg("nar record was not added to database because it already exists") return nil } @@ -892,7 +910,7 @@ func (c *Cache) storeInDatabase(log log15.Logger, hash string, narInfo *narinfo. return nil } -func (c *Cache) deleteNarInfoFromStore(ctx context.Context, log log15.Logger, hash string) error { +func (c *Cache) deleteNarInfoFromStore(ctx context.Context, log zerolog.Logger, hash string) error { if !c.hasNarInfoInStore(log, hash) { return ErrNotFound } @@ -904,7 +922,7 @@ func (c *Cache) deleteNarInfoFromStore(ctx context.Context, log log15.Logger, ha return os.Remove(c.getNarInfoPathInStore(hash)) } -func (c *Cache) hasInStore(_ log15.Logger, path string) bool { +func (c *Cache) hasInStore(_ zerolog.Logger, path string) bool { _, err := os.Stat(path) return err == nil @@ -912,7 +930,7 @@ func (c *Cache) hasInStore(_ log15.Logger, path string) bool { // GetFile returns the file define by its key // NOTE: It's the caller responsibility to close the file after using it. -func (c *Cache) getFromStore(_ log15.Logger, path string) (int64, io.ReadCloser, error) { +func (c *Cache) getFromStore(_ zerolog.Logger, path string) (int64, io.ReadCloser, error) { f, err := os.Open(path) if err != nil { return 0, nil, fmt.Errorf("error opening the file %q: %w", path, err) @@ -928,26 +946,32 @@ func (c *Cache) getFromStore(_ log15.Logger, path string) (int64, io.ReadCloser, func (c *Cache) validateHostname(hostName string) error { if hostName == "" { - c.logger.Error("given hostname is empty", "hostName", hostName) + c.logger.Error().Str("hostName", hostName).Msg("given hostname is empty") return ErrHostnameRequired } u, err := url.Parse(hostName) if err != nil { - c.logger.Error("failed to parse the hostname", "hostName", hostName, "error", err) + c.logger.Error(). + Err(err). + Str("hostName", hostName). + Msg("failed to parse the hostname") return fmt.Errorf("error parsing the hostName %q: %w", hostName, err) } if u.Scheme != "" { - c.logger.Error("hostname should not contain a scheme", "hostName", hostName, "scheme", u.Scheme) + c.logger.Error(). + Str("hostName", hostName). + Str("scheme", u.Scheme). + Msg("hostname should not contain a scheme") return ErrHostnameMustNotContainScheme } if strings.Contains(hostName, "/") { - c.logger.Error("hostname should not contain a path", "hostName", hostName) + c.logger.Error().Str("hostName", hostName).Msg("hostname should not contain a path") return ErrHostnameMustNotContainPath } @@ -957,20 +981,20 @@ func (c *Cache) validateHostname(hostName string) error { func (c *Cache) validatePath(cachePath string) error { if !filepath.IsAbs(cachePath) { - c.logger.Error("path is not absolute", "path", cachePath) + c.logger.Error().Str("path", cachePath).Msg("path is not absolute") return ErrPathMustBeAbsolute } info, err := os.Stat(cachePath) if errors.Is(err, fs.ErrNotExist) { - c.logger.Error("path does not exist", "path", cachePath) + c.logger.Error().Str("path", cachePath).Msg("path does not exist") return ErrPathMustExist } if !info.IsDir() { - c.logger.Error("path is not a directory", "path", cachePath) + c.logger.Error().Str("path", cachePath).Msg("path is not a directory") return ErrPathMustBeADirectory } @@ -985,7 +1009,10 @@ func (c *Cache) validatePath(cachePath string) error { func (c *Cache) isWritable(cachePath string) bool { tmpFile, err := os.CreateTemp(cachePath, "write_test") if err != nil { - c.logger.Error("error writing a temp file in the path", "path", cachePath, "error", err) + c.logger.Error(). + Err(err). + Str("path", cachePath). + Msg("error writing a temp file in the path") return false } @@ -1111,15 +1138,19 @@ func (c *Cache) runLRU() { c.mu.Lock() defer c.mu.Unlock() - log := c.logger.New("op", "lru", "max-size", c.maxSize) - log.Info("running LRU") + log := c.logger.With(). + Str("op", "lru"). + Uint64("max-size", c.maxSize). + Logger() + + log.Info().Msg("running LRU") // TODO: Possibly trickle ctx down ctx := context.Background() tx, err := c.db.DB().Begin() if err != nil { - log.Error("error beginning a transaction", "error", err) + log.Error().Err(err).Msg("error beginning a transaction") return } @@ -1127,75 +1158,84 @@ func (c *Cache) runLRU() { defer func() { if err := tx.Rollback(); err != nil { if !errors.Is(err, sql.ErrTxDone) { - log.Error("error rolling back the transaction", "error", err) + log.Error().Err(err).Msg("error rolling back the transaction") } } }() narTotalSize, err := c.db.WithTx(tx).GetNarTotalSize(ctx) if err != nil { - log.Error("error fetching the total nar size", "error", err) + log.Error().Err(err).Msg("error fetching the total nar size") return } if !narTotalSize.Valid { - log.Error("SUM(file_size) returned NULL") + log.Error().Msg("SUM(file_size) returned NULL") return } - log = log.New("nar-total-size", narTotalSize) + log = log.With().Float64("nar-total-size", narTotalSize.Float64).Logger() if uint64(narTotalSize.Float64) <= c.maxSize { - log.Info("store size is less than max-size, not removing any nars") + log.Info().Msg("store size is less than max-size, not removing any nars") return } cleanupSize := uint64(narTotalSize.Float64) - c.maxSize - log = log.New("cleanup-size", cleanupSize) + log = log.With().Uint64("cleanup-size", cleanupSize).Logger() - log.Info("going to remove nars") + log.Info().Msg("going to remove nars") nars, err := c.db.WithTx(tx).GetLeastUsedNars(ctx, cleanupSize) if err != nil { - log.Error("error getting the least used nars up to cleanup-size", "error", err) + log.Error().Err(err).Msg("error getting the least used nars up to cleanup-size") return } if len(nars) == 0 { - log.Warn("nars needed to be removed but none were returned in the query") + log.Warn().Msg("nars needed to be removed but none were returned in the query") return } - log.Info("found this many nars to remove", "count-nars", len(nars)) + log.Info().Int("count-nars", len(nars)).Msg("found this many nars to remove") filesToRemove := make([]string, 0, 2*len(nars)) for _, narRecord := range nars { narInfo, err := c.db.WithTx(tx).GetNarInfoByID(ctx, narRecord.NarInfoID) if err == nil { - log.Info("deleting narinfo record", "narinfo-hash", narInfo.Hash) + log.Info().Str("narinfo-hash", narInfo.Hash).Msg("deleting narinfo record") if _, err := c.db.WithTx(tx).DeleteNarInfoByHash(ctx, narInfo.Hash); err != nil { - log.Error("error removing narinfo from database", "hash", narInfo.Hash, "error", err) + log.Error(). + Err(err). + Str("narinfo-hash", narInfo.Hash). + Msg("error removing narinfo from database") } filesToRemove = append(filesToRemove, c.getNarInfoPathInStore(narInfo.Hash), ) } else { - log.Error("error fetching narinfo from the database", "ID", narRecord.NarInfoID, "error", err) + log.Error(). + Err(err). + Int64("ID", narRecord.NarInfoID). + Msg("error fetching narinfo from the database") } - log.Info("deleting nar record", "nar-hash", narRecord.Hash) + log.Info().Str("nar-hash", narRecord.Hash).Msg("deleting nar record") if _, err := c.db.WithTx(tx).DeleteNarByHash(ctx, narRecord.Hash); err != nil { - log.Error("error removing nar from database", "hash", narRecord.Hash, "error", err) + log.Error(). + Err(err). + Str("hash", narRecord.Hash). + Msg("error removing nar from database") } filesToRemove = append(filesToRemove, @@ -1218,10 +1258,13 @@ func (c *Cache) runLRU() { go func() { defer wg.Done() - log.Info("deleting file from store", "path", f) + log.Info().Str("path", f).Msg("deleting file from store") if err := os.Remove(f); err != nil { - log.Error("error removing the file", "file-to-remove", f, "error", err) + log.Error(). + Err(err). + Str("file-to-remove", f). + Msg("error removing the file") } }() } @@ -1231,13 +1274,13 @@ func (c *Cache) runLRU() { // finally commit the database transaction if err := tx.Commit(); err != nil { - log.Error("error committing the transaction", "error", err) + log.Error().Err(err).Msg("error committing the transaction") } } -func zstdMutator(log log15.Logger, compression nar.CompressionType) func(r *http.Request) { +func zstdMutator(log zerolog.Logger, compression nar.CompressionType) func(r *http.Request) { return func(r *http.Request) { - log.Debug("narinfo compress is none will set Accept-Encoding to zstd") + log.Debug().Msg("narinfo compress is none will set Accept-Encoding to zstd") r.Header.Set("Accept-Encoding", "zstd") diff --git a/pkg/cache/cache_internal_test.go b/pkg/cache/cache_internal_test.go index 825dcff..51279a7 100644 --- a/pkg/cache/cache_internal_test.go +++ b/pkg/cache/cache_internal_test.go @@ -4,6 +4,7 @@ import ( "context" "database/sql" "fmt" + "io" "math/rand/v2" "os" "path/filepath" @@ -11,7 +12,7 @@ import ( "testing" "time" - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -22,12 +23,7 @@ import ( ) //nolint:gochecknoglobals -var logger = log15.New() - -//nolint:gochecknoinits -func init() { - logger.SetHandler(log15.DiscardHandler()) -} +var logger = zerolog.New(io.Discard) func TestAddUpstreamCaches(t *testing.T) { t.Run("upstream caches added at once", func(t *testing.T) { diff --git a/pkg/cache/cache_test.go b/pkg/cache/cache_test.go index 5e5db98..93d2327 100644 --- a/pkg/cache/cache_test.go +++ b/pkg/cache/cache_test.go @@ -13,10 +13,10 @@ import ( "testing" "time" - "github.com/inconshreveable/log15/v3" "github.com/klauspost/compress/zstd" "github.com/nix-community/go-nix/pkg/narinfo" "github.com/nix-community/go-nix/pkg/narinfo/signature" + "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -34,12 +34,7 @@ import ( const cacheName = "cache.example.com" //nolint:gochecknoglobals -var logger = log15.New() - -//nolint:gochecknoinits -func init() { - logger.SetHandler(log15.DiscardHandler()) -} +var logger = zerolog.New(io.Discard) func TestNew(t *testing.T) { t.Parallel() diff --git a/pkg/cache/upstream/cache.go b/pkg/cache/upstream/cache.go index 6516bd7..d467938 100644 --- a/pkg/cache/upstream/cache.go +++ b/pkg/cache/upstream/cache.go @@ -9,9 +9,9 @@ import ( "net/url" "time" - "github.com/inconshreveable/log15/v3" "github.com/nix-community/go-nix/pkg/narinfo" "github.com/nix-community/go-nix/pkg/narinfo/signature" + "github.com/rs/zerolog" "github.com/kalbasit/ncps/pkg/helper" "github.com/kalbasit/ncps/pkg/nar" @@ -42,12 +42,12 @@ var ( type Cache struct { httpClient *http.Client url *url.URL - logger log15.Logger + logger zerolog.Logger priority uint64 publicKeys []signature.PublicKey } -func New(logger log15.Logger, u *url.URL, pubKeys []string) (Cache, error) { +func New(logger zerolog.Logger, u *url.URL, pubKeys []string) (Cache, error) { c := Cache{} if u == nil { @@ -56,7 +56,9 @@ func New(logger log15.Logger, u *url.URL, pubKeys []string) (Cache, error) { c.url = u - c.logger = logger.New("upstream-url", u.String()) + c.logger = logger.With(). + Str("upstream-url", u.String()). + Logger() if err := c.validateURL(u); err != nil { return c, err @@ -113,7 +115,11 @@ func (c Cache) GetNarInfo(ctx context.Context, hash string) (*narinfo.NarInfo, e return nil, ErrNotFound } - c.logger.Error(ErrUnexpectedHTTPStatusCode.Error(), "status_code", resp.StatusCode) + c.logger. + Error(). + Err(ErrUnexpectedHTTPStatusCode). + Int("status_code", resp.StatusCode). + Send() return nil, ErrUnexpectedHTTPStatusCode } @@ -150,9 +156,9 @@ func (c Cache) GetNar(ctx context.Context, narURL nar.URL, mutators ...func(*htt mutator(r) } - log := narURL.NewLogger(c.logger.New("nar-url", u)) + log := narURL.NewLogger(c.logger.With().Str("nar-url", u).Logger()) - log.Info("download the nar from upstream") + log.Info().Msg("download the nar from upstream") resp, err := c.httpClient.Do(r) if err != nil { @@ -167,7 +173,11 @@ func (c Cache) GetNar(ctx context.Context, narURL nar.URL, mutators ...func(*htt return nil, ErrNotFound } - log.Error(ErrUnexpectedHTTPStatusCode.Error(), "status_code", resp.StatusCode) + log. + Error(). + Err(ErrUnexpectedHTTPStatusCode). + Int("status_code", resp.StatusCode). + Send() return nil, ErrUnexpectedHTTPStatusCode } @@ -198,7 +208,10 @@ func (c Cache) parsePriority() (uint64, error) { defer resp.Body.Close() if resp.StatusCode != http.StatusOK { - c.logger.Error(ErrUnexpectedHTTPStatusCode.Error(), "status_code", resp.StatusCode) + c.logger.Error(). + Err(ErrUnexpectedHTTPStatusCode). + Int("status_code", resp.StatusCode). + Send() return 0, ErrUnexpectedHTTPStatusCode } @@ -213,13 +226,15 @@ func (c Cache) parsePriority() (uint64, error) { func (c Cache) validateURL(u *url.URL) error { if u == nil { - c.logger.Error("given url is nil", "url", u) + c.logger.Error().Msg("given url is nil") return ErrURLRequired } if u.Scheme == "" { - c.logger.Error("hostname should not contain a scheme", "url", u) + c.logger.Error(). + Str("url", u.String()). + Msg("hostname should not contain a scheme") return ErrURLMustContainScheme } diff --git a/pkg/cache/upstream/cache_test.go b/pkg/cache/upstream/cache_test.go index a4d328c..940945a 100644 --- a/pkg/cache/upstream/cache_test.go +++ b/pkg/cache/upstream/cache_test.go @@ -7,7 +7,7 @@ import ( "strings" "testing" - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -19,12 +19,7 @@ import ( ) //nolint:gochecknoglobals -var logger = log15.New() - -//nolint:gochecknoinits -func init() { - logger.SetHandler(log15.DiscardHandler()) -} +var logger = zerolog.New(io.Discard) func TestNew(t *testing.T) { t.Parallel() diff --git a/pkg/database/query_test.go b/pkg/database/query_test.go index 192b8e2..c98a0b4 100644 --- a/pkg/database/query_test.go +++ b/pkg/database/query_test.go @@ -11,7 +11,6 @@ import ( "testing" "time" - "github.com/inconshreveable/log15/v3" "github.com/mattn/go-sqlite3" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -23,14 +22,6 @@ import ( "github.com/kalbasit/ncps/testhelper" ) -//nolint:gochecknoglobals -var logger = log15.New() - -//nolint:gochecknoinits -func init() { - logger.SetHandler(log15.DiscardHandler()) -} - func TestGetNarInfoByHash(t *testing.T) { t.Parallel() diff --git a/pkg/nar/url.go b/pkg/nar/url.go index d8ba876..4b1723f 100644 --- a/pkg/nar/url.go +++ b/pkg/nar/url.go @@ -7,7 +7,7 @@ import ( "regexp" "strings" - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "github.com/kalbasit/ncps/pkg/helper" ) @@ -56,12 +56,12 @@ func ParseURL(u string) (URL, error) { } // NewLogger returns a new logger with the right fields. -func (u URL) NewLogger(log log15.Logger) log15.Logger { - return log.New( - "hash", u.Hash, - "compression", u.Compression, - "query", u.Query.Encode(), - ) +func (u URL) NewLogger(log zerolog.Logger) zerolog.Logger { + return log.With(). + Str("hash", u.Hash). + Str("compression", u.Compression.String()). + Str("query", u.Query.Encode()). + Logger() } // JoinURL returns a new URL combined with the given URL. diff --git a/pkg/server/server.go b/pkg/server/server.go index 747c61a..4c605af 100644 --- a/pkg/server/server.go +++ b/pkg/server/server.go @@ -3,7 +3,6 @@ package server import ( "encoding/json" "errors" - "fmt" "io" "net/http" "strconv" @@ -11,7 +10,7 @@ import ( "github.com/go-chi/chi/v5" "github.com/go-chi/chi/v5/middleware" - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "github.com/kalbasit/ncps/pkg/cache" "github.com/kalbasit/ncps/pkg/nar" @@ -38,7 +37,7 @@ Priority: 10` // Server represents the main HTTP server. type Server struct { cache *cache.Cache - logger log15.Logger + logger zerolog.Logger router *chi.Mux deletePermitted bool @@ -46,7 +45,7 @@ type Server struct { } // New returns a new server. -func New(logger log15.Logger, cache *cache.Cache) *Server { +func New(logger zerolog.Logger, cache *cache.Cache) *Server { s := &Server{ cache: cache, logger: logger, @@ -95,7 +94,7 @@ func (s *Server) createRouter() { s.router.Delete(routeNar, s.deleteNar) } -func requestLogger(logger log15.Logger) func(handler http.Handler) http.Handler { +func requestLogger(logger zerolog.Logger) func(handler http.Handler) http.Handler { return func(next http.Handler) http.Handler { fn := func(w http.ResponseWriter, r *http.Request) { startedAt := time.Now() @@ -104,21 +103,23 @@ func requestLogger(logger log15.Logger) func(handler http.Handler) http.Handler ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) defer func() { - entries := []interface{}{ - "status", ww.Status(), - "elapsed", time.Since(startedAt), - "from", r.RemoteAddr, - "reqID", reqID, - } + logger.With(). + Str("method", r.Method). + Str("request-uri", r.RequestURI). + Int("status", ww.Status()). + Dur("elapsed", time.Since(startedAt)). + Str("from", r.RemoteAddr). + Str("reqID", reqID). + Logger() switch r.Method { case http.MethodHead, http.MethodGet: - entries = append(entries, "bytes", ww.BytesWritten()) + logger = logger.With().Int("bytes", ww.BytesWritten()).Logger() case http.MethodPost, http.MethodPut, http.MethodPatch: - entries = append(entries, "bytes", r.ContentLength) + logger = logger.With().Int64("bytes", r.ContentLength).Logger() } - logger.Info(fmt.Sprintf("%s %s", r.Method, r.RequestURI), entries...) + logger.Info().Msg("handled request") }() next.ServeHTTP(ww, r) @@ -141,13 +142,13 @@ func (s *Server) getIndex(w http.ResponseWriter, _ *http.Request) { } if err := json.NewEncoder(w).Encode(body); err != nil { - s.logger.Error("error writing the body to the response", "error", err) + s.logger.Error().Err(err).Msg("error writing the body to the response") } } func (s *Server) getNixCacheInfo(w http.ResponseWriter, _ *http.Request) { if _, err := w.Write([]byte(nixCacheInfo)); err != nil { - s.logger.Error("error writing the response", "error", err) + s.logger.Error().Err(err).Msg("error writing the response") } } @@ -155,7 +156,7 @@ func (s *Server) getNarInfo(withBody bool) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { hash := chi.URLParam(r, "hash") - log := s.logger.New("hash", hash) + log := s.logger.With().Str("hash", hash).Logger() narInfo, err := s.cache.GetNarInfo(r.Context(), hash) if err != nil { @@ -163,17 +164,17 @@ func (s *Server) getNarInfo(withBody bool) http.HandlerFunc { w.WriteHeader(http.StatusNotFound) if _, err := w.Write([]byte(http.StatusText(http.StatusNotFound))); err != nil { - log.Error("error writing the response", "error", err) + log.Error().Err(err).Msg("error writing the response") } return } - log.Error("error fetching the narinfo", "error", err) + log.Error().Err(err).Msg("error fetching the narinfo") w.WriteHeader(http.StatusInternalServerError) if _, err := w.Write([]byte(http.StatusText(http.StatusInternalServerError) + " " + err.Error())); err != nil { - log.Error("error writing the response", "error", err) + log.Error().Err(err).Msg("error writing the response") } return @@ -192,7 +193,7 @@ func (s *Server) getNarInfo(withBody bool) http.HandlerFunc { } if _, err := w.Write(narInfoBytes); err != nil { - log.Error("error writing the narinfo to the response", "error", err) + log.Error().Err(err).Msg("error writing the narinfo to the response") } } } @@ -200,24 +201,24 @@ func (s *Server) getNarInfo(withBody bool) http.HandlerFunc { func (s *Server) putNarInfo(w http.ResponseWriter, r *http.Request) { hash := chi.URLParam(r, "hash") - log := s.logger.New("hash", hash) + log := s.logger.With().Str("hash", hash).Logger() if !s.putPermitted { w.WriteHeader(http.StatusMethodNotAllowed) if _, err := w.Write([]byte(http.StatusText(http.StatusMethodNotAllowed))); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return } if err := s.cache.PutNarInfo(r.Context(), hash, r.Body); err != nil { - log.Error("error putting the NAR in cache", "error", err) + log.Error().Err(err).Msg("error putting the NAR in cache") w.WriteHeader(http.StatusInternalServerError) if _, err := w.Write([]byte(http.StatusText(http.StatusInternalServerError) + " " + err.Error())); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -229,13 +230,13 @@ func (s *Server) putNarInfo(w http.ResponseWriter, r *http.Request) { func (s *Server) deleteNarInfo(w http.ResponseWriter, r *http.Request) { hash := chi.URLParam(r, "hash") - log := s.logger.New("hash", hash) + log := s.logger.With().Str("hash", hash).Logger() if !s.deletePermitted { w.WriteHeader(http.StatusMethodNotAllowed) if _, err := w.Write([]byte(http.StatusText(http.StatusMethodNotAllowed))); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -246,7 +247,7 @@ func (s *Server) deleteNarInfo(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusNotFound) if _, err := w.Write([]byte(http.StatusText(http.StatusNotFound))); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -255,7 +256,7 @@ func (s *Server) deleteNarInfo(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusInternalServerError) if _, err := w.Write([]byte(http.StatusText(http.StatusInternalServerError) + " " + err.Error())); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -279,7 +280,7 @@ func (s *Server) getNar(withBody bool) http.HandlerFunc { w.WriteHeader(http.StatusBadRequest) if _, err := w.Write([]byte(http.StatusText(http.StatusBadRequest))); err != nil { - log.Error("error computing the compression", "error", err) + log.Error().Err(err).Msg("error computing the compression") } return @@ -293,18 +294,18 @@ func (s *Server) getNar(withBody bool) http.HandlerFunc { w.WriteHeader(http.StatusNotFound) if _, err := w.Write([]byte(http.StatusText(http.StatusNotFound))); err != nil { - log.Error("error writing the response", "error", err) + log.Error().Err(err).Msg("error writing the response") } return } - log.Error("error fetching the nar", "error", err) + log.Error().Err(err).Msg("error fetching the nar") w.WriteHeader(http.StatusInternalServerError) if _, err := w.Write([]byte(http.StatusText(http.StatusInternalServerError) + " " + err.Error())); err != nil { - log.Error("error writing the response", "error", err) + log.Error().Err(err).Msg("error writing the response") } return @@ -322,13 +323,16 @@ func (s *Server) getNar(withBody bool) http.HandlerFunc { written, err := io.Copy(w, reader) if err != nil { - log.Error("error writing the response", "error", err) + log.Error().Err(err).Msg("error writing the response") return } if written != size { - log.Error("Bytes copied does not match object size", "expected", size, "written", written) + log.Error(). + Int64("expected", size). + Int64("written", written). + Msg("Bytes copied does not match object size") } } } @@ -347,7 +351,7 @@ func (s *Server) putNar(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusBadRequest) if _, err := w.Write([]byte(http.StatusText(http.StatusBadRequest))); err != nil { - log.Error("error computing the compression", "error", err) + log.Error().Err(err).Msg("error computing the compression") } return @@ -359,18 +363,18 @@ func (s *Server) putNar(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusMethodNotAllowed) if _, err := w.Write([]byte(http.StatusText(http.StatusMethodNotAllowed))); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return } if err := s.cache.PutNar(r.Context(), nu, r.Body); err != nil { - log.Error("error putting the NAR in cache", "error", err) + log.Error().Err(err).Msg("error putting the NAR in cache") w.WriteHeader(http.StatusInternalServerError) if _, err := w.Write([]byte(http.StatusText(http.StatusInternalServerError) + " " + err.Error())); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -393,7 +397,7 @@ func (s *Server) deleteNar(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusBadRequest) if _, err := w.Write([]byte(http.StatusText(http.StatusBadRequest))); err != nil { - log.Error("error computing the compression", "error", err) + log.Error().Err(err).Msg("error computing the compression") } return @@ -405,7 +409,7 @@ func (s *Server) deleteNar(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusMethodNotAllowed) if _, err := w.Write([]byte(http.StatusText(http.StatusMethodNotAllowed))); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -416,7 +420,7 @@ func (s *Server) deleteNar(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusNotFound) if _, err := w.Write([]byte(http.StatusText(http.StatusNotFound))); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return @@ -425,7 +429,7 @@ func (s *Server) deleteNar(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusInternalServerError) if _, err := w.Write([]byte(http.StatusText(http.StatusInternalServerError) + " " + err.Error())); err != nil { - log.Error("error writing the body to the response", "error", err) + log.Error().Err(err).Msg("error writing the body to the response") } return diff --git a/pkg/server/server_internal_test.go b/pkg/server/server_internal_test.go index c926219..82845ed 100644 --- a/pkg/server/server_internal_test.go +++ b/pkg/server/server_internal_test.go @@ -1,10 +1,11 @@ package server import ( + "io" "os" "testing" - "github.com/inconshreveable/log15/v3" + "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -12,12 +13,7 @@ import ( ) //nolint:gochecknoglobals -var logger = log15.New() - -//nolint:gochecknoinits -func init() { - logger.SetHandler(log15.DiscardHandler()) -} +var logger = zerolog.New(io.Discard) func TestSetDeletePermitted(t *testing.T) { dir, err := os.MkdirTemp("", "cache-path-") diff --git a/pkg/server/server_test.go b/pkg/server/server_test.go index e874b04..02ff0cc 100644 --- a/pkg/server/server_test.go +++ b/pkg/server/server_test.go @@ -11,9 +11,9 @@ import ( "strings" "testing" - "github.com/inconshreveable/log15/v3" "github.com/nix-community/go-nix/pkg/narinfo" "github.com/nix-community/go-nix/pkg/narinfo/signature" + "github.com/rs/zerolog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -27,12 +27,7 @@ import ( ) //nolint:gochecknoglobals -var logger = log15.New() - -//nolint:gochecknoinits -func init() { - logger.SetHandler(log15.DiscardHandler()) -} +var logger = zerolog.New(io.Discard) //nolint:paralleltest func TestServeHTTP(t *testing.T) {