General improvements.

- Test tool can now test write as well as read errors.
- Added watchdog timer to marlinSerialProtocol.
- Resync after send now improved.

tests/gcodeSender.py

@@ -47,9 +47,9 @@ def send_gcode_test(filename, serial):
     gcode = load_gcode(filename)
 
   for i, line in enumerate(gcode):
-    serial.sendCommand(line)
+    serial.enqueueCommand(line)
     while(not serial.clearToSend()):
-      serial.readLine()
+      serial.readline()
     if(i % 1000 == 0):
       print("Progress: %d" % (i*100/len(gcode)), end='\r')
       sys.stdout.flush()
@@ -57,7 +57,8 @@ def send_gcode_test(filename, serial):
 parser = argparse.ArgumentParser(description='''sends gcode to a printer while injecting errors to test error recovery.''')
 parser.add_argument('-p', '--port',   help='Serial port.', default='/dev/ttyACM1')
 parser.add_argument('-f', '--fake',   help='Use a fake Marlin simulation instead of serial port, for self-testing.', action='store_false', dest='port')
-parser.add_argument('-e', '--errors', help='Corrupt 1 out N lines to exercise error recovery.', default='0', type=int)
+parser.add_argument('-e', '--errors', help='Corrupt 1 out N lines written to exercise error recovery.', default='0', type=int)
+parser.add_argument('-r', '--readerrors', help='Corrupt 1 out N lines read to exercise error recovery.', default='0', type=int)
 parser.add_argument('-l', '--log',    help='Write log file.')
 parser.add_argument('-b', '--baud',   help='Sets the baud rate for the serial port.', default='115000', type=int)
 parser.add_argument('filename',       help='file containing gcode, or TEST for synthetic non-printing GCODE')
@@ -73,14 +74,19 @@ else:
   print("Using simulated Marlin device.")
   sio = FakeMarlinSerialDevice()
 
+if args.readerrors:
+  print("1 out of %d lines read will be corrupted." % args.readerrors)
+  sio = NoisySerialConnection(sio)
+  sio.setReadErrorRate(1, args.readerrors)
+
 if args.log:
   print("Writing log file: ", args.log)
   sio = LoggingSerialConnection(sio, args.log)
 
 if args.errors:
-  print("1 out of %d lines will be corrupted." % args.errors)
+  print("1 out of %d lines written will be corrupted." % args.errors)
   sio = NoisySerialConnection(sio)
-  sio.setErrorRate(1, args.errors)
+  sio.setWriteErrorRate(1, args.errors)
 
 print()
 

tests/pyMarlin/fakeMarlinSerialDevice.py

