Przeglądaj źródła

fix(logs): demote benign "not connected" + "may linger" warnings

  Two warnings polluting every A1 support bundle on healthy prints, both
  unrelated to the timelapse-default behaviour the issue actually reports.

  1. mqtt_bridge.py's post-bind nudge calls request_status_update on the
     real printer's MQTT client to populate the bridge cache without
     waiting for the next periodic pushall. The bind frequently races the
     TLS handshake, especially on A1 firmware. Skip the nudge when
     state.connected is False — the periodic pushall fills the cache
     anyway. The WARNING in bambu_mqtt.py stays for the genuinely-
     actionable callers (refresh-status API, bug reporter).

  2. Post-finish SD-card cleanup (and the symmetric forced-timelapse dir
     walk) used delete_file_async's bool return to drive a WARNING when
     all candidates failed. A1 firmware self-cleans the SD card before
     our cleanup runs — every candidate FTP-DELE returns 550, we burn
     the retry budget, then WARN on a successful print. Introduce
     DeleteResult.{DELETED,NOT_FOUND,FAILED} so the helpers only WARN
     on real network/auth/transient failures. NOT_FOUND advances to the
     next candidate without consuming the 2s backoff. User-facing delete
     endpoint returns 404 on NOT_FOUND.
maziggy 2 miesięcy temu
rodzic
commit
7190fc2d13

Plik diff jest za duży
+ 0 - 0
CHANGELOG.md


+ 6 - 2
backend/app/api/routes/printers.py

