From 8c3e00a5203adaf1d15d9bac55a9980f89b0fc10 Mon Sep 17 00:00:00 2001 From: JesseMarkowitz Date: Tue, 20 Oct 2026 10:32:20 -0400 Subject: [PATCH] fix: retry asset downloads on 5xx and recover them across runs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An asset download is two hops — mint a signed URL, then fetch the bytes — and only the first went through _make_request. The second was a bare session.request with no 5xx handling, which lost two images in the 2026-10-20 09:00 run: one to a 500 the retried first hop had already recovered from, one to a 503. Both re-downloaded cleanly an hour later (106 KB and 1.3 MB), so the bytes were there all along. A third asset timed out and aborted its whole conversation. curl_cffi's RequestException subclasses OSError, so the un-wrapped timeout slipped past resolve_media's except ProviderError into the export loop's except OSError and was reported as "File write failed for conversation 6a945155" — a conversation that had already downloaded ~20 images. Nothing was wrong with any file write. The retry loop is factored out of _make_request into _send_with_retries, which returns the raw response so a bytes caller gets the same handling as a JSON one. Hop 2 goes through it: 5xx retried, Retry-After honoured, timeouts surfacing as ProviderError for resolve_media to placeholder. The hop is now logged, which it never was. Assets get their own ladder — an immediate retry, then ~2/4/8/16s with jitter kept, since a storage incident fails many assets at once — bounded by a per-asset wall-clock budget, because the timeout case costs 40s a go. Beyond the retry: - Transient failures (5xx, timeout, network) are recorded as pending_media so a later run re-fetches just that asset; capped at 3 runs. 404/403 stay permanent — settled 2026-08-17 for 19 assets. - A circuit breaker stops downloads after 5 consecutive transient failures, recording the rest as retryable. Permanent failures never trip it; any success resets the streak. - Media failures now appear in the set ids. The run that lost two assets pushed a clean "OK". Keeps FUTURE.md's per-conversation cache reset correctly closed. The README split (FUTURE.md §2) stays otial enough to justify breaking every anchor link. 37 new tests (414 passing). Verified live: both lost assets recovered, doctor green, a read-only chatgpt dns. The cross-run retry and breaker are unit-tested only. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/cwa7qnGp Claude-Session: https://claude.ai/code/session_012gCWSknsWvhLnMFwa7qnGp --- CHANGELOG.md | 29 +++++ README.md | 50 ++++++++- src/cache.py | 43 +++++++ src/main.py | 17 ++- src/media.py | 144 +++++++++++++++++++++--- src/notify.py | 8 ++ src/providers/base.py | 168 ++++++++++++++++++++++------ src/providers/chatgpt.py | 33 +++++- tests/test_cache.py | 94 ++++++++++++++++ tests/test_cli.py | 63 +++++++++++ tests/test_media.py | 169 +++++++++++++++++++++++++++- tests/test_providers.py | 235 +++++++++++++++++++++++++++++++++++++++ 12 files changed, 990 insertions(+), 63 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1923ffd..63aa889 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,35 @@ Format follows [Keep a Changelog](https://keepachangelog.com/en/1.0.0/). ## [Unreleased] ### Fixed +- **A transient 5xx on an image download lost the image permanently, and a timeout lost the whole conversation.** An asset download is two hops: `GET /files/{id}/download` mints a signed URL, then that URL is fetched for the bytes. Only the first went through `_make_request`. The second was a bare `session.request` with no 5xx handling at all, which produced two distinct failures in the 2026-10-20 09:00 run: + + ``` + 09:04:05 .../files//download → 500 Retry 1/3 in 2.2s + 09:04:17 → 500 Retry 2/3 in 4.3s + 09:04:32 → 500 Retry 3/3 in 9.1s + 09:04:42 → 200 ← hop 1 recovered on attempt 4 + 09:04:47 WARNING Signed URL returned HTTP 500 ← hop 2, one try, gone + ``` + + Hop 1 was patiently retried and won; hop 2 failed once and gave up. A second asset was lost the same way to a **503**, so this was never specific to 500. Both assets downloaded cleanly on 2026-10-20 at 10:00 — 106 KB and 1.3 MB — confirming the bytes were there all along and only the retry policy lost them. + + Worse, a third asset **timed out**, and that aborted the entire conversation. `curl_cffi`'s `RequestException` subclasses `OSError`, so an un-wrapped timeout on hop 2 slipped past `resolve_media`'s `except ProviderError` and was caught by the export loop's `except OSError`, which reported it as **"File write failed for conversation 6a945155"** — a conversation that had already downloaded ~20 images. Nothing was wrong with any file write. The design intent in `media.py` ("Failures keep placeholders; never fatal") was bypassed because the exception took a path nobody had anticipated. + + The retry loop is now factored out of `_make_request` into `_send_with_retries`, which returns the raw response so a caller wanting **bytes** gets identical handling to one wanting JSON. Hop 2 goes through it, which fixes both bugs at once: 5xx is retried, `Retry-After` is honoured, and a timeout arrives as `ProviderError` — which `resolve_media` already knows how to placeholder. The hop is also now logged, which it never was; its absence from the log is what made this take a debug run to find. `_pace()` is no longer called by hand there, because `_send_with_retries` paces every attempt — pacing twice would have added `REQUEST_DELAY` to all 88 assets in that run. + + Assets get a more patient ladder than the conversation API, since they fail for their own reasons: an immediate retry (free, and a single bad backend node is the commonest shape of a transient 5xx), then ~2/4/8/16s with jitter. **Jitter is deliberately kept** rather than using fixed steps — a storage incident fails many assets at once, and un-jittered retries would hit a recovering backend in lockstep. The ladder is bounded by a wall-clock budget per asset, and the final attempt's read timeout is clamped to what remains, because the timeout case costs 40s a go and six unbounded attempts of it would eat a scheduled run's execution window (two hours, per the Windows task definition). + +### Added +- **Transiently failed assets are re-attempted on later runs.** Previously `mark_exported` ran regardless, so a conversation whose image 500'd was "up to date" forever and the image was unrecoverable without hand-editing the manifest. Failures are now split by whether retrying can possibly help: `expired-or-missing` (404) and `forbidden` (403) are permanent — that was settled exhaustively on 2026-08-17 for 19 assets whose bytes OpenAI lost in a Library migration — while 5xx, timeouts and network blips are transient. Transient refs are recorded against the conversation as `pending_media`, which makes `is_cached` treat it as stale so the next run re-fetches them. Re-exporting is cheap: media already on disk is reused and Joplin resource IDs are keyed by path, so only the missing asset is fetched and only the new resource uploaded. Capped at 3 runs (`MAX_MEDIA_RETRY_RUNS`), because an asset that 5xxs every morning would otherwise re-export and re-sync its conversation forever — one of today's conversations took 3m15s and 50 resource uploads. The refs are kept after the cap as a record of what was lost. + + This leaves the "per-conversation cache reset" item in `FUTURE.md` correctly closed: the case that would have motivated it — recovering one conversation after a transient asset failure — now heals itself, and the documented workaround (edit the manifest) still covers the rest. +- **A media circuit breaker, so a bad day at the provider costs one quiet morning.** Five consecutive *transient* asset failures stop downloads for the remainder of the run; the skipped assets are recorded as retryable rather than abandoned, so the next run collects them. Permanent failures never count toward tripping it — a deleted upload says nothing about the provider's health, and this archive holds 19 of those that would otherwise trip it on a perfectly healthy server. Any success resets the streak, so ordinary scattered losses never trip it either. Assets already on disk are still linked while the breaker is open, since that needs no network. +- **Media failures appear in the push notification.** `format_summary` now adds `N media failed` per provider. The 2026-10-20 run lost two assets and pushed a clean "AI archive OK" with no hint of it — the counts existed only in the log file, which is somewhere you have to think to go and look. Counts only, never asset ids, for the same reason conversation titles are excluded: a topic on public ntfy.sh is readable by anyone who knows its name. Media failures deliberately do **not** raise the notification's priority or mark the run failed — the transcript is archived and a transient asset recovers by itself. + +### Notes +- **`FUTURE.md` §2 (split the README) is still open and was deliberately not done here.** It asks to be folded into "the next substantial README edit", and this edit is a new subsection plus two cross-references — not substantial enough to justify breaking every existing link into a README anchor. The new material is written to survive the split: it lives under *Embedded images and media*, which that plan assigns to `docs/troubleshooting.md`. +- Verified live rather than only in tests: the two assets lost in the morning run were re-downloaded successfully through the new path (`doctor` all green, 409 tests passing, a read-only `export --dry-run --provider chatgpt` exercising the refactored request core across 4 listing pages / 379 conversations). The cross-run retry and the breaker are covered by unit tests only — reproducing a multi-day storage incident against the live provider is not something this change waited for. + - **Every scheduled Claude Code sync since 2026-09-24 died with `RecursionError`.** Claude Code's `fork` subagents write a transcript that opens with a copy of the parent turn that spawned them — the fork's own `Agent` call included. `_extract_messages` folds a subagent inline whenever it meets its spawn call, so it met that copy inside the fork, folded the same fork again, and recursed until Python's limit. One fork anywhere in `~/.claude/projects` was enough to fail the whole provider; seven existed across three sessions, and the Codex half of the run, unaffected, hid the cause behind a generic exit 1. The recursive pass now carries the spawn ids being expanded around it and skips a tool_use whose id is among them — the enclosing subagent block already stands for that call. Because the set accumulates, a longer cycle (A spawns B, whose transcript re-spawns A) stops too. The fork's `` preamble — generic worker rules the harness prepends — is now stripped with the other harness tags, so a fork block opens with its actual directive. diff --git a/README.md b/README.md index bba0a48..cd26109 100644 --- a/README.md +++ b/README.md @@ -807,8 +807,19 @@ On every `joplin` run: **This design makes every run inherently resumable.** If the tool is interrupted for any reason — rate limit, network drop, Ctrl+C, crash — simply re-run the same command. It will skip already-processed conversations and continue from where it stopped. +A conversation whose assets failed transiently also carries `pending_media` (the +asset refs still missing) and `pending_media_attempts`. While `pending_media` is +set and the attempt cap is not reached, step 2 treats the conversation as stale +so the next run re-fetches those assets — see +[Embedded images and media](#embedded-images-and-media). A run that recovers them +clears the key. + To force a full re-export: `ai-chat-exporter cache --clear` then re-run export. +To re-export a single conversation, delete its entry from `cache/manifest.json` +and re-run. (There is deliberately no `cache --reset --conversation` flag; see +`FUTURE.md`.) + --- ## Troubleshooting @@ -823,6 +834,12 @@ Note: neither token's expiry can be read client-side. Claude's `sessionKey` is a ### `429 Rate Limited` The tool automatically pauses, saves progress, and exits with a clear message showing how many conversations were exported vs remaining. Just re-run the same export command to resume — the cache picks up exactly where it left off. +### `HTTP 500` / `503` on an asset download +The provider's asset storage, not your setup. Retries and the cross-run recovery +described in [Embedded images and media](#embedded-images-and-media) handle this; +the run reports `media failed` and the next run re-fetches. Measured 2026-10-20: +two assets lost this way to a 500 and a 503 both downloaded cleanly an hour later. + ### Joplin: "JOPLIN_API_TOKEN is not set" You need to configure the token before running the `joplin` command: 1. Open Joplin desktop @@ -855,7 +872,38 @@ The provider's internal API may have changed. Run with `--debug`, sanitize the o Since v0.4.0, rich content is preserved as typed blocks in the export. ChatGPT voice transcripts render as text and audio assets as `📎 File attached` placeholders with size and duration metadata. Anything the extractor doesn't recognise renders as a visible `> ⚠️ Unsupported content` block naming the type and observed keys, *and* increments a counter in the post-export summary so you can tell whether real content is being silently skipped. ### Embedded images and media -Since v0.6.0, image attachments are downloaded by default into a `media/` folder beside each export and inlined as `![](media/…)`. Audio and other files download only with `EXPORTER_DOWNLOAD_MEDIA=all`. On the next `joplin` run these are uploaded as Joplin resources so they render inside the note. Assets that have expired on the provider's side (older AI-generated images often do) keep their text placeholder and are tallied as `media failed` in the run summary — they're never fatal to the export. Set `EXPORTER_DOWNLOAD_MEDIA=off` to skip downloads entirely. +Since v0.6.0, image attachments are downloaded by default into a `media/` folder beside each export and inlined as `![](media/…)`. Audio and other files download only with `EXPORTER_DOWNLOAD_MEDIA=all`. On the next `joplin` run these are uploaded as Joplin resources so they render inside the note. Set `EXPORTER_DOWNLOAD_MEDIA=off` to skip downloads entirely. + +A failed asset **never fails the export** — the conversation is archived with its +text placeholder, and the failure is tallied as `media failed` in the run summary +and in the push notification. What happens next depends on *why* it failed: + +| Bucket | Meaning | Retried? | +|---|---|---| +| `expired-or-missing` | 404 — the upload was deleted server-side | No. The bytes are gone. | +| `forbidden` | 403 — metadata survives, bytes do not (see the 2026-08-17 investigation in `CHANGELOG.md`) | No. | +| `download-error` | 5xx, a timeout, a network blip | **Yes** — within the run, then on up to 3 later runs | +| `skipped-provider-unwell` | the run's circuit breaker was open | **Yes**, on a later run | +| `unparseable-ref` / `write-error` | local problem, not the provider's | No | + +**Within a run**, an asset download is two requests — one for a signed URL, one +for the bytes — and each is retried on a 5xx: immediately once, then after about +2, 4, 8 and 16 seconds with jitter, honouring `Retry-After` when the server sends +one. Retries for a single asset are capped by a wall-clock budget so a hanging +endpoint cannot consume the run's whole execution window. + +**Across runs**, an asset that failed transiently is recorded against its +conversation in the cache manifest, and the next run re-exports that conversation +to re-fetch it. Only the missing asset is fetched — media already on disk is +reused, and Joplin resource IDs are keyed by path, so the re-sync uploads just +the new file. After 3 unsuccessful runs the asset is treated as lost and the +conversation stops being re-exported. + +**Circuit breaker.** If 5 transient failures land back to back, asset downloads +stop for the rest of the run and the remaining assets are recorded for a later +attempt. A provider's storage having a bad day should cost one quiet morning, not +a run that overruns its two-hour scheduled window. Permanent failures never count +toward this — a deleted upload says nothing about the provider's health. ### Tool output / hidden context collapsed Since v0.6.0, content that was invisible in the ChatGPT web UI is collapsed by default to one-line placeholders like `> 🔧 Tool output — file_search (15.0 KB) — omitted`. This is ChatGPT's file-retrieval tool re-injecting your attached files on every run — it can be 90% of a conversation's bytes while containing none of the dialogue. Custom Instructions collapse the same way (`> ℹ️ Hidden context`). The post-export summary lists every collapsed message by origin with the total KB omitted. To keep everything, set `EXPORTER_HIDDEN_CONTENT=full` in `.env` or pass `--hidden-content full`. diff --git a/src/cache.py b/src/cache.py index 387a2b3..1c8dd0b 100644 --- a/src/cache.py +++ b/src/cache.py @@ -10,6 +10,12 @@ from typing import Any logger = logging.getLogger(__name__) +# How many runs may re-export a conversation to re-fetch a transiently failed +# asset before giving up on it. Three mornings is enough to ride out a storage +# incident; past that the asset is treated as lost and the conversation stops +# being re-exported (the record of which assets were lost is kept). +MAX_MEDIA_RETRY_RUNS = 3 + MANIFEST_VERSION = 1 @@ -57,6 +63,33 @@ class Cache: logger.debug("[cache] MISS %s/%s", provider, conv_id[:8]) return False + # Assets the provider fumbled transiently (a 5xx or timeout on the + # signed URL) are worth asking for again: the conversation itself is + # up to date, but it is missing bytes that almost certainly still + # exist. Re-exporting is cheap — media already on disk is reused and + # Joplin resources are keyed by path — so only the missing asset is + # fetched. Capped, because an asset that fails this way every single + # day would otherwise re-export and re-sync its conversation forever. + pending = entry.get("pending_media") + if pending: + attempts = int(entry.get("pending_media_attempts") or 0) + if attempts <= MAX_MEDIA_RETRY_RUNS: + logger.debug( + "[cache] RETRY-MEDIA %s/%s (%d asset(s), retry %d/%d)", + provider, + conv_id[:8], + len(pending), + attempts, + MAX_MEDIA_RETRY_RUNS, + ) + return False + logger.debug( + "[cache] HIT (media retries exhausted) %s/%s — %d asset(s) lost", + provider, + conv_id[:8], + len(pending), + ) + cached_updated = entry.get("updated_at", "") if not cached_updated or not updated_at: logger.debug("[cache] HIT (no date comparison) %s/%s", provider, conv_id[:8]) @@ -102,6 +135,16 @@ class Cache: if carried in prev: entry[carried] = prev[carried] + # Assets that failed transiently this run. Deliberately NOT carried + # forward from `prev`: a run that resolved them must clear the flag, + # which is what makes "pending" mean "still missing" rather than + # "was missing once". The attempt counter does carry, so repeated + # failure eventually stops costing a daily re-export. + pending = [str(r) for r in (metadata.get("pending_media") or [])] + if pending: + entry["pending_media"] = pending + entry["pending_media_attempts"] = int(prev.get("pending_media_attempts") or 0) + 1 + self._data[provider][conv_id] = entry self._data["last_run"] = datetime.now(tz=timezone.utc).isoformat() self._save() diff --git a/src/main.py b/src/main.py index 62cc3f9..2173cb2 100644 --- a/src/main.py +++ b/src/main.py @@ -872,8 +872,13 @@ def export( # Single LossReport tracks data-loss visibility across all providers in this run. loss_report = LossReport() + # One breaker for the whole run: a provider's asset storage being unwell is + # a run-level fact, not a per-conversation one. + from src.media import MediaCircuit + media_circuit = MediaCircuit() + for prov_name, prov_instance in providers_to_run: - summary[prov_name] = {"exported": 0, "skipped": 0, "failed": 0} + summary[prov_name] = {"exported": 0, "skipped": 0, "failed": 0, "media_failed": 0} console.print(f"\n[bold cyan][{prov_name.upper()}][/bold cyan] Fetching conversation list…") @@ -958,16 +963,19 @@ def export( # Download assets (images by default) so the renderers # can inline them. Failures keep placeholders; never fatal. + from src.media import MediaOutcome, resolve_media + media_outcome = MediaOutcome() if cfg.download_media != "off": - from src.media import resolve_media - resolve_media( + media_outcome = resolve_media( normalized, prov_instance, export_base, structure, cfg.download_media, loss_report, + circuit=media_circuit, ) + summary[prov_name]["media_failed"] += media_outcome.failed exported_path: Path | None = None if md_exporter: @@ -982,6 +990,9 @@ def export( "created_at": normalized.get("created_at", ""), "updated_at": normalized.get("updated_at", ""), "file_path": str(exported_path) if exported_path else "", + # Empty clears the flag, so a run that recovered the + # asset stops the conversation being re-exported. + "pending_media": media_outcome.retryable_refs, }) summary[prov_name]["exported"] += 1 progress.advance(task) diff --git a/src/media.py b/src/media.py index 4f07911..11a0acb 100644 --- a/src/media.py +++ b/src/media.py @@ -12,13 +12,28 @@ Policy (``EXPORTER_DOWNLOAD_MEDIA``): are already in the exports as text) off — leave placeholders untouched -Failures (expired assets, network) keep the existing placeholder and are -counted in the run summary — never fatal to the export. +Failures keep the existing placeholder and are counted in the run summary — +never fatal to the export. They split two ways, and the split is what decides +whether the asset is ever seen again: + + permanent — ``expired-or-missing`` (404) and ``forbidden`` (403). The bytes + are gone server-side; retrying achieves nothing. Investigated + exhaustively 2026-08-17, see ``_classify_failure``. + transient — everything else: a 5xx from the signed URL, a timeout, a + network blip. The asset almost certainly still exists, so its + ref is handed back for the cache to remember and the next + scheduled run re-attempts it. + +A run also carries a ``MediaCircuit``: once enough *transient* failures land +back to back, asset downloads stop for the rest of the run. A storage incident +fails every asset in the archive, and a patient retry ladder times that many +failures over is how a scheduled run exceeds its execution window. """ import logging import os import tempfile +from dataclasses import dataclass, field from pathlib import Path from src.blocks import BLOCK_TYPE_FILE_PLACEHOLDER, BLOCK_TYPE_IMAGE_PLACEHOLDER @@ -33,6 +48,19 @@ MEDIA_ALL = "all" MEDIA_OFF = "off" VALID_MEDIA_POLICIES = {MEDIA_IMAGES, MEDIA_ALL, MEDIA_OFF} +# Failure buckets whose asset is worth asking for again on a later run. The +# permanent buckets are deliberately excluded: this archive holds 19 assets +# whose bytes OpenAI lost in a 2026-07-14 Library migration, and retrying +# those every morning forever would be pure noise — and would trip the +# circuit breaker below on a server that is perfectly healthy. +TRANSIENT_FAILURE_BUCKETS = frozenset({"download-error"}) + +# Consecutive transient failures before asset downloads stop for this run. +MEDIA_CIRCUIT_THRESHOLD = 5 + +# Bucket recorded for assets skipped because the breaker had already tripped. +CIRCUIT_OPEN_BUCKET = "skipped-provider-unwell" + _EXT_BY_MIME = { "image/png": ".png", "image/jpeg": ".jpg", @@ -62,6 +90,64 @@ def resolve_media_policy() -> str: return value +@dataclass +class MediaOutcome: + """What one conversation's media pass achieved. + + ``retryable_refs`` is the part that matters beyond the summary line: the + caller records it against the conversation in the cache manifest, which is + what lets a later run re-attempt an asset the provider fumbled. Without + it a transient 5xx lost the asset permanently, because the conversation was + marked exported and never looked at again. + """ + + downloaded: int = 0 + failed: int = 0 + retryable_refs: list[str] = field(default_factory=list) + + +class MediaCircuit: + """Run-scoped breaker that stops asset downloads when the provider is unwell. + + One run-level object, shared by every conversation in the run. Counts + *consecutive transient* failures: a permanent failure (a deleted upload) + says nothing about the provider's health and must not trip it, and any + success resets the count, so ordinary scattered losses never trip it either. + + Once tripped it stays tripped for the run. The alternative — keep trying + every asset through a storage incident — is what pushes a scheduled run + past its execution window (two hours, in the Windows task definition). + Assets skipped while open are still reported as retryable, so the next run + picks them up rather than losing them. + """ + + def __init__(self, threshold: int = MEDIA_CIRCUIT_THRESHOLD) -> None: + self.threshold = threshold + self.consecutive = 0 + self.tripped = False + self.skipped = 0 + + def record_success(self) -> None: + self.consecutive = 0 + + def record_failure(self, bucket: str) -> None: + """Count a failure; only transient ones count toward tripping.""" + if bucket not in TRANSIENT_FAILURE_BUCKETS: + return + self.consecutive += 1 + if not self.tripped and self.consecutive >= self.threshold: + self.tripped = True + logger.error( + "[media] %d consecutive transient asset failures — skipping " + "further downloads this run. Affected assets are recorded and " + "will be re-attempted on the next run.", + self.consecutive, + ) + + def record_skip(self) -> None: + self.skipped += 1 + + def resolve_media( normalized: dict, provider, @@ -69,19 +155,28 @@ def resolve_media( structure: str, policy: str, report: LossReport, -) -> int: - """Download assets for one normalized conversation. Returns download count. + circuit: "MediaCircuit | None" = None, +) -> MediaOutcome: + """Download assets for one normalized conversation. Mutates placeholder blocks in place (adds ``local_path``). Idempotent: - an asset already on disk is annotated without an API call. + an asset already on disk is annotated without an API call, which is also + what makes a re-export cheap when only one asset needs re-fetching. + + Returns: + A ``MediaOutcome``. ``retryable_refs`` is non-empty when an asset + failed transiently (or was skipped by an open circuit) and should be + re-attempted on a later run. """ + outcome = MediaOutcome() + if policy == MEDIA_OFF: - return 0 + return outcome download = getattr(provider, "download_asset", None) if download is None: # Provider has no remote assets (e.g. claude-code local transcripts). - return 0 + return outcome wanted_types = {BLOCK_TYPE_IMAGE_PLACEHOLDER} if policy == MEDIA_ALL: @@ -94,7 +189,7 @@ def resolve_media( if block.get("type") in wanted_types and block.get("ref") ] if not targets: - return 0 + return outcome # Same path computation the exporter uses, so media/ lands beside the .md. filename = generate_filename( @@ -112,12 +207,12 @@ def resolve_media( ).parent media_dir = conv_dir / "media" - downloaded = 0 for block in targets: ref = block["ref"] file_id = _safe_asset_name(provider, ref) if not file_id: report.record_media_failed("unparseable-ref") + outcome.failed += 1 continue existing = _find_existing(media_dir, file_id) @@ -125,13 +220,32 @@ def resolve_media( block["local_path"] = f"media/{existing.name}" continue + # Breaker open: do not touch the network, but keep the ref so the + # asset is re-attempted rather than silently abandoned. + if circuit is not None and circuit.tripped: + circuit.record_skip() + report.record_media_failed(CIRCUIT_OPEN_BUCKET) + outcome.failed += 1 + outcome.retryable_refs.append(ref) + continue + try: content, mime, file_name = download(ref) except ProviderError as e: + bucket = _classify_failure(e) logger.warning( - "[media] Could not download %s: %s", ref[:60], e.original + "[media] Could not download %s: %s (%s%s)", + ref[:60], + e.original, + bucket, + ", will retry next run" if bucket in TRANSIENT_FAILURE_BUCKETS else "", ) - report.record_media_failed(_classify_failure(e)) + report.record_media_failed(bucket) + outcome.failed += 1 + if bucket in TRANSIENT_FAILURE_BUCKETS: + outcome.retryable_refs.append(ref) + if circuit is not None: + circuit.record_failure(bucket) continue ext = _pick_extension(mime, file_name) @@ -141,13 +255,17 @@ def resolve_media( except OSError as e: logger.error("[media] Could not write %s: %s", target, e) report.record_media_failed("write-error") + outcome.failed += 1 continue block["local_path"] = f"media/{target.name}" report.record_media_downloaded(len(content)) - downloaded += 1 + outcome.downloaded += 1 + if circuit is not None: + circuit.record_success() + + return outcome - return downloaded def _classify_failure(error: ProviderError) -> str: diff --git a/src/notify.py b/src/notify.py index b8a4ed9..abde5ec 100644 --- a/src/notify.py +++ b/src/notify.py @@ -148,10 +148,18 @@ def format_summary( exported = counts.get("exported", 0) skipped = counts.get("skipped", 0) failed = counts.get("failed", 0) + media_failed = counts.get("media_failed", 0) total_exported += exported line = f"{prov}: {exported} exported, {skipped} up to date" if failed: line += f", {failed} FAILED" + # Media failures do not fail the run — the transcript is archived and a + # transient asset is re-attempted on a later run — but they were + # invisible here until 2026-10-20, when two assets were lost in a run + # that pushed a clean result. A count is enough to prompt a log check; + # asset ids stay out, like conversation titles (see module docstring). + if media_failed: + line += f", {media_failed} media failed" lines.append(line) synced = sum( diff --git a/src/providers/base.py b/src/providers/base.py index 820880b..ccebb7d 100644 --- a/src/providers/base.py +++ b/src/providers/base.py @@ -41,6 +41,19 @@ MAX_RETRIES = 3 BACKOFF_BASE = 2.0 BACKOFF_MAX = 60.0 +# Asset (media) download retry policy. The asset endpoints flake independently +# of the conversation API: measured 2026-10-20 in one scheduled run, a signed +# URL returned 500 on one image and 503 on another, while the metadata hop for +# the same assets succeeded. They therefore get a more patient ladder than the +# conversation API — an immediate retry, then ~2/4/8/16s with jitter — bounded +# by a wall-clock budget, because the other failure mode is a 40s timeout and +# an unbounded ladder over those would eat a scheduled run's whole window. +MEDIA_MAX_RETRIES = 5 +MEDIA_TIME_BUDGET = 60.0 +# Shorter read timeout than REQUEST_TIMEOUT: an asset that has not started +# sending bytes in 20s is not about to, and the budget has retries to fund. +MEDIA_REQUEST_TIMEOUT = (10, 20) + # EXPORTER_HIDDEN_CONTENT policy — what to do with content that was invisible # in the provider's UI (retrieval dumps, hidden-flagged context, agent tool # traffic). Shared by all providers. @@ -316,36 +329,73 @@ class BaseProvider(ABC): return all_convs - def _make_request( + def _send_with_retries( self, method: str, url: str, - debug_log_body: bool = False, + max_retries: int | None = None, + immediate_first_retry: bool = False, + time_budget: float | None = None, **kwargs: Any, - ) -> dict | list: - """Make an authenticated HTTP request with retry logic and unified error handling. + ) -> Any: + """Send one request with retry/backoff, returning the raw response. + + The transport half of ``_make_request``, split out so callers that want + **bytes** rather than JSON get identical retry behaviour. Before this + existed, the signed-URL hop of an asset download was a bare + ``session.request`` with no 5xx retry at all, and its timeouts escaped + as ``OSError`` (curl_cffi's ``RequestException`` subclasses it) to be + mis-reported by the export loop as "File write failed". Args: method: HTTP method ("GET", "POST", etc.) url: Full URL. - debug_log_body: If True, log redacted response body at DEBUG level. + max_retries: Retry ceiling; defaults to ``MAX_RETRIES``. + immediate_first_retry: Retry a 5xx once with no wait before backing + off. A single bad backend node is the most common shape of a + transient 5xx, and a zero-cost retry catches it. + time_budget: Seconds after which no further attempt starts. The last + attempt's read timeout is clamped to what remains, so the real + bound is the budget plus the connect timeout. Used to keep an + endpoint that is timing out (40s a go, measured 2026-10-20) from + consuming a scheduled run's whole execution window. **kwargs: Passed to requests.Session.request(). Returns: - Parsed JSON response body. + The response object, for the caller to read as JSON or bytes. Raises: ProviderError: On an authentication failure, exhausted retries, or unrecoverable errors. """ + ceiling = MAX_RETRIES if max_retries is None else max_retries kwargs.setdefault("timeout", REQUEST_TIMEOUT) + base_timeout = kwargs["timeout"] + started = time.monotonic() + + def _remaining() -> float | None: + if time_budget is None: + return None + return time_budget - (time.monotonic() - started) + + def _budget_exhausted(wait: float = 0.0) -> bool: + left = _remaining() + return left is not None and left - wait <= 0 attempt = 0 last_exc: Exception | None = None - while attempt <= MAX_RETRIES: + while attempt <= ceiling: attempt += 1 self._pace() + + # Clamp the read timeout to the remaining budget so the final + # attempt cannot overrun it by a whole timeout period. + left = _remaining() + if left is not None and isinstance(base_timeout, tuple): + connect_to, read_to = base_timeout + kwargs["timeout"] = (connect_to, max(1.0, min(read_to, left))) + start = time.monotonic() try: @@ -362,7 +412,7 @@ class BaseProvider(ABC): elapsed_ms, ) - # ── Auth failure: token expired / invalid ───────────────── + # ── Auth failure: token expired / invalid ────────────────── # Not keyed on 401 alone: a provider is free to answer an # invalid session with some other status, and claude.ai does # (403). Ask the provider rather than assuming. @@ -379,18 +429,18 @@ class BaseProvider(ABC): # ── 429: rate limited ────────────────────────────────────── if response.status_code == 429: - if attempt > MAX_RETRIES: + wait = self._backoff_wait(response, attempt) + if attempt > ceiling or _budget_exhausted(wait): raise ProviderError( self.provider_name, f"{method} {url}", RuntimeError("429 Rate Limited — max retries exhausted"), ) - wait = self._backoff_wait(response, attempt) logger.warning( "[%s] Rate limited. Retry %d/%d in %.1fs", self.provider_name, attempt, - MAX_RETRIES, + ceiling, wait, ) time.sleep(wait) @@ -398,24 +448,27 @@ class BaseProvider(ABC): # ── 5xx: server error ────────────────────────────────────── if response.status_code >= 500: - if attempt > MAX_RETRIES: + wait = self._backoff_wait( + response, attempt, immediate_first=immediate_first_retry + ) + if attempt > ceiling or _budget_exhausted(wait): raise ProviderError( self.provider_name, f"{method} {url}", RuntimeError( - f"HTTP {response.status_code} after {MAX_RETRIES} retries" + f"HTTP {response.status_code} after {attempt - 1} retries" ), ) - wait = self._backoff_wait(None, attempt) logger.warning( "[%s] HTTP %d. Retry %d/%d in %.1fs", self.provider_name, response.status_code, attempt, - MAX_RETRIES, + ceiling, wait, ) - time.sleep(wait) + if wait: + time.sleep(wait) continue # ── Other HTTP errors ────────────────────────────────────── @@ -433,42 +486,33 @@ class BaseProvider(ABC): ), ) - # ── Success ──────────────────────────────────────────────── - body = response.json() - - if debug_log_body: - logger.debug( - "[%s] Response body (redacted): %s", - self.provider_name, - redact_secrets(body), - ) - - return body + return response except ProviderError: raise except (requests.ConnectionError, requests.Timeout, _CurlConnectionError, _CurlTimeout) as e: last_exc = e - if attempt > MAX_RETRIES: + wait = self._backoff_wait(None, attempt, immediate_first=immediate_first_retry) + if attempt > ceiling or _budget_exhausted(wait): raise ProviderError( self.provider_name, f"{method} {url}", RuntimeError( - f"Network error after {MAX_RETRIES} retries: {e}. " + f"Network error after {attempt - 1} retries: {e}. " "Check your internet connection." ), ) from e - wait = self._backoff_wait(None, attempt) logger.warning( "[%s] Network error (attempt %d/%d): %s. Retrying in %.1fs", self.provider_name, attempt, - MAX_RETRIES, + ceiling, e, wait, ) - time.sleep(wait) + if wait: + time.sleep(wait) except (requests.HTTPError, _CurlHTTPError) as e: raise ProviderError( @@ -482,6 +526,43 @@ class BaseProvider(ABC): last_exc or RuntimeError("Unknown error"), ) + def _make_request( + self, + method: str, + url: str, + debug_log_body: bool = False, + **kwargs: Any, + ) -> dict | list: + """Make an authenticated HTTP request and return its parsed JSON body. + + Retry, backoff and error handling live in ``_send_with_retries``; this + adds JSON parsing and optional body logging. + + Args: + method: HTTP method ("GET", "POST", etc.) + url: Full URL. + debug_log_body: If True, log redacted response body at DEBUG level. + **kwargs: Passed through (see ``_send_with_retries``). + + Returns: + Parsed JSON response body. + + Raises: + ProviderError: On an authentication failure, exhausted retries, or + unrecoverable errors. + """ + response = self._send_with_retries(method, url, **kwargs) + body = response.json() + + if debug_log_body: + logger.debug( + "[%s] Response body (redacted): %s", + self.provider_name, + redact_secrets(body), + ) + + return body + def _is_auth_failure(self, response: Any) -> bool: """Whether this response means the stored credential is not valid. @@ -511,8 +592,22 @@ class BaseProvider(ABC): ) @staticmethod - def _backoff_wait(response: requests.Response | None, attempt: int) -> float: - """Compute exponential backoff with jitter.""" + def _backoff_wait( + response: requests.Response | None, + attempt: int, + immediate_first: bool = False, + ) -> float: + """Compute exponential backoff with jitter. + + ``Retry-After`` wins when the server sends one — including ahead of an + immediate retry, because a server naming a time knows better than we do + (503s commonly carry it). + + ``immediate_first`` makes the first retry free and shifts the ladder + down one step, giving 0, 2, 4, 8, 16s rather than 2, 4, 8, 16, 32s. + Jitter is never dropped: a storage incident fails many assets at once, + and un-jittered retries would hit a recovering backend in lockstep. + """ if response is not None: retry_after = response.headers.get("Retry-After") if retry_after: @@ -520,7 +615,10 @@ class BaseProvider(ABC): return float(retry_after) except ValueError: pass - base = min(BACKOFF_BASE ** attempt, BACKOFF_MAX) + if immediate_first and attempt <= 1: + return 0.0 + exponent = attempt - 1 if immediate_first else attempt + base = min(BACKOFF_BASE ** exponent, BACKOFF_MAX) jitter = random.uniform(0, base * 0.3) return base + jitter diff --git a/src/providers/chatgpt.py b/src/providers/chatgpt.py index 8222a94..32bfbef 100644 --- a/src/providers/chatgpt.py +++ b/src/providers/chatgpt.py @@ -51,6 +51,9 @@ from src.providers.base import ( HIDDEN_CONTENT_FULL, HIDDEN_CONTENT_OMIT, HIDDEN_CONTENT_PLACEHOLDER, + MEDIA_MAX_RETRIES, + MEDIA_REQUEST_TIMEOUT, + MEDIA_TIME_BUDGET, ProviderError, REQUEST_TIMEOUT, VALID_HIDDEN_CONTENT_POLICIES, @@ -764,14 +767,34 @@ class ChatGPTProvider(BaseProvider): RuntimeError(f"No download_url in response: {meta.get('detail') or meta}"), ) - self._pace() - resp = self._session.request("GET", download_url, timeout=REQUEST_TIMEOUT) - if resp.status_code != 200: + # The signed URL is a second hop that flakes on its own account. + # Measured 2026-10-20 in one scheduled run: a 500 here *after* the + # metadata hop had recovered on its 4th try, and a 503 on a different + # asset whose metadata hop was clean first time. It therefore goes + # through the shared retry path rather than being a bare request — + # which also means a timeout arrives as ProviderError, so resolve_media + # placeholders the asset, instead of as the OSError that previously + # escaped and aborted the whole conversation. + # + # No _pace() here: _send_with_retries paces every attempt itself, and + # pacing twice would add REQUEST_DELAY to every asset in the archive. + try: + resp = self._send_with_retries( + "GET", + download_url, + max_retries=MEDIA_MAX_RETRIES, + immediate_first_retry=True, + time_budget=MEDIA_TIME_BUDGET, + timeout=MEDIA_REQUEST_TIMEOUT, + ) + except ProviderError as e: + # Keep "which hop" in the message: that distinction is what made + # this diagnosable, since the two hops fail for different reasons. raise ProviderError( self.provider_name, f"download_asset({file_id})", - RuntimeError(f"Signed URL returned HTTP {resp.status_code}"), - ) + RuntimeError(f"Signed URL: {e.original}"), + ) from e mime = resp.headers.get("content-type") or None file_name = meta.get("file_name") or None logger.debug( diff --git a/tests/test_cache.py b/tests/test_cache.py index 4a11507..a08bc63 100644 --- a/tests/test_cache.py +++ b/tests/test_cache.py @@ -254,3 +254,97 @@ class TestReexportPreservesJoplinLink: pending = tmp_cache.get_joplin_pending("chatgpt") assert len(pending) == 1 assert pending[0][1]["joplin_note_id"] == "note-123" + + +# --------------------------------------------------------------------------- +# Cross-run media retry. +# +# Before this, a transient asset failure was permanent: resolve_media kept a +# placeholder, mark_exported ran anyway, and the conversation was never looked +# at again. Two assets were lost that way on 2026-10-20 to a 500 and a 503 — +# both recoverable. The manifest now remembers which refs are still missing. +# --------------------------------------------------------------------------- + + +class TestPendingMediaRetry: + UPDATED = "2026-10-20T09:00:00Z" + + def test_pending_media_forces_a_re_export(self, tmp_cache): + tmp_cache.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + assert tmp_cache.is_cached("chatgpt", "conv-1", self.UPDATED) is False + + def test_no_pending_media_is_an_ordinary_hit(self, tmp_cache): + tmp_cache.mark_exported("chatgpt", "conv-1", {"updated_at": self.UPDATED}) + assert tmp_cache.is_cached("chatgpt", "conv-1", self.UPDATED) is True + + def test_a_resolved_asset_clears_the_flag(self, tmp_cache): + """The run that recovers the asset must stop the daily re-export.""" + tmp_cache.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + assert tmp_cache.is_cached("chatgpt", "conv-1", self.UPDATED) is False + + tmp_cache.mark_exported("chatgpt", "conv-1", {"updated_at": self.UPDATED}) + assert tmp_cache.is_cached("chatgpt", "conv-1", self.UPDATED) is True + entry = tmp_cache.get_all_entries("chatgpt")["conv-1"] + assert "pending_media" not in entry + + def test_retries_are_capped_so_it_does_not_re_export_forever(self, tmp_cache): + """An asset that 5xxs every morning must stop costing a re-export.""" + from src.cache import MAX_MEDIA_RETRY_RUNS + + for run in range(MAX_MEDIA_RETRY_RUNS): + tmp_cache.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + assert tmp_cache.is_cached("chatgpt", "conv-1", self.UPDATED) is False, ( + f"run {run + 1} should still retry" + ) + + tmp_cache.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + assert tmp_cache.is_cached("chatgpt", "conv-1", self.UPDATED) is True + + def test_the_lost_refs_are_kept_as_a_record(self, tmp_cache): + from src.cache import MAX_MEDIA_RETRY_RUNS + + for _ in range(MAX_MEDIA_RETRY_RUNS + 1): + tmp_cache.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + entry = tmp_cache.get_all_entries("chatgpt")["conv-1"] + assert entry["pending_media"] == ["sediment://file_x"] + + def test_joplin_link_survives_a_media_re_export(self, tmp_cache): + """Re-exporting to recover an asset must not orphan the Joplin note.""" + tmp_cache.mark_exported("chatgpt", "conv-1", {"updated_at": self.UPDATED}) + tmp_cache.mark_joplin_synced("chatgpt", "conv-1", "note-123") + tmp_cache.set_joplin_resources("chatgpt", "conv-1", {"media/a.png": "res-1"}) + + tmp_cache.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + entry = tmp_cache.get_all_entries("chatgpt")["conv-1"] + assert entry["joplin_note_id"] == "note-123" + # Resource ids are the idempotency record: without them the re-sync + # would re-upload every image in the note, not just the new one. + assert entry["joplin_resources"] == {"media/a.png": "res-1"} + + def test_pending_media_survives_a_manifest_round_trip(self, tmp_path): + from src.cache import Cache + + c = Cache(tmp_path) + c.mark_exported( + "chatgpt", "conv-1", + {"updated_at": self.UPDATED, "pending_media": ["sediment://file_x"]}, + ) + assert Cache(tmp_path).is_cached("chatgpt", "conv-1", self.UPDATED) is False diff --git a/tests/test_cli.py b/tests/test_cli.py index 6af4c1d..7bfdcaf 100644 --- a/tests/test_cli.py +++ b/tests/test_cli.py @@ -661,3 +661,66 @@ class TestNoRealNotificationsDuringTests: monkeypatch.setenv("NTFY_TOPIC", "some-topic") assert "127.0.0.1" in os.getenv("NTFY_SERVER", "") assert notify_mod.send("t", "m") is False + + +# --------------------------------------------------------------------------- +# Media failures in the push notification. +# +# On 2026-10-20 a scheduled run lost two assets and pushed a clean "OK" with +# no hint of it — the counts were in the log file only, which is a place you +# have to think to go and look. Counts only, never asset ids: a topic on +# public ntfy.sh is readable by anyone who knows its name. +# --------------------------------------------------------------------------- + + +class TestMediaFailuresInNotification: + def test_media_failures_appear_in_the_message(self): + from src.notify import format_summary + + _, message, _, _ = format_summary( + {"chatgpt": {"exported": 24, "skipped": 826, "failed": 0, "media_failed": 2}}, + None, + None, + ) + assert "2 media failed" in message + + def test_absent_when_there_are_none(self): + from src.notify import format_summary + + _, message, _, _ = format_summary( + {"chatgpt": {"exported": 5, "skipped": 1, "failed": 0, "media_failed": 0}}, + None, + None, + ) + assert "media failed" not in message + + def test_media_failures_alone_do_not_fail_the_run(self): + """The transcript was archived and a transient asset retries later.""" + from src.notify import format_summary + + title, _, tags, priority = format_summary( + {"chatgpt": {"exported": 1, "skipped": 0, "failed": 0, "media_failed": 3}}, + None, + None, + ) + assert title.startswith("AI archive OK") + assert priority == "default" + assert tags == "white_check_mark" + + def test_no_asset_ids_leak_into_the_payload(self): + from src.notify import format_summary + + _, message, _, _ = format_summary( + {"chatgpt": {"exported": 1, "skipped": 0, "failed": 0, "media_failed": 1}}, + None, + None, + ) + assert "sediment" not in message and "file_" not in message + + def test_older_summaries_without_the_key_still_render(self): + from src.notify import format_summary + + _, message, _, _ = format_summary( + {"codex": {"exported": 0, "skipped": 29, "failed": 0}}, None, None + ) + assert "codex: 0 exported, 29 up to date" in message diff --git a/tests/test_media.py b/tests/test_media.py index b535848..06749ff 100644 --- a/tests/test_media.py +++ b/tests/test_media.py @@ -100,7 +100,7 @@ class TestResolveMedia: n = resolve_media(conv, provider, tmp_path, "provider/project/year", "images", report) - assert n == 1 + assert n.downloaded == 1 assert report.media_downloaded == 1 assert block["local_path"] == "media/file_img1.png" rendered = render_blocks_to_markdown([block]) @@ -117,7 +117,7 @@ class TestResolveMedia: report = LossReport() n = resolve_media(conv, provider, tmp_path, "provider/project/year", "images", report) - assert n == 0 + assert n.downloaded == 0 assert "local_path" not in block assert provider.calls == [] @@ -129,7 +129,7 @@ class TestResolveMedia: report = LossReport() n = resolve_media(conv, provider, tmp_path, "provider/project/year", "all", report) - assert n == 1 + assert n.downloaded == 1 assert block["local_path"] == "media/file_audio1.wav" rendered = render_blocks_to_markdown([block]) assert "media/file_audio1.wav" in rendered and rendered.startswith("> 📎") @@ -139,7 +139,9 @@ class TestResolveMedia: block = make_image_placeholder(ref="sediment://file_x", source="user_upload") conv = _conv_with([block]) report = LossReport() - assert resolve_media(conv, provider, tmp_path, "provider/project/year", "off", report) == 0 + assert resolve_media( + conv, provider, tmp_path, "provider/project/year", "off", report + ).downloaded == 0 assert provider.calls == [] def test_idempotent_uses_disk(self, tmp_path): @@ -164,7 +166,7 @@ class TestResolveMedia: report = LossReport() n = resolve_media(conv, provider, tmp_path, "provider/project/year", "images", report) - assert n == 0 + assert n.downloaded == 0 assert "local_path" not in block assert report.media_failed["expired-or-missing"] == 1 # Still renders as a placeholder, not a broken image link @@ -192,7 +194,9 @@ class TestResolveMedia: pass block = make_image_placeholder(ref="sediment://file_x", source="user_upload") conv = _conv_with([block]) - assert resolve_media(conv, NoDownload(), tmp_path, "provider/project/year", "images", LossReport()) == 0 + assert resolve_media( + conv, NoDownload(), tmp_path, "provider/project/year", "images", LossReport() + ).downloaded == 0 # --------------------------------------------------------------------------- @@ -262,3 +266,156 @@ class TestUploadMediaAndRewrite: new_body, res_map = upload_media_and_rewrite(body, tmp_path, client, {}) assert new_body == body assert res_map == {} + + +# --------------------------------------------------------------------------- +# Transient vs permanent failures, and the cross-run retry they feed. +# +# Measured 2026-10-20 in one scheduled run: a signed URL returned 500 on one +# asset and 503 on another. Both are recoverable, yet the conversation was +# marked exported, so the assets were lost for good. Permanent failures must +# stay out of the retry set — 19 assets in this archive 403/404 because their +# bytes were lost in a 2026-07-14 Library migration, and retrying those every +# morning would be noise that also trips the circuit breaker. +# --------------------------------------------------------------------------- + + +class TestTransientFailureRetry: + def _run(self, failure, tmp_path, circuit=None): + from src.media import resolve_media + + ref = "sediment://file_x" + provider = _FakeProvider(fail_refs={ref: RuntimeError(failure)}) + conv = _conv_with([make_image_placeholder(ref, "user_upload")]) + report = LossReport() + outcome = resolve_media( + conv, provider, tmp_path, "provider/project/year", "images", report, + circuit=circuit, + ) + return outcome, report, conv + + def test_server_error_is_retryable(self, tmp_path): + outcome, report, conv = self._run("Signed URL: HTTP 500 after 5 retries", tmp_path) + assert outcome.failed == 1 + assert outcome.retryable_refs == ["sediment://file_x"] + assert report.media_failed["download-error"] == 1 + # Placeholder survives, so the ref is still in the Markdown. + assert "local_path" not in conv["messages"][0]["blocks"][0] + + def test_service_unavailable_is_retryable(self, tmp_path): + outcome, _, _ = self._run("Signed URL: HTTP 503 after 5 retries", tmp_path) + assert outcome.retryable_refs == ["sediment://file_x"] + + def test_timeout_is_retryable(self, tmp_path): + outcome, _, _ = self._run( + "Network error after 5 retries: Operation timed out", tmp_path + ) + assert outcome.retryable_refs == ["sediment://file_x"] + + def test_deleted_asset_is_not_retryable(self, tmp_path): + outcome, report, _ = self._run( + "Asset no longer exists — HTTP 404 'File not found'", tmp_path + ) + assert outcome.failed == 1 + assert outcome.retryable_refs == [] + assert report.media_failed["expired-or-missing"] == 1 + + def test_forbidden_asset_is_not_retryable(self, tmp_path): + outcome, report, _ = self._run("HTTP 403 — detail: Forbidden", tmp_path) + assert outcome.retryable_refs == [] + assert report.media_failed["forbidden"] == 1 + + def test_success_reports_nothing_retryable(self, tmp_path): + from src.media import resolve_media + + ref = "sediment://file_x" + provider = _FakeProvider(assets={ref: (b"png", "image/png", None)}) + conv = _conv_with([make_image_placeholder(ref, "user_upload")]) + outcome = resolve_media( + conv, provider, tmp_path, "provider/project/year", "images", LossReport() + ) + assert (outcome.downloaded, outcome.failed, outcome.retryable_refs) == (1, 0, []) + + +class TestMediaCircuit: + def test_trips_after_consecutive_transient_failures(self): + from src.media import MediaCircuit + + c = MediaCircuit(threshold=3) + for _ in range(2): + c.record_failure("download-error") + assert not c.tripped + c.record_failure("download-error") + assert c.tripped + + def test_success_resets_the_streak(self): + from src.media import MediaCircuit + + c = MediaCircuit(threshold=3) + c.record_failure("download-error") + c.record_failure("download-error") + c.record_success() + c.record_failure("download-error") + assert not c.tripped, "scattered failures must not trip the breaker" + + def test_permanent_failures_never_trip_it(self): + """A deleted upload says nothing about the provider's health.""" + from src.media import MediaCircuit + + c = MediaCircuit(threshold=2) + for _ in range(10): + c.record_failure("expired-or-missing") + c.record_failure("forbidden") + assert not c.tripped + + def test_open_circuit_skips_downloads_but_keeps_refs(self, tmp_path): + from src.media import CIRCUIT_OPEN_BUCKET, MediaCircuit, resolve_media + + ref = "sediment://file_y" + provider = _FakeProvider(assets={ref: (b"png", "image/png", None)}) + conv = _conv_with([make_image_placeholder(ref, "user_upload")]) + circuit = MediaCircuit(threshold=1) + circuit.record_failure("download-error") + assert circuit.tripped + + report = LossReport() + outcome = resolve_media( + conv, provider, tmp_path, "provider/project/year", "images", report, + circuit=circuit, + ) + assert provider.calls == [], "must not touch the network while open" + assert outcome.downloaded == 0 + assert outcome.retryable_refs == [ref], "skipped assets must not be abandoned" + assert report.media_failed[CIRCUIT_OPEN_BUCKET] == 1 + assert circuit.skipped == 1 + + def test_already_downloaded_asset_served_while_open(self, tmp_path): + """An open circuit must not stop on-disk media being linked.""" + from src.media import MediaCircuit, resolve_media + + ref = "sediment://file_z" + conv = _conv_with([make_image_placeholder(ref, "user_upload")]) + # Derive the directory the way the exporter does rather than + # hardcoding it — the layout is "/./". + from src.utils import build_export_path, generate_filename + + media_dir = build_export_path( + tmp_path, + "chatgpt", + None, + "2026-05-20T00:00:00+00:00", + generate_filename("Has Media", "conv-1", "2026-05-20T00:00:00+00:00"), + "provider/project/year", + ).parent / "media" + media_dir.mkdir(parents=True) + (media_dir / "file_z.png").write_bytes(b"already here") + + circuit = MediaCircuit(threshold=1) + circuit.record_failure("download-error") + provider = _FakeProvider() + resolve_media( + conv, provider, tmp_path, "provider/project/year", "images", LossReport(), + circuit=circuit, + ) + assert provider.calls == [] + assert conv["messages"][0]["blocks"][0]["local_path"] == "media/file_z.png" diff --git a/tests/test_providers.py b/tests/test_providers.py index acb9614..dfb49ae 100644 --- a/tests/test_providers.py +++ b/tests/test_providers.py @@ -1399,6 +1399,8 @@ class TestDeletedAssetReporting: """The probe costs a request — it must not fire on a good download.""" class _Bytes: status_code = 200 + ok = True + reason = "OK" content = b"data" headers = {"content-type": "image/png"} @@ -1506,3 +1508,236 @@ class TestProjectAttribution: with caplog.at_level(logging.INFO): p.normalize_conversation(self._raw(gizmo_id="g-p-known")) assert not [r for r in caplog.records if "not in CHATGPT_PROJECT_IDS" in r.message] + + +# --------------------------------------------------------------------------- +# Asset download retries. Measured 2026-10-20 in one scheduled run: +# +# 09:04:05 .../files//download → 500 Retry 1/3 in 2.2s +# 09:04:17 → 500 Retry 2/3 in 4.3s +# 09:04:32 → 500 Retry 3/3 in 9.1s +# 09:04:42 → 200 ← metadata hop recovered +# 09:04:47 WARNING Signed URL returned HTTP 500 ← second hop, no retry +# +# The metadata hop went through _make_request and won; the signed-URL hop was +# a bare request and lost on its first try. A second asset lost the same way +# to a 503, and a third timed out — and because curl_cffi's RequestException +# subclasses OSError, that timeout escaped resolve_media's `except +# ProviderError` and was reported by the export loop as "File write failed", +# aborting a conversation that had already downloaded ~20 images. +# --------------------------------------------------------------------------- + + +class TestAssetDownloadRetries: + class _Resp: + def __init__(self, status=200, payload=None, content=b"", headers=None): + self.status_code = status + self.ok = 200 <= status < 400 + self.reason = "" + self.content = content + self.text = "" + self.headers = headers or {} + self._payload = payload + + def json(self): + if self._payload is None: + raise ValueError("not json") + return self._payload + + class _ScriptedSession: + """Returns scripted responses in order; an Exception entry is raised.""" + + def __init__(self, script): + self.script = list(script) + self.requests = [] + self.headers = {} + + def request(self, method, url, **kwargs): + self.requests.append((method, url, kwargs)) + item = self.script.pop(0) + if isinstance(item, BaseException): + raise item + return item + + def _provider(self, script): + from src.providers.chatgpt import ChatGPTProvider + + p = ChatGPTProvider.__new__(ChatGPTProvider) + p._request_delay = 0 + p._last_request_at = None + p._session = self._ScriptedSession(script) + return p + + def _meta(self): + """Hop 1: metadata response carrying the signed download_url.""" + return self._Resp(payload={"download_url": "https://files.example/signed"}) + + def test_signed_url_5xx_is_retried_and_recovers(self, monkeypatch): + """The exact 2026-10-20 failure: hop 2 500s once, then succeeds.""" + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = self._provider([ + self._meta(), + self._Resp(500), + self._Resp(200, content=b"PNGDATA", headers={"content-type": "image/png"}), + ]) + content, mime, _ = p.download_asset("sediment://file_x") + assert content == b"PNGDATA" + assert mime == "image/png" + assert len(p._session.requests) == 3, "hop 2 must be retried, not abandoned" + + def test_signed_url_503_is_retried(self, monkeypatch): + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = self._provider([ + self._meta(), + self._Resp(503), + self._Resp(200, content=b"OK", headers={"content-type": "image/png"}), + ]) + assert p.download_asset("sediment://file_x")[0] == b"OK" + + def test_signed_url_timeout_raises_provider_error_not_oserror(self, monkeypatch): + """The conversation-killer: a hop-2 timeout must be a ProviderError. + + curl_cffi's RequestException is an OSError subclass, so an un-wrapped + timeout here bypassed resolve_media's handler and was caught by the + export loop's `except OSError` as "File write failed". + """ + from curl_cffi.requests.exceptions import Timeout + from src.providers.base import ProviderError + + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + assert issubclass(Timeout, OSError), "premise of this test" + + p = self._provider([self._meta()] + [Timeout("timed out")] * 8) + with pytest.raises(ProviderError) as exc: + p.download_asset("sediment://file_x") + assert "Signed URL" in str(exc.value.original), "must name the failing hop" + + def test_which_hop_failed_stays_in_the_message(self, monkeypatch): + """Hop 1 vs hop 2 fail for different reasons; the message must say which.""" + from src.providers.base import ProviderError + + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = self._provider([self._meta()] + [self._Resp(500)] * 8) + with pytest.raises(ProviderError) as exc: + p.download_asset("sediment://file_x") + detail = str(exc.value.original) + assert detail.startswith("Signed URL:") + assert "500" in detail + + def test_hop_two_is_paced_once_per_attempt_not_twice(self, monkeypatch): + """Pacing twice per asset would add REQUEST_DELAY to every image.""" + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = self._provider([ + self._meta(), + self._Resp(200, content=b"X", headers={"content-type": "image/png"}), + ]) + calls = [] + real_pace = p._pace + monkeypatch.setattr(p, "_pace", lambda: calls.append(1) or real_pace()) + p.download_asset("sediment://file_x") + assert len(calls) == len(p._session.requests) == 2 + + +class TestRetryLadder: + def test_immediate_first_retry_costs_nothing(self): + from src.providers.base import BaseProvider + + assert BaseProvider._backoff_wait(None, 1, immediate_first=True) == 0.0 + + def test_ladder_shifts_down_so_it_reads_0_2_4_8_16(self): + from src.providers.base import BaseProvider + + for attempt, lo in ((2, 2), (3, 4), (4, 8), (5, 16)): + wait = BaseProvider._backoff_wait(None, attempt, immediate_first=True) + assert lo <= wait <= lo * 1.3, f"attempt {attempt} → {wait}" + + def test_jitter_is_never_dropped(self): + """A storage incident fails many assets; un-jittered retries sync up.""" + from src.providers.base import BaseProvider + + waits = { + BaseProvider._backoff_wait(None, 3, immediate_first=True) + for _ in range(25) + } + assert len(waits) > 1 + + def test_conversation_api_ladder_is_unchanged(self): + from src.providers.base import BaseProvider + + assert 2 <= BaseProvider._backoff_wait(None, 1) <= 2.6 + assert 4 <= BaseProvider._backoff_wait(None, 2) <= 5.2 + + def test_retry_after_wins_over_the_immediate_retry(self): + """A server naming a time knows better than we do; 503s often do.""" + from src.providers.base import BaseProvider + + class _R: + headers = {"Retry-After": "7"} + + assert BaseProvider._backoff_wait(_R(), 1, immediate_first=True) == 7.0 + + +class TestMediaTimeBudget: + def test_budget_refuses_a_wait_it_cannot_afford(self, monkeypatch): + """Bounds the timeout case, which costs 40s a go and has no cheap end.""" + from src.providers.base import ProviderError + + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = TestAssetDownloadRetries()._provider([ + TestAssetDownloadRetries._Resp(500) for _ in range(9) + ]) + # First backoff is 2-2.6s, which does not fit in a 1s budget. + with pytest.raises(ProviderError): + p._send_with_retries( + "GET", "https://files.example/signed", + max_retries=5, time_budget=1.0, + ) + assert len(p._session.requests) == 1 + + def test_budget_still_allows_the_free_immediate_retry(self, monkeypatch): + """The 0s retry costs nothing, so a small budget can still fund it.""" + from src.providers.base import ProviderError + + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = TestAssetDownloadRetries()._provider([ + TestAssetDownloadRetries._Resp(500) for _ in range(9) + ]) + with pytest.raises(ProviderError): + p._send_with_retries( + "GET", "https://files.example/signed", + max_retries=5, immediate_first_retry=True, time_budget=1.0, + ) + # Attempt 1, free retry, then the 2s backoff exceeds what is left. + assert len(p._session.requests) == 2 + + def test_read_timeout_is_clamped_to_the_remaining_budget(self, monkeypatch): + """So a final attempt cannot overrun the budget by a whole timeout.""" + from src.providers.base import ProviderError + + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = TestAssetDownloadRetries()._provider([ + TestAssetDownloadRetries._Resp(500) for _ in range(9) + ]) + with pytest.raises(ProviderError): + p._send_with_retries( + "GET", "https://files.example/signed", + max_retries=5, time_budget=3.0, timeout=(10, 20), + ) + _, _, kwargs = p._session.requests[0] + connect_to, read_to = kwargs["timeout"] + assert connect_to == 10 + assert read_to <= 3.0, "read timeout must not exceed the budget" + + def test_without_a_budget_the_full_ladder_runs(self, monkeypatch): + from src.providers.base import ProviderError + + monkeypatch.setattr("src.providers.base.time.sleep", lambda s: None) + p = TestAssetDownloadRetries()._provider([ + TestAssetDownloadRetries._Resp(500) for _ in range(9) + ]) + with pytest.raises(ProviderError): + p._send_with_retries( + "GET", "https://files.example/signed", + max_retries=5, immediate_first_retry=True, + ) + assert len(p._session.requests) == 6, "5 retries = 6 attempts"