@@ -21,9 +21,10 @@ class FakeMarlinSerialDevice:
      contain errors"""
 
   def __init__(self):
-    self.line      = 1
-    self.replies   = []
-    self.pendingOk = 0
+    self.line           = 1
+    self.replies        = []
+    self.pendingOk      = 0
+    self.dropCharacters = 0
 
     self.cumulativeReads     = 0
     self.cumulativeWrites    = 0
@@ -44,14 +45,37 @@ class FakeMarlinSerialDevice:
     else:
       return ''
 
+  def _enqueue_okay(self):
+    self._enqueue_reply("ok T:10")
+
   def _computeChecksum(self, data):
     """Computes the GCODE checksum, this is the XOR of all characters in the payload, including the position"""
-    return functools.reduce(lambda x,y: x^y, map(ord, data))
+    return functools.reduce(lambda x,y: x^y, map(ord, data) if isinstance(data, str) else list(data))
 
   def write(self, data):
-    if not isinstance(data, (bytes, bytearray)):
+    if isinstance(data, str):
       data = data.encode()
-    m = re.match(b'N(\d+)(\D[^*]*)\*(\d*)$', data)
+
+    if data.strip() == b"":
+      return
+
+    if self.dropCharacters:
+      data = data[self.dropCharacters:]
+      self.dropCharacters = 0
+
+    hasLineNumber = b"N" in data
+    hasChecksum   = b"*" in data
+
+    if not hasLineNumber and not hasChecksum:
+      self._enqueue_okay()
+      return
+
+    # Handle M110 commands which tell Marlin to reset the line counter
+    m = re.match(b'N(\d+)M110\*(\d+)$', data)
+    if m:
+      self.line = int(m.group(1))
+
+    m = re.match(b'N(\d+)(\D[^*]*)\*(\d+)$', data)
     if m and int(m.group(1)) == self.line and self._computeChecksum(b"N%d%s" % (self.line, m.group(2))) == int(m.group(3)):
       # We have a valid, properly sequenced command with a valid checksum
       self.line += 1
@@ -61,11 +85,14 @@ class FakeMarlinSerialDevice:
       self.replies   = []
       self.pendingOk = 0
       self._enqueue_reply("Resend: " + str(self.line))
+      # When Marlin issues a resend, it often misses the next few
+      # characters. So simulate this here.
+      self.dropCharacters = random.randint(0, 5)
 
     for i in range(0,random.randint(0,4)):
       # Simulate a command that takes a while to execute
       self._enqueue_reply("")
-    self._enqueue_reply("ok T:10")
+    self._enqueue_okay()
 
     self.cumulativeWrites     += 1
     self.cumulativeQueueSize  += self.pendingOk
@@ -83,4 +110,4 @@ class FakeMarlinSerialDevice:
     print("Average errors per write:         %.2f" % (float(self.cumulativeErrors)    / self.cumulativeWrites))
     print("Total writes:                     %d"   % self.cumulativeWrites)
     print("Total errors:                     %d"   % self.cumulativeErrors)
-    print("")
+    print()

tests/pyMarlin/marlinSerialProtocol.py

@@ -86,29 +86,28 @@ class MarlinSerialProtocol:
     self.serial                 = serial
     self.marlinBufSize          = 4
     self.marlinReserve          = 1
-    self.pendingOk              = 0
-    self.gotError               = False
     self.history                = GCodeHistory()
+    self.slow_commands          = re.compile("M109|M190|G28|G29")
     self.restart()
 
   def _stripCommentsAndWhitespace(self, str):
-    return str.split(';', 1)[0].strip()
+    return str.split(b';', 1)[0].strip()
 
   def _replaceEmptyLineWithM105(self, str):
     """Marlin will not accept empty lines, so replace blanks with M115 (Get Extruder Temperature)"""
-    return "M105" if str == "" else str
+    return b"M105" if str == b"" else str
 
   def _computeChecksum(self, data):
     """Computes the GCODE checksum, this is the XOR of all characters in the payload, including the position"""
-    return functools.reduce(lambda x,y: x^y, map(ord, data))
+    return functools.reduce(lambda x,y: x^y, map(ord, data) if isinstance(data, str) else list(data))
 
   def _addPositionAndChecksum(self, position, cmd):
     """An GCODE with line number and checksum consists of N{position}{cmd}*{checksum}"""
-    data = "N%d%s"    % (position, cmd)
-    return "N%d%s*%d" % (position, cmd, self._computeChecksum(data))
+    data = b"N%d%s"    % (position, cmd)
+    return b"N%d%s*%d" % (position, cmd, self._computeChecksum(data))
 
   def _sendImmediate(self, cmd):
-      self.serial.write(cmd + '\n')
+      self.serial.write(cmd + b'\n')
       self.serial.flush()
       self.pendingOk += 1
 
@@ -124,19 +123,22 @@ class MarlinSerialProtocol:
   def _isResendRequest(self, line):
     """If the line is a resend command from Marlin, returns the line number. This
        code was taken from Cura 1, I do not know why it is so convoluted."""
-    if "resend" in line.lower() or "rs" in line:
+    if b"resend" in line.lower() or b"rs" in line:
       try:
-        return int(line.replace("N:"," ").replace("N"," ").replace(":"," ").split()[-1])
+        return int(line.replace(b"N:",b" ").replace(b"N",b" ").replace(b":",b" ").split()[-1])
       except:
-        if "rs" in line:
-          return int(line.split()[1])
+        if b"rs" in line:
+          try:
+            return int(line.split()[1])
+          except:
+            return None
 
   def _isNoLineNumberErr(self, line):
     """If Marlin encounters a checksum without a line number, it will request
        a resend. This often happens at the start of a print, when a command is
        sent prior to Marlin being ready to listen."""
-    if line.startswith("Error:No Line Number with checksum"):
-      m = re.search("Last Line: (\d+)", line);
+    if line.startswith(b"Error:No Line Number with checksum"):
+      m = re.search(b"Last Line: (\d+)", line);
       if(m):
         return int(m.group(1)) + 1
 
@@ -146,111 +148,108 @@ class MarlinSerialProtocol:
     cmd = self._addPositionAndChecksum(self.history.position()-1, b"M110")
     self._sendImmediate(cmd)
 
+  def _stallWatchdog(self, line):
+    """Watches for a stall in the print. This can happen if a number of
+       okays are lost in transmission. To recover, we send Marlin a command
+       with an invalid checksum. One it requests a resend, we will back into
+       a known good state."""
+    if line == b"":
+      if self.stallCountdown > 0:
+        self.stallCountdown -= 1
+      else:
+        self.stallCountdown = 30
+        self._sendImmediate("\nN0M105*0\n")
+    else:
+      estimated_duration = 15 if self.slow_commands.search(line) else 2
+      self.stallCountdown = max(estimated_duration, self.stallCountdown-1)
+
   def _resendFrom(self, position):
     """If Marlin requests a resend, we need to backtrack."""
     self.history.rewindTo(position)
-    self.pendingOk    = 1
-    self._enterResyncPeriod();
+    self.pendingOk     = 0
+    self.consecutiveOk = 0
 
   def _flushReadBuffer(self):
     while self.serial.readline() != b"":
       pass
 
-  def sendCommand(self, cmd):
-    """Sends a command. Should only be called if clearToSend() is true"""
+  def enqueueCommand(self, cmd):
+    """Adds a command to the sending queue. Queued commands will only be processed during calls to readLine()"""
+    if isinstance(cmd, str):
+      cmd = cmd.encode()
     cmd = self._stripCommentsAndWhitespace(cmd)
     cmd = self._replaceEmptyLineWithM105(cmd)
     cmd = self._addPositionAndChecksum(self.history.getAppendPosition(), cmd)
-    # Add command to the history, but immediately send it out.
     self.history.append(cmd)
-    self._sendToMarlin()
 
   def _gotOkay(self):
     if self.pendingOk > 0:
       self.pendingOk -= 1
 
-  def _enterResyncPeriod(self):
-    """We define two operational modes. In the normal mode, we send as many
-       commands as necessary to keep the Marlin queue filled and wait for
-       an acknowledgement prior to issuing each subsequent command. In the
-       resync mode, we send only one command at a time, unless there is a
-       timeout waiting for a response, in which case we proceed to the next
-       command. The resync mode is engaged at the start of a print or after
-       an error causing a resend, as at those times the normal mode could
-       lead to an unrecoverable failure loop or block indefinitely."""
-    self.resyncCountdown = self.marlinBufSize
-
-  def _resyncCountdown(self):
-    """Decrement the resync countdown so we can eventually return to
-    normal mode"""
-    if self.resyncCountdown > 0:
-      self.resyncCountdown -= 1
-
-  def _inResync(self):
-    return self.resyncCountdown > 0
-
-  def readLine(self):
+  def readline(self):
     """This reads data from Marlin. If no data is available '' will be returned after
