diff --git a/CHANGELOG.md b/CHANGELOG.md index 079d16c..35f3cd5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,13 @@ # Changelog +## v1.0.0-rc.16 + +### Changed +- Bot loggers now apply the configured token replacer consistently across the main bot logger, request logger, internal API and uploader loggers, webhook logger, and auto-managed plugin loggers, so bot tokens stay masked in both stdout and file-backed logs. + +### Tests +- Added regression coverage proving token masking still applies after `initLoggers(...)` switches loggers to file-backed writers and that auto-managed plugin loggers inherit token masking as well. + ## v1.0.0-rc.15 ### Changed diff --git a/bot.go b/bot.go index 184c959..f92f8d9 100644 --- a/bot.go +++ b/bot.go @@ -220,6 +220,7 @@ func NewBot[T any](opts *BotOpts) (*Bot[T], error) { bot.logger.Warn("Can't get bot username. Named command handlers won't work!") } bot.logger.Infoln(fmt.Sprintf("Authorized as %s (@%s)", u.FirstName, Val(u.Username, "unknown"))) + bot.logger.Debugln("Bot initialized with configuration:", fmt.Sprintf("%+v", opts)) return bot, nil } diff --git a/bot_register.go b/bot_register.go index eb97890..8d046ab 100644 --- a/bot_register.go +++ b/bot_register.go @@ -30,6 +30,7 @@ func (bot *Bot[T]) AddPlugins(plugin ...*Plugin[T]) *Bot[T] { if cloned.logger == nil { cloned.logger = utils.CreateLogger(cloned.name, level) } + bot.addTokenReplacer(cloned.logger) bot.plugins = append(bot.plugins, cloned) if bot.logger != nil { bot.logger.Debugln(fmt.Sprintf("plugins with name \"%s\" registered", cloned.name)) @@ -145,7 +146,7 @@ func (bot *Bot[T]) AddAppDataLoggerWriter(writer AppDataLogger[T]) *Bot[T] { if bot.RequestLogger != nil { bot.RequestLogger.AddWriter(w) } - for _, l := range bot.extraLoggers { + for _, l := range bot.managedExtraLoggers() { l.AddWriter(w) } for _, p := range bot.plugins { @@ -153,5 +154,7 @@ func (bot *Bot[T]) AddAppDataLoggerWriter(writer AppDataLogger[T]) *Bot[T] { p.logger.AddWriter(w) } } + bot.addTokenReplacer(bot.logger, bot.RequestLogger) + bot.addTokenReplacer(bot.managedExtraLoggers()...) return bot } diff --git a/bot_test.go b/bot_test.go index e37848c..711bf9f 100644 --- a/bot_test.go +++ b/bot_test.go @@ -5,6 +5,7 @@ import ( "errors" "io" "net/http" + "os" "path/filepath" "reflect" "strings" @@ -136,6 +137,124 @@ func TestInitLoggersFallsBackToStdoutLoggerOnFileError(t *testing.T) { } } +func TestInitLoggersAppliesTokenReplacerToFileLoggers(t *testing.T) { + tempDir := t.TempDir() + api := tgapi.NewAPI(tgapi.NewAPIOpts("secret-token")) + uploader := tgapi.NewUploader(api) + bot := &Bot[NoData]{token: "secret-token", api: api, uploader: uploader} + t.Cleanup(func() { + if err := uploader.Close(); err != nil { + t.Fatalf("failed to close uploader: %v", err) + } + }) + t.Cleanup(func() { + if err := api.Close(); err != nil { + t.Fatalf("failed to close api: %v", err) + } + }) + + bot.initLoggers(&BotOpts{ + Debug: true, + WriteToFile: true, + UseRequestLogger: true, + LoggerBasePath: tempDir, + }) + + apiPath := filepath.Join(tempDir, "api.log") + apiFile, err := os.OpenFile(apiPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + t.Fatalf("failed to open api log: %v", err) + } + defer func() { _ = apiFile.Close() }() + bot.api.GetLogger().AddWriter(bot.api.GetLogger().CreateTextWriter(apiFile)) + + uploaderPath := filepath.Join(tempDir, "uploader.log") + uploaderFile, err := os.OpenFile(uploaderPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + t.Fatalf("failed to open uploader log: %v", err) + } + defer func() { _ = uploaderFile.Close() }() + bot.uploader.GetLogger().AddWriter(bot.uploader.GetLogger().CreateTextWriter(uploaderFile)) + + bot.logger.Infoln("main secret-token") + bot.RequestLogger.Infoln("request secret-token") + bot.api.GetLogger().Infoln("api secret-token") + bot.uploader.GetLogger().Infoln("uploader secret-token") + + if err := bot.RequestLogger.Close(); err != nil { + t.Fatalf("failed to close request logger: %v", err) + } + if err := bot.logger.Close(); err != nil { + t.Fatalf("failed to close main logger: %v", err) + } + + mainLog, err := os.ReadFile(filepath.Join(tempDir, "main.log")) + if err != nil { + t.Fatalf("failed to read main log: %v", err) + } + requestLog, err := os.ReadFile(filepath.Join(tempDir, "requests.log")) + if err != nil { + t.Fatalf("failed to read request log: %v", err) + } + apiLog, err := os.ReadFile(apiPath) + if err != nil { + t.Fatalf("failed to read api log: %v", err) + } + uploaderLog, err := os.ReadFile(uploaderPath) + if err != nil { + t.Fatalf("failed to read uploader log: %v", err) + } + + for _, tt := range []struct { + name string + data string + }{ + {name: "main", data: string(mainLog)}, + {name: "request", data: string(requestLog)}, + {name: "api", data: string(apiLog)}, + {name: "uploader", data: string(uploaderLog)}, + } { + if strings.Contains(tt.data, "secret-token") { + t.Fatalf("%s log leaked raw token: %q", tt.name, tt.data) + } + if !strings.Contains(tt.data, "") { + t.Fatalf("%s log did not contain masked token: %q", tt.name, tt.data) + } + } +} + +func TestAddPluginsAppliesTokenReplacerToPluginLogger(t *testing.T) { + bot := &Bot[NoData]{ + token: "secret-token", + logger: slog.CreateLogger(), + } + defer func() { _ = bot.logger.Close() }() + + plugin := NewPlugin[NoData]("demo") + bot.AddPlugins(plugin) + + logPath := filepath.Join(t.TempDir(), "plugin.log") + file, err := os.OpenFile(logPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + t.Fatalf("failed to open plugin log: %v", err) + } + defer func() { _ = file.Close() }() + + bot.plugins[0].logger.AddWriter(bot.plugins[0].logger.CreateTextWriter(file)) + bot.plugins[0].logger.Infoln("plugin secret-token") + + data, err := os.ReadFile(logPath) + if err != nil { + t.Fatalf("failed to read plugin log: %v", err) + } + if strings.Contains(string(data), "secret-token") { + t.Fatalf("plugin log leaked raw token: %q", string(data)) + } + if !strings.Contains(string(data), "") { + t.Fatalf("plugin log did not contain masked token: %q", string(data)) + } +} + func TestNextPollRetryDelay(t *testing.T) { tests := []struct { name string diff --git a/bot_utils.go b/bot_utils.go index 6bdb4f9..843b6cf 100644 --- a/bot_utils.go +++ b/bot_utils.go @@ -5,6 +5,7 @@ import ( "fmt" "maps" "reflect" + "slices" "strings" "time" @@ -15,6 +16,39 @@ import ( "github.com/alitto/pond/v2" ) +func (bot *Bot[T]) addTokenReplacer(loggers ...*slog.Logger) { + if bot.token == "" { + return + } + for _, logger := range loggers { + if logger == nil { + continue + } + logger.AddReplacer(bot.token, "") + } +} + +func appendUniqueLogger(loggers []*slog.Logger, logger *slog.Logger) []*slog.Logger { + if logger == nil { + return loggers + } + if slices.Contains(loggers, logger) { + return loggers + } + return append(loggers, logger) +} + +func (bot *Bot[T]) managedExtraLoggers() []*slog.Logger { + loggers := append([]*slog.Logger(nil), bot.extraLoggers...) + if bot.api != nil { + loggers = appendUniqueLogger(loggers, bot.api.GetLogger()) + } + if bot.uploader != nil { + loggers = appendUniqueLogger(loggers, bot.uploader.GetLogger()) + } + return loggers +} + func (bot *Bot[T]) enqueueUpdate(ctx context.Context, update tgapi.Update) error { select { case <-ctx.Done(): @@ -41,7 +75,7 @@ func (bot *Bot[T]) initLoggers(opts *BotOpts) { level = slog.DEBUG } - bot.logger = utils.CreateLogger("BOT", level).AddReplacer(bot.token, "") + bot.logger = utils.CreateLogger("BOT", level) if opts.WriteToFile { path := fmt.Sprintf("%s/main.log", strings.TrimRight(opts.LoggerBasePath, "/")) logger, err := utils.CreateFileLogger("BOT", level, path) @@ -53,7 +87,7 @@ func (bot *Bot[T]) initLoggers(opts *BotOpts) { } if opts.UseRequestLogger { - bot.RequestLogger = utils.CreateLogger("REQUESTS", level).AddReplacer(bot.token, "") + bot.RequestLogger = utils.CreateLogger("REQUESTS", level) if opts.WriteToFile { path := fmt.Sprintf("%s/requests.log", strings.TrimRight(opts.LoggerBasePath, "/")) logger, err := utils.CreateFileLogger("REQUESTS", level, path) @@ -64,6 +98,9 @@ func (bot *Bot[T]) initLoggers(opts *BotOpts) { } } } + + bot.addTokenReplacer(bot.logger, bot.RequestLogger) + bot.addTokenReplacer(bot.managedExtraLoggers()...) } func (bot *Bot[T]) beginRun() error { diff --git a/bot_webhook.go b/bot_webhook.go index 9612ff0..3198dae 100644 --- a/bot_webhook.go +++ b/bot_webhook.go @@ -153,6 +153,7 @@ func (bot *Bot[T]) RunWebHookWithContext(ctx context.Context, opts *BotWebHookOp } bot.webHookLogger = utils.CreateLogger("WEBHOOK", bot.GetLoggerLevel()) + bot.addTokenReplacer(bot.webHookLogger) if opts.SecretToken == "" { bot.webHookLogger.Warnln("Bot webhook secret token empty. It's VERY recommended to set secret.") } diff --git a/utils/version.go b/utils/version.go index 5209b17..abd6b55 100644 --- a/utils/version.go +++ b/utils/version.go @@ -2,7 +2,7 @@ package utils const ( // VersionString is the module version string. - VersionString = "1.0.0-rc.15" + VersionString = "1.0.0-rc.16" // VersionMajor is the module major version. VersionMajor = 1 // VersionMinor is the module minor version. @@ -10,5 +10,5 @@ const ( // VersionPatch is the module patch version. VersionPatch = 0 // VersionBeta is the prerelease counter for the current version. - VersionBeta = 15 + VersionBeta = 16 )