Przeglądaj źródła

Recover the preview slice from custom G-code the sidecar cannot parse

Opening the slice dialog on an unsliced project runs a preview slice purely
to ask the slicer which AMS slots the chosen plate consumes. Bambu Studio 2.8
writes {if timelapse_inline_photo} into the machine's time_lapse_gcode but
exports no definition for that variable, so the template is unresolvable the
moment it leaves Studio: an older sidecar stops with a placeholder parse error
before producing any slice_info. The preview returned nothing and the caller
fell back to guessing from painted faces, silently. On the H2D project this
was found with, the guess dropped the support material -- a whole slot off a
four-filament plate.

Retry the preview once with just the named template emptied, still on the
file's own settings. Keeping the embedded settings is what keeps the answer
honest: overriding the process preset instead discards the project's support
configuration, which loses that slot and moves used_g by up to 2x. Measured
against the same file: retry reproduces all four slots gram for gram, a
printer+process override returns three.

Only templates that cannot extrude are eligible -- a start or filament-change
template lays a prime line or purges, so emptying one would move the very
grams the preview reports, and returning nothing beats a confident wrong
number. Verified on a working H2D slice that emptying time_lapse_gcode leaves
every used_g/used_m in slice_info identical.

Match on a normalised option name: the slicer reports timelapse_gcode while
the 3MF stores time_lapse_gcode, so a literal comparison finds nothing.

Decide whether a retry applies before logging, so a slice that recovers does
not announce itself at WARNING twenty seconds before it succeeds.
maziggy 3 tygodni temu
rodzic
commit
15ea11e10b

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


+ 191 - 12
backend/app/services/slice_preview.py

@@ -10,7 +10,14 @@ This module wraps the sidecar's slice call so the endpoint can run a preview
 slice, parse the result's slice_info, and return the actual filament list.
 The preview always uses the file's embedded settings (``slice_without_profiles``):
 the slot-mapping is a model property, independent of process settings, so
-we don't need to thread the user's profile triplet through here.
+we don't need to thread the user's profile triplet through here. That choice
+also protects the numbers — overriding the process preset drops the project's
+own support configuration, which loses whole slots from the answer.
+
+The one thing that can defeat those embedded settings is a custom G-code
+template written by a Studio newer than the sidecar, which fails to parse
+before any slice_info exists. That case gets one retry with the offending
+template blanked; see ``_blank_custom_gcode``.
 
 Results are cached by ``(kind, source_id, plate_id, content_hash)`` so
 repeat opens on the same plate are instant. LRU eviction keeps the cache
@@ -22,7 +29,9 @@ from __future__ import annotations
 
 import asyncio
 import hashlib
+import json
 import logging
+import re
 import zipfile
 from collections import OrderedDict
 from io import BytesIO
