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.
This commit is contained in:
bwilliams committed 2026-10-15 16:10:52 +01:00
1 parent 0b5fde9563
commit 043e307663
49 files changed
+598 -248

No files matched your search

+4 -5
View File
@@ -52,17 +52,16 @@ opportunities.
PersistentPreRunE: func(cmd *cobra.Command, args []string) error { PersistentPreRunE: func(cmd *cobra.Command, args []string) error {
cli.SetupInitialLogging(cmd) cli.SetupInitialLogging(cmd)
slog.Debug("root.PersistentPreRun") slog.Debug("command persistent pre-run", "command", "root")
slog.Debug( slog.Debug(
"command: \"" + "command",
strings.Join(strings.Split(cmd.CommandPath(), " ")[1:], " ") + "path", strings.Join(strings.Split(cmd.CommandPath(), " ")[1:], " "),
"\"",
) )
return nil return nil
}, },
PersistentPostRunE: func(cmd *cobra.Command, args []string) error { PersistentPostRunE: func(cmd *cobra.Command, args []string) error {
slog.Debug("root.PersistentPostRun") slog.Debug("command persistent post-run", "command", "root")
return opts.Finish() return opts.Finish()
}, },
+12 -13
View File
@@ -24,6 +24,7 @@ import (
"errors" "errors"
"fmt" "fmt"
"log" "log"
"log/slog"
"net/http" "net/http"
"os" "os"
"os/signal" "os/signal"
@@ -206,15 +207,13 @@ func run(ctx context.Context, o *options) (err error) {
if err != nil { if err != nil {
return err return err
} }
log.Printf( slog.Info(
"catalog: %d buyers, %d suppliers, %d subjects, %d methods, %d classifications", "catalog loaded",
len( "buyers", len(cat.Buyers),
cat.Buyers, "suppliers", len(cat.Suppliers),
), "subjects", len(cat.Subjects),
len(cat.Suppliers), "methods", len(cat.Methods),
len(cat.Subjects), "classifications", len(cat.Classifications),
len(cat.Methods),
len(cat.Classifications),
) )
// ----- store ----- // ----- 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) { if err := os.Remove(storePath); err != nil && !errors.Is(err, os.ErrNotExist) {
return err return err
} }
log.Print("store: reset") slog.Info("store reset", "path", storePath)
} }
store, err := mock.OpenStore(storePath) store, err := mock.OpenStore(storePath)
if err != nil { if err != nil {
@@ -238,7 +237,7 @@ func run(ctx context.Context, o *options) (err error) {
return err 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 // The generator and server share a context that also ends if the server
// fails, so the generator is never left running after run returns. // 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() defer cancelShutdown()
if err := httpSrv.Shutdown(shutdownCtx); err != nil { 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() serveErr := httpSrv.ListenAndServe()
cancel() // stop the worker (and the shutdown goroutine) if the server failed cancel() // stop the worker (and the shutdown goroutine) if the server failed
+2 -2
View File
@@ -14,10 +14,10 @@ func NewCommand(opts *cli.Options) *cobra.Command {
Use: "config", Use: "config",
Short: "Configuration management", Short: "Configuration management",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { PersistentPostRun: func(cmd *cobra.Command, args []string) {
slog.Debug("config.PersistentPostRun") slog.Debug("command persistent post-run", "command", "config")
}, },
} }
cmd.AddCommand(commandShow(opts)) cmd.AddCommand(commandShow(opts))
+3 -3
View File
@@ -15,13 +15,13 @@ func commandGet(opts *cli.Options) *cobra.Command {
Args: cobra.ExactArgs(1), Args: cobra.ExactArgs(1),
Short: "Get a value from configuration", Short: "Get a value from configuration",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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 { if err := cobra.ExactArgs(1)(cmd, args); err != nil {
return err return err
+3 -3
View File
@@ -19,13 +19,13 @@ func commandInit() *cobra.Command {
Args: cobra.MatchAll(cobra.MinimumNArgs(0), cobra.MaximumNArgs(1)), Args: cobra.MatchAll(cobra.MinimumNArgs(0), cobra.MaximumNArgs(1)),
Short: "Create an empty configuration file", Short: "Create an empty configuration file",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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 { if err := cobra.MinimumNArgs(0)(cmd, args); err != nil {
return err return err
+3 -3
View File
@@ -18,13 +18,13 @@ func commandSet(opts *cli.Options) *cobra.Command {
Args: cobra.MatchAll(cobra.MinimumNArgs(1), cobra.MaximumNArgs(2)), Args: cobra.MatchAll(cobra.MinimumNArgs(1), cobra.MaximumNArgs(2)),
Short: "Set a value to configuration", Short: "Set a value to configuration",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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 { if err := cobra.MinimumNArgs(1)(cmd, args); err != nil {
return err return err
+3 -3
View File
@@ -14,13 +14,13 @@ func commandShow(opts *cli.Options) *cobra.Command {
Use: "show", Use: "show",
Short: "Print config information", Short: "Print config information",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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) conf, err := opts.RunSetup(cmd, true, true)
if err != nil { if err != nil {
+3 -2
View File
@@ -3,7 +3,7 @@ package cli
import ( import (
"bufio" "bufio"
"fmt" "fmt"
"log" "log/slog"
"os" "os"
"strings" "strings"
) )
@@ -19,7 +19,8 @@ func Confirm(s string) bool {
response, err := reader.ReadString('\n') response, err := reader.ReadString('\n')
if err != nil { if err != nil {
log.Fatal(err) slog.Error("reading the answer", "error", err)
os.Exit(1)
} }
response = strings.ToLower(strings.TrimSpace(response)) response = strings.ToLower(strings.TrimSpace(response))
+2 -2
View File
@@ -14,10 +14,10 @@ func NewCommand(opts *cli.Options) *cobra.Command {
Use: "fetch", Use: "fetch",
Short: "Fetch current opportunities", Short: "Fetch current opportunities",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { PersistentPostRun: func(cmd *cobra.Command, args []string) {
slog.Debug("fetch.PersistentPostRun") slog.Debug("command persistent post-run", "command", "fetch")
}, },
} }
cmd.AddCommand(commandOnce(opts)) cmd.AddCommand(commandOnce(opts))
+3 -3
View File
@@ -53,13 +53,13 @@ func commandOnce(opts *cli.Options) *cobra.Command {
Use: "once", Use: "once",
Short: "Fetch current opportunities - single shot", Short: "Fetch current opportunities - single shot",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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) conf, err := opts.RunSetup(cmd, true, true)
if err != nil { if err != nil {
+3 -3
View File
@@ -20,13 +20,13 @@ func commandService(opts *cli.Options) *cobra.Command {
Use: "service", Use: "service",
Short: "Fetch current opportunities - background service", Short: "Fetch current opportunities - background service",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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") foreground, _ := cmd.Flags().GetBool("foreground")
+3 -3
View File
@@ -21,13 +21,13 @@ func commandDown(opts *cli.Options) *cobra.Command {
confirmed by providing -yes.`, confirmed by providing -yes.`,
Args: cobra.NoArgs, Args: cobra.NoArgs,
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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) { 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") yes, _ := cmd.Flags().GetBool("yes")
steps, _ := cmd.Flags().GetUint("steps") steps, _ := cmd.Flags().GetUint("steps")
+3 -3
View File
@@ -26,13 +26,13 @@ Running without a subcommand is the same as running "migrate up": every pending
migration is applied.`, migration is applied.`,
Args: cobra.NoArgs, Args: cobra.NoArgs,
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { RunE: func(cmd *cobra.Command, args []string) error {
slog.Debug("migrate.Run") slog.Debug("command run", "command", "migrate")
return runStepUp(cmd, opts, 0, false) return runStepUp(cmd, opts, 0, false)
}, },
} }
+3 -3
View File
@@ -75,13 +75,13 @@ func commandStatus(opts *cli.Options) *cobra.Command {
Short: "Show which migrations have been applied to the SQLite database", Short: "Show which migrations have been applied to the SQLite database",
Args: cobra.NoArgs, Args: cobra.NoArgs,
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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) { 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) m, db, err := openMigrator(cmd, opts, false, false)
if err != nil { if err != nil {
+3 -3
View File
@@ -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", Short: "Migrate SQLite database to the latest version, or by a number of steps",
Args: cobra.NoArgs, Args: cobra.NoArgs,
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { 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") steps, _ := cmd.Flags().GetUint("steps")
create, _ := cmd.Flags().GetBool("create") create, _ := cmd.Flags().GetBool("create")
+1 -1
View File
@@ -65,7 +65,7 @@ func (o *Options) RunSetup(
// Check if the logging should be switched to file // Check if the logging should be switched to file
if !terminalLog { if !terminalLog {
if len(conf.Logging.File) == 0 { 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 { } else if err := logging.LogToFile(conf.Logging.File); err != nil {
return nil, fmt.Errorf("opening log file: %w", err) return nil, fmt.Errorf("opening log file: %w", err)
} }
+3 -3
View File
@@ -16,13 +16,13 @@ func NewCommand() *cobra.Command {
Short: "Print version information", Short: "Print version information",
SilenceUsage: true, SilenceUsage: true,
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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) { Run: func(cmd *cobra.Command, args []string) {
slog.Debug("version.Run") slog.Debug("command run", "command", "version")
fmt.Printf("JobSearch - %s\n", version.Version) fmt.Printf("JobSearch - %s\n", version.Version)
if version.BuildTime != "unknown" { if version.BuildTime != "unknown" {
+5 -5
View File
@@ -22,13 +22,13 @@ func NewCommand(opts *cli.Options) *cobra.Command {
Use: "wsserve", Use: "wsserve",
Short: "Run JobSearch TCP Websocket server", Short: "Run JobSearch TCP Websocket server",
PersistentPreRun: func(cmd *cobra.Command, args []string) { 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) { 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 { RunE: func(cmd *cobra.Command, args []string) error {
slog.Debug("wsserve.Run") slog.Debug("command run", "command", "wsserve")
addrOverride, _ := cmd.Flags().GetString("listen") addrOverride, _ := cmd.Flags().GetString("listen")
hostOverride, _ := cmd.Flags().GetString("host") hostOverride, _ := cmd.Flags().GetString("host")
@@ -74,8 +74,8 @@ func NewCommand(opts *cli.Options) *cobra.Command {
stop() stop()
}() }()
hub := websocket.NewHub(conf.Server.WebSocket, slog.Default()) hub := websocket.NewHub(conf.Server.WebSocket)
svr := tcpserver.New(&conf.Server, hub, slog.Default()) svr := tcpserver.New(&conf.Server, hub)
return svr.Run(ctx) return svr.Run(ctx)
}, },
+2 -2
View File
@@ -70,11 +70,11 @@ func LoadFromViper(conf *JobSearchConfig) {
} }
value, ok := viperValue(key, keyType) value, ok := viperValue(key, keyType)
if !ok { if !ok {
slog.Error(fmt.Sprintf("unknown key type: %s", keyType)) slog.Error("unknown config key type", "key", key, "kind", keyType.String())
continue continue
} }
if err := conf.SetValue(key, value); err != nil { 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)
} }
} }
} }
+62 -21
View File
@@ -1,6 +1,7 @@
package config package config
import ( import (
"context"
"fmt" "fmt"
"log/slog" "log/slog"
"os" "os"
@@ -9,41 +10,81 @@ import (
"strings" "strings"
"github.com/spf13/viper" "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() { func printEnv() {
slog.Debug("Environment:") logger := slog.Default()
env := os.Environ() terminal := logging.WritesToTerminal(logger.Handler())
slices.Sort(env) if terminal && !logger.Enabled(context.Background(), slog.LevelDebug) {
for _, e := range env { return
pair := strings.SplitN(e, "=", 2) }
if strings.HasPrefix(pair[0], EnvPrefix) {
slog.Debug("\t" + pair[0] + "=" + pair[1]) 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 // 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 <type>" lines; elsewhere each value is a log entry of its own.
func printLoadedConfig() { func printLoadedConfig() {
slog.Debug("Loaded config:") logger := slog.Default()
keys := viper.AllKeys() terminal := logging.WritesToTerminal(logger.Handler())
for i := range keys { if terminal && !logger.Enabled(context.Background(), slog.LevelDebug) {
k := keys[i] return
if isExplicitlySet(k) { }
v := viper.Get(k)
t := reflect.TypeOf(v) var keys []string
slog.Debug( for _, key := range viper.AllKeys() {
"\t" + k + " = " + fmt.Sprintf("%#v", v) + if isExplicitlySet(key) {
" <" + t.Kind().String() + ">", 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. // printConfig logs conf at debug level.
func printConfig(conf JobSearchConfig) { func printConfig(conf JobSearchConfig) {
slog.Debug("Config:")
conf.PrintLog(slog.LevelDebug) conf.PrintLog(slog.LevelDebug)
} }
+2 -2
View File
@@ -68,14 +68,14 @@ func loadConfig(cfgFile string) error {
if _, ok := err.(viper.ConfigFileNotFoundError); ok { if _, ok := err.(viper.ConfigFileNotFoundError); ok {
// Indicates an explicitly set config file is not found or // Indicates an explicitly set config file is not found or
// that no config file was found in any search path // 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 { } else {
// Config file was found but another error was produced // Config file was found but another error was produced
return err return err
} }
} else { } else {
// Config file found and successfully parsed // Config file found and successfully parsed
slog.Info("Using config file: " + viper.ConfigFileUsed()) slog.Info("using config file", "file", viper.ConfigFileUsed())
} }
return nil return nil
} }
+5 -5
View File
@@ -93,7 +93,7 @@ func TestInitNoConfigFile(t *testing.T) {
if err := Init("", &conf); err != nil { if err := Init("", &conf); err != nil {
t.Fatal(err) 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) t.Errorf("no warning logged: %s", logs)
} }
if conf.Logging.Level != "warn" { 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) t.Errorf("Logging.Level = %q; want %s kept", conf.Logging.Level, level)
} }
// At debug, the environment and loaded config are logged. // 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") { if gotDebug != (level == "debug") {
t.Errorf("debug output logged = %v at level %s: %s", gotDebug, level, logs) 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() out := logs.String()
for _, want := range []string{ for _, want := range []string{
`logging.level = \"info\" <string>`, `key=logging.level value=info type=string`,
`server.websocket.connection_limit.enabled = true <bool>`, `key=server.websocket.connection_limit.enabled value=true type=bool`,
`database.file = \"/tmp/js.db\" <string>`, `key=database.file value=/tmp/js.db type=string`,
} { } {
if !strings.Contains(out, want) { if !strings.Contains(out, want) {
t.Errorf("missing %q in:\n%s", want, out) t.Errorf("missing %q in:\n%s", want, out)
+25 -20
View File
@@ -1,10 +1,13 @@
package config package config
import ( import (
"context"
"fmt" "fmt"
"log/slog" "log/slog"
"maps" "maps"
"slices" "slices"
"git.avsdev.uk/Go/job-search/internal/logging"
) )
// PrintTerminal prints the configuration to stdout as String formats it. // 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: // 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) { func (conf JobSearchConfig) PrintLog(atLevel slog.Level) {
var logFn func(args ...interface{})
switch atLevel { switch atLevel {
case slog.LevelDebug: case slog.LevelDebug, slog.LevelWarn, slog.LevelError:
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...))
}
default: default:
logFn = func(args ...interface{}) { atLevel = slog.LevelInfo
slog.Info(fmt.Sprint(args...))
}
} }
ctx := context.Background()
logger := slog.Default()
flat := conf.Flatten() flat := conf.Flatten()
for _, k := range slices.Sorted(maps.Keys(flat)) { keys := slices.Sorted(maps.Keys(flat))
logFn("\t", k, " = ", flat[k])
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])
} }
} }
+4 -4
View File
@@ -108,15 +108,15 @@ func TestPrintLog(t *testing.T) {
t.Errorf("PrintLog(%v) line %q; want %s", tt.at, l, tt.want) 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) t.Errorf("PrintLog(%v) missing logging.level:\n%s", tt.at, logs)
} }
// Each line is msg="\t<key> = <value>". // Each line is msg="config value" key=<key> value=<value>.
flat := conf.Flatten() flat := conf.Flatten()
var keys []string var keys []string
for _, l := range lines { for _, l := range lines {
_, msg, _ := strings.Cut(l, `msg="\t`) _, rest, _ := strings.Cut(l, ` key=`)
key, _, _ := strings.Cut(msg, " = ") key, _, _ := strings.Cut(rest, " ")
if _, ok := flat[key]; !ok { if _, ok := flat[key]; !ok {
t.Errorf("PrintLog(%v) line %q: no key", tt.at, l) t.Errorf("PrintLog(%v) line %q: no key", tt.at, l)
} }
+49 -5
View File
@@ -14,16 +14,60 @@ import (
var ErrNoNewReleases = fmt.Errorf("%w: no new releases", util.ErrWorkerNoWork) 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 // 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 // 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 // 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( func Run(
ctx context.Context, conf *config.JobSearchConfig, since time.Time, ctx context.Context,
conf *config.JobSearchConfig,
since time.Time,
opts ...Option,
) error { ) error {
ctx, cancel := context.WithCancel(ctx) ctx, cancel := context.WithCancel(ctx)
defer cancel() defer cancel()
var settings options
for _, opt := range opts {
opt(&settings)
}
logger := settings.logger().With("component", "fetcher")
var ( var (
wg sync.WaitGroup wg sync.WaitGroup
mu sync.Mutex mu sync.Mutex
@@ -32,13 +76,13 @@ func Run(
start := func( start := func(
name string, name string,
run func(context.Context, *config.JobSearchConfig, time.Time) error, run runFunc,
) { ) {
wg.Add(1) wg.Add(1)
go func() { go func() {
defer wg.Done() defer wg.Done()
if err := run(ctx, conf, since); err != nil { if err := run(ctx, logger, conf, since); err != nil {
slog.Error("source stopped, shutting down", "source", name, "err", err) logger.Error("source stopped, shutting down", "source", name, "error", err)
mu.Lock() mu.Lock()
errs = append(errs, fmt.Errorf("%s: %w", name, err)) errs = append(errs, fmt.Errorf("%s: %w", name, err))
mu.Unlock() mu.Unlock()
+11 -8
View File
@@ -62,7 +62,7 @@ func confFor(apiRoot string) *config.JobSearchConfig {
} }
func TestFetchFunctions(t *testing.T) { func TestFetchFunctions(t *testing.T) {
fetchers := map[string]func(context.Context, *config.JobSearchConfig, time.Time) error{ fetchers := map[string]runFunc{
"FindAOpportunity": fetchFindAOpportunity, "FindAOpportunity": fetchFindAOpportunity,
"FTSMock": fetchFTSMock, "FTSMock": fetchFTSMock,
} }
@@ -91,7 +91,9 @@ func TestFetchFunctions(t *testing.T) {
for _, tc := range tests { for _, tc := range tests {
t.Run(fname+"/"+tc.name, func(t *testing.T) { t.Run(fname+"/"+tc.name, func(t *testing.T) {
srv, hits := ftsServer(t, tc.status, tc.body) 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) { if !tc.check(err) {
t.Fatalf("err = %v, want %s", err, tc.wantErr) 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.FindATender.APIRoot = fat.URL
conf.Sources.FTSMock.APIRoot = mock.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 { if fatHits.Load() != 1 || mockHits.Load() != 0 {
t.Fatalf("FindAOpportunity hits: fat=%d mock=%d", fatHits.Load(), mockHits.Load()) 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 { if fatHits.Load() != 1 || mockHits.Load() != 1 {
t.Fatalf("FTSMock hits: fat=%d mock=%d", fatHits.Load(), mockHits.Load()) 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. // Unroutable root: the request should never be waited on.
conf := confFor("http://192.0.2.1:9") conf := confFor("http://192.0.2.1:9")
start := time.Now() 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) t.Fatalf("err = %v, want context.Canceled", err)
} }
if d := time.Since(start); d > time.Second { if d := time.Since(start); d > time.Second {
@@ -163,7 +166,7 @@ func TestRunSleeperShutdown(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
done := make(chan struct{}) done := make(chan struct{})
go func() { go func() {
runSleeper(ctx, conf, time.Time{}) runSleeper(ctx, slog.Default(), conf, time.Time{})
close(done) close(done)
}() }()
time.Sleep(10 * time.Millisecond) // let the first sleep start time.Sleep(10 * time.Millisecond) // let the first sleep start
@@ -184,13 +187,13 @@ func TestRunSleeperShutdown(t *testing.T) {
func TestRunWorkersRejectZeroInterval(t *testing.T) { func TestRunWorkersRejectZeroInterval(t *testing.T) {
conf := &config.JobSearchConfig{} conf := &config.JobSearchConfig{}
runs := map[string]func(context.Context, *config.JobSearchConfig, time.Time) error{ runs := map[string]runFunc{
"FindAOpportunity": runFindAOpportunity, "FindAOpportunity": runFindAOpportunity,
"FTSMock": runFTSMock, "FTSMock": runFTSMock,
"Sleeper": runSleeper, "Sleeper": runSleeper,
} }
for name, run := range runs { 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) t.Errorf("%s: expected an error for a zero interval", name)
} }
} }
+6 -6
View File
@@ -3,7 +3,6 @@ package fetcher
import ( import (
"context" "context"
"errors" "errors"
"fmt"
"log/slog" "log/slog"
"time" "time"
@@ -16,13 +15,14 @@ import (
// runFindAOpportunity polls Find a Tender every configured interval until ctx // runFindAOpportunity polls Find a Tender every configured interval until ctx
// is cancelled. // is cancelled.
func runFindAOpportunity( func runFindAOpportunity(
ctx context.Context, conf *config.JobSearchConfig, since time.Time, ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time,
) error { ) error {
w := util.Worker{ w := util.Worker{
Logger: logger,
Name: "FindAOpportunity", Name: "FindAOpportunity",
Interval: conf.Sources.FindATender.Interval, Interval: conf.Sources.FindATender.Interval,
Task: func(ctx context.Context, since time.Time) error { 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) return w.Run(ctx, since)
@@ -32,10 +32,10 @@ func runFindAOpportunity(
// Tender. Finding nothing returns ErrNoNewReleases, so the worker still moves // Tender. Finding nothing returns ErrNoNewReleases, so the worker still moves
// its checkpoint on. // its checkpoint on.
func fetchFindAOpportunity( func fetchFindAOpportunity(
ctx context.Context, conf *config.JobSearchConfig, since time.Time, ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time,
) error { ) error {
opportunities, err := util.AwaitTask(ctx, func() ([]*types.Opportunity, 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() defer ft.Shutdown()
return ft.With(ctx).FetchAll(since, true) return ft.With(ctx).FetchAll(since, true)
}) })
@@ -46,7 +46,7 @@ func fetchFindAOpportunity(
return err return err
} }
slog.Info(fmt.Sprintf("Found %d opportunities", len(opportunities))) logger.Info("fetched opportunities", "count", len(opportunities))
return nil return nil
} }
+6 -6
View File
@@ -3,7 +3,6 @@ package fetcher
import ( import (
"context" "context"
"errors" "errors"
"fmt"
"log/slog" "log/slog"
"time" "time"
@@ -16,13 +15,14 @@ import (
// runFTSMock polls the mock Find a Tender server every configured interval // runFTSMock polls the mock Find a Tender server every configured interval
// until ctx is cancelled. // until ctx is cancelled.
func runFTSMock( func runFTSMock(
ctx context.Context, conf *config.JobSearchConfig, since time.Time, ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time,
) error { ) error {
w := util.Worker{ w := util.Worker{
Logger: logger,
Name: "FTSMock", Name: "FTSMock",
Interval: conf.Sources.FTSMock.Interval, Interval: conf.Sources.FTSMock.Interval,
Task: func(ctx context.Context, since time.Time) error { 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) return w.Run(ctx, since)
@@ -32,10 +32,10 @@ func runFTSMock(
// Tender server. Finding nothing returns ErrNoNewReleases, so the worker still // Tender server. Finding nothing returns ErrNoNewReleases, so the worker still
// moves its checkpoint on. // moves its checkpoint on.
func fetchFTSMock( func fetchFTSMock(
ctx context.Context, conf *config.JobSearchConfig, since time.Time, ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time,
) error { ) error {
opportunities, err := util.AwaitTask(ctx, func() ([]*types.Opportunity, 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() defer ft.Shutdown()
return ft.With(ctx).FetchAll(since, true) return ft.With(ctx).FetchAll(since, true)
}) })
@@ -46,7 +46,7 @@ func fetchFTSMock(
return err return err
} }
slog.Info(fmt.Sprintf("Found %d opportunities", len(opportunities))) logger.Info("fetched opportunities", "count", len(opportunities))
return nil return nil
} }
+3 -1
View File
@@ -2,6 +2,7 @@ package fetcher
import ( import (
"context" "context"
"log/slog"
"time" "time"
"git.avsdev.uk/Go/job-search/internal/config" "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 // runSleeper runs the sleeper test source until ctx is cancelled: every
// configured interval it simulates work by sleeping for sleepDuration. // configured interval it simulates work by sleeping for sleepDuration.
func runSleeper( func runSleeper(
ctx context.Context, conf *config.JobSearchConfig, since time.Time, ctx context.Context, logger *slog.Logger, conf *config.JobSearchConfig, since time.Time,
) error { ) error {
blockShutdown := conf.Sources.Sleeper.BlockShutdown blockShutdown := conf.Sources.Sleeper.BlockShutdown
w := util.Worker{ w := util.Worker{
Logger: logger,
Name: "Sleeper", Name: "Sleeper",
Interval: conf.Sources.Sleeper.Interval, Interval: conf.Sources.Sleeper.Interval,
Task: func(taskCtx context.Context, since time.Time) error { Task: func(taskCtx context.Context, since time.Time) error {
+38 -27
View File
@@ -226,7 +226,9 @@ func missingIDsError(haveOCID, haveID bool) error {
// releases, etc). // releases, etc).
// //
// This method takes ownership of the response body and closes it when done. // 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 var pkg safeReleasePackage
// Take ownership of the response body. // Take ownership of the response body.
@@ -263,9 +265,12 @@ func safeUnpackReleases(response *resty.Response) (*ocds.ReleasePackage, error)
err := unmarshalLenientDates(rawRel, &release) err := unmarshalLenientDates(rawRel, &release)
if err != nil { if err != nil {
ocid, release_id, _ := releaseIDs(rawRel) ocid, release_id, _ := releaseIDs(rawRel)
slog.Warn(fmt.Sprintf( logger.Warn(
"Skipping release (%s/%s) due to error: %s", ocid, release_id, err, "skipping unreadable release",
)) "ocid", ocid,
"release_id", release_id,
"error", err,
)
continue continue
} }
out.Releases = append(out.Releases, release) out.Releases = append(out.Releases, release)
@@ -303,8 +308,9 @@ func closeBody(res *resty.Response) {
// response status. // response status.
func fetchURI(ft *FindATender, uri string) (*resty.Response, error) { func fetchURI(ft *FindATender, uri string) (*resty.Response, error) {
withTrace := ft.config.Logging.LogLevel() <= slog.LevelDebug 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 ctx := ft.ctx
if ctx == nil { if ctx == nil {
@@ -316,23 +322,31 @@ func fetchURI(ft *FindATender, uri string) (*resty.Response, error) {
res, err := req.SetTrace(withTrace).Get(uri) res, err := req.SetTrace(withTrace).Get(uri)
if withTrace { if withTrace {
if logging.IsJSONHandler(slog.Default().Handler()) { logTrace(logger, res)
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())
}
} }
return res, err 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 // 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 // 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 // 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) return nil, fmt.Errorf("unknown retry-after value: %w", err)
} }
slog.Warn(fmt.Sprintf( retryAfter := time.Duration(retrySec) * time.Second
"API rate limit hit, waiting as requested for %d seconds", retrySec, ft.logger().Warn("api rate limit hit, waiting as asked", "retry_after", retryAfter)
)) if rateSleep(ctx, retryAfter) != nil {
if rateSleep(ctx, time.Duration(retrySec)*time.Second) != nil {
return nil, ErrFetchCancelled return nil, ErrFetchCancelled
} }
@@ -432,7 +445,7 @@ func (ft *FindATender) fetchOnce(opts RequestOptions) ([]ocds.Release, error) {
return nil, err return nil, err
} }
pkg, err := safeUnpackReleases(res) pkg, err := safeUnpackReleases(ft.logger(), res)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@@ -454,7 +467,7 @@ func (ft *FindATender) fetchAll(opts RequestOptions) ([]ocds.Release, error) {
return nil, err return nil, err
} }
pkg, err := safeUnpackReleases(res) pkg, err := safeUnpackReleases(ft.logger(), res)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@@ -466,9 +479,7 @@ func (ft *FindATender) fetchAll(opts RequestOptions) ([]ocds.Release, error) {
for { for {
if pkg.Links != nil && len(pkg.Links.Next) > 0 { if pkg.Links != nil && len(pkg.Links.Next) > 0 {
if seen[pkg.Links.Next] { if seen[pkg.Links.Next] {
slog.Warn(fmt.Sprintf( ft.logger().Warn("stopping at repeated next link", "link", pkg.Links.Next)
"Stopping at repeated next link: %s", pkg.Links.Next,
))
break break
} }
seen[pkg.Links.Next] = true seen[pkg.Links.Next] = true
@@ -482,7 +493,7 @@ func (ft *FindATender) fetchAll(opts RequestOptions) ([]ocds.Release, error) {
return nil, err return nil, err
} }
pkg, err = safeUnpackReleases(res) pkg, err = safeUnpackReleases(ft.logger(), res)
if err != nil { if err != nil {
return nil, err return nil, err
} }
+9 -4
View File
@@ -312,9 +312,14 @@ func TestFetchURIDebugTrace(t *testing.T) {
if len(releases) != 1 { if len(releases) != 1 {
t.Errorf("got %d releases, want 1", len(releases)) 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()) 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"} {"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 { if err != nil {
t.Fatal(err) t.Fatal(err)
} }
@@ -424,7 +429,7 @@ func TestSafeUnpackReleasesPublishedDate(t *testing.T) {
if tt.date != "" { if tt.date != "" {
body = `{"publishedDate":` + tt.date + `,"releases":[]}` body = `{"publishedDate":` + tt.date + `,"releases":[]}`
} }
pkg, err := safeUnpackReleases(responseFor(t, body)) pkg, err := safeUnpackReleases(slog.Default(), responseFor(t, body))
if err != nil { if err != nil {
t.Fatal(err) t.Fatal(err)
} }
@@ -448,7 +453,7 @@ func TestSafeUnpackReleasesInvalidJSON(t *testing.T) {
"publisher array": `{"publisher": []}`, "publisher array": `{"publisher": []}`,
} { } {
t.Run(name, func(t *testing.T) { 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") t.Error("expected a decode error")
} }
}) })
+27 -3
View File
@@ -18,21 +18,45 @@ type FindATender struct {
config *config.JobSearchConfig config *config.JobSearchConfig
apiRoot string apiRoot string
ctx context.Context 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 // 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. // 60 seconds and are retried once. Call Shutdown when finished with it. It
func New(conf *config.JobSearchConfig, apiRoot string) *FindATender { // logs to slog.Default() unless given WithLogger.
func New(conf *config.JobSearchConfig, apiRoot string, opts ...Option) *FindATender {
ft := &FindATender{ ft := &FindATender{
config: conf, config: conf,
apiRoot: apiRoot, apiRoot: apiRoot,
} }
for _, opt := range opts {
opt(ft)
}
ft.httpClient = resty.New(). ft.httpClient = resty.New().
SetTimeout(60 * time.Duration(time.Second)). SetTimeout(60 * time.Duration(time.Second)).
SetRetryCount(1) SetRetryCount(1)
return ft 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 // ReloadConfig replaces the configuration the client reads, such as the log
// level. The HTTP client and API root set by New are not changed. // level. The HTTP client and API root set by New are not changed.
func (ft *FindATender) ReloadConfig(conf *config.JobSearchConfig) { 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. // logged, as there is nothing a caller could do about it.
func (ft *FindATender) Shutdown() { func (ft *FindATender) Shutdown() {
if err := ft.httpClient.Close(); err != nil { if err := ft.httpClient.Close(); err != nil {
slog.Warn("findatender: closing HTTP client", "error", err) ft.logger().Warn("closing http client failed", "error", err)
} }
} }
+58 -5
View File
@@ -2,6 +2,7 @@ package logging
import ( import (
"errors" "errors"
"fmt"
"log/slog" "log/slog"
"os" "os"
"path/filepath" "path/filepath"
@@ -19,6 +20,14 @@ var (
// fileLogger is the log file opened by LogToFile, or nil when logging // fileLogger is the log file opened by LogToFile, or nil when logging
// to the terminal. // to the terminal.
fileLogger *os.File 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. // SetLevel sets the logging level without logging the change.
@@ -31,7 +40,7 @@ func SetLevel(level slog.Level) {
func EnableDebug() { func EnableDebug() {
if logLevel.Level() > slog.LevelDebug { if logLevel.Level() > slog.LevelDebug {
logLevel.Set(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 // 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() { func LogToTerminal() {
opts := &tint.Options{ opts := &tint.Options{
Level: &logLevel, Level: &logLevel,
TimeFormat: "*", TimeFormat: "*",
} }
handler := tint.NewTextHandler(os.Stdout, opts) handler := tint.NewTextHandler(terminal, opts)
logger := slog.New(handler) if isTerminal(terminal) {
slog.SetDefault(logger) 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. // IsJSONHandler reports whether h writes JSON, as the file logger does.
+51
View File
@@ -18,9 +18,11 @@ func saveGlobals(t *testing.T) {
t.Helper() t.Helper()
level := logLevel.Level() level := logLevel.Level()
def := slog.Default() def := slog.Default()
out, detect := terminal, isTerminal
t.Cleanup(func() { t.Cleanup(func() {
logLevel.Set(level) logLevel.Set(level)
slog.SetDefault(def) slog.SetDefault(def)
terminal, isTerminal = out, detect
Shutdown() Shutdown()
}) })
} }
@@ -155,3 +157,52 @@ func TestLogToTerminal(t *testing.T) {
t.Fatal("terminal handler ignores the package level") 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)
}
}
+9 -6
View File
@@ -4,7 +4,6 @@ import (
"context" "context"
"fmt" "fmt"
"hash/fnv" "hash/fnv"
"log"
"math" "math"
"math/rand" "math/rand"
"time" "time"
@@ -21,15 +20,18 @@ type Generator struct {
cat *Catalog cat *Catalog
store *Store store *Store
rnd *rand.Rand rnd *rand.Rand
opts options
} }
// NewGenerator returns a generator drawing from cat and storing releases in // NewGenerator returns a generator drawing from cat and storing releases in
// store. The same seed and store contents give the same releases. // store. The same seed and store contents give the same releases. It logs to
func NewGenerator(cat *Catalog, store *Store, seed int64) *Generator { // slog.Default() unless given WithLogger.
func NewGenerator(cat *Catalog, store *Store, seed int64, opts ...Option) *Generator {
return &Generator{ return &Generator{
cat: cat, cat: cat,
store: store, store: store,
rnd: rand.New(rand.NewSource(seed)), //nolint:gosec // seeded for repeatable mock data 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. // 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) { func (g *Generator) Run(ctx context.Context, min, max time.Duration) {
logger := g.opts.logger("generator")
for { for {
d := g.gap(min, max) 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) timer := time.NewTimer(d)
select { select {
@@ -249,11 +252,11 @@ func (g *Generator) Run(ctx context.Context, min, max time.Duration) {
r := g.Make(time.Now()) r := g.Make(time.Now())
if err := g.store.Append(r); err != nil { if err := g.store.Append(r); err != nil {
log.Printf("generator: storing release: %v", err) logger.Error("storing release failed", "error", err)
continue 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)
} }
} }
+7 -5
View File
@@ -5,7 +5,6 @@ import (
"encoding/json" "encoding/json"
"errors" "errors"
"fmt" "fmt"
"log"
"net/http" "net/http"
"net/url" "net/url"
"strconv" "strconv"
@@ -27,17 +26,20 @@ type server struct {
store *Store store *Store
baseURL string baseURL string
loc *time.Location // zone for updatedFrom/updatedTo without an offset; nil means UTC 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 // 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 // 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 // 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). // 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( func NewHandler(
store *Store, baseURL string, loc *time.Location, store *Store, baseURL string, loc *time.Location, opts ...Option,
) http.HandlerFunc { ) 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 // 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.SetIndent("", " ")
enc.SetEscapeHTML(false) enc.SetEscapeHTML(false)
if err := enc.Encode(pkg); err != nil { if err := enc.Encode(pkg); err != nil {
log.Printf("handler: writing response: %v", err) s.opts.logger("handler").Warn("writing response failed", "error", err)
} }
} }
+40
View File
@@ -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)
}
+17 -8
View File
@@ -6,7 +6,7 @@ import (
"encoding/json" "encoding/json"
"errors" "errors"
"fmt" "fmt"
"log" "log/slog"
"math/rand" "math/rand"
"os" "os"
"path/filepath" "path/filepath"
@@ -33,19 +33,27 @@ type Store struct {
// removing and picking one at random are all constant time. // removing and picking one at random are all constant time.
open []string open []string
openPos map[string]int openPos map[string]int
opts options
} }
// OpenStore loads the releases stored at path, creating the file and its // 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 // 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 // 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. // left incomplete by a crash is ended so new ones start on a fresh line.
func OpenStore(path string) (*Store, error) { // It logs to slog.Default() unless given WithLogger.
s := &Store{latest: map[string]int{}, lastNum: map[int]int{}, openPos: map[string]int{}} 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 { if err := os.MkdirAll(filepath.Dir(path), 0o750); err != nil {
return nil, err return nil, err
} }
releases, err := readReleases(path) releases, err := readReleases(s.opts.logger("store"), path)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@@ -67,9 +75,10 @@ func OpenStore(path string) (*Store, error) {
return s, nil return s, nil
} }
// readReleases reads the releases stored at path, skipping lines that are // readReleases reads the releases stored at path, skipping blank lines and
// blank or can't be decoded. A missing file holds no releases. // lines that can't be decoded (which are logged to logger). A missing file
func readReleases(path string) ([]ocds.Release, error) { // holds no releases.
func readReleases(logger *slog.Logger, path string) ([]ocds.Release, error) {
in, err := os.Open(filepath.Clean(path)) in, err := os.Open(filepath.Clean(path))
if os.IsNotExist(err) { if os.IsNotExist(err) {
return nil, nil return nil, nil
@@ -89,7 +98,7 @@ func readReleases(path string) ([]ocds.Release, error) {
} }
var r ocds.Release var r ocds.Release
if err := json.Unmarshal(b, &r); err != nil { 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 continue
} }
releases = append(releases, r) releases = append(releases, r)
+9 -2
View File
@@ -36,6 +36,9 @@ type Worker struct {
ShutdownTimeout time.Duration ShutdownTimeout time.Duration
// Task is the work to perform on each tick. // Task is the work to perform on each tick.
Task Task 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 // 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 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) logger.Info("starting worker", "since", since, "interval", w.Interval)
// workCtx is NOT cancelled immediately when ctx is. It gives an in-flight // 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) logger.Warn("task cancelled", "elapsed", elapsed)
return since return since
default: default:
logger.Error("task failed", "err", err, "elapsed", elapsed) logger.Error("task failed", "error", err, "elapsed", elapsed)
return since return since
} }
} }
+11 -7
View File
@@ -106,7 +106,7 @@ func (c *client) run(ctx context.Context) {
// consumer), after a failed write or ping, or by the caller. // consumer), after a failed write or ping, or by the caller.
c.conn.CloseNow() //nolint:errcheck,gosec // finished with; it may already be closed c.conn.CloseNow() //nolint:errcheck,gosec // finished with; it may already be closed
default: 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 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) err := c.conn.Write(writeCtx, websocket.MessageText, msg)
cancel() cancel()
if err != nil { 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() c.cancel()
return return
} }
@@ -215,7 +215,7 @@ func (c *client) pingLoop(ctx context.Context) {
err := c.conn.Ping(pingCtx) err := c.conn.Ping(pingCtx)
cancel() cancel()
if err != nil { 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.conn.CloseNow() //nolint:errcheck,gosec // dropping the client anyway
c.cancel() c.cancel()
return return
@@ -240,11 +240,11 @@ func (c *client) trySend(msg []byte) bool {
func (c *client) sendEnvelope(env Envelope) { func (c *client) sendEnvelope(env Envelope) {
encoded, err := json.Marshal(env) encoded, err := json.Marshal(env)
if err != nil { if err != nil {
c.hub.log.Error("marshal", "client", c.id, "error", err) c.hub.logger().Error("marshal", "client", c.id, "error", err)
return return
} }
if !c.trySend(encoded) { 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") 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 // level, with its size; at most logMessageLimit bytes of it are logged. It
// does nothing unless debug logging is enabled. // does nothing unless debug logging is enabled.
func (c *client) logMessage(ctx context.Context, event string, data []byte) { 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 return
} }
logged, truncated := data, false logged, truncated := data, false
if len(logged) > logMessageLimit { if len(logged) > logMessageLimit {
logged, truncated = logged[:logMessageLimit], true 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.String("client", c.id),
slog.Int("bytes", len(data)), slog.Int("bytes", len(data)),
slog.String("message", string(logged)), slog.String("message", string(logged)),
+5 -5
View File
@@ -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, // newTestClient returns a client of a new hub on f, with no loops running,
// and its context. // and its context.
func newTestClient(f *fakeConn) (*client, context.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()) ctx, cancel := context.WithCancel(context.Background())
return newClient(h, f, "192.0.2.1", cancel), ctx 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}, {config.JSCRateLimitRule{Enabled: true, PerSecond: 1, Burst: 1}, true},
} }
for _, tt := range tests { 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 := newClient(h, newFakeConn(), "", func() {})
c.limiter.Allow() c.limiter.Allow()
if limited := !c.limiter.Allow(); limited != tt.limited { 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. // At debug level, messages received from and sent to a client are logged.
func TestLogMessages(t *testing.T) { func TestLogMessages(t *testing.T) {
log, buf := jsonLog(slog.LevelDebug) 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) peer, _ := pipeClient(t, h)
ping := `{"type":"ping","id":"1"}` ping := `{"type":"ping","id":"1"}`
@@ -235,7 +235,7 @@ func TestLogMessages(t *testing.T) {
// unless debug logging is on. // unless debug logging is on.
func TestLogMessageLimit(t *testing.T) { func TestLogMessageLimit(t *testing.T) {
log, buf := jsonLog(slog.LevelDebug) log, buf := jsonLog(slog.LevelDebug)
h := NewHub(config.JSCServerWebSocket{}, log) h := NewHub(config.JSCServerWebSocket{}, WithLogger(log))
c := newClient(h, newFakeConn(), "", func() {}) c := newClient(h, newFakeConn(), "", func() {})
long := strings.Repeat("x", logMessageLimit+100) long := strings.Repeat("x", logMessageLimit+100)
c.logMessage(context.Background(), "message sent", []byte(long)) c.logMessage(context.Background(), "message sent", []byte(long))
@@ -251,7 +251,7 @@ func TestLogMessageLimit(t *testing.T) {
} }
log, buf = jsonLog(slog.LevelInfo) 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")) c.logMessage(context.Background(), "message sent", []byte("x"))
if entries := buf.entries(t); len(entries) != 0 { if entries := buf.entries(t); len(entries) != 0 {
t.Errorf("logged %v at info level", entries) t.Errorf("logged %v at info level", entries)
+3 -3
View File
@@ -22,7 +22,7 @@ func (h *Hub) ServeHTTP(w http.ResponseWriter, r *http.Request) {
CompressionMode: mode, CompressionMode: mode,
}) })
if err != nil { 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. return // Accept has already written the HTTP error.
} }
defer conn.CloseNow() //nolint:errcheck // finished with; it may already be closed 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) 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) c.run(ctx)
h.log.Info("client disconnected", "client", c.id, "ip", ip) h.logger().Info("client disconnected", "client", c.id, "ip", ip)
} }
+5 -5
View File
@@ -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 // A client upgraded over HTTP gets replies. A max_message_size of 0 uses the
// default limit rather than refusing every message. // default limit rather than refusing every message.
func TestHTTPMessages(t *testing.T) { 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) url := wsHub(t, h)
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel() defer cancel()
@@ -98,7 +98,7 @@ func TestPushBadPayload(t *testing.T) {
// A binary frame closes the connection with 1003 (unsupported data). // A binary frame closes the connection with 1003 (unsupported data).
func TestHTTPBinaryFrame(t *testing.T) { 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) url := wsHub(t, h)
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel() defer cancel()
@@ -120,7 +120,7 @@ func TestHTTPMessageRateLimit(t *testing.T) {
WriteTimeout: time.Second, WriteTimeout: time.Second,
MessageRateLimit: config.JSCRateLimitRule{Enabled: true, PerSecond: 1, Burst: 1}, MessageRateLimit: config.JSCRateLimitRule{Enabled: true, PerSecond: 1, Burst: 1},
} }
h := NewHub(conf, discardLog) h := NewHub(conf, WithLogger(discardLog))
url := wsHub(t, h) url := wsHub(t, h)
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
defer cancel() 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 // A request that isn't a WebSocket upgrade is refused by the upgrade and no
// client is registered. // client is registered.
func TestHTTPNotAnUpgrade(t *testing.T) { func TestHTTPNotAnUpgrade(t *testing.T) {
h := NewHub(config.JSCServerWebSocket{}, discardLog) h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog))
srv := httptest.NewServer(h) srv := httptest.NewServer(h)
defer srv.Close() defer srv.Close()
res, err := http.Get(srv.URL) 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 // After Shutdown, an upgrade succeeds but the client is closed at once with
// 1001 (going away). // 1001 (going away).
func TestHTTPRefusedAfterShutdown(t *testing.T) { func TestHTTPRefusedAfterShutdown(t *testing.T) {
h := NewHub(config.JSCServerWebSocket{}, discardLog) h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog))
url := wsHub(t, h) url := wsHub(t, h)
if err := h.Shutdown(context.Background()); err != nil { if err := h.Shutdown(context.Background()); err != nil {
t.Fatal(err) t.Fatal(err)
+29 -7
View File
@@ -27,13 +27,35 @@ type Hub struct {
// max_message_size is not set. // max_message_size is not set.
const defaultMaxMessageSize = 32 << 10 const defaultMaxMessageSize = 32 << 10
// NewHub creates a hub. // Option configures a Hub.
func NewHub(conf config.JSCServerWebSocket, log *slog.Logger) *Hub { type Option func(*Hub)
return &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, conf: conf,
log: log.With("component", "ws"),
clients: make(map[*client]struct{}), 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 // 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 { if payload != nil {
var err error var err error
if rawPayload, err = json.Marshal(payload); err != nil { 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 return
} }
} }
@@ -55,7 +77,7 @@ func (h *Hub) Push(msgType string, payload any) {
Payload: rawPayload, Payload: rawPayload,
}) })
if err != nil { if err != nil {
h.log.Error("marshal push", "type", msgType, "error", err) h.logger().Error("marshal push", "type", msgType, "error", err)
return return
} }
@@ -69,7 +91,7 @@ func (h *Hub) Push(msgType string, payload any) {
h.m.RUnlock() h.m.RUnlock()
for _, client := range slow { 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") go client.close(ws.StatusPolicyViolation, "slow consumer")
} }
} }
+4 -4
View File
@@ -32,7 +32,7 @@ func pipeClient(t *testing.T, h *Hub) (net.Conn, chan struct{}) {
// once and returns ctx's error. // once and returns ctx's error.
func TestShutdownTimeout(t *testing.T) { func TestShutdownTimeout(t *testing.T) {
// No write timeout: the client's goodbye blocks until it is cut short. // 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) _, done := pipeClient(t, h)
ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) 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. // Shutdown with no clients returns at once, even with an expired ctx.
func TestShutdownNoClients(t *testing.T) { func TestShutdownNoClients(t *testing.T) {
h := NewHub(config.JSCServerWebSocket{}, discardLog) h := NewHub(config.JSCServerWebSocket{}, WithLogger(discardLog))
ctx, cancel := context.WithCancel(context.Background()) ctx, cancel := context.WithCancel(context.Background())
cancel() cancel()
for range 20 { for range 20 {
@@ -64,7 +64,7 @@ func TestPingFailureDropsClient(t *testing.T) {
h := NewHub(config.JSCServerWebSocket{ h := NewHub(config.JSCServerWebSocket{
PingInterval: 10 * time.Millisecond, PingInterval: 10 * time.Millisecond,
PongTimeout: 20 * time.Millisecond, PongTimeout: 20 * time.Millisecond,
}, discardLog) }, WithLogger(discardLog))
_, done := pipeClient(t, h) _, done := pipeClient(t, h)
select { select {
@@ -85,7 +85,7 @@ func TestMaxMessageSize(t *testing.T) {
{config.JSCServerWebSocket{MaxMessageSize: 100}, 100}, {config.JSCServerWebSocket{MaxMessageSize: 100}, 100},
} }
for _, tt := range tests { for _, tt := range tests {
h := NewHub(tt.conf, discardLog) h := NewHub(tt.conf, WithLogger(discardLog))
if got := h.maxMessageSize(); got != tt.want { if got := h.maxMessageSize(); got != tt.want {
t.Errorf("maxMessageSize(%d) = %d; want %d", tt.conf.MaxMessageSize, got, tt.want) t.Errorf("maxMessageSize(%d) = %d; want %d", tt.conf.MaxMessageSize, got, tt.want)
} }
+2 -2
View File
@@ -71,10 +71,10 @@ func (h *Hub) ServeTCP(ctx context.Context, newConn net.Conn) {
} }
defer h.unregister(client) 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) client.run(ctx)
conn.CloseNow() //nolint:errcheck,gosec // finished with; it may already be closed 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 ---------- // ---------- tcpConn ----------
+4 -2
View File
@@ -31,7 +31,7 @@ func tcpHub(t *testing.T, mutate func(*config.JSCServerWebSocket)) (*Hub, string
if mutate != nil { if mutate != nil {
mutate(&conf) mutate(&conf)
} }
h := NewHub(conf, discardLog) h := NewHub(conf, WithLogger(discardLog))
ln, err := net.Listen("tcp", "127.0.0.1:0") ln, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil { if err != nil {
t.Fatal(err) 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 // 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. // full. net.Pipe has no buffer, so writes to it block until the peer reads.
func TestTCPSlowConsumer(t *testing.T) { 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() server, peer := net.Pipe()
t.Cleanup(func() { server.Close(); peer.Close() }) t.Cleanup(func() { server.Close(); peer.Close() })
done := make(chan struct{}) done := make(chan struct{})
+31 -8
View File
@@ -33,15 +33,38 @@ type Server struct {
hub *websocket.Hub 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 // 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. // hub down when it stops, so hub should not be shared with another server.
// Push to hub to reach the server's clients. // Push to hub to reach the server's clients. It logs to slog.Default()
func New(conf *config.JSCServer, hub *websocket.Hub, log *slog.Logger) *Server { // unless given WithLogger.
return &Server{ func New(conf *config.JSCServer, hub *websocket.Hub, opts ...Option) *Server {
server := &Server{
conf: conf, conf: conf,
log: log,
hub: hub, 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 // 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() defer stop()
s.log.Info("listening", "addr", listen.Addr().String()) s.logger().Info("listening", "addr", listen.Addr().String())
acceptErr := s.accept(ctx, connCtx, listen) acceptErr := s.accept(ctx, connCtx, listen)
if ctx.Err() != nil { if ctx.Err() != nil {
acceptErr = nil // cancelling ctx is how the server is stopped acceptErr = nil // cancelling ctx is how the server is stopped
} }
listen.Close() //nolint:errcheck,gosec // closed already when ctx was cancelled listen.Close() //nolint:errcheck,gosec // closed already when ctx was cancelled
s.log.Info("shutting down") s.logger().Info("shutting down")
shutdownCtx := context.Background() shutdownCtx := context.Background()
if s.conf.Timeouts.ShutdownTimeout > 0 { if s.conf.Timeouts.ShutdownTimeout > 0 {
var cancel context.CancelFunc var cancel context.CancelFunc
@@ -117,7 +140,7 @@ func (s *Server) accept(
// Back off and retry e.g. when out of file descriptors. // Back off and retry e.g. when out of file descriptors.
delay = min(max(2*delay, 5*time.Millisecond), time.Second) 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 { select {
case <-time.After(delay): case <-time.After(delay):
@@ -131,7 +154,7 @@ func (s *Server) accept(
if limiter != nil { if limiter != nil {
ip := remoteIP(newConn) ip := remoteIP(newConn)
if allowed, _ := limiter.Allow(ip); !allowed { 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") go reject(newConn, "rate limited")
continue continue
} }
+2 -2
View File
@@ -36,8 +36,8 @@ func testConf(mutate func(*config.JSCServer)) *config.JSCServer {
// newServer returns a server for conf with its own hub. // newServer returns a server for conf with its own hub.
func newServer(conf *config.JSCServer) (*Server, *websocket.Hub) { func newServer(conf *config.JSCServer) (*Server, *websocket.Hub) {
h := websocket.NewHub(conf.WebSocket, discardLog) h := websocket.NewHub(conf.WebSocket, websocket.WithLogger(discardLog))
return New(conf, h, discardLog), h return New(conf, h, WithLogger(discardLog)), h
} }
// startServer serves on a local port, returning the server's hub, its // startServer serves on a local port, returning the server's hub, its