-       the comm timeout. This *must* be called periodically to keep outgoing data moving
-       from the buffers."""
+       the comm timeout."""
+
     self._sendToMarlin()
     line = self.serial.readline()
 
-    # An okay means Marlin acknowledged a command. For us,
-    # this means a slot has been freed in the Marlin buffer.
+    # An okay means Marlin acknowledged a command. This means
+    # a slot has been freed in the Marlin buffer for a new
+    # command.
     if line.startswith(b"ok"):
       self._gotOkay()
-      self._resyncCountdown()
 
-    # During the resync period, we treat timeouts as "ok".
-    # This keeps us from stalling if an "ok" is lost.
-    if self._inResync() and line == b"":
-      self._resyncCountdown()
+    # Watch for and attempt to recover from complete stalls.
+    self._stallWatchdog(line)
 
     # Sometimes Marlin replies with an "Error:", but not an "ok".
     # So if we got an error, followed by a timeout, stop waiting
     # for an "ok" as it probably ain't coming
     if line.startswith(b"ok"):
       self.gotError = False
-    elif line.startswith("Error:"):
+    elif line.startswith(b"Error:"):
       self.gotError = True;
     elif line == b"" and self.gotError:
       self.gotError = False
       self._gotOkay()
 
-    # Handle retry related messages. There's no specific
-    # consistency on how these are indicated, alas.
+    # Handle resend requests from Marlin. This happens when Marlin
+    # detects a command with a checksum or line number error.
     resendPos = self._isResendRequest(line) or self._isNoLineNumberErr(line)
     if resendPos:
