Printer disconnects at same spot in gcode file

BarrettJ · November 13, 2019, 4:18pm

What is the problem?

When trying to print a particular gcode file the printer will disconnect every time at the same spot. I've done longer prints without issue (this failure occurs relatively early) and the same file is now currently printing fine from a usb stick (past the part where it will cause the printer to disconnect from OctoPrint if I try to print via OctoPrint).

What did you already try to solve it?

Upped the timeout,
Updated the raspberry pi's firmware (it's a 3B+),
Lowered the baud rate,

Logs (octoprint.log, serial.log or output on terminal tab at a minimum, browser error console if UI issue ... no logs, no support!)

Here is the tail end of serial.log

2019-11-13 15:44:34,060 - Recv: ok
2019-11-13 15:44:34,067 - Send: N810 G1 X221.962 Y118.192 E108.3839*93
2019-11-13 15:44:34,322 - Recv: ok
2019-11-13 15:44:34,329 - Send: N811 G1 X222.192 Y117.857 E108.3961*91
2019-11-13 15:44:34,517 - Recv: ok
2019-11-13 15:44:34,524 - Send: N812 G1 X221.355 Y117.020 E108.4316*87
2019-11-13 15:44:34,817 - Recv: ok
2019-11-13 15:44:34,825 - Send: N813 G92 E0.0000*99
2019-11-13 15:44:34,983 - Recv: ok
2019-11-13 15:44:35,040 - Send: N814 G1 E-1.0000 F2400*18
2019-11-13 15:44:35,342 - Recv: ok
2019-11-13 15:44:35,393 - Send: N815 M106 S255*105
2019-11-13 15:45:05,364 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2019-11-13 15:45:05,379 - Send: N816 M105*40
2019-11-13 15:45:35,398 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2019-11-13 15:45:35,405 - Send: N817 M105*41
2019-11-13 15:46:05,433 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2019-11-13 15:46:05,444 - Send: N818 M105*38
2019-11-13 15:46:35,467 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2019-11-13 15:46:35,478 - Send: N819 M105*39
2019-11-13 15:47:05,526 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2019-11-13 15:47:05,533 - Send: N820 M105*45
2019-11-13 15:47:35,565 - 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.
2019-11-13 15:47:39,518 - Changing monitoring state from "Printing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2019-11-13 15:47:39,544 - Connection closed, closing down monitor

Here is the tail octoprint.log

2019-11-13 15:42:54,163 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: flintvasea.gcode, owner: barrett, user: barrett
2019-11-13 15:42:54,171 - octoprint.plugins.DisplayLayerProgress - INFO - File selected. Determining number of layers.
2019-11-13 15:43:02,206 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2019-11-13 15:43:02,263 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: flintvasea.gcode, owner: barrett, user: barrett
2019-11-13 15:43:02,277 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 15:43:02,329 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-11-13 15:43:02,755 - octoprint.plugins.DisplayLayerProgress - INFO - Printing started. Detailed progress started.{'origin': 'local', 'name': u'flintvasea.gcode', 'file': u'/home/pi/.octoprint/uploads/flintvasea.gcode', 'owner': 'barrett', 'path': u'flintvasea.gcode', 'user': 'barrett', 'size': 2962393L, 'filename': u'flintvasea.gcode'}
2019-11-13 15:43:03,468 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': '2cbc52d6a4cca403c94bc14fe87d216e24c333bb'}
2019-11-13 15:43:03,772 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:03] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:11,092 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:15,478 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:15] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:18,917 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:18] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:27,521 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:27] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:31,199 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:32,509 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:32] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:39,440 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:39] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:51,491 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:51,543 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:02,942 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:02] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:11,254 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:14,776 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:14] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:26,723 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:26] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:31,316 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:38,207 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:38] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:50,029 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:44:51,351 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:44:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:01,861 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:01] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:05,361 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:45:11,387 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:13,705 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:13] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:25,779 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:31,414 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:35,396 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:45:37,615 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:37] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:49,476 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:49] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:45:51,443 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:45:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:01,318 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:01] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:05,430 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:46:11,463 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:12,755 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:12] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:24,564 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:24] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:31,504 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:35,465 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:46:36,534 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:36] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:48,277 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:51,564 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:46:59,649 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:46:59] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:05,517 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:47:11,476 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:11,609 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:23,352 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:23] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:31,631 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:34,822 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:34] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:35,564 - octoprint.util.comm - INFO - No response from printer after 6 consecutive communication timeouts, considering it dead.
2019-11-13 15:47:35,871 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:35] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:36,296 - octoprint.plugins.tracking - INFO - Sent tracking event commerror_timeout, payload: {'commerror_text': 'Too many consecutive timeouts, printer still connected and alive?'}
2019-11-13 15:47:39,519 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2019-11-13 15:47:40,267 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2019-11-13 15:47:40,449 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:40] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:41,106 - octoprint.plugins.tracking - INFO - Sent tracking event print_failed, payload: {'origin': 'local', 'reason': 'error', 'commerror_text': 'Too many consecutive timeouts, printer still connected and alive?', 'file': '2cbc52d6a4cca403c94bc14fe87d216e24c333bb', 'elapsed': 277}
2019-11-13 15:47:41,179 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:41] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:47:51,693 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:47:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:48:11,738 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:48:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:48:31,790 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:48:31] "GET /?action=snapshot HTTP/1.1" 200 -

I can attach full logs if need be, but I didn't see much and the one log is over 10mb

Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible)

OctoPrint 1.3.12 running on OctoPi 0.16.0 on a pi 3B+ (from a CanaKit with the included power adapter)

