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.
This commit is contained in:
2026-06-28 22:52:55 +07:00
parent 9d5b774846
commit 1fa549fa18
2 changed files with 105 additions and 6 deletions
+33 -2
View File
@@ -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
+72 -4
View File
@@ -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