Auto-slice STLs in queue (#166)

* First attempt at integrating OctoPrint configured slicers into queue automation; also anticipate FILE_ADDED changes upstream

* Added auto-slicing docs and fixed small bug in octoprint version detection

* Add working auto-slicer implementation; unit tests TBD

* Fix tests

* Add driver test

* Add tests for slicer profiles in JS, remove extra debug logging

* Remove unused driver state, improve verbosity of slicing errors, and fixed slicer output path in tmp folder

* Get working enough to verify STL and gcode handled correctly, plus update docs

* Fix tests, remove octoprint version req thing and reduce DB noise in testing

* Cleanup

Dockerfile

@@ -1,7 +1,8 @@
 FROM python:3.7
 
 # Installing ffmpeg is needed for working with timelapses - can be ommitted otherwise
-RUN apt-get update && apt-get -y install --no-install-recommends ffmpeg && rm -rf /var/lib/apt/lists/*
+# Also install vim for later edit based debugging
+RUN apt-get update && apt-get -y install --no-install-recommends ffmpeg vim && rm -rf /var/lib/apt/lists/*
 
 # IPFS installation for LAN filesharing
 RUN wget https://dist.ipfs.tech/kubo/v0.15.0/kubo_v0.15.0_linux-amd64.tar.gz \

continuousprint/__init__.py

@@ -54,6 +54,7 @@ def on_startup(self, host=None, port=None):
                 self._printer,
                 self._settings,
                 self._file_manager,
+                self._slicing_manager,
                 self._plugin_manager,
                 queries,
                 self.get_plugin_data_folder(),
@@ -65,6 +66,11 @@ def on_startup(self, host=None, port=None):
             )
 
     def on_after_startup(self):
+        self._logger.debug(
+            "Starting ContinuousPrint with settings: {}".format(
+                self._settings.get_all_data()
+            )
+        )
         self._plugin.patchCommJobReader()
         self._plugin.patchComms()
         self._plugin.start()

continuousprint/data/__init__.py

@@ -159,6 +159,8 @@ class Keys(Enum):
     INFER_PROFILE = ("cp_infer_profile", True)
     AUTO_RECONNECT = ("cp_auto_reconnect", False)
     SKIP_GCODE_COMMANDS = ("cp_skip_gcode_commands", "")
+    SLICER = ("cp_slicer", "")
+    SLICER_PROFILE = ("cp_slicer_profile", "")
 
     def __init__(self, setting, default):
         self.setting = setting

continuousprint/driver.py

@@ -7,6 +7,8 @@
 class Action(Enum):
     ACTIVATE = auto()
     DEACTIVATE = auto()
+    RESOLVED = auto()
+    RESOLVE_FAILURE = auto()
     SUCCESS = auto()
     FAILURE = auto()
     SPAGHETTI = auto()
@@ -207,10 +209,10 @@ def _enter_start_print(self, a: Action, p: Printer, run_pre_script=True):
         ):
             return self._state_preprint
 
-        # Pre-call start_print on entry to eliminate tick delay
+        # Pre-call resolve_print on entry to eliminate tick delay
         self.start_failures = 0
-        nxt = self._state_start_print(a, p)
-        return nxt if nxt is not None else self._state_start_print
+        nxt = self._state_resolve_print(a, p)
+        return nxt if nxt is not None else self._state_resolve_print
 
     def _fmt_material_key(self, mk):
         try:
@@ -265,7 +267,7 @@ def _state_awaiting_material(self, a: Action, p: Printer):
                 StatusType.NEEDS_ACTION,
             )
 
-    def _state_start_print(self, a: Action, p: Printer):
+    def _state_resolve_print(self, a: Action, p: Printer):
         if p != Printer.IDLE:
             self._set_status("Waiting for printer to be ready")
             return
@@ -275,10 +277,14 @@ def _state_start_print(self, a: Action, p: Printer):
             self._set_status("No work to do; going idle")
             return self._state_idle
 
-        if not self._runner.set_active(item):
-            # TODO: handle this gracefully by marking the job as not runnable somehow and moving on
-            return self._state_inactive
+        sa = self._runner.set_active(item, self._slicing_callback)
+        if sa is False:
+            return self._fail_start()
+        elif sa is None:  # Implies slicing
+            return self._state_slicing
 
+        # Invariant: item's path has been set as the active file in OctoPrint
+        # and the file is a .gcode file that's ready to go.
         valid, rep = self._runner.verify_active()
         if not self._materials_match(item) or not valid:
             self._runner.run_script_for_event(CustomEvents.AWAITING_MATERIAL)
@@ -288,20 +294,45 @@ def _state_start_print(self, a: Action, p: Printer):
                 )
             return self._state_awaiting_material
 
-        self.q.begin_run()
-        if self._runner.start_print(item):
-            return self._state_printing
+        try:
+            self.q.begin_run()
+            self._runner.start_print(item)
+        except Exception as e:
+            self._logger.error(e)
+            return self._fail_start()
+
+        return self._state_printing
+
+    def _state_slicing(self, a: Action, p: Printer):
+        self._set_status("Waiting for print file to be ready")
+        if a == Action.RESOLVED:
+            return (
+                self._state_resolve_print(Action.TICK, p) or self._state_resolve_print
+            )
+        elif a == Action.RESOLVE_FAILURE:
+            return self._fail_start()
+
+    def _slicing_callback(self, success: bool, error):
+        if error is not None:
+            return
+
+        # Forward action. We assume printer is idle here.
+        self.action(
+            Action.RESOLVED if success else Action.RESOLVE_FAILURE, Printer.IDLE
+        )
+
+    def _fail_start(self):
+        # TODO bail out of the job and mark it as bad rather than dropping into inactive state
+        self.start_failures += 1
+        if self.start_failures >= self.max_startup_attempts:
+            self._set_status("Failed to start; too many attempts", StatusType.ERROR)
+            return self._enter_inactive()
         else:
-            # TODO bail out of the job and mark it as bad rather than dropping into inactive state
-            self.start_failures += 1
-            if self.start_failures >= self.max_startup_attempts:
-                self._set_status("Failed to start; too many attempts", StatusType.ERROR)
-                return self._enter_inactive()
-            else:
-                self._set_status(
-                    f"Start attempt failed ({self.start_failures}/{self.max_startup_attempts})",
-                    StatusType.ERROR,
-                )
+            self._set_status(
+                f"Start attempt failed ({self.start_failures}/{self.max_startup_attempts})",
+                StatusType.ERROR,
+            )
+            return self._state_resolve_print
 
     def _long_idle(self, p):
         # We wait until we're in idle state for a long-ish period before acting, as
@@ -334,11 +365,11 @@ def _state_printing(self, a: Action, p: Printer, elapsed=None):
             # A limitation of `octoprint.printer`, the "current file" path passed to the driver is only
             # the file name, not the full path to the file.
             # See https://docs.octoprint.org/en/master/modules/printer.html#octoprint.printer.PrinterCallback.on_printer_send_current_data
-            if item.path.split("/")[-1] == self._cur_path:
+            if item.resolve().split("/")[-1] == self._cur_path:
                 return self._state_success
             else:
                 self._logger.info(
-                    f"Completed print {self._cur_path} not matching current queue item {item.path} - clearing it in prep to start queue item"
+                    f"Completed print {self._cur_path} not matching current queue item {item.resolve()} - clearing it in prep to start queue item"
                 )
                 return self._state_start_clearing
 

continuousprint/driver_test.py

@@ -21,7 +21,9 @@ def setUp(self):
         self.d.set_retry_on_pause(True)
         self.d.action(DA.DEACTIVATE, DP.IDLE)
         self.d._runner.run_script_for_event.reset_mock()
+        self.d._runner.start_print.return_value = True
         item = MagicMock(path="asdf")  # return same item by default every time
+        item.resolve.return_value = "asdf"
         self.d.q.get_set_or_acquire.return_value = item
         self.d.q.get_set.return_value = item
 
@@ -58,9 +60,45 @@ def test_activate_with_preprint_script(self):
         self.assertEqual(self.d.state.__name__, self.d._state_printing.__name__)
         self.d._runner.start_print.assert_called()
 
+    def test_activate_start_print_failure(self):
+        self.d._runner.run_script_for_event.return_value = None
+        self.d._runner.set_active.return_value = False
+        self.d.action(DA.ACTIVATE, DP.IDLE)  # -> fail, resolve_print
+        self.assertEqual(self.d.state.__name__, self.d._state_resolve_print.__name__)
+        self.assertEqual(self.d.start_failures, 1)
+
+    def test_activate_start_print_failure_from_exception(self):
+        self.d._runner.run_script_for_event.return_value = None
+        self.d._runner.set_active.return_value = True
+        self.d._runner.start_print.side_effect = Exception("test")
+        self.d.action(DA.ACTIVATE, DP.IDLE)  # -> fail, resolve_print
+        self.assertEqual(self.d.state.__name__, self.d._state_resolve_print.__name__)
+        self.assertEqual(self.d.start_failures, 1)
+
+    def test_activate_start_print_slicer_failure(self):
+        self.d._runner.run_script_for_event.return_value = None
+        self.d._runner.set_active.return_value = None  # Indicate callback
+        self.d.action(DA.ACTIVATE, DP.IDLE)  # -> slicing
+        self.assertEqual(self.d.state.__name__, self.d._state_slicing.__name__)
+        self.d.action(DA.RESOLVE_FAILURE, DP.IDLE)  # -> resolve_print attempt #2
+        self.assertEqual(self.d.state.__name__, self.d._state_resolve_print.__name__)
+        self.assertEqual(self.d.start_failures, 1)
+
+    def test_activate_start_print_slicer_success(self):
+        self.d._runner.run_script_for_event.return_value = None
+        self.d._runner.set_active.return_value = None  # Indicate callback
+        self.d.action(DA.ACTIVATE, DP.IDLE)  # -> slicing
+        self.assertEqual(self.d.state.__name__, self.d._state_slicing.__name__)
+
+        self.d._runner.set_active.return_value = True  # Now resolvable
+        self.d.action(
+            DA.RESOLVED, DP.IDLE
+        )  # script_runner finished slicing and started the print
+        self.assertEqual(self.d.state.__name__, self.d._state_printing.__name__)
+
     def test_activate_not_yet_printing(self):
         self.d._runner.run_script_for_event.return_value = None
-        self.d.action(DA.ACTIVATE, DP.IDLE)  # -> start_printing -> printing
+        self.d.action(DA.ACTIVATE, DP.IDLE)  # -> resolve_print -> printing
         self.d.q.begin_run.assert_called()
         self.d._runner.start_print.assert_called_with(self.d.q.get_set.return_value)
         self.assertEqual(self.d.state.__name__, self.d._state_printing.__name__)
@@ -104,6 +142,20 @@ def test_completed_print_not_in_queue(self):
         # Verify no end_run call anywhere in this process, since print was not in queue
         self.d.q.end_run.assert_not_called()
 
+    def test_completed_stl(self):
+        # In the case of STLs, the item path is not the print path
+        # But we should still complete the currently active print item
+        item = MagicMock(path="asdf.stl")
+        item.resolve.return_value = "asdf.stl.gcode"
+        self.d.q.get_set_or_acquire.return_value = item
+        self.d.q.get_set.return_value = item
+        self.d._runner.run_script_for_event.return_value = None
+        self.d.action(DA.ACTIVATE, DP.BUSY)  # -> start print -> printing
+        self.assertEqual(self.d.state.__name__, self.d._state_printing.__name__)
+        self.d.action(DA.SUCCESS, DP.IDLE, "asdf.stl.gcode")  # -> success
+        self.d.action(DA.TICK, DP.IDLE)  # -> start_clearing, end_run() called
+        self.d.q.end_run.assert_called()
+
     def test_start_clearing_waits_for_idle(self):
         self.d.state = self.d._state_start_clearing
         self.d.action(DA.TICK, DP.BUSY)
@@ -222,9 +274,11 @@ def setUp(self):
         self.d._runner.verify_active.return_value = (True, None)
         self.d.set_retry_on_pause(True)
         item = MagicMock(path="asdf")  # return same item by default every time
+        item.resolve.return_value = "asdf"
         self.d.q.get_set_or_acquire.return_value = item
         self.d.q.get_set.return_value = item
         self.d._runner.run_script_for_event.return_value = None
+        self.d._runner.start_print.return_value = True
         self.d.action(DA.DEACTIVATE, DP.IDLE)
         self.d.action(DA.ACTIVATE, DP.IDLE)  # -> start_print -> printing
         self.d._runner.run_script_for_event.reset_mock()
@@ -239,6 +293,7 @@ def test_success(self):
         self.d.action(DA.TICK, DP.IDLE)  # -> start_clearing
         self.d.q.end_run.assert_called_once()
         item2 = MagicMock(path="basdf")
+        item2.resolve.return_value = "basdf"
         self.d.q.get_set_or_acquire.return_value = (
             item2  # manually move the supervisor forward in the queue
         )
@@ -357,6 +412,7 @@ def setUp(self):
         )
         self.d.set_retry_on_pause(True)
         self.d._runner.run_script_for_event.return_value = None
+        self.d._runner.start_print.return_value = True
         self.d.action(DA.DEACTIVATE, DP.IDLE)
 
     def _setItemMaterials(self, m):

continuousprint/integration_test.py

@@ -48,6 +48,9 @@ def onupdate():
         self.d._runner.run_script_for_event.return_value = None
         self.d._runner.verify_active.return_value = (True, None)
 
+        # Default to succeeding when activating print
+        self.d._runner.set_active.return_value = True
+
         self.d.set_retry_on_pause(True)
         self.d.action(DA.DEACTIVATE, DP.IDLE)
 
@@ -191,6 +194,8 @@ def onupdate():
         self.s = ScriptRunner(
             msg=MagicMock(),
             file_manager=self.fm,
+            get_key=MagicMock(),
+            slicing_manager=MagicMock(),
             logger=logging.getLogger(),
             printer=MagicMock(),
             refresh_ui_state=MagicMock(),
@@ -297,7 +302,9 @@ def setUp(self):
         )
         self.lq.lan.q.locks = LocalLockManager(dict(), "lq")
         self.lq.lan.q.jobs = TestReplDict(lambda a, b: None)
-        self.lq.lan.q.peers = dict()
+        self.lq.lan.q.peers = {}
+        self.lq.lan.q.peers[self.lq.addr] = (time.time(), dict(fs_addr="mock"))
+        self.lq._fileshare.fetch.return_value = "from_fileshare.gcode"
 
     def test_completes_job_in_order(self):
         self.lq.lan.q.setJob(
@@ -346,12 +353,11 @@ def onupdate():
 
         self.locks = {}
         self.peers = []
-        lqpeers = {}
-        lqjobs = TestReplDict(lambda a, b: None)
         for i, db in enumerate(self.dbs):
             with db.bind_ctx(MODELS):
                 populate_queues()
             fsm = MagicMock(host="fsaddr", port=0)
+            fsm.fetch.return_value = "from_fileshare.gcode"
             profile = dict(name="profile")
             lq = LANQueue(
                 "LAN",
@@ -372,17 +378,27 @@ def onupdate():
             )
             d._runner.verify_active.return_value = (True, None)
             d._runner.run_script_for_event.return_value = None
+            d._runner.set_active.return_value = True
             d.set_retry_on_pause(True)
             d.action(DA.DEACTIVATE, DP.IDLE)
             lq.lan.q = LANPrintQueueBase(
                 lq.ns, lq.addr, MagicMock(), logging.getLogger("lantestbase")
             )
             lq.lan.q.locks = LocalLockManager(self.locks, f"peer{i}")
-            lq.lan.q.jobs = lqjobs
-            lq.lan.q.peers = lqpeers
-            lq.update_peer_state(lq.addr, "status", "run", profile)
+            if i == 0:
+                lq.lan.q.jobs = TestReplDict(lambda a, b: None)
+                lq.lan.q.peers = dict()
+            else:
+                lq.lan.q.peers = self.peers[0][2].lan.q.peers
+                lq.lan.q.jobs = self.peers[0][2].lan.q.jobs
             self.peers.append((d, mq, lq, db))
 
+        for p in self.peers:
+            self.peers[0][2].lan.q.peers[p[2].addr] = (
+                time.time(),
+                dict(fs_addr="fakeaddr", profile=dict(name="profile")),
+            )
+
     def test_ordered_acquisition(self):
         logging.info("============ BEGIN TEST ===========")
         self.assertEqual(len(self.peers), 2)