From 043e30766301a3c2a01fcce4b0419e1ed3a62d77 Mon Sep 17 00:00:00 2001 From: Craig Williams Date: Thu, 15 Oct 2026 16:10:52 +0100 Subject: [PATCH] Logging: structured slog messages throughout, and WithLogger options so callers choose the logger Log messages are lower-case event names with their details as key/value attributes ("error" for errors), in place of formatted strings. Loggable package take a WithLogger option as part of their "New*" call, defaulting to slog.Default(). Each tags its lines with its `component`. Some debug loggers print directly rather than using slog when in terminal logging mode. --- cmd/jobsearch/main.go | 9 +-- cmd/mock-fts/main.go | 25 +++---- internal/cli/config/command.go | 4 +- internal/cli/config/get.go | 6 +- internal/cli/config/init.go | 6 +- internal/cli/config/set.go | 6 +- internal/cli/config/show.go | 6 +- internal/cli/confirm_action.go | 5 +- internal/cli/fetch/command.go | 4 +- internal/cli/fetch/once.go | 6 +- internal/cli/fetch/service.go | 6 +- internal/cli/migrate/down.go | 6 +- internal/cli/migrate/migrate.go | 6 +- internal/cli/migrate/status.go | 6 +- internal/cli/migrate/up.go | 6 +- internal/cli/options.go | 2 +- internal/cli/version/command.go | 6 +- internal/cli/wsserve/command.go | 10 +-- internal/config/config.go | 4 +- internal/config/debug.go | 83 +++++++++++++++------ internal/config/load.go | 4 +- internal/config/load_test.go | 10 +-- internal/config/print.go | 45 ++++++----- internal/config/print_test.go | 8 +- internal/fetcher/fetcher.go | 54 ++++++++++++-- internal/fetcher/fetcher_test.go | 19 +++-- internal/fetcher/worker_findatender.go | 12 +-- internal/fetcher/worker_ftsmock.go | 12 +-- internal/fetcher/worker_sleeper.go | 4 +- internal/findatender/api.go | 65 +++++++++------- internal/findatender/api_test.go | 13 +++- internal/findatender/findatender.go | 30 +++++++- internal/logging/logging.go | 63 ++++++++++++++-- internal/logging/logging_test.go | 51 +++++++++++++ internal/mock/findatender/generator.go | 15 ++-- internal/mock/findatender/handler.go | 12 +-- internal/mock/findatender/options.go | 40 ++++++++++ internal/mock/findatender/store.go | 25 +++++-- internal/util/worker.go | 11 ++- internal/websocket/client.go | 18 +++-- internal/websocket/client_test.go | 10 +-- internal/websocket/http.go | 6 +- internal/websocket/http_test.go | 10 +-- internal/websocket/hub.go | 36 +++++++-- internal/websocket/hub_test.go | 8 +- internal/websocket/tcp.go | 4 +- internal/websocket/tcp_test.go | 6 +- internal/websocket/tcpserver/server.go | 39 ++++++++-- internal/websocket/tcpserver/server_test.go | 4 +- 49 files changed, 598 insertions(+), 248 deletions(-) create mode 100644 internal/mock/findatender/options.go diff --git a/cmd/jobsearch/main.go b/cmd/jobsearch/main.go index d8d9fba..7dfb88b 100644 --- a/cmd/jobsearch/main.go +++ b/cmd/jobsearch/main.go @@ -52,17 +52,16 @@ opportunities. PersistentPreRunE: func(cmd *cobra.Command, args []string) error { cli.SetupInitialLogging(cmd) - slog.Debug("root.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "root") slog.Debug( - "command: \"" + - strings.Join(strings.Split(cmd.CommandPath(), " ")[1:], " ") + - "\"", + "command", + "path", strings.Join(strings.Split(cmd.CommandPath(), " ")[1:], " "), ) return nil }, PersistentPostRunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("root.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "root") return opts.Finish() }, diff --git a/cmd/mock-fts/main.go b/cmd/mock-fts/main.go index 9711fd0..09edf93 100644 --- a/cmd/mock-fts/main.go +++ b/cmd/mock-fts/main.go @@ -24,6 +24,7 @@ import ( "errors" "fmt" "log" + "log/slog" "net/http" "os" "os/signal" @@ -206,15 +207,13 @@ func run(ctx context.Context, o *options) (err error) { if err != nil { return err } - log.Printf( - "catalog: %d buyers, %d suppliers, %d subjects, %d methods, %d classifications", - len( - cat.Buyers, - ), - len(cat.Suppliers), - len(cat.Subjects), - len(cat.Methods), - len(cat.Classifications), + slog.Info( + "catalog loaded", + "buyers", len(cat.Buyers), + "suppliers", len(cat.Suppliers), + "subjects", len(cat.Subjects), + "methods", len(cat.Methods), + "classifications", len(cat.Classifications), ) // ----- store ----- @@ -223,7 +222,7 @@ func run(ctx context.Context, o *options) (err error) { if err := os.Remove(storePath); err != nil && !errors.Is(err, os.ErrNotExist) { return err } - log.Print("store: reset") + slog.Info("store reset", "path", storePath) } store, err := mock.OpenStore(storePath) if err != nil { @@ -238,7 +237,7 @@ func run(ctx context.Context, o *options) (err error) { return err } - log.Printf("store: %d releases (%d generated to catch up)", store.Len(), n) + slog.Info("store ready", "releases", store.Len(), "generated", n) // The generator and server share a context that also ends if the server // fails, so the generator is never left running after run returns. @@ -286,11 +285,11 @@ func run(ctx context.Context, o *options) (err error) { ) defer cancelShutdown() if err := httpSrv.Shutdown(shutdownCtx); err != nil { - log.Printf("shutdown: %v", err) + slog.Error("shutdown failed", "error", err) } }() - log.Printf("FTS mock listening on %s%s (query times in %s)", o.addr, mock.BasePath, loc) + slog.Info("mock listening", "addr", o.addr, "path", mock.BasePath, "time_zone", loc.String()) serveErr := httpSrv.ListenAndServe() cancel() // stop the worker (and the shutdown goroutine) if the server failed diff --git a/internal/cli/config/command.go b/internal/cli/config/command.go index 196535d..c898930 100644 --- a/internal/cli/config/command.go +++ b/internal/cli/config/command.go @@ -14,10 +14,10 @@ func NewCommand(opts *cli.Options) *cobra.Command { Use: "config", Short: "Configuration management", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "config") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "config") }, } cmd.AddCommand(commandShow(opts)) diff --git a/internal/cli/config/get.go b/internal/cli/config/get.go index 79efe3f..9eb1d0d 100644 --- a/internal/cli/config/get.go +++ b/internal/cli/config/get.go @@ -15,13 +15,13 @@ func commandGet(opts *cli.Options) *cobra.Command { Args: cobra.ExactArgs(1), Short: "Get a value from configuration", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.get.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "config.get") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.get.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "config.get") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("config.get.Run") + slog.Debug("command run", "command", "config.get") if err := cobra.ExactArgs(1)(cmd, args); err != nil { return err diff --git a/internal/cli/config/init.go b/internal/cli/config/init.go index 7bbd112..4fbd850 100644 --- a/internal/cli/config/init.go +++ b/internal/cli/config/init.go @@ -19,13 +19,13 @@ func commandInit() *cobra.Command { Args: cobra.MatchAll(cobra.MinimumNArgs(0), cobra.MaximumNArgs(1)), Short: "Create an empty configuration file", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.init.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "config.init") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.init.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "config.init") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("config.init.Run") + slog.Debug("command run", "command", "config.init") if err := cobra.MinimumNArgs(0)(cmd, args); err != nil { return err diff --git a/internal/cli/config/set.go b/internal/cli/config/set.go index 66e1bfd..7a69012 100644 --- a/internal/cli/config/set.go +++ b/internal/cli/config/set.go @@ -18,13 +18,13 @@ func commandSet(opts *cli.Options) *cobra.Command { Args: cobra.MatchAll(cobra.MinimumNArgs(1), cobra.MaximumNArgs(2)), Short: "Set a value to configuration", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.set.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "config.set") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.set.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "config.set") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("config.set.Run") + slog.Debug("command run", "command", "config.set") if err := cobra.MinimumNArgs(1)(cmd, args); err != nil { return err diff --git a/internal/cli/config/show.go b/internal/cli/config/show.go index a493f4a..1a89822 100644 --- a/internal/cli/config/show.go +++ b/internal/cli/config/show.go @@ -14,13 +14,13 @@ func commandShow(opts *cli.Options) *cobra.Command { Use: "show", Short: "Print config information", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.show.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "config.show") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("config.show.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "config.show") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("config.show.Run") + slog.Debug("command run", "command", "config.show") conf, err := opts.RunSetup(cmd, true, true) if err != nil { diff --git a/internal/cli/confirm_action.go b/internal/cli/confirm_action.go index 4b0c12e..186e552 100644 --- a/internal/cli/confirm_action.go +++ b/internal/cli/confirm_action.go @@ -3,7 +3,7 @@ package cli import ( "bufio" "fmt" - "log" + "log/slog" "os" "strings" ) @@ -19,7 +19,8 @@ func Confirm(s string) bool { response, err := reader.ReadString('\n') if err != nil { - log.Fatal(err) + slog.Error("reading the answer", "error", err) + os.Exit(1) } response = strings.ToLower(strings.TrimSpace(response)) diff --git a/internal/cli/fetch/command.go b/internal/cli/fetch/command.go index bdf4a10..cdc1709 100644 --- a/internal/cli/fetch/command.go +++ b/internal/cli/fetch/command.go @@ -14,10 +14,10 @@ func NewCommand(opts *cli.Options) *cobra.Command { Use: "fetch", Short: "Fetch current opportunities", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("fetch.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "fetch") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("fetch.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "fetch") }, } cmd.AddCommand(commandOnce(opts)) diff --git a/internal/cli/fetch/once.go b/internal/cli/fetch/once.go index 843ad76..b132eac 100644 --- a/internal/cli/fetch/once.go +++ b/internal/cli/fetch/once.go @@ -53,13 +53,13 @@ func commandOnce(opts *cli.Options) *cobra.Command { Use: "once", Short: "Fetch current opportunities - single shot", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("fetch.once.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "fetch.once") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("fetch.once.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "fetch.once") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("fetch.once.Run") + slog.Debug("command run", "command", "fetch.once") conf, err := opts.RunSetup(cmd, true, true) if err != nil { diff --git a/internal/cli/fetch/service.go b/internal/cli/fetch/service.go index 92ddba6..9fbd54d 100644 --- a/internal/cli/fetch/service.go +++ b/internal/cli/fetch/service.go @@ -20,13 +20,13 @@ func commandService(opts *cli.Options) *cobra.Command { Use: "service", Short: "Fetch current opportunities - background service", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("fetch.service.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "fetch.service") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("fetch.service.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "fetch.service") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("fetch.service.Run") + slog.Debug("command run", "command", "fetch.service") foreground, _ := cmd.Flags().GetBool("foreground") diff --git a/internal/cli/migrate/down.go b/internal/cli/migrate/down.go index b27a7bb..6d395de 100644 --- a/internal/cli/migrate/down.go +++ b/internal/cli/migrate/down.go @@ -21,13 +21,13 @@ func commandDown(opts *cli.Options) *cobra.Command { confirmed by providing -yes.`, Args: cobra.NoArgs, PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.down.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "migrate.down") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.down.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "migrate.down") }, RunE: func(cmd *cobra.Command, args []string) (err error) { - slog.Debug("migrate.down.Run") + slog.Debug("command run", "command", "migrate.down") yes, _ := cmd.Flags().GetBool("yes") steps, _ := cmd.Flags().GetUint("steps") diff --git a/internal/cli/migrate/migrate.go b/internal/cli/migrate/migrate.go index 7ee67b9..d04a9bd 100644 --- a/internal/cli/migrate/migrate.go +++ b/internal/cli/migrate/migrate.go @@ -26,13 +26,13 @@ Running without a subcommand is the same as running "migrate up": every pending migration is applied.`, Args: cobra.NoArgs, PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "migrate") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "migrate") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("migrate.Run") + slog.Debug("command run", "command", "migrate") return runStepUp(cmd, opts, 0, false) }, } diff --git a/internal/cli/migrate/status.go b/internal/cli/migrate/status.go index bca7de7..e11b763 100644 --- a/internal/cli/migrate/status.go +++ b/internal/cli/migrate/status.go @@ -75,13 +75,13 @@ func commandStatus(opts *cli.Options) *cobra.Command { Short: "Show which migrations have been applied to the SQLite database", Args: cobra.NoArgs, PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.status.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "migrate.status") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.status.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "migrate.status") }, RunE: func(cmd *cobra.Command, args []string) (err error) { - slog.Debug("migrate.status.Run") + slog.Debug("command run", "command", "migrate.status") m, db, err := openMigrator(cmd, opts, false, false) if err != nil { diff --git a/internal/cli/migrate/up.go b/internal/cli/migrate/up.go index 266c8ac..dfe493b 100644 --- a/internal/cli/migrate/up.go +++ b/internal/cli/migrate/up.go @@ -46,13 +46,13 @@ func commandUp(opts *cli.Options) *cobra.Command { Short: "Migrate SQLite database to the latest version, or by a number of steps", Args: cobra.NoArgs, PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.up.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "migrate.up") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("migrate.up.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "migrate.up") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("migrate.up.Run") + slog.Debug("command run", "command", "migrate.up") steps, _ := cmd.Flags().GetUint("steps") create, _ := cmd.Flags().GetBool("create") diff --git a/internal/cli/options.go b/internal/cli/options.go index f52d05f..bb80f9c 100644 --- a/internal/cli/options.go +++ b/internal/cli/options.go @@ -65,7 +65,7 @@ func (o *Options) RunSetup( // Check if the logging should be switched to file if !terminalLog { if len(conf.Logging.File) == 0 { - slog.Warn("No log file configured, remaining in console logging mode!") + slog.Warn("no log file configured; logging to the terminal") } else if err := logging.LogToFile(conf.Logging.File); err != nil { return nil, fmt.Errorf("opening log file: %w", err) } diff --git a/internal/cli/version/command.go b/internal/cli/version/command.go index b88aded..9873a52 100644 --- a/internal/cli/version/command.go +++ b/internal/cli/version/command.go @@ -16,13 +16,13 @@ func NewCommand() *cobra.Command { Short: "Print version information", SilenceUsage: true, PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("version.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "version") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("version.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "version") }, Run: func(cmd *cobra.Command, args []string) { - slog.Debug("version.Run") + slog.Debug("command run", "command", "version") fmt.Printf("JobSearch - %s\n", version.Version) if version.BuildTime != "unknown" { diff --git a/internal/cli/wsserve/command.go b/internal/cli/wsserve/command.go index 2654a5d..58d0b4a 100644 --- a/internal/cli/wsserve/command.go +++ b/internal/cli/wsserve/command.go @@ -22,13 +22,13 @@ func NewCommand(opts *cli.Options) *cobra.Command { Use: "wsserve", Short: "Run JobSearch TCP Websocket server", PersistentPreRun: func(cmd *cobra.Command, args []string) { - slog.Debug("wsserve.PersistentPreRun") + slog.Debug("command persistent pre-run", "command", "wsserve") }, PersistentPostRun: func(cmd *cobra.Command, args []string) { - slog.Debug("wsserve.PersistentPostRun") + slog.Debug("command persistent post-run", "command", "wsserve") }, RunE: func(cmd *cobra.Command, args []string) error { - slog.Debug("wsserve.Run") + slog.Debug("command run", "command", "wsserve") addrOverride, _ := cmd.Flags().GetString("listen") hostOverride, _ := cmd.Flags().GetString("host") @@ -74,8 +74,8 @@ func NewCommand(opts *cli.Options) *cobra.Command { stop() }() - hub := websocket.NewHub(conf.Server.WebSocket, slog.Default()) - svr := tcpserver.New(&conf.Server, hub, slog.Default()) + hub := websocket.NewHub(conf.Server.WebSocket) + svr := tcpserver.New(&conf.Server, hub) return svr.Run(ctx) }, diff --git a/internal/config/config.go b/internal/config/config.go index ed5ef56..f8dbde9 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -70,11 +70,11 @@ func LoadFromViper(conf *JobSearchConfig) { } value, ok := viperValue(key, keyType) if !ok { - slog.Error(fmt.Sprintf("unknown key type: %s", keyType)) + slog.Error("unknown config key type", "key", key, "kind", keyType.String()) continue } if err := conf.SetValue(key, value); err != nil { - slog.Warn("ignoring invalid config value", "key", key, "err", err) + slog.Warn("ignoring invalid config value", "key", key, "error", err) } } } diff --git a/internal/config/debug.go b/internal/config/debug.go index 62fc643..012ad93 100644 --- a/internal/config/debug.go +++ b/internal/config/debug.go @@ -1,6 +1,7 @@ package config import ( + "context" "fmt" "log/slog" "os" @@ -9,41 +10,81 @@ import ( "strings" "github.com/spf13/viper" + + "git.avsdev.uk/Go/job-search/internal/logging" ) -// printEnv logs the JOBSEARCH* environment variables at debug level. +// printEnv logs each JOBSEARCH* environment variable at debug level. On a +// terminal it logs one line and prints the variables under it as +// "name=value" lines; elsewhere each variable is a log entry of its own. func printEnv() { - slog.Debug("Environment:") - env := os.Environ() - slices.Sort(env) - for _, e := range env { - pair := strings.SplitN(e, "=", 2) - if strings.HasPrefix(pair[0], EnvPrefix) { - slog.Debug("\t" + pair[0] + "=" + pair[1]) + logger := slog.Default() + terminal := logging.WritesToTerminal(logger.Handler()) + if terminal && !logger.Enabled(context.Background(), slog.LevelDebug) { + return + } + + var variables []string + for _, variable := range os.Environ() { + if strings.HasPrefix(variable, EnvPrefix) { + variables = append(variables, variable) } } + slices.Sort(variables) + + if terminal { + logger.Debug("environment variables", "count", len(variables)) + } + for _, variable := range variables { + if terminal { + logging.PrintToTerminal("\t" + variable) + continue + } + name, value, _ := strings.Cut(variable, "=") + logger.Debug("environment variable", "name", name, "value", value) + } } // printLoadedConfig logs every key set by the config file or an environment -// variable (see isExplicitlySet), with its value and type, at debug level. +// variable (see isExplicitlySet), with its value and type, at debug level. On +// a terminal it logs one line and prints the values under it as +// "key = value " lines; elsewhere each value is a log entry of its own. func printLoadedConfig() { - slog.Debug("Loaded config:") - keys := viper.AllKeys() - for i := range keys { - k := keys[i] - if isExplicitlySet(k) { - v := viper.Get(k) - t := reflect.TypeOf(v) - slog.Debug( - "\t" + k + " = " + fmt.Sprintf("%#v", v) + - " <" + t.Kind().String() + ">", - ) + logger := slog.Default() + terminal := logging.WritesToTerminal(logger.Handler()) + if terminal && !logger.Enabled(context.Background(), slog.LevelDebug) { + return + } + + var keys []string + for _, key := range viper.AllKeys() { + if isExplicitlySet(key) { + keys = append(keys, key) } } + + if terminal { + logger.Debug("loaded config values", "count", len(keys)) + } + for _, key := range keys { + value := viper.Get(key) + kind := reflect.TypeOf(value).Kind().String() + if terminal { + logging.PrintToTerminal( + fmt.Sprintf("\t%s = %#v <%s>", key, value, kind), + ) + continue + } + logger.Debug( + "loaded config value", + "key", key, + "value", value, + "type", kind, + ) + } } // printConfig logs conf at debug level. func printConfig(conf JobSearchConfig) { - slog.Debug("Config:") conf.PrintLog(slog.LevelDebug) } diff --git a/internal/config/load.go b/internal/config/load.go index 0e133fb..62afb56 100644 --- a/internal/config/load.go +++ b/internal/config/load.go @@ -68,14 +68,14 @@ func loadConfig(cfgFile string) error { if _, ok := err.(viper.ConfigFileNotFoundError); ok { // Indicates an explicitly set config file is not found or // that no config file was found in any search path - slog.Warn("No config file found!") + slog.Warn("no config file found; using defaults") } else { // Config file was found but another error was produced return err } } else { // Config file found and successfully parsed - slog.Info("Using config file: " + viper.ConfigFileUsed()) + slog.Info("using config file", "file", viper.ConfigFileUsed()) } return nil } diff --git a/internal/config/load_test.go b/internal/config/load_test.go index 8007b7d..c8f1c86 100644 --- a/internal/config/load_test.go +++ b/internal/config/load_test.go @@ -93,7 +93,7 @@ func TestInitNoConfigFile(t *testing.T) { if err := Init("", &conf); err != nil { t.Fatal(err) } - if !strings.Contains(logs.String(), "No config file found") { + if !strings.Contains(logs.String(), "no config file found") { t.Errorf("no warning logged: %s", logs) } if conf.Logging.Level != "warn" { @@ -116,7 +116,7 @@ func TestInitKeepsCommandLineLevel(t *testing.T) { t.Errorf("Logging.Level = %q; want %s kept", conf.Logging.Level, level) } // At debug, the environment and loaded config are logged. - gotDebug := strings.Contains(logs.String(), "Loaded config:") + gotDebug := strings.Contains(logs.String(), "loaded config value") if gotDebug != (level == "debug") { t.Errorf("debug output logged = %v at level %s: %s", gotDebug, level, logs) } @@ -241,9 +241,9 @@ func TestPrintLoadedConfig(t *testing.T) { out := logs.String() for _, want := range []string{ - `logging.level = \"info\" `, - `server.websocket.connection_limit.enabled = true `, - `database.file = \"/tmp/js.db\" `, + `key=logging.level value=info type=string`, + `key=server.websocket.connection_limit.enabled value=true type=bool`, + `key=database.file value=/tmp/js.db type=string`, } { if !strings.Contains(out, want) { t.Errorf("missing %q in:\n%s", want, out) diff --git a/internal/config/print.go b/internal/config/print.go index 99798bb..9c7eb2e 100644 --- a/internal/config/print.go +++ b/internal/config/print.go @@ -1,10 +1,13 @@ package config import ( + "context" "fmt" "log/slog" "maps" "slices" + + "git.avsdev.uk/Go/job-search/internal/logging" ) // PrintTerminal prints the configuration to stdout as String formats it. @@ -23,31 +26,33 @@ func (conf JobSearchConfig) PrintYaml() { } // PrintLog logs each configuration key and value, sorted by key, at atLevel: -// debug, warn, error, or info for any other level. +// debug, warn, error, or info for any other level. On a terminal it logs one +// line and prints the values under it as "key = value" lines; elsewhere each +// value is a log entry of its own. func (conf JobSearchConfig) PrintLog(atLevel slog.Level) { - var logFn func(args ...interface{}) - switch atLevel { - case slog.LevelDebug: - logFn = func(args ...interface{}) { - slog.Debug(fmt.Sprint(args...)) - } - case slog.LevelError: - logFn = func(args ...interface{}) { - slog.Error(fmt.Sprint(args...)) - } - case slog.LevelWarn: - logFn = func(args ...interface{}) { - slog.Warn(fmt.Sprint(args...)) - } + case slog.LevelDebug, slog.LevelWarn, slog.LevelError: default: - logFn = func(args ...interface{}) { - slog.Info(fmt.Sprint(args...)) - } + atLevel = slog.LevelInfo } + ctx := context.Background() + logger := slog.Default() flat := conf.Flatten() - for _, k := range slices.Sorted(maps.Keys(flat)) { - logFn("\t", k, " = ", flat[k]) + keys := slices.Sorted(maps.Keys(flat)) + + if logging.WritesToTerminal(logger.Handler()) { + if !logger.Enabled(ctx, atLevel) { + return + } + logger.Log(ctx, atLevel, "config values", "count", len(keys)) + for _, key := range keys { + logging.PrintToTerminal(fmt.Sprintf("\t%s = %v", key, flat[key])) + } + return + } + + for _, key := range keys { + logger.Log(ctx, atLevel, "config value", "key", key, "value", flat[key]) } } diff --git a/internal/config/print_test.go b/internal/config/print_test.go index fe7d924..b8761bc 100644 --- a/internal/config/print_test.go +++ b/internal/config/print_test.go @@ -108,15 +108,15 @@ func TestPrintLog(t *testing.T) { t.Errorf("PrintLog(%v) line %q; want %s", tt.at, l, tt.want) } } - if !strings.Contains(logs.String(), "logging.level = warn") { + if !strings.Contains(logs.String(), "key=logging.level value=warn") { t.Errorf("PrintLog(%v) missing logging.level:\n%s", tt.at, logs) } - // Each line is msg="\t = ". + // Each line is msg="config value" key= value=. flat := conf.Flatten() var keys []string for _, l := range lines { - _, msg, _ := strings.Cut(l, `msg="\t`) - key, _, _ := strings.Cut(msg, " = ") + _, rest, _ := strings.Cut(l, ` key=`) + key, _, _ := strings.Cut(rest, " ") if _, ok := flat[key]; !ok { t.Errorf("PrintLog(%v) line %q: no key", tt.at, l) } diff --git a/internal/fetcher/fetcher.go b/internal/fetcher/fetcher.go index 7141dc8..a6a247c 100644 --- a/internal/fetcher/fetcher.go +++ b/internal/fetcher/fetcher.go @@ -14,16 +14,60 @@ import ( var ErrNoNewReleases = fmt.Errorf("%w: no new releases", util.ErrWorkerNoWork) +// Option configures Run. +type Option func(*options) + +// options holds the settings Options change. +type options struct { + log *slog.Logger +} + +// WithLogger makes Run, its workers and their clients log to logger instead +// of slog.Default(). +func WithLogger(logger *slog.Logger) Option { + return func(opts *options) { + opts.log = logger + } +} + +// logger returns the logger Run logs to: the given one, or slog.Default(). +// It isn't tagged here; each worker adds its source. +func (opts options) logger() *slog.Logger { + if opts.log == nil { + return slog.Default() + } + return opts.log +} + +// runFunc runs one source's worker until ctx is cancelled, logging to +// logger. +type runFunc func( + ctx context.Context, + logger *slog.Logger, + conf *config.JobSearchConfig, + since time.Time, +) error + // Run starts a worker for each enabled source and blocks until every worker // has stopped. Workers stop when ctx is cancelled, or when any worker stops // with an error, which starts a shutdown of all of them. The errors are -// logged as they happen and returned joined; nil means a clean shutdown. +// logged as they happen and returned joined; nil means a clean shutdown. It +// logs to slog.Default() unless given WithLogger. func Run( - ctx context.Context, conf *config.JobSearchConfig, since time.Time, + ctx context.Context, + conf *config.JobSearchConfig, + since time.Time, + opts ...Option, ) error { ctx, cancel := context.WithCancel(ctx) defer cancel() + var settings options + for _, opt := range opts { + opt(&settings) + } + logger := settings.logger().With("component", "fetcher") + var ( wg sync.WaitGroup mu sync.Mutex @@ -32,13 +76,13 @@ func Run( start := func( name string, - run func(context.Context, *config.JobSearchConfig, time.Time) error, + run runFunc, ) { wg.Add(1) go func() { defer wg.Done() - if err := run(ctx, conf, since); err != nil { - slog.Error("source stopped, shutting down", "source", name, "err", err) + if err := run(ctx, logger, conf, since); err != nil { + logger.Error("source stopped, shutting down", "source", name, "error", err) mu.Lock() errs = append(errs, fmt.Errorf("%s: %w", name, err)) mu.Unlock() diff --git a/internal/fetcher/fetcher_test.go b/internal/fetcher/fetcher_test.go index a49f017..3598690 100644 --- a/internal/fetcher/fetcher_test.go +++ b/internal/fetcher/fetcher_test.go @@ -62,7 +62,7 @@ func confFor(apiRoot string) *config.JobSearchConfig { } func TestFetchFunctions(t *testing.T) { - fetchers := map[string]func(context.Context, *config.JobSearchConfig, time.Time) error{ + fetchers := map[string]runFunc{ "FindAOpportunity": fetchFindAOpportunity, "FTSMock": fetchFTSMock, } @@ -91,7 +91,9 @@ func TestFetchFunctions(t *testing.T) { for _, tc := range tests { t.Run(fname+"/"+tc.name, func(t *testing.T) { srv, hits := ftsServer(t, tc.status, tc.body) - err := fetch(context.Background(), confFor(srv.URL), time.Now().Add(-time.Hour)) + err := fetch( + context.Background(), slog.Default(), confFor(srv.URL), time.Now().Add(-time.Hour), + ) if !tc.check(err) { t.Fatalf("err = %v, want %s", err, tc.wantErr) } @@ -110,11 +112,11 @@ func TestFetchUsesConfiguredAPIRoot(t *testing.T) { conf.Sources.FindATender.APIRoot = fat.URL conf.Sources.FTSMock.APIRoot = mock.URL - fetchFindAOpportunity(context.Background(), conf, time.Time{}) + fetchFindAOpportunity(context.Background(), slog.Default(), conf, time.Time{}) if fatHits.Load() != 1 || mockHits.Load() != 0 { t.Fatalf("FindAOpportunity hits: fat=%d mock=%d", fatHits.Load(), mockHits.Load()) } - fetchFTSMock(context.Background(), conf, time.Time{}) + fetchFTSMock(context.Background(), slog.Default(), conf, time.Time{}) if fatHits.Load() != 1 || mockHits.Load() != 1 { t.Fatalf("FTSMock hits: fat=%d mock=%d", fatHits.Load(), mockHits.Load()) } @@ -126,7 +128,8 @@ func TestFetchCancelled(t *testing.T) { // Unroutable root: the request should never be waited on. conf := confFor("http://192.0.2.1:9") start := time.Now() - if err := fetchFTSMock(ctx, conf, time.Time{}); !errors.Is(err, context.Canceled) { + err := fetchFTSMock(ctx, slog.Default(), conf, time.Time{}) + if !errors.Is(err, context.Canceled) { t.Fatalf("err = %v, want context.Canceled", err) } if d := time.Since(start); d > time.Second { @@ -163,7 +166,7 @@ func TestRunSleeperShutdown(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) done := make(chan struct{}) go func() { - runSleeper(ctx, conf, time.Time{}) + runSleeper(ctx, slog.Default(), conf, time.Time{}) close(done) }() time.Sleep(10 * time.Millisecond) // let the first sleep start @@ -184,13 +187,13 @@ func TestRunSleeperShutdown(t *testing.T) { func TestRunWorkersRejectZeroInterval(t *testing.T) { conf := &config.JobSearchConfig{} - runs := map[string]func(context.Context, *config.JobSearchConfig, time.Time) error{ + runs := map[string]runFunc{ "FindAOpportunity": runFindAOpportunity, "FTSMock": runFTSMock, "Sleeper": runSleeper, } for name, run := range runs { - if err := run(context.Background(), conf, time.Time{}); err == nil { + if err := run(context.Background(), slog.Default(), conf, time.Time{}); err == nil { t.Errorf("%s: expected an error for a zero interval", name) } } diff --git a/internal/fetcher/worker_findatender.go b/internal/fetcher/worker_findatender.go index 7d8d8a7..b77590c 100644 --- a/internal/fetcher/worker_findatender.go +++ b/internal/fetcher/worker_findatender.go @@ -3,7 +3,6 @@ package fetcher import ( "context" "errors" - "fmt" "log/slog" "time" @@ -16,13 +15,14 @@ import ( // runFindAOpportunity polls Find a Tender every configured interval until ctx // is cancelled. func runFindAOpportunity( - ctx context.Context, conf *config.JobSearchConfig, since time.Time, + ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time, ) error { w := util.Worker{ + Logger: logger, Name: "FindAOpportunity", Interval: conf.Sources.FindATender.Interval, Task: func(ctx context.Context, since time.Time) error { - return fetchFindAOpportunity(ctx, conf, since) + return fetchFindAOpportunity(ctx, logger, conf, since) }, } return w.Run(ctx, since) @@ -32,10 +32,10 @@ func runFindAOpportunity( // Tender. Finding nothing returns ErrNoNewReleases, so the worker still moves // its checkpoint on. func fetchFindAOpportunity( - ctx context.Context, conf *config.JobSearchConfig, since time.Time, + ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time, ) error { opportunities, err := util.AwaitTask(ctx, func() ([]*types.Opportunity, error) { - ft := findatender.New(conf, conf.Sources.FindATender.APIRoot) + ft := findatender.New(conf, conf.Sources.FindATender.APIRoot, findatender.WithLogger(logger)) defer ft.Shutdown() return ft.With(ctx).FetchAll(since, true) }) @@ -46,7 +46,7 @@ func fetchFindAOpportunity( return err } - slog.Info(fmt.Sprintf("Found %d opportunities", len(opportunities))) + logger.Info("fetched opportunities", "count", len(opportunities)) return nil } diff --git a/internal/fetcher/worker_ftsmock.go b/internal/fetcher/worker_ftsmock.go index 8946906..47e5fb5 100644 --- a/internal/fetcher/worker_ftsmock.go +++ b/internal/fetcher/worker_ftsmock.go @@ -3,7 +3,6 @@ package fetcher import ( "context" "errors" - "fmt" "log/slog" "time" @@ -16,13 +15,14 @@ import ( // runFTSMock polls the mock Find a Tender server every configured interval // until ctx is cancelled. func runFTSMock( - ctx context.Context, conf *config.JobSearchConfig, since time.Time, + ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time, ) error { w := util.Worker{ + Logger: logger, Name: "FTSMock", Interval: conf.Sources.FTSMock.Interval, Task: func(ctx context.Context, since time.Time) error { - return fetchFTSMock(ctx, conf, since) + return fetchFTSMock(ctx, logger, conf, since) }, } return w.Run(ctx, since) @@ -32,10 +32,10 @@ func runFTSMock( // Tender server. Finding nothing returns ErrNoNewReleases, so the worker still // moves its checkpoint on. func fetchFTSMock( - ctx context.Context, conf *config.JobSearchConfig, since time.Time, + ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time, ) error { opportunities, err := util.AwaitTask(ctx, func() ([]*types.Opportunity, error) { - ft := findatender.New(conf, conf.Sources.FTSMock.APIRoot) + ft := findatender.New(conf, conf.Sources.FTSMock.APIRoot, findatender.WithLogger(logger)) defer ft.Shutdown() return ft.With(ctx).FetchAll(since, true) }) @@ -46,7 +46,7 @@ func fetchFTSMock( return err } - slog.Info(fmt.Sprintf("Found %d opportunities", len(opportunities))) + logger.Info("fetched opportunities", "count", len(opportunities)) return nil } diff --git a/internal/fetcher/worker_sleeper.go b/internal/fetcher/worker_sleeper.go index 8404b91..092b22c 100644 --- a/internal/fetcher/worker_sleeper.go +++ b/internal/fetcher/worker_sleeper.go @@ -2,6 +2,7 @@ package fetcher import ( "context" + "log/slog" "time" "git.avsdev.uk/Go/job-search/internal/config" @@ -14,10 +15,11 @@ const sleepDuration = 60 * time.Second // runSleeper runs the sleeper test source until ctx is cancelled: every // configured interval it simulates work by sleeping for sleepDuration. func runSleeper( - ctx context.Context, conf *config.JobSearchConfig, since time.Time, + ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time, ) error { blockShutdown := conf.Sources.Sleeper.BlockShutdown w := util.Worker{ + Logger: logger, Name: "Sleeper", Interval: conf.Sources.Sleeper.Interval, Task: func(taskCtx context.Context, since time.Time) error { diff --git a/internal/findatender/api.go b/internal/findatender/api.go index 7659cd6..67c93af 100644 --- a/internal/findatender/api.go +++ b/internal/findatender/api.go @@ -226,7 +226,9 @@ func missingIDsError(haveOCID, haveID bool) error { // releases, etc). // // This method takes ownership of the response body and closes it when done. -func safeUnpackReleases(response *resty.Response) (*ocds.ReleasePackage, error) { +func safeUnpackReleases( + logger *slog.Logger, response *resty.Response, +) (*ocds.ReleasePackage, error) { var pkg safeReleasePackage // Take ownership of the response body. @@ -263,9 +265,12 @@ func safeUnpackReleases(response *resty.Response) (*ocds.ReleasePackage, error) err := unmarshalLenientDates(rawRel, &release) if err != nil { ocid, release_id, _ := releaseIDs(rawRel) - slog.Warn(fmt.Sprintf( - "Skipping release (%s/%s) due to error: %s", ocid, release_id, err, - )) + logger.Warn( + "skipping unreadable release", + "ocid", ocid, + "release_id", release_id, + "error", err, + ) continue } out.Releases = append(out.Releases, release) @@ -303,8 +308,9 @@ func closeBody(res *resty.Response) { // response status. func fetchURI(ft *FindATender, uri string) (*resty.Response, error) { withTrace := ft.config.Logging.LogLevel() <= slog.LevelDebug + logger := ft.logger() - slog.Info("findTender.resty", "request_uri", uri) + logger.Info("fetching", "uri", uri) ctx := ft.ctx if ctx == nil { @@ -316,23 +322,31 @@ func fetchURI(ft *FindATender, uri string) (*resty.Response, error) { res, err := req.SetTrace(withTrace).Get(uri) if withTrace { - if logging.IsJSONHandler(slog.Default().Handler()) { - slog.Debug( - "Resty", - "trace", res.Request.TraceInfo().JSON(), - "status", res.Status(), - "response", res, - ) - } else { - slog.Debug("Resty " + res.Request.TraceInfo().String()) - slog.Debug("Resty status: " + res.Status()) - slog.Debug("Resty response: " + res.String()) - } + logTrace(logger, res) } return res, err } +// logTrace logs res's trace, status and body at debug level. On a terminal +// the trace and body are printed as they are, as a field would escape them +// into one line; elsewhere they are fields, the trace as JSON for the JSON +// (file) logger. +func logTrace(logger *slog.Logger, res *resty.Response) { + if logging.WritesToTerminal(logger.Handler()) { + logger.Debug("fetched", "status", res.Status()) + logging.PrintToTerminal(res.Request.TraceInfo().String()) + logging.PrintToTerminal(res.String()) + return + } + + trace := res.Request.TraceInfo().String() + if logging.IsJSONHandler(logger.Handler()) { + trace = res.Request.TraceInfo().JSON() + } + logger.Debug("fetched", "trace", trace, "status", res.Status(), "response", res.String()) +} + // fetchURI performs a fetch against the API. If the API returns with a rate limit // reached response and allowRateLimit is true, then wait and retry like a good // client. If allowRateLimit is false, return to the caller informing them of @@ -365,10 +379,9 @@ func (ft *FindATender) fetchURI( return nil, fmt.Errorf("unknown retry-after value: %w", err) } - slog.Warn(fmt.Sprintf( - "API rate limit hit, waiting as requested for %d seconds", retrySec, - )) - if rateSleep(ctx, time.Duration(retrySec)*time.Second) != nil { + retryAfter := time.Duration(retrySec) * time.Second + ft.logger().Warn("api rate limit hit, waiting as asked", "retry_after", retryAfter) + if rateSleep(ctx, retryAfter) != nil { return nil, ErrFetchCancelled } @@ -432,7 +445,7 @@ func (ft *FindATender) fetchOnce(opts RequestOptions) ([]ocds.Release, error) { return nil, err } - pkg, err := safeUnpackReleases(res) + pkg, err := safeUnpackReleases(ft.logger(), res) if err != nil { return nil, err } @@ -454,7 +467,7 @@ func (ft *FindATender) fetchAll(opts RequestOptions) ([]ocds.Release, error) { return nil, err } - pkg, err := safeUnpackReleases(res) + pkg, err := safeUnpackReleases(ft.logger(), res) if err != nil { return nil, err } @@ -466,9 +479,7 @@ func (ft *FindATender) fetchAll(opts RequestOptions) ([]ocds.Release, error) { for { if pkg.Links != nil && len(pkg.Links.Next) > 0 { if seen[pkg.Links.Next] { - slog.Warn(fmt.Sprintf( - "Stopping at repeated next link: %s", pkg.Links.Next, - )) + ft.logger().Warn("stopping at repeated next link", "link", pkg.Links.Next) break } seen[pkg.Links.Next] = true @@ -482,7 +493,7 @@ func (ft *FindATender) fetchAll(opts RequestOptions) ([]ocds.Release, error) { return nil, err } - pkg, err = safeUnpackReleases(res) + pkg, err = safeUnpackReleases(ft.logger(), res) if err != nil { return nil, err } diff --git a/internal/findatender/api_test.go b/internal/findatender/api_test.go index c989b90..15fbf68 100644 --- a/internal/findatender/api_test.go +++ b/internal/findatender/api_test.go @@ -312,9 +312,14 @@ func TestFetchURIDebugTrace(t *testing.T) { if len(releases) != 1 { t.Errorf("got %d releases, want 1", len(releases)) } - if !strings.Contains(logs.String(), "Resty") { + if !strings.Contains(logs.String(), "msg=fetched") && + !strings.Contains(logs.String(), `"msg":"fetched"`) { t.Errorf("no trace logged: %s", logs.String()) } + // Every field must be loggable (a *resty.Response isn't, as JSON). + if strings.Contains(logs.String(), "!ERROR") { + t.Errorf("a field could not be logged: %s", logs.String()) + } }) } } @@ -387,7 +392,7 @@ func TestSafeUnpackReleases(t *testing.T) { {"ocid": "ocds-3", "id": "3", "date": "2026-10-08", "tag": [], "initiationType": "tender"} ] }` - pkg, err := safeUnpackReleases(responseFor(t, body)) + pkg, err := safeUnpackReleases(slog.Default(), responseFor(t, body)) if err != nil { t.Fatal(err) } @@ -424,7 +429,7 @@ func TestSafeUnpackReleasesPublishedDate(t *testing.T) { if tt.date != "" { body = `{"publishedDate":` + tt.date + `,"releases":[]}` } - pkg, err := safeUnpackReleases(responseFor(t, body)) + pkg, err := safeUnpackReleases(slog.Default(), responseFor(t, body)) if err != nil { t.Fatal(err) } @@ -448,7 +453,7 @@ func TestSafeUnpackReleasesInvalidJSON(t *testing.T) { "publisher array": `{"publisher": []}`, } { t.Run(name, func(t *testing.T) { - if _, err := safeUnpackReleases(responseFor(t, body)); err == nil { + if _, err := safeUnpackReleases(slog.Default(), responseFor(t, body)); err == nil { t.Error("expected a decode error") } }) diff --git a/internal/findatender/findatender.go b/internal/findatender/findatender.go index d3a1538..d4c55dd 100644 --- a/internal/findatender/findatender.go +++ b/internal/findatender/findatender.go @@ -18,21 +18,45 @@ type FindATender struct { config *config.JobSearchConfig apiRoot string ctx context.Context + log *slog.Logger +} + +// Option configures a FindATender client. +type Option func(*FindATender) + +// WithLogger makes the client log to logger instead of slog.Default(). +func WithLogger(logger *slog.Logger) Option { + return func(ft *FindATender) { + ft.log = logger + } } // New returns a client for the OCDS API at apiRoot. Requests time out after -// 60 seconds and are retried once. Call Shutdown when finished with it. -func New(conf *config.JobSearchConfig, apiRoot string) *FindATender { +// 60 seconds and are retried once. Call Shutdown when finished with it. It +// logs to slog.Default() unless given WithLogger. +func New(conf *config.JobSearchConfig, apiRoot string, opts ...Option) *FindATender { ft := &FindATender{ config: conf, apiRoot: apiRoot, } + for _, opt := range opts { + opt(ft) + } ft.httpClient = resty.New(). SetTimeout(60 * time.Duration(time.Second)). SetRetryCount(1) return ft } +// logger returns the logger the client logs to, tagged with its component. +func (ft *FindATender) logger() *slog.Logger { + log := ft.log + if log == nil { + log = slog.Default() + } + return log.With("component", "findatender") +} + // ReloadConfig replaces the configuration the client reads, such as the log // level. The HTTP client and API root set by New are not changed. func (ft *FindATender) ReloadConfig(conf *config.JobSearchConfig) { @@ -55,7 +79,7 @@ func (ft *FindATender) With(ctx context.Context) *FindATender { // logged, as there is nothing a caller could do about it. func (ft *FindATender) Shutdown() { if err := ft.httpClient.Close(); err != nil { - slog.Warn("findatender: closing HTTP client", "error", err) + ft.logger().Warn("closing http client failed", "error", err) } } diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 9323cd2..47d7b53 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -2,6 +2,7 @@ package logging import ( "errors" + "fmt" "log/slog" "os" "path/filepath" @@ -19,6 +20,14 @@ var ( // fileLogger is the log file opened by LogToFile, or nil when logging // to the terminal. fileLogger *os.File + // terminal is where LogToTerminal and PrintToTerminal write. + terminal = os.Stdout + // isTerminal reports whether file is an interactive terminal rather than + // a file or pipe. Tests replace it. + isTerminal = func(file *os.File) bool { + info, err := file.Stat() + return err == nil && info.Mode()&os.ModeCharDevice != 0 + } ) // SetLevel sets the logging level without logging the change. @@ -31,7 +40,7 @@ func SetLevel(level slog.Level) { func EnableDebug() { if logLevel.Level() > slog.LevelDebug { logLevel.Set(slog.LevelDebug) - slog.Debug("Debug logging enabled") + slog.Debug("debug logging enabled") } } @@ -71,15 +80,59 @@ func Shutdown() error { } // LogToTerminal sends all logging to stdout as coloured text, replacing the -// default slog logger. +// default slog logger. When stdout is an interactive terminal, loggers +// derived from it report so to WritesToTerminal. func LogToTerminal() { opts := &tint.Options{ Level: &logLevel, TimeFormat: "*", } - handler := tint.NewTextHandler(os.Stdout, opts) - logger := slog.New(handler) - slog.SetDefault(logger) + handler := tint.NewTextHandler(terminal, opts) + if isTerminal(terminal) { + handler = terminalHandler{ + Handler: handler, + } + } + + slog.SetDefault(slog.New(handler)) +} + +// WritesToTerminal reports whether handler writes to an interactive +// terminal, where multi-line text (such as a trace) reads best printed as +// it is with PrintToTerminal, rather than escaped into a field. +func WritesToTerminal(handler slog.Handler) bool { + _, ok := handler.(terminalHandler) + return ok +} + +// PrintToTerminal writes text to the terminal as it is, on lines of its own. +// It is for detail that a handler would escape into one line; check +// WritesToTerminal first. +func PrintToTerminal(text string) { + fmt.Fprintln(terminal, text) //nolint:errcheck // nothing to do if the terminal has gone +} + +// ---------- terminalHandler ---------- + +// terminalHandler marks the handler LogToTerminal installs on an interactive +// terminal. WithAttrs and WithGroup keep the mark, so a logger derived with +// With still reports to WritesToTerminal. +type terminalHandler struct { + slog.Handler +} + +// WithAttrs implements slog.Handler, keeping the terminal mark. +func (h terminalHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return terminalHandler{ + Handler: h.Handler.WithAttrs(attrs), + } +} + +// WithGroup implements slog.Handler, keeping the terminal mark. +func (h terminalHandler) WithGroup(name string) slog.Handler { + return terminalHandler{ + Handler: h.Handler.WithGroup(name), + } } // IsJSONHandler reports whether h writes JSON, as the file logger does. diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go index 9606f7c..484d7dc 100644 --- a/internal/logging/logging_test.go +++ b/internal/logging/logging_test.go @@ -18,9 +18,11 @@ func saveGlobals(t *testing.T) { t.Helper() level := logLevel.Level() def := slog.Default() + out, detect := terminal, isTerminal t.Cleanup(func() { logLevel.Set(level) slog.SetDefault(def) + terminal, isTerminal = out, detect Shutdown() }) } @@ -155,3 +157,52 @@ func TestLogToTerminal(t *testing.T) { t.Fatal("terminal handler ignores the package level") } } + +// On an interactive terminal the handler, and loggers derived from it, report +// that they write to the terminal; when stdout is a file or pipe they don't. +func TestWritesToTerminal(t *testing.T) { + for _, interactive := range []bool{true, false} { + saveGlobals(t) + isTerminal = func(*os.File) bool { + return interactive + } + + LogToTerminal() + + derived := slog.Default().With("component", "test").WithGroup("g") + for name, h := range map[string]slog.Handler{ + "default": slog.Default().Handler(), + "derived": derived.Handler(), + } { + if got := WritesToTerminal(h); got != interactive { + t.Errorf( + "interactive %v, %s: WritesToTerminal = %v", + interactive, name, got, + ) + } + } + } + if WritesToTerminal(slog.DiscardHandler) { + t.Error("another handler reported as the terminal") + } +} + +func TestPrintToTerminal(t *testing.T) { + saveGlobals(t) + out, err := os.Create(filepath.Join(t.TempDir(), "terminal")) + if err != nil { + t.Fatal(err) + } + defer out.Close() + terminal = out + + PrintToTerminal("line one\nline two") + + got, err := os.ReadFile(out.Name()) + if err != nil { + t.Fatal(err) + } + if string(got) != "line one\nline two\n" { + t.Errorf("printed %q; want the text as it is, then a newline", got) + } +} diff --git a/internal/mock/findatender/generator.go b/internal/mock/findatender/generator.go index 16ca31e..2d23b94 100644 --- a/internal/mock/findatender/generator.go +++ b/internal/mock/findatender/generator.go @@ -4,7 +4,6 @@ import ( "context" "fmt" "hash/fnv" - "log" "math" "math/rand" "time" @@ -21,15 +20,18 @@ type Generator struct { cat *Catalog store *Store rnd *rand.Rand + opts options } // NewGenerator returns a generator drawing from cat and storing releases in -// store. The same seed and store contents give the same releases. -func NewGenerator(cat *Catalog, store *Store, seed int64) *Generator { +// store. The same seed and store contents give the same releases. It logs to +// slog.Default() unless given WithLogger. +func NewGenerator(cat *Catalog, store *Store, seed int64, opts ...Option) *Generator { return &Generator{ cat: cat, store: store, rnd: rand.New(rand.NewSource(seed)), //nolint:gosec // seeded for repeatable mock data + opts: applyOptions(opts), } } @@ -235,9 +237,10 @@ func (g *Generator) CatchUp( // Run publishes a new release after a random gap between min and max until ctx ends. func (g *Generator) Run(ctx context.Context, min, max time.Duration) { + logger := g.opts.logger("generator") for { d := g.gap(min, max) - log.Printf("generator: next release in %s", d.Round(time.Second)) + logger.Info("next release", "in", d.Round(time.Second)) timer := time.NewTimer(d) select { @@ -249,11 +252,11 @@ func (g *Generator) Run(ctx context.Context, min, max time.Duration) { r := g.Make(time.Now()) if err := g.store.Append(r); err != nil { - log.Printf("generator: storing release: %v", err) + logger.Error("storing release failed", "error", err) continue } - log.Printf("generator: published %s (%s) %s", r.ID, r.Tag[0], r.OCID) + logger.Info("published release", "release_id", r.ID, "tag", r.Tag[0], "ocid", r.OCID) } } diff --git a/internal/mock/findatender/handler.go b/internal/mock/findatender/handler.go index 8ce907b..a50e7b5 100644 --- a/internal/mock/findatender/handler.go +++ b/internal/mock/findatender/handler.go @@ -5,7 +5,6 @@ import ( "encoding/json" "errors" "fmt" - "log" "net/http" "net/url" "strconv" @@ -27,17 +26,20 @@ type server struct { store *Store baseURL string loc *time.Location // zone for updatedFrom/updatedTo without an offset; nil means UTC + opts options } // NewHandler serves release packages from store. baseURL is the public base // URL used in each package's uri and links.next. loc is the time zone that // updatedFrom and updatedTo are read in when they carry no offset, as the // documented yyyy-MM-ddTHH:mm:ss format doesn't (Europe/London for FTS). -// Stored release dates are UTC; comparisons are on absolute instants. +// Stored release dates are UTC; comparisons are on absolute instants. It +// logs to slog.Default() unless given WithLogger. func NewHandler( - store *Store, baseURL string, loc *time.Location, + store *Store, baseURL string, loc *time.Location, opts ...Option, ) http.HandlerFunc { - return (&server{store: store, baseURL: baseURL, loc: loc}).handle + s := &server{store: store, baseURL: baseURL, loc: loc, opts: applyOptions(opts)} + return s.handle } // encodeCursor makes the opaque cursor for a next link that resumes at store @@ -134,7 +136,7 @@ func (s *server) handle(w http.ResponseWriter, req *http.Request) { enc.SetIndent("", " ") enc.SetEscapeHTML(false) if err := enc.Encode(pkg); err != nil { - log.Printf("handler: writing response: %v", err) + s.opts.logger("handler").Warn("writing response failed", "error", err) } } diff --git a/internal/mock/findatender/options.go b/internal/mock/findatender/options.go new file mode 100644 index 0000000..5491408 --- /dev/null +++ b/internal/mock/findatender/options.go @@ -0,0 +1,40 @@ +package mock + +import ( + "log/slog" +) + +// Option configures a Store, Generator or handler. +type Option func(*options) + +// options holds the settings Options change. +type options struct { + log *slog.Logger +} + +// WithLogger makes a Store, Generator or handler log to logger instead of +// slog.Default(). +func WithLogger(logger *slog.Logger) Option { + return func(opts *options) { + opts.log = logger + } +} + +// applyOptions returns the settings opts make. +func applyOptions(opts []Option) options { + var settings options + for _, opt := range opts { + opt(&settings) + } + return settings +} + +// logger returns the logger to use, tagged with component: the given one, or +// slog.Default(), looked up now. +func (opts options) logger(component string) *slog.Logger { + log := opts.log + if log == nil { + log = slog.Default() + } + return log.With("component", component) +} diff --git a/internal/mock/findatender/store.go b/internal/mock/findatender/store.go index 3a9e11c..15693e8 100644 --- a/internal/mock/findatender/store.go +++ b/internal/mock/findatender/store.go @@ -6,7 +6,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "math/rand" "os" "path/filepath" @@ -33,19 +33,27 @@ type Store struct { // removing and picking one at random are all constant time. open []string openPos map[string]int + + opts options } // OpenStore loads the releases stored at path, creating the file and its // directory if needed, and opens it for appending. Lines that can't be read // are skipped, releases are put back in date order if needed, and a record // left incomplete by a crash is ended so new ones start on a fresh line. -func OpenStore(path string) (*Store, error) { - s := &Store{latest: map[string]int{}, lastNum: map[int]int{}, openPos: map[string]int{}} +// It logs to slog.Default() unless given WithLogger. +func OpenStore(path string, opts ...Option) (*Store, error) { + s := &Store{ + latest: map[string]int{}, + lastNum: map[int]int{}, + openPos: map[string]int{}, + opts: applyOptions(opts), + } if err := os.MkdirAll(filepath.Dir(path), 0o750); err != nil { return nil, err } - releases, err := readReleases(path) + releases, err := readReleases(s.opts.logger("store"), path) if err != nil { return nil, err } @@ -67,9 +75,10 @@ func OpenStore(path string) (*Store, error) { return s, nil } -// readReleases reads the releases stored at path, skipping lines that are -// blank or can't be decoded. A missing file holds no releases. -func readReleases(path string) ([]ocds.Release, error) { +// readReleases reads the releases stored at path, skipping blank lines and +// lines that can't be decoded (which are logged to logger). A missing file +// holds no releases. +func readReleases(logger *slog.Logger, path string) ([]ocds.Release, error) { in, err := os.Open(filepath.Clean(path)) if os.IsNotExist(err) { return nil, nil @@ -89,7 +98,7 @@ func readReleases(path string) ([]ocds.Release, error) { } var r ocds.Release if err := json.Unmarshal(b, &r); err != nil { - log.Printf("store: skipping unreadable line %d: %v", line, err) + logger.Warn("skipping unreadable line", "line", line, "error", err) continue } releases = append(releases, r) diff --git a/internal/util/worker.go b/internal/util/worker.go index 5b11c36..5e628d1 100644 --- a/internal/util/worker.go +++ b/internal/util/worker.go @@ -36,6 +36,9 @@ type Worker struct { ShutdownTimeout time.Duration // Task is the work to perform on each tick. Task Task + // Logger is what the worker logs to; nil means slog.Default(), looked up + // when Run starts. + Logger *slog.Logger } // Run executes Task immediately, then once per Interval, until ctx is @@ -55,7 +58,11 @@ func (w Worker) Run(ctx context.Context, since time.Time) error { timeout = DefaultWorkerShutdownTimeout } - logger := slog.With("source", w.Name) + logger := w.Logger + if logger == nil { + logger = slog.Default() + } + logger = logger.With("source", w.Name) logger.Info("starting worker", "since", since, "interval", w.Interval) // workCtx is NOT cancelled immediately when ctx is. It gives an in-flight @@ -123,7 +130,7 @@ func (w Worker) execute( logger.Warn("task cancelled", "elapsed", elapsed) return since default: - logger.Error("task failed", "err", err, "elapsed", elapsed) + logger.Error("task failed", "error", err, "elapsed", elapsed) return since } } diff --git a/internal/websocket/client.go b/internal/websocket/client.go index f5b9519..4052dda 100644 --- a/internal/websocket/client.go +++ b/internal/websocket/client.go @@ -106,7 +106,7 @@ func (c *client) run(ctx context.Context) { // consumer), after a failed write or ping, or by the caller. c.conn.CloseNow() //nolint:errcheck,gosec // finished with; it may already be closed default: - c.hub.log.Debug("read error", "client", c.id, "error", err) + c.hub.logger().Debug("read error", "client", c.id, "error", err) c.conn.CloseNow() //nolint:errcheck,gosec // the connection has failed anyway } @@ -178,7 +178,7 @@ func (c *client) writeLoop(ctx context.Context) { err := c.conn.Write(writeCtx, websocket.MessageText, msg) cancel() if err != nil { - c.hub.log.Debug("write failed", "client", c.id, "error", err) + c.hub.logger().Debug("write failed", "client", c.id, "error", err) c.cancel() return } @@ -215,7 +215,7 @@ func (c *client) pingLoop(ctx context.Context) { err := c.conn.Ping(pingCtx) cancel() if err != nil { - c.hub.log.Debug("ping failed", "client", c.id, "error", err) + c.hub.logger().Debug("ping failed", "client", c.id, "error", err) c.conn.CloseNow() //nolint:errcheck,gosec // dropping the client anyway c.cancel() return @@ -240,11 +240,11 @@ func (c *client) trySend(msg []byte) bool { func (c *client) sendEnvelope(env Envelope) { encoded, err := json.Marshal(env) if err != nil { - c.hub.log.Error("marshal", "client", c.id, "error", err) + c.hub.logger().Error("marshal", "client", c.id, "error", err) return } if !c.trySend(encoded) { - c.hub.log.Warn("dropping slow client", "client", c.id, "ip", c.ip) + c.hub.logger().Warn("dropping slow client", "client", c.id, "ip", c.ip) go c.close(websocket.StatusPolicyViolation, "slow consumer") } } @@ -273,14 +273,18 @@ func (c *client) close(code websocket.StatusCode, reason string) { // level, with its size; at most logMessageLimit bytes of it are logged. It // does nothing unless debug logging is enabled. func (c *client) logMessage(ctx context.Context, event string, data []byte) { - if !c.hub.log.Enabled(ctx, slog.LevelDebug) { + logger := c.hub.logger() + if !logger.Enabled(ctx, slog.LevelDebug) { return } logged, truncated := data, false if len(logged) > logMessageLimit { logged, truncated = logged[:logMessageLimit], true } - c.hub.log.LogAttrs(ctx, slog.LevelDebug, event, + logger.LogAttrs( + ctx, + slog.LevelDebug, + event, slog.String("client", c.id), slog.Int("bytes", len(data)), slog.String("message", string(logged)), diff --git a/internal/websocket/client_test.go b/internal/websocket/client_test.go index 38dc770..6d6d6f2 100644 --- a/internal/websocket/client_test.go +++ b/internal/websocket/client_test.go @@ -44,7 +44,7 @@ func (f *fakeConn) CloseNow() error { return nil } // newTestClient returns a client of a new hub on f, with no loops running, // and its context. func newTestClient(f *fakeConn) (*client, context.Context) { - h := NewHub(config.JSCServerWebSocket{}, discardLog) + h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog)) ctx, cancel := context.WithCancel(context.Background()) return newClient(h, f, "192.0.2.1", cancel), ctx } @@ -114,7 +114,7 @@ func TestClientMessageRateLimit(t *testing.T) { {config.JSCRateLimitRule{Enabled: true, PerSecond: 1, Burst: 1}, true}, } for _, tt := range tests { - h := NewHub(config.JSCServerWebSocket{MessageRateLimit: tt.rule}, discardLog) + h := NewHub(config.JSCServerWebSocket{MessageRateLimit: tt.rule}, WithLogger(discardLog)) c := newClient(h, newFakeConn(), "", func() {}) c.limiter.Allow() if limited := !c.limiter.Allow(); limited != tt.limited { @@ -193,7 +193,7 @@ func jsonLog(level slog.Level) (*slog.Logger, *syncBuffer) { // At debug level, messages received from and sent to a client are logged. func TestLogMessages(t *testing.T) { log, buf := jsonLog(slog.LevelDebug) - h := NewHub(config.JSCServerWebSocket{WriteTimeout: time.Second}, log) + h := NewHub(config.JSCServerWebSocket{WriteTimeout: time.Second}, WithLogger(log)) peer, _ := pipeClient(t, h) ping := `{"type":"ping","id":"1"}` @@ -235,7 +235,7 @@ func TestLogMessages(t *testing.T) { // unless debug logging is on. func TestLogMessageLimit(t *testing.T) { log, buf := jsonLog(slog.LevelDebug) - h := NewHub(config.JSCServerWebSocket{}, log) + h := NewHub(config.JSCServerWebSocket{}, WithLogger(log)) c := newClient(h, newFakeConn(), "", func() {}) long := strings.Repeat("x", logMessageLimit+100) c.logMessage(context.Background(), "message sent", []byte(long)) @@ -251,7 +251,7 @@ func TestLogMessageLimit(t *testing.T) { } log, buf = jsonLog(slog.LevelInfo) - c.hub = NewHub(config.JSCServerWebSocket{}, log) + c.hub = NewHub(config.JSCServerWebSocket{}, WithLogger(log)) c.logMessage(context.Background(), "message sent", []byte("x")) if entries := buf.entries(t); len(entries) != 0 { t.Errorf("logged %v at info level", entries) diff --git a/internal/websocket/http.go b/internal/websocket/http.go index 85240bf..6344fe4 100644 --- a/internal/websocket/http.go +++ b/internal/websocket/http.go @@ -22,7 +22,7 @@ func (h *Hub) ServeHTTP(w http.ResponseWriter, r *http.Request) { CompressionMode: mode, }) if err != nil { - h.log.Debug("upgrade failed", "error", err) + h.logger().Debug("upgrade failed", "error", err) return // Accept has already written the HTTP error. } defer conn.CloseNow() //nolint:errcheck // finished with; it may already be closed @@ -39,7 +39,7 @@ func (h *Hub) ServeHTTP(w http.ResponseWriter, r *http.Request) { } defer h.unregister(c) - h.log.Info("client connected", "client", c.id, "ip", ip) + h.logger().Info("client connected", "client", c.id, "ip", ip) c.run(ctx) - h.log.Info("client disconnected", "client", c.id, "ip", ip) + h.logger().Info("client disconnected", "client", c.id, "ip", ip) } diff --git a/internal/websocket/http_test.go b/internal/websocket/http_test.go index 70a3d59..53bdecd 100644 --- a/internal/websocket/http_test.go +++ b/internal/websocket/http_test.go @@ -46,7 +46,7 @@ func dialWS(t *testing.T, ctx context.Context, url string) *ws.Conn { // A client upgraded over HTTP gets replies. A max_message_size of 0 uses the // default limit rather than refusing every message. func TestHTTPMessages(t *testing.T) { - h := NewHub(config.JSCServerWebSocket{WriteTimeout: time.Second}, discardLog) + h := NewHub(config.JSCServerWebSocket{WriteTimeout: time.Second}, WithLogger(discardLog)) url := wsHub(t, h) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) defer cancel() @@ -98,7 +98,7 @@ func TestPushBadPayload(t *testing.T) { // A binary frame closes the connection with 1003 (unsupported data). func TestHTTPBinaryFrame(t *testing.T) { - h := NewHub(config.JSCServerWebSocket{WriteTimeout: time.Second}, discardLog) + h := NewHub(config.JSCServerWebSocket{WriteTimeout: time.Second}, WithLogger(discardLog)) url := wsHub(t, h) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) defer cancel() @@ -120,7 +120,7 @@ func TestHTTPMessageRateLimit(t *testing.T) { WriteTimeout: time.Second, MessageRateLimit: config.JSCRateLimitRule{Enabled: true, PerSecond: 1, Burst: 1}, } - h := NewHub(conf, discardLog) + h := NewHub(conf, WithLogger(discardLog)) url := wsHub(t, h) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) defer cancel() @@ -147,7 +147,7 @@ func TestHTTPMessageRateLimit(t *testing.T) { // A request that isn't a WebSocket upgrade is refused by the upgrade and no // client is registered. func TestHTTPNotAnUpgrade(t *testing.T) { - h := NewHub(config.JSCServerWebSocket{}, discardLog) + h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog)) srv := httptest.NewServer(h) defer srv.Close() res, err := http.Get(srv.URL) @@ -166,7 +166,7 @@ func TestHTTPNotAnUpgrade(t *testing.T) { // After Shutdown, an upgrade succeeds but the client is closed at once with // 1001 (going away). func TestHTTPRefusedAfterShutdown(t *testing.T) { - h := NewHub(config.JSCServerWebSocket{}, discardLog) + h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog)) url := wsHub(t, h) if err := h.Shutdown(context.Background()); err != nil { t.Fatal(err) diff --git a/internal/websocket/hub.go b/internal/websocket/hub.go index 69ddb66..bf74e53 100644 --- a/internal/websocket/hub.go +++ b/internal/websocket/hub.go @@ -27,13 +27,35 @@ type Hub struct { // max_message_size is not set. const defaultMaxMessageSize = 32 << 10 -// NewHub creates a hub. -func NewHub(conf config.JSCServerWebSocket, log *slog.Logger) *Hub { - return &Hub{ +// Option configures a Hub. +type Option func(*Hub) + +// WithLogger makes the hub log to logger instead of slog.Default(). +func WithLogger(logger *slog.Logger) Option { + return func(h *Hub) { + h.log = logger + } +} + +// NewHub creates a hub. It logs to slog.Default() unless given WithLogger. +func NewHub(conf config.JSCServerWebSocket, opts ...Option) *Hub { + hub := &Hub{ conf: conf, - log: log.With("component", "ws"), clients: make(map[*client]struct{}), } + for _, opt := range opts { + opt(hub) + } + return hub +} + +// logger returns the logger the hub logs to, tagged with its component. +func (h *Hub) logger() *slog.Logger { + log := h.log + if log == nil { + log = slog.Default() + } + return log.With("component", "ws") } // Push sends a message of type msgType to every client. The payload is @@ -45,7 +67,7 @@ func (h *Hub) Push(msgType string, payload any) { if payload != nil { var err error if rawPayload, err = json.Marshal(payload); err != nil { - h.log.Error("marshal push payload", "type", msgType, "error", err) + h.logger().Error("marshal push payload", "type", msgType, "error", err) return } } @@ -55,7 +77,7 @@ func (h *Hub) Push(msgType string, payload any) { Payload: rawPayload, }) if err != nil { - h.log.Error("marshal push", "type", msgType, "error", err) + h.logger().Error("marshal push", "type", msgType, "error", err) return } @@ -69,7 +91,7 @@ func (h *Hub) Push(msgType string, payload any) { h.m.RUnlock() for _, client := range slow { - h.log.Warn("dropping slow client", "client", client.id, "ip", client.ip) + h.logger().Warn("dropping slow client", "client", client.id, "ip", client.ip) go client.close(ws.StatusPolicyViolation, "slow consumer") } } diff --git a/internal/websocket/hub_test.go b/internal/websocket/hub_test.go index 1ee2108..07a0851 100644 --- a/internal/websocket/hub_test.go +++ b/internal/websocket/hub_test.go @@ -32,7 +32,7 @@ func pipeClient(t *testing.T, h *Hub) (net.Conn, chan struct{}) { // once and returns ctx's error. func TestShutdownTimeout(t *testing.T) { // No write timeout: the client's goodbye blocks until it is cut short. - h := NewHub(config.JSCServerWebSocket{}, discardLog) + h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog)) _, done := pipeClient(t, h) ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) @@ -49,7 +49,7 @@ func TestShutdownTimeout(t *testing.T) { // Shutdown with no clients returns at once, even with an expired ctx. func TestShutdownNoClients(t *testing.T) { - h := NewHub(config.JSCServerWebSocket{}, discardLog) + h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog)) ctx, cancel := context.WithCancel(context.Background()) cancel() for range 20 { @@ -64,7 +64,7 @@ func TestPingFailureDropsClient(t *testing.T) { h := NewHub(config.JSCServerWebSocket{ PingInterval: 10 * time.Millisecond, PongTimeout: 20 * time.Millisecond, - }, discardLog) + }, WithLogger(discardLog)) _, done := pipeClient(t, h) select { @@ -85,7 +85,7 @@ func TestMaxMessageSize(t *testing.T) { {config.JSCServerWebSocket{MaxMessageSize: 100}, 100}, } for _, tt := range tests { - h := NewHub(tt.conf, discardLog) + h := NewHub(tt.conf, WithLogger(discardLog)) if got := h.maxMessageSize(); got != tt.want { t.Errorf("maxMessageSize(%d) = %d; want %d", tt.conf.MaxMessageSize, got, tt.want) } diff --git a/internal/websocket/tcp.go b/internal/websocket/tcp.go index f06b7cf..ab5604d 100644 --- a/internal/websocket/tcp.go +++ b/internal/websocket/tcp.go @@ -71,10 +71,10 @@ func (h *Hub) ServeTCP(ctx context.Context, newConn net.Conn) { } defer h.unregister(client) - h.log.Info("client connected", "client", client.id, "ip", ip, "transport", "tcp") + h.logger().Info("client connected", "client", client.id, "ip", ip, "transport", "tcp") client.run(ctx) conn.CloseNow() //nolint:errcheck,gosec // finished with; it may already be closed - h.log.Info("client disconnected", "client", client.id, "ip", ip, "transport", "tcp") + h.logger().Info("client disconnected", "client", client.id, "ip", ip, "transport", "tcp") } // ---------- tcpConn ---------- diff --git a/internal/websocket/tcp_test.go b/internal/websocket/tcp_test.go index 2fa6ef9..e94790c 100644 --- a/internal/websocket/tcp_test.go +++ b/internal/websocket/tcp_test.go @@ -31,7 +31,7 @@ func tcpHub(t *testing.T, mutate func(*config.JSCServerWebSocket)) (*Hub, string if mutate != nil { mutate(&conf) } - h := NewHub(conf, discardLog) + h := NewHub(conf, WithLogger(discardLog)) ln, err := net.Listen("tcp", "127.0.0.1:0") if err != nil { t.Fatal(err) @@ -243,7 +243,9 @@ func TestTCPPing(t *testing.T) { // A client that doesn't read is dropped as a slow consumer once its queue is // full. net.Pipe has no buffer, so writes to it block until the peer reads. func TestTCPSlowConsumer(t *testing.T) { - h := NewHub(config.JSCServerWebSocket{WriteTimeout: 50 * time.Millisecond}, discardLog) + h := NewHub( + config.JSCServerWebSocket{WriteTimeout: 50 * time.Millisecond}, WithLogger(discardLog), + ) server, peer := net.Pipe() t.Cleanup(func() { server.Close(); peer.Close() }) done := make(chan struct{}) diff --git a/internal/websocket/tcpserver/server.go b/internal/websocket/tcpserver/server.go index ecce52f..4be4965 100644 --- a/internal/websocket/tcpserver/server.go +++ b/internal/websocket/tcpserver/server.go @@ -33,15 +33,38 @@ type Server struct { hub *websocket.Hub } +// Option configures a Server. +type Option func(*Server) + +// WithLogger makes the server log to logger instead of slog.Default(). +func WithLogger(logger *slog.Logger) Option { + return func(s *Server) { + s.log = logger + } +} + // New builds a server for hub's plain TCP clients. Run starts it; it shuts // hub down when it stops, so hub should not be shared with another server. -// Push to hub to reach the server's clients. -func New(conf *config.JSCServer, hub *websocket.Hub, log *slog.Logger) *Server { - return &Server{ +// Push to hub to reach the server's clients. It logs to slog.Default() +// unless given WithLogger. +func New(conf *config.JSCServer, hub *websocket.Hub, opts ...Option) *Server { + server := &Server{ conf: conf, - log: log, hub: hub, } + for _, opt := range opts { + opt(server) + } + return server +} + +// logger returns the logger the server logs to, tagged with its component. +func (s *Server) logger() *slog.Logger { + log := s.log + if log == nil { + log = slog.Default() + } + return log.With("component", "tcp") } // Run listens on the configured host and port and serves plain TCP clients @@ -71,14 +94,14 @@ func (s *Server) serve(ctx context.Context, listen net.Listener) error { }) defer stop() - s.log.Info("listening", "addr", listen.Addr().String()) + s.logger().Info("listening", "addr", listen.Addr().String()) acceptErr := s.accept(ctx, connCtx, listen) if ctx.Err() != nil { acceptErr = nil // cancelling ctx is how the server is stopped } listen.Close() //nolint:errcheck,gosec // closed already when ctx was cancelled - s.log.Info("shutting down") + s.logger().Info("shutting down") shutdownCtx := context.Background() if s.conf.Timeouts.ShutdownTimeout > 0 { var cancel context.CancelFunc @@ -117,7 +140,7 @@ func (s *Server) accept( // Back off and retry e.g. when out of file descriptors. delay = min(max(2*delay, 5*time.Millisecond), time.Second) - s.log.Warn("tcp accept failed", "error", err, "retry_in", delay) + s.logger().Warn("tcp accept failed", "error", err, "retry_in", delay) select { case <-time.After(delay): @@ -131,7 +154,7 @@ func (s *Server) accept( if limiter != nil { ip := remoteIP(newConn) if allowed, _ := limiter.Allow(ip); !allowed { - s.log.Warn("tcp connection rate limited", "ip", ip) + s.logger().Warn("tcp connection rate limited", "ip", ip) go reject(newConn, "rate limited") continue } diff --git a/internal/websocket/tcpserver/server_test.go b/internal/websocket/tcpserver/server_test.go index be4dbfd..570af84 100644 --- a/internal/websocket/tcpserver/server_test.go +++ b/internal/websocket/tcpserver/server_test.go @@ -36,8 +36,8 @@ func testConf(mutate func(*config.JSCServer)) *config.JSCServer { // newServer returns a server for conf with its own hub. func newServer(conf *config.JSCServer) (*Server, *websocket.Hub) { - h := websocket.NewHub(conf.WebSocket, discardLog) - return New(conf, h, discardLog), h + h := websocket.NewHub(conf.WebSocket, websocket.WithLogger(discardLog)) + return New(conf, h, WithLogger(discardLog)), h } // startServer serves on a local port, returning the server's hub, its