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.
2026-09-05 08:17:39 +00:00 · 2026-08-25 15:54:01 +07:00
parent e56f5c5d7d
commit 24f0cde1b3
2 changed files with 245 additions and 2 deletions
@@ -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
@@ -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")
+}