@@ -36,6 +45,51 @@ from backend.app.services.slicer_api import (
 
 logger = logging.getLogger(__name__)
 
+_PROJECT_SETTINGS_PATH = "Metadata/project_settings.config"
+
+# The slicer names the offending G-code field in its stderr, e.g.
+#   timelapse_gcode Parsing error at line 13: Not a variable name
+#       {if timelapse_inline_photo}
+_GCODE_PARSE_ERROR_RE = re.compile(
+    r"^\s*([A-Za-z_][A-Za-z0-9_]*)\s+Parsing error at line \d+:",
+    re.MULTILINE,
+)
+
+# Custom G-code fields we are willing to blank to get a preview through.
+#
+# Deliberately narrow, and the narrowness is the whole point: blanking a
+# field that *extrudes* would change the very numbers the preview exists to
+# report. `machine_start_gcode` lays a prime line, `change_filament_gcode`
+# purges — silence either and the returned grams are quietly wrong, which is
+# worse than returning nothing. Everything below only moves the toolhead or
+# emits markers, so removing it cannot alter filament accounting. Verified
+# against a real H2D slice: blanking `time_lapse_gcode` left every
+# used_g/used_m in slice_info byte-identical.
+#
+# Keys are normalised (see `_normalise_option`) because the slicer reports
+# `timelapse_gcode` while the 3MF stores `time_lapse_gcode`.
+_BLANKABLE_GCODE_FIELDS = frozenset(
+    {
+        "timelapsegcode",
+        "layerchangegcode",
+        "beforelayerchangegcode",
+        "machinepausegcode",
+        "templatecustomgcode",
+        "printingbyobjectgcode",
+    }
+)
+
+
+def _normalise_option(name: str) -> str:
+    """Fold a config-option name to a comparable form.
+
+    Bambu Studio's error text and its 3MF config disagree on word breaks for
+    the same option (`timelapse_gcode` vs `time_lapse_gcode`), so matching on
+    the literal string silently fails to find the field it just named.
+    """
+    return re.sub(r"[^a-z0-9]", "", name.lower())
+
+
 _PREVIEW_CACHE_MAX = 256
 _PreviewCacheKey = tuple[str, int, int, str]
 # Cache values: list[dict] on success, [] on parsed-but-empty (slicer
@@ -54,6 +108,85 @@ def _content_hash(file_bytes: bytes) -> str:
     return hashlib.sha256(file_bytes).hexdigest()[:16]
 
 
+def _unparsable_gcode_option(error_text: str) -> str | None:
+    """The normalised name of the custom-G-code field the slicer choked on.
+
+    Returns ``None`` when the failure was something else entirely, or when the
+    named field is one whose removal could change filament accounting — see
+    ``_BLANKABLE_GCODE_FIELDS``. Callers treat ``None`` as "don't retry".
+    """
+    match = _GCODE_PARSE_ERROR_RE.search(error_text)
+    if match is None:
+        return None
+    option = _normalise_option(match.group(1))
+    return option if option in _BLANKABLE_GCODE_FIELDS else None
+
+
+def _blank_custom_gcode(file_bytes: bytes, option: str) -> bytes | None:
+    """Return a copy of the 3MF with ``option``'s G-code template emptied.
+
+    A 3MF saved by a newer Bambu Studio can carry a machine G-code template
+    that references a config variable an older sidecar doesn't define — e.g.
+    Studio 2.8 writes ``{if timelapse_inline_photo}`` into ``time_lapse_gcode``
+    without exporting a definition for it, so the template is unresolvable the
+    moment it leaves Studio. Slicing then dies with a placeholder parse error
+    before producing any slice_info, and the preview has nothing to read.
+
+    Emptying just the one named template lets the slice complete on the file's
+    own settings, which is what keeps the answer trustworthy: process settings,
+    support configuration and per-slot filament assignments are all preserved,
+    so the filament list matches what the file would really produce.
+
+    Returns ``None`` when there is nothing to do — not a 3MF, no embedded
+    settings, no matching field, or a field that is already empty — so the
+    caller can skip a retry that would fail identically.
+    """
+    try:
+        with zipfile.ZipFile(BytesIO(file_bytes)) as zf:
+            if _PROJECT_SETTINGS_PATH not in zf.namelist():
+                return None
+            entries = [(info, zf.read(info.filename)) for info in zf.infolist()]
+            settings = json.loads(zf.read(_PROJECT_SETTINGS_PATH).decode("utf-8", "replace"))
+    except (zipfile.BadZipFile, OSError, UnicodeDecodeError, json.JSONDecodeError):
+        return None
+    if not isinstance(settings, dict):
+        return None
+
+    # Match on the normalised name so the slicer's spelling finds the config's.
+    # Only `*_gcode` keys are eligible, so a same-stem non-template setting
+    # can never be caught by the fold.
+    blanked: list[str] = []
+    for key, value in settings.items():
+        if not key.endswith("_gcode") or _normalise_option(key) != option:
+            continue
+        if isinstance(value, str) and value:
+            settings[key] = ""
+        elif isinstance(value, list) and any(value):
+            # Preserve the container type — a per-extruder template is a list,
+            # and handing the CLI a bare string where it expects one would
+            # trade this parse error for a different one.
+            settings[key] = [""] * len(value)
+        else:
+            continue
+        blanked.append(key)
+    if not blanked:
+        return None
+
+    out = BytesIO()
+    try:
+        with zipfile.ZipFile(out, "w") as zf_out:
+            for info, data in entries:
+                if info.filename == _PROJECT_SETTINGS_PATH:
+                    data = json.dumps(settings, indent=4).encode("utf-8")
+                # Carry each member's original compression across so the copy
+                # stays a 3MF the slicer reads the same way as the original.
+                zf_out.writestr(info, data, compress_type=info.compress_type)
+    except (OSError, ValueError):
+        return None
+    logger.debug("Preview slice: emptied custom G-code field(s) %s for retry", ", ".join(blanked))
+    return out.getvalue()
+
+
 async def get_preview_filaments(
     *,
     kind: str,
@@ -70,7 +203,8 @@ async def get_preview_filaments(
 
     Uses the file's embedded settings (``slice_without_profiles``) since the
     slot mapping is a model property, independent of any user-picked profile
-    triplet.
+    triplet. A slice killed by an unparsable custom G-code template is retried
+    once with that template blanked, still on the file's own settings.
 
     Returns ``None`` when the preview slice fails — the caller should fall
     back to whatever heuristic it has (typically the project_filaments +
@@ -92,28 +226,73 @@ async def get_preview_filaments(
             _preview_cache.move_to_end(key)
             return cached
 
-        try:
-            # Preview slices are bounded the same way as real ones (#2730):
-            # a heavy plate can take a long time and must not be cut off
-            # while the slicer is visibly working.
-            svc_kwargs = {} if timeout_seconds is None else {"timeout_seconds": timeout_seconds}
+        # Preview slices are bounded the same way as real ones (#2730):
+        # a heavy plate can take a long time and must not be cut off
+        # while the slicer is visibly working.
+        svc_kwargs = {} if timeout_seconds is None else {"timeout_seconds": timeout_seconds}
+
+        async def _slice(model_bytes: bytes):
             async with SlicerApiService(base_url=api_url, **svc_kwargs) as svc:
-                result = await svc.slice_without_profiles(
-                    model_bytes=file_bytes,
+                return await svc.slice_without_profiles(
+                    model_bytes=model_bytes,
                     model_filename=file_name,
                     plate=plate_id,
                     export_3mf=True,
                     request_id=request_id,
                 )
+
+        try:
+            result = await _slice(file_bytes)
         except SlicerApiError as e:
-            logger.warning(
-                "Preview slice failed for %s/%s plate %s: %s",
+            # One retry, and only for a custom-G-code template the sidecar
+            # cannot parse — a file from a Studio newer than the sidecar. The
+            # alternative is to give the caller nothing and let it fall back to
+            # its painted-face heuristic, so a retry that reproduces the file's
+            # own settings is strictly better than the status quo. Anything
+            # else (unreachable sidecar, timeout, bad input) returns as before.
+            #
+            # Whether a retry is even possible is decided *before* anything is
+            # logged, so a slice that recovers never announces itself as a
+            # failure. Logging the first attempt at WARNING regardless sent a
+            # reader looking for a bug in a path that had already fixed itself
+            # twenty seconds later, several screens further down the log.
+            retry_bytes = None
+            option = _unparsable_gcode_option(str(e))
+            if option is not None:
+                retry_bytes = _blank_custom_gcode(file_bytes, option)
+            if retry_bytes is None:
+                logger.warning(
+                    "Preview slice failed for %s/%s plate %s: %s",
+                    kind,
+                    source_id,
+                    plate_id,
+                    e,
+                )
+                return None
+            logger.info(
+                "Preview slice for %s/%s plate %s hit unparsable custom G-code; retrying without it. "
+                "The file's G-code references a setting this slicer build does not know, so it is "
+                "probably from a newer Bambu Studio than the sidecar. Original failure: %s",
                 kind,
                 source_id,
                 plate_id,
                 e,
             )
-            return None
+            try:
+                result = await _slice(retry_bytes)
+            except SlicerApiError as retry_exc:
+                logger.warning(
+                    "Preview slice retry without the unparsable G-code also failed for %s/%s plate %s: %s",
+                    kind,
+                    source_id,
+                    plate_id,
+                    retry_exc,
+                )
+                return None
+            except Exception as retry_exc:  # noqa: BLE001 — never break the modal on sidecar issues
+                logger.warning("Preview slice retry unexpected error: %s", retry_exc)
+                return None
+            logger.info("Preview slice for %s/%s plate %s succeeded on retry", kind, source_id, plate_id)
         except Exception as e:  # noqa: BLE001 — never break the modal on sidecar issues
             logger.warning("Preview slice unexpected error: %s", e)
             return None

+ 241 - 0
backend/tests/unit/services/test_slice_preview.py

@@ -10,6 +10,7 @@ from __future__ import annotations
 
 import asyncio
 import io
+import json
 import zipfile
 from typing import Any
 from unittest.mock import patch
@@ -23,6 +24,7 @@ from backend.app.services.slice_preview import (
     get_preview_filaments,
 )
 from backend.app.services.slicer_api import (
+    SlicerApiServerError,
     SlicerApiUnavailableError,
     SliceResult,
 )
@@ -254,3 +256,242 @@ class TestGetPreviewFilaments:
         assert len(slice_preview._preview_cache) == _PREVIEW_CACHE_MAX
         # Lock dict is also pruned (no leak): same size as cache.
         assert len(slice_preview._preview_locks) == _PREVIEW_CACHE_MAX
+
+
+# ---------------------------------------------------------------------------
+# Unparsable custom G-code — a 3MF from a Studio newer than the sidecar.
+#
+# Studio 2.8 writes `{if timelapse_inline_photo}` into `time_lapse_gcode`
+# without exporting a definition for that variable, so an older sidecar dies
+# on a placeholder parse error before any slice_info exists. Blanking just
+# that template lets the slice finish on the file's own settings.
+# ---------------------------------------------------------------------------
+
+
+# Reproduced verbatim from a Bambu Studio 2.7.1.62 sidecar refusing an H2D
+# project saved by Studio 02.08.00.50. Note the slicer says `timelapse_gcode`
+# while the 3MF stores the field as `time_lapse_gcode`.
+_TIMELAPSE_PARSE_ERROR = (
+    "Slicer CLI failed (500): Slicing failed with error from slicer: Failed slicing the model.: "
+    "Slicer process failed (exit code 156)\n"
+    "stderr: Failed to generate gcode for invalid custom G-code.\n\n"
+    "timelapse_gcode Parsing error at line 13: Not a variable name\n"
+    "    {if timelapse_inline_photo}\n"
+    "        ^\n"
+)
+
+
+def _make_project_3mf(settings: dict[str, Any], extra: dict[str, bytes] | None = None) -> bytes:
+    buf = io.BytesIO()
+    with zipfile.ZipFile(buf, "w") as zf:
+        zf.writestr("Metadata/project_settings.config", json.dumps(settings))
+        for name, data in (extra or {}).items():
+            zf.writestr(name, data)
+    return buf.getvalue()
+
+
+def _settings_of(file_bytes: bytes) -> dict[str, Any]:
+    with zipfile.ZipFile(io.BytesIO(file_bytes)) as zf:
+        return json.loads(zf.read("Metadata/project_settings.config").decode())
+
+
+class TestUnparsableGcodeOption:
+    def test_names_the_field_the_slicer_choked_on(self):
+        assert slice_preview._unparsable_gcode_option(_TIMELAPSE_PARSE_ERROR) == "timelapsegcode"
+
+    def test_unrelated_failure_is_not_a_gcode_problem(self):
+        err = "Slicer CLI failed (500): raft_first_layer_expansion: -1 not in range [0, 340282346638]"
+        assert slice_preview._unparsable_gcode_option(err) is None
+
+    def test_refuses_a_field_that_extrudes(self):
+        # The whole safety argument for this retry: silencing a template that
+        # lays a prime line or purges would change the grams the preview
+        # exists to report. Returning nothing beats returning wrong numbers.
+        for field in ("machine_start_gcode", "change_filament_gcode", "filament_start_gcode"):
+            err = f"{field} Parsing error at line 3: Not a variable name\n    {{if whatever}}\n"
+            assert slice_preview._unparsable_gcode_option(err) is None, field
+
+
+class TestBlankCustomGcode:
+    def test_blanks_the_matching_field_despite_the_spelling_difference(self):
+        original = _make_project_3mf(
+            {
+                "time_lapse_gcode": "M971 S11 C10\n{if timelapse_inline_photo}\n",
+                "machine_start_gcode": "G28 ; home",
+                "filament_colour": ["#FFFFFF", "#000000"],
+            }
+        )
+        out = slice_preview._blank_custom_gcode(original, "timelapsegcode")
+        assert out is not None
+        settings = _settings_of(out)
+        assert settings["time_lapse_gcode"] == ""
+        # Everything else survives untouched — the preview's accuracy depends
+        # on the file's own process/support/filament settings being intact.
+        assert settings["machine_start_gcode"] == "G28 ; home"
+        assert settings["filament_colour"] == ["#FFFFFF", "#000000"]
+
+    def test_keeps_every_other_archive_member(self):
+        original = _make_project_3mf(
+            {"time_lapse_gcode": "x"},
+            extra={"3D/3dmodel.model": b"<model/>", "Metadata/plate_1.png": b"\x89PNG"},
+        )
+        out = slice_preview._blank_custom_gcode(original, "timelapsegcode")
+        assert out is not None
+        with zipfile.ZipFile(io.BytesIO(out)) as zf:
+            assert zf.read("3D/3dmodel.model") == b"<model/>"
+            assert zf.read("Metadata/plate_1.png") == b"\x89PNG"
+
+    def test_preserves_a_list_valued_template(self):
+        original = _make_project_3mf({"layer_change_gcode": ["a", "b", "c"]})
+        out = slice_preview._blank_custom_gcode(original, "layerchangegcode")
+        assert out is not None
+        assert _settings_of(out)["layer_change_gcode"] == ["", "", ""]
+
+    def test_no_retry_when_the_field_is_already_empty(self):
+        # Blanking an empty field would produce a byte-identical request and
+        # the identical failure, so the caller must be told not to bother.
+        assert slice_preview._blank_custom_gcode(_make_project_3mf({"time_lapse_gcode": ""}), "timelapsegcode") is None
+
+    def test_no_match_no_retry(self):
+        assert slice_preview._blank_custom_gcode(_make_project_3mf({"other": "x"}), "timelapsegcode") is None
+
+    def test_only_gcode_keys_are_eligible(self):
+        # The normalising fold must not let a same-stem non-template setting
+        # be silently rewritten.
+        original = _make_project_3mf({"timelapse_type": "0", "timelapse_gcode_extra": "keep"})
+        assert slice_preview._blank_custom_gcode(original, "timelapsetype") is None
+
+    def test_non_3mf_input_is_not_a_crash(self):
+        assert slice_preview._blank_custom_gcode(b"not a zip", "timelapsegcode") is None
+
+    def test_3mf_without_embedded_settings(self):
+        buf = io.BytesIO()
+        with zipfile.ZipFile(buf, "w") as zf:
+            zf.writestr("3D/3dmodel.model", "<model/>")
+        assert slice_preview._blank_custom_gcode(buf.getvalue(), "timelapsegcode") is None
+
+
+class _FailThenSucceedService:
+    """Fails the first slice with ``first_error``, then succeeds."""
+
+    def __init__(self, first_error: BaseException, response_bytes: bytes) -> None:
+        self.first_error = first_error
+        self.response_bytes = response_bytes
+        self.calls: list[bytes] = []
+
+    async def __aenter__(self):
+        return self
+
+    async def __aexit__(self, *exc):
+        return False
+
+    async def slice_without_profiles(self, **kw):
+        self.calls.append(kw["model_bytes"])
+        if len(self.calls) == 1:
+            raise self.first_error
+        return SliceResult(
+            content=self.response_bytes,
+            print_time_seconds=0,
+            filament_used_g=0.0,
+            filament_used_mm=0.0,
+        )
+
+
+class TestPreviewRetriesUnparsableGcode:
+    @pytest.mark.asyncio
+    async def test_retries_once_with_the_template_blanked(self):
+        original = _make_project_3mf({"time_lapse_gcode": "{if timelapse_inline_photo}"})
+        body = _make_sliced_3mf(
+            plate_id=1,
+            filaments=[
+                {"id": "1", "type": "PLA", "color": "#FFFFFF", "used_g": "77.9"},
+                {"id": "4", "type": "PLA-S", "color": "#0F80FF", "used_g": "11.5"},
+            ],
+        )
+        stub = _FailThenSucceedService(SlicerApiServerError(_TIMELAPSE_PARSE_ERROR), body)
+        with patch.object(slice_preview, "SlicerApiService", lambda **kw: stub):
+            result = await get_preview_filaments(
+                kind="library_file",
+                source_id=18000,
+                plate_id=1,
+                file_bytes=original,
+                file_name="x.3mf",
+                api_url="http://sidecar",
+            )
+        assert result is not None
+        # The support slot must survive — losing it is exactly the failure a
+        # profile-override fallback would have introduced.
+        assert [f["slot_id"] for f in result] == [1, 4]
+        assert len(stub.calls) == 2
+        # The retry sent a modified file, not the original.
+        assert stub.calls[1] != original
+        assert _settings_of(stub.calls[1])["time_lapse_gcode"] == ""
+
+    @pytest.mark.asyncio
+    async def test_result_is_cached_under_the_original_file_hash(self):
+        original = _make_project_3mf({"time_lapse_gcode": "{if timelapse_inline_photo}"})
+        body = _make_sliced_3mf(plate_id=1, filaments=[{"id": "1", "type": "PLA", "color": "#000"}])
+        stub = _FailThenSucceedService(SlicerApiServerError(_TIMELAPSE_PARSE_ERROR), body)
+        with patch.object(slice_preview, "SlicerApiService", lambda **kw: stub):
+            first = await get_preview_filaments(
+                kind="library_file",
+                source_id=1,
+                plate_id=1,
+                file_bytes=original,
+                file_name="x.3mf",
+                api_url="http://sidecar",
+            )
+            second = await get_preview_filaments(
+                kind="library_file",
+                source_id=1,
+                plate_id=1,
+                file_bytes=original,
+                file_name="x.3mf",
+                api_url="http://sidecar",
+            )
+        assert second == first
+        # Two slices for the first call, none for the second.
+        assert len(stub.calls) == 2
+
+    @pytest.mark.asyncio
+    async def test_no_retry_for_an_unrelated_failure(self):
+        original = _make_project_3mf({"time_lapse_gcode": "{if timelapse_inline_photo}"})
+        stub = _FailThenSucceedService(
+            SlicerApiUnavailableError("Slicer sidecar unreachable"),
+            _make_sliced_3mf(plate_id=1, filaments=[{"id": "1", "type": "PLA", "color": "#000"}]),
+        )
+        with patch.object(slice_preview, "SlicerApiService", lambda **kw: stub):
+            result = await get_preview_filaments(
+                kind="library_file",
+                source_id=1,
+                plate_id=1,
+                file_bytes=original,
+                file_name="x.3mf",
+                api_url="http://sidecar",
+            )
+        assert result is None
+        assert len(stub.calls) == 1
+
+    @pytest.mark.asyncio
+    async def test_a_failing_retry_falls_through_rather_than_raising(self):
+        original = _make_project_3mf({"time_lapse_gcode": "{if timelapse_inline_photo}"})
+
+        class _AlwaysFails(_FailThenSucceedService):
+            async def slice_without_profiles(self, **kw):
+                self.calls.append(kw["model_bytes"])
+                raise self.first_error
+
+        stub = _AlwaysFails(SlicerApiServerError(_TIMELAPSE_PARSE_ERROR), b"")
+        with patch.object(slice_preview, "SlicerApiService", lambda **kw: stub):
+            result = await get_preview_filaments(
+                kind="library_file",
+                source_id=1,
+                plate_id=1,
+                file_bytes=original,
+                file_name="x.3mf",
+                api_url="http://sidecar",
+            )
+        assert result is None
+        assert len(stub.calls) == 2
+        # A failed retry must not be cached — the sidecar may be upgraded.
+        assert not slice_preview._preview_cache

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