Don't trigger an M105 on timeout during a resend
Had to reorder message processing a bit in order to be able to properly handle further resends in timeout situations. Has the added benefit that "ok" now gets processed very early and now extra state based processing is needed anymore.
This commit is contained in:
Gina Häußge
parent
d393a6730c
commit
c9009496f6
2 changed files with 171 additions and 105 deletions
|
|
@ -91,6 +91,10 @@ class VirtualPrinter():
|
|||
|
||||
self._killed = False
|
||||
|
||||
self._triggerResendAt100 = True
|
||||
self._triggerResendWithTimeoutAt105 = True
|
||||
self._triggeredResendWithTimeoutAt105 = False
|
||||
|
||||
waitThread = threading.Thread(target=self._sendWaitAfterTimeout)
|
||||
waitThread.start()
|
||||
|
||||
|
|
@ -148,6 +152,10 @@ class VirtualPrinter():
|
|||
linenumber = int(re.search("N([0-9]+)", data).group(1))
|
||||
self.lastN = linenumber
|
||||
self.currentLine = linenumber
|
||||
|
||||
self._triggerResendAt100 = True
|
||||
self._triggerResendWithTimeoutAt105 = True
|
||||
|
||||
self._sendOk()
|
||||
continue
|
||||
elif data.startswith("N"):
|
||||
|
|
@ -156,10 +164,18 @@ class VirtualPrinter():
|
|||
if linenumber != expected:
|
||||
self._triggerResend(actual=linenumber)
|
||||
continue
|
||||
elif self.currentLine == 100:
|
||||
elif linenumber == 100 and self._triggerResendAt100:
|
||||
# simulate a resend at line 100
|
||||
self._triggerResendAt100 = False
|
||||
self._triggerResend(expected=100)
|
||||
continue
|
||||
elif linenumber == 105 and self._triggerResendWithTimeoutAt105 and not self._writingToSd:
|
||||
# simulate a resend with timeout at line 105
|
||||
self._triggerResendWithTimeoutAt105 = False
|
||||
self._triggerResend(expected=105)
|
||||
self._dont_answer = True
|
||||
self.lastN = linenumber
|
||||
continue
|
||||
else:
|
||||
self.lastN = linenumber
|
||||
data = data.split(None, 1)[1].strip()
|
||||
|
|
|
|||
|
|
@ -246,6 +246,8 @@ class MachineCom(object):
|
|||
self._resendSwallowRepetitions = settings().getBoolean(["feature", "ignoreIdenticalResends"])
|
||||
self._resendSwallowRepetitionsCounter = 0
|
||||
|
||||
self._resendActive = False
|
||||
|
||||
self._terminal_log = deque([], 20)
|
||||
|
||||
self._disconnect_on_errors = settings().getBoolean(["serial", "disconnectOnErrors"])
|
||||
|
|
@ -340,7 +342,7 @@ class MachineCom(object):
|
|||
self._serialLogger.debug(message)
|
||||
|
||||
def _to_logfile_with_terminal(self, message=None, level=logging.INFO):
|
||||
log = "Last lines in terminal:\n" + "\n".join(map(lambda x: "| " + x, self._terminal_log))
|
||||
log = "Last lines in terminal:\n" + "\n".join(map(lambda x: "| " + x, list(self._terminal_log)))
|
||||
if message is not None:
|
||||
log = message + "\n| " + log
|
||||
self._logger.log(level, log)
|
||||
|
|
@ -974,10 +976,29 @@ class MachineCom(object):
|
|||
self._sdFiles.append((filename, size))
|
||||
continue
|
||||
|
||||
##~~ process oks
|
||||
if line.strip().startswith("ok") or (self.isPrinting() and supportWait and line.strip().startswith("wait")):
|
||||
self._clear_to_send.set()
|
||||
self._long_running_command = False
|
||||
handled = False
|
||||
|
||||
# process oks
|
||||
if line.startswith("ok") or (self.isPrinting() and supportWait and line == "wait"):
|
||||
# ok only considered handled if it's alone on the line, might be
|
||||
# a response to an M105 or an M114
|
||||
self._handle_ok()
|
||||
handled = (line == "wait" or line == "ok" or not ("T:" in line or "T0:" in line or "B:" in line or "C:" in line))
|
||||
|
||||
# process resends
|
||||
elif lower_line.startswith("resend") or lower_line.startswith("rs"):
|
||||
self._handleResendRequest(line)
|
||||
handled = True
|
||||
|
||||
# process timeouts
|
||||
elif line == "" and time.time() > self._timeout:
|
||||
# timeout only considered handled if the printer is printing
|
||||
self._handle_timeout()
|
||||
handled = self.isPrinting()
|
||||
|
||||
# we don't have to process the rest if the line has already been handled fully
|
||||
if handled and self._state not in (self.STATE_CONNECTING, self.STATE_DETECT_BAUDRATE):
|
||||
continue
|
||||
|
||||
##~~ Temperature processing
|
||||
if ' T:' in line or line.startswith('T:') or ' T0:' in line or line.startswith('T0:') or ' B:' in line or line.startswith('B:'):
|
||||
|
|
@ -1016,16 +1037,6 @@ class MachineCom(object):
|
|||
except ValueError:
|
||||
pass
|
||||
|
||||
#If we are waiting for an M109 or M190 then measure the time we lost during heatup, so we can remove that time from our printing time estimate.
|
||||
if line.startswith("ok"):
|
||||
if self._formerTool is not None:
|
||||
self._currentTool = self._formerTool
|
||||
self._formerTool = None
|
||||
if self._heatupWaitStartTime:
|
||||
self._heatupWaitTimeLost = self._heatupWaitTimeLost + (time.time() - self._heatupWaitStartTime)
|
||||
self._heatupWaitStartTime = None
|
||||
self._heating = False
|
||||
|
||||
##~~ SD Card handling
|
||||
elif 'SD init fail' in line or 'volume.init failed' in line or 'openRoot failed' in line:
|
||||
self._sdAvailable = False
|
||||
|
|
@ -1094,12 +1105,11 @@ class MachineCom(object):
|
|||
if self._trigger_ok_for_m29:
|
||||
# workaround for most versions of Marlin out in the wild
|
||||
# not sending an ok after saving a file
|
||||
self._clear_to_send.set()
|
||||
line, lower_line = convert_line("ok")
|
||||
self._handle_ok()
|
||||
elif 'File deleted' in line and line.strip().endswith("ok"):
|
||||
# buggy Marlin version that doesn't send a proper \r after the "File deleted" statement, fixed in
|
||||
# buggy Marlin version that doesn't send a proper line break after the "File deleted" statement, fixed in
|
||||
# current versions
|
||||
self._clear_to_send.set()
|
||||
self._handle_ok()
|
||||
|
||||
##~~ Message handling
|
||||
elif line != '' \
|
||||
|
|
@ -1158,7 +1168,8 @@ class MachineCom(object):
|
|||
eventManager().fire(Events.ERROR, {"error": self.getErrorString()})
|
||||
elif 'start' in line or 'ok' in line:
|
||||
self._onConnected()
|
||||
self._clear_to_send.set()
|
||||
if 'start' in line:
|
||||
self._clear_to_send.set()
|
||||
|
||||
### Connection attempt
|
||||
elif self._state == self.STATE_CONNECTING:
|
||||
|
|
@ -1170,32 +1181,6 @@ class MachineCom(object):
|
|||
elif time.time() > self._timeout:
|
||||
self.close()
|
||||
|
||||
### Operational
|
||||
elif self._state == self.STATE_OPERATIONAL or self._state == self.STATE_PAUSED:
|
||||
if line.startswith("ok"):
|
||||
self._handle_ok()
|
||||
|
||||
# resend -> start resend procedure from requested line
|
||||
elif lower_line.startswith("resend") or lower_line.startswith("rs"):
|
||||
self._handleResendRequest(line)
|
||||
|
||||
### Printing
|
||||
elif self._state == self.STATE_PRINTING:
|
||||
if line == "" and time.time() > self._timeout:
|
||||
if not self._long_running_command:
|
||||
self._log("Communication timeout during printing, forcing a line")
|
||||
self._sendCommand("M105")
|
||||
self._clear_to_send.set()
|
||||
else:
|
||||
self._logger.debug("Ran into a communication timeout, but a command known to be a long runner is currently active")
|
||||
|
||||
if line.startswith("ok") or (supportWait and line.startswith("wait")):
|
||||
# a wait while printing means our printer's buffer ran out, probably due to some ok getting
|
||||
# swallowed, so we treat it the same as an ok here to take up communication again
|
||||
self._handle_ok()
|
||||
|
||||
elif lower_line.startswith("resend") or lower_line.startswith("rs"):
|
||||
self._handleResendRequest(line)
|
||||
except:
|
||||
self._logger.exception("Something crashed inside the serial connection loop, please report this in OctoPrint's bug tracker:")
|
||||
|
||||
|
|
@ -1207,16 +1192,54 @@ class MachineCom(object):
|
|||
self._log("Connection closed, closing down monitor")
|
||||
|
||||
def _handle_ok(self):
|
||||
self._clear_to_send.set()
|
||||
|
||||
# reset long running commands, persisted current tools and heatup counters on ok
|
||||
|
||||
self._long_running_command = False
|
||||
|
||||
if self._formerTool is not None:
|
||||
self._currentTool = self._formerTool
|
||||
self._formerTool = None
|
||||
|
||||
if self._heatupWaitStartTime:
|
||||
self._heatupWaitTimeLost = self._heatupWaitTimeLost + (time.time() - self._heatupWaitStartTime)
|
||||
self._heatupWaitStartTime = None
|
||||
self._heating = False
|
||||
|
||||
if not self._state in (self.STATE_PRINTING, self.STATE_OPERATIONAL, self.STATE_PAUSED):
|
||||
return
|
||||
|
||||
if self._resendSwallowNextOk:
|
||||
self._resendSwallowNextOk = False
|
||||
elif self._resendDelta is not None:
|
||||
# process queues ongoing resend requests and queues if we are operational
|
||||
|
||||
if self._resendDelta is not None:
|
||||
self._resendNextCommand()
|
||||
else:
|
||||
self._resendActive = False
|
||||
self._continue_sending()
|
||||
|
||||
return
|
||||
|
||||
def _handle_timeout(self):
|
||||
if self._state not in (self.STATE_PRINTING,):
|
||||
return
|
||||
|
||||
if self._long_running_command:
|
||||
self._logger.debug("Ran into a communication timeout, but a command known to be a long runner is currently active")
|
||||
|
||||
general_message = "Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves."
|
||||
if self._resendActive:
|
||||
self._log("Communication timeout while printing and during an active resend, resending same line again to trigger response from printer. " + general_message)
|
||||
self._resendSameCommand()
|
||||
self._clear_to_send.set()
|
||||
|
||||
else:
|
||||
self._log("Communication timeout while printing, trying to trigger response from printer. " + general_message)
|
||||
self._sendCommand("M105")
|
||||
self._clear_to_send.set()
|
||||
|
||||
return
|
||||
|
||||
def _continue_sending(self):
|
||||
if self._state == self.STATE_PRINTING:
|
||||
if not self._sendFromQueue() and not self.isSdPrinting():
|
||||
|
|
@ -1524,70 +1547,97 @@ class MachineCom(object):
|
|||
if "rs" in line:
|
||||
lineToResend = int(line.split()[1])
|
||||
|
||||
if lineToResend is not None:
|
||||
self._resendSwallowNextOk = True
|
||||
if lineToResend is None:
|
||||
return False
|
||||
|
||||
lastCommError = self._lastCommError
|
||||
self._lastCommError = None
|
||||
|
||||
resendDelta = self._currentLine - lineToResend
|
||||
|
||||
if lastCommError is not None \
|
||||
and ("line number" in lastCommError.lower() or "expected line" in lastCommError.lower()) \
|
||||
and lineToResend == self._lastResendNumber \
|
||||
and self._resendDelta is not None and self._currentResendCount < self._resendDelta:
|
||||
self._logger.debug("Ignoring resend request for line %d, that still originates from lines we sent before we got the first resend request" % lineToResend)
|
||||
self._currentResendCount += 1
|
||||
return
|
||||
|
||||
# If we ignore resend repetitions (Repetier firmware...), check if we
|
||||
# need to do this now. If the same line number has been requested we
|
||||
# already saw and resent, we'll ignore it up to <counter> times.
|
||||
if self._resendSwallowRepetitions and lineToResend == self._lastResendNumber and self._resendSwallowRepetitionsCounter > 0:
|
||||
self._logger.debug("Ignoring resend request for line %d, that is probably a repetition sent by the firmware to ensure it arrives, not a real request" % lineToResend)
|
||||
self._resendSwallowRepetitionsCounter -= 1
|
||||
return
|
||||
|
||||
self._resendDelta = resendDelta
|
||||
self._lastResendNumber = lineToResend
|
||||
self._currentResendCount = 0
|
||||
self._resendSwallowRepetitionsCounter = settings().getInt(["feature", "identicalResendsCountdown"])
|
||||
|
||||
if self._resendDelta > len(self._lastLines) or len(self._lastLines) == 0 or self._resendDelta < 0:
|
||||
self._errorValue = "Printer requested line %d but no sufficient history is available, can't resend" % lineToResend
|
||||
self._log(self._errorValue)
|
||||
self._logger.warn(self._errorValue + ". Printer requested line {}, current line is {}, line history has {} entries.".format(lineToResend, self._currentLine, len(self._lastLines)))
|
||||
if self.isPrinting():
|
||||
# abort the print, there's nothing we can do to rescue it now
|
||||
self._changeState(self.STATE_ERROR)
|
||||
eventManager().fire(Events.ERROR, {"error": self.getErrorString()})
|
||||
else:
|
||||
# reset resend delta, we can't do anything about it
|
||||
self._resendDelta = None
|
||||
else:
|
||||
self._resendNextCommand()
|
||||
|
||||
# if we log resends, make sure we don't log more resends than the set rate within a window
|
||||
if self._resendDelta is None and lineToResend == self._currentLine:
|
||||
# We don't expect to have an active resend request and the printer is requesting a resend of
|
||||
# a line we haven't yet sent.
|
||||
#
|
||||
# this it to prevent the log from getting flooded for extremely bad communication issues
|
||||
if self._log_resends:
|
||||
now = time.time()
|
||||
new_rate_window = self._log_resends_rate_start is None or self._log_resends_rate_start + self._log_resends_rate_frame < now
|
||||
in_rate = self._log_resends_rate_count < self._log_resends_max
|
||||
# This means the printer got a line from us with N = self._currentLine - 1 but had already
|
||||
# acknowledged that. This can happen if the last line was resent due to a timeout during
|
||||
# an active (prior) resend request.
|
||||
#
|
||||
# We will ignore this resend request and just continue normally.
|
||||
self._logger.debug("Ignoring resend request for line %d == current line, we haven't sent that yet so the printer got N-1 twice from us, probably due to a timeout" % lineToResend)
|
||||
return False
|
||||
|
||||
if new_rate_window or in_rate:
|
||||
if new_rate_window:
|
||||
self._log_resends_rate_start = now
|
||||
self._log_resends_rate_count = 0
|
||||
lastCommError = self._lastCommError
|
||||
self._lastCommError = None
|
||||
|
||||
self._to_logfile_with_terminal("Got a resend request from the printer: requested line = {}, current line = {}".format(lineToResend, self._currentLine))
|
||||
self._log_resends_rate_count += 1
|
||||
resendDelta = self._currentLine - lineToResend
|
||||
|
||||
def _resendNextCommand(self):
|
||||
if lastCommError is not None \
|
||||
and ("line number" in lastCommError.lower() or "expected line" in lastCommError.lower()) \
|
||||
and lineToResend == self._lastResendNumber \
|
||||
and self._resendDelta is not None and self._currentResendCount < self._resendDelta:
|
||||
self._logger.debug("Ignoring resend request for line %d, that still originates from lines we sent before we got the first resend request" % lineToResend)
|
||||
self._currentResendCount += 1
|
||||
return True
|
||||
|
||||
# If we ignore resend repetitions (Repetier firmware...), check if we
|
||||
# need to do this now. If the same line number has been requested we
|
||||
# already saw and resent, we'll ignore it up to <counter> times.
|
||||
if self._resendSwallowRepetitions and lineToResend == self._lastResendNumber and self._resendSwallowRepetitionsCounter > 0:
|
||||
self._logger.debug("Ignoring resend request for line %d, that is probably a repetition sent by the firmware to ensure it arrives, not a real request" % lineToResend)
|
||||
self._resendSwallowRepetitionsCounter -= 1
|
||||
return True
|
||||
|
||||
self._resendActive = True
|
||||
self._resendDelta = resendDelta
|
||||
self._lastResendNumber = lineToResend
|
||||
self._currentResendCount = 0
|
||||
self._resendSwallowRepetitionsCounter = settings().getInt(["feature", "identicalResendsCountdown"])
|
||||
|
||||
if self._resendDelta > len(self._lastLines) or len(self._lastLines) == 0 or self._resendDelta < 0:
|
||||
self._errorValue = "Printer requested line %d but no sufficient history is available, can't resend" % lineToResend
|
||||
self._log(self._errorValue)
|
||||
self._logger.warn(self._errorValue + ". Printer requested line {}, current line is {}, line history has {} entries.".format(lineToResend, self._currentLine, len(self._lastLines)))
|
||||
if self.isPrinting():
|
||||
# abort the print, there's nothing we can do to rescue it now
|
||||
self._changeState(self.STATE_ERROR)
|
||||
eventManager().fire(Events.ERROR, {"error": self.getErrorString()})
|
||||
else:
|
||||
# reset resend delta, we can't do anything about it
|
||||
self._resendDelta = None
|
||||
|
||||
# if we log resends, make sure we don't log more resends than the set rate within a window
|
||||
#
|
||||
# this it to prevent the log from getting flooded for extremely bad communication issues
|
||||
if self._log_resends:
|
||||
now = time.time()
|
||||
new_rate_window = self._log_resends_rate_start is None or self._log_resends_rate_start + self._log_resends_rate_frame < now
|
||||
in_rate = self._log_resends_rate_count < self._log_resends_max
|
||||
|
||||
if new_rate_window or in_rate:
|
||||
if new_rate_window:
|
||||
self._log_resends_rate_start = now
|
||||
self._log_resends_rate_count = 0
|
||||
|
||||
self._to_logfile_with_terminal("Got a resend request from the printer: requested line = {}, current line = {}".format(lineToResend, self._currentLine))
|
||||
self._log_resends_rate_count += 1
|
||||
|
||||
return True
|
||||
|
||||
def _resendSameCommand(self):
|
||||
self._resendNextCommand(again=True)
|
||||
|
||||
def _resendNextCommand(self, again=False):
|
||||
self._lastCommError = None
|
||||
|
||||
# Make sure we are only handling one sending job at a time
|
||||
with self._sendingLock:
|
||||
if again:
|
||||
# If we are about to last line from the active resend request
|
||||
# again, we first need to increment resend delta. It might already
|
||||
# be set to None if the last resend line was already sent, so
|
||||
# if that's the case we set it to 0. It will then be incremented,
|
||||
# the last line will be sent again, and then the delta will be
|
||||
# decremented and set to None again, completing the cycle.
|
||||
if self._resendDelta is None:
|
||||
self._resendDelta = 0
|
||||
self._resendDelta += 1
|
||||
|
||||
cmd = self._lastLines[-self._resendDelta]
|
||||
lineNumber = self._currentLine - self._resendDelta
|
||||
|
||||
|
|
|
|||
Loading…
Reference in a new issue