@@ -1535,8 +1535,12 @@ async def delete_printer_file(
     if not printer:
         raise HTTPException(404, "Printer not found")
 
-    success = await delete_file_async(printer.ip_address, printer.access_code, path, printer_model=printer.model)
-    if not success:
+    from backend.app.services.bambu_ftp import DeleteResult
+
+    result = await delete_file_async(printer.ip_address, printer.access_code, path, printer_model=printer.model)
+    if result == DeleteResult.NOT_FOUND:
+        raise HTTPException(404, f"File not found on printer: {path}")
+    if result == DeleteResult.FAILED:
         raise HTTPException(500, f"Failed to delete file: {path}")
 
     return {"status": "deleted", "path": path}

+ 68 - 17
backend/app/main.py

@@ -3375,11 +3375,14 @@ async def _cleanup_forced_timelapse(archive_id: int, printer_id: int) -> None:
     # _scan_for_timelapse_with_retries used the original filename when it
     # attached, so the basename of timelapse_path matches the printer-side
     # filename. Try the directories the scanner walks (#1397).
+    from backend.app.services.bambu_ftp import DeleteResult
+
     filename = Path(local_relpath).name
+    any_real_failure = False
     for remote_dir in ("/timelapse", "/timelapse/video", "/record", "/recording"):
         remote_path = f"{remote_dir}/{filename}"
         try:
-            ok = await delete_file_async(
+            result = await delete_file_async(
                 printer.ip_address,
                 printer.access_code,
                 remote_path,
@@ -3388,15 +3391,29 @@ async def _cleanup_forced_timelapse(archive_id: int, printer_id: int) -> None:
         except Exception as e:
             logger.debug("[FORCED-TIMELAPSE] FTP delete attempt failed for %s: %s", remote_path, e)
             continue
-        if ok:
+        if result == DeleteResult.DELETED:
             logger.info("[FORCED-TIMELAPSE] Deleted printer-side timelapse %s", remote_path)
             return
-
-    logger.warning(
-        "[FORCED-TIMELAPSE] Could not delete printer-side timelapse %s for archive %s (file may already be gone)",
-        filename,
-        archive_id,
-    )
+        if result == DeleteResult.FAILED:
+            any_real_failure = True
+
+    # All four dirs returned NOT_FOUND with no actual failures: the printer
+    # never wrote a file under any expected path (or already swept). That's
+    # the normal post-print state on most models — debug, not warning.
+    if any_real_failure:
+        logger.warning(
+            "[FORCED-TIMELAPSE] Could not delete printer-side timelapse %s for archive %s "
+            "(network/auth/transient error)",
+            filename,
+            archive_id,
+        )
+    else:
+        logger.debug(
+            "[FORCED-TIMELAPSE] No printer-side timelapse to delete for %s (archive %s) — "
+            "every candidate dir returned 550",
+            filename,
+            archive_id,
+        )
 
 
 async def on_print_running_observed(printer_id: int, data: dict):
@@ -3786,7 +3803,7 @@ async def on_print_complete(printer_id: int, data: dict):
                     archive_filename = archive_row.scalar_one_or_none()
 
             if printer:
-                from backend.app.services.bambu_ftp import delete_file_async
+                from backend.app.services.bambu_ftp import DeleteResult, delete_file_async
                 from backend.app.utils.filename import derive_remote_filename
 
                 # Primary candidate: the exact path the dispatcher uploaded to
@@ -3804,8 +3821,23 @@ async def on_print_complete(printer_id: int, data: dict):
                     if fallback not in candidate_paths:
                         candidate_paths.append(fallback)
 
+                # Three outcomes track across all candidates so the final log
+                # line reflects what actually happened. The A1 in #1721 always
+                # ends here with ``any_not_found=True`` and the others False
+                # — its firmware auto-cleans the SD card before our cleanup
+                # runs, every candidate FTP-DELE returns 550, and the old
+                # code burned 3 retries × 2 s × 3 candidates per print
+                # logging a misleading "may linger" WARNING on a successful
+                # print.
+                any_deleted = False
+                any_real_failure = False
+                any_not_found = False
+
                 for remote_path in candidate_paths:
-                    # Retry up to 3 times — the printer may still lock the filesystem briefly after a print ends
+                    # Retry only the FAILED case — 550 NOT_FOUND will never
+                    # recover by waiting, so a "file isn't here" answer
+                    # advances immediately to the next candidate without
+                    # consuming the retry budget.
                     for attempt in range(1, 4):
                         try:
                             delete_result = await delete_file_async(
@@ -3814,24 +3846,43 @@ async def on_print_complete(printer_id: int, data: dict):
                                 remote_path,
                                 printer_model=printer.model,
                             )
-                            if delete_result:
-                                logger.info("Deleted %s from printer %s SD card", remote_path, printer.name)
-                                break
                         except Exception as e:
-                            delete_result = False
+                            delete_result = DeleteResult.FAILED
                             logger.warning(
                                 "SD card cleanup attempt %d/3 raised for %s: %s",
                                 attempt,
                                 remote_path,
                                 e,
                             )
-                        if not delete_result and attempt < 3:
+
+                        if delete_result == DeleteResult.DELETED:
+                            any_deleted = True
+                            logger.info("Deleted %s from printer %s SD card", remote_path, printer.name)
+                            break
+                        if delete_result == DeleteResult.NOT_FOUND:
+                            any_not_found = True
+                            break  # 550 will not recover; try next candidate
+                        # FAILED: real error — retry with backoff, then give up
+                        if attempt < 3:
                             await asyncio.sleep(2)
-                        elif not delete_result:
+                        else:
+                            any_real_failure = True
                             logger.warning(
-                                "SD card cleanup failed after 3 attempts for %s (file may linger on SD card)",
+                                "SD card cleanup failed after 3 attempts for %s "
+                                "(network/auth/transient error — file may linger on SD card)",
                                 remote_path,
                             )
+
+                if not any_deleted and not any_real_failure and any_not_found:
+                    # Every candidate said "not here." Either the printer
+                    # firmware swept the SD card itself (common on A1) or the
+                    # dispatcher's upload path doesn't match our candidate
+                    # rule. Either way: nothing to clean up, no warning.
+                    logger.debug(
+                        "SD card cleanup: nothing to delete on %s — every candidate returned 550 "
+                        "(printer likely self-cleaned)",
+                        printer.name,
+                    )
     except Exception as e:
         logger.warning("SD card file cleanup failed for printer %s: %s", printer_id, e)
 

+ 46 - 12
backend/app/services/bambu_ftp.py

@@ -7,6 +7,7 @@ import ssl
 import threading
 import time
 from collections.abc import Awaitable, Callable
+from enum import Enum
 from ftplib import FTP, FTP_TLS  # nosec B402
 from io import BytesIO
 from pathlib import Path
@@ -17,6 +18,22 @@ logger = logging.getLogger(__name__)
 T = TypeVar("T")
 
 
+class DeleteResult(Enum):
+    """Outcome of an FTP delete attempt.
+
+    Distinguishes "file isn't on the printer" (550, recovery impossible by
+    retrying) from "delete failed for some other reason" (network, auth,
+    transient FTP error — worth retrying). The post-print SD-card cleanup in
+    main.py used to flatten both into ``False`` and log a "may linger" WARNING
+    on every successful print where the printer self-cleaned its SD card
+    before our cleanup ran (#1721 reporter's A1).
+    """
+
+    DELETED = "deleted"
+    NOT_FOUND = "not_found"
+    FAILED = "failed"
+
+
 class FileNotOnPrinterError(Exception):
     """Raised when a remote FTP path returns 550 (file not found).
 
@@ -507,14 +524,16 @@ class BambuFTPClient:
                 )
 
             if callback_exception is not None:
-                cleanup_ok = False
+                cleanup_result: DeleteResult = DeleteResult.FAILED
                 try:
-                    cleanup_ok = self.delete_file(remote_path)
+                    cleanup_result = self.delete_file(remote_path)
                 except Exception as cleanup_error:
                     logger.warning("FTP cancel cleanup failed for %s: %s", remote_path, cleanup_error)
 
-                if cleanup_ok:
-                    logger.info("FTP cancel cleanup succeeded for %s", remote_path)
+                # NOT_FOUND is success here — the partial file is gone (printer
+                # may have already swept on cancel), which is the goal.
+                if cleanup_result in (DeleteResult.DELETED, DeleteResult.NOT_FOUND):
+                    logger.info("FTP cancel cleanup succeeded for %s (%s)", remote_path, cleanup_result.value)
                     raise callback_exception
 
                 raise RuntimeError(
@@ -621,17 +640,28 @@ class BambuFTPClient:
         except (OSError, ftplib.Error):
             return False
 
-    def delete_file(self, remote_path: str) -> bool:
-        """Delete a file from the printer."""
+    def delete_file(self, remote_path: str) -> DeleteResult:
+        """Delete a file from the printer.
+
+        Returns :class:`DeleteResult` distinguishing the file-not-found case
+        (550) from network / auth / transient FTP failure. Callers that just
+        want "did it work" should check ``result == DeleteResult.DELETED``.
+        """
         if not self._ftp:
-            return False
+            return DeleteResult.FAILED
 
         try:
             self._ftp.delete(remote_path)
-            return True
+            return DeleteResult.DELETED
+        except ftplib.error_perm as e:
+            if str(e).startswith("550"):
+                logger.debug("FTP delete: %s not on printer (550)", remote_path)
+                return DeleteResult.NOT_FOUND
+            logger.warning("Failed to delete %s: %s", remote_path, e)
+            return DeleteResult.FAILED
         except (OSError, ftplib.Error) as e:
             logger.warning("Failed to delete %s: %s", remote_path, e)
-            return False
+            return DeleteResult.FAILED
 
     def get_file_size(self, remote_path: str) -> int | None:
         """Get the size of a file."""
@@ -1055,23 +1085,27 @@ async def delete_file_async(
     remote_path: str,
     socket_timeout: float | None = None,
     printer_model: str | None = None,
-) -> bool:
+) -> DeleteResult:
     """Async wrapper for deleting a file.
 
+    Returns :class:`DeleteResult` so callers can distinguish ``NOT_FOUND``
+    (550 — file isn't on the printer, no retry value) from ``FAILED``
+    (network / auth / transient — worth retrying or surfacing).
+
     Args:
         socket_timeout: FTP socket timeout for slow connections (e.g., A1 printers)
         printer_model: Printer model for A1-specific workarounds
     """
     loop = asyncio.get_event_loop()
 
-    def _delete():
+    def _delete() -> DeleteResult:
         client = BambuFTPClient(ip_address, access_code, timeout=socket_timeout, printer_model=printer_model)
         if client.connect():
             try:
                 return client.delete_file(remote_path)
             finally:
                 client.disconnect()
-        return False
+        return DeleteResult.FAILED
 
     return await loop.run_in_executor(None, _delete)
 

+ 32 - 12
backend/app/services/virtual_printer/mqtt_bridge.py

@@ -371,18 +371,38 @@ class MQTTBridge:
         # but that fires before the bridge attaches as a raw-message consumer,
         # so without this nudge the cache stays empty until the next periodic
         # query (which can be minutes away).
-        request_fn = getattr(current, "_request_version", None)
-        if callable(request_fn):
-            try:
-                request_fn()
-            except Exception:
-                logger.exception("[%s] MQTT bridge: _request_version failed", self.vp_name)
-        request_status_fn = getattr(current, "request_status_update", None)
-        if callable(request_status_fn):
-            try:
-                request_status_fn()
-            except Exception:
-                logger.exception("[%s] MQTT bridge: request_status_update failed", self.vp_name)
+        #
+        # The bind frequently races the real printer's MQTT TLS handshake — a
+        # slicer-side reconnect re-resolves the client before the underlying
+        # session has reconnected, especially on A1 firmware where the bridge
+        # cycles more aggressively (#1721). When that happens, the nudge is a
+        # no-op — the next periodic pushall populates the cache anyway — but
+        # `request_status_update` logs WARNING on the not-connected return path
+        # and pollutes every support bundle with a benign line.
+        #
+        # Gate both nudges on the client being actually connected. The fall-
+        # through path is unchanged: when the client comes up, the next
+        # `_resolve_client` tick re-enters this branch on identity change OR
+        # the periodic pushall in `bambu_mqtt.py` fills the cache.
+        client_connected = bool(getattr(getattr(current, "state", None), "connected", False))
+        if not client_connected:
+            logger.debug(
+                "[%s] MQTT bridge: post-bind nudge skipped (printer client not connected yet)",
+                self.vp_name,
+            )
+        else:
+            request_fn = getattr(current, "_request_version", None)
+            if callable(request_fn):
+                try:
+                    request_fn()
+                except Exception:
+                    logger.exception("[%s] MQTT bridge: _request_version failed", self.vp_name)
+            request_status_fn = getattr(current, "request_status_update", None)
+            if callable(request_status_fn):
+                try:
+                    request_status_fn()
+                except Exception:
+                    logger.exception("[%s] MQTT bridge: request_status_update failed", self.vp_name)
 
     def _unbind_client(self) -> None:
         if self._target_client is None:

+ 27 - 6
backend/tests/unit/services/test_bambu_ftp.py

@@ -575,26 +575,32 @@ class TestDelete:
 
     def test_delete_success(self, ftp_client_factory, ftp_server):
         """Successful file deletion."""
+        from backend.app.services.bambu_ftp import DeleteResult
+
         ftp_server.add_file("cache/to_delete.bin", b"delete me")
         client = ftp_client_factory()
         client.connect()
         result = client.delete_file("/cache/to_delete.bin")
-        assert result is True
+        assert result == DeleteResult.DELETED
         assert not ftp_server.file_exists("cache/to_delete.bin")
         client.disconnect()
 
     def test_delete_not_found(self, ftp_client_factory):
-        """Deleting a nonexistent file returns False."""
+        """Deleting a nonexistent file returns NOT_FOUND (550, #1721)."""
+        from backend.app.services.bambu_ftp import DeleteResult
+
         client = ftp_client_factory()
         client.connect()
         result = client.delete_file("/cache/no_such_file.bin")
-        assert result is False
+        assert result == DeleteResult.NOT_FOUND
         client.disconnect()
 
     def test_delete_not_connected(self):
-        """Delete when not connected returns False."""
+        """Delete when not connected returns FAILED."""
+        from backend.app.services.bambu_ftp import DeleteResult
+
         client = BambuFTPClient("127.0.0.1", "12345678")
-        assert client.delete_file("/cache/test.bin") is False
+        assert client.delete_file("/cache/test.bin") == DeleteResult.FAILED
 
 
 # ---------------------------------------------------------------------------
@@ -1053,6 +1059,8 @@ class TestAsyncWrappers:
     @pytest.mark.asyncio
     async def test_delete_file_async_success(self, patch_ftp_port):
         """delete_file_async deletes a file."""
+        from backend.app.services.bambu_ftp import DeleteResult
+
         server = patch_ftp_port
         server.add_file("cache/to_async_del.bin", b"delete me")
         result = await delete_file_async(
@@ -1061,9 +1069,22 @@ class TestAsyncWrappers:
             "/cache/to_async_del.bin",
             printer_model="X1C",
         )
-        assert result is True
+        assert result == DeleteResult.DELETED
         assert not server.file_exists("cache/to_async_del.bin")
 
+    @pytest.mark.asyncio
+    async def test_delete_file_async_not_found(self, patch_ftp_port):
+        """delete_file_async distinguishes 550 from real failure (#1721)."""
+        from backend.app.services.bambu_ftp import DeleteResult
+
+        result = await delete_file_async(
+            "127.0.0.1",
+            "12345678",
+            "/cache/never_existed.bin",
+            printer_model="X1C",
+        )
+        assert result == DeleteResult.NOT_FOUND
+
 
 # ---------------------------------------------------------------------------
 # TestFailureScenarios

+ 91 - 5
backend/tests/unit/test_cleanup_forced_timelapse.py

@@ -25,6 +25,7 @@ import pytest
 
 from backend.app import main as main_module
 from backend.app.main import _cleanup_forced_timelapse
+from backend.app.services.bambu_ftp import DeleteResult
 
 
 def _fake_session_factory(rows: dict):
@@ -92,7 +93,7 @@ async def test_not_forced_is_noop(monkeypatch, tmp_path):
     video_path.parent.mkdir(parents=True, exist_ok=True)
     video_path.write_bytes(b"x" * 100)
 
-    delete_mock = AsyncMock(return_value=True)
+    delete_mock = AsyncMock(return_value=DeleteResult.DELETED)
     with patch("backend.app.services.bambu_ftp.delete_file_async", new=delete_mock):
         await _cleanup_forced_timelapse(archive_id=99, printer_id=10)
 
@@ -123,7 +124,7 @@ async def test_forced_deletes_local_and_remote(monkeypatch, tmp_path):
     video_path.write_bytes(b"x" * 100)
 
     # FTP DELE succeeds on the first directory we try.
-    delete_mock = AsyncMock(return_value=True)
+    delete_mock = AsyncMock(return_value=DeleteResult.DELETED)
     with patch("backend.app.services.bambu_ftp.delete_file_async", new=delete_mock):
         await _cleanup_forced_timelapse(archive_id=99, printer_id=10)
 
@@ -158,9 +159,10 @@ async def test_forced_walks_alternate_dirs_when_first_fails(monkeypatch, tmp_pat
     video_path.parent.mkdir(parents=True, exist_ok=True)
     video_path.write_bytes(b"x" * 100)
 
-    # First two attempts fail (False), third succeeds (True). Cleanup
-    # should stop after the third.
-    delete_mock = AsyncMock(side_effect=[False, False, True])
+    # First two dirs report NOT_FOUND (file not there), third succeeds.
+    # Cleanup should stop after the third — and crucially must NOT WARN
+    # because no real network/auth failure happened (#1721).
+    delete_mock = AsyncMock(side_effect=[DeleteResult.NOT_FOUND, DeleteResult.NOT_FOUND, DeleteResult.DELETED])
     with patch("backend.app.services.bambu_ftp.delete_file_async", new=delete_mock):
         await _cleanup_forced_timelapse(archive_id=99, printer_id=10)
 
@@ -203,3 +205,87 @@ async def test_forced_local_cleanup_runs_even_if_ftp_unreachable(monkeypatch, tm
     assert archive.timelapse_path is None
     # All four dirs were attempted before giving up.
     assert delete_mock.await_count == 4
+
+
+@pytest.mark.asyncio
+async def test_forced_no_warning_when_every_dir_returns_not_found(monkeypatch, tmp_path, caplog):
+    """#1721: when every candidate dir returns 550 (file not there) the
+    helper used to emit "Could not delete printer-side timelapse ...
+    (file may already be gone)" at WARNING. That message landed in support
+    bundles for healthy printers whose firmware swept the SD card itself.
+    With DeleteResult.NOT_FOUND signalling, no real failure happened →
+    must be DEBUG, not WARNING.
+    """
+    import logging
+
+    archive = SimpleNamespace(
+        bambuddy_forced_timelapse=True,
+        timelapse_path="archive/1/myprint.mp4",
+    )
+    printer = SimpleNamespace(ip_address="10.0.0.5", access_code="12345678", model="N2S")
+    monkeypatch.setattr(
+        main_module,
+        "async_session",
+        _fake_session_factory({"PrintArchive": archive, "Printer": printer}),
+    )
+
+    video_path = tmp_path / archive.timelapse_path
+    video_path.parent.mkdir(parents=True, exist_ok=True)
+    video_path.write_bytes(b"x" * 100)
+
+    delete_mock = AsyncMock(return_value=DeleteResult.NOT_FOUND)
+    with (
+        caplog.at_level(logging.DEBUG, logger="backend.app.main"),
+        patch("backend.app.services.bambu_ftp.delete_file_async", new=delete_mock),
+    ):
+        await _cleanup_forced_timelapse(archive_id=99, printer_id=10)
+
+    assert delete_mock.await_count == 4
+    warnings = [r for r in caplog.records if r.levelno >= logging.WARNING and "[FORCED-TIMELAPSE]" in r.message]
+    assert warnings == [], f"unexpected WARNING(s): {[w.message for w in warnings]}"
+    debugs = [
+        r for r in caplog.records if r.levelno == logging.DEBUG and "No printer-side timelapse to delete" in r.message
+    ]
+    assert len(debugs) == 1, "expected the 'nothing to delete' debug summary"
+
+
+@pytest.mark.asyncio
+async def test_forced_warns_when_any_dir_returns_failed(monkeypatch, tmp_path, caplog):
+    """Counterpart to the above: a real network/auth/transient FAILED on any
+    dir keeps the WARNING — that's the signal the maintainer actually wants
+    to see.
+    """
+    import logging
+
+    archive = SimpleNamespace(
+        bambuddy_forced_timelapse=True,
+        timelapse_path="archive/1/myprint.mp4",
+    )
+    printer = SimpleNamespace(ip_address="10.0.0.5", access_code="12345678", model="O1C")
+    monkeypatch.setattr(
+        main_module,
+        "async_session",
+        _fake_session_factory({"PrintArchive": archive, "Printer": printer}),
+    )
+
+    video_path = tmp_path / archive.timelapse_path
+    video_path.parent.mkdir(parents=True, exist_ok=True)
+    video_path.write_bytes(b"x" * 100)
+
+    delete_mock = AsyncMock(
+        side_effect=[
+            DeleteResult.NOT_FOUND,
+            DeleteResult.FAILED,
+            DeleteResult.NOT_FOUND,
+            DeleteResult.NOT_FOUND,
+        ]
+    )
+    with (
+        caplog.at_level(logging.WARNING, logger="backend.app.main"),
+        patch("backend.app.services.bambu_ftp.delete_file_async", new=delete_mock),
+    ):
+        await _cleanup_forced_timelapse(archive_id=99, printer_id=10)
+
+    warnings = [r for r in caplog.records if r.levelno >= logging.WARNING and "[FORCED-TIMELAPSE]" in r.message]
+    assert len(warnings) == 1
+    assert "network/auth/transient" in warnings[0].message

+ 16 - 0
backend/tests/unit/test_vp_mqtt_bridge.py

@@ -150,6 +150,22 @@ class TestBridgeLifecycle:
         target.request_status_update.assert_called_once()
         await bridge.stop()
 
+    @pytest.mark.asyncio
+    async def test_post_bind_nudge_skipped_when_target_not_connected(self):
+        """#1721: the bridge can attach before the real printer's MQTT TLS
+        handshake completes. Calling request_status_update on a disconnected
+        client logs WARNING (bambu_mqtt.py:3224); on A1 firmware that
+        reconnects aggressively, every bind cycle pollutes the support bundle
+        with a benign line. The bridge must check state.connected before
+        nudging — the next periodic pushall picks up the cache anyway.
+        """
+        target = _make_paho_client(connected=False)
+        bridge = _make_bridge(_make_server(), target)
+        await bridge.start()
+        target._request_version.assert_not_called()
+        target.request_status_update.assert_not_called()
+        await bridge.stop()
+
 
 # ---------------------------------------------------------------------------
 # Caching: push_status

Niektóre pliki nie zostały wyświetlone z powodu dużej ilości zmienionych plików