From 3614033b0df60cd2bc44fe4c97ee9d275f05a81e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 21 Jul 2016 16:10:00 +0200 Subject: [PATCH 1/3] No endless circles if we can't write any bytes to serial --- src/octoprint/settings.py | 1 + src/octoprint/util/comm.py | 17 +++++++++++++++++ 2 files changed, 18 insertions(+) diff --git a/src/octoprint/settings.py b/src/octoprint/settings.py index d135e798..271f5c14 100644 --- a/src/octoprint/settings.py +++ b/src/octoprint/settings.py @@ -85,6 +85,7 @@ default_settings = { "temperature": 5, "sdStatus": 1 }, + "maxWritePasses": 5, "additionalPorts": [], "longRunningCommands": ["G4", "G28", "G29", "G30", "G32", "M400", "M226"], "checksumRequiringCommands": ["M110"], diff --git a/src/octoprint/util/comm.py b/src/octoprint/util/comm.py index 269ec8cb..a1666833 100644 --- a/src/octoprint/util/comm.py +++ b/src/octoprint/util/comm.py @@ -236,6 +236,8 @@ class MachineCom(object): except: pass + self._max_write_passes = settings().getInt(["serial", "maxWritePasses"]) + self._hello_command = settings().get(["serial", "helloCommand"]) self._trigger_ok_for_m29 = settings().getBoolean(["serial", "triggerOkForM29"]) @@ -1945,8 +1947,11 @@ class MachineCom(object): cmd += "\n" written = 0 + passes = 0 while written < len(cmd): to_send = cmd[written:] + old_written = written + try: written += self._serial.write(to_send) except serial.SerialTimeoutException: @@ -1968,6 +1973,18 @@ class MachineCom(object): self.close(is_error=True) break + if old_written == written: + # nothing written this pass + passes += 1 + if passes > self._max_write_passes: + # nothing written in max consecutive passes, we give up + message = "Could not write anything to the serial port in {} tries, something appears to be wrong with the printer communication".format(self._max_write_passes) + self._logger.error(message) + self._log(message) + self._errorValue = "Could not write to serial port" + self.close(is_error=True) + break + ##~~ command handlers def _gcode_T_sent(self, cmd, cmd_type=None): From b5e19f067646e5a9873db1f9cf4583bf46c2d7e4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 21 Jul 2016 16:10:57 +0200 Subject: [PATCH 2/3] Synchronize access to selected file --- src/octoprint/printer/standard.py | 109 +++++++++++++++++------------- 1 file changed, 61 insertions(+), 48 deletions(-) diff --git a/src/octoprint/printer/standard.py b/src/octoprint/printer/standard.py index 2400a12f..8a446036 100644 --- a/src/octoprint/printer/standard.py +++ b/src/octoprint/printer/standard.py @@ -71,6 +71,7 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): self._streamingFinishedCallback = None self._selectedFile = None + self._selectedFileLock = threading.RLock() self._timeEstimationData = None # comm @@ -111,8 +112,8 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): current_z=None ) - eventManager().subscribe(Events.METADATA_ANALYSIS_FINISHED, self._on_event_MetadataAnalysisFinished) - eventManager().subscribe(Events.METADATA_STATISTICS_UPDATED, self._on_event_MetadataStatisticsUpdated) + eventManager().subscribe(Events.METADATA_ANALYSIS_FINISHED, self._on_metadata_event) + eventManager().subscribe(Events.METADATA_STATISTICS_UPDATED, self._on_metadata_event) #~~ handling of PrinterCallbacks @@ -149,25 +150,23 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): #~~ callback from metadata analysis event - def _on_event_MetadataAnalysisFinished(self, event, data): - if self._selectedFile: - self._setJobData(self._selectedFile["filename"], - self._selectedFile["filesize"], - self._selectedFile["sd"]) - - def _on_event_MetadataStatisticsUpdated(self, event, data): - self._setJobData(self._selectedFile["filename"], - self._selectedFile["filesize"], - self._selectedFile["sd"]) + def _on_metadata_event(self, event, data): + with self._selectedFileLock: + if self._selectedFile and data and data.get("path", None) == self._selectedFile["filename"] \ + and data.get("storage", None) == FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL: + self._setJobData(self._selectedFile["filename"], + self._selectedFile["filesize"], + self._selectedFile["sd"]) #~~ progress plugin reporting def _reportPrintProgressToPlugins(self, progress): - if not progress or not self._selectedFile or not "sd" in self._selectedFile or not "filename" in self._selectedFile: - return + with self._selectedFileLock: + if not progress or not self._selectedFile or not "sd" in self._selectedFile or not "filename" in self._selectedFile: + return - storage = "sdcard" if self._selectedFile["sd"] else "local" - filename = self._selectedFile["filename"] + storage = "sdcard" if self._selectedFile["sd"] else "local" + filename = self._selectedFile["filename"] def call_plugins(storage, filename, progress): for plugin in self._progressPlugins: @@ -378,13 +377,16 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): """ if self._comm is None or not self._comm.isOperational() or self._comm.isPrinting(): return - if self._selectedFile is None: - return + + with self._selectedFileLock: + if self._selectedFile is None: + return + sd = self._selectedFile["sd"] rolling_window = None threshold = None countdown = None - if self._selectedFile["sd"]: + if sd: # we are interesting in a rolling window of roughly the last 15s, so the number of entries has to be derived # by that divided by the sd status polling interval rolling_window = 15 / settings().get(["serial", "timeout", "sdStatus"]) @@ -441,15 +443,16 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): self._setProgressData() # mark print as failure - if self._selectedFile is not None: - self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False, self._printerProfileManager.get_current_or_default()["id"]) - payload = { - "file": self._selectedFile["filename"], - "origin": FileDestinations.LOCAL - } - if self._selectedFile["sd"]: - payload["origin"] = FileDestinations.SDCARD - eventManager().fire(Events.PRINT_FAILED, payload) + with self._selectedFileLock: + if self._selectedFile is not None: + self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False, self._printerProfileManager.get_current_or_default()["id"]) + payload = { + "file": self._selectedFile["filename"], + "origin": FileDestinations.LOCAL + } + if self._selectedFile["sd"]: + payload["origin"] = FileDestinations.SDCARD + eventManager().fire(Events.PRINT_FAILED, payload) def get_state_string(self): """ @@ -632,9 +635,13 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): estimatedTotalPrintTime = self._estimateTotalPrintTime(progress, cleanedPrintTime) totalPrintTime = estimatedTotalPrintTime - if self._selectedFile and "estimatedPrintTime" in self._selectedFile and self._selectedFile["estimatedPrintTime"]: - statisticalTotalPrintTime = self._selectedFile["estimatedPrintTime"] - if progress and cleanedPrintTime: + statisticalTotalPrintTime = None + with self._selectedFileLock: + if self._selectedFile and "estimatedPrintTime" in self._selectedFile and self._selectedFile[ + "estimatedPrintTime"]: + statisticalTotalPrintTime = self._selectedFile["estimatedPrintTime"] + + if statisticalTotalPrintTime is not None and progress and cleanedPrintTime: if estimatedTotalPrintTime is None: totalPrintTime = statisticalTotalPrintTime else: @@ -691,14 +698,16 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): else: path_in_storage = self._fileManager.path_in_storage(FileDestinations.LOCAL, filename) path_on_disk = self._fileManager.path_on_disk(FileDestinations.LOCAL, filename) - self._selectedFile = { - "filename": path_in_storage, - "filesize": filesize, - "sd": sd, - "estimatedPrintTime": None - } + with self._selectedFileLock: + self._selectedFile = { + "filename": path_in_storage, + "filesize": filesize, + "sd": sd, + "estimatedPrintTime": None + } else: - self._selectedFile = None + with self._selectedFileLock: + self._selectedFile = None self._stateMonitor.set_job_data({ "file": { "name": None, @@ -741,11 +750,13 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): if "lastPrintTime" in fileData["statistics"] and printer_profile in fileData["statistics"]["lastPrintTime"]: lastPrintTime = fileData["statistics"]["lastPrintTime"][printer_profile] - if averagePrintTime is not None: - self._selectedFile["estimatedPrintTime"] = averagePrintTime - elif estimatedPrintTime is not None: - # TODO apply factor which first needs to be tracked! - self._selectedFile["estimatedPrintTime"] = estimatedPrintTime + with self._selectedFileLock: + if self._selectedFile is not None: + if averagePrintTime is not None: + self._selectedFile["estimatedPrintTime"] = averagePrintTime + elif estimatedPrintTime is not None: + # TODO apply factor which first needs to be tracked! + self._selectedFile["estimatedPrintTime"] = estimatedPrintTime self._stateMonitor.set_job_data({ "file": { @@ -802,9 +813,10 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): # forward relevant state changes to gcode manager if oldState == comm.MachineCom.STATE_PRINTING: - if self._selectedFile is not None: - if state == comm.MachineCom.STATE_CLOSED or state == comm.MachineCom.STATE_ERROR or state == comm.MachineCom.STATE_CLOSED_WITH_ERROR: - self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False, self._printerProfileManager.get_current_or_default()["id"]) + with self._selectedFileLock: + if self._selectedFile is not None: + if state == comm.MachineCom.STATE_CLOSED or state == comm.MachineCom.STATE_ERROR or state == comm.MachineCom.STATE_CLOSED_WITH_ERROR: + self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False, self._printerProfileManager.get_current_or_default()["id"]) self._analysisQueue.resume() # printing done, put those cpu cycles to good use elif state == comm.MachineCom.STATE_PRINTING: self._analysisQueue.pause() # do not analyse files while printing @@ -862,8 +874,9 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): self.start_print(pos=self._posAfterSelect) def on_comm_print_job_done(self): - self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), True, self._printerProfileManager.get_current_or_default()["id"]) - self._setProgressData(completion=1.0, filepos=self._selectedFile["filesize"], printTime=self._comm.getPrintTime(), printTimeLeft=0) + with self._selectedFileLock: + self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), True, self._printerProfileManager.get_current_or_default()["id"]) + self._setProgressData(completion=1.0, filepos=self._selectedFile["filesize"], printTime=self._comm.getPrintTime(), printTimeLeft=0) self._stateMonitor.set_state({"text": self.get_state_string(), "flags": self._getStateFlags()}) self._fileManager.delete_recovery_data() From 2f26104b982556d2036006044a75bff3bb491298 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 21 Jul 2016 16:11:09 +0200 Subject: [PATCH 3/3] Better sleep debug command in virtual printer --- .../plugins/virtual_printer/virtual.py | 29 +++++++++++++++++-- 1 file changed, 26 insertions(+), 3 deletions(-) diff --git a/src/octoprint/plugins/virtual_printer/virtual.py b/src/octoprint/plugins/virtual_printer/virtual.py index 63a3654f..93ad5825 100644 --- a/src/octoprint/plugins/virtual_printer/virtual.py +++ b/src/octoprint/plugins/virtual_printer/virtual.py @@ -82,6 +82,7 @@ class VirtualPrinter(object): self._incoming_lock = threading.RLock() + self._debug_sleep = None self._sleepAfterNext = dict() self._sleepAfter = dict() @@ -412,7 +413,7 @@ class VirtualPrinter(object): if sleep_match is not None: interval = int(sleep_match.group(1)) self._output("// sleeping for {interval} seconds".format(interval=interval)) - time.sleep(interval) + self._debug_sleep = interval elif sleep_after_match is not None: command = sleep_after_match.group(1) interval = int(sleep_after_match.group(2)) @@ -803,11 +804,32 @@ class VirtualPrinter(object): if self._debug_drop_connection: raise SerialTimeoutException() + if self._debug_sleep > 0: + # if we are supposed to sleep, we sleep not longer than the read timeout + # (and then on the next call sleep again if there's time to sleep left) + sleep_for = min(self._debug_sleep, self._read_timeout) + self._debug_sleep -= sleep_for + time.sleep(sleep_for) + + if self._debug_sleep > 0: + # we slept the full read timeout, return an empty line + return "" + + # otherwise our left over timeout is the read timeout minus what we already + # slept for + timeout = self._read_timeout - sleep_for + + else: + # use the full read timeout as timeout + timeout = self._read_timeout + try: - line = self.outgoing.get(timeout=self._read_timeout) + # fetch a line from the queue, wait no longer than timeout + line = self.outgoing.get(timeout=timeout) self.outgoing.task_done() return line except Queue.Empty: + # queue empty? return empty line return "" def close(self): @@ -843,7 +865,8 @@ class CharCountingQueue(Queue.Queue): try: if not self._will_it_fit(item) and partial: space_left = self.maxsize - self._qsize() - item = item[:space_left] + if space_left: + item = item[:space_left] if not block: if not self._will_it_fit(item):