What is the problem?
Attempted to print a calibration tower and it failed with a communication timeout error. Problem occurred just after updating to OctoPrint 1.3.9. Log seems to indicate it could be related to the Exclude Region plug-in.
Can you provide any insight as to what may be causing this? Thanks!
What did you already try to solve it?
Rebooted OctoPrint.
Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, octoprint.log
, serial.log
or output on terminal tab, ...)
OctoPrint version: 1.3.9
OctoPi version: 0.15.1
Printer: Prusa i3 MK3
Printer Firmware: 3.3.1-845
Pi: Raspberry Pi 3B+
Camera: Raspberry Pi Camera Module v2
OctoPrint Log (last few lines before failure):
2018-07-26 20:41:07,522 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 92.6, 'old': 93.0}
2018-07-26 20:41:14,460 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 8759, current line = 8766
| Last lines in terminal:
| Recv: ok
| Send: N8759 G1 E0.80000 F2100.00000*35
| Recv: ok
| Send: N8760 M204 S800*87
| Recv: ok
| Send: N8761 G1 F900*79
| Recv: ok
| Send: N8762 G1 X137.275 Y117.275 E0.00609*84
| Send: N8763 G1 X112.725 Y117.275 E0.83099*86
| Recv: echo:busy: processing
| Recv: echo:busy: processing
| Recv: echo:busy: processing
| Recv: ok
| Send: N8764 M105*26
| Recv: Full RX Buffer
| Recv: tmc2130_goto_step 3 28 2 1000
| Recv: ok
| Send: N8765 G1 X112.725 Y92.725 E0.83099*108
| Recv: Error:Line Number is not Last Line Number+1, Last Line: 8758
| Recv: Resend: 8759
2018-07-26 20:41:14,500 - octoprint.util.comm - INFO - Ignoring resend request for line 8759, that still originates from lines we sent before we got the first resend request
2018-07-26 20:41:14,597 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E-0.04000 F2100.00000
2018-07-26 20:41:14,598 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E-0.04000 F2100.00000, returnCommands=[u'G1 E-0.04000 F2100.00000']
2018-07-26 20:41:14,615 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.2, 'old': 92.6}
2018-07-26 20:41:14,621 - octoprint.plugins.excluderegion - INFO - Event received: event=Dwelling payload=None
2018-07-26 20:41:14,635 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 92.8, 'old': 93.2}
2018-07-26 20:41:18,694 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2018-07-26 20:41:21,528 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E0.80000 F2100.00000
2018-07-26 20:41:21,530 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E0.80000 F2100.00000, returnCommands=[u'G1 E0.80000 F2100.00000']
2018-07-26 20:41:21,665 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E-0.04000 F2100.00000
2018-07-26 20:41:21,666 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E-0.04000 F2100.00000, returnCommands=[u'G1 E-0.04000 F2100.00000']
2018-07-26 20:41:21,687 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.4, 'old': 92.8}
2018-07-26 20:41:21,692 - octoprint.plugins.excluderegion - INFO - Event received: event=Dwelling payload=None
2018-07-26 20:41:21,703 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E0.80000 F2100.00000
2018-07-26 20:41:21,705 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E0.80000 F2100.00000, returnCommands=[u'G1 E0.80000 F2100.00000']
2018-07-26 20:41:21,713 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.0, 'old': 93.4}
2018-07-26 20:41:28,607 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E-0.04000 F2100.00000
2018-07-26 20:41:28,608 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E-0.04000 F2100.00000, returnCommands=[u'G1 E-0.04000 F2100.00000']
2018-07-26 20:41:28,631 - octoprint.plugins.excluderegion - INFO - Event received: event=Dwelling payload=None
2018-07-26 20:41:28,636 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.6, 'old': 93.0}
2018-07-26 20:41:28,647 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E0.80000 F2100.00000
2018-07-26 20:41:28,648 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E0.80000 F2100.00000, returnCommands=[u'G1 E0.80000 F2100.00000']
2018-07-26 20:41:28,661 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.2, 'old': 93.6}
2018-07-26 20:41:35,705 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E-0.04000 F2100.00000
2018-07-26 20:41:35,707 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E-0.04000 F2100.00000, returnCommands=[u'G1 E-0.04000 F2100.00000']
2018-07-26 20:41:35,735 - octoprint.plugins.excluderegion - INFO - Event received: event=Dwelling payload=None
2018-07-26 20:41:35,752 - octoprint.plugins.excluderegion - WARNING - Encountered recovery without a corresponding retraction: G1 E0.80000 F2100.00000
2018-07-26 20:41:35,754 - octoprint.plugins.excluderegion - INFO - recovery: excluding=False, originalCmd=G1 E0.80000 F2100.00000, returnCommands=[u'G1 E0.80000 F2100.00000']
2018-07-26 20:41:35,758 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.8, 'old': 93.2}
2018-07-26 20:41:35,771 - octoprint.plugins.excluderegion - INFO - Event received: event=ZChange payload={'new': 93.4, 'old': 93.8}
2018-07-26 20:41:53,810 - octoprint.util.comm - INFO - No response from printer after 6 consecutive communication timeouts, considering it dead.
2018-07-26 20:41:53,833 - octoprint.plugins.excluderegion - INFO - Event received: event=Error payload={'reason': 'timeout', 'error': 'Too many consecutive timeouts, printer still connected and alive?'}
2018-07-26 20:41:53,834 - octoprint.plugins.excluderegion - INFO - Printing stopped
2018-07-26 20:41:53,845 - octoprint.plugins.excluderegion - INFO - Event received: event=UpdatedFiles payload={'type': 'gcode'}
2018-07-26 20:41:53,857 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2018-07-26 20:41:53,887 - octoprint.plugins.excluderegion - INFO - Event received: event=Disconnected payload=None
2018-07-26 20:41:53,894 - octoprint.plugins.excluderegion - INFO - Event received: event=PrinterStateChanged payload={'state_string': 'Offline', 'state_id': 'OFFLINE'}
2018-07-26 20:41:53,929 - octoprint.plugins.excluderegion - INFO - Event received: event=MetadataStatisticsUpdated payload={'path': u'pla-mk-3-ecor-tower.gcode', 'storage': 'local'}
2018-07-26 20:41:56,445 - octoprint.plugins.excluderegion - INFO - Event received: event=PrintFailed payload={'origin': 'local', 'name': u'pla-mk-3-ecor-tower.gcode', 'file': u'/home/pi/.octoprint/uploads/pla-mk-3-ecor-tower.gcode', 'time': 3557.72283411026, 'path': u'pla-mk-3-ecor-tower.gcode', 'size': 245309L, 'filename': u'pla-mk-3-ecor-tower.gcode'}
2018-07-26 20:41:56,446 - octoprint.plugins.excluderegion - INFO - Printing stopped
Serial Log (last few lines before failure):
2018-07-26 20:41:35,694 - Send: N8822 G1 X137.275 Y117.275 E-0.04401*124
2018-07-26 20:41:35,699 - Send: N8823 G1 F8160*112
2018-07-26 20:41:35,700 - Recv: ok
2018-07-26 20:41:35,714 - Recv: ok
2018-07-26 20:41:35,722 - Recv: ok
2018-07-26 20:41:35,723 - Send: N8824 G1 X134.346 Y117.275 E-0.71599*122
2018-07-26 20:41:35,737 - Recv: ok
2018-07-26 20:41:35,734 - Send: N8825 G1 E-0.04000 F2100.00000*6
2018-07-26 20:41:35,743 - Recv: ok
2018-07-26 20:41:35,747 - Send: N8826 G1 Z93.800 F10200.000*49
2018-07-26 20:41:35,748 - Recv: ok
2018-07-26 20:41:35,753 - Send: N8827 G4 S0*91
2018-07-26 20:41:35,761 - Send: TMC_SET_STEP_E932
2018-07-26 20:41:35,764 - Send: N8828 G1 Z93.400 F10200.000*51
2018-07-26 20:41:35,767 - Send: N8829 G1 E0.80000 F2100.00000*43
2018-07-26 20:41:35,769 - Send: N8830 M204 S800*93
2018-07-26 20:41:35,779 - Recv: Full RX Buffer
2018-07-26 20:41:53,812 - No response from printer after 6 consecutive communication timeouts, considering it dead. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2018-07-26 20:41:53,855 - Changing monitoring state from "Printing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2018-07-26 20:41:53,872 - Connection closed, closing down monitor