From 4e79f9c2f717f8753f1f3ccd3a6b9598f50c1a53 Mon Sep 17 00:00:00 2001 From: maziggy Date: Tue, 25 Aug 2026 09:33:52 +0200 Subject: [PATCH] Fill in a fallback archive when the 3MF finally arrives (issue #2957) A failed TLS handshake pauses a printer's file service for five minutes, and the archive flow checks that pause at the top of its path loop and gives up before opening a connection. A print that starts inside one gets an empty fallback archive 13 milliseconds later, having never touched the network. Four minutes on, the pause clears and the cover endpoint downloads the same file, parses it, takes a thumbnail out of it, and publishes it to the shared 3MF cache under the exact key the archive flow looks up. Nothing ever looks: all three readers of that cache run before or during the print-start handler that already gave up, and print completion drops the cache as its first act, deleting the file. No path existed by which a fallback archive could become a real one. Offer a later 3MF to the running print's archive, filling the existing row rather than adding a second -- the row id carries the energy reading, the timelapse session and the start notification. That covers the reported case at no network cost, since opening the printer card already downloads the file. Schedule a bounded retry when the pause is what caused the fallback, spending the cache first and the printer only if that misses. Not scheduled for the other cause: a print kept on internal eMMC has no FTPS copy to come back for, and retrying it is the sweep removed in #2780. The two reasons are now recorded separately instead of both landing as "no 3MF". Recovery refuses anything that is not a readable 3MF -- a truncated download would replace an honest empty archive with wrong metadata -- and leaves an archive alone once it has a real file. Three things the recovery path has to get right, each with a test: Reduce every retry candidate to a bare name. MQTT hands `filename` over as "/data/Metadata/plate_1.gcode" on some firmware, and joining that onto the temp directory yields the absolute path itself, so the retry is fed the flow's own sanitised candidate list and strips the path again on its own account. Serialise recovery per printer. The cover endpoint's single-flight coalesces by view, so two views race each other, and the retry task and print completion can land on top of either -- each reads file_path == "" and runs a full copy, leaving the row on one timestamped directory and the rest orphaned. Keep looking for photos in the pre-recovery directory. `archive_dir` derives from `file_path`, so filling the row moves the archive's directory, and a photo uploaded to the empty card while the print ran stays where it was put. --- CHANGELOG.md | 1 + backend/app/api/routes/printers.py | 11 + backend/app/main.py | 317 +++++++++- backend/app/services/archive.py | 77 +++ backend/app/services/print_storage.py | 8 + backend/app/utils/archive_paths.py | 24 +- .../test_fallback_archive_recovery_2957.py | 569 ++++++++++++++++++ .../unit/test_internal_storage_probe_2856.py | 17 + 8 files changed, 1022 insertions(+), 2 deletions(-) create mode 100644 backend/tests/unit/test_fallback_archive_recovery_2957.py diff --git a/CHANGELOG.md b/CHANGELOG.md index bab4769b2..93222aa12 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,7 @@ All notable changes to Bambuddy will be documented in this file. - **The Windows installer build is split in two so a signing request can wait for a human (SignPath Foundation)** — Release tags are Authenticode-signed through the SignPath Foundation OSS programme, and the production certificate does not sign on demand the way the self-signed test certificate does: every request has to be approved by hand in the SignPath UI, because the Foundation verifies what is being signed and which build it came from. The submitting action waits for that approval with a default timeout of 600 seconds, which is ample when the test policy approves automatically in seconds and far too short once the wait is a person noticing a tag went out. A tag pushed at night would have failed the run ten minutes later with the installer already compiled and thrown away. The compile now ends in its own job that uploads the unsigned artifact and stops; a second job downloads it, signs it, and does the release-facing work, with the wait raised to an hour. Because the artifact is uploaded before the wait begins and is addressed by id, a missed approval window is recovered by re-running the second job alone rather than rebuilding the installer — which is the reason to separate them rather than simply raise the timeout in place. The second job runs for unsigned builds too, so the daily prereleases that are deliberately left unsigned to preserve the signing quota keep going out through exactly one set of alias, artifact and release steps. The property that matters is unchanged and now recorded next to the steps that depend on it: none of the alias, upload or release-attach steps carry `always()`, so GitHub skips all three when signing fails or times out, and an unsigned `.exe` cannot reach a release. Nothing about the signed output changes, and the restructure behaves identically under the test policy — the request simply completes immediately instead of waiting — so it can be proven green before the production certificate arrives. ### Fixed +- **A print that started during an FTPS pause was archived empty forever, even after Bambuddy downloaded the file (#2957, reported and diagnosed by @doncaruana)** — A failed TLS handshake puts a printer's file service in a five-minute pause, and the archive flow checks that pause at the top of its path loop and gives up before opening a connection. @doncaruana's P1S started a print inside one: Bambuddy wrote an empty fallback archive 13 milliseconds after print start, having never touched the network. Four minutes later the pause cleared, the cover endpoint downloaded the very same file — all 8,956,942 bytes — parsed it, took the plate-2 thumbnail out of it, and published it to the shared 3MF cache under the exact key the archive flow looks up. Nothing ever looked. All three readers of that cache run before or during the print-start handler that had already given up, and print completion drops the cache as its first act, deleting the file. So the archive stayed a shell — no thumbnail, no file size, no filament, no layers — for a print whose source Bambuddy had held, parsed and indexed, and there was no path in the codebase by which a fallback archive could ever become a real one. Two things change. A 3MF that arrives later is now offered to the running print's archive, which fills the existing row in place rather than adding a second one — the row's id is load-bearing, with the energy reading, the timelapse session and the start notification all written against it. That covers this report at no network cost, because opening the printer card already downloads the file to draw its thumbnail. And a fallback created *because of* the pause now schedules its own bounded retry, spending the cache first and the printer only if that misses. The retry is deliberately not scheduled for the other reason an archive comes up empty: a print the printer kept on internal eMMC has no FTPS copy to come back for, and retrying it is the sweep that was removed in #2780 — so the two causes are now recorded separately instead of both landing as "no 3MF". Recovery refuses anything that is not a readable 3MF, since a truncated download would replace an honest empty archive with wrong metadata, and leaves an archive alone once it has a real file. The last opportunity is taken too: print completion spends the cache on a still-empty archive before evicting it. Wiki updated. - **A printer whose failure detection was not working showed a green "Safe" badge (#2952, reported via in-app bug report, with a full ML API and Bambuddy log correlation)** — The printer card's AI badge collapsed every class that was not Warning or Failure into green **Safe**, and the service reported `safe` whenever it had no verdict to give. The state entry is created the moment a monitored print is seen, which is before the first snapshot and well before the first inference, so a rejected ML API token, an unreachable ML API, a camera that never yielded a frame and an unset External URL all rendered identically to a healthy watched print: a green pill reading Safe at score 0.000. For a safety feature that is the worst available failure mode — it asserts the print is being watched at exactly the moment it is not. The reporter read that badge, concluded the detection loop had never started, and spent an evening ruling out the network path; the loop had in fact been calling the ML API every ten seconds the whole time and being turned away with a 401. What hid it is that Obico's auth layer rejects a bad token before its own request log records anything, so a token problem and a service that never runs leave the same trace in the ML container: nothing. Successful checks log nothing there either, which leaves the container log unable to distinguish working from broken in either direction. The badge now has two more states and tells the truth in both: **Not checking** (amber) when the last check produced no result, carrying the reason — rejected token, unreachable API, failed capture, missing External URL — in the tooltip and the modal, and **Starting** while a monitored print waits for its first result. Score and frame count are withheld while a printer is not being checked, since 0.000 next to "Not checking" reads as a measurement rather than the absence of one. The reason is tracked per printer rather than service-wide, so on a multi-printer setup a card names its own problem instead of whichever printer failed most recently; it stays behind `settings:read` because it can quote configured URLs, while the badge state itself does not, because whether a print is being watched is not configuration. An unrecognised class from a future backend now falls back to **Starting** rather than **Safe** — the fallback that caused this. Also fixed alongside: **Test Connection** now saves the form before probing, so a green "reachable and healthy" always describes the configuration the detection loop is actually running with rather than what is typed in the boxes. The wiki's badge table and troubleshooting section are updated, including the ML API container log being unable to answer this question. - **Bambuddy could not start against a PostgreSQL server whose messages are not in English (#2949, reported and diagnosed by @dvb6666)** — @dvb6666's Debian PostgreSQL 15 answered the first migration statement with `столбец "parent_run_id" отношения "pipeline_runs" уже существует` and startup aborted. The column already existing is the *expected* outcome there: `create_all()` builds the tables from the models before the migration list runs, so on a fresh database essentially every `ADD COLUMN` in that list is a duplicate by design, and all 382 of them relied on the runner recognising "already applied" and moving on. It recognised it by searching the error text for `already exists` — but PostgreSQL renders its messages in the server's own `lc_messages` locale, and a Russian server does not say that. So the very first statement was re-raised as a fatal error. This was never specific to `parent_run_id` or to one PostgreSQL version, which is why @dvb6666 got the identical failure after moving from 15 to 18: no PostgreSQL server outside an English locale could start Bambuddy at all, fresh install or upgrade, and the failure surfaced as a schema error rather than as anything pointing at the language. Idempotency is now decided by SQLSTATE, the five-character code PostgreSQL never translates — `42701` duplicate column, `42P07` duplicate table or index, `42710` duplicate constraint or trigger, `23505` duplicate key. The narrowing that was already there is kept and now rests on a code rather than a phrase: a missing column counts as "already applied" only for `RENAME COLUMN`, so a column missing during `ADD COLUMN` or `CREATE INDEX` still aborts startup instead of quietly hiding a corrupt schema — as do a missing table, an unknown column type, and a syntax error, each verified against a live server. SQLite keeps the text match, since its driver publishes no SQLSTATE and it never localises its messages. The same treatment went to the second place that read message text, the OIDC auto-link safety constraint, where a mistranslated "already exists" would have failed startup on the same servers. Measured rather than reasoned about: against PostgreSQL 15 under `ru_RU`, `en_US` and `C`, a full `init_db()` completes on both a fresh database and a re-run, and the schema the Russian server ends up with is byte-identical to the English one — nothing is being silently skipped to make startup succeed. - **A test in the plug-energy suite failed for 31 minutes of every day (#2938, reported and measured by @ojimpo)** — `test_nothing_derivable_before_the_first_midnight` passed for 23.5 hours a day and failed for the other half hour, which is the shape that reads as ordinary flakiness and gets re-run rather than fixed. @ojimpo hit it running the full suite for an unrelated PR at 22:10 UTC, stashed his branch to confirm it reproduced on clean `dev`, then measured the window minute by minute against the real day boundary instead of guessing at it. **The test's premise, not the product.** It asserts that nothing can be derived when a plug's only snapshot was taken *after* this local midnight, and it placed that snapshot at a raw wall-clock offset — `now - 30 minutes`. The comment beside it, "taken this morning, after midnight", is the premise, and it is only true away from the boundary: for the first half hour of each local day, `now - 30 minutes` lands *before* local midnight, where it is a perfectly good baseline. `_counter_at` finds it, and `today` comes back `103.5 - 102.0 = 1.5` instead of `None`. The window is local 00:00–00:30, which is 22:00–22:30 UTC while CEST is in effect and 23:00–23:30 under CET — it moves with DST, because the module pins `Europe/Berlin` in an autouse fixture and an outer `TZ` makes no difference to it. **`derive_today_yesterday` is right and unchanged.** A snapshot from before local midnight genuinely *is* a valid baseline for today, and the production code treating it as one is the documented behaviour, so nothing here reaches a running install. The snapshot is now anchored to `local_day_start(now) + 30 minutes`, which is the idiom the file's other nine snapshot writes already use and the reason none of *them* could drift — this was the only one that offset from the wall clock, and the only one that failed. Verified by replaying 5760 minutes across four days including both DST switch days: the old expression fails 31 minutes per day, the new one fails none. **Scope.** One test file. No product code, no DB migration, no schema change, no permission, no i18n change. diff --git a/backend/app/api/routes/printers.py b/backend/app/api/routes/printers.py index 8cf26b6e9..d2b76b953 100644 --- a/backend/app/api/routes/printers.py +++ b/backend/app/api/routes/printers.py @@ -1444,6 +1444,17 @@ async def _produce_cover_image( temp_path.unlink() raise HTTPException(500, f"Downloaded file is empty for '{subtask_name}'") + # Offer the file to the archive flow before extracting the thumbnail. When + # the print started inside the printer's FTPS cool-off, the archive flow + # gave up without a single connection and this endpoint holds the very file + # it wanted — which used to be read for a thumbnail and then deleted at + # print completion, leaving a permanently empty archive (#2957). Covers the + # cached branch as well as a fresh download: whoever fetched it, the running + # print's archive should have it. A no-op unless that archive is a fallback. + from backend.app.main import try_recover_fallback_archive + + await try_recover_fallback_archive(printer_id, temp_filename, temp_path) + try: # Extract thumbnail from 3MF (which is a ZIP file) try: diff --git a/backend/app/main.py b/backend/app/main.py index 81b9ff669..2fd13b174 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -95,6 +95,7 @@ from backend.app.services.bambu_ftp import ( ftps_handshake_blocked, get_cached_3mf, get_ftp_retry_settings, + normalize_3mf_name, with_ftp_retry, ) from backend.app.services.bambu_mqtt import PrinterState @@ -111,6 +112,7 @@ from backend.app.services.obico_detection import obico_detection_service from backend.app.services.print_cost_estimate import plate_scoped_run_estimate as _plate_scoped_run_estimate from backend.app.services.print_scheduler import scheduler as print_scheduler from backend.app.services.print_storage import ( + REASON_FTPS_COOLOFF, external_storage_present, ftp_probe_paths, print_file_reachable_over_ftp, @@ -2975,6 +2977,244 @@ async def _restore_printable_objects(printer_id: int, state, db, logger) -> None _load_objects_from_archive(archive, printer_id, logger) +# Retry ladder for a fallback archive created while the printer's FTPS cool-off +# was running (#2957). The cool-off is 300s, so the first attempt is placed just +# past it; the second covers a handshake that failed again on the way back and +# armed a fresh one. Module-level so tests can shrink them. +_FALLBACK_3MF_RETRY_DELAYS_SECONDS: tuple[float, ...] = (310.0, 620.0) + +# printer_id -> the in-flight retry task, so print completion can cancel it. +_fallback_3mf_retry_tasks: dict[int, asyncio.Task] = {} + +# printer_id -> lock serialising recovery attempts for that printer. Three callers +# can reach one archive at once: the cover endpoint (whose single-flight coalesces +# by view, so two views race), the cool-off retry task, and print completion. +# Without this they each read file_path == "" and each run a full copy, so the row +# ends up pointing at one timestamped directory while the others sit orphaned. +# +# Keyed by printer rather than archive because a printer runs one print at a time, +# which makes the two equally strong here — and it bounds the dict by printer +# count instead of needing a cleanup pass. Popping a per-archive entry cannot be +# done safely: `Lock.locked()` reads False between release and the queued waiter +# resuming, so "no waiters" is not a question this API can answer. +_fallback_recovery_locks: dict[int, asyncio.Lock] = {} + + +async def _recover_fallback_archive(archive_id: int, source_3mf: Path, printer_id: int) -> bool: + """Fill in a no-3MF archive from a 3MF that turned up later. + + Returns True when the row was upgraded. Safe to call speculatively: it + verifies the archive still exists, is still a fallback, and that the file + is a readable 3MF before touching anything. + + Serialised per printer — see ``_fallback_recovery_locks``. + """ + lock = _fallback_recovery_locks.setdefault(printer_id, asyncio.Lock()) + async with lock: + return await _recover_fallback_archive_locked(archive_id, source_3mf, printer_id) + + +async def _recover_fallback_archive_locked(archive_id: int, source_3mf: Path, printer_id: int) -> bool: + """The body of :func:`_recover_fallback_archive`, under its per-printer lock.""" + import zipfile + + from backend.app.models.archive import PrintArchive + from backend.app.services.archive import ArchiveService + + logger = logging.getLogger(__name__) + + if not source_3mf.exists() or source_3mf.stat().st_size == 0: + return False + if not await asyncio.to_thread(zipfile.is_zipfile, source_3mf): + # A truncated or half-written download is worse than no download: it + # would replace an honest empty archive with wrong metadata. + logger.warning("[RECOVER] %s is not a readable 3MF; leaving archive %s as-is", source_3mf, archive_id) + return False + + async with async_session() as db: + archive = (await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))).scalar_one_or_none() + if archive is None or archive.deleted_at is not None: + return False + if archive.file_path: + # Already recovered, or never was a fallback. Either way there is a + # real 3MF attached and overwriting it is not this function's job. + return False + + print_data = (archive.extra_data or {}).get("_print_data") or {} + service = ArchiveService(db) + recovered = await service.archive_print( + printer_id=printer_id, + source_file=source_3mf, + print_data={**print_data, "status": archive.status or "printing"}, + subtask_id=archive.subtask_id, + update_archive_id=archive.id, + ) + if recovered is None: + return False + + logger.info( + "[RECOVER] Archive %s filled in from %s (%s bytes) — it started as a no-3MF fallback", + archive_id, + source_3mf, + recovered.file_size, + ) + # `archive_updated`, not `archive_created` — the row was already on the + # Archives page as an empty card and is now filled in, not new. + await ws_manager.send_archive_updated( + { + "id": recovered.id, + "printer_id": recovered.printer_id, + "filename": recovered.filename, + "print_name": recovered.print_name, + "status": recovered.status, + } + ) + return True + + +async def try_recover_fallback_archive(printer_id: int, name: str, path: Path) -> bool: + """Offer a freshly-downloaded 3MF to this printer's running fallback archive. + + Called from the paths that pull a 3MF for a print that is already under way + — chiefly the cover endpoint, which downloads the very file the archive flow + could not get and, before #2957, used it for a thumbnail and nothing else. + The bytes are already local, so this costs a parse and a row update. + + No-op when the running print has a real archive, which is the common case. + """ + from backend.app.models.archive import PrintArchive + + logger = logging.getLogger(__name__) + + # `_active_prints` is keyed on the raw names seen at print start — the + # dispatch filename, the subtask name, and the subtask name plus ".3mf". + # Callers here arrive with whichever variant their own path produced, so + # match on the same normalization the download cache uses rather than on an + # exact string; that is what makes "Desktop_Goose.gcode.3mf" from the cover + # endpoint find an archive registered under "Desktop_Goose". + wanted = normalize_3mf_name(name) + archive_id = None + for (key_printer_id, key_name), value in list(_active_prints.items()): + if key_printer_id == printer_id and normalize_3mf_name(key_name) == wanted: + archive_id = value + break + if archive_id is None: + return False + + async with async_session() as db: + archive = (await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id))).scalar_one_or_none() + # Cheap pre-check so the common case (a normal archive) does no work. + if archive is None or archive.file_path or archive.deleted_at is not None: + return False + + try: + return await _recover_fallback_archive(archive_id, path, printer_id) + except Exception as e: + # Recovery is opportunistic. A failure here must never take down the + # caller, which is usually just trying to render a thumbnail. + logger.warning("[RECOVER] Could not fill in archive %s from %s: %s", archive_id, path, e) + return False + + +def _schedule_fallback_3mf_retry(printer_id: int, archive_id: int, filenames: list[str]) -> None: + """Re-attempt the 3MF download after the printer's FTPS cool-off clears.""" + + logger = logging.getLogger(__name__) + + async def _retry() -> None: + from backend.app.models.archive import PrintArchive + from backend.app.models.printer import Printer + + for delay in _FALLBACK_3MF_RETRY_DELAYS_SECONDS: + await asyncio.sleep(delay) + + async with async_session() as db: + archive = ( + await db.execute(select(PrintArchive).where(PrintArchive.id == archive_id)) + ).scalar_one_or_none() + if archive is None or archive.deleted_at is not None or archive.file_path: + return + printer = (await db.execute(select(Printer).where(Printer.id == printer_id))).scalar_one_or_none() + if printer is None: + return + # Read the fields while the session is open rather than touching + # a detached instance minutes later, mid-download. + printer_ip = printer.ip_address + printer_code = printer.access_code + printer_model = printer.model + + # Someone else may have fetched it in the meantime — the cover + # endpoint routinely does, and its copy is the same bytes. + for name in filenames: + cached = get_cached_3mf(printer_id, name) + if cached and await _recover_fallback_archive(archive_id, cached, printer_id): + return + + if ftps_handshake_blocked(printer_ip): + logger.info( + "[RECOVER] Printer %s is still in its FTPS cool-off; archive %s retry deferred", + printer_id, + archive_id, + ) + continue + + _, _, _, ftp_timeout = await get_ftp_retry_settings() + for candidate in filenames: + # Bare name only. These come from the print-start flow, which + # already strips the path, but the local temp write must not + # depend on that holding for every future caller — a name that + # is absolute or contains ".." would otherwise escape the data + # volume via the `/` operator. + name = Path(candidate).name + if not name or name in (".", ".."): + continue + if not name.endswith(".3mf"): + name = f"{name}.3mf" + temp_path = app_settings.archive_dir / "temp" / name + temp_path.parent.mkdir(parents=True, exist_ok=True) + try: + hit = await download_file_try_paths_async( + printer_ip, + printer_code, + ftp_probe_paths(name), + temp_path, + socket_timeout=ftp_timeout, + printer_model=printer_model, + ) + except Exception as e: + logger.debug("[RECOVER] Retry download of %s failed: %s", name, e) + continue + if not hit: + continue + cache_3mf_download(printer_id, name, temp_path) + if await _recover_fallback_archive(archive_id, temp_path, printer_id): + return + + logger.info("[RECOVER] Archive %s still has no 3MF after a retry", archive_id) + + async def _guarded() -> None: + try: + await _retry() + except asyncio.CancelledError: + raise + except Exception as e: + logger.warning("[RECOVER] Retry task for archive %s failed: %s", archive_id, e) + finally: + if _fallback_3mf_retry_tasks.get(printer_id) is asyncio.current_task(): + _fallback_3mf_retry_tasks.pop(printer_id, None) + + existing = _fallback_3mf_retry_tasks.pop(printer_id, None) + if existing and not existing.done(): + existing.cancel() + task = asyncio.create_task(_guarded()) + _fallback_3mf_retry_tasks[printer_id] = task + logger.info( + "[RECOVER] Archive %s has no 3MF because printer %s was in its FTPS cool-off; will retry", + archive_id, + printer_id, + ) + + async def on_print_start(printer_id: int, data: dict): """Handle print start - archive the 3MF file immediately.""" logger = logging.getLogger(__name__) @@ -3659,6 +3899,12 @@ async def on_print_start(printer_id: int, data: dict): # succeed. Skip it and say why (#2780). storage = print_file_reachable_over_ftp(printer_manager.get_status(printer_id)) + # Set when a lookup is abandoned because the printer's FTPS cool-off is + # running rather than because the file is somewhere unreachable. The + # distinction is the whole of #2957: one is permanent, the other clears + # in minutes with the file still sitting on the printer. + blocked_by_ftps_cooloff = False + # Get FTP retry settings ftp_retry_enabled, ftp_retry_count, ftp_retry_delay, ftp_timeout = await get_ftp_retry_settings() @@ -3671,6 +3917,12 @@ async def on_print_start(printer_id: int, data: dict): # comes back empty does the verdict's reason stand. if not storage.reachable and not downloaded_filename and storage.probe_filename: if ftps_handshake_blocked(printer.ip_address): + # Deliberately NOT recorded as a cool-off give-up. This branch + # only runs on an unreachable verdict, and that verdict is the + # honest, permanent reason the archive is empty — the probe was + # a long shot on top of it. Blaming the cool-off here would + # schedule a retry for a file sitting on internal eMMC, which is + # the sweep #2780 removed (#2957). logger.debug( "Not probing for %s on printer %s: its file service is not answering over TLS", storage.probe_filename, @@ -3745,6 +3997,13 @@ async def on_print_start(printer_id: int, data: dict): # handshake, so it has no path we could reach — walking the # remaining candidates only re-runs the same failure # (#2780). Fall through to the no-3MF archive now. + # + # Remember *why*, though. This is the one give-up that is + # temporary: the cool-off clears in minutes and the file was + # on the printer the whole time. The fallback archive is + # stamped with it so a retry can be scheduled, and so the + # Archives banner stops blaming storage (#2957). + blocked_by_ftps_cooloff = True logger.warning( "Giving up on the 3MF for printer %s: its file service is not answering over TLS", printer_id, @@ -4026,7 +4285,11 @@ async def on_print_start(printer_id: int, data: dict): # Why the card is empty, when we know. The banner reads # this to stop telling H2/P2 owners to switch on a # setting that is already on and would not help (#2780). - "no_3mf_reason": storage.reason, + # A cool-off outranks the storage verdict: the sweep was + # skipped at the transport, so the verdict never got to + # be tested, and reporting it would blame the SD card + # for a TLS handshake (#2957). + "no_3mf_reason": REASON_FTPS_COOLOFF if blocked_by_ftps_cooloff else storage.reason, "original_subtask": subtask_name, "_print_data": data, }, @@ -4087,6 +4350,23 @@ async def on_print_start(printer_id: int, data: dict): except Exception as e: logger.debug("[SPOOLMAN] Could not store tracking for fallback archive: %s", e) + # A cool-off give-up is temporary and the file is on the + # printer — come back for it once the handshake block clears + # (#2957). Deliberately not scheduled for a storage verdict: + # a file on internal eMMC will not appear at any FTPS path + # however long we wait, and retrying it is exactly the sweep + # #2780 removed. + if blocked_by_ftps_cooloff and possible_names: + # `possible_names`, not the raw MQTT strings: it is the exact + # list this flow just tried, already stripped of any path + # (`filename` arrives as "/data/Metadata/plate_1.gcode" on + # some firmware) and deduped. + _schedule_fallback_3mf_retry( + printer_id=printer_id, + archive_id=fallback_archive.id, + filenames=list(possible_names), + ) + # Send notification without archive data (file not found) if not notification_sent: await _send_print_start_notification(printer_id, data, logger=logger) @@ -5576,6 +5856,29 @@ async def _completion_belongs_to_queue_item(db, item, data: dict) -> bool: return False +async def _recover_fallback_from_cache_before_eviction(printer_id: int, data: dict) -> None: + """Spend the 3MF download cache on a still-empty fallback archive. + + ``on_print_complete`` drops the cache as its first act, which deletes the + file. If the cover endpoint (or anything else) pulled the 3MF while the + print ran and the archive never got one, this is the last moment those bytes + exist (#2957). + """ + logger = logging.getLogger(__name__) + names = [ + n + for n in (data.get("filename"), data.get("subtask_name"), (data.get("raw_data") or {}).get("subtask_name")) + if n + ] + for name in names: + try: + cached = get_cached_3mf(printer_id, name) + if cached and await try_recover_fallback_archive(printer_id, name, cached): + return + except Exception as e: + logger.debug("[RECOVER] Pre-eviction recovery for %s failed: %s", name, e) + + async def on_print_complete(printer_id: int, data: dict): """Handle print completion - update the archive status.""" import time @@ -5594,6 +5897,18 @@ async def on_print_complete(printer_id: int, data: dict): # if that immediate attempt failed, the regular completion path retries. kill_switch_notification_task = _kill_switch_notification_tasks.pop(printer_id, None) + # Last chance before the bytes go: if this print's archive is still an empty + # fallback and something downloaded the 3MF while it ran, fill the archive in + # now. The cover endpoint's copy lives in exactly this cache, and clearing it + # below deletes the file (#2957). + await _recover_fallback_from_cache_before_eviction(printer_id, data) + + # A pending cool-off retry has nothing left to recover for — the cache is + # about to be dropped and the print is over. + retry_task = _fallback_3mf_retry_tasks.pop(printer_id, None) + if retry_task and not retry_task.done(): + retry_task.cancel() + # Drop the 3MF download cache for this printer (#972). The print is over, # nothing else legitimately needs the bytes; keeping them would only risk # handing a stale file to the next print if it reuses the same name. diff --git a/backend/app/services/archive.py b/backend/app/services/archive.py index 1b8f0cc5e..a1c65f966 100644 --- a/backend/app/services/archive.py +++ b/backend/app/services/archive.py @@ -1218,6 +1218,7 @@ class ArchiveService: library_file_id: int | None = None, slicer_ams_mapping: list[int] | None = None, slicer_ams_mapping_printer_id: int | None = None, + update_archive_id: int | None = None, ) -> PrintArchive | None: """Archive a 3MF file with metadata. @@ -1255,6 +1256,17 @@ class ArchiveService: reused later on any printer, including the same one (there'd be no way to tell). A model-based VP with no fixed target printer has no valid value to pass here and must leave both params unset. + update_archive_id: Fill in an existing archive row instead of adding one. + Used to upgrade a no-3MF fallback archive once the file finally arrives + (#2957). Everything above the row itself — the copy, the parse, the + thumbnail, the cost — is exactly what a fresh archive does; only the + destination differs. The row must keep its id: the energy-start reading, + the timelapse session, ``_active_prints``, the start notification and any + queue link were all written against it while the print was running, and a + second row would orphan every one of them. Fields the fallback path + already established from MQTT (``started_at``, ``subtask_id``, + ``created_by_id``, ``project_id``) are left alone; the 3MF has nothing + better to say about them. """ # Verify printer exists if specified if printer_id is not None: @@ -1395,6 +1407,71 @@ class ArchiveService: quantity = len(printable_objects) logger.debug("Auto-detected %s parts from 3MF printable objects", quantity) + # Recovery of an existing fallback row: assign the freshly-parsed values + # onto it rather than adding a second archive for the same print (#2957). + if update_archive_id is not None: + existing = await self.db.get(PrintArchive, update_archive_id) + if existing is None: + logger.warning("archive_print: archive %s to update no longer exists", update_archive_id) + return None + # `metadata` is freshly parsed from the 3MF, so assigning it drops + # the row's `no_3mf_available` / `no_3mf_reason` markers as a side + # effect — which is correct, the archive is no longer a fallback, + # and it is what stops the Archives banner counting it. + # `_print_data` is diagnostic history rather than something the 3MF + # knows about: keep the row's copy for a caller that passed no + # print_data of its own. + merged = dict(metadata) + preserved = (existing.extra_data or {}).get("_print_data") + if preserved is not None and "_print_data" not in merged: + merged["_print_data"] = preserved + # A record that this row started life without a 3MF, which the + # dropped markers no longer say. + merged["recovered_no_3mf"] = True + existing.filename = original_filename or source_file.name + existing.file_path = str(dest_file.relative_to(settings.base_dir)) + existing.file_size = dest_file.stat().st_size + existing.content_hash = content_hash + existing.thumbnail_path = thumbnail_path + existing.print_name = ( + clean_display_name(display_stem) + if prefer_filename_for_name + else (clean_display_name(metadata.get("print_name")) or clean_display_name(display_stem)) + ) + # Only overwrite what the 3MF actually knows. A fallback archive + # recovered mid-print has a real print_time_seconds from MQTT and a + # filament type/colour from the AMS; a 3MF that omits a field must + # not blank them back out. + for field in ( + "print_time_seconds", + "filament_used_grams", + "filament_type", + "filament_color", + "layer_height", + "total_layers", + "nozzle_diameter", + "bed_temperature", + "bed_type", + "nozzle_temperature", + "sliced_for_model", + "makerworld_url", + "designer", + ): + value = metadata.get(field) + if value is not None: + setattr(existing, field, value) + if cost is not None: + existing.cost = cost + existing.quantity = quantity + existing.extra_data = merged + if plate_id is not None: + existing.plate_id = plate_id + if library_file_id is not None: + existing.library_file_id = library_file_id + await self.db.commit() + await self.db.refresh(existing) + return existing + # Create archive record archive = PrintArchive( printer_id=printer_id, diff --git a/backend/app/services/print_storage.py b/backend/app/services/print_storage.py index 218e4c846..64b5c1cc8 100644 --- a/backend/app/services/print_storage.py +++ b/backend/app/services/print_storage.py @@ -66,6 +66,14 @@ _INTERNAL_FILE_PREFIXES = ("/userdata/",) REASON_INTERNAL_STORAGE = "internal_storage" REASON_NO_EXTERNAL_STORAGE = "no_external_storage" +# Not a storage verdict — the file's location was never in question. The +# printer's FTPS service was inside its post-failed-handshake cool-off when the +# print started, so the sweep was skipped without a single connection. Stamped +# on the fallback archive by the print-start handler rather than returned by +# `_verdict`, and unlike the two above it is temporary: it is the one reason a +# retry is worth scheduling (#2957). +REASON_FTPS_COOLOFF = "ftps_cooloff" + # Where a sliced file has ever been found over FTPS, in the order the sweep in # `main.py` tries them -- root first, which is where A1/P1-series uploads land # (#972), then `/cache`, which is where the H2D keeps its copy of an eMMC job diff --git a/backend/app/utils/archive_paths.py b/backend/app/utils/archive_paths.py index 67449d0b9..f0d1da210 100644 --- a/backend/app/utils/archive_paths.py +++ b/backend/app/utils/archive_paths.py @@ -58,6 +58,24 @@ def _legacy_shared_photos_dir(archive: object) -> Path | None: return settings.base_dir / "photos" # SEC-PATH-OK: constant subdirectory +def _pre_recovery_photos_dir(archive: object) -> Path | None: + """Where this archive's photos were written while it had no 3MF. + + An archive that started as a no-3MF fallback and was later filled in from a + 3MF that turned up (#2957) changes directory: ``archive_dir`` derives from + ``file_path``, which goes from empty to a real path. Anything written to + ``//photos`` before that moment is still there, so it stays + a lookup candidate afterwards -- the same reason + :func:`_legacy_shared_photos_dir` exists. + + None while ``file_path`` is empty, where this *is* the current directory and + the caller already checks it. + """ + if not (getattr(archive, "file_path", "") or ""): + return None + return settings.archive_dir / str(archive.id) / "photos" # SEC-PATH-OK: archive.id is an int primary key + + def find_archive_photo(archive: object, filename: str) -> Path | None: """Locate an existing photo, or None if it is in neither location. @@ -67,7 +85,11 @@ def find_archive_photo(archive: object, filename: str) -> Path | None: one caller is a background notification task, where an HTTP error would have nowhere to go. """ - for directory in (archive_photos_dir(archive), _legacy_shared_photos_dir(archive)): + for directory in ( + archive_photos_dir(archive), + _legacy_shared_photos_dir(archive), + _pre_recovery_photos_dir(archive), + ): if directory is None: continue try: diff --git a/backend/tests/unit/test_fallback_archive_recovery_2957.py b/backend/tests/unit/test_fallback_archive_recovery_2957.py new file mode 100644 index 000000000..1470e9eb0 --- /dev/null +++ b/backend/tests/unit/test_fallback_archive_recovery_2957.py @@ -0,0 +1,569 @@ +"""A fallback archive is filled in when the 3MF finally turns up (#2957). + +The reporter's P1S started a print while Bambuddy was inside the five-minute +FTPS cool-off armed by an earlier failed TLS handshake. The archive flow checks +that cool-off at the top of its path loop and breaks before opening a single +connection, so it gave up 13 ms after print start and wrote an empty fallback +archive. Four minutes later the cool-off cleared and the cover endpoint +downloaded the very same file -- all 8,956,942 bytes of it -- read a thumbnail +out of it, and published it to the shared 3MF cache under the exact key the +archive flow looks up. + +Nothing ever looked. Every ``get_cached_3mf`` caller runs before or during the +print-start handler that had already given up, and ``on_print_complete`` drops +the cache as its first statement, deleting the file. The archive stayed an empty +shell for a print whose source Bambuddy had held, parsed and indexed. + +These tests pin the recovery: the row is filled in place (its id is load-bearing +-- the energy reading, the timelapse session and the start notification were all +written against it), it is only ever offered a readable 3MF, and it is left +alone once it has a real file. +""" + +from __future__ import annotations + +import uuid +import zipfile +from pathlib import Path +from unittest.mock import patch + +import pytest +from sqlalchemy import select +from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker + +from backend.app.models.archive import PrintArchive +from backend.app.models.printer import Printer + +pytestmark = pytest.mark.asyncio + +PRINT_NAME = "Desktop_Goose" +DISPATCH_FILENAME = "Desktop_Goose.gcode.3mf" + + +def _write_3mf(path: Path, print_name: str = PRINT_NAME) -> Path: + """A 3MF the archive parser can read metadata out of.""" + path.parent.mkdir(parents=True, exist_ok=True) + with zipfile.ZipFile(path, "w", zipfile.ZIP_DEFLATED) as zf: + zf.writestr( + "Metadata/slice_info.config", + "" + "" + "" + "" + "" + "" + "", + ) + zf.writestr( + "Metadata/model_settings.config", + f"", + ) + zf.writestr("3D/3dmodel.model", "") + return path + + +async def _seed(engine, tmp_path: Path) -> tuple[async_sessionmaker, int, int]: + """A printer plus the empty fallback archive the cool-off produced.""" + maker = async_sessionmaker(engine, class_=AsyncSession, expire_on_commit=False) + async with maker() as db: + printer = Printer( + name="P1S", + serial_number="01P00A3B1200579", + ip_address="172.25.12.149", + access_code="12345678", + model="P1S", + ) + db.add(printer) + await db.commit() + await db.refresh(printer) + + archive = PrintArchive( + printer_id=printer.id, + filename=DISPATCH_FILENAME, + file_path="", # the shell + file_size=0, + print_name=PRINT_NAME, + status="printing", + subtask_id="4242", + extra_data={ + "no_3mf_available": True, + "no_3mf_reason": "ftps_cooloff", + "original_subtask": PRINT_NAME, + "_print_data": {"filename": DISPATCH_FILENAME}, + }, + ) + db.add(archive) + await db.commit() + await db.refresh(archive) + return maker, printer.id, archive.id + + +class TestRecoveryFillsTheExistingRow: + async def test_the_cover_endpoints_download_recovers_the_archive(self, test_engine, tmp_path): + """The reporter's case, end to end from the download onwards.""" + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + # The cover endpoint's own temp name, as it appears in the report: + # /app/data/archive/temp/cover_1_Desktop_Goose.gcode.3mf + source = _write_3mf(tmp_path / "temp" / f"cover_{printer_id}_{DISPATCH_FILENAME}") + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, DISPATCH_FILENAME): archive_id}, clear=True), + ): + recovered = await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) + + assert recovered is True + + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + # Same row. A second archive would orphan the energy reading, the + # timelapse session and the notification already sent against it. + assert archive.id == archive_id + assert archive.file_path + assert archive.file_size == source.stat().st_size + assert archive.subtask_id == "4242" + assert archive.status == "printing" + # No longer a fallback, so the Archives banner stops counting it. + assert not archive.extra_data.get("no_3mf_available") + assert archive.extra_data.get("recovered_no_3mf") is True + # The start payload is diagnostic history and survives. + assert archive.extra_data["_print_data"]["filename"] == DISPATCH_FILENAME + + # And exactly one archive, not the original shell plus a new one. + async with maker() as db: + rows = (await db.execute(select(PrintArchive).where(PrintArchive.printer_id == printer_id))).scalars().all() + assert [row.id for row in rows] == [archive_id] + + async def test_metadata_from_the_3mf_lands_on_the_row(self, test_engine, tmp_path): + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + source = _write_3mf(tmp_path / "temp" / DISPATCH_FILENAME) + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, DISPATCH_FILENAME): archive_id}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is True + + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + # The empty shell had none of these. + assert archive.filament_used_grams == pytest.approx(42.5) + assert archive.filament_type == "PLA" + assert archive.print_time_seconds == 3600 + + async def test_a_name_variant_still_finds_the_archive(self, test_engine, tmp_path): + """The cover endpoint arrives with whichever spelling its own path built. + + `_active_prints` is keyed on the raw names seen at print start, so an + exact-string lookup would miss "Desktop_Goose.gcode.3mf" against an + archive registered under "Desktop_Goose". + """ + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + source = _write_3mf(tmp_path / "temp" / DISPATCH_FILENAME) + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, PRINT_NAME): archive_id}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is True + + +class TestRecoveryRefusesTheWrongInput: + async def test_a_truncated_download_is_refused(self, test_engine, tmp_path): + """Half a file would replace an honest empty archive with wrong metadata.""" + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + source = tmp_path / "temp" / DISPATCH_FILENAME + source.parent.mkdir(parents=True, exist_ok=True) + source.write_bytes(b"PK\x03\x04 truncated, not a readable zip") + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, DISPATCH_FILENAME): archive_id}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is False + + async with maker() as db: + assert (await db.get(PrintArchive, archive_id)).file_path == "" + + async def test_an_empty_file_is_refused(self, test_engine, tmp_path): + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + source = tmp_path / "temp" / DISPATCH_FILENAME + source.parent.mkdir(parents=True, exist_ok=True) + source.write_bytes(b"") + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, DISPATCH_FILENAME): archive_id}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is False + + async def test_an_archive_that_already_has_a_3mf_is_left_alone(self, test_engine, tmp_path): + """The normal case: every cover request during a healthy print hits this.""" + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + archive.file_path = "archives/1/real/Desktop_Goose.gcode.3mf" + archive.file_size = 8956942 + await db.commit() + + source = _write_3mf(tmp_path / "temp" / DISPATCH_FILENAME) + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, DISPATCH_FILENAME): archive_id}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is False + + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + assert archive.file_path == "archives/1/real/Desktop_Goose.gcode.3mf" + assert archive.file_size == 8956942 + + async def test_no_running_print_for_this_printer_is_a_no_op(self, test_engine, tmp_path): + from backend.app import main as main_module + + maker, printer_id, _archive_id = await _seed(test_engine, tmp_path) + source = _write_3mf(tmp_path / "temp" / DISPATCH_FILENAME) + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is False + + async def test_a_deleted_archive_is_not_resurrected(self, test_engine, tmp_path): + from datetime import datetime, timezone + + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + archive.deleted_at = datetime.now(timezone.utc) + await db.commit() + + source = _write_3mf(tmp_path / "temp" / DISPATCH_FILENAME) + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, DISPATCH_FILENAME): archive_id}, clear=True), + ): + assert await main_module.try_recover_fallback_archive(printer_id, DISPATCH_FILENAME, source) is False + + +class TestTheGiveUpReasonIsRecorded: + @pytest.mark.filterwarnings("ignore::pytest.PytestWarning") + async def test_the_cooloff_slug_is_distinct_from_the_storage_verdicts(self): + """The retry decision keys off it: a cool-off clears in minutes with the + file still on the printer, while an eMMC job never appears at any FTPS + path and retrying it is the sweep #2780 removed.""" + from backend.app.services.print_storage import ( + REASON_FTPS_COOLOFF, + REASON_INTERNAL_STORAGE, + REASON_NO_EXTERNAL_STORAGE, + ) + + assert REASON_FTPS_COOLOFF not in (REASON_INTERNAL_STORAGE, REASON_NO_EXTERNAL_STORAGE) + + async def test_the_banner_endpoint_does_not_leak_the_new_slug(self): + """The two storage slugs are a UI contract; a cool-off is not one of them + and must degrade to the generic banner rather than a missing string.""" + from backend.app.api.routes.archives import REASON_INTERNAL_STORAGE, REASON_NO_EXTERNAL_STORAGE + from backend.app.services.print_storage import REASON_FTPS_COOLOFF + + assert REASON_FTPS_COOLOFF not in (REASON_INTERNAL_STORAGE, REASON_NO_EXTERNAL_STORAGE) + + +class TestTheCooloffRetry: + """The other half: nothing may ever download the file on its own.""" + + async def test_the_retry_recovers_from_the_shared_cache(self, test_engine, tmp_path, monkeypatch): + """The cover endpoint's copy is the same bytes, so the retry spends no + FTP connection when the cache already holds it.""" + import asyncio + + from backend.app import main as main_module + from backend.app.services import bambu_ftp + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + source = _write_3mf(tmp_path / "temp" / DISPATCH_FILENAME) + monkeypatch.setattr(main_module, "_FALLBACK_3MF_RETRY_DELAYS_SECONDS", (0.01,)) + bambu_ftp.cache_3mf_download(printer_id, DISPATCH_FILENAME, source) + + try: + with patch.object(main_module, "async_session", maker): + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, archive_id=archive_id, filenames=[DISPATCH_FILENAME] + ) + task = main_module._fallback_3mf_retry_tasks[printer_id] + await asyncio.wait_for(task, timeout=5) + finally: + bambu_ftp.clear_3mf_cache(printer_id, delete_files=False) + + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + assert archive.file_path + assert not archive.extra_data.get("no_3mf_available") + + async def test_the_retry_stops_once_the_archive_has_a_3mf(self, test_engine, tmp_path, monkeypatch): + """Something else recovered it first — usually the cover endpoint.""" + import asyncio + + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + archive.file_path = "archives/1/real/Desktop_Goose.gcode.3mf" + await db.commit() + + monkeypatch.setattr(main_module, "_FALLBACK_3MF_RETRY_DELAYS_SECONDS", (0.01, 0.01)) + downloads = [] + + async def _never(*args, **kwargs): + downloads.append(args) + return False + + with ( + patch.object(main_module, "async_session", maker), + patch.object(main_module, "download_file_try_paths_async", _never), + ): + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, archive_id=archive_id, filenames=[DISPATCH_FILENAME] + ) + await asyncio.wait_for(main_module._fallback_3mf_retry_tasks[printer_id], timeout=5) + + assert downloads == [] + + async def test_a_second_schedule_replaces_the_first(self, test_engine, tmp_path, monkeypatch): + """One printer prints one job at a time; two live retry tasks would race + to write the same row.""" + import asyncio + + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + monkeypatch.setattr(main_module, "_FALLBACK_3MF_RETRY_DELAYS_SECONDS", (30.0,)) + + with patch.object(main_module, "async_session", maker): + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, archive_id=archive_id, filenames=[DISPATCH_FILENAME] + ) + first = main_module._fallback_3mf_retry_tasks[printer_id] + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, archive_id=archive_id, filenames=[DISPATCH_FILENAME] + ) + second = main_module._fallback_3mf_retry_tasks[printer_id] + + assert first is not second + await asyncio.sleep(0) + assert first.cancelled() or first.done() + second.cancel() + with pytest.raises(asyncio.CancelledError): + await second + main_module._fallback_3mf_retry_tasks.pop(printer_id, None) + + async def test_the_retry_downloads_from_the_printer_when_the_cache_is_empty( + self, test_engine, tmp_path, monkeypatch + ): + """Nothing else fetched the file, so the retry has to go and get it — + the branch the reporter would have hit had they never opened the card.""" + import asyncio + + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + monkeypatch.setattr(main_module, "_FALLBACK_3MF_RETRY_DELAYS_SECONDS", (0.01,)) + # Left on the real archive dir: ArchiveService stores the destination + # relative to settings.base_dir, so a temp path outside it cannot be + # archived at all. + asked: list[list[str]] = [] + + async def _serve(ip, code, paths, dest, **kwargs): + asked.append(list(paths)) + _write_3mf(Path(dest)) + return paths[0] + + with ( + patch.object(main_module, "async_session", maker), + patch.object(main_module, "ftps_handshake_blocked", return_value=False), + patch.object(main_module, "get_ftp_retry_settings", return_value=(True, 3, 2.0, 30.0)), + patch.object(main_module, "download_file_try_paths_async", _serve), + ): + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, archive_id=archive_id, filenames=[DISPATCH_FILENAME] + ) + await asyncio.wait_for(main_module._fallback_3mf_retry_tasks[printer_id], timeout=5) + + assert asked, "the retry never asked the printer for the file" + async with maker() as db: + archive = await db.get(PrintArchive, archive_id) + assert archive.file_path + assert archive.id == archive_id + + async def test_a_printer_still_in_cool_off_is_not_contacted(self, test_engine, tmp_path, monkeypatch): + """Retrying into a live cool-off is the failure that created the fallback.""" + import asyncio + + from backend.app import main as main_module + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + monkeypatch.setattr(main_module, "_FALLBACK_3MF_RETRY_DELAYS_SECONDS", (0.01,)) + downloads = [] + + async def _never(*args, **kwargs): + downloads.append(args) + return False + + with ( + patch.object(main_module, "async_session", maker), + patch.object(main_module, "ftps_handshake_blocked", return_value=True), + patch.object(main_module, "download_file_try_paths_async", _never), + ): + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, archive_id=archive_id, filenames=[DISPATCH_FILENAME] + ) + await asyncio.wait_for(main_module._fallback_3mf_retry_tasks[printer_id], timeout=5) + + assert downloads == [] + + +class TestConcurrentRecoveryIsSerialised: + async def test_two_racing_callers_produce_one_archive_directory(self, test_engine, tmp_path): + """The cover endpoint coalesces by view, so two views race each other — + and the cool-off retry can land on top of either. Unserialised, each + caller reads file_path == "" and runs its own copy, leaving the row + pointing at one timestamped directory with the others orphaned.""" + import asyncio + + from backend.app import main as main_module + from backend.app.core.config import settings as app_config + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + # A name unique to this run. `archive_print` builds its directory as + # "_" with exist_ok=True, so a + # shared stem collides with the directory another test in this file made + # a moment ago, and the count below would measure that instead. + unique = f"Racing_{uuid.uuid4().hex[:12]}.gcode.3mf" + source = _write_3mf(tmp_path / "temp" / unique) + printer_root = app_config.archive_dir / str(printer_id) + before = set(printer_root.iterdir()) if printer_root.exists() else set() + + with ( + patch.object(main_module, "async_session", maker), + patch.dict(main_module._active_prints, {(printer_id, unique): archive_id}, clear=True), + ): + results = await asyncio.gather( + *(main_module.try_recover_fallback_archive(printer_id, unique, source) for _ in range(4)) + ) + + # Exactly one caller did the work; the rest saw a recovered archive. + assert results.count(True) == 1 + created = (set(printer_root.iterdir()) if printer_root.exists() else set()) - before + assert len(created) == 1, f"expected one archive directory, got {sorted(p.name for p in created)}" + + async with maker() as db: + rows = (await db.execute(select(PrintArchive).where(PrintArchive.printer_id == printer_id))).scalars().all() + assert [row.id for row in rows] == [archive_id] + assert (app_config.base_dir / rows[0].file_path).is_file() + + +class TestTheRetryWritesInsideTheDataVolume: + async def test_a_path_shaped_name_cannot_escape_the_temp_directory(self, test_engine, tmp_path, monkeypatch): + """MQTT hands `filename` over as a path on some firmware — the print-start + log shows "/data/Metadata/plate_1.gcode". Joining that onto a directory + with `/` yields the absolute path itself, so the temp write has to reduce + every candidate to a bare name of its own accord.""" + import asyncio + + from backend.app import main as main_module + from backend.app.core.config import settings as app_config + + maker, printer_id, archive_id = await _seed(test_engine, tmp_path) + monkeypatch.setattr(main_module, "_FALLBACK_3MF_RETRY_DELAYS_SECONDS", (0.01,)) + temp_root = (app_config.archive_dir / "temp").resolve() + written: list[Path] = [] + + async def _record(ip, code, paths, dest, **kwargs): + written.append(Path(dest)) + return None # a miss, so the loop walks every candidate + + with ( + patch.object(main_module, "async_session", maker), + patch.object(main_module, "ftps_handshake_blocked", return_value=False), + patch.object(main_module, "get_ftp_retry_settings", return_value=(True, 3, 2.0, 30.0)), + patch.object(main_module, "download_file_try_paths_async", _record), + ): + main_module._schedule_fallback_3mf_retry( + printer_id=printer_id, + archive_id=archive_id, + filenames=[ + "/data/Metadata/plate_1.gcode", + "../../../../etc/passwd", + "/etc/cron.d/evil.3mf", + "..", + ], + ) + await asyncio.wait_for(main_module._fallback_3mf_retry_tasks[printer_id], timeout=5) + + assert written, "the retry never attempted a download" + for dest in written: + assert dest.resolve().parent == temp_root, f"{dest} escaped {temp_root}" + + +class TestPhotosSurviveRecovery: + """Recovery moves the archive's directory, because `archive_dir` derives it + from `file_path` and that goes from empty to a real path. A photo uploaded + to the empty card while the print ran is still where it was put.""" + + async def test_a_photo_written_before_recovery_is_still_found_after(self, tmp_path, monkeypatch): + from types import SimpleNamespace + + from backend.app.core.config import settings as app_config + from backend.app.utils.archive_paths import find_archive_photo + + monkeypatch.setattr(app_config, "archive_dir", tmp_path / "archive") + monkeypatch.setattr(app_config, "base_dir", tmp_path) + + archive = SimpleNamespace(id=83, file_path="") + + # Uploaded while the archive was still an empty fallback. + before_dir = tmp_path / "archive" / "83" / "photos" + before_dir.mkdir(parents=True) + (before_dir / "snap.jpg").write_bytes(b"jpeg") + assert find_archive_photo(archive, "snap.jpg") == before_dir / "snap.jpg" + + # The 3MF turns up and the row gains a file_path in a new directory. + archive.file_path = "archive/1/20260825_000000_Desktop_Goose/Desktop_Goose.gcode.3mf" + (tmp_path / "archive/1/20260825_000000_Desktop_Goose").mkdir(parents=True) + + assert find_archive_photo(archive, "snap.jpg") == before_dir / "snap.jpg" + + async def test_the_current_directory_still_wins(self, tmp_path, monkeypatch): + from types import SimpleNamespace + + from backend.app.core.config import settings as app_config + from backend.app.utils.archive_paths import find_archive_photo + + monkeypatch.setattr(app_config, "archive_dir", tmp_path / "archive") + monkeypatch.setattr(app_config, "base_dir", tmp_path) + + archive = SimpleNamespace(id=83, file_path="archive/1/run/Desktop_Goose.gcode.3mf") + current = tmp_path / "archive/1/run/photos" + current.mkdir(parents=True) + (current / "snap.jpg").write_bytes(b"new") + stale = tmp_path / "archive" / "83" / "photos" + stale.mkdir(parents=True) + (stale / "snap.jpg").write_bytes(b"old") + + assert find_archive_photo(archive, "snap.jpg") == current / "snap.jpg" diff --git a/backend/tests/unit/test_internal_storage_probe_2856.py b/backend/tests/unit/test_internal_storage_probe_2856.py index da115e91e..6d066cf94 100644 --- a/backend/tests/unit/test_internal_storage_probe_2856.py +++ b/backend/tests/unit/test_internal_storage_probe_2856.py @@ -406,6 +406,23 @@ class TestPrintStart: probe.assert_not_awaited() assert _fallback(added).extra_data["no_3mf_reason"] == "internal_storage" + @pytest.mark.asyncio + async def test_a_cool_off_on_an_emmc_job_schedules_no_retry(self): + """#2957 added a retry for a cool-off give-up, because that one clears + in minutes with the file still on the printer. This is not that: the + file is on internal eMMC and will not appear at any FTPS path however + long we wait, so the retry must not be scheduled here.""" + from backend.app.main import _fallback_3mf_retry_tasks + + added = [] + before = dict(_fallback_3mf_retry_tasks) + + with patch("backend.app.main._schedule_fallback_3mf_retry") as schedule: + await _run_print_start("brtc://emmc/test.gcode.3mf", probe_hit=None, added=added, handshake_blocked=True) + + schedule.assert_not_called() + assert _fallback_3mf_retry_tasks == before + @pytest.mark.asyncio async def test_a_gcode_job_is_not_probed_for(self): """Nothing names a 3MF, so there is no name to ask about and the skip