From 937487037aeae452d1656e2fc38870b8203eb5a6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Wed, 13 Jul 2016 17:21:45 +0200 Subject: [PATCH 1/6] Shorter timeout during heatup & no scary message on end Set read timeout on serial port to a much shorter value (default 2.0s) during a heatup. Firmware should usually send the current temperature back every second, so if that stops we can consider the heatup to be finished even if we don't see an ok. That is important in cases such as SD printing, where we might see a heatup sequence we didn't trigger ourselves, during which we shouldn't spam the printer with commands it potentially can't process but after which we still should take up normal communication again. In case of a heatup sequence triggered by an SD print we won't see an ok and hence only can now through a timeout that things are now done printer side. In such a case the user should not get thrown a scary timeout message in their general direction either. Solves #1409 --- .../plugins/virtual_printer/virtual.py | 22 ++++++++++-- src/octoprint/settings.py | 1 + src/octoprint/util/comm.py | 35 +++++++++++++------ 3 files changed, 45 insertions(+), 13 deletions(-) diff --git a/src/octoprint/plugins/virtual_printer/virtual.py b/src/octoprint/plugins/virtual_printer/virtual.py index 1d9adba6..77b79ead 100644 --- a/src/octoprint/plugins/virtual_printer/virtual.py +++ b/src/octoprint/plugins/virtual_printer/virtual.py @@ -16,7 +16,7 @@ from serial import SerialTimeoutException from octoprint.settings import settings from octoprint.plugin import plugin_manager -class VirtualPrinter(): +class VirtualPrinter(object): command_regex = re.compile("[GM]\d+") sleep_regex = re.compile("sleep (\d+)") sleep_after_regex = re.compile("sleep_after ([GM]\d+) (\d+)") @@ -25,7 +25,7 @@ class VirtualPrinter(): def __init__(self, read_timeout=5.0, write_timeout=10.0): import logging - self._logger = logging.getLogger("octoprint.plugin.virtual_printer.VirtualPrinter") + self._logger = logging.getLogger("octoprint.plugins.virtual_printer.VirtualPrinter") self._read_timeout = read_timeout self._write_timeout = write_timeout @@ -108,6 +108,24 @@ class VirtualPrinter(): return "VIRTUAL(read_timeout={read_timeout},write_timeout={write_timeout},options={options})"\ .format(read_timeout=self._read_timeout, write_timeout=self._write_timeout, options=settings().get(["devel", "virtualPrinter"])) + @property + def timeout(self): + return self._read_timeout + + @timeout.setter + def timeout(self, value): + self._logger.debug("Setting read timeout to {}s".format(value)) + self._read_timeout = value + + @property + def write_timeout(self): + return self._write_timeout + + @write_timeout.setter + def write_timeout(self, value): + self._logger.debug("Setting write timeout to {}s".format(value)) + self._write_timeout = value + def _clearQueue(self, queue): try: while queue.get(block=False): diff --git a/src/octoprint/settings.py b/src/octoprint/settings.py index 84fe8d80..d135e798 100644 --- a/src/octoprint/settings.py +++ b/src/octoprint/settings.py @@ -81,6 +81,7 @@ default_settings = { "detection": 0.5, "connection": 10, "communication": 30, + "heatup": 2, "temperature": 5, "sdStatus": 1 }, diff --git a/src/octoprint/util/comm.py b/src/octoprint/util/comm.py index bd84f70a..e9bb8fb6 100644 --- a/src/octoprint/util/comm.py +++ b/src/octoprint/util/comm.py @@ -956,7 +956,10 @@ class MachineCom(object): if line is None: break if line.strip() is not "": - self._timeout = get_new_timeout("communication", self._timeout_intervals) + if self._heating: + self._timeout = get_new_timeout("heatup", self._timeout_intervals) + else: + self._timeout = get_new_timeout("communication", self._timeout_intervals) ##~~ debugging output handling if line.startswith("//"): @@ -1059,8 +1062,7 @@ class MachineCom(object): elif ' T:' in line or line.startswith('T:') or ' T0:' in line or line.startswith('T0:') or ((' B:' in line or line.startswith('B:')) and not 'A:' in line): if not disable_external_heatup_detection and not line.strip().startswith("ok") and not self._heating: self._logger.debug("Externally triggered heatup detected") - self._heating = True - self._heatupWaitStartTime = time.time() + self._track_heatup() self._processTemperatures(line) self._callback.on_comm_temperature_update(self._temp, self._bedTemp) @@ -1259,10 +1261,7 @@ class MachineCom(object): self._currentTool = self._formerTool self._formerTool = None - if self._heatupWaitStartTime: - self._heatupWaitTimeLost = self._heatupWaitTimeLost + (time.time() - self._heatupWaitStartTime) - self._heatupWaitStartTime = None - self._heating = False + self._finish_heatup() if not self._state in (self.STATE_PRINTING, self.STATE_OPERATIONAL, self.STATE_PAUSED): return @@ -1291,6 +1290,10 @@ class MachineCom(object): self._resendSameCommand() self._clear_to_send.set() + elif self._heating: + self._logger.debug("Timeout while in an active heatup, considering heatup to be over then") + self._finish_heatup() + else: self._log("Communication timeout while printing, trying to trigger response from printer. " + general_message) self._sendCommand("M105", cmd_type="temperature") @@ -1298,6 +1301,18 @@ class MachineCom(object): return + def _track_heatup(self): + self._heating = True + self._heatupWaitStartTime = time.time() + self._serial.timeout = settings().getFloat(["serial", "timeout", "heatup"]) + + def _finish_heatup(self): + if self._heatupWaitStartTime: + self._heatupWaitTimeLost = self._heatupWaitTimeLost + (time.time() - self._heatupWaitStartTime) + self._heatupWaitStartTime = None + self._heating = False + self._serial.timeout = settings().getFloat(["serial", "timeout", "communication"]) + def _continue_sending(self): if self._state == self.STATE_PRINTING: if not self._sendFromQueue() and not self.isSdPrinting(): @@ -2036,15 +2051,13 @@ class MachineCom(object): pass def _gcode_M109_sent(self, cmd, cmd_type=None): - self._heatupWaitStartTime = time.time() self._long_running_command = True - self._heating = True + self._track_heatup() self._gcode_M104_sent(cmd, cmd_type, wait=True) def _gcode_M190_sent(self, cmd, cmd_type=None): - self._heatupWaitStartTime = time.time() self._long_running_command = True - self._heating = True + self._track_heatup() self._gcode_M140_sent(cmd, cmd_type, wait=True) def _gcode_M110_sending(self, cmd, cmd_type=None): From 297c434d641db4e10f4f742f5829706124f0573f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 14 Jul 2016 11:41:39 +0200 Subject: [PATCH 2/6] Ease up a bit on the version pinning --- setup.py | 48 ++++++++++++++++++++++++------------------------ 1 file changed, 24 insertions(+), 24 deletions(-) diff --git a/setup.py b/setup.py index 565113f2..bf0cb84f 100644 --- a/setup.py +++ b/setup.py @@ -15,26 +15,26 @@ import octoprint_setuptools # Requirements for our application INSTALL_REQUIRES = [ "flask>=0.9,<0.11", - "werkzeug==0.8.3", - "tornado==4.0.1", - "sockjs-tornado==1.0.1", - "PyYAML==3.10", - "Flask-Login==0.2.2", - "Flask-Principal==0.3.5", - "Flask-Babel==0.9", - "Flask-Assets==0.10", - "Flask-Markdown==0.3", - "pyserial==2.7", - "netaddr==0.7.17", - "watchdog==0.8.3", - "sarge==0.1.4", - "netifaces==0.10", - "pylru==1.0.9", - "rsa==3.2", - "pkginfo==1.2.1", - "requests==2.7.0", - "semantic_version==2.4.2", - "psutil==3.2.1", + "werkzeug>=0.8.3,<0.9", + "tornado>=4.0.1,<4.1", + "sockjs-tornado>=1.0.1,<1.1", + "PyYAML>=3.10,<3.11", + "Flask-Login>=0.2.2,<0.3", + "Flask-Principal>=0.3.5,<0.4", + "Flask-Babel>=0.9,<0.10", + "Flask-Assets>=0.10,<0.11", + "Flask-Markdown>=0.3,<0.4", + "pyserial>=2.7,<2.8", + "netaddr>=0.7.17,<0.8", + "watchdog>=0.8.3,<0.9", + "sarge>=0.1.4,<0.2", + "netifaces>=0.10,<0.11", + "pylru>=1.0.9,<1.1", + "rsa>=3.2,<3.3", + "pkginfo>=1.2.1,<1.3", + "requests>=2.7.0,<2.8", + "semantic_version>=2.4.2,<2.5", + "psutil>=3.2.1,<3.3", "awesome-slugify>=1.6.5,<1.7", "feedparser>=5.2.1,<5.3" ] @@ -44,12 +44,12 @@ EXTRA_REQUIRES = dict( # Dependencies for developing OctoPrint develop=[ # Testing dependencies - "mock>=1.0.1", - "nose>=1.3.0", + "mock>=1.0.1,<1.1", + "nose>=1.3.0,<1.4", "ddt", # Documentation dependencies - "sphinx>=1.3", + "sphinx>=1.3,<1.4", "sphinxcontrib-httpdomain", "sphinx_rtd_theme", @@ -59,7 +59,7 @@ EXTRA_REQUIRES = dict( # Dependencies for developing OctoPrint plugins plugins=[ - "cookiecutter" + "cookiecutter>=1.4,<1.5" ] ) From 20fc7f25bc89130f6d31fc84001a6e3cf31075c0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 14 Jul 2016 19:20:05 +0200 Subject: [PATCH 3/6] Fix: Ensure log entries and messages from printer are unicode Otherwise even one line that can't be converted while sending the backlog to the client can kill the whole backlog. --- src/octoprint/printer/standard.py | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/src/octoprint/printer/standard.py b/src/octoprint/printer/standard.py index 4fea92f1..e758d5ee 100644 --- a/src/octoprint/printer/standard.py +++ b/src/octoprint/printer/standard.py @@ -24,6 +24,7 @@ from octoprint.printer.estimation import TimeEstimationHelper from octoprint.settings import settings from octoprint.util import comm as comm from octoprint.util import InvariantContainer +from octoprint.util import to_unicode class Printer(PrinterInterface, comm.MachineComPrintCallback): @@ -50,11 +51,9 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): self._temps = TemperatureHistory(cutoff=settings().getInt(["temperature", "cutoff"])*60) self._tempBacklog = [] - self._latestMessage = None self._messages = deque([], 300) self._messageBacklog = [] - self._latestLog = None self._log = deque([], 300) self._logBacklog = [] @@ -770,10 +769,8 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): "messages": list(self._messages) }) callback.on_printer_send_initial_data(data) - except Exception, err: - import sys - sys.stderr.write("ERROR: %s\n" % str(err)) - pass + except: + self._logger.exception("Error while trying to send inital state update") def _getStateFlags(self): return { @@ -792,7 +789,7 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): """ Callback method for the comm object, called upon log output. """ - self._addLog(message) + self._addLog(to_unicode(message, "utf-8", errors="replace")) def on_comm_temperature_update(self, temp, bedTemp): self._addTemperatureData(temp, bedTemp) @@ -827,7 +824,7 @@ class Printer(PrinterInterface, comm.MachineComPrintCallback): Callback method for the comm object, called upon message exchanges via serial. Stores the message in the message buffer, truncates buffer to the last 300 lines. """ - self._addMessage(message) + self._addMessage(to_unicode(message, "utf-8", errors="replace")) def on_comm_progress(self): """ @@ -924,6 +921,8 @@ class StateMonitor(object): self._change_event = threading.Event() self._state_lock = threading.Lock() self._progress_lock = threading.Lock() + self._log_lock = threading.Lock() + self._message_lock = threading.Lock() self._last_update = time.time() self._worker = threading.Thread(target=self._work) From bfcd00e466824cd56dd7ae9123196214edde0221 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 14 Jul 2016 19:42:43 +0200 Subject: [PATCH 4/6] Fix: Send non-protocol messages from the printer to clients Solves #1385 --- src/octoprint/util/comm.py | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/src/octoprint/util/comm.py b/src/octoprint/util/comm.py index 5cf8283a..269ec8cb 100644 --- a/src/octoprint/util/comm.py +++ b/src/octoprint/util/comm.py @@ -1171,13 +1171,7 @@ class MachineCom(object): self._handle_ok() ##~~ Message handling - elif line != '' \ - and not line.startswith("ok") \ - and not line.startswith("wait") \ - and not line.startswith('Resend:') \ - and line != 'echo:Unknown command:""\n' \ - and self.isOperational(): - self._callback.on_comm_message(line) + self._callback.on_comm_message(line) ##~~ Parsing for feedback commands if feedback_controls and feedback_matcher and not "_all" in feedback_errors: From 0a8a7ba589d9765bd1c036818d281963d44112bb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 14 Jul 2016 19:43:22 +0200 Subject: [PATCH 5/6] Fixed some imports --- src/octoprint/server/util/sockjs.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/octoprint/server/util/sockjs.py b/src/octoprint/server/util/sockjs.py index 6663834b..0554f346 100644 --- a/src/octoprint/server/util/sockjs.py +++ b/src/octoprint/server/util/sockjs.py @@ -12,6 +12,9 @@ import time import octoprint.timelapse import octoprint.server +import octoprint.events +import octoprint.plugin + from octoprint.events import Events import octoprint.printer From 92f9ed465e3516c9039b64a5192bfd0daed195f3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gina=20H=C3=A4u=C3=9Fge?= Date: Thu, 14 Jul 2016 19:46:44 +0200 Subject: [PATCH 6/6] Removed two unused locks from StateMonitor --- src/octoprint/printer/standard.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/octoprint/printer/standard.py b/src/octoprint/printer/standard.py index e758d5ee..2400a12f 100644 --- a/src/octoprint/printer/standard.py +++ b/src/octoprint/printer/standard.py @@ -921,8 +921,6 @@ class StateMonitor(object): self._change_event = threading.Event() self._state_lock = threading.Lock() self._progress_lock = threading.Lock() - self._log_lock = threading.Lock() - self._message_lock = threading.Lock() self._last_update = time.time() self._worker = threading.Thread(target=self._work)