CraftBot 3 Printer

I'm VERY new to 3d printing, sorry if excluding something useful and thank you in advance.

Ewald_Ikemann · November 13, 2019, 6:27pm

2019-11-13 15:44:35,393 - Send: N815 M106 S255*105

A wild guess: the (part cooling) fan lowers the bed or nozzle temperature that much, that the firmware tries to recover it but can't and the communication timeout triggers before the thermal runaway protection.

BarrettJ · November 13, 2019, 6:32pm

Does that mean my timeout just needs to be set longer in OctoPrint? It's currently printing that same exact file (that failed in that same spot a dozen times when sent via OctoPrint) via a USB stick in the printer.

Like is the issue that it cooled it too much, and is taking longer than the timeout to heat back up so OctoPrint is giving up?

I'm VERY new to 3D printing, and this is the second gcode I've made that errors in only OctoPrint (previous one I fixed by rotating the model in the slicer and that fixed the issue, I didn't try that this time as I've become a bit more familiar with the system)

Ewald_Ikemann · November 13, 2019, 8:10pm

I would rather don't set the fan to maximum speed. Try 75% or 50% in the slicer settings.
It would be a bit more easy if you would have sent the full log, because at the start the first settings for the print are made.

BarrettJ · November 13, 2019, 8:28pm

Here's more of the log (should be starting in the middle of the night during a successful print). The snapshots are really spamming the log, so I tried to trim some out.

