switch to zerolog logging

Some places don't have access to the logger yet and need to be adjusted
or use a global logger somewhere

balancer/main.go

@@ -32,7 +32,7 @@ func NewBalancer(ctx context.Context, cfg config.Config) (*Balancer, error) {
 	const op errors.Op = "balancer/NewBalancer"
 
 	c := cfg.Conf()
-	ss, err := storage.Open(cfg)
+	ss, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return nil, errors.E(op, err)
 	}

cmd/hanyuu/database.go

@@ -18,6 +18,7 @@ import (
 	"github.com/R-a-dio/valkyrie/streamer/audio"
 	"github.com/R-a-dio/valkyrie/website/admin"
 	"github.com/google/subcommands"
+	"github.com/rs/zerolog"
 )
 
 type databaseCmd struct {
@@ -62,11 +63,15 @@ func (d *databaseCmd) Execute(ctx context.Context, f *flag.FlagSet, args ...any)
 		execute: withConfig(d.addUser),
 	}, "")
 
+	zerolog.Ctx(ctx).UpdateContext(func(zc zerolog.Context) zerolog.Context {
+		return zc.Str("service", d.Name())
+	})
+
 	return cmder.Execute(ctx, args...)
 }
 
 func (d databaseCmd) addTrack(ctx context.Context, cfg config.Config) error {
-	db, err := storage.Open(cfg)
+	db, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}
@@ -118,7 +123,7 @@ func (d databaseCmd) addTrack(ctx context.Context, cfg config.Config) error {
 }
 
 func (d databaseCmd) addUser(ctx context.Context, cfg config.Config) error {
-	db, err := storage.Open(cfg)
+	db, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}

cmd/hanyuu/elastic.go

@@ -84,7 +84,7 @@ func (e elasticCmd) indexSongs(ctx context.Context, cfg config.Config) error {
 		return err
 	}
 
-	store, err := storage.Open(cfg)
+	store, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}

cmd/hanyuu/main.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"flag"
 	"fmt"
-	"log"
 	"os"
 	"os/signal"
 	"runtime/debug"
@@ -20,6 +19,7 @@ import (
 	_ "github.com/R-a-dio/valkyrie/storage/mariadb" // mariadb storage interface
 	"github.com/R-a-dio/valkyrie/website"
 	"github.com/google/subcommands"
+	"github.com/rs/zerolog"
 )
 
 type executeFn func(context.Context, config.Loader) error
@@ -47,6 +47,10 @@ func (c cmd) Execute(ctx context.Context, f *flag.FlagSet, args ...interface{})
 	// because that is an unrecoverable programmer error
 	errCh := args[0].(chan error)
 
+	zerolog.Ctx(ctx).UpdateContext(func(zc zerolog.Context) zerolog.Context {
+		return zc.Str("service", c.name)
+	})
+
 	loader := func() (config.Config, error) {
 		return config.LoadFile(configFile, configEnvFile)
 	}
@@ -196,8 +200,12 @@ func main() {
 
 	// exit code passed to os.Exit
 	var code int
+	// setup logger
+	logger := zerolog.New(zerolog.ConsoleWriter{Out: os.Stdout}).With().Timestamp().Logger()
 	// setup root context
 	ctx := context.Background()
+	ctx = logger.WithContext(ctx)
+
 	// setup our error channel, we only use this channel if a nil error is returned by
 	// executeCommand; because if it is a non-nil error we know our cmd.Execute finished
 	// running; otherwise we have to wait for it to finish so we know it had the chance
@@ -219,7 +227,7 @@ func main() {
 		// normal non-nil error, we exit with the default failure exit code
 		code = 1
 		// print the error if it's a non-ExitError since it's probably important
-		fmt.Println(err)
+		logger.Fatal().Err(err).Msg("")
 	}
 
 	os.Exit(code)
@@ -260,10 +268,10 @@ func executeCommand(ctx context.Context, errCh chan error) error {
 
 		switch sig {
 		case os.Interrupt:
-			log.Printf("SIGINT received")
+			zerolog.Ctx(ctx).Info().Msg("SIGINT received")
 			return nil
 		case syscall.SIGHUP:
-			log.Printf("SIGHUP received: not implemented")
+			zerolog.Ctx(ctx).Info().Msg("SIGHUP received: not implemented")
 			// TODO: implement this
 		}
 	}

cmd/hanyuu/migrations.go

@@ -13,6 +13,7 @@ import (
 	"github.com/R-a-dio/valkyrie/errors"
 	"github.com/R-a-dio/valkyrie/migrations"
 	"github.com/R-a-dio/valkyrie/storage/mariadb"
+	"github.com/rs/zerolog"
 
 	"github.com/golang-migrate/migrate/v4"
 	mysqldriver "github.com/golang-migrate/migrate/v4/database/mysql"
@@ -92,6 +93,10 @@ func (m *migrateCmd) Execute(ctx context.Context, f *flag.FlagSet, args ...inter
 		execute: withConfig(m.ls),
 	}, "")
 
+	zerolog.Ctx(ctx).UpdateContext(func(zc zerolog.Context) zerolog.Context {
+		return zc.Str("service", "migrate")
+	})
+
 	return cmder.Execute(ctx, args...)
 }
 

