diff --git a/README.md b/README.md index 94d8ff5..5892e3c 100644 --- a/README.md +++ b/README.md @@ -133,6 +133,30 @@ git fetch → pick target (latest release tag by default, or a branch) i.e. `git clone` the repo and `pip install -e .` rather than installing a wheel. The `repo_dir` defaults to the repo root above the package; override it if needed. +## Run logs + +With `logging.enabled: true` (the default), every `plan`/`run` writes a fresh +timestamped log to `logging.log_dir` (`scanfiler-.log`). It records, +per file, whether it was **sent** to the LLM, **skipped** (with the reason — already +judged, already named, image under text mode, …), **processed** successfully, or +**failed**, and ends with a summary of the counts: + +``` +SEND: SCAN00001.pdf (pdf, 0 image(s), 354 text chars) +OK: SCAN00001.pdf -> receipts/2025-06-riverside-auto-service-receipt.pdf (conf=0.95) +SKIP (criteria): PIC00001.png - nothing to send in text mode +---- run summary ---- +sent to LLM: 2 +processed successfully: 2 (of which 0 routed to _Unsorted) +failed: 0 +skipped (already judged): 0 +skipped (criteria): 1 (selection 0 + nothing-to-send 1) +``` + +Failures log full diagnostics — status code, URL, the request (with base64 image data +redacted to a size summary), and the response body — so you can see exactly what the +server returned. Set `logging.enabled: false` to turn run logs off. + ## Testing ```bash diff --git a/config.example.yaml b/config.example.yaml index 5da89e2..1a5eb8e 100644 --- a/config.example.yaml +++ b/config.example.yaml @@ -20,7 +20,9 @@ ai: extraction: pdf_max_pages: 2 # only the first N pages go to the model raster_dpi: 150 # rasterization DPI for the vision model - send_mode: auto # vision | text | auto (text if rich layer, else images) + send_mode: auto # vision | text | auto. text = never send images + # (image-only files are skipped); auto uses text + # when the layer is rich, else page images. selection: process_pattern: '^(SCAN|PIC|IMG)[\W_]*\d+' # "looks unprocessed" @@ -49,6 +51,8 @@ apply: on_collision: suffix # suffix (-2,-3) | skip | overwrite logging: + enabled: true # write a fresh timestamped log file each run + log_dir: ./logs # where per-run logs land (scanfiler-.log) level: info # debug | info | warn | error audit_file: ./logs/audit.jsonl # JSONL record of every move (reversible via undo) ledger_db: ./state/ledger.sqlite # content-hash processed-file ledger diff --git a/samples/config.yaml b/samples/config.yaml index 363ef14..3c12c2a 100644 --- a/samples/config.yaml +++ b/samples/config.yaml @@ -38,6 +38,7 @@ apply: action: copy logging: + log_dir: samples/logs audit_file: samples/logs/audit.jsonl ledger_db: samples/state/ledger.sqlite diff --git a/scanfiler/ai/client.py b/scanfiler/ai/client.py index 30cc08d..9d14c64 100644 --- a/scanfiler/ai/client.py +++ b/scanfiler/ai/client.py @@ -2,11 +2,14 @@ Works against llama-server, mlx-vlm, or any cloud OpenAI-compatible endpoint. The client is deliberately small and injectable so tests can swap in a stub (the same -approach actual-ai-categorizer uses for its provider). +approach actual-ai-categorizer uses for its provider). On failure it raises AIError, +which carries the status code, the (image-redacted) request, and the response body so +the run log can record exactly what went wrong. """ from __future__ import annotations +import copy import json import time from typing import Protocol @@ -17,6 +20,54 @@ from .schema import Decision, build_response_format +class AIError(RuntimeError): + """An AI request that failed after all retries, with diagnostic detail.""" + + def __init__( + self, message: str, *, status_code: int | None = None, url: str | None = None, + attempts: int | None = None, request: dict | None = None, + response_text: str | None = None, + ): + super().__init__(message) + self.status_code = status_code + self.url = url + self.attempts = attempts + self.request = request + self.response_text = response_text + + def detail(self) -> str: + """A single-line-ish summary with everything useful for the log.""" + parts = [str(self)] + if self.status_code is not None: + parts.append(f"status_code={self.status_code}") + if self.url: + parts.append(f"url={self.url}") + if self.attempts is not None: + parts.append(f"attempts={self.attempts}") + if self.response_text: + parts.append(f"response={self.response_text[:4000]}") + if self.request is not None: + parts.append("request=" + json.dumps(self.request)[:8000]) + return " | ".join(parts) + + +def redact_request(body: dict) -> dict: + """Deep-copy the request, replacing base64 image data URLs with a size summary. + + Keeps full request structure/text in logs without dumping megabytes of base64. + """ + b = copy.deepcopy(body) + for msg in b.get("messages", []): + content = msg.get("content") + if isinstance(content, list): + for part in content: + if part.get("type") == "image_url": + url = part.get("image_url", {}).get("url", "") + if isinstance(url, str) and url.startswith("data:"): + part["image_url"]["url"] = f"" + return b + + class AIClient(Protocol): def decide( self, system_prompt: str, user_content: list[dict], @@ -49,19 +100,36 @@ def decide( url = self.cfg.base_url.rstrip("/") + "/chat/completions" last_exc: Exception | None = None + status_code: int | None = None + response_text: str | None = None for attempt in range(1, self.cfg.max_retries + 1): + resp = None try: with httpx.Client(timeout=self.cfg.request_timeout_s) as client: resp = client.post(url, json=body, headers=headers) - resp.raise_for_status() - data = resp.json() + resp.raise_for_status() + data = resp.json() content = data["choices"][0]["message"]["content"] return Decision.model_validate(json.loads(content)) except Exception as exc: # noqa: BLE001 — retry transient failures last_exc = exc + if resp is not None: + status_code = resp.status_code + try: + response_text = resp.text + except Exception: # noqa: BLE001 + response_text = None if attempt < self.cfg.max_retries: time.sleep(min(2 ** attempt, 10)) - raise RuntimeError(f"AI request failed after {self.cfg.max_retries} attempts: {last_exc}") + + raise AIError( + f"AI request failed after {self.cfg.max_retries} attempts: {last_exc}", + status_code=status_code, + url=url, + attempts=self.cfg.max_retries, + request=redact_request(body), + response_text=response_text, + ) def make_client(cfg: AIConfig) -> AIClient: diff --git a/scanfiler/cli.py b/scanfiler/cli.py index b7f323c..c3c2026 100644 --- a/scanfiler/cli.py +++ b/scanfiler/cli.py @@ -25,6 +25,15 @@ def _make_client(cfg: Config): return make_client(cfg.ai) +def _stats_line(stats) -> str: + return ( + f"sent={stats.sent} proposed={stats.proposed} unsorted={stats.unsorted} " + f"skipped_seen={stats.skipped_seen} " + f"skipped_criteria={stats.skipped_selection + stats.skipped_no_content} " + f"errors={stats.errors}" + ) + + def cmd_init(args) -> int: dest = Path(args.config) if dest.exists(): @@ -39,20 +48,20 @@ def cmd_plan(args) -> int: from .ledger import open_ledger from .pipeline import plan from .proposals import write_proposals + from .runlog import open_run_log cfg = _load(args) client = _make_client(cfg) - with open_ledger(cfg.logging.ledger_db) as ledger: - proposals, stats = plan(cfg, client, ledger) + with open_run_log(cfg) as (log, log_path), open_ledger(cfg.logging.ledger_db) as ledger: + proposals, stats = plan(cfg, client, ledger, log) if not args.dry_run: write_proposals(args.proposals, proposals) print(f"Wrote {len(proposals)} proposals to {args.proposals}") else: print("[dry-run] not writing proposals file") - print( - f"proposed={stats.proposed} unsorted={stats.unsorted} " - f"skipped_seen={stats.skipped_seen} errors={stats.errors}" - ) + print(_stats_line(stats)) + if log_path: + print(f"log: {log_path}") return 0 @@ -77,6 +86,7 @@ def _run_once(cfg: Config, args) -> int: from .lock import LockHeld, file_lock from .pipeline import plan from .proposals import write_proposals + from .runlog import open_run_log # Check for + apply a newer release before doing any work. Done before the lock so a # re-exec into the updated version doesn't deadlock against our own lockfile. On a @@ -90,12 +100,11 @@ def _run_once(cfg: Config, args) -> int: lock_path = Path(cfg.logging.ledger_db).with_suffix(".lock") try: with file_lock(lock_path): - with open_ledger(cfg.logging.ledger_db) as ledger: - proposals, stats = plan(cfg, client, ledger) - print( - f"proposed={stats.proposed} unsorted={stats.unsorted} " - f"skipped_seen={stats.skipped_seen} errors={stats.errors}" - ) + with open_run_log(cfg) as (log, log_path), open_ledger(cfg.logging.ledger_db) as ledger: + proposals, stats = plan(cfg, client, ledger, log) + print(_stats_line(stats)) + if log_path: + print(f"log: {log_path}") if cfg.apply.mode == "auto" and not args.dry_run: result = apply_proposals(cfg, proposals, ledger) print(f"[auto-apply] run={result.run_id} applied={result.applied} " diff --git a/scanfiler/config.py b/scanfiler/config.py index c94b144..591850f 100644 --- a/scanfiler/config.py +++ b/scanfiler/config.py @@ -87,6 +87,8 @@ class ApplyConfig(BaseModel): class LoggingConfig(BaseModel): + enabled: bool = True # write a timestamped per-run log file + log_dir: Path = Path("./logs") # where per-run logs (and audit) live level: Literal["debug", "info", "warn", "error"] = "info" audit_file: Path = Path("./logs/audit.jsonl") ledger_db: Path = Path("./state/ledger.sqlite") diff --git a/scanfiler/extract/image.py b/scanfiler/extract/image.py index 1560a7f..59a8aa0 100644 --- a/scanfiler/extract/image.py +++ b/scanfiler/extract/image.py @@ -14,6 +14,12 @@ def extract_image(path: Path, cfg: ExtractionConfig) -> ExtractResult: + # Text-only mode: an image has no text layer, so there is nothing to send. + # Return empty (no images) without decoding; the pipeline skips it rather than + # shipping an image to a text-only model. + if cfg.send_mode == "text": + return ExtractResult(kind="image") + from PIL import Image with Image.open(path) as im: diff --git a/scanfiler/pipeline.py b/scanfiler/pipeline.py index d00e7c4..81f8eab 100644 --- a/scanfiler/pipeline.py +++ b/scanfiler/pipeline.py @@ -8,13 +8,14 @@ from __future__ import annotations import fnmatch +import logging import re import time from dataclasses import dataclass from pathlib import Path from .ai import prompt as prompt_mod -from .ai.client import AIClient +from .ai.client import AIClient, AIError from .config import Config from .extract import classify, extract from .ledger import STATUS_ERROR, Ledger, LedgerEntry, hash_file @@ -27,13 +28,18 @@ ) from .proposals import Proposal +_NULL_LOG = logging.getLogger("scanfiler.pipeline.null") +_NULL_LOG.addHandler(logging.NullHandler()) + @dataclass class PlanStats: + sent: int = 0 # files for which an LLM request was attempted proposed: int = 0 unsorted: int = 0 - skipped_seen: int = 0 - skipped_selection: int = 0 + skipped_seen: int = 0 # already judged by the AI on a prior run + skipped_selection: int = 0 # didn't fit run criteria (already named, ignored, too new) + skipped_no_content: int = 0 # nothing to send in this mode (e.g. image under text mode) errors: int = 0 @@ -45,28 +51,42 @@ def list_subdirs(library_dir: Path) -> list[str]: ) -def _selected(path: Path, cfg: Config) -> bool: - """Apply ignore globs, mtime-age guard, and the process_pattern/process_all rule.""" +def _select_reason(path: Path, cfg: Config) -> str | None: + """Why this file is NOT eligible to be sent, or None if it is. + + Covers ignore globs, unsupported types, the mtime-age guard, and the + process_pattern/process_all rule (already-named files). + """ name = path.name for pat in cfg.selection.ignore_globs: if fnmatch.fnmatch(name, pat): - return False + return f"ignored (matches glob {pat!r})" if classify(path) == "unknown": - return False + return "unsupported file type" try: if time.time() - path.stat().st_mtime < cfg.selection.min_mtime_age_s: - return False # still being written / synced + return "too recently modified (still being written/synced)" except OSError: - return False - if cfg.selection.process_all: - return True - return re.search(cfg.selection.process_pattern, name) is not None + return "stat failed" + if not cfg.selection.process_all and re.search(cfg.selection.process_pattern, name) is None: + return "name does not match process_pattern (already named)" + return None + + +def _selected(path: Path, cfg: Config) -> bool: + return _select_reason(path, cfg) is None + + +def _walk(cfg: Config): + """All regular files under the inbox, sorted for deterministic ordering.""" + for path in sorted(cfg.paths.inbox_dir.rglob("*")): + if path.is_file(): + yield path def iter_inbox(cfg: Config): - inbox = cfg.paths.inbox_dir - for path in sorted(inbox.rglob("*")): - if path.is_file() and _selected(path, cfg): + for path in _walk(cfg): + if _selected(path, cfg): yield path @@ -95,47 +115,72 @@ def claim(self, subdir: str, desired: str, ext: str, policy: str) -> str | None: return chosen -def plan(cfg: Config, client: AIClient, ledger: Ledger) -> tuple[list[Proposal], PlanStats]: +def plan( + cfg: Config, client: AIClient, ledger: Ledger, logger: logging.Logger | None = None +) -> tuple[list[Proposal], PlanStats]: + log = logger or _NULL_LOG stats = PlanStats() proposals: list[Proposal] = [] existing_subdirs = list_subdirs(cfg.paths.library_dir) system_prompt = prompt_mod.build_system_prompt(cfg, existing_subdirs) taken = _TakenIndex(cfg.paths.library_dir, cfg.paths.unsorted_subdir) - for path in iter_inbox(cfg): + log.info( + "run start: inbox=%s library=%s send_mode=%s model=%s", + cfg.paths.inbox_dir, cfg.paths.library_dir, cfg.extraction.send_mode, cfg.ai.model, + ) + + for path in _walk(cfg): + name = path.name + + reason = _select_reason(path, cfg) + if reason is not None: + stats.skipped_selection += 1 + log.info("SKIP (criteria): %s - %s", name, reason) + continue + file_hash = hash_file(path) if ledger.seen(file_hash): stats.skipped_seen += 1 + log.info("SKIP (already judged): %s", name) continue result = extract(path, cfg.extraction) - if result.error or not result.has_content: + if result.error: stats.errors += 1 - ledger.upsert( - LedgerEntry( - file_hash=file_hash, - original_name=path.name, - status=STATUS_ERROR, - error=result.error or "no extractable content", - ) - ) + log.error("FAIL (extract): %s - %s", name, result.error) + ledger.upsert(LedgerEntry(file_hash=file_hash, original_name=name, + status=STATUS_ERROR, error=result.error)) + continue + if not result.has_content: + # Nothing to send in this mode (e.g. an image under send_mode: text, or a + # PDF with no text layer). Counted as a criteria skip, not an error, and + # not recorded so it is reconsidered if vision is later enabled. + stats.skipped_no_content += 1 + log.info("SKIP (criteria): %s - nothing to send in %s mode", + name, cfg.extraction.send_mode) continue + stats.sent += 1 + log.info("SEND: %s (%s, %d image(s), %d text chars)", + name, result.kind, len(result.images), len(result.text)) try: - user_content = prompt_mod.build_user_content(path.name, result) + user_content = prompt_mod.build_user_content(name, result) decision = client.decide( system_prompt, user_content, existing_subdirs, cfg.naming.allow_new_subdirs ) - except Exception as exc: # noqa: BLE001 + except AIError as exc: stats.errors += 1 - ledger.upsert( - LedgerEntry( - file_hash=file_hash, - original_name=path.name, - status=STATUS_ERROR, - error=f"ai: {type(exc).__name__}: {exc}", - ) - ) + log.error("FAIL (ai): %s - %s", name, exc.detail()) + ledger.upsert(LedgerEntry(file_hash=file_hash, original_name=name, + status=STATUS_ERROR, error=f"ai: {exc}")) + continue + except Exception as exc: # noqa: BLE001 — any other client/parse failure + stats.errors += 1 + err = f"ai: {type(exc).__name__}: {exc}" + log.error("FAIL (ai): %s - %s", name, err) + ledger.upsert(LedgerEntry(file_hash=file_hash, original_name=name, + status=STATUS_ERROR, error=err)) continue proposal = _build_proposal(cfg, path, file_hash, decision, taken) @@ -144,21 +189,34 @@ def plan(cfg: Config, client: AIClient, ledger: Ledger) -> tuple[list[Proposal], stats.unsorted += 1 else: stats.proposed += 1 + log.info("OK: %s -> %s/%s (conf=%.2f%s)", name, proposal.subdir, + proposal.new_filename, proposal.confidence, + ", unsorted" if proposal.unsorted else "") from .ledger import STATUS_PROPOSED, STATUS_UNSORTED - ledger.upsert( - LedgerEntry( - file_hash=file_hash, - original_name=path.name, - status=STATUS_UNSORTED if proposal.unsorted else STATUS_PROPOSED, - decision=decision.model_dump(), - ) - ) + ledger.upsert(LedgerEntry( + file_hash=file_hash, original_name=name, + status=STATUS_UNSORTED if proposal.unsorted else STATUS_PROPOSED, + decision=decision.model_dump(), + )) + _log_summary(log, stats) return proposals, stats +def _log_summary(log: logging.Logger, stats: PlanStats) -> None: + log.info("---- run summary ----") + log.info("sent to LLM: %d", stats.sent) + log.info("processed successfully: %d (of which %d routed to _Unsorted)", + stats.proposed + stats.unsorted, stats.unsorted) + log.info("failed: %d", stats.errors) + log.info("skipped (already judged): %d", stats.skipped_seen) + log.info("skipped (criteria): %d (selection %d + nothing-to-send %d)", + stats.skipped_selection + stats.skipped_no_content, + stats.skipped_selection, stats.skipped_no_content) + + def _build_proposal(cfg, path: Path, file_hash: str, decision, taken: _TakenIndex) -> Proposal: ext = normalize_extension(path.suffix) base = sanitize_component(decision.filename, max_len=cfg.naming.max_filename_len) diff --git a/scanfiler/runlog.py b/scanfiler/runlog.py new file mode 100644 index 0000000..7c6b2b3 --- /dev/null +++ b/scanfiler/runlog.py @@ -0,0 +1,61 @@ +"""Per-run logging: a fresh timestamped log file for each plan/run invocation. + +The log records, per file, whether it was sent to the LLM, skipped (and why), +processed, or failed (with full diagnostic detail on failure), plus an end-of-run +summary of the counts. Enabled by default; controlled by the [logging] config block. +""" + +from __future__ import annotations + +import datetime +import logging +from collections.abc import Iterator +from contextlib import contextmanager +from pathlib import Path + +_LEVELS = { + "debug": logging.DEBUG, + "info": logging.INFO, + "warn": logging.WARNING, + "error": logging.ERROR, +} + + +def _null_logger() -> logging.Logger: + log = logging.getLogger("scanfiler.run.null") + log.handlers.clear() + log.addHandler(logging.NullHandler()) + log.propagate = False + return log + + +@contextmanager +def open_run_log(cfg) -> Iterator[tuple[logging.Logger, Path | None]]: + """Yield (logger, path). When logging is disabled, logger is a no-op and path None. + + The file handler is always flushed and closed on exit so the file is complete and + not left locked (important on Windows). + """ + log_cfg = cfg.logging + if not log_cfg.enabled: + yield _null_logger(), None + return + + log_dir = Path(log_cfg.log_dir) + log_dir.mkdir(parents=True, exist_ok=True) + ts = datetime.datetime.now().strftime("%Y%m%d-%H%M%S-%f")[:-3] + path = log_dir / f"scanfiler-{ts}.log" + + logger = logging.getLogger(f"scanfiler.run.{ts}") + logger.handlers.clear() + logger.setLevel(_LEVELS.get(log_cfg.level, logging.INFO)) + logger.propagate = False + handler = logging.FileHandler(path, encoding="utf-8") + handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s")) + logger.addHandler(handler) + try: + yield logger, path + finally: + handler.flush() + handler.close() + logger.removeHandler(handler) diff --git a/scanfiler/templates.py b/scanfiler/templates.py index 46592c4..dc466d8 100644 --- a/scanfiler/templates.py +++ b/scanfiler/templates.py @@ -23,7 +23,9 @@ extraction: pdf_max_pages: 2 # only the first N pages go to the model raster_dpi: 150 # rasterization DPI for the vision model - send_mode: auto # vision | text | auto (text if rich layer, else images) + send_mode: auto # vision | text | auto. text = never send images + # (image-only files are skipped); auto uses text + # when the layer is rich, else page images. selection: process_pattern: '^(SCAN|PIC|IMG)[\\W_]*\\d+' # "looks unprocessed" @@ -52,6 +54,8 @@ on_collision: suffix # suffix (-2,-3) | skip | overwrite logging: + enabled: true # write a fresh timestamped log file each run + log_dir: ./logs # where per-run logs land (scanfiler-.log) level: info # debug | info | warn | error audit_file: ./logs/audit.jsonl # JSONL record of every move (reversible via undo) ledger_db: ./state/ledger.sqlite # content-hash processed-file ledger diff --git a/tests/conftest.py b/tests/conftest.py index 1c5c160..de4455e 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -64,6 +64,7 @@ def config(workspace) -> Config: }, "selection": {"min_mtime_age_s": 0}, # files are brand new in tests "logging": { + "log_dir": str(root / "logs"), "audit_file": str(root / "logs" / "audit.jsonl"), "ledger_db": str(root / "state" / "ledger.sqlite"), }, diff --git a/tests/test_client.py b/tests/test_client.py index 76609c9..0b2e7d4 100644 --- a/tests/test_client.py +++ b/tests/test_client.py @@ -14,10 +14,12 @@ class _FakeResponse: def __init__(self, payload, status_ok=True): self._payload = payload self._ok = status_ok + self.status_code = 200 if status_ok else 500 + self.text = json.dumps(payload) def raise_for_status(self): if not self._ok: - raise RuntimeError("HTTP 500") + raise RuntimeError(f"HTTP {self.status_code}") def json(self): return self._payload @@ -56,9 +58,13 @@ def _decision_payload(**over): def _patch_httpx(monkeypatch): import httpx + import scanfiler.ai.client as client_module + _FakeClient.script = [] _FakeClient.posted = [] monkeypatch.setattr(httpx, "Client", _FakeClient) + # No retry backoff during tests. + monkeypatch.setattr(client_module.time, "sleep", lambda *a, **k: None) def _client(**over): @@ -100,3 +106,32 @@ def test_api_key_sets_auth_header(): def test_make_client_returns_openai_compat(): assert isinstance(make_client(AIConfig()), OpenAICompatClient) + + +def test_aierror_carries_status_and_response(): + from scanfiler.ai.client import AIError + + _FakeClient.script = [_FakeResponse({"error": "overloaded"}, status_ok=False) for _ in range(3)] + with pytest.raises(AIError) as ei: + _client().decide("sys", [], [], True) + err = ei.value + assert err.status_code == 500 + assert "overloaded" in (err.response_text or "") + assert err.attempts == 3 + assert err.url.endswith("/chat/completions") + detail = err.detail() + assert "status_code=500" in detail and "overloaded" in detail + + +def test_redact_request_hides_base64_image(): + from scanfiler.ai.client import redact_request + + body = {"messages": [{"role": "user", "content": [ + {"type": "text", "text": "hi"}, + {"type": "image_url", "image_url": {"url": "data:image/png;base64,QUJDQUJD"}}, + ]}]} + red = redact_request(body) + redacted_url = red["messages"][0]["content"][1]["image_url"]["url"] + assert "base64" not in redacted_url and "chars" in redacted_url + # original is untouched (deep copy) + assert body["messages"][0]["content"][1]["image_url"]["url"].startswith("data:image") diff --git a/tests/test_config.py b/tests/test_config.py index e49bf56..f071a7d 100644 --- a/tests/test_config.py +++ b/tests/test_config.py @@ -17,6 +17,19 @@ def test_env_interpolation(tmp_path, monkeypatch): assert cfg.ai.api_key == "secret-token" +def test_logging_enabled_by_default(tmp_path): + cfg_file = tmp_path / "config.yaml" + cfg_file.write_text( + "paths:\n" + f" inbox_dir: {tmp_path / 'in'}\n" + f" library_dir: {tmp_path / 'lib'}\n", + encoding="utf-8", + ) + cfg = load_config(cfg_file) + assert cfg.logging.enabled is True + assert cfg.logging.log_dir.name == "logs" + + def test_missing_env_becomes_empty(tmp_path, monkeypatch): monkeypatch.delenv("NOPE_VAR", raising=False) cfg_file = tmp_path / "config.yaml" diff --git a/tests/test_extract.py b/tests/test_extract.py index 61abe78..427fcd1 100644 --- a/tests/test_extract.py +++ b/tests/test_extract.py @@ -54,6 +54,18 @@ def test_pdf_vision_mode_renders_images(tmp_path): assert len(r.images) == 1 +def test_image_text_mode_sends_nothing(tmp_path): + from PIL import Image + + f = tmp_path / "p.png" + Image.new("RGB", (32, 32), (10, 20, 30)).save(str(f)) + r = extract(f, ExtractionConfig(send_mode="text")) + assert r.kind == "image" + assert r.images == [] # nothing to send to a text-only model + assert r.error is None # not an error + assert r.has_content is False + + def test_image_downscaled_and_pngified(tmp_path): from PIL import Image diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..3bf3ea5 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,59 @@ +"""Per-run logging: event lines, summary counts, and failure detail.""" + +from __future__ import annotations + +from scanfiler.ai.client import AIError +from scanfiler.ledger import Ledger +from scanfiler.pipeline import plan +from scanfiler.runlog import open_run_log + + +def test_log_records_events_and_summary(config, stub_client, workspace): + with open_run_log(config) as (log, path), Ledger(config.logging.ledger_db) as ledger: + proposals, stats = plan(config, stub_client, ledger, log) + + text = path.read_text(encoding="utf-8") + assert "run start" in text + assert "SEND:" in text + assert "OK:" in text + # TaxReturn2024.pdf doesn't match process_pattern -> counted + logged as a criteria skip. + assert "SKIP (criteria): TaxReturn2024.pdf" in text + assert stats.skipped_selection >= 1 + # summary block with the user-requested counts + assert "run summary" in text + assert "sent to LLM:" in text + assert "processed successfully:" in text + assert "failed:" in text + assert "skipped (already judged):" in text + assert "skipped (criteria):" in text + + +def test_log_records_ai_failure_detail(config, workspace): + class _Failing: + def decide(self, *a, **k): + raise AIError( + "request failed", status_code=503, + url="http://host:8001/v1/chat/completions", attempts=2, + request={"model": "m", "messages": []}, response_text="upstream is down", + ) + + with open_run_log(config) as (log, path), Ledger(config.logging.ledger_db) as ledger: + proposals, stats = plan(config, _Failing(), ledger, log) + + text = path.read_text(encoding="utf-8") + assert "FAIL (ai)" in text + assert "status_code=503" in text + assert "upstream is down" in text + assert stats.errors >= 1 + assert proposals == [] + + +def test_already_judged_skip_logged_on_second_run(config, stub_client, workspace): + # First run proposes; second run should log the hash-dedupe skip. + with open_run_log(config) as (log, _), Ledger(config.logging.ledger_db) as ledger: + plan(config, stub_client, ledger, log) + with open_run_log(config) as (log, path), Ledger(config.logging.ledger_db) as ledger: + _, stats = plan(config, stub_client, ledger, log) + text = path.read_text(encoding="utf-8") + assert "SKIP (already judged):" in text + assert stats.skipped_seen >= 1 diff --git a/tests/test_pipeline_edges.py b/tests/test_pipeline_edges.py index bf36127..87cc845 100644 --- a/tests/test_pipeline_edges.py +++ b/tests/test_pipeline_edges.py @@ -59,6 +59,27 @@ def decide(self, *a, **k): assert any("ai:" in (e.error or "") for e in errors) +def test_text_mode_skips_image_files_without_sending(config, workspace): + # send_mode: text must never ship an image; image-only files are skipped, not errored. + config.extraction.send_mode = "text" + calls: list[list[dict]] = [] + + class _Recording: + def decide(self, system_prompt, content, subdirs, allow_new): + calls.append(content) + return Decision(filename="Doc", subdir="Misc", confidence=0.9) + + with Ledger(config.logging.ledger_db) as ledger: + proposals, stats = plan(config, _Recording(), ledger) + + assert stats.skipped_no_content >= 1 # the PIC0001.jpg + assert stats.errors == 0 # skipping is not an error + assert not any("PIC0001" in p.original_path for p in proposals) + # the text docs were processed, but no request ever carried an image part + sent_parts = [part for c in calls for part in c] + assert sent_parts and all(p.get("type") != "image_url" for p in sent_parts) + + def test_mtime_guard_excludes_fresh_files(config, workspace): config.selection.min_mtime_age_s = 3600 # everything is "too fresh" assert list(iter_inbox(config)) == [] diff --git a/tests/test_runlog.py b/tests/test_runlog.py new file mode 100644 index 0000000..094818a --- /dev/null +++ b/tests/test_runlog.py @@ -0,0 +1,40 @@ +import time + +from scanfiler.config import Config +from scanfiler.runlog import open_run_log + + +def _cfg(tmp_path, enabled=True): + return Config.model_validate({ + "paths": {"inbox_dir": str(tmp_path / "in"), "library_dir": str(tmp_path / "lib")}, + "logging": {"enabled": enabled, "log_dir": str(tmp_path / "logs")}, + }) + + +def test_creates_timestamped_file(tmp_path): + cfg = _cfg(tmp_path) + with open_run_log(cfg) as (log, path): + assert path is not None + log.info("hello-line") + assert path.exists() # handler flushed + closed on exit + assert path.name.startswith("scanfiler-") and path.suffix == ".log" + assert "hello-line" in path.read_text(encoding="utf-8") + + +def test_disabled_yields_no_file(tmp_path): + cfg = _cfg(tmp_path, enabled=False) + with open_run_log(cfg) as (log, path): + assert path is None + log.info("ignored") # no-op, must not raise + assert not (tmp_path / "logs").exists() + + +def test_separate_runs_get_distinct_files(tmp_path): + cfg = _cfg(tmp_path) + paths = [] + for _ in range(2): + with open_run_log(cfg) as (log, path): + log.info("x") + paths.append(path) + time.sleep(0.003) # ensure the ms-precision timestamp differs + assert paths[0] != paths[1]