diff --git a/cmd/jellybit/recognize.go b/cmd/jellybit/recognize.go index 4715649..e1a5604 100644 --- a/cmd/jellybit/recognize.go +++ b/cmd/jellybit/recognize.go @@ -41,7 +41,7 @@ func runRecognize(args []string) error { return fmt.Errorf("usage: jellybit recognize [--dry-run] [--context ...]") } if !*dryRun { - return fmt.Errorf("recognize работает только в режиме --dry-run; раскладка — через ревью") + return fmt.Errorf("recognize runs only in --dry-run mode; layout is applied via review") } cfg, err := config.Load(*configPath) @@ -49,7 +49,7 @@ func runRecognize(args []string) error { return err } if cfg.LLM.Type == "" || cfg.LLM.BaseURL == "" { - return fmt.Errorf("в конфиге не настроен [llm] — распознавание невозможно") + return fmt.Errorf("[llm] is not configured in config — recognition is unavailable") } // Внутренние логи (ретраи/ошибки провайдеров) — в stderr, чтобы не мешать // плану в stdout. @@ -63,7 +63,7 @@ func runRecognize(args []string) error { URL: cfg.QBittorrent.URL, Username: cfg.QBittorrent.Username, Password: cfg.QBittorrent.Password, - }) + }, logger) if err != nil { return err } @@ -73,7 +73,7 @@ func runRecognize(args []string) error { } t, ok := findTorrent(torrents, infohash) if !ok { - return fmt.Errorf("торрент с infohash %s не найден в qBittorrent", infohash) + return fmt.Errorf("torrent with infohash %s not found in qBittorrent", infohash) } files, err := qb.Files(ctx, t.Hash) if err != nil { @@ -81,14 +81,14 @@ func runRecognize(args []string) error { } // Провайдеры метаданных + LLM + распознаватель. - providers, err := metadataProviders(cfg) + providers, err := metadataProviders(cfg, logger) if err != nil { return err } provider, err := llm.New(llm.Config{ Type: cfg.LLM.Type, BaseURL: cfg.LLM.BaseURL, APIKey: cfg.LLM.APIKey, Model: cfg.LLM.Model, Proxy: cfg.LLM.Proxy, Timeout: cfg.LLM.Timeout.Std(), - }) + }, logger) if err != nil { return err } @@ -105,11 +105,11 @@ func runRecognize(args []string) error { start := time.Now() res, err := rec.Recognize(ctx, in) if err != nil { - return fmt.Errorf("распознавание: %w", err) + return fmt.Errorf("recognize: %w", err) } - // Раскладчик для превью (BuildLinks ничего не пишет). - lay, err := layout.New(layout.Config{MoviesDir: cfg.Paths.Movies, SeriesDir: cfg.Paths.Series}) + // Раскладчик для превью (BuildLinks ничего не пишет; логгер не нужен). + lay, err := layout.New(layout.Config{MoviesDir: cfg.Paths.Movies, SeriesDir: cfg.Paths.Series}, nil) if err != nil { return err } diff --git a/cmd/jellybit/serve.go b/cmd/jellybit/serve.go index 3059a48..45e1274 100644 --- a/cmd/jellybit/serve.go +++ b/cmd/jellybit/serve.go @@ -5,6 +5,7 @@ import ( "errors" "flag" "fmt" + "log/slog" "net/http" "net/url" "os/signal" @@ -55,7 +56,7 @@ func runServe(args []string) error { URL: cfg.QBittorrent.URL, Username: cfg.QBittorrent.Username, Password: cfg.QBittorrent.Password, - }) + }, logger) if err != nil { return err } @@ -66,7 +67,7 @@ func runServe(args []string) error { }, logger) // Ф4: базы метаданных (опц.). Без них авто-раскладки нет — всё в review. - providers, err := metadataProviders(cfg) + providers, err := metadataProviders(cfg, logger) if err != nil { return err } @@ -85,7 +86,7 @@ func runServe(args []string) error { Model: cfg.LLM.Model, Proxy: cfg.LLM.Proxy, Timeout: cfg.LLM.Timeout.Std(), - }) + }, logger) if perr != nil { return fmt.Errorf("llm provider: %w", perr) } @@ -101,7 +102,7 @@ func runServe(args []string) error { layouter, err := layout.New(layout.Config{ MoviesDir: cfg.Paths.Movies, SeriesDir: cfg.Paths.Series, - }) + }, logger) if err != nil { return fmt.Errorf("layouter: %w", err) } @@ -208,14 +209,14 @@ func telegramHTTPClient(proxy string) (*http.Client, error) { // metadataProviders собирает включённые конфигом базы метаданных. Для // сериалов Jellyfin привычнее tvdbid, поэтому TVDB идёт первым. -func metadataProviders(cfg *config.Config) ([]metadata.Provider, error) { +func metadataProviders(cfg *config.Config, logger *slog.Logger) ([]metadata.Provider, error) { var out []metadata.Provider // TVMaze без ключа и покрывает сериалы — ставим первым. if cfg.Metadata.TVMaze.Enabled { p, err := metadata.NewTVMaze(metadata.TVMazeConfig{ Proxy: cfg.Metadata.TVMaze.Proxy, Timeout: cfg.Metadata.TVMaze.Timeout.Std(), - }) + }, logger) if err != nil { return nil, fmt.Errorf("tvmaze provider: %w", err) } @@ -228,7 +229,7 @@ func metadataProviders(cfg *config.Config) ([]metadata.Provider, error) { APIKey: cfg.Metadata.TVDB.APIKey, Proxy: cfg.Metadata.TVDB.Proxy, Timeout: cfg.Metadata.TVDB.Timeout.Std(), - }) + }, logger) if err != nil { return nil, fmt.Errorf("tvdb provider: %w", err) } @@ -239,7 +240,7 @@ func metadataProviders(cfg *config.Config) ([]metadata.Provider, error) { APIKey: cfg.Metadata.TMDB.APIKey, Proxy: cfg.Metadata.TMDB.Proxy, Timeout: cfg.Metadata.TMDB.Timeout.Std(), - }) + }, logger) if err != nil { return nil, fmt.Errorf("tmdb provider: %w", err) } diff --git a/internal/httpapi/httpapi.go b/internal/httpapi/httpapi.go index 659648b..4c0be61 100644 --- a/internal/httpapi/httpapi.go +++ b/internal/httpapi/httpapi.go @@ -265,6 +265,7 @@ func (s *server) apiCommand(w http.ResponseWriter, r *http.Request, cmd func(con return } if err := cmd(r.Context(), id); err != nil { + s.deps.Logger.Warn("api command failed", "path", r.URL.Path, "id", id, "err", err) writeJSON(w, http.StatusConflict, errJSON(err)) return } diff --git a/internal/httpapi/review.go b/internal/httpapi/review.go index 1645c3f..6293158 100644 --- a/internal/httpapi/review.go +++ b/internal/httpapi/review.go @@ -151,6 +151,7 @@ func (s *server) handleApply(w http.ResponseWriter, r *http.Request) { return } if err := s.deps.Reviewer.Apply(r.Context(), id); err != nil { + s.deps.Logger.Warn("review action failed", "action", "apply", "id", id, "err", err) redirectReview(w, r, id, err.Error()) return } @@ -211,6 +212,7 @@ func (s *server) handleDefer(w http.ResponseWriter, r *http.Request) { return } if err := s.deps.Reviewer.Defer(r.Context(), id); err != nil { + s.deps.Logger.Warn("review action failed", "action", "defer", "id", id, "err", err) redirectReview(w, r, id, err.Error()) return } @@ -224,6 +226,7 @@ func (s *server) handleUndo(w http.ResponseWriter, r *http.Request) { return } if err := s.deps.Reviewer.Undo(r.Context(), id); err != nil { + s.deps.Logger.Warn("review action failed", "action", "undo", "id", id, "err", err) redirectErr(w, r, err.Error()) return } @@ -239,6 +242,8 @@ func (s *server) reviewAction(w http.ResponseWriter, r *http.Request, fn func(co return } if err := fn(r.Context(), id); err != nil { + s.deps.Logger.Warn("review action failed", + "action", r.URL.Path, "id", id, "err", err) redirectReview(w, r, id, err.Error()) return } diff --git a/internal/ingest/ingest.go b/internal/ingest/ingest.go index 5ddbc6c..068d986 100644 --- a/internal/ingest/ingest.go +++ b/internal/ingest/ingest.go @@ -101,6 +101,8 @@ func (s *Service) Ingest(ctx context.Context, req Request) (Result, error) { SavePath: s.cfg.SavePath, }) if addErr != nil { + s.log.Warn("ingest: qbittorrent add failed, marking download failed", + "download_id", id, "infohash", info.Infohash, "err", addErr) // Задача уже в БД — помечаем failed, чтобы worker её не подхватил. if setErr := s.store.SetDownloadState(ctx, id, store.StateFailed, "qbit_add", addErr.Error()); setErr != nil { s.log.Error("ingest: failed to mark download failed after qbit error", diff --git a/internal/layout/layout.go b/internal/layout/layout.go index ede9598..eb81580 100644 --- a/internal/layout/layout.go +++ b/internal/layout/layout.go @@ -15,7 +15,9 @@ import ( "context" "errors" "fmt" + "io" "io/fs" + "log/slog" "os" "path/filepath" "syscall" @@ -86,10 +88,12 @@ type Layouter struct { movies string series string dirMode os.FileMode + log *slog.Logger } -// New собирает раскладчик. Корни нормализуются (filepath.Clean). -func New(cfg Config) (*Layouter, error) { +// New собирает раскладчик. Корни нормализуются (filepath.Clean). logger nil → +// slog.Default(). +func New(cfg Config, logger *slog.Logger) (*Layouter, error) { if cfg.MoviesDir == "" || cfg.SeriesDir == "" { return nil, fmt.Errorf("layout: movies/series dirs required") } @@ -97,10 +101,14 @@ func New(cfg Config) (*Layouter, error) { if mode == 0 { mode = 0o755 } + if logger == nil { + logger = slog.Default() + } return &Layouter{ movies: filepath.Clean(cfg.MoviesDir), series: filepath.Clean(cfg.SeriesDir), dirMode: mode, + log: logger, }, nil } @@ -112,7 +120,7 @@ func (l *Layouter) root(t MediaType) (string, error) { case Series: return l.series, nil default: - return "", fmt.Errorf("layout: неизвестный тип %q", t) + return "", fmt.Errorf("layout: unknown type %q", t) } } @@ -152,12 +160,12 @@ func (l *Layouter) BuildLinks(p Plan) ([]Link, error) { continue // роль не линкуется (extra/sample/ignore) } if !underRoot(root, dst) { - return nil, fmt.Errorf("layout: цель %q вне библиотеки %q (файл %q)", dst, root, f.Src) + return nil, fmt.Errorf("layout: target %q is outside library %q (file %q)", dst, root, f.Src) } links = append(links, Link{Src: f.Src, Dst: dst, Kind: kind}) } if len(links) == 0 { - return nil, fmt.Errorf("layout: план не дал ни одной ссылки") + return nil, fmt.Errorf("layout: plan produced no links") } return links, nil } @@ -180,7 +188,7 @@ func (l *Layouter) seriesDst(root, folder, base string, f *PlanFile) (string, Ki return "", "", nil } if f.Season == nil || f.Episode == nil { - return "", "", fmt.Errorf("layout: файл %q без season/episode", f.Src) + return "", "", fmt.Errorf("layout: file %q has no season/episode", f.Src) } episodeEnd := 0 if f.EpisodeEnd != nil { @@ -203,7 +211,8 @@ func (l *Layouter) seriesDst(root, folder, base string, f *PlanFile) (string, Ki type LinkStatus string const ( - StatusLinked LinkStatus = "linked" // ссылка создана + StatusLinked LinkStatus = "linked" // хардлинк создан + StatusCopied LinkStatus = "copied" // хардлинк невозможен — файл скопирован (фолбэк) StatusExists LinkStatus = "exists" // уже была (тот же inode) — идемпотентно StatusCollision LinkStatus = "collision" // цель занята другим файлом ) @@ -219,7 +228,8 @@ var ErrCollision = errors.New("layout: target collision") // Apply создаёт хардлинки по ссылкам. Идемпотентно: повтор после сбоя // доводит начатое. При коллизии (цель занята чужим файлом) возвращает -// ErrCollision, не перезаписывая. EXDEV (разные ФС) — явная ошибка. +// ErrCollision, не перезаписывая. Если хардлинк невозможен (разные ФС или ФС +// не поддерживает link) — фолбэк на копирование файла с предупреждением в лог. func (l *Layouter) Apply(_ context.Context, links []Link) ([]Result, error) { results := make([]Result, 0, len(links)) for _, ln := range links { @@ -228,23 +238,28 @@ func (l *Layouter) Apply(_ context.Context, links []Link) ([]Result, error) { root = l.series } if !underRoot(root, ln.Dst) { - return results, fmt.Errorf("layout: цель %q вне библиотек", ln.Dst) + return results, fmt.Errorf("layout: target %q is outside libraries", ln.Dst) } if err := os.MkdirAll(filepath.Dir(ln.Dst), l.dirMode); err != nil { return results, fmt.Errorf("layout: mkdir %q: %w", filepath.Dir(ln.Dst), err) } - status, err := linkOne(ln.Src, ln.Dst) + status, err := l.linkOne(ln.Src, ln.Dst) if err != nil { + l.log.Error("layout: link failed", + "src", ln.Src, "dst", ln.Dst, "kind", ln.Kind, "err", err) return results, err } + l.log.Debug("layout: link applied", + "src", ln.Src, "dst", ln.Dst, "kind", ln.Kind, "status", status) results = append(results, Result{Link: ln, Status: status}) } return results, nil } -// linkOne создаёт одну ссылку, разбирая «уже существует». -func linkOne(src, dst string) (LinkStatus, error) { +// linkOne создаёт одну ссылку, разбирая «уже существует» и невозможность +// хардлинка (фолбэк на копирование). +func (l *Layouter) linkOne(src, dst string) (LinkStatus, error) { err := os.Link(src, dst) if err == nil { return StatusLinked, nil @@ -257,14 +272,82 @@ func linkOne(src, dst string) (LinkStatus, error) { if same { return StatusExists, nil // идемпотентно: тот же inode } - return StatusCollision, fmt.Errorf("%w: %q занят другим файлом", ErrCollision, dst) + return StatusCollision, fmt.Errorf("%w: %q is occupied by a different file", ErrCollision, dst) } - if errors.Is(err, syscall.EXDEV) { - return "", fmt.Errorf("layout: hardlink через границу ФС (%q → %q): %w", src, dst, err) + if hardlinkUnsupported(err) { + // Хардлинк невозможен (граница ФС или ФС без поддержки link). Не валим + // раскладку — копируем файл и предупреждаем: диск дублируется, но + // задача доходит до конца. dst здесь заведомо отсутствует (иначе был бы + // fs.ErrExist выше). + l.log.Warn("layout: hardlink unsupported, falling back to file copy", + "src", src, "dst", dst, "err", err) + if cerr := copyFile(src, dst); cerr != nil { + return "", fmt.Errorf("layout: copy fallback %q → %q: %w", src, dst, cerr) + } + return StatusCopied, nil } return "", fmt.Errorf("layout: link %q → %q: %w", src, dst, err) } +// hardlinkUnsupported сообщает, означает ли ошибка os.Link, что хардлинк между +// этими путями в принципе невозможен (а не временный сбой): разные ФС (EXDEV) +// или ФС без поддержки жёстких ссылок (ENOTSUP/EOPNOTSUPP, у части ФС — EPERM). +func hardlinkUnsupported(err error) bool { + return errors.Is(err, syscall.EXDEV) || + errors.Is(err, syscall.ENOTSUP) || + errors.Is(err, syscall.EOPNOTSUPP) || + errors.Is(err, syscall.EPERM) +} + +// copyFile копирует src в dst через временный файл в каталоге назначения и +// атомарный rename — так сбой посреди копирования не оставит частичный файл на +// месте dst. Источник не модифицируется. Вызывается, только когда хардлинк +// невозможен (см. linkOne). +func copyFile(src, dst string) error { + in, err := os.Open(src) + if err != nil { + return fmt.Errorf("open source: %w", err) + } + defer func() { _ = in.Close() }() + + info, err := in.Stat() + if err != nil { + return fmt.Errorf("stat source: %w", err) + } + + tmp, err := os.CreateTemp(filepath.Dir(dst), ".jellybit-copy-*") + if err != nil { + return fmt.Errorf("create temp: %w", err) + } + tmpName := tmp.Name() + cleanup := true + defer func() { + if cleanup { + _ = os.Remove(tmpName) + } + }() + + if _, err := io.Copy(tmp, in); err != nil { + _ = tmp.Close() + return fmt.Errorf("copy data: %w", err) + } + if err := tmp.Sync(); err != nil { + _ = tmp.Close() + return fmt.Errorf("sync temp: %w", err) + } + if err := tmp.Close(); err != nil { + return fmt.Errorf("close temp: %w", err) + } + if err := os.Chmod(tmpName, info.Mode().Perm()); err != nil { + return fmt.Errorf("chmod temp: %w", err) + } + if err := os.Rename(tmpName, dst); err != nil { + return fmt.Errorf("rename into place: %w", err) + } + cleanup = false + return nil +} + // sameFile сообщает, указывают ли src и dst на один inode. func sameFile(src, dst string) (bool, error) { si, err := os.Stat(src) @@ -289,15 +372,17 @@ func (l *Layouter) Undo(_ context.Context, links []Link) (int, error) { root = l.series } if !underRoot(root, ln.Dst) { - return removed, fmt.Errorf("layout: undo вне библиотеки: %q", ln.Dst) + return removed, fmt.Errorf("layout: undo outside library: %q", ln.Dst) } if err := os.Remove(ln.Dst); err != nil { if errors.Is(err, fs.ErrNotExist) { continue } + l.log.Error("layout: undo remove failed", "dst", ln.Dst, "err", err) return removed, fmt.Errorf("layout: undo remove %q: %w", ln.Dst, err) } removed++ + l.log.Debug("layout: link removed", "dst", ln.Dst) pruneEmptyDirs(filepath.Dir(ln.Dst), root) } return removed, nil diff --git a/internal/layout/layout_test.go b/internal/layout/layout_test.go index 73d8f52..6dc8a29 100644 --- a/internal/layout/layout_test.go +++ b/internal/layout/layout_test.go @@ -5,6 +5,7 @@ import ( "errors" "os" "path/filepath" + "syscall" "testing" ) @@ -30,7 +31,7 @@ func newFixture(t *testing.T) fixture { t.Fatal(err) } } - l, err := New(Config{MoviesDir: movies, SeriesDir: series}) + l, err := New(Config{MoviesDir: movies, SeriesDir: series}, nil) if err != nil { t.Fatal(err) } @@ -251,6 +252,63 @@ func TestUndo_Idempotent(t *testing.T) { } } +func TestCopyFile_DuplicatesContentAndKeepsSource(t *testing.T) { + dir := t.TempDir() + src := filepath.Join(dir, "src.mkv") + dst := filepath.Join(dir, "sub", "dst.mkv") + if err := os.MkdirAll(filepath.Dir(dst), 0o755); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(src, []byte("payload"), 0o640); err != nil { + t.Fatal(err) + } + + if err := copyFile(src, dst); err != nil { + t.Fatalf("copyFile: %v", err) + } + + got, err := os.ReadFile(dst) + if err != nil || string(got) != "payload" { + t.Fatalf("dst content = %q, err = %v", got, err) + } + // Источник цел и это отдельный inode (копия, не хардлинк). + si, _ := os.Stat(src) + di, _ := os.Stat(dst) + if os.SameFile(si, di) { + t.Error("dst must be a distinct copy, not a hardlink") + } + if di.Mode().Perm() != 0o640 { + t.Errorf("dst mode = %v, want source mode 0640", di.Mode().Perm()) + } + // Временные файлы копирования подчищены. + entries, _ := os.ReadDir(filepath.Dir(dst)) + for _, e := range entries { + if len(e.Name()) >= 14 && e.Name()[:14] == ".jellybit-copy" { + t.Errorf("leftover temp file: %s", e.Name()) + } + } +} + +func TestHardlinkUnsupported(t *testing.T) { + cases := []struct { + err error + want bool + }{ + {syscall.EXDEV, true}, + {syscall.ENOTSUP, true}, + {syscall.EOPNOTSUPP, true}, + {syscall.EPERM, true}, + {syscall.ENOENT, false}, + {os.ErrExist, false}, + {errors.New("random"), false}, + } + for _, tc := range cases { + if got := hardlinkUnsupported(tc.err); got != tc.want { + t.Errorf("hardlinkUnsupported(%v) = %v, want %v", tc.err, got, tc.want) + } + } +} + func TestUndo_RefusesOutsideLibrary(t *testing.T) { f := newFixture(t) outside := filepath.Join(f.downloads, "victim.mkv") diff --git a/internal/layout/name.go b/internal/layout/name.go index bb38928..6a1592f 100644 --- a/internal/layout/name.go +++ b/internal/layout/name.go @@ -32,7 +32,7 @@ func sanitizeComponent(s string) string { func titleYear(title string, year int) (string, error) { t := sanitizeComponent(title) if t == "" { - return "", fmt.Errorf("layout: пустое название после санитизации (%q)", title) + return "", fmt.Errorf("layout: empty title after sanitization (%q)", title) } if year > 0 { return fmt.Sprintf("%s (%d)", t, year), nil diff --git a/internal/llm/integration_test.go b/internal/llm/integration_test.go index 4a17888..b890536 100644 --- a/internal/llm/integration_test.go +++ b/internal/llm/integration_test.go @@ -31,7 +31,7 @@ func TestIntegration_OpenAICompat(t *testing.T) { APIKey: key, Model: model, Timeout: 90 * time.Second, - }) + }, nil) if err != nil { t.Fatalf("New: %v", err) } diff --git a/internal/llm/llm.go b/internal/llm/llm.go index d45ac2f..54d5345 100644 --- a/internal/llm/llm.go +++ b/internal/llm/llm.go @@ -14,6 +14,7 @@ import ( "context" "errors" "fmt" + "log/slog" "time" ) @@ -74,13 +75,16 @@ type Config struct { // ErrUnknownType — запрошенный [llm].type не поддерживается. var ErrUnknownType = errors.New("llm: unknown provider type") -// New собирает провайдер по дискриминатору cfg.Type. -func New(cfg Config) (Provider, error) { +// New собирает провайдер по дискриминатору cfg.Type. logger nil → slog.Default(). +func New(cfg Config, logger *slog.Logger) (Provider, error) { + if logger == nil { + logger = slog.Default() + } switch cfg.Type { case "openai-compat": - return newOpenAICompat(cfg) + return newOpenAICompat(cfg, logger) case "": - return nil, fmt.Errorf("%w: %q (укажите [llm].type)", ErrUnknownType, cfg.Type) + return nil, fmt.Errorf("%w: %q (set [llm].type)", ErrUnknownType, cfg.Type) default: return nil, fmt.Errorf("%w: %q", ErrUnknownType, cfg.Type) } diff --git a/internal/llm/llm_test.go b/internal/llm/llm_test.go index af954a7..47cae3a 100644 --- a/internal/llm/llm_test.go +++ b/internal/llm/llm_test.go @@ -20,7 +20,7 @@ func newTestProvider(t *testing.T, baseURL, apiKey string) *openAICompat { BaseURL: baseURL, APIKey: apiKey, Model: "test-model", - }) + }, nil) if err != nil { t.Fatalf("newOpenAICompat: %v", err) } @@ -215,22 +215,22 @@ func TestComplete_EmptyMessages(t *testing.T) { } func TestNew_UnknownType(t *testing.T) { - if _, err := New(Config{Type: "anthropic", Model: "x", BaseURL: "http://x"}); err == nil { + if _, err := New(Config{Type: "anthropic", Model: "x", BaseURL: "http://x"}, nil); err == nil { t.Fatal("want error for unknown type") } - if _, err := New(Config{Type: ""}); err == nil { + if _, err := New(Config{Type: ""}, nil); err == nil { t.Fatal("want error for empty type") } } func TestNew_OpenAICompatValidation(t *testing.T) { - if _, err := New(Config{Type: "openai-compat", Model: "x"}); err == nil { + if _, err := New(Config{Type: "openai-compat", Model: "x"}, nil); err == nil { t.Fatal("want error for empty base_url") } - if _, err := New(Config{Type: "openai-compat", BaseURL: "http://x"}); err == nil { + if _, err := New(Config{Type: "openai-compat", BaseURL: "http://x"}, nil); err == nil { t.Fatal("want error for empty model") } - if _, err := New(Config{Type: "openai-compat", BaseURL: "http://x", Model: "m"}); err != nil { + if _, err := New(Config{Type: "openai-compat", BaseURL: "http://x", Model: "m"}, nil); err != nil { t.Fatalf("unexpected error: %v", err) } } diff --git a/internal/llm/openai.go b/internal/llm/openai.go index 6765c37..1099ba5 100644 --- a/internal/llm/openai.go +++ b/internal/llm/openai.go @@ -6,6 +6,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "net/url" "strings" @@ -26,10 +27,11 @@ type openAICompat struct { apiKey string model string retryWait time.Duration // базовая пауза между ретраями (0 в тестах) + log *slog.Logger } // newOpenAICompat собирает клиент из конфига. -func newOpenAICompat(cfg Config) (*openAICompat, error) { +func newOpenAICompat(cfg Config, logger *slog.Logger) (*openAICompat, error) { if cfg.BaseURL == "" { return nil, fmt.Errorf("llm: empty base_url") } @@ -51,12 +53,16 @@ func newOpenAICompat(cfg Config) (*openAICompat, error) { transport = &http.Transport{Proxy: http.ProxyURL(proxyURL)} } + if logger == nil { + logger = slog.Default() + } return &openAICompat{ endpoint: strings.TrimRight(cfg.BaseURL, "/") + "/chat/completions", hc: &http.Client{Timeout: timeout, Transport: transport}, apiKey: cfg.APIKey, model: cfg.Model, retryWait: baseRetryWait, + log: logger, }, nil } @@ -119,15 +125,30 @@ func (c *openAICompat) Complete(ctx context.Context, req Request) (Response, err } } + c.log.Debug("llm: request", + "endpoint", c.endpoint, "model", c.model, + "attempt", attempt, "max_attempts", maxAttempts) + start := time.Now() resp, retryable, err := c.do(ctx, body) if err == nil { + c.log.Debug("llm: response ok", + "model", resp.Model, "attempt", attempt, + "duration", time.Since(start), + "total_tokens", resp.Usage.TotalTokens, "cost", resp.Usage.Cost) return resp, nil } lastErr = err if !retryable { + c.log.Error("llm: request failed (non-retryable)", + "model", c.model, "attempt", attempt, "duration", time.Since(start), "err", err) return Response{}, err } + c.log.Warn("llm: request failed, will retry", + "model", c.model, "attempt", attempt, "max_attempts", maxAttempts, + "duration", time.Since(start), "err", err) } + c.log.Error("llm: all attempts exhausted", + "model", c.model, "max_attempts", maxAttempts, "err", lastErr) return Response{}, fmt.Errorf("llm: exhausted %d attempts: %w", maxAttempts, lastErr) } diff --git a/internal/metadata/http.go b/internal/metadata/http.go index 44609ed..e4736b0 100644 --- a/internal/metadata/http.go +++ b/internal/metadata/http.go @@ -6,6 +6,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "net/url" "time" @@ -38,7 +39,7 @@ const maxBody = 4 << 20 // 4 MiB — потолок на тело ответа // getJSON выполняет GET и декодирует JSON-ответ в out. headers — опц. // дополнительные заголовки (напр. Authorization). -func getJSON(ctx context.Context, hc *http.Client, rawURL string, headers map[string]string, out any) error { +func getJSON(ctx context.Context, hc *http.Client, log *slog.Logger, rawURL string, headers map[string]string, out any) error { req, err := http.NewRequestWithContext(ctx, http.MethodGet, rawURL, nil) if err != nil { return fmt.Errorf("metadata: build request: %w", err) @@ -47,11 +48,11 @@ func getJSON(ctx context.Context, hc *http.Client, rawURL string, headers map[st for k, v := range headers { req.Header.Set(k, v) } - return doJSON(hc, req, out) + return doJSON(hc, log, req, out) } // postJSON выполняет POST с JSON-телом и декодирует ответ. -func postJSON(ctx context.Context, hc *http.Client, rawURL string, body, out any) error { +func postJSON(ctx context.Context, hc *http.Client, log *slog.Logger, rawURL string, body, out any) error { payload, err := json.Marshal(body) if err != nil { return fmt.Errorf("metadata: marshal body: %w", err) @@ -62,26 +63,46 @@ func postJSON(ctx context.Context, hc *http.Client, rawURL string, body, out any } req.Header.Set("Content-Type", "application/json") req.Header.Set("Accept", "application/json") - return doJSON(hc, req, out) + return doJSON(hc, log, req, out) } -func doJSON(hc *http.Client, req *http.Request, out any) error { +// doJSON выполняет запрос и декодирует ответ, логируя исход. В лог идут только +// host и path (без query) — у TMDB api_key передаётся query-параметром, его +// нельзя светить в логах. +func doJSON(hc *http.Client, log *slog.Logger, req *http.Request, out any) error { + if log == nil { + log = slog.Default() + } + start := time.Now() resp, err := hc.Do(req) if err != nil { + log.Warn("metadata: request failed", + "method", req.Method, "host", req.URL.Host, "path", req.URL.Path, + "duration", time.Since(start), "err", err) return fmt.Errorf("metadata: request: %w", err) } defer func() { _ = resp.Body.Close() }() raw, err := io.ReadAll(io.LimitReader(resp.Body, maxBody)) if err != nil { + log.Warn("metadata: read body failed", + "host", req.URL.Host, "path", req.URL.Path, "err", err) return fmt.Errorf("metadata: read body: %w", err) } if resp.StatusCode != http.StatusOK { + log.Warn("metadata: non-ok status", + "method", req.Method, "host", req.URL.Host, "path", req.URL.Path, + "status", resp.StatusCode, "duration", time.Since(start)) return fmt.Errorf("metadata: status %d: %s", resp.StatusCode, snippet(raw)) } if err := json.Unmarshal(raw, out); err != nil { + log.Warn("metadata: decode failed", + "host", req.URL.Host, "path", req.URL.Path, "err", err) return fmt.Errorf("metadata: decode: %w (body: %s)", err, snippet(raw)) } + log.Debug("metadata: request ok", + "method", req.Method, "host", req.URL.Host, "path", req.URL.Path, + "duration", time.Since(start)) return nil } diff --git a/internal/metadata/integration_test.go b/internal/metadata/integration_test.go index f0763a2..fb9f085 100644 --- a/internal/metadata/integration_test.go +++ b/internal/metadata/integration_test.go @@ -17,7 +17,7 @@ func TestIntegration_TVMaze(t *testing.T) { if os.Getenv("JELLYBIT_LIVE") == "" { t.Skip("set JELLYBIT_LIVE=1 to run network tests") } - c, err := metadata.NewTVMaze(metadata.TVMazeConfig{Timeout: 20 * time.Second}) + c, err := metadata.NewTVMaze(metadata.TVMazeConfig{Timeout: 20 * time.Second}, nil) if err != nil { t.Fatalf("NewTVMaze: %v", err) } @@ -57,7 +57,7 @@ func TestIntegration_TVDB(t *testing.T) { if key == "" { t.Skip("set TVDB_API_KEY to run") } - c, err := metadata.NewTVDB(metadata.TVDBConfig{APIKey: key, Timeout: 20 * time.Second}) + c, err := metadata.NewTVDB(metadata.TVDBConfig{APIKey: key, Timeout: 20 * time.Second}, nil) if err != nil { t.Fatalf("NewTVDB: %v", err) } diff --git a/internal/metadata/tmdb.go b/internal/metadata/tmdb.go index 3a9f37b..ff25e8c 100644 --- a/internal/metadata/tmdb.go +++ b/internal/metadata/tmdb.go @@ -3,6 +3,7 @@ package metadata import ( "context" "fmt" + "log/slog" "net/http" "net/url" "strconv" @@ -25,10 +26,11 @@ type TMDB struct { apiKey string baseURL string hc *http.Client + log *slog.Logger } -// NewTMDB собирает клиент TMDB. -func NewTMDB(cfg TMDBConfig) (*TMDB, error) { +// NewTMDB собирает клиент TMDB. logger nil → slog.Default(). +func NewTMDB(cfg TMDBConfig, logger *slog.Logger) (*TMDB, error) { if cfg.APIKey == "" { return nil, fmt.Errorf("metadata: tmdb api_key required") } @@ -40,7 +42,10 @@ func NewTMDB(cfg TMDBConfig) (*TMDB, error) { if base == "" { base = tmdbDefaultBaseURL } - return &TMDB{apiKey: cfg.APIKey, baseURL: strings.TrimRight(base, "/"), hc: hc}, nil + if logger == nil { + logger = slog.Default() + } + return &TMDB{apiKey: cfg.APIKey, baseURL: strings.TrimRight(base, "/"), hc: hc, log: logger}, nil } func (t *TMDB) Name() string { return "tmdb" } @@ -73,13 +78,15 @@ func (t *TMDB) Search(ctx context.Context, q Query) ([]Candidate, error) { params.Set("first_air_date_year", strconv.Itoa(q.Year)) } default: - return nil, fmt.Errorf("metadata: tmdb: неизвестный тип %q", q.Type) + return nil, fmt.Errorf("metadata: tmdb: unknown type %q", q.Type) } + t.log.Debug("tmdb: search", "type", q.Type, "title", q.Title, "year", q.Year) var resp tmdbSearchResp - if err := getJSON(ctx, t.hc, t.baseURL+path+"?"+params.Encode(), nil, &resp); err != nil { + if err := getJSON(ctx, t.hc, t.log, t.baseURL+path+"?"+params.Encode(), nil, &resp); err != nil { return nil, fmt.Errorf("tmdb search: %w", err) } + t.log.Debug("tmdb: search done", "title", q.Title, "results", len(resp.Results)) out := make([]Candidate, 0, len(resp.Results)) for _, r := range resp.Results { @@ -109,7 +116,7 @@ type tmdbTVResp struct { func (t *TMDB) SeasonEpisodeCounts(ctx context.Context, id string) (map[int]int, error) { params := url.Values{"api_key": {t.apiKey}} var resp tmdbTVResp - if err := getJSON(ctx, t.hc, t.baseURL+"/tv/"+url.PathEscape(id)+"?"+params.Encode(), nil, &resp); err != nil { + if err := getJSON(ctx, t.hc, t.log, t.baseURL+"/tv/"+url.PathEscape(id)+"?"+params.Encode(), nil, &resp); err != nil { return nil, fmt.Errorf("tmdb tv %s: %w", id, err) } out := make(map[int]int, len(resp.Seasons)) diff --git a/internal/metadata/tmdb_test.go b/internal/metadata/tmdb_test.go index 78e91af..b68a7fc 100644 --- a/internal/metadata/tmdb_test.go +++ b/internal/metadata/tmdb_test.go @@ -9,7 +9,7 @@ import ( func newTMDB(t *testing.T, url string) *TMDB { t.Helper() - c, err := NewTMDB(TMDBConfig{APIKey: "k", BaseURL: url}) + c, err := NewTMDB(TMDBConfig{APIKey: "k", BaseURL: url}, nil) if err != nil { t.Fatalf("NewTMDB: %v", err) } @@ -103,7 +103,7 @@ func TestTMDB_ErrorStatus(t *testing.T) { } func TestNewTMDB_RequiresKey(t *testing.T) { - if _, err := NewTMDB(TMDBConfig{}); err == nil { + if _, err := NewTMDB(TMDBConfig{}, nil); err == nil { t.Fatal("want error without api_key") } } diff --git a/internal/metadata/tvdb.go b/internal/metadata/tvdb.go index 707e15a..0c7371b 100644 --- a/internal/metadata/tvdb.go +++ b/internal/metadata/tvdb.go @@ -5,6 +5,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "net/url" "strconv" @@ -30,13 +31,14 @@ type TVDB struct { apiKey string baseURL string hc *http.Client + log *slog.Logger mu sync.Mutex token string } -// NewTVDB собирает клиент TVDB. -func NewTVDB(cfg TVDBConfig) (*TVDB, error) { +// NewTVDB собирает клиент TVDB. logger nil → slog.Default(). +func NewTVDB(cfg TVDBConfig, logger *slog.Logger) (*TVDB, error) { if cfg.APIKey == "" { return nil, fmt.Errorf("metadata: tvdb api_key required") } @@ -48,7 +50,10 @@ func NewTVDB(cfg TVDBConfig) (*TVDB, error) { if base == "" { base = tvdbDefaultBaseURL } - return &TVDB{apiKey: cfg.APIKey, baseURL: strings.TrimRight(base, "/"), hc: hc}, nil + if logger == nil { + logger = slog.Default() + } + return &TVDB{apiKey: cfg.APIKey, baseURL: strings.TrimRight(base, "/"), hc: hc, log: logger}, nil } func (t *TVDB) Name() string { return "tvdb" } @@ -65,7 +70,8 @@ func (t *TVDB) login(ctx context.Context) (string, error) { Token string `json:"token"` } `json:"data"` } - if err := postJSON(ctx, t.hc, t.baseURL+"/login", + t.log.Debug("tvdb: login (fetching bearer token)") + if err := postJSON(ctx, t.hc, t.log, t.baseURL+"/login", map[string]string{"apikey": t.apiKey}, &resp); err != nil { return "", fmt.Errorf("tvdb login: %w", err) } @@ -87,6 +93,7 @@ func (t *TVDB) get(ctx context.Context, path string, out any) error { return err } if status == http.StatusUnauthorized { + t.log.Warn("tvdb: token expired, re-login", "path", path) t.mu.Lock() t.token = "" // сбрасываем протухший токен t.mu.Unlock() @@ -113,15 +120,21 @@ func (t *TVDB) rawGet(ctx context.Context, path, token string) (int, []byte, err } req.Header.Set("Authorization", "Bearer "+token) req.Header.Set("Accept", "application/json") + start := time.Now() resp, err := t.hc.Do(req) if err != nil { + t.log.Warn("tvdb: request failed", + "host", req.URL.Host, "path", req.URL.Path, "duration", time.Since(start), "err", err) return 0, nil, fmt.Errorf("tvdb: request: %w", err) } defer func() { _ = resp.Body.Close() }() raw, err := io.ReadAll(io.LimitReader(resp.Body, maxBody)) if err != nil { + t.log.Warn("tvdb: read body failed", "host", req.URL.Host, "path", req.URL.Path, "err", err) return 0, nil, fmt.Errorf("tvdb: read body: %w", err) } + t.log.Debug("tvdb: request done", + "host", req.URL.Host, "path", req.URL.Path, "status", resp.StatusCode, "duration", time.Since(start)) return resp.StatusCode, raw, nil } @@ -143,10 +156,12 @@ func (t *TVDB) Search(ctx context.Context, q Query) ([]Candidate, error) { if q.Year > 0 { params.Set("year", strconv.Itoa(q.Year)) } + t.log.Debug("tvdb: search", "type", q.Type, "title", q.Title, "year", q.Year) var resp tvdbSearchResp if err := t.get(ctx, "/search?"+params.Encode(), &resp); err != nil { return nil, fmt.Errorf("tvdb search: %w", err) } + t.log.Debug("tvdb: search done", "title", q.Title, "results", len(resp.Data)) out := make([]Candidate, 0, len(resp.Data)) for _, r := range resp.Data { if r.TVDBID == "" { diff --git a/internal/metadata/tvdb_test.go b/internal/metadata/tvdb_test.go index ef6c330..95ae8c0 100644 --- a/internal/metadata/tvdb_test.go +++ b/internal/metadata/tvdb_test.go @@ -52,7 +52,7 @@ func fakeTVDB(t *testing.T, logins *atomic.Int32) *httptest.Server { func newTVDB(t *testing.T, url string) *TVDB { t.Helper() - c, err := NewTVDB(TVDBConfig{APIKey: "k", BaseURL: url}) + c, err := NewTVDB(TVDBConfig{APIKey: "k", BaseURL: url}, nil) if err != nil { t.Fatalf("NewTVDB: %v", err) } @@ -126,7 +126,7 @@ func TestTVDB_ReloginOn401(t *testing.T) { } func TestNewTVDB_RequiresKey(t *testing.T) { - if _, err := NewTVDB(TVDBConfig{}); err == nil { + if _, err := NewTVDB(TVDBConfig{}, nil); err == nil { t.Fatal("want error without api_key") } } diff --git a/internal/metadata/tvmaze.go b/internal/metadata/tvmaze.go index c483c0d..fddf587 100644 --- a/internal/metadata/tvmaze.go +++ b/internal/metadata/tvmaze.go @@ -3,6 +3,7 @@ package metadata import ( "context" "fmt" + "log/slog" "net/http" "net/url" "strconv" @@ -25,10 +26,11 @@ type TVMazeConfig struct { type TVMaze struct { baseURL string hc *http.Client + log *slog.Logger } -// NewTVMaze собирает клиент TVMaze (ключ не нужен). -func NewTVMaze(cfg TVMazeConfig) (*TVMaze, error) { +// NewTVMaze собирает клиент TVMaze (ключ не нужен). logger nil → slog.Default(). +func NewTVMaze(cfg TVMazeConfig, logger *slog.Logger) (*TVMaze, error) { hc, err := newHTTPClient(cfg.Proxy, cfg.Timeout) if err != nil { return nil, err @@ -37,7 +39,10 @@ func NewTVMaze(cfg TVMazeConfig) (*TVMaze, error) { if base == "" { base = tvmazeDefaultBaseURL } - return &TVMaze{baseURL: strings.TrimRight(base, "/"), hc: hc}, nil + if logger == nil { + logger = slog.Default() + } + return &TVMaze{baseURL: strings.TrimRight(base, "/"), hc: hc, log: logger}, nil } func (t *TVMaze) Name() string { return "tvmaze" } @@ -63,9 +68,11 @@ func (t *TVMaze) Search(ctx context.Context, q Query) ([]Candidate, error) { Show tvmazeShow `json:"show"` } rawURL := t.baseURL + "/search/shows?q=" + url.QueryEscape(q.Title) - if err := getJSON(ctx, t.hc, rawURL, nil, &resp); err != nil { + t.log.Debug("tvmaze: search", "title", q.Title) + if err := getJSON(ctx, t.hc, t.log, rawURL, nil, &resp); err != nil { return nil, fmt.Errorf("tvmaze search: %w", err) } + t.log.Debug("tvmaze: search done", "title", q.Title, "results", len(resp)) out := make([]Candidate, 0, len(resp)) for _, r := range resp { @@ -97,7 +104,7 @@ type tvmazeEpisode struct { func (t *TVMaze) SeasonEpisodeCounts(ctx context.Context, id string) (map[int]int, error) { var eps []tvmazeEpisode rawURL := t.baseURL + "/shows/" + url.PathEscape(id) + "/episodes" - if err := getJSON(ctx, t.hc, rawURL, nil, &eps); err != nil { + if err := getJSON(ctx, t.hc, t.log, rawURL, nil, &eps); err != nil { return nil, fmt.Errorf("tvmaze episodes %s: %w", id, err) } out := map[int]int{} diff --git a/internal/metadata/tvmaze_test.go b/internal/metadata/tvmaze_test.go index 645ce63..acd8525 100644 --- a/internal/metadata/tvmaze_test.go +++ b/internal/metadata/tvmaze_test.go @@ -9,7 +9,7 @@ import ( func newTVMaze(t *testing.T, url string) *TVMaze { t.Helper() - c, err := NewTVMaze(TVMazeConfig{BaseURL: url}) + c, err := NewTVMaze(TVMazeConfig{BaseURL: url}, nil) if err != nil { t.Fatalf("NewTVMaze: %v", err) } diff --git a/internal/qbt/qbt.go b/internal/qbt/qbt.go index 9f25f59..f4a1b31 100644 --- a/internal/qbt/qbt.go +++ b/internal/qbt/qbt.go @@ -12,6 +12,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "mime/multipart" "net/http" "net/http/cookiejar" @@ -36,6 +37,7 @@ type Client struct { hc *http.Client user string pass string + log *slog.Logger mu sync.Mutex // сериализует логин } @@ -74,8 +76,8 @@ type AddRequest struct { Paused bool } -// New создаёт клиент с собственным cookie-jar. -func New(cfg Config) (*Client, error) { +// New создаёт клиент с собственным cookie-jar. logger nil → slog.Default(). +func New(cfg Config, logger *slog.Logger) (*Client, error) { base, err := url.Parse(strings.TrimRight(cfg.URL, "/")) if err != nil { return nil, fmt.Errorf("parse qbittorrent url %q: %w", cfg.URL, err) @@ -88,11 +90,15 @@ func New(cfg Config) (*Client, error) { if timeout == 0 { timeout = 30 * time.Second } + if logger == nil { + logger = slog.Default() + } return &Client{ base: base, hc: &http.Client{Jar: jar, Timeout: timeout}, user: cfg.Username, pass: cfg.Password, + log: logger, }, nil } @@ -119,9 +125,12 @@ func (c *Client) login(ctx context.Context) error { defer func() { _ = resp.Body.Close() }() body, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<10)) if resp.StatusCode != http.StatusOK || strings.TrimSpace(string(body)) != "Ok." { + c.log.Error("qbittorrent: login failed", + "status", resp.StatusCode, "body", strings.TrimSpace(string(body))) return fmt.Errorf("qbittorrent login failed: status %d body %q", resp.StatusCode, strings.TrimSpace(string(body))) } + c.log.Debug("qbittorrent: login ok", "user", c.user) return nil } @@ -138,6 +147,7 @@ func (c *Client) do(ctx context.Context, build func() (*http.Request, error)) (* } if resp.StatusCode == http.StatusForbidden { _ = resp.Body.Close() + c.log.Debug("qbittorrent: session expired (403), re-login") if err := c.login(ctx); err != nil { return nil, err } @@ -199,8 +209,13 @@ func (c *Client) Add(ctx context.Context, ar AddRequest) error { resp.StatusCode, strings.TrimSpace(string(body))) } if strings.TrimSpace(string(body)) == "Fails." { + c.log.Error("qbittorrent: add rejected", + "category", ar.Category, "urls", len(ar.URLs), "torrents", len(ar.Torrents)) return fmt.Errorf("qbittorrent add: rejected (Fails.)") } + c.log.Info("qbittorrent: torrent added", + "category", ar.Category, "save_path", ar.SavePath, + "urls", len(ar.URLs), "torrents", len(ar.Torrents), "paused", ar.Paused) return nil } @@ -226,6 +241,7 @@ func (c *Client) Torrents(ctx context.Context, category string) ([]Torrent, erro if err := json.NewDecoder(resp.Body).Decode(&ts); err != nil { return nil, fmt.Errorf("decode qbittorrent info: %w", err) } + c.log.Debug("qbittorrent: torrents fetched", "category", category, "count", len(ts)) return ts, nil } @@ -250,5 +266,6 @@ func (c *Client) Files(ctx context.Context, hash string) ([]File, error) { if err := json.NewDecoder(resp.Body).Decode(&fs); err != nil { return nil, fmt.Errorf("decode qbittorrent files: %w", err) } + c.log.Debug("qbittorrent: files fetched", "hash", hash, "count", len(fs)) return fs, nil } diff --git a/internal/qbt/qbt_test.go b/internal/qbt/qbt_test.go index 17ad952..4727308 100644 --- a/internal/qbt/qbt_test.go +++ b/internal/qbt/qbt_test.go @@ -62,7 +62,7 @@ func fakeQBittorrent(t *testing.T, info string) *httptest.Server { func newClient(t *testing.T, url string) *Client { t.Helper() - c, err := New(Config{URL: url, Username: "admin", Password: "secret"}) + c, err := New(Config{URL: url, Username: "admin", Password: "secret"}, nil) if err != nil { t.Fatalf("New: %v", err) } @@ -107,7 +107,7 @@ func TestTorrents(t *testing.T) { func TestLoginFailure(t *testing.T) { srv := fakeQBittorrent(t, "[]") - c, err := New(Config{URL: srv.URL, Username: "admin", Password: "wrong"}) + c, err := New(Config{URL: srv.URL, Username: "admin", Password: "wrong"}, nil) if err != nil { t.Fatal(err) } diff --git a/internal/recognize/integration_test.go b/internal/recognize/integration_test.go index 7c896f5..d610bf0 100644 --- a/internal/recognize/integration_test.go +++ b/internal/recognize/integration_test.go @@ -38,7 +38,7 @@ func TestIntegration_RecognizeSeries(t *testing.T) { provider, err := llm.New(llm.Config{ Type: "openai-compat", BaseURL: base, APIKey: key, Model: model, Timeout: 90 * time.Second, - }) + }, nil) if err != nil { t.Fatalf("llm.New: %v", err) } diff --git a/internal/recognize/validate.go b/internal/recognize/validate.go index d7b9938..6964b11 100644 --- a/internal/recognize/validate.go +++ b/internal/recognize/validate.go @@ -15,7 +15,7 @@ import ( func parsePlan(raw string, in Input) (Plan, error) { jsonStr, err := llm.ExtractJSONObject(raw) if err != nil { - return Plan{}, fmt.Errorf("в ответе нет JSON-объекта") + return Plan{}, fmt.Errorf("no JSON object in response") } var p Plan @@ -25,7 +25,7 @@ func parsePlan(raw string, in Input) (Plan, error) { // Повторяем без строгого режима: лишние поля — не повод падать, // но если и так не разобралось — это ошибка схемы. if err2 := json.Unmarshal([]byte(jsonStr), &p); err2 != nil { - return Plan{}, fmt.Errorf("JSON не разобран: %v", err2) + return Plan{}, fmt.Errorf("JSON not parsed: %v", err2) } } @@ -42,15 +42,15 @@ func validateSchema(p *Plan, in Input) error { switch p.Type { case MediaMovie, MediaSeries: case "": - return fmt.Errorf("поле type пустое (ожидалось movie или series)") + return fmt.Errorf("field type is empty (expected movie or series)") default: - return fmt.Errorf("неизвестный type %q", p.Type) + return fmt.Errorf("unknown type %q", p.Type) } if strings.TrimSpace(p.Title) == "" { - return fmt.Errorf("поле title пустое") + return fmt.Errorf("field title is empty") } if len(p.Files) == 0 { - return fmt.Errorf("список files пуст") + return fmt.Errorf("files list is empty") } known := make(map[string]bool, len(in.Files)) @@ -61,16 +61,16 @@ func validateSchema(p *Plan, in Input) error { for i := range p.Files { pf := &p.Files[i] if !pf.Role.valid() { - return fmt.Errorf("файл %q: неизвестная role %q", pf.Src, pf.Role) + return fmt.Errorf("file %q: unknown role %q", pf.Src, pf.Role) } if strings.TrimSpace(pf.Src) == "" { - return fmt.Errorf("файл с пустым src") + return fmt.Errorf("file with empty src") } if !known[pf.Src] { - return fmt.Errorf("src %q не найден среди файлов торрента", pf.Src) + return fmt.Errorf("src %q not found among torrent files", pf.Src) } if pf.Role == RoleEpisode && pf.Episode == nil { - return fmt.Errorf("серия %q без номера episode", pf.Src) + return fmt.Errorf("episode %q has no episode number", pf.Src) } } return nil diff --git a/internal/recognize/validate_test.go b/internal/recognize/validate_test.go index 6093546..1e55fa1 100644 --- a/internal/recognize/validate_test.go +++ b/internal/recognize/validate_test.go @@ -37,14 +37,14 @@ func TestValidateSchema_Errors(t *testing.T) { p Plan want string }{ - {"empty type", Plan{Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: RoleMain}}}, "type пустое"}, - {"bad type", Plan{Type: "show", Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: RoleMain}}}, "неизвестный type"}, - {"empty title", Plan{Type: MediaMovie, Files: []PlanFile{{Src: "a.mkv", Role: RoleMain}}}, "title пустое"}, - {"no files", Plan{Type: MediaMovie, Title: "x"}, "files пуст"}, - {"bad role", Plan{Type: MediaMovie, Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: "boss"}}}, "неизвестная role"}, - {"empty src", Plan{Type: MediaMovie, Title: "x", Files: []PlanFile{{Src: "", Role: RoleMain}}}, "пустым src"}, - {"unknown src", Plan{Type: MediaMovie, Title: "x", Files: []PlanFile{{Src: "z.mkv", Role: RoleMain}}}, "не найден"}, - {"episode no num", Plan{Type: MediaSeries, Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: RoleEpisode, Season: intp(1)}}}, "без номера episode"}, + {"empty type", Plan{Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: RoleMain}}}, "type is empty"}, + {"bad type", Plan{Type: "show", Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: RoleMain}}}, "unknown type"}, + {"empty title", Plan{Type: MediaMovie, Files: []PlanFile{{Src: "a.mkv", Role: RoleMain}}}, "title is empty"}, + {"no files", Plan{Type: MediaMovie, Title: "x"}, "files list is empty"}, + {"bad role", Plan{Type: MediaMovie, Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: "boss"}}}, "unknown role"}, + {"empty src", Plan{Type: MediaMovie, Title: "x", Files: []PlanFile{{Src: "", Role: RoleMain}}}, "empty src"}, + {"unknown src", Plan{Type: MediaMovie, Title: "x", Files: []PlanFile{{Src: "z.mkv", Role: RoleMain}}}, "not found among torrent files"}, + {"episode no num", Plan{Type: MediaSeries, Title: "x", Files: []PlanFile{{Src: "a.mkv", Role: RoleEpisode, Season: intp(1)}}}, "has no episode number"}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { diff --git a/internal/tgbot/bot.go b/internal/tgbot/bot.go index d5c8f57..fa75c34 100644 --- a/internal/tgbot/bot.go +++ b/internal/tgbot/bot.go @@ -214,6 +214,7 @@ func (b *Bot) handleCallback(ctx context.Context, cq *tgbotapi.CallbackQuery) { func (b *Bot) refreshCard(ctx context.Context, chatID int64, msgID int, id int64) { rd, err := b.reviewer.ReviewData(ctx, id) if err != nil { + b.log.Warn("telegram: refresh card failed", "download_id", id, "err", err) return } text, kb := b.renderCard(rd) diff --git a/internal/worker/review.go b/internal/worker/review.go index 7662729..225750a 100644 --- a/internal/worker/review.go +++ b/internal/worker/review.go @@ -81,14 +81,14 @@ func (w *Worker) recognizeOne(ctx context.Context, id int64) { // относительных путей файлов в абсолютные при раскладке. func (w *Worker) runRecognize(ctx context.Context, d store.Download) (recognize.Result, string, error) { if !d.Infohash.Valid { - return recognize.Result{}, "", fmt.Errorf("нет infohash") + return recognize.Result{}, "", fmt.Errorf("no infohash") } t, ok, err := w.torrentByInfohash(ctx, d.Infohash.String) if err != nil { return recognize.Result{}, "", err } if !ok { - return recognize.Result{}, "", fmt.Errorf("торрент не найден в qBittorrent") + return recognize.Result{}, "", fmt.Errorf("torrent not found in qBittorrent") } files, err := w.qbt.Files(ctx, t.Hash) if err != nil { @@ -209,7 +209,7 @@ func (w *Worker) Apply(ctx context.Context, id int64) error { w.mu.Lock() defer w.mu.Unlock() if w.layouter == nil { - return fmt.Errorf("apply: раскладчик не сконфигурирован") + return fmt.Errorf("apply: layouter not configured") } d, err := w.store.GetDownload(ctx, id) @@ -217,7 +217,7 @@ func (w *Worker) Apply(ctx context.Context, id int64) error { return fmt.Errorf("apply: %w", err) } if d.State != store.StateReview && d.State != store.StateDeferred { - return fmt.Errorf("apply: задача %d в состоянии %s (ожидалось review/deferred)", id, d.State) + return fmt.Errorf("apply: download %d is in state %s (expected review/deferred)", id, d.State) } plan, tag, err := w.effectivePlan(ctx, id) @@ -226,7 +226,7 @@ func (w *Worker) Apply(ctx context.Context, id int64) error { } t, ok, err := w.torrentByInfohash(ctx, d.Infohash.String) if err != nil || !ok { - return fmt.Errorf("apply: торрент не найден: %v", err) + return fmt.Errorf("apply: torrent not found: %v", err) } w.transition(ctx, *d, store.StateLinking, "", "") @@ -243,7 +243,7 @@ func (w *Worker) linkPlan(ctx context.Context, d *store.Download, plan recognize links, err := w.layouter.BuildLinks(toLayoutPlan(plan, savePath, providerTag)) if err != nil { w.transition(ctx, *d, store.StateReview, "build", err.Error()) - return fmt.Errorf("построение ссылок: %w", err) + return fmt.Errorf("build links: %w", err) } batch := w.newID() @@ -263,7 +263,7 @@ func (w *Worker) linkPlan(ctx context.Context, d *store.Download, plan recognize } if len(fl) > 0 { if err := w.store.CreateFileLinks(ctx, fl); err != nil { - return fmt.Errorf("запись ссылок: %w", err) + return fmt.Errorf("persist links: %w", err) } } @@ -285,7 +285,7 @@ func (w *Worker) linkPlan(ctx context.Context, d *store.Download, plan recognize func (w *Worker) Refine(ctx context.Context, id int64, hint string) error { hint = strings.TrimSpace(hint) if hint == "" { - return fmt.Errorf("refine: пустая подсказка") + return fmt.Errorf("refine: empty hint") } w.mu.Lock() defer w.mu.Unlock() @@ -297,6 +297,7 @@ func (w *Worker) Refine(ctx context.Context, id int64, hint string) error { if err := w.store.AddHint(ctx, id, hint); err != nil { return fmt.Errorf("refine: %w", err) } + w.log.Info("review: hint added, re-recognizing", "download_id", id, "hint", hint) w.transition(ctx, *d, store.StateRecognizing, "", "") return nil } @@ -305,7 +306,7 @@ func (w *Worker) Refine(ctx context.Context, id int64, hint string) error { // — чтобы LLM пересобрал роли файлов под новый тип. func (w *Worker) SetType(ctx context.Context, id int64, mediaType string) error { if mediaType != string(recognize.MediaMovie) && mediaType != string(recognize.MediaSeries) { - return fmt.Errorf("set type: недопустимый тип %q", mediaType) + return fmt.Errorf("set type: invalid type %q", mediaType) } w.mu.Lock() defer w.mu.Unlock() @@ -333,7 +334,7 @@ func (w *Worker) SetType(ctx context.Context, id int64, mediaType string) error func (w *Worker) IgnoreFile(ctx context.Context, id int64, src string) error { src = strings.TrimSpace(src) if src == "" { - return fmt.Errorf("ignore: пустой путь") + return fmt.Errorf("ignore: empty path") } w.mu.Lock() defer w.mu.Unlock() @@ -353,6 +354,7 @@ func (w *Worker) IgnoreFile(ctx context.Context, id int64, src string) error { if err := w.store.SetOverride(ctx, id, ovrIgnoredFiles, string(b)); err != nil { return fmt.Errorf("ignore: %w", err) } + w.log.Info("review: file ignored", "download_id", id, "src", src) return nil } @@ -366,7 +368,7 @@ func (w *Worker) Defer(ctx context.Context, id int64) error { return fmt.Errorf("defer: %w", err) } if d.State.IsTerminal() { - return fmt.Errorf("defer: задача %d терминальна (%s)", id, d.State) + return fmt.Errorf("defer: download %d is terminal (%s)", id, d.State) } w.transition(ctx, *d, store.StateDeferred, "", "") return nil @@ -378,7 +380,7 @@ func (w *Worker) Undo(ctx context.Context, id int64) error { w.mu.Lock() defer w.mu.Unlock() if w.layouter == nil { - return fmt.Errorf("undo: раскладчик не сконфигурирован") + return fmt.Errorf("undo: layouter not configured") } d, err := w.store.GetDownload(ctx, id) @@ -386,14 +388,14 @@ func (w *Worker) Undo(ctx context.Context, id int64) error { return fmt.Errorf("undo: %w", err) } if d.State != store.StateDone { - return fmt.Errorf("undo: задача %d в состоянии %s (ожидалось done)", id, d.State) + return fmt.Errorf("undo: download %d is in state %s (expected done)", id, d.State) } batch, err := w.store.LatestBatchID(ctx, id) if err != nil { return fmt.Errorf("undo: %w", err) } if batch == "" { - return fmt.Errorf("undo: нечего откатывать") + return fmt.Errorf("undo: nothing to revert") } rows, err := w.store.ListFileLinksByBatch(ctx, batch) if err != nil { @@ -422,7 +424,7 @@ func (w *Worker) requireReviewable(ctx context.Context, id int64, op string) (*s return nil, fmt.Errorf("%s: %w", op, err) } if d.State != store.StateReview && d.State != store.StateDeferred { - return nil, fmt.Errorf("%s: задача %d в состоянии %s (ожидалось review/deferred)", op, id, d.State) + return nil, fmt.Errorf("%s: download %d is in state %s (expected review/deferred)", op, id, d.State) } return d, nil } @@ -448,7 +450,7 @@ func (w *Worker) ChooseCandidate(ctx context.Context, id, candidateID int64) err return fmt.Errorf("choose candidate: %w", err) } if rec == nil || cand == nil || cand.RecognitionID != rec.ID { - return fmt.Errorf("choose candidate: кандидат %d не относится к текущему распознаванию", candidateID) + return fmt.Errorf("choose candidate: candidate %d does not belong to the current recognition", candidateID) } pins := map[string]string{ovrProvider: cand.Provider, ovrProviderID: cand.ProviderID} @@ -478,10 +480,10 @@ func (w *Worker) SetProviderID(ctx context.Context, id int64, provider, provider switch provider { case "tmdb", "tvdb", "imdb": default: - return fmt.Errorf("set provider: недопустимый провайдер %q (tmdb/tvdb/imdb)", provider) + return fmt.Errorf("set provider: invalid provider %q (tmdb/tvdb/imdb)", provider) } if providerID == "" { - return fmt.Errorf("set provider: пустой id") + return fmt.Errorf("set provider: empty id") } w.mu.Lock() defer w.mu.Unlock() @@ -495,6 +497,8 @@ func (w *Worker) SetProviderID(ctx context.Context, id int64, provider, provider if err := w.store.SetOverride(ctx, id, ovrProviderID, providerID); err != nil { return fmt.Errorf("set provider: %w", err) } + w.log.Info("review: provider set manually", + "download_id", id, "provider", provider, "provider_id", providerID) return nil } @@ -512,6 +516,7 @@ func (w *Worker) ClearProvider(ctx context.Context, id int64) error { if err := w.store.SetOverride(ctx, id, ovrProviderID, ""); err != nil { return fmt.Errorf("clear provider: %w", err) } + w.log.Info("review: provider cleared (no metadata base)", "download_id", id) return nil } @@ -557,19 +562,27 @@ func (w *Worker) ReviewData(ctx context.Context, id int64) (*ReviewData, error) if rec != nil { if cands, cerr := w.store.ListCandidatesByRecognition(ctx, rec.ID); cerr == nil { rd.Candidates = cands + } else { + w.log.Debug("review data: list candidates failed (skipped)", + "download_id", id, "err", cerr) } } if rec != nil && rec.Plan.Valid { var plan recognize.Plan - if err := json.Unmarshal([]byte(rec.Plan.String), &plan); err == nil { + if err := json.Unmarshal([]byte(rec.Plan.String), &plan); err != nil { + w.log.Warn("review data: unmarshal plan failed", "download_id", id, "err", err) + } else { plan = applyOverrides(plan, overrides) rd.Plan = plan // Превью строим по относительным путям с provider-тегом; ошибку - // игнорируем — просто покажем причины без превью. + // логируем на Debug — просто покажем причины без превью. if w.layouter != nil { tag := providerTag(prov, pid) if links, lerr := w.layouter.BuildLinks(toLayoutPlan(plan, "", tag)); lerr == nil { rd.Preview = links + } else { + w.log.Debug("review data: build preview failed (skipped)", + "download_id", id, "err", lerr) } } } @@ -585,11 +598,11 @@ func (w *Worker) effectivePlan(ctx context.Context, id int64) (recognize.Plan, s return recognize.Plan{}, "", err } if rec == nil || !rec.Plan.Valid { - return recognize.Plan{}, "", fmt.Errorf("нет плана распознавания") + return recognize.Plan{}, "", fmt.Errorf("no recognition plan") } var plan recognize.Plan if err := json.Unmarshal([]byte(rec.Plan.String), &plan); err != nil { - return recognize.Plan{}, "", fmt.Errorf("разбор плана: %w", err) + return recognize.Plan{}, "", fmt.Errorf("parse plan: %w", err) } overrides, err := w.store.ListOverrides(ctx, id) if err != nil { diff --git a/internal/worker/review_test.go b/internal/worker/review_test.go index 08f9f70..aabed9c 100644 --- a/internal/worker/review_test.go +++ b/internal/worker/review_test.go @@ -491,7 +491,7 @@ func newApplyFixture(t *testing.T, plan recognize.Plan) applyFixture { t.Fatal(err) } } - lay, err := layout.New(layout.Config{MoviesDir: movies, SeriesDir: series}) + lay, err := layout.New(layout.Config{MoviesDir: movies, SeriesDir: series}, nil) if err != nil { t.Fatal(err) } @@ -653,7 +653,7 @@ func TestRecognizeOne_AutoApplies(t *testing.T) { _ = os.MkdirAll(filepath.Dir(p), 0o755) _ = os.WriteFile(p, []byte("x"), 0o644) } - lay, _ := layout.New(layout.Config{MoviesDir: movies, SeriesDir: series}) + lay, _ := layout.New(layout.Config{MoviesDir: movies, SeriesDir: series}, nil) st := newMemStore() st.put(completedDownload(1))