diff --git a/cmd/jellybit/serve.go b/cmd/jellybit/serve.go index 7b01abd..9d603b6 100644 --- a/cmd/jellybit/serve.go +++ b/cmd/jellybit/serve.go @@ -182,9 +182,17 @@ func runServe(args []string) error { if perr != nil { return perr } + // Внутренние логи tgbotapi (сбои long-poll getUpdates и пр.) — в наш slog + // вместо stdlib log мимо структурированных логов; токен вырезается. + if lerr := tgbot.SetLibraryLogger(logger, cfg.Telegram.Token); lerr != nil { + logger.Warn("telegram library logger not set", "error", lerr) + } api, terr := tgbotapi.NewBotAPIWithClient(cfg.Telegram.Token, tgbotapi.APIEndpoint, tgClient) if terr != nil { - logger.Error("telegram bot disabled, cannot connect", "error", terr) + // NewBotAPIWithClient дёргает getMe: при недоступном Telegram/прокси + // terr — *url.Error с URL …/bot/getMe; санитизируем, чтобы + // токен не утёк в лог. + logger.Error("telegram bot disabled, cannot connect", "error", logging.SanitizeErr(terr)) } else { bot := tgbot.New(api, ingestor, wrk, tgbot.Config{ AllowedUserIDs: cfg.Telegram.AllowedUserIDs, diff --git a/internal/ingest/ingest.go b/internal/ingest/ingest.go index 0ecad06..81cdd2c 100644 --- a/internal/ingest/ingest.go +++ b/internal/ingest/ingest.go @@ -77,6 +77,9 @@ type Result struct { func (s *Service) Ingest(ctx context.Context, req Request) (Result, error) { src, err := s.parse(req) if err != nil { + // Невалидный источник — норма (адресат не команда, а пользователь, и он + // получит отказ на транспорте): DEBUG, чтобы не шуметь в аудите. + s.log.Debug("ingest source rejected", "capability", capIngest, "error", err) return Result{}, err } @@ -88,6 +91,8 @@ func (s *Service) Ingest(ctx context.Context, req Request) (Result, error) { // CreateDownloadIfNoActive ниже. Дедуп — по ЛЮБОМУ из хешей источника: // гибридный несёт и v1, и v2. if existing, err := s.store.FindActiveByInfohash(ctx, src.infohashes...); err != nil { + // Инфраструктурный сбой (БД) — операция приёма не выполнена: ERROR. + log.Error("ingest failed", "stage", "lookup-active", "error", err) return Result{}, fmt.Errorf("ingest: lookup active: %w", err) } else if existing != nil { log.Info("download attached to active", "download_id", existing.ID, "state", existing.State) @@ -109,6 +114,8 @@ func (s *Service) Ingest(ctx context.Context, req Request) (Result, error) { // транзакции лишь на ветке создания. existing, err := s.store.CreateDownloadIfNoActive(ctx, d, src.infohashes, src.torrentBlob) if err != nil { + // Инфраструктурный сбой (БД) — операция приёма не выполнена: ERROR. + log.Error("ingest failed", "stage", "create-download", "error", err) return Result{}, fmt.Errorf("ingest: create download: %w", err) } if existing != nil { diff --git a/internal/logging/ext.go b/internal/logging/ext.go index d7309a3..c20b2cb 100644 --- a/internal/logging/ext.go +++ b/internal/logging/ext.go @@ -54,12 +54,15 @@ func (c ExtCall) SuccessDebug(log *slog.Logger, extra ...any) { log.Debug("external call", c.attrs(extra...)...) } -// Retry логирует неудачную попытку, после которой будет повтор (WARN). +// Retry логирует неудачную попытку, после которой будет повтор (WARN). Ошибка +// санитизируется (SanitizeErr): транспортный сбой несёт URL с секретом +// (api_key TMDB в query, токен в пути) — в лог он попасть не должен. func (c ExtCall) Retry(log *slog.Logger, err error, extra ...any) { - log.Warn("external call retry", c.attrs(append([]any{"error", err}, extra...)...)...) + log.Warn("external call retry", c.attrs(append([]any{"error", SanitizeErr(err)}, extra...)...)...) } // Failure логирует окончательную неудачу вызова / недоступность сервиса (ERROR). +// Ошибка санитизируется (SanitizeErr) — см. Retry. func (c ExtCall) Failure(log *slog.Logger, err error, extra ...any) { - log.Error("external call failed", c.attrs(append([]any{"error", err}, extra...)...)...) + log.Error("external call failed", c.attrs(append([]any{"error", SanitizeErr(err)}, extra...)...)...) } diff --git a/internal/logging/sanitize.go b/internal/logging/sanitize.go new file mode 100644 index 0000000..9080d34 --- /dev/null +++ b/internal/logging/sanitize.go @@ -0,0 +1,24 @@ +package logging + +import ( + "errors" + "net/url" +) + +// SanitizeErr убирает из ошибки HTTP-транспорта URL запроса и возвращает только +// первопричину. Ошибки клиента net/http — `*url.Error`, чей текст встраивает +// полный URL, а URL может нести секрет: токен бота Telegram в пути +// (`…/bot/`) или api_key TMDB в query +// (`…/search/movie?api_key=&…`). Логировать или оборачивать такую ошибку +// как есть нельзя — секрет утечёт в логи (инвариант «секреты не в логи», см. +// logging.md, раздел «Безопасность»). +// +// Логическая операция при этом не теряется: она пишется отдельным полем +// (`ext.operation`) на границе клиента. Не `*url.Error` — возвращаем как есть. +func SanitizeErr(err error) error { + var ue *url.Error + if errors.As(err, &ue) { + return ue.Err + } + return err +} diff --git a/internal/logging/sanitize_test.go b/internal/logging/sanitize_test.go new file mode 100644 index 0000000..257b213 --- /dev/null +++ b/internal/logging/sanitize_test.go @@ -0,0 +1,63 @@ +package logging + +import ( + "errors" + "fmt" + "net/url" + "strings" + "testing" +) + +// SanitizeErr обязана убрать URL (носитель секрета) из *url.Error, оставив +// первопричину — это единый предохранитель от утечки токена/ключа в логи. +func TestSanitizeErr(t *testing.T) { + cause := errors.New("dial tcp 1.2.3.4:443: connect: connection refused") + + t.Run("url error with token in path", func(t *testing.T) { + ue := &url.Error{ + Op: "Get", + URL: "https://api.telegram.org/botSECRET123:AAtoken/getUpdates", + Err: cause, + } + got := SanitizeErr(ue) + if strings.Contains(got.Error(), "SECRET123") || strings.Contains(got.Error(), "AAtoken") { + t.Fatalf("токен утёк: %v", got) + } + if !errors.Is(got, cause) { + t.Fatalf("первопричина потеряна: %v", got) + } + }) + + t.Run("url error with api_key in query", func(t *testing.T) { + ue := &url.Error{ + Op: "Get", + URL: "https://api.themoviedb.org/3/search/movie?api_key=DEADBEEFSECRET&query=dune", + Err: cause, + } + if strings.Contains(SanitizeErr(ue).Error(), "DEADBEEFSECRET") { + t.Fatalf("api_key утёк: %v", SanitizeErr(ue)) + } + }) + + t.Run("wrapped url error is unwrapped via errors.As", func(t *testing.T) { + wrapped := fmt.Errorf("metadata: request: %w", &url.Error{ + Op: "Get", URL: "https://x/api_key=SECRET", Err: cause, + }) + if strings.Contains(SanitizeErr(wrapped).Error(), "SECRET") { + t.Fatalf("секрет утёк из обёрнутой ошибки: %v", SanitizeErr(wrapped)) + } + }) + + t.Run("non-url error passes through unchanged", func(t *testing.T) { + plain := errors.New("plain domain error") + if !errors.Is(SanitizeErr(plain), plain) { + t.Fatalf("обычная ошибка изменена: %v", SanitizeErr(plain)) + } + }) + + t.Run("nil stays nil", func(t *testing.T) { + if SanitizeErr(nil) != nil { + t.Fatal("nil должен оставаться nil") + } + }) +} diff --git a/internal/metadata/http.go b/internal/metadata/http.go index 379fd1b..d94802c 100644 --- a/internal/metadata/http.go +++ b/internal/metadata/http.go @@ -79,6 +79,10 @@ func doJSON(ctx context.Context, hc *http.Client, log *slog.Logger, service, ope call := logging.ExtCall{Service: service, Operation: operation, Start: time.Now()} resp, err := hc.Do(req) if err != nil { + // Транспортный сбой несёт *url.Error с полным URL, а у TMDB api_key — + // query-параметр: санитизируем до логирования И до обёртки, чтобы ключ + // не утёк ни в лог, ни вверх по цепочке %w. + err = logging.SanitizeErr(err) call.Failure(log, err) return fmt.Errorf("metadata: request: %w", err) } diff --git a/internal/tgbot/bot.go b/internal/tgbot/bot.go index 6c72c68..aa45e41 100644 --- a/internal/tgbot/bot.go +++ b/internal/tgbot/bot.go @@ -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/). Ошибки транспорта (*url.Error) встраивают этот -// URL в текст — их нельзя возвращать/логировать как есть. stripURL оставляет -// только первопричину без URL, чтобы токен не утёк в логи (см. logging.md). +// URL в текст — их нельзя возвращать/логировать как есть. logging.SanitizeErr +// оставляет только первопричину без URL, чтобы токен не утёк в логи (см. +// logging.md). GetFileDirectURL тоже ходит в Bot API (…/bot/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)) } } diff --git a/internal/tgbot/document_test.go b/internal/tgbot/document_test.go index 12a7db2..5fada10 100644 --- a/internal/tgbot/document_test.go +++ b/internal/tgbot/document_test.go @@ -63,7 +63,7 @@ func TestBot_DocumentByExtension(t *testing.T) { // Ошибка скачивания не должна утекать токен бота (URL файла Telegram содержит // …/bot/…). Транспортная ошибка *url.Error встраивает URL — проверяем, -// что stripURL его убрал. +// что logging.SanitizeErr его убрал. func TestBot_DownloadErrorNoTokenLeak(t *testing.T) { b, api, _, _ := newTestBot(t, []int64{7}) // «Токен» в URL, указывающем на закрытый порт → ошибка транспорта. diff --git a/internal/tgbot/liblog.go b/internal/tgbot/liblog.go new file mode 100644 index 0000000..1ffb7cb --- /dev/null +++ b/internal/tgbot/liblog.go @@ -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/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) +} diff --git a/internal/worker/review.go b/internal/worker/review.go index c2bac72..1901e19 100644 --- a/internal/worker/review.go +++ b/internal/worker/review.go @@ -225,7 +225,8 @@ func (w *Worker) overridesOrNil(ctx context.Context, id string) map[string]strin // Apply создаёт хардлинки по текущему плану (с применёнными правками) и // переводит задачу в done. Коллизия цели → остаёмся в review с причиной. -func (w *Worker) Apply(ctx context.Context, id string) error { +func (w *Worker) Apply(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "apply", id, err) }() w.mu.Lock() defer w.mu.Unlock() if w.layouter == nil { @@ -362,7 +363,8 @@ func (w *Worker) linkPlan(ctx context.Context, d *store.Download, plan recognize // перезапустит recognize. Авто-раскладку при этом не делаем — ручная // перепривязка всегда проходит через ревью с подтверждением (force_review). // Источник (раздача в qBittorrent) для этого должен быть на месте и докачан. -func (w *Worker) Relink(ctx context.Context, id string) error { +func (w *Worker) Relink(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "relink", id, err) }() w.mu.Lock() defer w.mu.Unlock() @@ -399,7 +401,8 @@ func (w *Worker) Relink(ctx context.Context, id string) error { // Rerecognize перезапускает распознавание для задачи в review/deferred без // добавления подсказки: контекст и прежние подсказки уже накоплены. Поллинг- // цикл проведёт задачу recognizing → review заново. -func (w *Worker) Rerecognize(ctx context.Context, id string) error { +func (w *Worker) Rerecognize(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "rerecognize", id, err) }() w.mu.Lock() defer w.mu.Unlock() @@ -417,7 +420,8 @@ func (w *Worker) Rerecognize(ctx context.Context, id string) error { } // Refine добавляет подсказку и отправляет задачу на перераспознавание. -func (w *Worker) Refine(ctx context.Context, id string, hint string) error { +func (w *Worker) Refine(ctx context.Context, id string, hint string) (err error) { + defer func() { w.logCmd(ctx, "refine", id, err) }() hint = strings.TrimSpace(hint) if hint == "" { return fmt.Errorf("refine: empty hint") @@ -443,7 +447,8 @@ func (w *Worker) Refine(ctx context.Context, id string, hint string) error { // SetType фиксирует тип (override) и перезапускает распознавание с подсказкой // — чтобы LLM пересобрал роли файлов под новый тип. -func (w *Worker) SetType(ctx context.Context, id string, mediaType string) error { +func (w *Worker) SetType(ctx context.Context, id string, mediaType string) (err error) { + defer func() { w.logCmd(ctx, "set_type", id, err) }() if mediaType != string(recognize.MediaMovie) && mediaType != string(recognize.MediaSeries) { return fmt.Errorf("set type: invalid type %q", mediaType) } @@ -474,7 +479,8 @@ func (w *Worker) SetType(ctx context.Context, id string, mediaType string) error // IgnoreFile помечает файл к игнорированию (не линкуем). Остаёмся в review; // превью пересчитается с учётом правки. -func (w *Worker) IgnoreFile(ctx context.Context, id string, src string) error { +func (w *Worker) IgnoreFile(ctx context.Context, id string, src string) (err error) { + defer func() { w.logCmd(ctx, "ignore_file", id, err) }() src = strings.TrimSpace(src) if src == "" { return fmt.Errorf("ignore: empty path") @@ -503,7 +509,8 @@ func (w *Worker) IgnoreFile(ctx context.Context, id string, src string) error { } // Defer паркует задачу в deferred (вернётся в ревью по действию). -func (w *Worker) Defer(ctx context.Context, id string) error { +func (w *Worker) Defer(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "defer", id, err) }() w.mu.Lock() defer w.mu.Unlock() @@ -523,7 +530,8 @@ func (w *Worker) Defer(ctx context.Context, id string) error { // Источник недосягаем (раскладчик удаляет только пути под библиотекой). Откат // снимает ЛИШНИЙ хардлинк, а не последнюю копию: layout.Undo отказывается // удалять ссылку, если источник уже пропал (nlink<=1) — см. state-reconciliation. -func (w *Worker) Undo(ctx context.Context, id string) error { +func (w *Worker) Undo(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "undo", id, err) }() w.mu.Lock() defer w.mu.Unlock() if w.layouter == nil { @@ -588,7 +596,8 @@ func laidOutLinks(rows []store.FileLink) []layout.Link { // в транспорте. Доступно из done/orphaned/target_missing; идемпотентно к // отсутствующей стороне. Source-preflight НЕ делает (цель — снять источник, // его отсутствие трактуем как уже снятую сторону). -func (w *Worker) Delete(ctx context.Context, id string) error { +func (w *Worker) Delete(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "delete", id, err) }() w.mu.Lock() defer w.mu.Unlock() if w.layouter == nil { @@ -666,7 +675,8 @@ func (w *Worker) requireReviewable(ctx context.Context, id string, op string) (* // ChooseCandidate пиннит выбранного кандидата базы как override (провайдер, // id, каноническое имя/год). Раскладку не запускает — превью обновится, а // человек подтвердит «Применить». -func (w *Worker) ChooseCandidate(ctx context.Context, id, candidateID string) error { +func (w *Worker) ChooseCandidate(ctx context.Context, id, candidateID string) (err error) { + defer func() { w.logCmd(ctx, "choose_candidate", id, err) }() w.mu.Lock() defer w.mu.Unlock() @@ -691,7 +701,8 @@ func (w *Worker) ChooseCandidate(ctx context.Context, id, candidateID string) er // AddManualSource добавляет источник вручную по (provider, id) и выбирает его. // Когда автопоиск промахнулся: сохраняем кандидата (дедуп по provider:id) и // пиннит как выбранный. provider — из набора tmdb/tvdb/imdb. -func (w *Worker) AddManualSource(ctx context.Context, id, provider, providerID string) error { +func (w *Worker) AddManualSource(ctx context.Context, id, provider, providerID string) (err error) { + defer func() { w.logCmd(ctx, "add_manual_source", id, err) }() provider = strings.TrimSpace(strings.ToLower(provider)) providerID = strings.TrimSpace(providerID) switch provider { @@ -786,7 +797,8 @@ func (w *Worker) chooseCandidateLocked(ctx context.Context, id string, d *store. } // SetProviderID пиннит провайдера и id вручную (без выбора из списка). -func (w *Worker) SetProviderID(ctx context.Context, id string, provider, providerID string) error { +func (w *Worker) SetProviderID(ctx context.Context, id string, provider, providerID string) (err error) { + defer func() { w.logCmd(ctx, "set_provider_id", id, err) }() provider = strings.TrimSpace(strings.ToLower(provider)) providerID = strings.TrimSpace(providerID) switch provider { @@ -818,7 +830,8 @@ func (w *Worker) SetProviderID(ctx context.Context, id string, provider, provide // ClearProvider — «без базы»: снимает матч (тег папки не ставится) и очищает // пины названия/года (источник — распознавание нейронкой). -func (w *Worker) ClearProvider(ctx context.Context, id string) error { +func (w *Worker) ClearProvider(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "clear_provider", id, err) }() w.mu.Lock() defer w.mu.Unlock() diff --git a/internal/worker/worker.go b/internal/worker/worker.go index dfed43f..d001662 100644 --- a/internal/worker/worker.go +++ b/internal/worker/worker.go @@ -775,9 +775,33 @@ func (w *Worker) shouldNotifyFail(id string) bool { return true } +// logCmd — единый чокпоинт логирования исхода команды воркера +// (apply/cancel/retry/…), вызываемой транспортами. Конвенция (logging.md, +// раздел «Ошибки»): доменную ошибку логирует граница домена ровно один раз, а +// транспорты (HTTP/web/Telegram) — нет. Команды воркера и есть эта граница. +// +// Уровень — по адресату: штатный отказ по состоянию/наличию +// (ErrConflict/ErrNotReady/ErrNotFound) адресован пользователю, он уже получил +// ответ на поверхности — DEBUG; всё прочее (сбой БД/ФС/зависимости) адресовано +// команде — ERROR. Успех (err == nil) — молча. Ставится в defer при именованном +// возврате, поэтому видит финальную ошибку и scoped-логгер, накопленный в ctx. +func (w *Worker) logCmd(ctx context.Context, cmd, id string, err error) { + if err == nil { + return + } + log := logctx.FromOr(ctx, w.log) + switch { + case errors.Is(err, ErrConflict), errors.Is(err, ErrNotReady), errors.Is(err, store.ErrNotFound): + log.Debug("command rejected", "command", cmd, "download_id", id, "error", err) + default: + log.Error("command failed", "command", cmd, "download_id", id, "error", err) + } +} + // Cancel отклоняет задачу. Торрент в qBittorrent не трогаем — он продолжает // раздачу (источник неприкосновенен). -func (w *Worker) Cancel(ctx context.Context, id string) error { +func (w *Worker) Cancel(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "cancel", id, err) }() w.mu.Lock() defer w.mu.Unlock() @@ -797,7 +821,8 @@ func (w *Worker) Cancel(ctx context.Context, id string) error { // Retry повторяет застрявшую/упавшую задачу: заново отдаёт источник в // qBittorrent и возвращает в downloading. -func (w *Worker) Retry(ctx context.Context, id string) error { +func (w *Worker) Retry(ctx context.Context, id string) (err error) { + defer func() { w.logCmd(ctx, "retry", id, err) }() w.mu.Lock() defer w.mu.Unlock()