Логирование: доменная граница ошибок + защита секретов в логах

Приём торрента через Telegram молча падал без записи в логах. Разобрали цепочку и починили логирование/обработку ошибок по конвенции logging.md (логирует граница домена один раз, транспорты — нет). Доменная граница логирует исход: - ingest.Ingest: сбой БД → ERROR, невалидный источник → DEBUG; - команды воркера (Apply/Cancel/Retry/Refine/…) — единый чокпоинт logCmd (ERROR для инфраструктурного сбоя; DEBUG для conflict/not-ready/not-found), закрывает и Telegram-, и HTTP-путь; дублирующие ERROR-логи в tgbot сняты; - внутренний логгер tgbotapi заведён в slog: сбои long-poll getUpdates больше не уходят в stdlib log мимо структурированных логов; - тихое закрытие канала обновлений бота → ERROR. Защита секретов (инвариант «секреты не в логи»): - общий logging.SanitizeErr убирает URL из *url.Error; - закрыты утечки токена бота (getMe на старте, getFile, Send/Request) и api_key TMDB (query-параметр, попадавший в *url.Error на ERROR); - покрыто тестом internal/logging/sanitize_test.go. Ревью двумя сабагентами (fable): инфраструктурные и доменные ошибки. Отложено (не в scope этого коммита): обёртка ErrConflict в Cancel/Defer/Retry и классификация 500→409/400, обновление docs/conventions. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
2026-07-10 14:29:38 +03:00
parent 5c3ef79496
commit f8fb4fabb3
11 changed files with 240 additions and 40 deletions
@@ -7,7 +7,6 @@ import (
 	"io"
 	"log/slog"
 	"net/http"
-	"net/url"
 	"strings"
 	"sync"
 	"time"
@@ -16,6 +15,7 @@ import (

 	"git.vakhrushev.me/av/jellybit/internal/ident"
 	"git.vakhrushev.me/av/jellybit/internal/ingest"
+	"git.vakhrushev.me/av/jellybit/internal/logging"
 	"git.vakhrushev.me/av/jellybit/internal/worker"
 )

@@ -106,6 +106,12 @@ func (b *Bot) Run(ctx context.Context) {
 			return
 		case u, ok := <-updates:
 			if !ok {
+				// Канал закрыт не по нашей отмене (ctx ещё жив) — библиотека
+				// прекратила приём обновлений: иначе бот молча перестал бы
+				// реагировать без следа в логах.
+				if ctx.Err() == nil {
+					b.log.Error("telegram updates channel closed unexpectedly")
+				}
 				return
 			}
 			b.handleUpdate(ctx, u)
@@ -147,6 +153,8 @@ func (b *Bot) handleMessage(ctx context.Context, m *tgbotapi.Message) {
 	// Ждём подсказку для перераспознавания?
 	if id, ok := b.takePending(m.Chat.ID); ok && !strings.Contains(text, "magnet:") {
 		if err := b.reviewer.Refine(ctx, id, text); err != nil {
+			// Ошибку логирует доменная граница (worker.Refine); транспорт лишь
+			// показывает пользователю (logging.md: «транспорты не логируют»).
 			b.send(m.Chat.ID, opErr("Не удалось обработать подсказку", id), nil)
 			return
 		}
@@ -161,6 +169,9 @@ func (b *Bot) handleMessage(ctx context.Context, m *tgbotapi.Message) {

 	source, context, ok := ParseMessage(text)
 	if !ok {
+		// Невалидный ввод — норма (пользователь получит отказ): DEBUG, чтобы
+		// при разборе «почему не приняло» отказ был виден в логах.
+		b.log.Debug("telegram source not recognized", "chat_id", m.Chat.ID)
 		b.send(m.Chat.ID, "Не вижу magnet-ссылки. Перешлите сообщение торрент-бота, пришлите magnet или .torrent-файл.", nil)
 		return
 	}
@@ -172,10 +183,12 @@ func (b *Bot) handleMessage(ctx context.Context, m *tgbotapi.Message) {
 func (b *Bot) handleDocument(ctx context.Context, m *tgbotapi.Message) {
 	doc := m.Document
 	if !isTorrentDoc(doc) {
+		b.log.Debug("telegram document rejected", "chat_id", m.Chat.ID, "reason", "not-torrent", "mime", doc.MimeType)
 		b.send(m.Chat.ID, "Это не .torrent-файл. Пришлите magnet-ссылку или .torrent.", nil)
 		return
 	}
 	if doc.FileSize > 0 && doc.FileSize > ingest.MaxTorrentSize {
+		b.log.Debug("telegram document rejected", "chat_id", m.Chat.ID, "reason", "too-large", "size", doc.FileSize)
 		b.send(m.Chat.ID, "Файл слишком большой для .torrent.", nil)
 		return
 	}
@@ -192,16 +205,6 @@ func (b *Bot) handleDocument(ctx context.Context, m *tgbotapi.Message) {
 	})
 }

-// stripURL убирает URL из ошибки *url.Error (URL файла Telegram содержит токен
-// бота), оставляя только первопричину — защита от утечки секрета в логи.
-func stripURL(err error) error {
-	var ue *url.Error
-	if errors.As(err, &ue) {
-		return ue.Err
-	}
-	return err
-}
-
 // isTorrentDoc — документ выглядит как .torrent (по mime или расширению).
 func isTorrentDoc(doc *tgbotapi.Document) bool {
 	if doc == nil {
@@ -218,20 +221,22 @@ func isTorrentDoc(doc *tgbotapi.Document) bool {
 //
 // ВАЖНО: прямой URL файла Telegram содержит токен бота
 // (…/file/bot<TOKEN>/<path>). Ошибки транспорта (*url.Error) встраивают этот
-// URL в текст — их нельзя возвращать/логировать как есть. stripURL оставляет
-// только первопричину без URL, чтобы токен не утёк в логи (см. logging.md).
+// URL в текст — их нельзя возвращать/логировать как есть. logging.SanitizeErr
+// оставляет только первопричину без URL, чтобы токен не утёк в логи (см.
+// logging.md). GetFileDirectURL тоже ходит в Bot API (…/bot<TOKEN>/getFile) —
+// его ошибку санитизируем так же.
 func (b *Bot) downloadFile(ctx context.Context, fileID string) ([]byte, error) {
 	fileURL, err := b.api.GetFileDirectURL(fileID)
 	if err != nil {
-		return nil, fmt.Errorf("file url: %w", err)
+		return nil, fmt.Errorf("file url: %w", logging.SanitizeErr(err))
 	}
 	req, err := http.NewRequestWithContext(ctx, http.MethodGet, fileURL, nil)
 	if err != nil {
-		return nil, fmt.Errorf("telegram file request: %w", stripURL(err))
+		return nil, fmt.Errorf("telegram file request: %w", logging.SanitizeErr(err))
 	}
 	resp, err := b.httpClient.Do(req)
 	if err != nil {
-		return nil, fmt.Errorf("telegram file GET: %w", stripURL(err))
+		return nil, fmt.Errorf("telegram file GET: %w", logging.SanitizeErr(err))
 	}
 	defer func() { _ = resp.Body.Close() }()
 	if resp.StatusCode != http.StatusOK {
@@ -340,6 +345,8 @@ func (b *Bot) handleCallback(ctx context.Context, cq *tgbotapi.CallbackQuery) {
 			b.send(chatID, opErr("Торрент ещё качается — дождитесь докачки", id), nil)
 			return
 		}
+		// Ошибку логирует доменная граница (соответствующая команда worker);
+		// транспорт лишь переводит её в ответ пользователю (logging.md).
 		b.answer(cq.ID, "Ошибка")
 		b.send(chatID, opErr("Не удалось выполнить действие", id), nil)
 		return
@@ -363,7 +370,7 @@ func (b *Bot) refreshCard(ctx context.Context, chatID int64, msgID int, id strin
 		edit = tgbotapi.NewEditMessageText(chatID, msgID, text)
 	}
 	if _, err := b.api.Send(edit); err != nil {
-		b.log.Warn("telegram edit card failed", "download_id", id, "error", err)
+		b.log.Warn("telegram edit card failed", "download_id", id, "error", logging.SanitizeErr(err))
 	}
 }

@@ -402,13 +409,13 @@ func (b *Bot) send(chatID int64, text string, kb *tgbotapi.InlineKeyboardMarkup)
 		msg.ReplyMarkup = *kb
 	}
 	if _, err := b.api.Send(msg); err != nil {
-		b.log.Warn("telegram send failed", "chat_id", chatID, "error", err)
+		b.log.Warn("telegram send failed", "chat_id", chatID, "error", logging.SanitizeErr(err))
 	}
 }

 func (b *Bot) answer(callbackID, text string) {
 	if _, err := b.api.Request(tgbotapi.NewCallback(callbackID, text)); err != nil {
-		b.log.Warn("telegram answer callback failed", "error", err)
+		b.log.Warn("telegram answer callback failed", "error", logging.SanitizeErr(err))
 	}
 }

@@ -419,7 +426,7 @@ func (b *Bot) editMarkup(chatID int64, msgID int, kb *tgbotapi.InlineKeyboardMar
 		return
 	}
 	if _, err := b.api.Send(tgbotapi.NewEditMessageReplyMarkup(chatID, msgID, *kb)); err != nil {
-		b.log.Warn("telegram edit markup failed", "chat_id", chatID, "error", err)
+		b.log.Warn("telegram edit markup failed", "chat_id", chatID, "error", logging.SanitizeErr(err))
 	}
 }

@@ -63,7 +63,7 @@ func TestBot_DocumentByExtension(t *testing.T) {

 // Ошибка скачивания не должна утекать токен бота (URL файла Telegram содержит
 // …/bot<TOKEN>/…). Транспортная ошибка *url.Error встраивает URL — проверяем,
-// что stripURL его убрал.
+// что logging.SanitizeErr его убрал.
 func TestBot_DownloadErrorNoTokenLeak(t *testing.T) {
 	b, api, _, _ := newTestBot(t, []int64{7})
 	// «Токен» в URL, указывающем на закрытый порт → ошибка транспорта.
@@ -0,0 +1,46 @@
+package tgbot
+
+import (
+	"fmt"
+	"log/slog"
+	"strings"
+
+	tgbotapi "github.com/go-telegram-bot-api/telegram-bot-api/v5"
+)
+
+// SetLibraryLogger направляет внутренние логи клиента tgbotapi в наш slog.
+//
+// Зачем: библиотека логирует сбои long-poll `getUpdates` через собственный
+// (stdlib `log`) логгер — МИМО slog. Из-за этого сетевые/API-ошибки поллинга не
+// попадали в структурированные JSON-логи: входящее сообщение молча не
+// подхватывалось, а в логах — пусто (см. logging.md). После вызова такие сбои
+// видны как `telegram library` (WARN).
+//
+// Токен вырезается из текста: строка ошибки транспорта — `*url.Error` с URL вида
+// `…/bot<TOKEN>/getUpdates`, писать её как есть нельзя (утечка секрета в логи).
+// Замена по подстроке страхует и от прочих мест, где токен мог бы просочиться.
+//
+// Логгер в tgbotapi — глобальный на пакет; вызывать один раз при старте.
+func SetLibraryLogger(log *slog.Logger, token string) error {
+	return tgbotapi.SetLogger(libLogger{log: log, token: token})
+}
+
+type libLogger struct {
+	log   *slog.Logger
+	token string
+}
+
+func (l libLogger) Println(v ...any) { l.emit(fmt.Sprintln(v...)) }
+
+func (l libLogger) Printf(format string, v ...any) { l.emit(fmt.Sprintf(format, v...)) }
+
+func (l libLogger) emit(msg string) {
+	msg = strings.TrimSpace(msg)
+	if l.token != "" {
+		msg = strings.ReplaceAll(msg, l.token, "***")
+	}
+	// Сбои поллинга транзиентны (библиотека повторяет через 3 с) — WARN
+	// («retry внешнего вызова»); устойчивый сбой станет потоком WARN — сигнал
+	// разбираться, но не ERROR на каждый повтор.
+	l.log.Warn("telegram library", "detail", msg)
+}