Add host power panic recovery

prusa/link/printer_adapter/command_handlers.py

@@ -25,12 +25,18 @@
     STATE_CHANGE_TIMEOUT,
 )
 from ..serial.helpers import enqueue_instruction, enqueue_list_from_str
-from ..util import file_is_on_sd, round_to_five
+from ..util import (
+    _parse_little_endian_uint32,
+    file_is_on_sd,
+    get_d3_code,
+    round_to_five,
+)
 from .command import Command, CommandFailed, FileNotFound, NotStateToPrint
 from .model import Model
 from .state_manager import StateChange
-from .structures.model_classes import JobState
+from .structures.model_classes import EEPROMParams, JobState
 from .structures.regular_expressions import (
+    D3_OUTPUT_REGEX,
     OPEN_RESULT_REGEX,
     PRINTER_BOOT_REGEX,
     REJECTION_REGEX,
@@ -663,3 +669,29 @@ def _run_command(self):
         """Enables resets"""
         change_reset_mode(self.model, self.serial_adapter, self.serial_parser,
                           self.quit_evt, timeout=self.timeout, enable=True)
+
+
+class PPRecovery(Command):
+    """Class for recovering from the host power panic"""
+    command_name = "pp_recovery"
+
+    def _run_command(self):
+        """Recovers from host power panic"""
+        if self.model.file_printer.recovering:
+            return
+        try:
+            if not self.file_printer.pp_exists:
+                raise CommandFailed("No PP file exists, cannot recover.")
+        except CommandFailed as exception:
+            enqueue_instruction(self.serial_queue, "M117 \x7ERecovery failed",
+                                to_front=True)
+            enqueue_instruction(self.serial_queue, "M603", to_front=True)
+            raise exception
+
+        d_code = get_d3_code(*EEPROMParams.EEPROM_FILE_POSITION.value)
+        match = self.do_matchable(d_code, D3_OUTPUT_REGEX).match()
+        if match is None:
+            raise CommandFailed("Failed to get file position")
+        line_number = _parse_little_endian_uint32(match)
+        self.file_printer.recover_from_pp(line_number)
+        self.serial_queue.set_message_number(line_number)

prusa/link/printer_adapter/file_printer.py

@@ -1,7 +1,9 @@
 """Contains implementation of the FilePrinter class"""
+import json
 import logging
 import os
 from collections import deque
+from threading import RLock
 from time import sleep
 from typing import Optional
 
@@ -17,10 +19,10 @@
 from .model import Model
 from .print_stats import PrintStats
 from .structures.mc_singleton import MCSingleton
+from .structures.model_classes import PPData
 from .structures.module_data_classes import FilePrinterData
 from .structures.regular_expressions import (
     CANCEL_REGEX,
-    POWER_PANIC_REGEX,
     RESUMED_REGEX,
 )
 from .updatable import Thread
@@ -52,19 +54,22 @@ def __init__(self, serial_queue: SerialQueue,
         #                                               total: int
         self.layer_trigger_signal = Signal()
 
+        self.lock = RLock()
+
         self.model.file_printer = FilePrinterData(
             printing=False,
             paused=False,
-            stopped_forcefully=False,
+            recovering=False,
+            was_stopped=False,
+            power_panic=False,
+            recovery_ready=False,
             file_path="",
             pp_file_path=get_clean_path(cfg.daemon.power_panic_file),
             enqueued=deque(),
             line_number=0,
             gcode_number=0)
         self.data = self.model.file_printer
 
-        self.serial_parser.add_decoupled_handler(
-            POWER_PANIC_REGEX, lambda sender, match: self.power_panic())
         self.serial_parser.add_decoupled_handler(
             CANCEL_REGEX, lambda sender, match: self.stop_print())
         self.serial_parser.add_decoupled_handler(
@@ -91,52 +96,82 @@ def pp_exists(self) -> bool:
         """Checks whether a file created on power panic exists"""
         return os.path.exists(self.data.pp_file_path)
 
-    def check_failed_print(self) -> None:
-        """Not implemented, would try to resume after power panic or error"""
-        # log.warning("There was a loss of power, let's try to recover")
-        if self.pp_exists:
-            os.remove(self.data.pp_file_path)
-
-    def print(self, os_path: str) -> None:
+    def print(self, os_path: str, from_gcode_number=None) -> None:
         """Starts a file print for the supplied path"""
         if self.data.printing:
             raise RuntimeError("Cannot print two things at once")
 
+        if from_gcode_number is None and self.pp_exists:
+            os.remove(self.data.pp_file_path)
+
         self.data.file_path = os_path
         self.thread = Thread(target=self._print,
                              name="file_print",
+                             args=(from_gcode_number,),
                              daemon=True)
         self.data.printing = True
-        self.data.stopped_forcefully = False
+        self.data.was_stopped = False
+        self.data.power_panic = False
+        self.data.paused = False
+        self.data.enqueued.clear()
         self.print_stats.start_time_segment()
         self.new_print_started_signal.send(self)
         self.print_stats.track_new_print(self.data.file_path)
         self.thread.start()
 
-    def _print(self, from_line=0):
+    def power_panic(self) -> None:
+        """Handle the printer sending us a power panic  signal
+        This means halt the serial print, do not send any more instructions
+        Do not delete the power panic file"""
+        self.data.power_panic = True
+        self.data.printing = False
+        log.warning("Power panic!")
+
+    def _print(self, from_gcode_number=None):
         """
         Parses and sends the gcode commands from the file to serial.
         Supports pausing, resuming and stopping.
+
+        param from_gcode_number:
+            the gcode number to start from. Implies power panic recovery -
+            goes into pause when the correct gcode number is reached
         """
+        self.data.recovering = from_gcode_number is not None
 
         prctl_name()
         total_size = os.path.getsize(self.data.file_path)
-        with open(self.data.file_path, "r", encoding='utf-8') as file:
+        with (open(self.data.file_path, "r", encoding='utf-8') as file):
             # Reset the line counter, printing a new file
-            self.serial_queue.reset_message_number()
+            if not self.data.recovering:
+                self.serial_queue.reset_message_number()
 
             self.data.gcode_number = 0
             self.data.enqueued.clear()
             line_index = 0
 
-            self.do_instruction("M75")  # start printer's print timer
+            if not self.data.recovering:
+                self.do_instruction("M75")  # start printer's print timer
+
             while True:
                 line = file.readline()
 
                 # Recognise the end of the file
                 if line == "":
                     break
 
+                self.data.line_number = line_index + 1
+                gcode = get_gcode(line)
+                # Skip to the part we need to recover from
+                if (self.data.recovering
+                        and from_gcode_number > self.data.gcode_number):
+                    if gcode:
+                        self.data.gcode_number += 1
+                    continue
+
+                # Skip finished, pause here, remove the recovering flag
+                if self.data.recovering:
+                    self.pause()
+
                 # This will make it PRINT_QUEUE_SIZE lines in front of what
                 # is being sent to the printer, which is another as much as
                 # 16 gcode commands in front of what's actually being printed.
@@ -145,14 +180,16 @@ def _print(self, from_line=0):
                                                current=current_byte,
                                                total=total_size)
 
-                if line_index < from_line:
-                    continue
-
                 if self.data.paused:
                     log.debug("Pausing USB print")
-                    self.do_instruction("M76")  # pause printer's print timer
+                    if self.data.recovering:
+                        self.data.recovery_ready = True
+                    else:
+                        # pause printer's print timer
+                        self.do_instruction("M76")
                     self.wait_for_unpause()
 
+                    self.data.recovering = False
                     if not self.data.printing:
                         break
 
@@ -163,8 +200,6 @@ def _print(self, from_line=0):
                 if ";LAYER_CHANGE" in line:
                     self.layer_trigger_signal.send()
 
-                self.data.line_number = line_index + 1
-                gcode = get_gcode(line)
                 if gcode:
                     self.print_gcode(gcode)
                     self.wait_for_queue()
@@ -175,26 +210,29 @@ def _print(self, from_line=0):
                 if not self.data.printing:
                     break
 
-            self.do_instruction("M77")  # stop printer's print timer
-            log.debug("Print ended")
+            # Print ended
+            self._print_end()
 
-            if self.pp_exists:
-                os.remove(self.data.pp_file_path)
-            self.data.printing = False
-            self.data.enqueued.clear()
+    def _print_end(self):
+        """Handles the end of a file print"""
+        self.data.enqueued.clear()
+        self.print_stats.reset_stats()
+        log.debug("Print ended")
 
-            if self.data.stopped_forcefully:
-                self.serial_queue.flush_print_queue()
-                self.data.enqueued.clear()  # Ensure this gets cleared
-                # This results in double stop on 3.10 hopefully will get
-                # changed
-                # Prevents the print head from stopping in the print
-                enqueue_instruction(self.serial_queue, "M603", to_front=True)
-                self.print_stopped_signal.send(self)
-            else:
-                self.print_finished_signal.send(self)
+        if self.data.power_panic:
+            return
+
+        self.do_instruction("M77")  # stop printer's print timer
 
-            self.print_stats.reset_stats()
+        self.data.printing = False
+
+        if self.data.was_stopped:
+            self.serial_queue.flush_print_queue()
+            # Prevents the print head from stopping in the print
+            enqueue_instruction(self.serial_queue, "M603", to_front=True)
+            self.print_stopped_signal.send(self)
+        else:
+            self.print_finished_signal.send(self)
 
     def do_instruction(self, message):
         """Shorthand for enqueueing and waiting for an instruction
@@ -209,22 +247,24 @@ def print_gcode(self, gcode):
         """Sends a gcode to print, keeps a small buffer of gcodes
          and inlines print stats for files without them
         (estimated time left and progress)"""
-        self.data.gcode_number += 1
+        with self.lock:
+            self.data.gcode_number += 1
 
-        divisible = self.data.gcode_number % STATS_EVERY == 0
-        if divisible:
-            time_printing = int(self.print_stats.get_time_printing())
-            self.time_printing_signal.send(self, time_printing=time_printing)
+            divisible = self.data.gcode_number % STATS_EVERY == 0
+            if divisible:
+                time_printing = int(self.print_stats.get_time_printing())
+                self.time_printing_signal.send(
+                    self, time_printing=time_printing)
 
-        if self.to_print_stats(self.data.gcode_number):
-            self.send_print_stats()
+            if self.to_print_stats(self.data.gcode_number):
+                self.send_print_stats()
 
-        log.debug("USB enqueuing gcode: %s", gcode)
-        instruction = enqueue_instruction(self.serial_queue,
-                                          gcode,
-                                          to_front=True,
-                                          to_checksum=True)
-        self.data.enqueued.append(instruction)
+            log.debug("USB enqueuing gcode: %s", gcode)
+            instruction = enqueue_instruction(self.serial_queue,
+                                              gcode,
+                                              to_front=True,
+                                              to_checksum=True)
+            self.data.enqueued.append(instruction)
 
     def wait_for_queue(self) -> None:
         """Gets rid of already confirmed messages and waits for any
@@ -256,19 +296,6 @@ def react_to_gcode(self, gcode):
         if gcode.startswith("M601") or gcode.startswith("M25"):
             self.pause()
 
-    def power_panic(self):
-        """Not used/working"""
-        # when doing this again don't forget to write print time
-        if self.data.printing:
-            self.pause()
-            self.serial_queue.closed = True
-            log.warning("POWER PANIC!")
-            with open(self.data.pp_file_path, "w",
-                      encoding='utf-8') as pp_file:
-                pp_file.write(f"{self.data.line_number}")
-                pp_file.flush()
-                os.fsync(pp_file.fileno())
-
     def send_print_stats(self):
         """Sends a gcode to the printer, which tells it the progress
         percentage and estimated time left, the printer is expected to send
@@ -331,6 +358,60 @@ def stop_print(self):
         print has been stopped and did not finish on its own"""
         # TODO: wrong, needs to be in line with the rest of commands
         if self.data.printing:
-            self.data.stopped_forcefully = True
+            self.data.was_stopped = True
             self.data.printing = False
             self.data.paused = False
+
+    def write_file_stats(self, file_path, message_number, gcode_number):
+        """Writes the data needed for power panic recovery"""
+        data = PPData(
+            file_path=file_path,
+            message_number=message_number,
+            gcode_number=gcode_number,
+        )
+        with open(self.data.pp_file_path, "w") as pp_file:
+            pp_file.write(json.dumps(data.dict()))
+
+    def serial_message_number_changed(self, message_number):
+        """Updates the pairing of the FW message number to gcode line number
+
+        If all the instructions in the buffer are sent
+        The message number belongs to the next instruction
+        that will be sent
+
+        Here's an illustration of the situation
+        _________________________________________
+        |enqueued   |gcode_number|message_number|
+        |           | current=25 | current=100  |
+        |___________|____________|______________|
+        |next instr.|     26     |     102      |
+        | I0        |    *25*    |     101      |
+        | I1        |     24     |    *100*     |
+        | I2 (sent) |     23     |     99       |
+        | I3 (sent) |     22     |     98       |
+        |___________|____________|______________|
+        """
+
+        with self.lock:
+            instruction_gcode_number = self.data.gcode_number + 1
+            for instruction in self.data.enqueued:
+                if instruction.is_sent():
+                    break
+                instruction_gcode_number -= 1
+            self.write_file_stats(self.data.file_path, message_number,
+                                  instruction_gcode_number)
+
+    def recover_from_pp(self, message_number):
+        """Gets the file path and the gcode number to start from
+        calls the start print with the correct arguments to recover"""
+        if not self.pp_exists:
+            log.warning("Cannot recover from power panic, no pp state found")
+            raise RuntimeError("Cannot recover from power panic, "
+                               "no pp state found")
+
+        with open(self.data.pp_file_path, "r") as pp_file:
+            pp_data = PPData(**json.load(pp_file))
+
+            gcode_number = (pp_data.gcode_number
+                            + (message_number - pp_data.message_number))
+            self.print(pp_data.file_path, gcode_number)