diff --git a/CHANGELOG.md b/CHANGELOG.md index 7b4731ef9..712fb16f4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -31,6 +31,8 @@ All notable changes to Bambuddy will be documented in this file. - **Error and warning toasts now stay up twice as long** — Every pop-up notification disappeared after three seconds regardless of what it said. That is about right for "Settings saved", which confirms something you just did and is skimmed rather than read, but errors and warnings are a different kind of message: they carry a reason, often one relayed from the printer or the backend, and they run to a couple of lines. Three seconds was not long enough to finish reading one, and a missed error message is gone for good — there is no notification history to go back to. Errors and warnings now hold for six seconds. Success and informational toasts keep the three-second default, so the common case of clicking something and seeing it confirmed is unchanged, and the close button and the manual dismiss work exactly as before on all of them. The background print-dispatch toast is unaffected: it stays up while it has work in progress and clears itself shortly after the last job settles. Covered by frontend tests. ### Fixed +- **Every finish photo taken of a print that arrived without a 3MF was written and then never readable (#1820, reported by @ojimpo)** — A print Bambuddy cannot fetch a 3MF for still gets an archive, and that archive has no file to derive its folder from. The finish-photo capture noticed and put the picture in a folder named after the archive; everything that later went looking for it worked the folder out from the missing file instead, which quietly resolved to the top of the data directory. So the photo was written in one place and looked for in another. Opening it returned "Photo not found", deleting it removed the name from the archive and left the file on the disk forever, and a finish photo could never be attached to a Pushover or Telegram notification for such a print. Photos uploaded by hand happened to work, because the upload agreed with the reader rather than with the capture — those are still where they were put and still open normally. Only archives with no 3MF were affected; every other archive has always had a folder of its own. Covered by backend tests. +- **Filament tracking now says when it charges nothing to a spool, instead of leaving no trace (#1820, reported by @ojimpo)** — When a print arrives without a 3MF there is no sliced weight to report, so both the built-in inventory and Spoolman fall back to the drop in the AMS's own remaining-percentage reading. That reading is coarse, and on some printers it is worse than coarse: the reporter measured it *rising* during a print, swinging five points either way over a single job, sitting at 100% for the whole of a 36-minute print on a freshly loaded spool, and going negative on a nearly empty one. Each of those ends with nothing written, and until now nothing said so — the log line read "no spools updated", which is exactly what a print with nothing to charge also prints. Two of the reporter's prints went uncounted that way, for two different reasons, and neither was distinguishable from normal. Each case now names the slot and the two readings it compared, on both the built-in and the Spoolman path, so the prints that need a manual correction can be found. A slot whose reading is unusable at print start is now named at print start as well, rather than simply vanishing from the calculation. Fixed alongside it: the Spoolman side considered *every* slot whose reading had moved, not only the ones the print used, so swapping a spool into an idle slot during a print could be charged as if that spool had printed. The built-in inventory has refused to do that since #1269; the Spoolman path now uses the same evidence — the print's slot mapping, any tray it switched to mid-print, and the tray it began on, which for a print started from the printer's own screen is usually the only one of the three there is. Where none of them is known, every slot is still considered, as before. **This does not make the fallback more accurate** — at one percent per step, a single step is around ten grams on a one-kilogram spool, so a small print cannot be resolved by it at all. What changes is that it stops being silent about it. - **A printer with more than one plug could show the wrong one as its power, complete with the buttons that switch the printer off (#2830)** — The Power row on the printer card names a plug, shows what it is drawing, and carries the auto-off and on/off buttons. Which plug it lands on was decided by nothing at all: it took the first one the database happened to hand back that was not a Home Assistant script. For the reporter that was an enclosure exhaust fan with no power monitoring, added before the outlet the X1C is plugged into — so the card showed the fan's name with `--` where the wattage goes, offered to switch the printer off by cutting the fan, and pushed the metered outlet down into the small row of Home Assistant buttons underneath. The fan was marked as not powering the printer and hidden from the card, and both settings were ignored. They are now the first things consulted. A plug that can be switched at all comes first — a Home Assistant script can only be run, and an MQTT plug is monitor-only, so the on/off button answers either with an error — then the plug that feeds the printer, then one that is enabled, then one the user has not hidden, then one that can actually report watts, and equal plugs settle by age so the answer is the same every time — which it previously was not: the query had no ordering, so on PostgreSQL editing an unrelated field on a plug could move its row and silently change which plug the card called the printer's power. Hidden and disabled are used to rank plugs rather than to rule them out, because a printer with a single plug still needs its Power row: that row holds the on/off button, and the Home Assistant buttons are drawn inside it. Powering the printer is ranked above being visible on purpose. The two only disagree when someone hides the plug that genuinely feeds the printer, and letting the display setting win there would point the power buttons at an accessory, which is the fault #2629 fixed for automatic power-on. Whether a plug reports watts is read from how it is set up rather than measured — this runs every time a card is drawn, and asking every plug in turn would put a network round trip into it — so it only ever breaks a tie between plugs that are equal on everything else. One thing that was wrong before and would have become visible now is fixed with it: the main plug is no longer repeated as a button in the Home Assistant row directly below itself. A printer whose only entities are scripts is left exactly as it was, script button and all — there the Power row is a fallback rather than a duplicate, and reaching a script through it would cost a confirmation dialog the button never needed. Covered by backend tests. - **A finished job stayed in the queue at 0% and blocked everything behind it until it was cancelled by hand (#2829)** — The progress bar emptied, the job never cleared, and the next job for that printer would not start. Bambuddy has no run identifier to match a completion against, so it finds the job to close by printer and "currently printing" alone. A check added three days earlier compares the finished print's name against the file the job was sent with, so that the printer's own automatic calibration runs cannot close somebody's job early — and it compared the two names letter for letter. The printer does not send the name back the way it received it: it puts underscores where the file has spaces, so `H2D_Carbon_Filter_(V2)_Body & Solid Lid` came back as `H2D_Carbon_Filter_(V2)_Body_&_Solid_Lid`, the check called that a different print, and the job was left running forever. It also shortens long names and marks the cut, which would have done the same to anything with a long title. Both are now understood, using the same rule the rest of Bambuddy has always applied when matching these names. The check keeps doing its real job: on the same printer, on the same day, it correctly turned away a completion for the printer's own pressure-advance calibration. **If a job of yours is stuck like this, cancelling it is still the way to clear it — the fix stops it happening again rather than repairing the row.** Since the whole failure was one comparison being stricter than reality, and a stuck job is far more damaging than a job closed slightly late, the scheduler now also closes a job by itself if it is still marked as printing five minutes after the printer went quiet. That is well outside anything normal — a real completion lands within seconds — so it only ever sees a job that was already stuck, and it does not fire on a printer Bambuddy has lost contact with. Covered by backend tests. - **The printer card's thumbnail dropped to the placeholder after leaving the page and coming back, until the browser was reloaded (#2826, reported by @chitrangdesign)** — The thumbnail's address carries the print's name so that starting a different print fetches a different picture. That name does not change while a print runs, so returning to the printers page asked for the very same address again and the browser answered from memory without going to the network at all. The card only ever learned that its picture had arrived from the browser telling it so, and on a picture that was already in hand that announcement raced against the card's own setup, which assumed nothing had arrived yet. When the announcement came first the setup undid it, and nothing put it right afterwards, because the address stays the same for the rest of the print. The card now asks the picture whether it is showing something rather than assuming it is not, which settles the race whichever way round it happens. Being a race is also why it happened every single time for the reporter and not once on the machine it was tested on, and why nothing showed up in the browser's network panel: there was no request to show. Only the printer card was affected -- archive thumbnails use a different address every time and never had it. Covered by frontend tests. diff --git a/backend/app/api/routes/archives.py b/backend/app/api/routes/archives.py index f3c10cbce..ce3ddf907 100644 --- a/backend/app/api/routes/archives.py +++ b/backend/app/api/routes/archives.py @@ -32,8 +32,8 @@ from backend.app.services.archive import ArchiveService from backend.app.services.design_settings import overrides_from_config from backend.app.services.filament_requirements import annotate_rack_groups from backend.app.services.print_storage import REASON_INTERNAL_STORAGE, REASON_NO_EXTERNAL_STORAGE +from backend.app.utils.archive_paths import archive_photos_dir, find_archive_photo from backend.app.utils.http import build_content_disposition -from backend.app.utils.safe_path import safe_join_under from backend.app.utils.threemf_tools import ( default_plate_gcode_name, expand_to_project_slots, @@ -2932,10 +2932,10 @@ async def upload_photo( if not file.filename or not file.filename.lower().endswith((".jpg", ".jpeg", ".png", ".webp")): raise HTTPException(400, "File must be an image (.jpg, .jpeg, .png, .webp)") - # Get archive directory - archive_dir = settings.base_dir / Path(archive.file_path).parent - photos_dir = archive_dir / "photos" - photos_dir.mkdir(exist_ok=True) + # Get archive directory. parents=True because an archive with no 3MF owns + # //, which nothing else has necessarily created yet. + photos_dir = archive_photos_dir(archive) + photos_dir.mkdir(parents=True, exist_ok=True) # Generate unique filename import uuid @@ -2982,15 +2982,14 @@ async def get_photo( if not archive.photos or filename not in archive.photos: raise HTTPException(404, "Photo not found") - archive_dir = settings.base_dir / Path(archive.file_path).parent - photos_dir = archive_dir / "photos" # Defence-in-depth: even though the membership check above already - # constrains `filename` to UUID-generated names from upload, the - # resolve + containment check guards against future code paths that - # might populate `archive.photos` from a less-trusted source. - photo_path = safe_join_under(photos_dir, filename) + # constrains `filename` to UUID-generated names from upload, + # find_archive_photo resolves and containment-checks each candidate, + # guarding against future code paths that might populate + # `archive.photos` from a less-trusted source. + photo_path = find_archive_photo(archive, filename) - if not photo_path.exists(): + if photo_path is None: raise HTTPException(404, "Photo not found") # Determine media type @@ -3026,11 +3025,11 @@ async def delete_photo( if not archive.photos or filename not in archive.photos: raise HTTPException(404, "Photo not found") - # Delete file — same defence-in-depth as get_photo above. - archive_dir = settings.base_dir / Path(archive.file_path).parent - photos_dir = archive_dir / "photos" - photo_path = safe_join_under(photos_dir, filename) - if photo_path.exists(): + # Delete file — same lookup as get_photo above, so a photo that is + # readable is also deletable. Removing the name while leaving the file is + # how a no-3MF archive accumulated photos nobody could see or remove. + photo_path = find_archive_photo(archive, filename) + if photo_path is not None: photo_path.unlink() # Update archive photos list diff --git a/backend/app/core/database.py b/backend/app/core/database.py index 69d915ec4..ea5c1db5b 100644 --- a/backend/app/core/database.py +++ b/backend/app/core/database.py @@ -2374,6 +2374,7 @@ async def run_migrations(conn): layer_usage TEXT, filament_properties TEXT, tray_remain_start TEXT, + tray_now_at_start INTEGER, UNIQUE(printer_id, archive_id) ) """ @@ -2389,6 +2390,7 @@ async def run_migrations(conn): layer_usage TEXT, filament_properties TEXT, tray_remain_start TEXT, + tray_now_at_start INTEGER, UNIQUE(printer_id, archive_id) ) """, @@ -2397,6 +2399,18 @@ async def run_migrations(conn): # the original schema: add tray_remain_start, and relax filament_usage's # NOT NULL so the no-3MF branch can persist a remain-only tracking row. await _safe_execute(conn, "ALTER TABLE active_print_spoolman ADD COLUMN tray_remain_start TEXT") + # Which slot the print was drawing from at the start, so the remain%-delta + # fallback can tell a slot this print used from one it never touched + # (#1820). Nullable, because a row written mid-upgrade has no answer to + # give. INTEGER is spelled the same either way; the branch is only for + # IF NOT EXISTS, which SQLite's ALTER TABLE does not accept. + if is_sqlite(): + await _safe_execute(conn, "ALTER TABLE active_print_spoolman ADD COLUMN tray_now_at_start INTEGER") + else: + await _safe_execute( + conn, + "ALTER TABLE active_print_spoolman ADD COLUMN IF NOT EXISTS tray_now_at_start INTEGER", + ) if is_sqlite(): # SQLite can't ALTER COLUMN; patch sqlite_master directly. Mirrors the # users.password_hash NULL-relaxation a few hundred lines below — see diff --git a/backend/app/main.py b/backend/app/main.py index 08524f0c9..18d473dc4 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -6327,13 +6327,12 @@ async def on_print_complete(printer_id: int, data: dict): import uuid from datetime import datetime - from pathlib import Path - if archive.file_path: - archive_dir = app_settings.base_dir / Path(archive.file_path).parent - else: + from backend.app.utils.archive_paths import archive_dir as resolve_archive_dir + + if not archive.file_path: logger.warning("[PHOTO-BG] Archive %s has no file_path, using fallback dir", archive_id) - archive_dir = app_settings.archive_dir / str(archive.id) + archive_dir = resolve_archive_dir(archive) photo_filename = None # Prefer the timelapse last-frame source when a timelapse was @@ -6653,15 +6652,10 @@ async def on_print_complete(printer_id: int, data: dict): # Read finish photo bytes for image attachment (e.g. Pushover) try: - from pathlib import Path + from backend.app.utils.archive_paths import find_archive_photo - photo_path = ( - app_settings.base_dir - / Path(archive.file_path).parent - / "photos" - / finish_photo_filename - ) - if photo_path.exists(): + photo_path = find_archive_photo(archive, finish_photo_filename) + if photo_path is not None: photo_bytes = await asyncio.to_thread(photo_path.read_bytes) if len(photo_bytes) <= 2_500_000: archive_data["image_data"] = photo_bytes diff --git a/backend/app/models/active_print_spoolman.py b/backend/app/models/active_print_spoolman.py index c5c0f1f4a..c4d4dbb99 100644 --- a/backend/app/models/active_print_spoolman.py +++ b/backend/app/models/active_print_spoolman.py @@ -51,3 +51,14 @@ class ActivePrintSpoolman(Base): # ``tray_remain_start`` snapshot at usage_tracker.py:301. # Format: {"-": {"remain": int, "tray_uuid": str}, ...} tray_remain_start: Mapped[dict | None] = mapped_column(JSON, nullable=True) + + # Global tray id the printer was drawing from when the print started. + # Evidence of which slot the print actually used, for the remain%-delta + # fallback (#1269 on the internal side, #1820 here): without it, a spool + # swapped in an untouched slot mid-print reads as consumption and is + # charged to whatever spool that slot was assigned. Often the only + # evidence there is — a print started from the printer's own screen + # carries no ams_mapping and may change tray never. Nullable: rows written + # before this column existed, and printers that report no tray_now, simply + # provide no evidence and are handled as before. + tray_now_at_start: Mapped[int | None] = mapped_column(nullable=True) diff --git a/backend/app/services/spoolman_tracking.py b/backend/app/services/spoolman_tracking.py index f0e2c4fe1..fe87f0097 100644 --- a/backend/app/services/spoolman_tracking.py +++ b/backend/app/services/spoolman_tracking.py @@ -26,6 +26,19 @@ logger = logging.getLogger(__name__) _ZERO_UUID = "00000000000000000000000000000000" _ZERO_TAG_UID = "0000000000000000" +# Highest global tray id that names a real slot. 255 does not: it is +# ``PrinterState.tray_now``'s initial value, what an unparseable reading falls +# back to, and what the field reads while nothing is loaded. The external spool +# reports 254 when it is actually in use, and ``bambu_mqtt`` applies the same +# cut-off when it seeds the tray-change log. Treating 255 as a slot would put +# ``(255, 1)`` into the "slots this print used" evidence and exclude every real +# one -- silently disabling the very fallback this guard protects (#1820). +# +# Applied to ``tray_now`` only. A 255 in the print's mapping or its tray-change +# log was written there by a print and is evidence, however odd; a 255 in +# ``tray_now`` is the field at rest, which is the absence of evidence. +_MAX_REAL_TRAY_ID = 254 + def _is_non_zero_identifier(value: str) -> bool: """Return True when identifier is non-empty and not all zeros.""" @@ -238,7 +251,7 @@ def build_ams_tray_lookup(raw_data: dict) -> dict[int, dict]: return lookup -def _snapshot_tray_remain(raw_data: dict) -> dict[str, dict]: +def _snapshot_tray_remain(raw_data: dict, skipped_out: list[str] | None = None) -> dict[str, dict]: """Capture per-slot ``remain%`` + ``tray_uuid`` at print start so the completion path can compute a remain-delta when 3MF data doesn't cover the slot (or there's no 3MF at all — #1820). @@ -248,6 +261,12 @@ def _snapshot_tray_remain(raw_data: dict) -> dict[str, dict]: values mean the AMS hasn't read the spool yet and a delta would be meaningless. Mirrors the gate in ``usage_tracker.on_print_start:309``. + + A rejected slot is appended to *skipped_out* when one is supplied, so the + caller can say which slots this print will not be able to charge. That is + not hypothetical: an AMS reports a negative ``remain`` on a nearly empty + spool, so the gate can drop the one slot that is about to do the printing + (#1820). """ snapshot: dict[str, dict] = {} ams_raw = raw_data.get("ams", []) @@ -266,6 +285,8 @@ def _snapshot_tray_remain(raw_data: dict) -> dict[str, dict]: "remain": remain, "tray_uuid": tray.get("tray_uuid", "") or "", } + elif skipped_out is not None: + skipped_out.append(f"AMS{ams_id}-T{tray_id}(remain={remain})") vt_tray_raw = raw_data.get("vt_tray") or [] if isinstance(vt_tray_raw, dict): vt_tray_raw = [vt_tray_raw] @@ -281,6 +302,8 @@ def _snapshot_tray_remain(raw_data: dict) -> dict[str, dict]: "remain": remain, "tray_uuid": vt.get("tray_uuid", "") or "", } + elif skipped_out is not None: + skipped_out.append(f"VT{vt_id}(remain={remain})") return snapshot @@ -329,7 +352,17 @@ async def store_print_data( tray_remain_start: dict[str, dict] = {} if state and state.raw_data: ams_trays = build_ams_tray_lookup(state.raw_data) - tray_remain_start = _snapshot_tray_remain(state.raw_data) + skipped_slots: list[str] = [] + tray_remain_start = _snapshot_tray_remain(state.raw_data, skipped_slots) + if skipped_slots: + # Matches what usage_tracker.on_print_start reports for the + # internal inventory, so both backends name the slots that this + # print will not be able to charge at AMS granularity. + logger.info( + "[SPOOLMAN] Printer %s: slots with no usable remain%% at print start: %s", + printer_id, + ", ".join(skipped_slots), + ) # Try to read per-slot filament estimates from the 3MF. Two paths can # leave ``filament_usage`` empty: (1) fallback archive (no .gcode.3mf @@ -409,6 +442,11 @@ async def store_print_data( layer_usage=layer_usage_json, filament_properties=filament_properties, tray_remain_start=tray_remain_start or None, + # Which slot the printer was drawing from when this print began. For a + # print with no ams_mapping -- one started from the printer's own + # screen, which is the case this whole fallback exists for -- it is the + # only evidence of which slot the print used (#1820). + tray_now_at_start=getattr(state, "tray_now", None) if state else None, ) db.add(tracking) await db.commit() @@ -881,6 +919,7 @@ async def _report_partial_usage( current_lookup=current_lookup, handled_global_tray_ids=set(), archive_id=getattr(tracking, "archive_id", -1), + print_used_keys=_print_used_tray_keys(slot_to_tray, getattr(tracking, "tray_now_at_start", None), state), ) return @@ -1026,6 +1065,7 @@ async def report_usage(printer_id: int, archive_id: int): # on read. layer_usage_raw = getattr(tracking, "layer_usage", None) or {} filament_properties = getattr(tracking, "filament_properties", None) or {} + tray_now_at_start = getattr(tracking, "tray_now_at_start", None) printer_serial = await _get_printer_serial(printer_id) # Delete tracking row (we're done with it) @@ -1177,6 +1217,7 @@ async def report_usage(printer_id: int, archive_id: int): current_lookup=current_lookup, handled_global_tray_ids=handled_global_tray_ids, archive_id=archive_id, + print_used_keys=_print_used_tray_keys(slot_to_tray, tray_now_at_start, current), slot_colors_out=slot_colors, slot_materials_out=slot_materials, ) @@ -1197,6 +1238,49 @@ async def report_usage(printer_id: int, archive_id: int): await _apply_spool_types_to_archive(db, archive_id, filament_usage, slot_materials) +def _print_used_tray_keys( + slot_to_tray: list | None, + tray_now_at_start: int | None, + state, +) -> set[tuple[int, int]]: + """Which AMS slots this print actually drew from, as far as we can tell. + + Mirrors the guard the internal tracker has carried since #1269. Without + it, swapping a spool in a slot the print never touched drops that slot's + ``remain%``, and the remain-delta path reads the drop as consumption and + charges it to whoever the slot is assigned to. That is a phantom write to + an uninvolved spool, and it is likeliest on exactly the prints this + fallback serves -- ones with no 3MF, where nothing else limits which slots + are considered. + + Three sources, matching the internal tracker's: + + - the print's ``ams_mapping``, stored here as ``slot_to_tray``; + - every tray the printer switched to mid-print; + - the tray it was drawing from at the start. + + An empty result means no evidence, not "no slots" -- callers must then + consider every slot, as before, or a printer that reports none of the + three would silently stop being tracked at all. + + Takes the two stored values rather than the tracking row: the caller + deletes that row before it gets this far, and everything read off it is + read into locals beforehand. + """ + keys: set[tuple[int, int]] = set() + for global_tray_id in list(slot_to_tray or []): + if isinstance(global_tray_id, int) and global_tray_id >= 0: + keys.add(_global_tray_id_to_ams_slot(global_tray_id)) + for change in getattr(state, "tray_change_log", None) or []: + if isinstance(change, (tuple, list)) and change: + global_tray_id = change[0] + if isinstance(global_tray_id, int) and global_tray_id >= 0: + keys.add(_global_tray_id_to_ams_slot(global_tray_id)) + if isinstance(tray_now_at_start, int) and 0 <= tray_now_at_start <= _MAX_REAL_TRAY_ID: + keys.add(_global_tray_id_to_ams_slot(tray_now_at_start)) + return keys + + async def _report_remain_delta_for_slots( client, *, @@ -1205,6 +1289,7 @@ async def _report_remain_delta_for_slots( current_lookup: dict[str, dict], handled_global_tray_ids: set[int], archive_id: int, + print_used_keys: set[tuple[int, int]] | None = None, slot_colors_out: dict[int, str] | None = None, slot_materials_out: dict[int, str] | None = None, ) -> int: @@ -1217,6 +1302,7 @@ async def _report_remain_delta_for_slots( unreliable ``tray_weight`` (which is the failure mode #1119 documented). """ spools_updated = 0 + not_in_print: list[str] = [] for slot_key, start in tray_remain_start.items(): try: ams_id_str, tray_id_str = slot_key.split("-", 1) @@ -1236,9 +1322,24 @@ async def _report_remain_delta_for_slots( if global_tray_id in handled_global_tray_ids: continue + # Slots the print never touched (#1269's guard, see _print_used_tray_keys). + # Only enforced when there is evidence of which slots it did use. + # Collected rather than logged per slot: on a four-AMS farm a + # single-colour print leaves fifteen of these, and they are the + # expected case, unlike the "consumed but charged nothing" lines below. + if print_used_keys and (ams_id, tray_id) not in print_used_keys: + not_in_print.append(f"AMS{ams_id}-T{tray_id}") + continue + current = current_lookup.get(slot_key) if not current: - logger.debug("[SPOOLMAN] AMS%d-T%d: no current remain%% at completion, skipping fallback", ams_id, tray_id) + # Reported at info, like the internal tracker's equivalent: on a + # near-empty spool the AMS reports a negative remain%, which the + # snapshot gate rejects, and the slot that was actually printing + # disappears from this path entirely (#1820). + logger.info( + "[SPOOLMAN] AMS%d-T%d: no valid remain%% at completion, nothing charged for this slot", ams_id, tray_id + ) continue # Spool swap mid-print — tray_uuid changed. We don't know how much @@ -1253,11 +1354,28 @@ async def _report_remain_delta_for_slots( delta_pct = start["remain"] - current["remain"] if delta_pct <= 0: + # A fresh spool reads 100% for the first tens of grams and the AMS + # estimate drifts upward on its own, so this covers a real print + # that simply left no trace at AMS granularity -- not only a refill. + # Said out loud so it can be told apart from having nothing to + # charge, which is what "no spools updated" alone looked like. + logger.info( + "[SPOOLMAN] AMS%d-T%d: remain%% did not fall over the print (%d%% -> %d%%), nothing charged", + ams_id, + tray_id, + start["remain"], + current["remain"], + ) continue # No consumption captured at AMS granularity, or refilled spool_id = await _resolve_spool_id_via_slot_assignment(printer_id, ams_id, tray_id) if spool_id is None: - logger.debug("[SPOOLMAN] AMS%d-T%d: no Spoolman slot assignment, skipping fallback", ams_id, tray_id) + logger.info( + "[SPOOLMAN] AMS%d-T%d: consumed %d%% but has no Spoolman slot assignment, nothing charged", + ams_id, + tray_id, + delta_pct, + ) continue # Look up the spool's filament reference weight. Use a fresh GET so @@ -1314,6 +1432,12 @@ async def _report_remain_delta_for_slots( ref_weight, spool_id, ) + if not_in_print: + logger.info( + "[SPOOLMAN] Archive %s: slots not part of this print, left alone: %s", + archive_id, + ", ".join(not_in_print), + ) return spools_updated diff --git a/backend/app/services/usage_tracker.py b/backend/app/services/usage_tracker.py index 5120d5495..c2b0c6543 100644 --- a/backend/app/services/usage_tracker.py +++ b/backend/app/services/usage_tracker.py @@ -791,7 +791,13 @@ async def on_print_complete( gid = change[0] if isinstance(gid, int) and gid >= 0: print_used_keys.add(_global_to_ams_key(gid)) - if session.tray_now_at_start is not None and session.tray_now_at_start >= 0: + # 255 is not a slot: it is what ``tray_now`` reads at rest, before + # the printer has reported one and while nothing is loaded, and an + # unparseable reading falls back to it too. Mapped as a tray id it + # becomes (255, 1), and if it were the only evidence every real + # slot would be excluded and the fallback would charge nothing at + # all (#1820). The external spool reports 254 when in use. + if session.tray_now_at_start is not None and 0 <= session.tray_now_at_start <= 254: print_used_keys.add(_global_to_ams_key(session.tray_now_at_start)) # Collect all trays to check: AMS trays + VT (external) trays @@ -851,7 +857,23 @@ async def on_print_complete( delta_pct = start_remain - current_remain if delta_pct <= 0: - continue # No consumption or tray was refilled + # Not necessarily "nothing was printed". A fresh spool sits + # at 100% for the first tens of grams, and the AMS estimate + # drifts upward on its own, so a real print can end with the + # same or a higher reading than it started with. Said out + # loud because the alternative -- charging nothing, silently + # -- is indistinguishable from having nothing to charge, and + # the operator has no other way to find the prints that went + # uncounted (#1820). + logger.info( + "[UsageTracker] %s: remain%% did not fall over the print (%d%% -> %d%%), " + "nothing charged for printer %d", + tray_label, + start_remain, + current_remain, + printer_id, + ) + continue spool_id = await _resolve_spool_id_for_tray( printer_id=printer_id, diff --git a/backend/app/utils/archive_paths.py b/backend/app/utils/archive_paths.py new file mode 100644 index 000000000..67449d0b9 --- /dev/null +++ b/backend/app/utils/archive_paths.py @@ -0,0 +1,79 @@ +"""Where an archive's files live on disk (#1820). + +An archive normally owns a directory, derived from its ``file_path``: +``//``. An archive created without a 3MF has +``file_path == ""``, and ``Path("").parent`` is ``Path(".")`` -- so every site +that derived the directory that way silently resolved to ``base_dir`` itself, +and all such archives shared one pile. + +The finish-photo capture path spotted that and used ``//`` +instead. Nothing else did, so a captured photo was written to one directory and +then looked for in another: the read 404'd, the delete removed the name and +left the file, and the notification attachment never found the image. Four +sites deriving the same directory four times is what let them drift, so they +now all ask here. + +Photos written before this are still where they were put, which is why lookups +check both locations rather than only the current one. + +Scope note: a *source 3MF* uploaded onto a no-3MF archive has its own layout, +``archive/no_source//``, chosen separately and stored in its own column. +This module does not model that -- do not reach for ``archive_dir`` to find one. +""" + +from __future__ import annotations + +from pathlib import Path + +from backend.app.core.config import settings +from backend.app.utils.safe_path import PathTraversalError, safe_join_under + + +def archive_dir(archive: object) -> Path: + """The directory belonging to *archive*. + + Falls back to ``/`` for an archive with no 3MF, matching + what the finish-photo capture has always written. + """ + file_path = getattr(archive, "file_path", "") or "" + if file_path: + return settings.base_dir / Path(file_path).parent + return settings.archive_dir / str(archive.id) # SEC-PATH-OK: archive.id is an int primary key + + +def archive_photos_dir(archive: object) -> Path: + """Where photos for *archive* are written.""" + return archive_dir(archive) / "photos" # SEC-PATH-OK: constant subdirectory + + +def _legacy_shared_photos_dir(archive: object) -> Path | None: + """Where a no-3MF archive's photos used to be read from, and uploaded to. + + ``/photos``, shared by every no-3MF archive at once. Only ever + consulted for an archive that has no ``file_path``; one with a real path + always resolved correctly and has no second location to check. + """ + if getattr(archive, "file_path", "") or "": + return None + return settings.base_dir / "photos" # SEC-PATH-OK: constant subdirectory + + +def find_archive_photo(archive: object, filename: str) -> Path | None: + """Locate an existing photo, or None if it is in neither location. + + *filename* must already have been checked for membership in + ``archive.photos``; it is joined containment-checked regardless. A name + that fails that check is treated as not found rather than raised on -- + 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)): + if directory is None: + continue + try: + candidate = safe_join_under(directory, filename, http=False) + except PathTraversalError: + return None + if candidate.exists(): + return candidate + return None diff --git a/backend/tests/integration/test_fallback_archive_photos_1820.py b/backend/tests/integration/test_fallback_archive_photos_1820.py new file mode 100644 index 000000000..cbc60bd4a --- /dev/null +++ b/backend/tests/integration/test_fallback_archive_photos_1820.py @@ -0,0 +1,179 @@ +"""Photos on an archive that has no 3MF (#1820). + +The finish-photo capture writes to ``//photos/`` when the +archive has no ``file_path``. Every reader derived the directory from +``file_path`` instead, and ``Path("").parent`` is ``Path(".")`` -- so they all +resolved to ``/photos``. The photo was written to one place and +looked for in another: reads 404'd, deletes removed the name and left the file, +and the notification attachment never found the image. + +The reporter hit the read. These cover all of it, plus the photos already +written to the old location, which must not become unreachable in the fix. +""" + +import pytest +from httpx import AsyncClient + +pytestmark = [pytest.mark.integration, pytest.mark.asyncio] + +PHOTO = "deadbeef.jpg" +JPEG = b"\xff\xd8\xff\xe0" + b"0" * 64 + + +@pytest.fixture +def base_dir(monkeypatch, tmp_path): + """Point both roots at a tmp dir, keeping their real relationship.""" + from backend.app.core.config import settings + + monkeypatch.setattr(settings, "base_dir", tmp_path) + monkeypatch.setattr(settings, "archive_dir", tmp_path / "archive") + return tmp_path + + +async def _fallback_archive(archive_factory, printer_factory, **kwargs): + printer = await printer_factory() + return await archive_factory( + printer.id, + print_name="Started From The Printer", + filename="Started From The Printer.3mf", + file_path="", + **kwargs, + ) + + +def _write(directory, name=PHOTO, content=JPEG): + directory.mkdir(parents=True, exist_ok=True) + (directory / name).write_bytes(content) + + +class TestReadingACapturedPhoto: + async def test_a_captured_finish_photo_is_served( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + """The reporter's 404: written by the capture, unreadable forever.""" + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + _write(base_dir / "archive" / str(archive.id) / "photos") + + response = await async_client.get(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 200 + assert response.content == JPEG + + async def test_a_photo_in_the_old_shared_location_is_still_served( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + """Manual uploads landed in /photos, where reads also looked, + so those worked. Moving the lookup must not orphan them.""" + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + _write(base_dir / "photos") + + response = await async_client.get(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 200 + assert response.content == JPEG + + async def test_a_photo_that_is_in_neither_place_is_404( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + + response = await async_client.get(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 404 + + async def test_a_name_not_on_the_archive_is_404( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + """The membership check comes first and still does.""" + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + _write(base_dir / "archive" / str(archive.id) / "photos", name="someone_elses.jpg") + + response = await async_client.get(f"/api/v1/archives/{archive.id}/photos/someone_elses.jpg") + + assert response.status_code == 404 + + +class TestANormalArchiveIsUnaffected: + async def test_it_reads_from_its_own_directory( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + printer = await printer_factory() + archive = await archive_factory(printer.id, file_path="archives/test/print.gcode.3mf", photos=[PHOTO]) + _write(base_dir / "archives" / "test" / "photos") + + response = await async_client.get(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 200 + + async def test_it_does_not_borrow_from_the_shared_location( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + """An archive with a real path has one location and only one. Looking + in the shared pile as well would serve another archive's photo when + the names ever collided.""" + printer = await printer_factory() + archive = await archive_factory(printer.id, file_path="archives/test/print.gcode.3mf", photos=[PHOTO]) + _write(base_dir / "photos") + + response = await async_client.get(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 404 + + +class TestDeleting: + async def test_a_captured_photo_is_removed_from_disk( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + """It used to drop the name and leave the file, so the photo became + both invisible and unremovable.""" + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + photos_dir = base_dir / "archive" / str(archive.id) / "photos" + _write(photos_dir) + + response = await async_client.delete(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 200 + assert not (photos_dir / PHOTO).exists() + + async def test_a_photo_in_the_old_location_is_removed_too( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + _write(base_dir / "photos") + + response = await async_client.delete(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 200 + assert not (base_dir / "photos" / PHOTO).exists() + + async def test_a_missing_file_still_clears_the_name( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + archive = await _fallback_archive(archive_factory, printer_factory, photos=[PHOTO]) + + response = await async_client.delete(f"/api/v1/archives/{archive.id}/photos/{PHOTO}") + + assert response.status_code == 200 + assert response.json()["photos"] is None + + +class TestUploading: + async def test_an_uploaded_photo_can_be_read_back( + self, async_client: AsyncClient, archive_factory, printer_factory, base_dir + ): + """Upload and read now agree on the location for these archives, which + also means the directory has to be created with its parents.""" + archive = await _fallback_archive(archive_factory, printer_factory) + + upload = await async_client.post( + f"/api/v1/archives/{archive.id}/photos", + files={"file": ("shot.jpg", JPEG, "image/jpeg")}, + ) + assert upload.status_code == 200, upload.text + filename = upload.json()["filename"] + + assert (base_dir / "archive" / str(archive.id) / "photos" / filename).is_file() + + read_back = await async_client.get(f"/api/v1/archives/{archive.id}/photos/{filename}") + assert read_back.status_code == 200 + assert read_back.content == JPEG diff --git a/backend/tests/unit/services/test_usage_tracker.py b/backend/tests/unit/services/test_usage_tracker.py index 786570d24..90e50a930 100644 --- a/backend/tests/unit/services/test_usage_tracker.py +++ b/backend/tests/unit/services/test_usage_tracker.py @@ -186,6 +186,63 @@ class TestOnPrintCompleteAMSDelta: assert results == [] db.commit.assert_not_called() + @pytest.mark.asyncio + async def test_an_unloaded_tray_at_start_does_not_exclude_every_slot(self): + """tray_now reads 255 at rest -- its initial value, and what an + unparseable reading falls back to. Mapped as a tray id that is (255, 1), + so taking it as evidence of which slots the print used would exclude + every real one and charge nothing (#1820).""" + _active_sessions[1] = PrintSession( + printer_id=1, + print_name="test", + started_at=datetime.now(timezone.utc), + tray_remain_start={(0, 0): 80}, + tray_now_at_start=255, + ) + ams_data = [{"id": 0, "tray": [{"id": 0, "remain": 70}]}] + pm = _make_printer_manager(_make_printer_state(ams_data)) + + spool = _make_spool(label_weight=1000, weight_used=0) + db = AsyncMock() + db.execute = AsyncMock( + side_effect=[ + MagicMock(), # _find_3mf_by_filename: library search + MagicMock(), # _find_3mf_by_filename: archive search + MagicMock(scalar_one_or_none=MagicMock(return_value=_make_assignment())), + MagicMock(scalar_one_or_none=MagicMock(return_value=spool)), + ] + ) + + results = await on_print_complete(1, {"status": "completed"}, pm, db) + + assert len(results) == 1 + assert results[0]["weight_used"] == 100.0 + + @pytest.mark.asyncio + async def test_a_delta_that_charges_nothing_says_so(self, caplog): + """Charging nothing has to be distinguishable from having nothing to + charge (#1820). A fresh spool reads 100% for its first tens of grams + and the AMS estimate drifts upward on its own, so this fires on real + prints, not only on refills -- and used to fire in complete silence.""" + import logging + + _active_sessions[1] = PrintSession( + printer_id=1, + print_name="test", + started_at=datetime.now(timezone.utc), + tray_remain_start={(0, 0): 100}, + ) + ams_data = [{"id": 0, "tray": [{"id": 0, "remain": 100}]}] + pm = _make_printer_manager(_make_printer_state(ams_data)) + db = AsyncMock() + + with caplog.at_level(logging.INFO, logger="backend.app.services.usage_tracker"): + results = await on_print_complete(1, {"status": "completed"}, pm, db) + + assert results == [] + assert "did not fall" in caplog.text + assert "100% -> 100%" in caplog.text + @pytest.mark.asyncio async def test_no_session_falls_through_to_3mf(self): """When no session exists, AMS delta path skipped (3MF may still run).""" diff --git a/backend/tests/unit/test_remain_delta_silence_1820.py b/backend/tests/unit/test_remain_delta_silence_1820.py new file mode 100644 index 000000000..55a7a14ba --- /dev/null +++ b/backend/tests/unit/test_remain_delta_silence_1820.py @@ -0,0 +1,282 @@ +"""The remain%-delta fallback must say when it charges nothing (#1820). + +The fallback exists so a print with no 3MF still moves the spool weight. On an +H2S the AMS ``remain%`` it reads is too coarse and too noisy to carry that: the +reporter measured it rising mid-print, swinging +/-5 points over one job, +saturating at 100 on a fresh spool, and going negative near the end of one. + +Two of their prints wrote nothing, each for a different one of those reasons, +and both looked identical from the outside -- ``no spools updated``, which is +also what a print with genuinely nothing to charge prints. The arithmetic is a +separate question; this is about not failing silently, so an operator can tell +which prints need correcting by hand. +""" + +import logging +import types + +import pytest + +from backend.app.services.spoolman_tracking import ( + _print_used_tray_keys, + _report_remain_delta_for_slots, + _snapshot_tray_remain, +) + +pytestmark = pytest.mark.unit + + +def _raw(remain, tray_uuid="uuid-a"): + return {"ams": [{"id": 0, "tray": [{"id": 0, "remain": remain, "tray_uuid": tray_uuid}]}]} + + +def _slot(remain, tray_uuid="uuid-a"): + return {"0-0": {"remain": remain, "tray_uuid": tray_uuid}} + + +class _Client: + """Records anything the fallback tries to write.""" + + def __init__(self): + self.used = [] + + async def get_spool(self, spool_id): + return {"filament": {"weight": 1000}} + + async def use_spool(self, spool_id, grams): + self.used.append((spool_id, grams)) + + +async def _run(caplog, **kwargs): + client = _Client() + with caplog.at_level(logging.INFO, logger="backend.app.services.spoolman_tracking"): + written = await _report_remain_delta_for_slots( + client, + printer_id=1, + handled_global_tray_ids=set(), + archive_id=7, + **kwargs, + ) + return client, written, caplog.text + + +class TestTheSnapshotGate: + """A negative remain% -- what the AMS reports on a nearly empty spool -- + keeps the slot out of the snapshot entirely. That is how the reporter's + second print lost the only slot that was printing.""" + + def test_a_negative_remain_is_reported_as_skipped(self): + skipped = [] + + snapshot = _snapshot_tray_remain(_raw(-3), skipped) + + assert snapshot == {} + assert skipped == ["AMS0-T0(remain=-3)"] + + def test_a_valid_remain_is_not_reported(self): + skipped = [] + + snapshot = _snapshot_tray_remain(_raw(42), skipped) + + assert snapshot == {"0-0": {"remain": 42, "tray_uuid": "uuid-a"}} + assert skipped == [] + + def test_the_external_spool_holder_is_reported_too(self): + skipped = [] + + _snapshot_tray_remain({"vt_tray": {"id": 254, "remain": -1}}, skipped) + + assert skipped == ["VT254(remain=-1)"] + + def test_the_collector_is_optional(self): + """Two of the three call sites pass nothing; they must still work.""" + assert _snapshot_tray_remain(_raw(-3)) == {} + + +@pytest.mark.asyncio +class TestNothingCharged: + async def test_a_spool_still_reading_full_is_reported(self, caplog): + """The reporter's first print: 36 minutes on a fresh spool, 100% at + both ends, so the delta was zero and the slot was skipped in silence.""" + client, written, text = await _run(caplog, tray_remain_start=_slot(100), current_lookup=_slot(100)) + + assert written == 0 + assert client.used == [] + assert "did not fall" in text + assert "100% -> 100%" in text + + async def test_a_reading_that_rose_is_reported(self, caplog): + """remain% moving upward mid-print is noise, not a refill, but either + way nothing is charged and the operator should hear about it.""" + _, written, text = await _run(caplog, tray_remain_start=_slot(12), current_lookup=_slot(17)) + + assert written == 0 + assert "12% -> 17%" in text + + async def test_a_slot_missing_at_completion_is_reported(self, caplog): + """The completion-side twin of the snapshot gate.""" + _, written, text = await _run(caplog, tray_remain_start=_slot(50), current_lookup={}) + + assert written == 0 + assert "no valid remain" in text + + async def test_an_unassigned_slot_names_what_was_lost(self, caplog, monkeypatch): + """It consumed something real and there is nowhere to put it, which is + worth more than the debug line it used to get.""" + monkeypatch.setattr( + "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment", + _fake_resolver(None), + ) + + _, written, text = await _run(caplog, tray_remain_start=_slot(60), current_lookup=_slot(50)) + + assert written == 0 + assert "no Spoolman slot assignment" in text + assert "consumed 10%" in text + + +@pytest.mark.asyncio +class TestItStillWritesWhenItCan: + async def test_a_real_drop_is_charged(self, caplog, monkeypatch): + monkeypatch.setattr( + "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment", + _fake_resolver(42), + ) + + client, written, text = await _run(caplog, tray_remain_start=_slot(60), current_lookup=_slot(50)) + + assert written == 1 + assert client.used == [(42, 100.0)] # 10% of a 1000 g reference weight + assert "did not fall" not in text + + async def test_a_spool_swap_is_still_refused(self, caplog, monkeypatch): + monkeypatch.setattr( + "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment", + _fake_resolver(42), + ) + + client, written, text = await _run( + caplog, + tray_remain_start=_slot(60, "uuid-a"), + current_lookup=_slot(10, "uuid-b"), + ) + + assert written == 0 + assert client.used == [] + assert "swapped mid-print" in text + + +def _fake_resolver(spool_id): + async def _resolve(*_args, **_kwargs): + return spool_id + + return _resolve + + +class TestWhichSlotsThePrintUsed: + """The guard the internal tracker has had since #1269, now on this path + too. Without it a spool swapped into an idle slot mid-print reads as + consumption and is charged to whatever that slot is assigned to.""" + + def test_the_mapping_names_the_slots(self): + """Global tray ids: 0-3 are AMS 0, 4-7 are AMS 1.""" + assert _print_used_tray_keys([0, 5], None, None) == {(0, 0), (1, 1)} + + def test_a_slicer_slot_routed_to_the_external_spool_is_ignored(self): + """-1 means "external spool" in the flat mapping and names no AMS slot; + the external holder arrives as 254/255 when it is really used.""" + assert _print_used_tray_keys([-1], None, None) == set() + assert _print_used_tray_keys([254], None, None) == {(255, 0)} + + def test_an_ams_ht_keeps_its_own_id(self): + assert _print_used_tray_keys([128], None, None) == {(128, 0)} + + def test_a_mid_print_tray_change_counts(self): + """Filament backup switches trays mid-print; the substitute fed part of + the job and has to be chargeable.""" + state = types.SimpleNamespace(tray_change_log=[[0, 0], [5, 120]]) + + assert _print_used_tray_keys(None, None, state) == {(0, 0), (1, 1)} + + def test_the_tray_in_use_at_the_start_counts(self): + """Often the only evidence: a print started from the printer's screen + carries no mapping and may never change tray.""" + assert _print_used_tray_keys(None, 2, None) == {(0, 2)} + + def test_an_unloaded_printer_is_not_read_as_a_slot(self): + """255 is what tray_now reads at rest -- its initial value, the + unparseable-reading fallback, and "nothing loaded". Mapped as a tray id + it becomes (255, 1), and as the only evidence it would exclude every + real slot and charge nothing at all, which is this issue's own bug.""" + assert _print_used_tray_keys(None, 255, None) == set() + + def test_the_external_spool_in_use_is_a_slot(self): + """It reports 254 when actually in use, which is a real slot.""" + assert _print_used_tray_keys(None, 254, None) == {(255, 0)} + + def test_no_evidence_at_all_yields_nothing(self): + """Which callers must read as "consider every slot", not "no slots" -- + otherwise a printer reporting none of the three stops being tracked.""" + assert _print_used_tray_keys(None, None, None) == set() + assert _print_used_tray_keys([], -1, types.SimpleNamespace(tray_change_log=[])) == set() + + def test_a_row_written_before_the_column_existed(self): + """tray_now_at_start is nullable for exactly this reason.""" + assert _print_used_tray_keys([4], None, None) == {(1, 0)} + + +@pytest.mark.asyncio +class TestSlotsThePrintNeverTouched: + async def test_an_untouched_slot_is_not_charged(self, caplog, monkeypatch): + """A spool swapped into an idle slot drops that slot's remain%. Reading + that as consumption is a phantom write to an uninvolved spool.""" + monkeypatch.setattr( + "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment", + _fake_resolver(42), + ) + + client, written, text = await _run( + caplog, + tray_remain_start=_slot(60), + current_lookup=_slot(10), + print_used_keys={(1, 3)}, # this print used AMS1-T3, not AMS0-T0 + ) + + assert written == 0 + assert client.used == [] + assert "slots not part of this print" in text + assert "AMS0-T0" in text + + async def test_the_slot_the_print_used_is_still_charged(self, caplog, monkeypatch): + monkeypatch.setattr( + "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment", + _fake_resolver(42), + ) + + client, written, _ = await _run( + caplog, + tray_remain_start=_slot(60), + current_lookup=_slot(50), + print_used_keys={(0, 0)}, + ) + + assert written == 1 + assert client.used == [(42, 100.0)] + + async def test_without_evidence_every_slot_is_still_considered(self, caplog, monkeypatch): + """The reporter's own prints have no mapping and no tray changes. The + guard must not turn "we don't know" into "charge nothing".""" + monkeypatch.setattr( + "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment", + _fake_resolver(42), + ) + + client, written, _ = await _run( + caplog, + tray_remain_start=_slot(60), + current_lookup=_slot(50), + print_used_keys=set(), + ) + + assert written == 1 + assert client.used == [(42, 100.0)] diff --git a/backend/tests/unit/test_spoolman_no3mf_remain_fallback.py b/backend/tests/unit/test_spoolman_no3mf_remain_fallback.py index 838145bba..1a3ba83da 100644 --- a/backend/tests/unit/test_spoolman_no3mf_remain_fallback.py +++ b/backend/tests/unit/test_spoolman_no3mf_remain_fallback.py @@ -126,6 +126,75 @@ class TestStorePrintDataNo3mf: "0-1": {"remain": 20, "tray_uuid": "BBBB"}, } + @pytest.mark.asyncio + async def test_records_the_tray_the_print_started_on(self): + """A print with no 3MF also has no ams_mapping, so the tray in use at + the start is the only evidence of which slot it drew from — and without + that, the completion path would charge every slot whose remain% moved, + including one a spool was merely swapped into (#1269's fault, on this + path).""" + db = AsyncMock() + db.execute = AsyncMock(side_effect=[MagicMock()]) + db.add = MagicMock() + db.commit = AsyncMock() + + printer_manager = MagicMock() + printer_manager.get_status.return_value = SimpleNamespace( + tray_now=5, + raw_data={"ams": [{"id": 1, "tray": [{"id": 1, "tray_uuid": "AAAA", "remain": 80}]}]}, + ) + + mock_settings = MagicMock() + mock_path = MagicMock() + mock_path.exists.return_value = False + mock_settings.base_dir.__truediv__.return_value = mock_path + + with ( + patch("backend.app.services.spoolman_tracking.app_settings", mock_settings), + patch("backend.app.api.routes.settings.get_setting", AsyncMock(return_value="true")), + ): + await store_print_data( + printer_id=1, + archive_id=42, + file_path="", + db=db, + printer_manager=printer_manager, + ) + + assert db.add.call_args.args[0].tray_now_at_start == 5 + + @pytest.mark.asyncio + async def test_a_printer_that_reports_no_tray_records_none(self): + """Nullable on purpose: no answer is not the same as slot 0.""" + db = AsyncMock() + db.execute = AsyncMock(side_effect=[MagicMock()]) + db.add = MagicMock() + db.commit = AsyncMock() + + printer_manager = MagicMock() + printer_manager.get_status.return_value = SimpleNamespace( + raw_data={"ams": [{"id": 0, "tray": [{"id": 0, "tray_uuid": "AAAA", "remain": 80}]}]}, + ) + + mock_settings = MagicMock() + mock_path = MagicMock() + mock_path.exists.return_value = False + mock_settings.base_dir.__truediv__.return_value = mock_path + + with ( + patch("backend.app.services.spoolman_tracking.app_settings", mock_settings), + patch("backend.app.api.routes.settings.get_setting", AsyncMock(return_value="true")), + ): + await store_print_data( + printer_id=1, + archive_id=42, + file_path="", + db=db, + printer_manager=printer_manager, + ) + + assert db.add.call_args.args[0].tray_now_at_start is None + @pytest.mark.asyncio async def test_no_row_when_no_3mf_and_no_remain_data(self): """If the AMS has no slot with valid remain either (e.g. printer diff --git a/backend/tests/unit/test_spoolman_tray_now_migration_1820.py b/backend/tests/unit/test_spoolman_tray_now_migration_1820.py new file mode 100644 index 000000000..e3356a658 --- /dev/null +++ b/backend/tests/unit/test_spoolman_tray_now_migration_1820.py @@ -0,0 +1,199 @@ +"""Migration for active_print_spoolman.tray_now_at_start (#1820). + +The remain%-delta fallback needs to know which slot a print actually drew from, +or a spool swapped into an idle slot mid-print is charged for consumption it +never had. For a print with no 3MF -- the case this fallback exists for -- the +tray in use at the start is often the only evidence, so it is captured at print +start and has to survive on an upgraded database. + +Nullable, not backfilled: a row written before the column existed has no answer +to give, and inventing 0 would name a real slot. +""" + +from __future__ import annotations + +import pytest +from sqlalchemy import text +from sqlalchemy.ext.asyncio import create_async_engine + +from backend.app.core.database import run_migrations + +LEGACY_TABLE = """ +CREATE TABLE active_print_spoolman ( + id INTEGER PRIMARY KEY AUTOINCREMENT, + printer_id INTEGER NOT NULL, + archive_id INTEGER NOT NULL, + filament_usage TEXT, + ams_trays TEXT NOT NULL, + slot_to_tray TEXT, + layer_usage TEXT, + filament_properties TEXT, + tray_remain_start TEXT, + UNIQUE(printer_id, archive_id) +) +""" + + +@pytest.fixture(autouse=True) +def force_sqlite_dialect(monkeypatch): + """settings.database_url may point at Postgres in dev configs; the test + engine is SQLite, so force the dialect where run_migrations reads it.""" + from backend.app.core import database as database_module, db_dialect + + monkeypatch.setattr(db_dialect, "is_sqlite", lambda: True) + monkeypatch.setattr(db_dialect, "is_postgres", lambda: False) + monkeypatch.setattr(database_module, "is_sqlite", lambda: True) + + +def _register_every_model() -> None: + """Put every table on ``Base.metadata``. + + ``backend.app.models``'s ``__init__`` re-exports only some of them, and + ``run_migrations`` walks the whole schema -- a table that was never + imported is missing, and its ALTER fails the run before reaching ours. + Walking the package keeps this from rotting as models are added. + """ + import importlib + import pkgutil + + import backend.app.models as models_pkg + + for module in pkgutil.iter_modules(models_pkg.__path__): + importlib.import_module(f"backend.app.models.{module.name}") + + +@pytest.fixture +async def legacy_engine(): + """A modern schema whose tracking table predates the column, mid-print.""" + from backend.app.core.database import Base + + _register_every_model() + engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False) + async with engine.begin() as conn: + await conn.run_sync(Base.metadata.create_all) + await conn.execute(text("DROP TABLE active_print_spoolman")) + await conn.execute(text(LEGACY_TABLE)) + await conn.execute( + text( + "INSERT INTO active_print_spoolman (id, printer_id, archive_id, ams_trays, tray_remain_start) " + 'VALUES (1, 1, 42, \'{}\', \'{"0-0": {"remain": 80, "tray_uuid": "AAAA"}}\')' + ) + ) + yield engine + await engine.dispose() + + +async def test_column_missing_before_migration(legacy_engine): + """Sanity check, so the assertion below cannot pass by accident.""" + async with legacy_engine.begin() as conn: + columns = {row[1] for row in await conn.execute(text("PRAGMA table_info(active_print_spoolman)"))} + + assert "tray_now_at_start" not in columns + + +async def test_the_column_is_added_and_the_row_survives(legacy_engine): + """A print running across the upgrade keeps its remain snapshot; it simply + has no tray evidence, which the fallback reads as "consider every slot".""" + async with legacy_engine.begin() as conn: + await run_migrations(conn) + + async with legacy_engine.begin() as conn: + row = ( + await conn.execute( + text("SELECT tray_now_at_start, tray_remain_start FROM active_print_spoolman WHERE id = 1") + ) + ).one() + + assert row[0] is None + assert "AAAA" in row[1] + + +async def test_migration_is_idempotent(legacy_engine): + """Second boot must not fail on the already-present column.""" + async with legacy_engine.begin() as conn: + await run_migrations(conn) + async with legacy_engine.begin() as conn: + await run_migrations(conn) + + async with legacy_engine.begin() as conn: + columns = {row[1] for row in await conn.execute(text("PRAGMA table_info(active_print_spoolman)"))} + + assert "tray_now_at_start" in columns + + +async def test_a_fresh_database_has_the_column(legacy_engine): + """The CREATE TABLE carries it too, so a new install never runs the ALTER.""" + from backend.app.core.database import Base + + _register_every_model() + engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False) + try: + async with engine.begin() as conn: + await conn.run_sync(Base.metadata.create_all) + columns = {row[1] for row in await conn.execute(text("PRAGMA table_info(active_print_spoolman)"))} + finally: + await engine.dispose() + + assert "tray_now_at_start" in columns + + +class TestPostgresBranch: + """CI runs on SQLite, so the Postgres side of the dialect switch would be + dead code without this. Captures the SQL run_migrations would emit, + mirroring test_smart_plug_power_flag_migration_2629. + """ + + @staticmethod + async def _capture_sql(is_sqlite_value: bool) -> list[str]: + from unittest.mock import AsyncMock, MagicMock, patch + + from backend.app.core import database as db_module + + class _AsyncCtxStub: + async def __aenter__(self): + return self + + async def __aexit__(self, *_exc): + return False + + executed_sql: list[str] = [] + + async def fake_safe_execute(_conn, sql: str) -> None: + executed_sql.append(sql) + + fake_conn = MagicMock() + fake_conn.begin_nested = lambda: _AsyncCtxStub() + fake_conn.execute = AsyncMock(return_value=MagicMock(fetchone=MagicMock(return_value=None))) + + with ( + patch("backend.app.core.database.is_sqlite", return_value=is_sqlite_value), + patch("backend.app.core.database._safe_execute", side_effect=fake_safe_execute), + patch("backend.app.core.database._migrate_update_auto_link_constraint", AsyncMock()), + patch("backend.app.core.database._migrate_widen_spoolman_slot_ams_id_range", AsyncMock()), + ): + await db_module.run_migrations(fake_conn) + + return executed_sql + + @staticmethod + def _alter_statements(executed: list[str]) -> list[str]: + return [s for s in executed if "tray_now_at_start" in s and "ALTER" in s.upper()] + + @pytest.mark.asyncio + async def test_pg_branch_is_idempotent_on_its_own(self): + """Postgres has no _safe_execute retry semantics to lean on.""" + stmts = self._alter_statements(await self._capture_sql(is_sqlite_value=False)) + + assert len(stmts) == 1, f"expected exactly one ALTER, got: {stmts!r}" + assert "IF NOT EXISTS" in stmts[0] + assert "INTEGER" in stmts[0] + + @pytest.mark.asyncio + async def test_sqlite_branch_omits_if_not_exists(self): + """SQLite's ALTER TABLE has no IF NOT EXISTS; _safe_execute swallows the + duplicate-column error instead.""" + stmts = self._alter_statements(await self._capture_sql(is_sqlite_value=True)) + + assert len(stmts) == 1 + assert "IF NOT EXISTS" not in stmts[0] + assert "INTEGER" in stmts[0]