2019-11-13 14:45:46,745 - octoprint.plugins.pluginmanager - INFO - Installing plugin from https://github.com/FormerLurker/Octolapse/archive/v0.3.4.zip
2019-11-13 14:45:55,957 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:45:55] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:46:03,808 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2019-11-13 14:46:05,159 - octoprint.plugin.core - INFO - Found 25 plugin(s) providing 24 mixin implementations, 40 hook handlers
2019-11-13 14:46:05,167 - octoprint.plugin.core - INFO - 25 plugin(s) registered with the system:
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
|  DisplayLayerProgress Plugin (1.14.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_DisplayLayerProgress
|  Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
|  Floating Navbar (0.3.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_floatingnavbar
|  Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
|  Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
|  Navbar Temperature Plugin (0.11) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_navbartemp
| !Octolapse (0.3.4) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_octolapse
|  OctoPrint Anywhere (1.0.20) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere
|  Octoslack (1.9.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_Octoslack
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
|  Printer Safety Check (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
|  Simple Emergency Stop (0.2.5) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_simpleemergencystop
|  Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
|  The Spaghetti Detective (1.0.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_thespaghettidetective
|  TouchUI (0.3.13) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_touchui
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
|  Webcam Tab (0.1.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_webcamtab
2019-11-13 14:46:05,169 - octoprint.plugins.pluginmanager - INFO - The plugin was installed successfully: Octolapse, version 0.3.4
2019-11-13 14:46:05,889 - octoprint.plugins.tracking - INFO - Sent tracking event install_plugin, payload: {'plugin_version': '0.3.4', 'plugin': 'octolapse'}
2019-11-13 14:46:16,036 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2019-11-13 14:46:16,092 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:46:16] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:46:16,993 - octoprint.plugin.core - INFO - Found 24 plugin(s) providing 24 mixin implementations, 40 hook handlers
2019-11-13 14:46:17,684 - octoprint.plugins.tracking - INFO - Sent tracking event uninstall_plugin, payload: {'plugin_version': '0.3.4', 'plugin': 'octolapse'}
2019-11-13 14:46:22,427 - octoprint.server.api.system - INFO - Performing command for core:restart: sudo service octoprint restart
2019-11-13 14:46:22,611 - octoprint.server - INFO - Shutting down...
2019-11-13 14:46:23,540 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2019-11-13 14:46:23,601 - octoprint.events - INFO - Event loop shut down
2019-11-13 14:46:23,663 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:46:23] "POST /shutdown HTTP/1.1" 404 -
2019-11-13 14:46:23,677 - octoprint.server - INFO - Goodbye!
2019-11-13 14:46:28,889 - octoprint.startup - INFO - ******************************************************************************
2019-11-13 14:46:28,892 - octoprint.startup - INFO - Starting OctoPrint 1.3.12
2019-11-13 14:46:28,893 - octoprint.startup - INFO - ******************************************************************************
2019-11-13 14:46:29,041 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online
2019-11-13 14:46:29,759 - octoprint.startup - INFO - Blacklist processing done, adding 1 blacklisted plugin versions: roomtemp (any)
2019-11-13 14:46:29,839 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2019-11-13 14:46:32,596 - octoprint.plugin.core - INFO - Found 24 plugin(s) providing 24 mixin implementations, 40 hook handlers
2019-11-13 14:46:33,207 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2019-11-13 14:46:33,221 - octoprint.server - INFO - Intermediary server started
2019-11-13 14:46:33,222 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2019-11-13 14:46:34,015 - octoprint.plugin.core - INFO - Found 24 plugin(s) providing 24 mixin implementations, 40 hook handlers
2019-11-13 14:46:34,059 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2019-11-13 14:46:34,805 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2019-11-13 14:46:35,077 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2019-11-13 14:46:36,920 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-11-13 14:46:38,722 - octoprint.util.pip - INFO - Version of pip is 19.0.1
2019-11-13 14:46:38,724 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2019-11-13 14:46:38,724 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-11-13 14:46:38,729 - octoprint.plugin.core - INFO - Initialized 24 plugin implementation(s)
2019-11-13 14:46:38,764 - octoprint.plugin.core - INFO - 24 plugin(s) registered with the system:
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
|  DisplayLayerProgress Plugin (1.14.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_DisplayLayerProgress
|  Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
|  Floating Navbar (0.3.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_floatingnavbar
|  Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
|  Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
|  Navbar Temperature Plugin (0.11) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_navbartemp
|  OctoPrint Anywhere (1.0.20) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere
|  Octoslack (1.9.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_Octoslack
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
|  Printer Safety Check (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
|  Simple Emergency Stop (0.2.5) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_simpleemergencystop
|  Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
|  The Spaghetti Detective (1.0.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_thespaghettidetective
|  TouchUI (0.3.13) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_touchui
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
|  Webcam Tab (0.1.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_webcamtab
2019-11-13 14:46:38,784 - octoprint.environment - INFO - Detected environment is Python 2.7.13 under Linux (linux2). Details:
|  hardware:
|    cores: 4
|    freq: 1400.0
|    ram: 918188032
|  os:
|    id: linux
|    platform: linux2
|  plugins:
|    pi_support:
|      model: Raspberry Pi 3 Model B Plus Rev 1.3
|      octopi_version: 0.16.0
|  python:
|    pip: 19.0.1
|    version: 2.7.13
|    virtualenv: /home/pi/oprint
2019-11-13 14:46:38,799 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2019-11-13 14:46:38,819 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2019-11-13 14:46:40,015 - octoprint.server - INFO - Shutting down intermediary server...
2019-11-13 14:46:40,343 - octoprint.server - INFO - Intermediary server shut down
2019-11-13 14:46:40,346 - octoprint.events - INFO - Processing startup event, this is our first event
2019-11-13 14:46:40,371 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2019-11-13 14:46:40,373 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2019-11-13 14:46:40,460 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-11-13 14:46:40,513 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2019-11-13 14:46:41,368 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2019-11-13 14:46:41,404 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2019-11-13 14:46:41,409 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2019-11-13 14:46:41,425 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on octopi' for _http._tcp
2019-11-13 14:46:41,439 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on octopi' for _octoprint._tcp
2019-11-13 14:46:41,447 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on octopi for SSDP
2019-11-13 14:46:41,484 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2019-11-13 14:46:41,548 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-11-13 14:46:42,016 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2019-11-13 14:46:43,006 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.163
2019-11-13 14:46:43,238 - octoprint.server.util.flask - INFO - Passively logging in user barrett from ::ffff:192.168.1.163
2019-11-13 14:46:43,254 - octoprint.server.util.sockjs - INFO - User barrett logged in on the socket from client ::ffff:192.168.1.163
2019-11-13 14:46:43,548 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-11-13 14:46:43,550 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2019-11-13 14:46:43,551 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-11-13 14:46:43,847 - py.warnings - WARNING - /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere/config.py:53: YAMLLoadWarning: calling yaml.load() without Loader=... is deprecated, as the default Loader is unsafe. Please read https://msg.pyyaml.org/load for full details.
  self.__items__ = yaml.load(config_str)

2019-11-13 14:46:43,951 - octoprint.plugins.navbartemp - INFO - Broadcom detected
2019-11-13 14:46:44,124 - octoprint.plugins.anywhere - WARNING - {u'mjpeg_stream_tier': 1, u'UserId': 36910, u'camResolution': u'medium', u'name': u'Craftbot 3', u'premium_video': True, u'flipV': True, u'octolapseOptedIn': True, u'recordTimelapse': True, u'rotate90N': False, u'token': u'T93HCQLETZN1NPZMBFFIL6KQYNPIOFWQ', u'lastSeen': u'2019-11-13T14:46:10.329Z', u'flipH': False, u'updatedAt': u'2019-11-13T14:46:10.329Z', u'deletedAt': None, u'rotate90': False, u'id': 47248, u'createdAt': u'2019-11-09T21:13:04.157Z', u'subscription': u'pro'}
2019-11-13 14:46:44,125 - octoprint.plugins.anywhere - WARNING - Printer is eligible for premium video streaming.
2019-11-13 14:46:44,326 - backoff - INFO - Backing off capture_mjpeg(...) for 0.7s (URLError: <urlopen error [Errno 111] Connection refused>)
2019-11-13 14:46:44,456 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 12}
2019-11-13 14:46:45,194 - backoff - INFO - Backing off capture_mjpeg(...) for 0.1s (URLError: <urlopen error [Errno 111] Connection refused>)
2019-11-13 14:46:45,408 - octoprint.plugins.tracking - INFO - Sent tracking event pong, payload: {'plugins': u'displaylayerprogress:1.14.2,webcamtab:0.1.2,octoslack:1.9.1,touchui:0.3.13,simpleemergencystop:0.2.5,thespaghettidetective:1.0.0,navbartemp:0.11,anywhere:1.0.20,floatingnavbar:0.3.1'}
2019-11-13 14:46:45,420 - backoff - INFO - Backing off capture_mjpeg(...) for 1.9s (URLError: <urlopen error [Errno 111] Connection refused>)
2019-11-13 14:46:45,842 - werkzeug - INFO -  * Running on http://0.0.0.0:8080/ (Press CTRL+C to quit)
2019-11-13 14:46:45,941 - octoprint.plugins.anywhere - WARNING - Launching: /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere/bin/ffmpeg -re -i pipe:0 -y -an -vcodec copy -f hls -hls_time 2 -hls_list_size 10 -hls_delete_threshold 10 -hls_flags split_by_time+delete_segments+second_level_segment_index -strftime 1 -hls_segment_filename /tmp/octoprintanywhere-ts/%s-%%d.ts -hls_segment_type mpegts -
2019-11-13 14:46:46,056 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'python': '2.7.13', 'ram': 918188032, 'octopi_version': '0.16.0', 'version': u'1.3.12', 'pip': '19.0.1', 'cores': 4, 'freq': 1400.0, 'pi_model': 'Raspberry Pi 3 Model B Plus Rev 1.3', 'os': 'linux'}
2019-11-13 14:46:47,517 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:46:47] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:46:54,481 - octoprint.plugins.thespaghettidetective - WARNING - Conceding pi camera exclusive use
2019-11-13 14:47:04,533 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:47:04] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:47:24,615 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:47:24] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:47:44,762 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:47:44] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:48:04,822 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:48:04] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:48:05,723 - octoprint.server.util.flask - INFO - Passively logging in user barrett from ::ffff:192.168.1.163
2019-11-13 14:48:25,392 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:48:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:48:25,475 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:192.168.1.163
2019-11-13 14:48:26,024 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.163
2019-11-13 14:48:26,272 - octoprint.server.util.flask - INFO - Passively logging in user barrett from ::ffff:192.168.1.163
2019-11-13 14:48:28,325 - octoprint.server.util.sockjs - INFO - User barrett logged in on the socket from client ::ffff:192.168.1.163
2019-11-13 14:48:44,839 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:48:44] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:49:04,991 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:49:04] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:49:24,979 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:49:24] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:49:45,060 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:49:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:50:05,038 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:50:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:50:25,157 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:50:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:50:45,096 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:50:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:51:05,091 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:51:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:51:25,115 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:51:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:51:45,186 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:51:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:52:05,294 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:52:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:52:25,300 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:52:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:52:45,288 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:52:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:53:05,345 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:53:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:53:25,414 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:53:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:53:45,458 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:53:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:54:05,512 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:54:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:54:25,501 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:54:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:54:45,653 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:54:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:55:05,640 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:55:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:55:25,789 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:55:25] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:55:45,865 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:55:45] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:56:05,892 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:56:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:56:26,017 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:56:26] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:56:46,108 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:56:46] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:57:06,099 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:57:06] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:57:26,127 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:57:26] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:57:46,286 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:57:46] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:58:06,347 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:58:06] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:58:26,298 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:58:26] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:58:46,366 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:58:46] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:59:06,406 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:59:06] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:59:26,428 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:59:26] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:59:40,579 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial port"
2019-11-13 14:59:40,981 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2019-11-13 14:59:40,985 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial port" to "Connecting"
2019-11-13 14:59:41,769 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 14:59:41,786 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 14:59:41,792 - octoprint.util.comm - INFO - Changing monitoring state from "Connecting" to "Operational"
2019-11-13 14:59:41,797 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 14:59:42,185 - octoprint.util.comm - INFO - Printer reports firmware name "pr3Dator"
2019-11-13 14:59:42,865 - octoprint.plugins.tracking - INFO - Sent tracking event printer_connected, payload: {u'printer_baudrate': 115200, u'printer_port': u'AUTO', 'firmware_name': 'pr3Dator'}
2019-11-13 14:59:46,533 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 14:59:46] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 14:59:51,961 - octoprint.filemanager.analysis - INFO - Starting analysis of local:flintvasea.gcode
2019-11-13 14:59:51,990 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python2 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 --offset 0.0 0.0 /home/pi/.octoprint/uploads/flintvasea.gcode
2019-11-13 14:59:58,715 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: flintvasea.gcode, owner: barrett, user: barrett
2019-11-13 14:59:58,721 - octoprint.plugins.DisplayLayerProgress - INFO - File selected. Determining number of layers.
2019-11-13 14:59:58,826 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2019-11-13 14:59:58,902 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: flintvasea.gcode, owner: barrett, user: barrett
2019-11-13 14:59:58,920 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 14:59:58,953 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-11-13 15:00:00,163 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:00:00] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:00:02,355 - octoprint.plugins.DisplayLayerProgress - INFO - Printing started. Detailed progress started.{'origin': 'local', 'name': u'flintvasea.gcode', 'file': u'/home/pi/.octoprint/uploads/flintvasea.gcode', 'owner': 'barrett', 'path': u'flintvasea.gcode', 'user': 'barrett', 'size': 2962393L, 'filename': u'flintvasea.gcode'}
2019-11-13 15:00:03,377 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': '2cbc52d6a4cca403c94bc14fe87d216e24c333bb'}
2019-11-13 15:07:08,627 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:07:19,656 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:19] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:07:27,701 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:27] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:07:31,130 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:07:41,833 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:07:42,643 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:42] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:07:47,766 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:47] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:07:53,799 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:07:53] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:05,203 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:05] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:07,845 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:07] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:11,876 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:08:16,674 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:16] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:27,860 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:27] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:28,041 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:28] "GET /?action=snapshot HTTP/1.1" 200 -

