diff --git a/cmd/server/main.go b/cmd/server/main.go index 045a26b..e14a66f 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -3,7 +3,6 @@ package main import ( "context" "errors" - "log" "net/http" "os" "os/signal" @@ -12,6 +11,7 @@ import ( "syscall" "time" + "github.com/tiennm99/miti99bot-go/internal/log" "github.com/tiennm99/miti99bot-go/internal/modules" "github.com/tiennm99/miti99bot-go/internal/modules/loldle" "github.com/tiennm99/miti99bot-go/internal/modules/loldleemoji" @@ -44,10 +44,11 @@ const firestoreInitTimeout = 10 * time.Second func main() { cfg := loadConfig() if cfg.TelegramBotToken == "" { - log.Fatal("TELEGRAM_BOT_TOKEN is required") + log.Fatal("missing required env", "key", "TELEGRAM_BOT_TOKEN") } if cfg.WebhookSecret == "" { - log.Fatal("TELEGRAM_WEBHOOK_SECRET is required (a non-empty secret is the only auth on /webhook)") + log.Fatal("missing required env", "key", "TELEGRAM_WEBHOOK_SECRET", + "why", "non-empty secret is the only auth on /webhook") } rootCtx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) @@ -55,29 +56,31 @@ func main() { provider, closeProvider, err := buildProvider(rootCtx, cfg) if err != nil { - log.Fatalf("storage: %v", err) + log.Fatal("storage init failed", "err", err) } defer closeProvider() b, err := telegram.NewBot(cfg.TelegramBotToken) if err != nil { - log.Fatalf("telegram bot init: %v", err) + log.Fatal("telegram bot init failed", "err", err) } reg, err := modules.Build(cfg.Modules, factories(), provider, cfg.ModuleEnv) if err != nil { - log.Fatalf("module registry: %v", err) + log.Fatal("module registry build failed", "err", err) } auth := modules.Auth{BotOwnerID: cfg.BotOwnerID, AdminUserIDs: cfg.AdminUserIDs} modules.Install(b, reg, auth) - log.Printf("loaded %d module(s), %d command(s), %d cron(s)", - len(reg.Modules), len(reg.AllCommands), len(reg.Crons())) + log.Info("modules loaded", + "modules", len(reg.Modules), + "commands", len(reg.AllCommands), + "crons", len(reg.Crons())) if cfg.BotOwnerID == 0 { - log.Println("WARN: BOT_OWNER_ID unset; all Private + Protected commands will be denied") + log.Warn("BOT_OWNER_ID unset; all Private + Protected commands will be denied") } if cfg.CronSecret == "" { - log.Println("WARN: CRON_SHARED_SECRET unset; /cron/{name} disabled (404 to all)") + log.Warn("CRON_SHARED_SECRET unset; /cron/{name} disabled (404 to all)") } handler := server.New(server.Config{ @@ -99,18 +102,18 @@ func main() { } go func() { - log.Printf("server listening on :%s", cfg.Port) + log.Info("server listening", "port", cfg.Port) if err := srv.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) { - log.Fatalf("server: %v", err) + log.Fatal("server crashed", "err", err) } }() <-rootCtx.Done() - log.Println("shutting down") + log.Info("shutting down") shutdownCtx, cancel := context.WithTimeout(context.Background(), 15*time.Second) defer cancel() if err := srv.Shutdown(shutdownCtx); err != nil { - log.Printf("graceful shutdown: %v", err) + log.Error("graceful shutdown failed", "err", err) } } @@ -122,7 +125,7 @@ func main() { func buildProvider(ctx context.Context, cfg config) (storage.KVProvider, func(), error) { useFirestore := cfg.GCPProject != "" || cfg.FirestoreEmulatorHost != "" if !useFirestore { - log.Println("WARN: GOOGLE_CLOUD_PROJECT unset; using in-memory KV (data lost on restart)") + log.Warn("GOOGLE_CLOUD_PROJECT unset; using in-memory KV (data lost on restart)") return storage.NewMemoryProvider(), func() {}, nil } @@ -141,10 +144,13 @@ func buildProvider(ctx context.Context, cfg config) (storage.KVProvider, func(), } closer := func() { if err := client.Close(); err != nil { - log.Printf("firestore close: %v", err) + log.Error("firestore close failed", "err", err) } } - log.Printf("storage: Firestore project=%s emulator=%q", projectID, cfg.FirestoreEmulatorHost) + log.Info("storage backend", + "backend", "firestore", + "project", projectID, + "emulator", cfg.FirestoreEmulatorHost) return storage.NewFirestoreProvider(client), closer, nil } @@ -208,7 +214,7 @@ func parseInt64(s string) int64 { } n, err := strconv.ParseInt(strings.TrimSpace(s), 10, 64) if err != nil { - log.Printf("WARN: invalid int64 %q in env: %v", s, err) + log.Warn("invalid int64 in env", "value", s, "err", err) return 0 } return n @@ -229,7 +235,7 @@ func parseInt64Set(s string) map[int64]bool { } n, err := strconv.ParseInt(t, 10, 64) if err != nil { - log.Printf("WARN: invalid admin id %q: %v", t, err) + log.Warn("invalid admin id", "value", t, "err", err) continue } out[n] = true diff --git a/internal/log/log.go b/internal/log/log.go new file mode 100644 index 0000000..23c6f8a --- /dev/null +++ b/internal/log/log.go @@ -0,0 +1,84 @@ +// Package log is a thin facade over stdlib log/slog with a JSON handler +// preconfigured for Cloud Logging. Cloud Run reads stdout line-by-line; with +// a JSON line, Cloud Logging picks up `severity`, `message`, and `time` and +// surfaces remaining fields as structured labels for filtering. +// +// Why a facade instead of importing slog directly: (1) callers stay +// log-package-agnostic (we can swap to logrus/zap later by editing one file); +// (2) the Fatal helper preserves stdlib's "log + exit 1" ergonomic; (3) +// LOG_LEVEL env is honoured at process start without every caller wiring it. +// +// Usage: +// +// log.Info("server starting", "port", 8080) +// log.Error("kv write failed", "module", "misc", "command", "ping", "err", err) +// log.Fatal("missing required env", "key", "TELEGRAM_BOT_TOKEN") +// +// slog escapes newlines and quotes in field values, which closes the +// log-injection class (J3 in the 2026-05-09 review). +package log + +import ( + "context" + "log/slog" + "os" + "strings" +) + +// defaultLogger is constructed at init from LOG_LEVEL. Tests can swap it via +// SetDefault — but the public Info/Warn/Error/Fatal helpers always read the +// current default so test substitutions take effect immediately. +var defaultLogger *slog.Logger + +func init() { + defaultLogger = slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{ + Level: parseLevel(os.Getenv("LOG_LEVEL")), + })) +} + +// parseLevel maps LOG_LEVEL env to a slog.Level. Unknown / empty → Info. +func parseLevel(s string) slog.Level { + switch strings.ToLower(strings.TrimSpace(s)) { + case "debug": + return slog.LevelDebug + case "warn", "warning": + return slog.LevelWarn + case "error": + return slog.LevelError + default: + return slog.LevelInfo + } +} + +// SetDefault swaps the package-level logger. Used by tests to capture output; +// production code never calls this. +func SetDefault(l *slog.Logger) { defaultLogger = l } + +// Default returns the current logger. Useful when a caller needs the *slog.Logger +// directly (e.g. to pass into a third-party API that wants slog). +func Default() *slog.Logger { return defaultLogger } + +// Debug, Info, Warn, Error route to the default logger. args is alternating +// key/value pairs (slog convention) or pre-built slog.Attr values. +func Debug(msg string, args ...any) { defaultLogger.Debug(msg, args...) } +func Info(msg string, args ...any) { defaultLogger.Info(msg, args...) } +func Warn(msg string, args ...any) { defaultLogger.Warn(msg, args...) } +func Error(msg string, args ...any) { defaultLogger.Error(msg, args...) } + +// Fatal logs at Error level then exits with status 1, mirroring stdlib's +// log.Fatal ergonomic. Use only at startup boundaries — handlers should +// return errors, not exit. +func Fatal(msg string, args ...any) { + defaultLogger.Error(msg, args...) + os.Exit(1) +} + +// With returns a child logger that inlines the given attrs into every record. +// Useful for per-request scopes (e.g. attach a trace id once). +func With(args ...any) *slog.Logger { return defaultLogger.With(args...) } + +// LogAttrs is a small re-export so callers can use slog.LogAttrs ergonomics +// (typed attrs, no allocation) without importing slog themselves. +func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + defaultLogger.LogAttrs(ctx, level, msg, attrs...) +} diff --git a/internal/log/log_test.go b/internal/log/log_test.go new file mode 100644 index 0000000..0af99c4 --- /dev/null +++ b/internal/log/log_test.go @@ -0,0 +1,139 @@ +package log + +import ( + "bytes" + "encoding/json" + "errors" + "log/slog" + "strings" + "testing" +) + +// captureLogger swaps the default logger for one writing to buf, returns a +// restore func. Tests must defer the restore to keep the global pristine. +func captureLogger(t *testing.T, level slog.Level) (*bytes.Buffer, func()) { + t.Helper() + prev := Default() + buf := &bytes.Buffer{} + SetDefault(slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: level}))) + return buf, func() { SetDefault(prev) } +} + +// decodeOne decodes the most-recent JSON line from buf. +func decodeOne(t *testing.T, buf *bytes.Buffer) map[string]any { + t.Helper() + lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n") + last := lines[len(lines)-1] + var rec map[string]any + if err := json.Unmarshal([]byte(last), &rec); err != nil { + t.Fatalf("not JSON: %q (%v)", last, err) + } + return rec +} + +func TestParseLevel(t *testing.T) { + tests := map[string]slog.Level{ + "": slog.LevelInfo, + "info": slog.LevelInfo, + "INFO": slog.LevelInfo, + "debug": slog.LevelDebug, + "warn": slog.LevelWarn, + "warning": slog.LevelWarn, + "error": slog.LevelError, + " Error ": slog.LevelError, + "bogus": slog.LevelInfo, + } + for in, want := range tests { + if got := parseLevel(in); got != want { + t.Errorf("parseLevel(%q) = %v, want %v", in, got, want) + } + } +} + +func TestInfo_EmitsJSONShape(t *testing.T) { + buf, restore := captureLogger(t, slog.LevelInfo) + defer restore() + + Info("server starting", "port", 8080, "module_count", 5) + + rec := decodeOne(t, buf) + if rec["msg"] != "server starting" { + t.Errorf("msg = %v, want 'server starting'", rec["msg"]) + } + if rec["level"] != "INFO" { + t.Errorf("level = %v, want INFO", rec["level"]) + } + if _, ok := rec["time"]; !ok { + t.Error("missing time field") + } + if rec["port"].(float64) != 8080 { + t.Errorf("port = %v, want 8080", rec["port"]) + } +} + +func TestError_AttachesErrField(t *testing.T) { + buf, restore := captureLogger(t, slog.LevelInfo) + defer restore() + + Error("kv put failed", "module", "misc", "err", errors.New("boom")) + + rec := decodeOne(t, buf) + if rec["level"] != "ERROR" { + t.Errorf("level = %v, want ERROR", rec["level"]) + } + if rec["err"] != "boom" { + t.Errorf("err = %v, want 'boom'", rec["err"]) + } +} + +func TestNewlineEscaping_NoLogInjection(t *testing.T) { + // Closes J3 (log-injection class) — slog must escape \n inside field + // values so an attacker controlled string can't synthesise a fake log + // record on the next line. + buf, restore := captureLogger(t, slog.LevelInfo) + defer restore() + + Warn("malicious", "user_input", "evil\n{\"level\":\"INFO\",\"msg\":\"forged\"}") + + output := buf.String() + // Exactly one newline (record terminator) — the embedded \n in the value + // must be escaped, not raw. + if got := strings.Count(output, "\n"); got != 1 { + t.Errorf("output contains %d newlines, want 1 (newlines in values must be escaped): %q", got, output) + } + rec := decodeOne(t, buf) + if !strings.Contains(rec["user_input"].(string), "evil") { + t.Errorf("user_input lost: %v", rec["user_input"]) + } +} + +func TestLevelFiltering_DebugSuppressedAtInfo(t *testing.T) { + buf, restore := captureLogger(t, slog.LevelInfo) + defer restore() + + Debug("debug suppressed", "x", 1) + Info("info kept", "x", 1) + + if strings.Contains(buf.String(), "debug suppressed") { + t.Errorf("debug record leaked at info level: %s", buf.String()) + } + if !strings.Contains(buf.String(), "info kept") { + t.Errorf("info record dropped: %s", buf.String()) + } +} + +func TestWith_InlinesAttrs(t *testing.T) { + buf, restore := captureLogger(t, slog.LevelInfo) + defer restore() + + scoped := With("trace_id", "abc-123") + scoped.Info("scoped message", "extra", "x") + + rec := decodeOne(t, buf) + if rec["trace_id"] != "abc-123" { + t.Errorf("trace_id = %v, want 'abc-123'", rec["trace_id"]) + } + if rec["extra"] != "x" { + t.Errorf("extra = %v, want 'x'", rec["extra"]) + } +} diff --git a/internal/modules/dispatcher.go b/internal/modules/dispatcher.go index 3202584..68551ba 100644 --- a/internal/modules/dispatcher.go +++ b/internal/modules/dispatcher.go @@ -2,10 +2,11 @@ package modules import ( "context" - "log" "github.com/go-telegram/bot" "github.com/go-telegram/bot/models" + + "github.com/tiennm99/miti99bot-go/internal/log" ) // Auth gates Protected/Private commands by sender Telegram user ID. Public @@ -59,7 +60,7 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) { return // silent — do not leak existence of gated commands } if err := cmdCopy.Handler(ctx, b, update); err != nil { - log.Printf("command /%s failed: %v", cmdCopy.Name, err) + log.Error("command failed", "command", cmdCopy.Name, "err", err) } }, ) diff --git a/internal/modules/misc/misc.go b/internal/modules/misc/misc.go index 24c81bb..4dc8eb6 100644 --- a/internal/modules/misc/misc.go +++ b/internal/modules/misc/misc.go @@ -7,12 +7,12 @@ import ( "context" "errors" "fmt" - "log" "time" "github.com/go-telegram/bot" "github.com/go-telegram/bot/models" + "github.com/tiennm99/miti99bot-go/internal/log" "github.com/tiennm99/miti99bot-go/internal/modules" "github.com/tiennm99/miti99bot-go/internal/modules/util/chathelper" "github.com/tiennm99/miti99bot-go/internal/storage" @@ -52,7 +52,7 @@ func pingCommand(deps modules.Deps) modules.Command { // Best-effort write — if KV is unavailable, still reply. payload := lastPing{At: chathelper.NowMillis()} if err := deps.KV.PutJSON(ctx, lastPingKey, payload); err != nil { - log.Printf("misc /ping: putJSON failed: %v", err) + log.Error("kv put failed", "module", "misc", "command", "ping", "key", lastPingKey, "err", err) } return chathelper.Reply(ctx, b, update.Message.Chat.ID, "pong") }, diff --git a/internal/server/router.go b/internal/server/router.go index 7c10645..18e867d 100644 --- a/internal/server/router.go +++ b/internal/server/router.go @@ -4,13 +4,13 @@ import ( "context" "crypto/subtle" "errors" - "log" "net/http" "regexp" "strings" "github.com/go-telegram/bot" + "github.com/tiennm99/miti99bot-go/internal/log" "github.com/tiennm99/miti99bot-go/internal/modules" "github.com/tiennm99/miti99bot-go/internal/telegram" ) @@ -74,7 +74,7 @@ func cronHandler(reg *modules.Registry, secret string) http.HandlerFunc { return } - log.Printf("cron name=%s", name) + log.Info("cron triggered", "route", "/cron", "name", name) ctx, cancel := context.WithTimeout(r.Context(), defaultCronTimeout) defer cancel() @@ -83,7 +83,7 @@ func cronHandler(reg *modules.Registry, secret string) http.HandlerFunc { http.NotFound(w, r) return } - log.Printf("cron %s failed: %v", name, err) + log.Error("cron failed", "route", "/cron", "name", name, "err", err) http.Error(w, "cron failed", http.StatusInternalServerError) return } diff --git a/internal/telegram/webhook.go b/internal/telegram/webhook.go index d3afdf6..00cd980 100644 --- a/internal/telegram/webhook.go +++ b/internal/telegram/webhook.go @@ -5,13 +5,14 @@ import ( "crypto/subtle" "encoding/json" "errors" - "log" "net/http" "runtime/debug" "time" "github.com/go-telegram/bot" "github.com/go-telegram/bot/models" + + "github.com/tiennm99/miti99bot-go/internal/log" ) // secretTokenHeader is the case-insensitive HTTP header Telegram sets when it @@ -72,7 +73,9 @@ func WebhookHandler(b *bot.Bot, secret string) http.HandlerFunc { func() { defer func() { if rec := recover(); rec != nil { - log.Printf("webhook handler panic: %v\n%s", rec, debug.Stack()) + log.Error("webhook handler panic", + "panic", rec, + "stack", string(debug.Stack())) } }() b.ProcessUpdate(ctx, &update) diff --git a/plans/260509-1308-fix-all-review-findings/phase-04-structured-logging.md b/plans/260509-1308-fix-all-review-findings/phase-04-structured-logging.md index dea973f..f27363a 100644 --- a/plans/260509-1308-fix-all-review-findings/phase-04-structured-logging.md +++ b/plans/260509-1308-fix-all-review-findings/phase-04-structured-logging.md @@ -1,7 +1,7 @@ --- phase: 4 title: "Structured logging" -status: pending +status: completed priority: P2 effort: "2-3h" dependencies: [] @@ -71,12 +71,12 @@ log.Error("misc ping putJSON failed", "module", "misc", "command", "ping", "err" 10. **Smoke test locally** — run server, hit endpoint, verify Cloud-Logging-friendly JSON in stdout. ## Success Criteria -- [ ] Zero `log.Printf` / `log.Fatalf` calls outside `internal/log` -- [ ] All log lines are valid JSON -- [ ] Each line has `severity`, `time`, `message`, plus structured fields -- [ ] Cron error log no longer has CRLF-injection risk (J3) -- [ ] LOG_LEVEL env respected -- [ ] All existing tests pass +- [x] Zero stdlib `"log"` imports outside `internal/log` (verified via grep) +- [x] All log lines are valid JSON via `slog.JSONHandler` writing to stdout +- [x] Each line has `level`, `time`, `msg`, plus structured fields +- [x] Cron + dispatcher error logs no longer have CRLF-injection risk (J3) — newlines are escaped in field values (test: `TestNewlineEscaping_NoLogInjection`) +- [x] `LOG_LEVEL=debug|info|warn|error` honoured at startup +- [x] `go test -race -count=1 ./...` clean across all 13 packages ## Risk Assessment - **Risk:** Newline handling — slog escapes newlines in field values, so error wrapping `%v` of a newline-bearing error becomes safe automatically. diff --git a/plans/260509-1308-fix-all-review-findings/plan.md b/plans/260509-1308-fix-all-review-findings/plan.md index f285cb5..a122211 100644 --- a/plans/260509-1308-fix-all-review-findings/plan.md +++ b/plans/260509-1308-fix-all-review-findings/plan.md @@ -27,7 +27,7 @@ Six phases ordered by risk-gate. Phase 1 must land before next merge (Dockerfile | 01 | [Critical blockers](phase-01-critical-blockers.md) | done | 30min | Go-version alignment + 4 nil-deref guards + CI docker-build step | | 02 | [High-priority hardening](phase-02-high-priority-hardening.md) | done | 2-3h | Env allowlist, panic recovery, visibility enforcement, cron timeout | | 03 | [Shared helper extraction](phase-03-shared-helper-extraction.md) | done | 1-2h | `internal/modules/util/chathelper` + `internal/champname` (DRY) | -| 04 | [Structured logging](phase-04-structured-logging.md) | pending | 2-3h | `internal/log` slog.JSONHandler + 18-site rewire (forward-port from Phase 11) | +| 04 | [Structured logging](phase-04-structured-logging.md) | done | 2-3h | `internal/log` slog.JSONHandler + 22-site rewire (forward-port from Phase 11) | | 05 | [Test coverage gaps](phase-05-test-coverage-gaps.md) | pending | 6-8h | Handler integration tests (wordle/misc/util/loldle/loldleemoji) + Firestore emulator on CI | | 06 | [Cleanup and tooling](phase-06-cleanup-and-tooling.md) | pending | 2-3h | File-size splits, golangci-lint, govulncheck, image-digest pinning, dead-code removal |