go.mod

@@ -22,6 +22,10 @@ require (
 
 require (
 	github.com/golang/protobuf v1.5.3 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
+	github.com/rs/xid v1.5.0 // indirect
+	github.com/rs/zerolog v1.31.0 // indirect
 	golang.org/x/exp v0.0.0-20240119083558-1b970713d09a // indirect
 	golang.org/x/net v0.20.0 // indirect
 	golang.org/x/sys v0.16.0 // indirect

go.sum

@@ -10,6 +10,7 @@ github.com/alexedwards/scs/v2 v2.7.0 h1:DY4rqLCM7UIR9iwxFS0++z1NhTzQlKV30aMHkJCD
 github.com/alexedwards/scs/v2 v2.7.0/go.mod h1:ToaROZxyKukJKT/xLcVQAChi5k6+Pn1Gvmdl7h3RRj8=
 github.com/cenkalti/backoff v2.2.1+incompatible h1:tNowT99t7UNflLxfYYSlKYsBpXdEet03Pg2g16Swow4=
 github.com/cenkalti/backoff v2.2.1+incompatible/go.mod h1:90ReRw6GdpyfrHakVjL/QHaoyV4aDUVVkXQJJJ3NXXM=
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 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/dhui/dktest v0.4.0 h1:z05UmuXZHO/bgj/ds2bGMBu8FI4WA+Ag/m3ghL+om7M=
@@ -29,6 +30,7 @@ github.com/go-chi/chi/v5 v5.0.11/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNIT
 github.com/go-sql-driver/mysql v1.6.0/go.mod h1:DCzpHaOWr8IXmIStZouvnhqoel9Qv2LBy8hT2VhHyBg=
 github.com/go-sql-driver/mysql v1.7.1 h1:lUIinVbN1DY0xBg0eMOzmmtGoHwWBbvnWubQUrtU8EI=
 github.com/go-sql-driver/mysql v1.7.1/go.mod h1:OXbVy3sEdcQ2Doequ6Z5BW6fXNQTmx+9S1MCJN5yJMI=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q=
 github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q=
 github.com/golang-migrate/migrate/v4 v4.17.0 h1:rd40H3QXU0AA4IoLllFcEAEo9dYKRHYND2gB4p7xcaU=
@@ -60,6 +62,11 @@ github.com/lrstanley/girc v0.0.0-20230911164840-f47717952bf9 h1:Kgp9FtxM8VZr2wDm
 github.com/lrstanley/girc v0.0.0-20230911164840-f47717952bf9/go.mod h1:lgrnhcF8bg/Bd5HA5DOb4Z+uGqUqGnp4skr+J2GwVgI=
 github.com/mailru/easyjson v0.7.7 h1:UGYAvKxe3sBsEDzO8ZeWOSlIQfWFlxbzLZe7hwFURr0=
 github.com/mailru/easyjson v0.7.7/go.mod h1:xzfreul335JAWq5oZzymOObrkdz5UnU4kGfJJLY9Nlc=
+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 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mattn/go-sqlite3 v1.14.6/go.mod h1:NyWgC/yNuGj7Q9rpYnZvas74GogHl5/Z4A/KQRfk6bU=
 github.com/mattn/go-sqlite3 v1.14.16 h1:yOQRA0RpS5PFz/oikGwBEqvAWhWg5ufRz4ETLjwpU1Y=
 github.com/mattn/go-sqlite3 v1.14.16/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg=
@@ -77,6 +84,10 @@ github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 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/rs/xid v1.5.0 h1:mKX4bl4iPYJtEIxp6CYiUuLQ/8DYMoz0PUdtGgMFRVc=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.31.0 h1:FcTR3NnLWW+NnTwwhFWiJSZr4ECLpqCm6QsEnyvbV4A=
+github.com/rs/zerolog v1.31.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/stretchr/testify v1.8.3 h1:RP3t2pwF7cMEbC1dqtB6poj3niw/9gnV4Cjg5oW5gtY=
 github.com/stretchr/testify v1.8.3/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 github.com/tcolgate/mp3 v0.0.0-20170426193717-e79c5a46d300 h1:XQdibLKagjdevRB6vAjVY4qbSr8rQ610YzTkWcxzxSI=
@@ -95,6 +106,9 @@ golang.org/x/net v0.19.0 h1:zTwKpTd2XuCqf8huc7Fo2iSy+4RHPd10s4KzeTnVr1c=
 golang.org/x/net v0.19.0/go.mod h1:CfAk/cbD4CthTvqiEl8NpboMuiuOYsAr/7NOjZJtv1U=
 golang.org/x/net v0.20.0 h1:aCL9BSgETF1k+blQaYUBx9hJ9LOGP3gAVemcZlf1Kpo=
 golang.org/x/net v0.20.0/go.mod h1:z8BVo6PvndSri0LbOE3hAn0apkU+1YvI6E70E9jsnvY=
+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.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc=
 golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/sys v0.16.0 h1:xWw16ngr6ZMtmxDyKyIgsE93KNKz5HKmMa3b8ALHidU=

ircbot/api.go

@@ -2,7 +2,6 @@ package ircbot
 
 import (
 	"context"
-	"log"
 	"strconv"
 	"strings"
 	"time"
@@ -12,6 +11,7 @@ import (
 	"github.com/R-a-dio/valkyrie/errors"
 	"github.com/R-a-dio/valkyrie/rpc"
 	"github.com/lrstanley/girc"
+	"github.com/rs/zerolog"
 	"google.golang.org/grpc"
 )
 
@@ -45,7 +45,7 @@ func (ann *announceService) AnnounceSong(ctx context.Context, status radio.Statu
 
 	// don't do the announcement if the last one was recent enough
 	if time.Since(ann.lastAnnounceSong) < time.Duration(ann.Conf().IRC.AnnouncePeriod) {
-		log.Printf("skipping announce because of AnnouncePeriod")
+		zerolog.Ctx(ctx).Info().Str("metadata", status.Song.Metadata).Msg("skipping announce")
 		return nil
 	}
 	message := "Now starting:{red} '%s' {clear}[%s](%s), %s, %s, {green}LP:{clear} %s"

ircbot/commands.go

@@ -2,14 +2,14 @@ package ircbot
 
 import (
 	"context"
-	"log"
 	"regexp"
 	"strconv"
 	"time"
 
 	radio "github.com/R-a-dio/valkyrie"
 	"github.com/R-a-dio/valkyrie/errors"
 	"github.com/lrstanley/girc"
+	"github.com/rs/zerolog"
 )
 
 var (
@@ -101,7 +101,7 @@ func (rh RegexHandlers) Execute(c *girc.Client, e girc.Event) {
 			case errors.Is(errors.SongCooldown, err):
 				event.Echo(CooldownMessageFromError(err))
 			default:
-				log.Println("handler error:", err)
+				zerolog.Ctx(ctx).Error().Err(err).Msg("handler error")
 			}
 			return
 		}

ircbot/commands_impl.go

@@ -2,14 +2,14 @@ package ircbot
 
 import (
 	"context"
-	"log"
 	"regexp"
 	"strings"
 	"time"
 
 	radio "github.com/R-a-dio/valkyrie"
 	"github.com/R-a-dio/valkyrie/config"
 	"github.com/R-a-dio/valkyrie/errors"
+	"github.com/rs/zerolog"
 )
 
 func NowPlaying(e Event) error {
@@ -356,8 +356,7 @@ func ChannelTopic(e Event) error {
 
 	channel := e.Client.LookupChannel(e.Params[0])
 	if channel == nil {
-		log.Println("unknown channel in .topic")
-		// unknown channel?
+		zerolog.Ctx(e.Ctx).Warn().Str("command", "topic").Msg("nil channel")
 		return nil
 	}
 

ircbot/main.go

@@ -2,12 +2,12 @@ package ircbot
 
 import (
 	"context"
-	"log"
 	"net"
 	"os"
 	"time"
 
 	"github.com/cenkalti/backoff"
+	"github.com/rs/zerolog"
 
 	radio "github.com/R-a-dio/valkyrie"
 	"github.com/R-a-dio/valkyrie/config"
@@ -62,12 +62,12 @@ func Execute(ctx context.Context, cfg config.Config) error {
 func NewBot(ctx context.Context, cfg config.Config) (*Bot, error) {
 	const op errors.Op = "irc/NewBot"
 
-	store, err := storage.Open(cfg)
+	store, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return nil, errors.E(op, err)
 	}
 
-	ss, err := search.Open(cfg)
+	ss, err := search.Open(ctx, cfg)
 	if err != nil {
 		return nil, errors.E(op, err)
 	}
@@ -132,10 +132,10 @@ func (b *Bot) runClient(ctx context.Context) error {
 	doConnect := func() error {
 		const op errors.Op = "irc/Bot.runClient.doConnect"
 
-		log.Println("client: connecting to:", b.c.Config.Server)
+		zerolog.Ctx(ctx).Info().Str("address", b.c.Config.Server).Msg("connecting")
 		err := b.c.Connect()
 		if err != nil {
-			log.Println("irc: connect error:", err)
+			zerolog.Ctx(ctx).Error().Str("address", b.c.Config.Server).Err(err).Msg("connecting")
 			// reset the backoff if we managed to stay connected for a decent period of
 			// time so we will retry fast again
 			if cb.GetElapsedTime() > time.Minute*10 {

jobs/listenlog.go

@@ -10,7 +10,7 @@ import (
 // ExecuteListenerLog fetches the listener count from the manager and inserts a line into
 // the listenlog table.
 func ExecuteListenerLog(ctx context.Context, cfg config.Config) error {
-	store, err := storage.Open(cfg)
+	store, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}

jobs/requestcount.go

@@ -15,7 +15,7 @@ const duration = time.Hour * 24 * 11
 // ExecuteRequestCount drops the requestcount of all tracks by 1 if they have not been
 // requested within the specified duration.
 func ExecuteRequestCount(ctx context.Context, cfg config.Config) error {
-	store, err := storage.Open(cfg)
+	store, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}
@@ -43,7 +43,7 @@ func ExecuteRequestCount(ctx context.Context, cfg config.Config) error {
 	}
 
 	// update search index
-	search, err := search.Open(cfg)
+	search, err := search.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}

jobs/verifier.go

@@ -1,19 +1,22 @@
+//go:build !nostreamer
 // +build !nostreamer
 
 package jobs
 
 import (
 	"context"
-	"log"
 	"path/filepath"
 
 	"github.com/R-a-dio/valkyrie/config"
 	"github.com/R-a-dio/valkyrie/storage"
 	"github.com/R-a-dio/valkyrie/streamer/audio"
+	"github.com/rs/zerolog"
 )
 
 func ExecuteVerifier(ctx context.Context, cfg config.Config) error {
-	store, err := storage.Open(cfg)
+	logger := zerolog.Ctx(ctx)
+
+	store, err := storage.Open(ctx, cfg)
 	if err != nil {
 		return err
 	}
@@ -30,23 +33,24 @@ func ExecuteVerifier(ctx context.Context, cfg config.Config) error {
 		filename := filepath.Join(root, song.FilePath)
 		err := decodeFile(filename)
 		if err != nil {
+			l := logger.Error().
+				Err(err).
+				Uint64("track_id", uint64(song.TrackID)).
+				Str("filename", filename)
 			if err, ok := err.(*audio.DecodeError); ok {
-				log.Printf("verify: failed to decode file: (%d) %s: %s\n %s",
-					song.TrackID, filename, err.Err, err.ExtraInfo)
-			} else {
-				log.Printf("verify: failed to decode file: (%d) %s: %s",
-					song.TrackID, filename, err)
+				l = l.Str("info", err.ExtraInfo)
 			}
+			l.Msg("failed to decode file")
 			continue
 		}
 
 		err = ts.UpdateUsable(song, 1)
 		if err != nil {
-			log.Printf("verify: failed to mark as usable: (%d): %s", song.TrackID, err)
+			logger.Error().Err(err).Uint64("track_id", uint64(song.TrackID)).Msg("failed to verify")
 			continue
 		}
 
-		log.Printf("verify: success: (%d) %s", song.TrackID, song.Metadata)
+		logger.Info().Uint64("track_id", uint64(song.TrackID)).Msg("success")
 	}
 
 	return nil