+      # If we got a resend requests, purge lines until timeout, but watch
+      # for any subsequent resend requests (we must only act on the last).
+      while line != b"":
+        line = self.serial.readline()
+        resendPos = self._isResendRequest(line) or self._isNoLineNumberErr(line) or resendPos
+      # Process the last received resend request:
       if resendPos > self.history.position():
         # If Marlin is asking us to step forward in time, reset its counter.
-        self._resetMarlinLineCounter();
+        self._resetMarlinLineCounter()
       else:
         # Otherwise rewind to where Marlin wants us to resend from.
-        self._resendFrom(resendPos);
+        self._resendFrom(resendPos)
+      # Report a timeout to the calling code.
       line = b""
 
     return line
 
   def clearToSend(self):
-      self._sendToMarlin()
-      return self.marlinBufferCapacity() > 0
+    self._sendToMarlin()
+    return self.marlinBufferCapacity() > 0
 
   def marlinBufferCapacity(self):
     """Returns how many buffer positions are open in Marlin. This is the difference between
-       the non-reserved buffer spots and the number of not yet acknowleged commands. In
-       resync mode, this always returns 0 if a command has not yet been acknowledged, 1
-       otherwise."""
-    if self._inResync():
-      return 0 if self.pendingOk else 1
-    else:
-      return (self.marlinBufSize - self.marlinReserve) - self.pendingOk
+       the non-reserved buffer spots and the number of not yet acknowleged commands."""
+    return (self.marlinBufSize - self.marlinReserve) - self.pendingOk
 
   def restart(self):
     """Clears all buffers and issues a M110 to Marlin. Call this at the start of every print."""
     self.history.clear()
+    self.pendingOk       = 0
+    self.stallCountdown  = 30
+    self.gotError        = False
     self._flushReadBuffer()
-    self._enterResyncPeriod()
     self._resetMarlinLineCounter()
 
   def close(self):

tests/pyMarlin/noisySerialConnection.py

@@ -14,24 +14,34 @@ import random
 import string
 
 class NoisySerialConnection:
-  """Wrapper class which injects character noise into the outgoing packets
-     of a serial connection for testing Marlin's error correction"""
+  """Wrapper class which injects character noise into data of
+     a serial connection for testing Marlin's error correction"""
   def __init__(self, serial):
-    self.serial     = serial
-    self.errorRate  = 0
+    self.serial         = serial
+    self.readErrorRate  = 0
+    self.writeErrorRate = 0
 
-  def _corruptStr(self, str):
+  def _corruptData(self, data):
     """Introduces a single character error on a string"""
-    charToCorrupt = random.randint(0, len(str) - 1)
-    return str[:charToCorrupt] + random.choice(string.ascii_letters) + str[charToCorrupt+1:]
+    badChar = random.choice(string.ascii_letters)
+    badChar = badChar if isinstance(data, str) else badChar.encode()
+    if len(data) == 0:
+      return data
+    if len(data) == 1:
+      return badChar
+    charToCorrupt = random.randint(0, len(data) - 1)
+    return data[:charToCorrupt] + badChar + data[charToCorrupt+1:]
 
   def write(self, data):
-    if(random.random() < self.errorRate):
-      data = self._corruptStr(data)
+    if(random.random() < self.writeErrorRate):
+      data = self._corruptData(data)
     self.serial.write(data)
 
   def readline(self):
-    return self.serial.readline()
+    data = self.serial.readline()
+    if(random.random() < self.readErrorRate):
+      data = self._corruptData(data)
+    return data
 
   def flush(self):
     self.serial.flush()
@@ -39,6 +49,10 @@ class NoisySerialConnection:
   def close(self):
     self.serial.close()
 
-  def setErrorRate(self, badWrites, totalWrites):
+  def setWriteErrorRate(self, badWrites, totalWrites):
     """Inserts a single character error into every badWrites out of totalWrites"""
-    self.errorRate = float(badWrites)/float(totalWrites)
+    self.writeErrorRate = float(badWrites)/float(totalWrites)
+
+  def setReadErrorRate(self, badReads, totalReads):
+    """Inserts a single character error into every badReads out of totalReads"""
+    self.readErrorRate = float(badReads)/float(totalReads)