tiennm99/miti99bot
1
0
Fork 0
mirror of https://github.com/tiennm99/miti99bot.git synced 2026-09-05 02:20:00 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(log): structured slog.JSONHandler + 22-site rewire

Browse Source 
Phase 4 of the 2026-05-09 review remediation plan.

- internal/log: thin facade over log/slog.NewJSONHandler writing to
  stdout. Cloud Run's Cloud Logging integration auto-parses level,
  time, msg fields. Honours LOG_LEVEL env (debug|info|warn|error).
  Re-exports Info/Warn/Error/Fatal/Debug/With ergonomics.
- Migrated all 22 stdlib log call sites: cmd/server/main.go (17),
  internal/server/router.go (2), internal/modules/dispatcher.go (1),
  internal/telegram/webhook.go (1), internal/modules/misc/misc.go (1).
  Format-string args replaced with structured key/value attrs.
- Closes log-injection class (J3 from security audit) — slog escapes
  newlines and quotes inside field values, so attacker-controlled
  strings cannot synthesise fake log records (test:
  TestNewlineEscaping_NoLogInjection).

go test -race -count=1 ./... clean across all 13 packages. Zero
stdlib log imports remain outside internal/log.
This commit is contained in:
tiennm99
2026-05-09 16:01:00 +07:00
parent 576b6b6aec
commit 1f09d0926b
9 changed files with 269 additions and 36 deletions
Download Patch File Download Diff File Expand all files Collapse all files
cmd/server/main.go
+25 -19
View File
@@ -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
internal/log/log.go
+84
View File
@@ -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...)
}
internal/log/log_test.go
+139
View File
@@ -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"])
}
}
internal/modules/dispatcher.go
+3 -2
View File
@@ -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)
}
},
)
internal/modules/misc/misc.go
+2 -2
View File
@@ -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")
},
internal/server/router.go
+3 -3
View File
@@ -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
}
internal/telegram/webhook.go
+5 -2
View File
@@ -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)
plans/260509-1308-fix-all-review-findings/phase-04-structured-logging.md
+7 -7
View File
@@ -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.
plans/260509-1308-fix-all-review-findings/plan.md
+1 -1
View File
@@ -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 |