BarrettJ · November 13, 2019, 8:29pm

2019-11-13 15:08:39,173 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:39] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:41,886 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:08:47,983 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:47] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:08:50,662 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:08:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:02,122 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:02] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:07,959 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:07] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:11,908 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:09:13,602 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:13] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:24,643 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:24] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:27,988 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:27] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:36,078 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:36] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:41,941 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2019-11-13 15:09:47,547 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:47] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:48,100 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:09:58,650 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:09:58] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:08,175 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:10,103 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:11,970 - octoprint.util.comm - INFO - No response from printer after 6 consecutive communication timeouts, considering it dead.
2019-11-13 15:10:12,279 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:12] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:12,740 - octoprint.plugins.tracking - INFO - Sent tracking event commerror_timeout, payload: {'commerror_text': 'Too many consecutive timeouts, printer still connected and alive?'}
2019-11-13 15:10:15,957 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Offline (Error: Too many consecutive timeouts, printer still connected and alive?)"
2019-11-13 15:10:15,969 - octoprint.filemanager.analysis - INFO - Starting analysis of local:flintvasea.gcode
2019-11-13 15:10:15,974 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python2 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 --offset 0.0 0.0 /home/pi/.octoprint/uploads/flintvasea.gcode
2019-11-13 15:10:17,193 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2019-11-13 15:10:17,659 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:17] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:17,791 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:17] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:18,025 - octoprint.plugins.tracking - INFO - Sent tracking event print_failed, payload: {'origin': 'local', 'reason': 'error', 'commerror_text': 'Too many consecutive timeouts, printer still connected and alive?', 'file': '2cbc52d6a4cca403c94bc14fe87d216e24c333bb', 'elapsed': 617}
2019-11-13 15:10:28,195 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:28] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:10:36,206 - octoprint.filemanager.analysis - INFO - Analysis of entry local:flintvasea.gcode finished, needed 20.24s
2019-11-13 15:10:48,310 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:10:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:11:08,334 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:11:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:11:28,405 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:11:28] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:11:48,450 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:11:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:12:08,477 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:12:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:12:28,575 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:12:28] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:12:48,654 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:12:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:13:08,679 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:13:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:13:28,661 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:13:28] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:13:48,650 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:13:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:14:08,775 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:14:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:14:28,797 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:14:28] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:14:48,910 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:14:48] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:15:08,930 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:15:08] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:15:29,007 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:15:29] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:15:49,030 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:15:49] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:16:09,099 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:16:09] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:16:29,165 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:16:29] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:16:33,212 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-11-13 15:16:44,478 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 1812}
2019-11-13 15:16:49,279 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:16:49] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:17:09,346 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:17:09] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:17:29,330 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:17:29] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:17:29,787 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:17:29] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:17:49,856 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:17:49] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:18:09,912 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:18:09] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:18:29,999 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:18:29] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:18:50,022 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:18:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:19:10,046 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:19:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:19:30,081 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:19:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:19:50,102 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:19:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:20:10,095 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:20:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:20:30,201 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:20:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:20:50,229 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:20:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:21:10,216 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:21:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:21:30,258 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:21:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:21:50,324 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:21:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:22:10,396 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:22:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:22:30,417 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:22:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:22:50,458 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:22:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:23:10,488 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:23:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:23:30,513 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:23:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:23:50,576 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:23:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:24:10,617 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:24:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:24:30,602 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:24:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:24:50,634 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:24:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:25:10,655 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:25:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:25:30,723 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:25:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:25:50,765 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:25:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:26:10,797 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:26:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:26:30,819 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:26:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:26:50,890 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:26:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:27:10,878 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:27:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:27:30,957 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:27:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:27:51,049 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:27:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:28:11,131 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:28:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:28:31,119 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:28:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:28:51,155 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:28:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:29:11,249 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:29:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:29:31,275 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:29:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:29:51,347 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:29:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:30:11,386 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:30:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:30:31,373 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:30:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:30:51,435 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:30:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:31:11,471 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:31:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:31:31,543 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:31:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:31:33,214 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-11-13 15:31:44,467 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 2712}
2019-11-13 15:31:51,615 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:31:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:32:11,681 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:32:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:32:31,750 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:32:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:32:51,859 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:32:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:33:11,920 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:33:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:33:31,991 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:33:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:33:52,416 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:33:52] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:34:12,098 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:34:12] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:34:32,120 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:34:32] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:34:52,197 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:34:52] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:35:12,179 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:35:12] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:35:32,220 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:35:32] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:37:54,344 - octoprint.startup - INFO - ******************************************************************************
2019-11-13 15:37:54,347 - octoprint.startup - INFO - Starting OctoPrint 1.3.12
2019-11-13 15:37:54,349 - octoprint.startup - INFO - ******************************************************************************
2019-11-13 15:37:54,521 - octoprint.startup - INFO - We don't appear to be online, not fetching plugin blacklist
2019-11-13 15:37:54,608 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2019-11-13 15:37:58,531 - octoprint.plugin.core - INFO - Found 24 plugin(s) providing 24 mixin implementations, 40 hook handlers
2019-11-13 15:37:59,158 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2019-11-13 15:37:59,195 - octoprint.server - INFO - Intermediary server started
2019-11-13 15:37:59,196 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2019-11-13 15:37:59,991 - octoprint.plugin.core - INFO - Found 24 plugin(s) providing 24 mixin implementations, 40 hook handlers
2019-11-13 15:38:00,037 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2019-11-13 15:38:00,792 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2019-11-13 15:38:01,055 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2019-11-13 15:38:03,296 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-11-13 15:38:05,110 - octoprint.util.pip - INFO - Version of pip is 19.0.1
2019-11-13 15:38:05,112 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2019-11-13 15:38:05,114 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-11-13 15:38:05,131 - octoprint.plugin.core - INFO - Initialized 24 plugin implementation(s)
2019-11-13 15:38:05,165 - octoprint.plugin.core - INFO - 24 plugin(s) registered with the system:
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
|  DisplayLayerProgress Plugin (1.14.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_DisplayLayerProgress
|  Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
|  Floating Navbar (0.3.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_floatingnavbar
|  Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
|  Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
|  Navbar Temperature Plugin (0.11) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_navbartemp
|  OctoPrint Anywhere (1.0.20) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere
|  Octoslack (1.9.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_Octoslack
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
|  Printer Safety Check (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
|  Simple Emergency Stop (0.2.5) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_simpleemergencystop
|  Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
|  The Spaghetti Detective (1.0.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_thespaghettidetective
|  TouchUI (0.3.13) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_touchui
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
|  Webcam Tab (0.1.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_webcamtab
2019-11-13 15:38:05,187 - octoprint.environment - INFO - Detected environment is Python 2.7.13 under Linux (linux2). Details:
|  hardware:
|    cores: 4
|    freq: 1400.0
|    ram: 917008384
|  os:
|    id: linux
|    platform: linux2
|  plugins:
|    pi_support:
|      model: Raspberry Pi 3 Model B Plus Rev 1.3
|      octopi_version: 0.16.0
|  python:
|    pip: 19.0.1
|    version: 2.7.13
|    virtualenv: /home/pi/oprint
2019-11-13 15:38:05,200 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2019-11-13 15:38:05,222 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2019-11-13 15:38:06,451 - octoprint.server - INFO - Shutting down intermediary server...
2019-11-13 15:38:06,789 - octoprint.server - INFO - Intermediary server shut down
2019-11-13 15:38:06,793 - octoprint.events - INFO - Processing startup event, this is our first event
2019-11-13 15:38:06,793 - octoprint.events - INFO - Adding 0 events to queue that were held back before startup event
2019-11-13 15:38:06,817 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2019-11-13 15:38:06,870 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2019-11-13 15:38:06,886 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2019-11-13 15:38:06,890 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2019-11-13 15:38:06,905 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on octopi' for _http._tcp
2019-11-13 15:38:06,917 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on octopi' for _octoprint._tcp
2019-11-13 15:38:06,931 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on octopi for SSDP
2019-11-13 15:38:06,955 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2019-11-13 15:38:06,997 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-11-13 15:38:07,637 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2019-11-13 15:38:08,844 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-11-13 15:38:08,845 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python2.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2019-11-13 15:38:08,846 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-11-13 15:38:08,890 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online
2019-11-13 15:38:08,919 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-11-13 15:38:09,434 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2019-11-13 15:38:09,810 - py.warnings - WARNING - /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere/config.py:53: YAMLLoadWarning: calling yaml.load() without Loader=... is deprecated, as the default Loader is unsafe. Please read https://msg.pyyaml.org/load for full details.
  self.__items__ = yaml.load(config_str)

2019-11-13 15:38:09,904 - octoprint.plugins.navbartemp - INFO - Broadcom detected
2019-11-13 15:38:10,074 - octoprint.plugins.anywhere - WARNING - {u'mjpeg_stream_tier': 1, u'UserId': 36910, u'camResolution': u'medium', u'name': u'Craftbot 3', u'premium_video': True, u'flipV': True, u'octolapseOptedIn': True, u'recordTimelapse': True, u'rotate90N': False, u'token': u'T93HCQLETZN1NPZMBFFIL6KQYNPIOFWQ', u'lastSeen': u'2019-11-13T15:34:53.143Z', u'flipH': False, u'updatedAt': u'2019-11-13T15:34:53.143Z', u'deletedAt': None, u'rotate90': False, u'id': 47248, u'createdAt': u'2019-11-09T21:13:04.157Z', u'subscription': u'pro'}
2019-11-13 15:38:10,082 - octoprint.plugins.anywhere - WARNING - Printer is eligible for premium video streaming.
2019-11-13 15:38:10,654 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 13}
2019-11-13 15:38:11,623 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'python': '2.7.13', 'ram': 917008384, 'octopi_version': '0.16.0', 'version': u'1.3.12', 'pip': '19.0.1', 'cores': 4, 'freq': 1400.0, 'pi_model': 'Raspberry Pi 3 Model B Plus Rev 1.3', 'os': 'linux'}
2019-11-13 15:38:12,362 - werkzeug - INFO -  * Running on http://0.0.0.0:8080/ (Press CTRL+C to quit)
2019-11-13 15:38:12,452 - octoprint.plugins.anywhere - WARNING - Launching: /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_anywhere/bin/ffmpeg -re -i pipe:0 -y -an -vcodec copy -f hls -hls_time 2 -hls_list_size 10 -hls_delete_threshold 10 -hls_flags split_by_time+delete_segments+second_level_segment_index -strftime 1 -hls_segment_filename /tmp/octoprintanywhere-ts/%s-%%d.ts -hls_segment_type mpegts -
2019-11-13 15:38:12,482 - octoprint.plugins.tracking - INFO - Sent tracking event pong, payload: {'plugins': u'displaylayerprogress:1.14.2,webcamtab:0.1.2,octoslack:1.9.1,touchui:0.3.13,simpleemergencystop:0.2.5,thespaghettidetective:1.0.0,navbartemp:0.11,anywhere:1.0.20,floatingnavbar:0.3.1'}
2019-11-13 15:38:12,876 - backoff - INFO - Backing off wait_for_janus(...) for 0.5s (error: [Errno 111] Connection refused)
2019-11-13 15:38:14,382 - backoff - INFO - Backing off wait_for_janus(...) for 1.6s (error: [Errno 111] Connection refused)
2019-11-13 15:38:18,110 - backoff - INFO - Backing off start_gst(...) for 1.0s (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:38:29,032 - backoff - INFO - Backing off start_gst(...) for 0.1s (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:38:30,265 - backoff - INFO - Backing off start_gst(...) for 3.5s (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:38:30,401 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:38:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:38:34,828 - backoff - INFO - Backing off start_gst(...) for 3.5s (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:38:39,397 - backoff - INFO - Backing off start_gst(...) for 14.4s (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:38:50,456 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:38:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:38:54,825 - backoff - INFO - Backing off start_gst(...) for 31.6s (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:39:10,526 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:39:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:39:22,374 - octoprint.server.util.flask - INFO - Passively logging in user barrett from ::ffff:192.168.1.163
2019-11-13 15:39:27,533 - backoff - ERROR - Giving up start_gst(...) after 7 tries (Exception: GST failed. Exit code: 1
STDERR: None)
2019-11-13 15:39:30,930 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:39:30] "POST /shutdown HTTP/1.1" 404 -
2019-11-13 15:39:30,976 - octoprint_thespaghettidetective.utils - ERROR - Backing off 0.209622 seconds: Janus WS connection closed!
2019-11-13 15:39:31,189 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:39:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:39:31,196 - octoprint_thespaghettidetective.utils - ERROR - Backing off 0.493435 seconds: Janus WS connection closed!
2019-11-13 15:39:31,713 - octoprint_thespaghettidetective.utils - ERROR - Backing off 1.271539 seconds: Janus WS connection closed!
2019-11-13 15:39:32,017 - octoprint.plugins.thespaghettidetective - ERROR - GST failed. Exit code: 1
STDERR: None

2019-11-13 15:39:44,561 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.1.163
2019-11-13 15:39:44,784 - octoprint.server.util.flask - INFO - Passively logging in user barrett from ::ffff:192.168.1.163
2019-11-13 15:39:47,165 - octoprint.server.util.sockjs - INFO - User barrett logged in on the socket from client ::ffff:192.168.1.163
2019-11-13 15:39:50,587 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:39:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:40:10,664 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:40:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:40:30,934 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial port"
2019-11-13 15:40:31,009 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:40:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:40:31,580 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2019-11-13 15:40:31,933 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial port" to "Detecting baudrate"
2019-11-13 15:40:32,948 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 15:40:32,957 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting baudrate" to "Operational"
2019-11-13 15:40:32,986 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 15:40:33,392 - octoprint.util.comm - INFO - Printer reports firmware name "pr3Dator"
2019-11-13 15:40:34,068 - octoprint.plugins.tracking - INFO - Sent tracking event printer_connected, payload: {u'printer_baudrate': 0, u'printer_port': u'AUTO', 'firmware_name': 'pr3Dator'}
2019-11-13 15:40:50,762 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:40:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:41:10,781 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:41:10] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:41:30,859 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:41:30] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:41:50,932 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:41:50] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:42:11,032 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:42:11] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:42:31,022 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:42:31] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:42:51,064 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:42:51] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:42:54,163 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: flintvasea.gcode, owner: barrett, user: barrett
2019-11-13 15:42:54,171 - octoprint.plugins.DisplayLayerProgress - INFO - File selected. Determining number of layers.
2019-11-13 15:43:02,206 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2019-11-13 15:43:02,263 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: flintvasea.gcode, owner: barrett, user: barrett
2019-11-13 15:43:02,277 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-11-13 15:43:02,329 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-11-13 15:43:02,755 - octoprint.plugins.DisplayLayerProgress - INFO - Printing started. Detailed progress started.{'origin': 'local', 'name': u'flintvasea.gcode', 'file': u'/home/pi/.octoprint/uploads/flintvasea.gcode', 'owner': 'barrett', 'path': u'flintvasea.gcode', 'user': 'barrett', 'size': 2962393L, 'filename': u'flintvasea.gcode'}
2019-11-13 15:43:03,468 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': '2cbc52d6a4cca403c94bc14fe87d216e24c333bb'}
2019-11-13 15:43:03,772 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:03] "GET /?action=snapshot HTTP/1.1" 200 -
2019-11-13 15:43:11,092 - werkzeug - INFO - 127.0.0.1 - - [13/Nov/2019 15:43:11] "GET /?action=snapshot HTTP/1.1" 200 -

BarrettJ · November 13, 2019, 8:30pm

Full logs: https://www.dropbox.com/s/ei7vzpgfgib5cuv/Archive%202.zip?dl=0

BarrettJ · November 15, 2019, 7:44pm

So since I got the file to print via USB I didn't bother trying that print again via OctoPrint, but the issue did occur again several prints down the road. This time I just went and tripled every timeout (both busy and not busy communications and connection) from it's initial value. This has gotten me past the part that was failing on that print (which was consistent with the earlier failures).

So if someone comes across this thread in the future (probably me in several months) triple those three timeout settings and it seems to go through without a problem (and assumedly the only consequence would be that it'd take a few more seconds to recognize it lost connection were there to be another problem).

AtHeartEngineer · April 22, 2020, 4:34am

I was having very similar troubles but this didn't seem to fix it.

BarrettJ · March 2, 2021, 7:20pm

Did you ever find a fix for your issues? I had stopped using this printer for a while and clearly nothing I did before has fixed it.

b-morgan · March 2, 2021, 11:50pm

To troubleshoot this problem, a serial.log that captures the error is going to be crucial. The M106 command should be executed by the firmware in just a few milliseconds (and the first one in the attached full logs is):

2019-11-13 15:43:02,742 - Send: N3 M106 S0*100
2019-11-13 15:43:02,745 - Recv: ok S:0 H:255 L:0

There's only two in the log and the second one fails:

2019-11-13 15:44:35,393 - Send: N815 M106 S255*105
2019-11-13 15:45:05,364 - Communication timeout while printing, trying to trigger response from printer...

I'm guessing that when you say printing from a USB stick it is the Craftbot equivalent of an SD card. Are there two USB ports on the printer?

@AtHeartEngineer "very similar troubles" is not "exactly the same failure at exactly the same gcode command" so it would be best if you opened your own thread filling out the template with your details including the complete logs.

BarrettJ · March 3, 2021, 12:10am

Yes, one usb A that’s read like the SD card slot on other printers and one usb B for hooking up to a computer/octoprint.

The serial.log just sends the M106 with nothing out of the ordinary and gets no response before showing the timeout message.

After more testing I think what might be occurring is that this printer buffers print commands (in a way none of my other printers do).

When the fan is supposed to kick on is a layer change, but when the printer tells me it’s timed out (in theory a fair bit after it has sent the fan command) I can still walk down the stairs to the basement and watch it finish the first layer before it kicks on the fan and then just sits there.

I added M106 to the long running commands and then I changed the long running command number of retries to like 20 (it was at 5) - this allowed a file that was failing before to continue fine.

b-morgan · March 3, 2021, 1:58am

Start OctoPrint, connect to your printer, and from the Terminal type M106 S0, M106 S127, M106 S255, and M107. All four commands should respond with an ok within milliseconds (you will have to look in the serial.log for the timestamps). M106 should not need to be a long running command.

BarrettJ · March 3, 2021, 2:15am

The commands respond instantly when not in a print (I had already tried this to see if it was an issue with the fan or the firmware not responding).

I very strongly think it is the printer buffering up commands and then the timeout occurs for the fan command before the printer finishes printing the commands it has buffered. If I cancel a print via octoprint it definitely doesn’t a noticeable amount more printing before cancelling stopping than my other printers (while actually printing, they all take forever if cancelled during warm up, and yes I know there’s a plug-in that could fix that)

b-morgan · March 3, 2021, 3:04am

Does the printer respond to an M155? Try M155 S2 and M155 S0. Change the OctoPrint Settings, Serial Connection, Intervals & timeouts, Temperature Interval (polling) from 5 seconds to at least 10, maybe 20 seconds and the Temperature Interval (autoreport) to 0 if the M155 command didn't work and 10 or 20 if it did work.

Does CraftBot have any documentation on their firmware? In particular, any GCode commands they have added. In the serial.log I see responses like ok Q:256 and eventually ok Q:1 and for a while, just ok. Then the ok Q:n comes back. I'm guessing that the command queue is 256 deep and the Q:n is how many free slots are left.

The temperature reporting changes should reduce the number of M105 commands that are sent. Don't know if that will change the symptoms any but it can't hurt to try.

I'm wondering if there is a CraftBot specific gcode command to vary the size of the command queue. If so, it would be interesting to make it smaller and see what happens.

BarrettJ · March 3, 2021, 3:42am

In the middle of a print (my tweaks to the long running commands has allowed me to print without issue for most of the day now) so I can't try the M155 yet, but I wanted to respond on the other points.

I can find next to no documentation or other people experiencing this issue. I did find List of M- and G commands as used by the CraftBot and expert specs. | Craftbot.nl which mentions

M1115 : Get queue. gives back the coordinates last entered into the queue of movements, that is the last GCODE line processed, but not necessarily executed yet.

But nothing about managing or changing it.

Seems others aren't please with the lack of documentation: Craftunique | multi - award winner 3D Printer’s manufacturer

b-morgan · March 3, 2021, 4:25am

Have you seen this: https://support.craftbot.com/hc/en-us/articles/360018198658-Setting-up-OctoPi-OctoPrint-for-Craftbot-Plus-Pro-2-XL-3?

I'm intrigued by the M1116 1; Set queue 1

foosel · March 3, 2021, 12:52pm

For the record, the only commands that should be buffered by firmware are G0, G1, G2, G3 and the like, so anything movement associated. Buffered commands should return an ok once the command could be moved into the planner buffer. All other commands should return an ok once the command has been executed. What we seem to have here is a firmware that decided to not give a crap about this approach and instead throws commands (that shouldn't even be buffered in the first place) into an internal buffer that is apparently really big, but still only acknowledges those once they have been executed. Or the firmware is waiting for the planner buffer to process fully before it executes unbuffered commands. Either way, it's firmware behaviour that is incompatible to Everything Else(TM) and I frankly don't know how this can be worked around other than with ridiculously huge timeouts and some praying to the printer gods.

Don't you just love it when printer vendors mess with stuff they apparently don't understand, and break things for users in the process?

ETA: see also reprap.org/wiki/G-code#Buffering

BarrettJ · March 3, 2021, 2:21pm

No - I hadn't seen that before - thanks! Edit: if I'm reading their site correctly, that page was created yesterday (none of the other pages have yesterday as the day they were created so it doesn't seem to be a "default display date" either)

Unfortunately I don't think it worked:

Send: M1116 1
Recv: ok ?: Unsupported command: M1116
Recv: ok ?:Line: 155701/7 Syntax error, char: '1' (0x31) :

BarrettJ · March 3, 2021, 2:29pm

Yeah, I've always assumed it was something weird with the printer and it's firmware (it was my first 3d Printer but I've since gotten several Enders and Prusas, and I'm just now getting enough time where I can really play around with it as it was always more temperamental than I expected/the other machines).

The buffer seems pretty large - when printing a 50mm square I'd say a good half of the first layer is in the buffer.

I was mostly hoping this was something someone else had encountered before and knew the settings to tweak.

For future finders of this thread, what's been working so far (fingers crossed) is adding M106 to the long running commands and increasing the retries for long running commands.