From 24f0cde1b3a9b35f624da9ad4fb2b99b2d1f2a16 Mon Sep 17 00:00:00 2001 From: tiennm99 Date: Tue, 25 Aug 2026 15:54:01 +0700 Subject: [PATCH] feat(modules): recover panics in command and callback dispatch The bot runs with WithNotAsyncHandlers and a single worker, so handlers execute inline on the polling goroutine. A panic in any handler therefore killed the process and took every user's bot down with it. Wrap the command closure, the callback closure and the detached command hook in a recover barrier. The callback path also answers the pending query so the client stops spinning rather than waiting out its timeout. The barrier is a backstop, not a licence to skip nil checks: handlers still guard their own inputs. --- internal/modules/dispatcher.go | 44 ++++- internal/modules/dispatcher_panic_test.go | 203 ++++++++++++++++++++++ 2 files changed, 245 insertions(+), 2 deletions(-) create mode 100644 internal/modules/dispatcher_panic_test.go diff --git a/internal/modules/dispatcher.go b/internal/modules/dispatcher.go index 373af35..4416a69 100644 --- a/internal/modules/dispatcher.go +++ b/internal/modules/dispatcher.go @@ -2,6 +2,7 @@ package modules import ( "context" + "runtime/debug" "strings" "time" @@ -71,6 +72,7 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) { return matchCommand(nameCopy, update) }, func(ctx context.Context, b *bot.Bot, update *models.Update) { + defer recoverHandler("command", cmdCopy.Name, nil) if !auth.Permits(cmdCopy.Visibility, update) { return // silent — do not leak existence of gated commands } @@ -78,6 +80,10 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) { // context.Background is intentional: the hook must outlive the request // context so stats writes complete even after the handler returns. go func() { //nolint:gosec // G118: goroutine intentionally detached from request context + // This goroutine is outside the handler's barrier above, so + // it needs its own: a panicking hook on its own goroutine + // still terminates the process. + defer recoverHandler("command hook", cmdCopy.Name, nil) hookCtx, cancel := context.WithTimeout(context.Background(), 2*time.Second) defer cancel() reg.RunCommandHooks(hookCtx, cmdCopy.Name, update) @@ -95,6 +101,11 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) { prefixCopy := prefix b.RegisterHandler(bot.HandlerTypeCallbackQueryData, prefixCopy, bot.MatchTypePrefix, func(ctx context.Context, b *bot.Bot, update *models.Update) { + defer recoverHandler("callback", prefixCopy, func() { + if update != nil && update.CallbackQuery != nil { + _, _ = b.AnswerCallbackQuery(ctx, &bot.AnswerCallbackQueryParams{CallbackQueryID: update.CallbackQuery.ID}) + } + }) if !auth.Permits(callbackCopy.Visibility, update) { if update != nil && update.CallbackQuery != nil { _, _ = b.AnswerCallbackQuery(ctx, &bot.AnswerCallbackQueryParams{CallbackQueryID: update.CallbackQuery.ID}) @@ -110,6 +121,34 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) { } } +// recoverHandler contains a panic raised by a module handler. The bot runs with +// bot.WithNotAsyncHandlers() and a single worker, so the handler executes inline +// on the polling goroutine: without this barrier one panicking handler ends the +// process for every user. Mirrors the barrier the cron scheduler already puts +// around its handlers (internal/cron/scheduler.go). +// +// The panic is logged at ERROR with a full stack and counted under a distinct +// handler-panic metric, so a handler that panics on every call is loud rather +// than quietly failing per-request. +// +// onPanic, when non-nil, runs after logging — the callback path uses it to +// answer the query so the caller's client stops showing a spinner. It is itself +// guarded, because a panic raised inside the recovery path would have no +// remaining barrier. +func recoverHandler(kind, name string, onPanic func()) { + rec := recover() + if rec == nil { + return + } + metrics.IncError("handler-panic") + log.Error(kind+" panic", kind, name, "panic", rec, "stack", string(debug.Stack())) + if onPanic == nil { + return + } + defer func() { _ = recover() }() + onPanic() +} + // logCommand emits one structured line per authorized command invocation: what // was typed (input), who sent it (user id + @username), where (DM vs group, with // chat id and — for groups — the title), and the outcome. The result is kept @@ -163,8 +202,9 @@ func matchCommand(name string, update *models.Update) bool { continue } // Bounds check: defensive against malformed entities from a future - // API revision; the library's match func omits this so a bad entity - // would panic the goroutine before our recover() in webhook.go. + // API revision. The library's match func omits it, and a matcher runs + // outside Install's panic barrier, so a bad entity would panic the + // polling goroutine with nothing to catch it. end := e.Offset + e.Length if e.Offset < 0 || end > len(text) || e.Length < 1 { continue diff --git a/internal/modules/dispatcher_panic_test.go b/internal/modules/dispatcher_panic_test.go new file mode 100644 index 0000000..14980cc --- /dev/null +++ b/internal/modules/dispatcher_panic_test.go @@ -0,0 +1,203 @@ +package modules_test + +import ( + "bytes" + "context" + "log/slog" + "strings" + "sync" + "testing" + "time" + + "github.com/go-telegram/bot" + "github.com/go-telegram/bot/models" + + "github.com/tiennm99/miti99bot/internal/log" + "github.com/tiennm99/miti99bot/internal/metrics" + "github.com/tiennm99/miti99bot/internal/modules" + "github.com/tiennm99/miti99bot/internal/storage" + "github.com/tiennm99/miti99bot/internal/testutil" +) + +// The bot dispatches updates inline on a single polling goroutine +// (bot.WithNotAsyncHandlers), so an unrecovered handler panic takes the whole +// process down for every user — not just the caller who triggered it. These +// tests pin the barrier that stops that: the panic is contained, logged with a +// stack, and counted, and the process (here, the test binary) survives. + +// syncBuffer is a log sink safe to read while another goroutine writes. +// +// slog is concurrency-safe, but the *sink* it writes into is the test's +// responsibility — and one of these tests deliberately provokes a panic on a +// detached goroutine, which then logs while the test reads. +type syncBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *syncBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *syncBuffer) String() string { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.String() +} + +// captureLogs redirects the default logger for the duration of fn and returns +// everything written. Mirrors TestLogCommand's idiom. +func captureLogs(t *testing.T, fn func()) string { + t.Helper() + buf := &syncBuffer{} + prev := log.Default() + log.SetDefault(slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + defer log.SetDefault(prev) + fn() + return buf.String() +} + +// waitForLog polls buf until it contains needle, so a test never races a +// detached goroutine with a fixed sleep. +func waitForLog(t *testing.T, buf *syncBuffer, needle string) { + t.Helper() + deadline := time.Now().Add(5 * time.Second) + for time.Now().Before(deadline) { + if strings.Contains(buf.String(), needle) { + return + } + time.Sleep(5 * time.Millisecond) + } + t.Fatalf("timed out waiting for %q; log was %q", needle, buf.String()) +} + +// installPanicking builds a registry with one command and one callback that +// both panic, and installs it on a recording bot. +func installPanicking(t *testing.T) *testutil.RecordingBot { + t.Helper() + rb := testutil.NewRecordingBot(t) + reg, err := modules.Build([]string{"boom"}, map[string]modules.Factory{ + "boom": func(modules.Deps) modules.Module { + return modules.Module{ + Commands: []modules.Command{{ + Name: "boom", + Visibility: modules.VisibilityPublic, + Description: "panics on purpose", + Handler: func(context.Context, *bot.Bot, *models.Update) error { + panic("command exploded") + }, + }}, + Callbacks: []modules.Callback{{ + Prefix: "boom:", + Visibility: modules.VisibilityPublic, + Handler: func(context.Context, *bot.Bot, *models.Update) error { + panic("callback exploded") + }, + }}, + } + }, + }, storage.NewMemoryProvider(), modules.BuildOptions{}) + if err != nil { + t.Fatalf("build registry: %v", err) + } + modules.Install(rb.Bot, reg, modules.Auth{}) + return rb +} + +func TestInstall_CommandPanicIsContained(t *testing.T) { + rb := installPanicking(t) + + // The assertion is that this line returns at all: without the barrier the + // panic unwinds through ProcessUpdate and kills the test binary. + logs := captureLogs(t, func() { + rb.Bot.ProcessUpdate(context.Background(), testutil.NewPrivateMessage(42, "/boom")) + metrics.Flush() + }) + + if !strings.Contains(logs, "command panic") { + t.Errorf("panic not logged; got %q", logs) + } + if !strings.Contains(logs, "command exploded") { + t.Errorf("panic value not logged; got %q", logs) + } + if !strings.Contains(logs, "stack") { + t.Errorf("stack not logged; got %q", logs) + } + // metrics.Flush renders the error counters into its log line, which is the + // only view of them from outside the metrics package. + if !strings.Contains(logs, "handler-panic") { + t.Errorf("handler-panic metric not incremented; got %q", logs) + } +} + +func TestInstall_CallbackPanicIsContainedAndAnswered(t *testing.T) { + rb := installPanicking(t) + + update := &models.Update{CallbackQuery: &models.CallbackQuery{ + ID: "cbq-1", + From: models.User{ID: 42}, + Data: "boom:go", + }} + + logs := captureLogs(t, func() { + rb.Bot.ProcessUpdate(context.Background(), update) + }) + + if !strings.Contains(logs, "callback panic") { + t.Errorf("panic not logged; got %q", logs) + } + + // A panicking callback must still answer the query, or the caller's client + // spins until it times out. + var answered bool + for _, call := range rb.Sent() { + if call.Method == "answerCallbackQuery" && call.Form["callback_query_id"] == "cbq-1" { + answered = true + } + } + if !answered { + t.Errorf("callback query not answered after panic; sent %+v", rb.Sent()) + } +} + +// The stats module registers a CommandHook, which runs on a detached goroutine +// outside the handler's barrier. A panic there has nothing above it on that +// goroutine's stack, so it terminates the process regardless of how well the +// handler itself is protected. +func TestInstall_CommandHookPanicIsContained(t *testing.T) { + rb := testutil.NewRecordingBot(t) + reg, err := modules.Build([]string{"hooky"}, map[string]modules.Factory{ + "hooky": func(modules.Deps) modules.Module { + return modules.Module{ + Commands: []modules.Command{{ + Name: "hooky", + Visibility: modules.VisibilityPublic, + Description: "fine itself; its hook is not", + Handler: func(context.Context, *bot.Bot, *models.Update) error { + return nil + }, + }}, + CommandHook: func(context.Context, string, *models.Update) { + panic("hook exploded") + }, + } + }, + }, storage.NewMemoryProvider(), modules.BuildOptions{}) + if err != nil { + t.Fatalf("build registry: %v", err) + } + modules.Install(rb.Bot, reg, modules.Auth{}) + + buf := &syncBuffer{} + prev := log.Default() + log.SetDefault(slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + defer log.SetDefault(prev) + + rb.Bot.ProcessUpdate(context.Background(), testutil.NewPrivateMessage(42, "/hooky")) + + // The assertion is that the test binary is still alive to run it: without + // the barrier, the hook's panic has nothing above it on its own goroutine. + waitForLog(t, buf, "command hook panic") +}