From 1fa549fa18657e1b90b71b8a053759b21a4befaa Mon Sep 17 00:00:00 2001 From: tiennm99 Date: Sun, 28 Jun 2026 22:52:55 +0700 Subject: [PATCH] feat(modules): log every command with input, sender, chat, result Emit one structured line per authorized command: input text, sender id + username, chat type/id/title (DM vs group), and outcome (INFO ok / ERROR with err). Replaces the prior error-only log; denied commands stay silent. --- internal/modules/dispatcher.go | 35 ++++++++++++- internal/modules/dispatcher_test.go | 76 +++++++++++++++++++++++++++-- 2 files changed, 105 insertions(+), 6 deletions(-) diff --git a/internal/modules/dispatcher.go b/internal/modules/dispatcher.go index fbc68a1..655ae35 100644 --- a/internal/modules/dispatcher.go +++ b/internal/modules/dispatcher.go @@ -74,15 +74,46 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) { defer cancel() reg.RunCommandHooks(hookCtx, cmdCopy.Name, update) }() - if err := cmdCopy.Handler(ctx, b, update); err != nil { + err := cmdCopy.Handler(ctx, b, update) + if err != nil { metrics.IncError("handler-error") - log.Error("command failed", "command", cmdCopy.Name, "err", err) } + logCommand(cmdCopy.Name, update, err) }, ) } } +// 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 +// simple — "ok" via INFO, or the handler error via ERROR — because handler +// return values can be arbitrarily complex; the error plus context is the useful +// part. msg is non-nil here: matchCommand only matches updates with a Message. +func logCommand(name string, update *models.Update, err error) { + msg := update.Message + fields := []any{ + "command", name, + "input", msg.Text, + "chat_type", string(msg.Chat.Type), + "chat_id", msg.Chat.ID, + } + if msg.Chat.Title != "" { + fields = append(fields, "chat_title", msg.Chat.Title) + } + if from := msg.From; from != nil { + fields = append(fields, "user_id", from.ID) + if from.Username != "" { + fields = append(fields, "username", from.Username) + } + } + if err != nil { + log.Error("command", append(fields, "err", err)...) + return + } + log.Info("command", fields...) +} + // matchCommand reports whether update is a text message whose bot_command // entity (after stripping any @botname suffix) equals name. Mirrors the // library's HandlerTypeMessageText + MatchTypeCommand semantics but tolerates diff --git a/internal/modules/dispatcher_test.go b/internal/modules/dispatcher_test.go index eadc047..1e571e7 100644 --- a/internal/modules/dispatcher_test.go +++ b/internal/modules/dispatcher_test.go @@ -1,9 +1,15 @@ package modules import ( + "bytes" + "encoding/json" + "errors" + "log/slog" "testing" "github.com/go-telegram/bot/models" + + "github.com/tiennm99/miti99bot/internal/log" ) func TestAuth_Permits(t *testing.T) { @@ -21,10 +27,10 @@ func TestAuth_Permits(t *testing.T) { } cases := []struct { - name string - v Visibility - update *models.Update - expect bool + name string + v Visibility + update *models.Update + expect bool }{ {"public-no-message", VisibilityPublic, &models.Update{}, true}, {"public-stranger", VisibilityPublic, updateFrom(stranger), true}, @@ -151,6 +157,68 @@ func TestMatchCommand(t *testing.T) { } } +func TestLogCommand(t *testing.T) { + capture := func(update *models.Update, err error) map[string]any { + var buf bytes.Buffer + prev := log.Default() + log.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + defer log.SetDefault(prev) + + logCommand("ping", update, err) + + var out map[string]any + if e := json.Unmarshal(buf.Bytes(), &out); e != nil { + t.Fatalf("log line not JSON: %v (%q)", e, buf.String()) + } + return out + } + + t.Run("group success logs input, sender, chat", func(t *testing.T) { + update := &models.Update{Message: &models.Message{ + Text: "/ping now", + From: &models.User{ID: 42, Username: "alice"}, + Chat: models.Chat{ID: -100, Type: models.ChatTypeSupergroup, Title: "Squad"}, + }} + got := capture(update, nil) + if got["level"] != "INFO" { + t.Errorf("level = %v, want INFO", got["level"]) + } + want := map[string]any{ + "command": "ping", "input": "/ping now", "chat_type": "supergroup", + "chat_title": "Squad", "username": "alice", + } + for k, v := range want { + if got[k] != v { + t.Errorf("%s = %v, want %v", k, got[k], v) + } + } + if got["user_id"].(float64) != 42 || got["chat_id"].(float64) != -100 { + t.Errorf("ids = user %v chat %v, want 42 / -100", got["user_id"], got["chat_id"]) + } + }) + + t.Run("dm error logs at ERROR with err", func(t *testing.T) { + update := &models.Update{Message: &models.Message{ + Text: "/ping", + From: &models.User{ID: 7}, + Chat: models.Chat{ID: 7, Type: models.ChatTypePrivate}, + }} + got := capture(update, errors.New("boom")) + if got["level"] != "ERROR" { + t.Errorf("level = %v, want ERROR", got["level"]) + } + if got["err"] != "boom" { + t.Errorf("err = %v, want boom", got["err"]) + } + if _, hasTitle := got["chat_title"]; hasTitle { + t.Error("DM should not log chat_title") + } + if _, hasUser := got["username"]; hasUser { + t.Error("missing username should be omitted") + } + }) +} + func TestAuth_ZeroDeniesAllGated(t *testing.T) { // Misconfigured deploy: zero-value Auth must deny every Protected/Private // command without panicking, so an unconfigured bot cannot be hijacked