There appears to have been a similar issue with the Prussa Firmware on the MK series of printers. I found this at GetHub- https://github.com/foosel/OctoPrint/issues/2285
Reading this, I'm convinced it's not power. The only difference between that issue and my issue is I don't see timeout statements in my log.
So i decided to download the code for the Unified Firmware and do a search for the error message in the code. This is deftly an error getting generated by the Unified firmware that the Ender 3 is running.
Here is a screenshot of the code I believe is generating the error randomly and returning it Octoprint:
It is deftly not a power issue, because this issue only happens when I print and very randomly. A print appears to work fine for an hour, then you walk away, and then you're greeted with a mess of filament when you return an hour later to check on things. This has also happened at the beginning of a print as well. Sometimes it wont happen until several hours later.
if we take a look at this:
| Last lines in terminal:
| Recv: ok
| Send: N2369 G0 F6000 X99.449 Y146.44573
| Recv: ok
| Send: N2370 G0 X100.992 Y147.42227
| Recv: ok
| Send: N2371 G0 X101.228 Y147.04924
| Recv: ok
| Send: N2372 G1 F900 X87.804 Y133.624 E2521.8396613
| Recv: ok
| Send: N2373 G0 F6000 X87.42 Y133.838118
| Recv: ok
| Send: N2374 G0 X86.687 Y132.50242
| Recv: ok
| Send: N2375 G0 X87.099 Y132.35438
| Recv: ok
| Send: N2376 M10523
| Recv: ok T:240.00 /240.00 B:79.99 /80.00 @:80 B@:127
| Send: N2377 G1 F900 X102.736 Y147.991 E2522.5384*3
| Recv: Error:checksum mismatch, Last Line: 2376
Octoprint receives and gets acknowledgements for lines N2369 to N2376. Then receives an error Error:checksum mismatch, Last Line: 2376 and asks for octoprint to resend 2377.
Things appear to go smoothly for a little from there and the issue reoccurs at line 4299. In the octoprint.log it sends New Line commands for Lines 4292 to 4299.. Octorpint then recieves Recv: Error:checksum mismatch, Last Line: 4299 but asks for Line 4300 to be resent instead.
If there is a checksum mismatch on the previously stated line, but is TH3Ds firmware asking for the next line to be sent?
@foosel do you have any thoughts on this? Is there anyone I can tag from TH3D to get their attention/input on this?
A checksum mismatch means something went wrong during communication. As in, some bits got jumbled and so what OctoPrint sent out isn't what arrived at the printer. This isn't a firmware bug (most likely, the code looks like regular checksum calculation code to me), but rather something in your setup is still causing communication issues on the serial line.
See this FAQ entry on the topic:
I can't tell you anything new here that is not already in that.
A charger is a charger and a power adapter is a power adapter. They're not the same thing. If you looked at the output of the power adapter it would be a horizontal line as seen on an oscilloscope. If you looked at the output of a charger again you'd see a rippling signal above 0V somewhere. It would waver above/below the 5V mark. Although this works to charge a battery, it's not what you want for powering electronic devices.
tomato, tomoto. Charger, power supply. Used incorrect lingo. Any way, I verified the PS with a multimeter. Its good. I requested Amazon to send me a new Raspberry Pi so they did. I was going to reformat the SD card and reinstall Octoprint all together. Upon Flashing, Etcher said it failed to verify the disk.
I went ahead and tried flashing with Win32 as well and it failed to verify as well. Appears this maybe a disk issue. I requested Amazon to send a new one, but it'll take a couple of days for it to arrive. I'll keep you in the loop once I can get it back up and running.
So I think I'm good to go now. I'll send some longer print jobs through Octoprint this weekend to confirm. Last night, I setup octoprint again from scratch. A few things to note on:
This does not appear to have been a hard disk issue, rather an issue with Etcher. When I originally flashed the SD with Etcher, I walked away and closed out the window so quick when I returned that it apparently unmounted the disk and I failed to realized the error on the screen of it displaying " 1 failed device" (Flash Successful to 100%. Verification Failed at 100%).
There is a lot of issues right now with newer versions of Etcher and Windows 10 x64. If you Google the error, you'll find a lot out there:
To get around this error, I went out to GitHub and downloaded and tried several versions of Etcher. I believe I finally ended up at 1.5.11 before it successfully flashed and verified correctly with no issues.
Amazon did send me the new pi as well and I did use it instead of the other - but there is no real evidence that hardware is the cause. I used OctoPrint to print my Bed level test and did not come up with 1 single error this time ((VERY POSITIVE SIGN)). This was a 50 min print job.
Here is the log output for this job:
2019-12-06 04:30:44,527 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: CE3_bed_level_test.gcode, owner: USER, user: USER
2019-12-06 04:30:47,914 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2019-12-06 04:30:47,925 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: CE3_bed_level_test.gcode, owner: USER, user: USER
2019-12-06 04:30:47,942 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-12-06 04:30:47,988 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-12-06 04:30:48,674 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': '09d2f6d2cf473483c7d4e56a6818360f93a13d38'}
2019-12-06 04:36:42,841 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2019-12-06 04:37:11,570 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2019-12-06 04:38:50,178 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:38:50,293 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:38:50,736 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:38:50,837 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:38:51,776 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 04:40:34,984 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:40:35,132 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:40:35,432 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:40:35,511 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:40:36,826 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 04:45:23,767 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 04:45:30,624 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 26097}
2019-12-06 04:46:27,279 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:48:32,413 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:48:32,538 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:48:32,579 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 04:48:38,376 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:48:38,551 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:48:39,101 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:48:39,185 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:48:40,470 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 04:49:50,385 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:49:50,455 - tornado.access - WARNING - 404 GET /favicon.ico (::ffff:X.X.X.X82) 20.49ms
2019-12-06 04:50:53,238 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:50:53,332 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:50:54,493 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 04:57:38,554 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:57:38,714 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:57:39,071 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:57:39,162 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:57:40,563 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 04:58:24,443 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 04:59:00,542 - tornado.access - WARNING - 404 GET /msdn.cpp (::ffff:176.58.124.134) 10.90ms
2019-12-06 04:59:27,567 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 04:59:27,691 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 04:59:28,843 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:00:03,825 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Cancelling"
2019-12-06 05:00:03,836 - octoprint.util.comm - INFO - Force-sending M108 to the printer
2019-12-06 05:00:03,856 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: local, path: CE3_bed_level_test.gcode, owner: USER, user: USER
2019-12-06 05:00:04,588 - octoprint.plugins.tracking - INFO - Sent tracking event print_cancelled, payload: {'origin': 'local', 'file': '09d2f6d2cf473483c7d4e56a6818360f93a13d38', 'elapsed': 1755}
2019-12-06 05:00:05,295 - octoprint.plugins.tracking - INFO - Sent tracking event print_failed, payload: {'origin': 'local', 'reason': 'cancelled', 'file': '09d2f6d2cf473483c7d4e56a6818360f93a13d38', 'elapsed': 1755}
2019-12-06 05:00:12,078 - octoprint.util.comm - INFO - Changing monitoring state from "Cancelling" to "Operational"
2019-12-06 05:00:23,769 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 05:00:30,628 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 26997}
2019-12-06 05:01:35,244 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:02:48,950 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:02:49,043 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:02:49,083 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:04:06,309 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2019-12-06 05:04:06,321 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: CE3_bed_level_test.gcode, owner: USER, user: USER
2019-12-06 05:04:06,343 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-12-06 05:04:06,384 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-12-06 05:04:07,027 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': '09d2f6d2cf473483c7d4e56a6818360f93a13d38'}
2019-12-06 05:04:18,818 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:05:34,653 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:05:34,783 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:05:34,988 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:05:46,899 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:05:48,046 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:05:48,189 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:05:48,266 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:05:48,342 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:05:49,062 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:05:49,225 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:05:51,415 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:05:52,857 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:05:52,917 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:06:12,188 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:06:13,058 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:06:13,355 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:06:13,424 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:06:14,672 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:07:37,372 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:08:00,898 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:08:01,033 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:08:01,076 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:08:07,978 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:08:08,182 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:08:08,629 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:08:08,701 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:08:09,967 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:15:23,771 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 05:15:30,626 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 27897}
2019-12-06 05:17:53,511 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:18:49,266 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:18:49,382 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:18:50,693 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:21:42,612 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:21:42,788 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:21:43,314 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:21:43,402 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:21:44,806 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:22:24,825 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:30:01,294 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:30:01,444 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:30:01,483 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:30:06,060 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:30:06,219 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:30:06,801 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:30:06,879 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:30:08,116 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:30:23,772 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 05:30:30,649 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 28797}
2019-12-06 05:33:53,920 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:45:23,775 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 05:45:30,667 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 29697}
2019-12-06 05:52:00,010 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:52:00,129 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:52:00,171 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:53:15,804 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:53:15,950 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.X82
2019-12-06 05:53:16,438 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.X82
2019-12-06 05:53:16,509 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.X82
2019-12-06 05:53:17,926 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.X82
2019-12-06 05:53:58,339 - octoprint.util.comm - INFO - Finished in 2992.030 s.
2019-12-06 05:53:58,341 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
Both macOS and Windows suffer since they purposely decided not to provide support for the ext4 partition type. So after flashing a Raspbian IMG, for example, Windows (and sometimes macOS) will panic and flag an error, requesting that you "fix" the problem. If you do, then it's now a corrupt installation and you have to start over.
To make matters worse, your browser will try to "help" by trying to unzip the ZIP file and will make problems for the resulting IMG file. I wrote up a step-by-step guide to minimize all these Windows-related issues but it's admittedly odd since no other guide matches it. It will however result in a perfect flashing if you follow the instructions since it removes all the points which earlier could have caused problems.
On a two hour print job... THe errors continue, but this time with a timeout..
2019-12-06 17:39:51,886 - octoprint.util.comm - INFO - Ignoring resend request for line 6825 == current line, we haven't sent that yet so the printer got N-1 twice from us, probably due to a timeout
2019-12-06 17:46:26,444 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 17:46:37,778 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 35111}
2019-12-06 18:00:54,100 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 19078, current line = 19079
| Last lines in terminal:
| Recv: ok
| Send: N19070 G1 X116.521 Y128.016 E3603.1348*105
| Recv: ok
| Send: N19071 G1 X116.829 Y127.684 E3603.14911*93
| Recv: ok
| Send: N19072 G1 X117.116 Y127.328 E3603.16356*82
| Recv: ok
| Send: N19073 G1 X117.373 Y126.957 E3603.17782*93
| Recv: ok
| Send: N19074 G1 X117.612 Y126.557 E3603.19254*84
| Recv: ok
| Send: N19075 G1 X117.785 Y126.209 E3603.20482*81
| Recv: ok
| Send: N19076 G1 X117.988 Y125.73 E3603.22126*100
| Recv: ok
| Send: N19077 G1 X118.133 Y125.291 E3603.23587*82
| Recv: ok
| Send: N19078 G1 X118.244 Y124.862 E3603.24987*82
| Recv: Error:checksum mismatch, Last Line: 19077
| Recv: Resend: 19078
2019-12-06 18:01:26,448 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 18:01:37,803 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 36011}
2019-12-06 18:05:24,647 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 21459, current line = 21460
| Last lines in terminal:
| Recv: ok
| Recv: ok T:239.94 /240.00 B:79.97 /80.00 @:79 B@:127
| Send: N21451 G1 F1350 X132.349 Y106.935 E3735.83315*56
| Send: N21452 G0 F9000 X132.349 Y107.501*75
| Recv: ok
| Send: N21453 G1 F1350 X123.957 Y115.892 E3736.20812*55
| Recv: ok
| Send: N21454 G0 F9000 X124.265 Y116.15*117
| Recv: ok
| Send: N21455 G1 F1350 X132.349 Y108.067 E3736.56933*57
| Recv: ok
| Send: N21456 G0 F9000 X132.349 Y108.632*67
| Recv: ok
| Send: N21457 G1 F1350 X124.573 Y116.408 E3736.9168*13
| Recv: ok
| Send: N21458 G0 F9000 X124.88 Y116.666*122
| Recv: ok
| Send: N21459 G1 F1350 X132.349 Y109.198 E3737.25053*63
| Recv: Error:checksum mismatch, Last Line: 21458
| Recv: Resend: 21459
2019-12-06 18:16:26,449 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-12-06 18:16:37,838 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 36911}
2019-12-06 18:21:05,403 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 37692, current line = 37693
| Last lines in terminal:
| Recv: ok
| Send: N37685 G0 X139.043 Y127.878*40
| Recv: ok
| Send: N37686 G0 X139.914 Y121.565*39
| Recv: ok
| Send: N37687 G0 X139.914 Y120.486*43
| Recv: echo:busy: processing
| Recv: ok
| Send: N37688 G0 X140.1 Y120.3*46
| Recv: ok
| Send: N37689 G1 F1500 E4098.40596*57
| Recv: ok
| Send: N37690 G1 F1350 X140.1 Y119.5 E4098.43124*53
| Recv: echo:busy: processing
| Recv: ok
| Send: N37691 G1 X140.9 Y119.5 E4098.45652*93
| Recv: ok
| Send: N37692 G1 X140.9 Y120.3 E4098.4818*103
| Recv: Error:checksum mismatch, Last Line: 37691
| Recv: Resend: 37692
2019-12-06 18:28:26,018 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Cancelling"
2019-12-06 18:28:26,023 - octoprint.util.comm - INFO - Force-sending M108 to the printer
2019-12-06 18:28:26,043 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: local, path: CE3_AIl_In_One_3D_printer_test_micro.gcode, owner: USER, user: USER
2019-12-06 18:28:26,750 - octoprint.plugins.tracking - INFO - Sent tracking event print_cancelled, payload: {'origin': 'local', 'file': '0ee62de76eef3fb7b2ed9dc7ea7939e897ceb4e7', 'elapsed': 7337}
2019-12-06 18:28:27,443 - octoprint.plugins.tracking - INFO - Sent tracking event print_failed, payload: {'origin': 'local', 'reason': 'cancelled', 'file': '0ee62de76eef3fb7b2ed9dc7ea7939e897ceb4e7', 'elapsed': 7337}
2019-12-06 18:28:29,246 - octoprint.util.comm - INFO - Changing monitoring state from "Cancelling" to "Operational"
2019-12-06 18:28:51,010 - octoprint.server.api.system - INFO - Performing command for core:restart_safe: sudo service octoprint restart
2019-12-06 18:28:51,420 - octoprint.server - INFO - Shutting down...
2019-12-06 18:28:51,852 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2019-12-06 18:28:51,858 - octoprint.events - INFO - Event loop shut down
2019-12-06 18:28:51,885 - octoprint.plugins.HeaterTimeout - INFO - Shutting down...
2019-12-06 18:28:51,898 - octoprint.server - INFO - Goodbye!
2019-12-06 18:28:54,642 - octoprint.startup - INFO - ******************************************************************************
2019-12-06 18:28:54,644 - octoprint.startup - INFO - Starting OctoPrint 1.3.12
2019-12-06 18:28:54,645 - octoprint.startup - INFO - Starting in SAFE MODE. Third party plugins will be disabled!
2019-12-06 18:28:54,646 - octoprint.startup - INFO - Reason for safe mode: setting in config.yaml
2019-12-06 18:28:54,647 - octoprint.startup - INFO - ******************************************************************************
2019-12-06 18:28:55,239 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online
2019-12-06 18:28:55,943 - octoprint.startup - INFO - Blacklist processing done, adding 1 blacklisted plugin versions: roomtemp (any)
2019-12-06 18:28:56,041 - 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-12-06 18:28:57,377 - octoprint.plugin.core - INFO - Found 19 plugin(s) providing 15 mixin implementations, 23 hook handlers
2019-12-06 18:28:57,644 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2019-12-06 18:28:57,667 - octoprint.server - INFO - Intermediary server started
2019-12-06 18:28:57,668 - 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-12-06 18:28:57,800 - octoprint.plugin.core - INFO - Found 19 plugin(s) providing 15 mixin implementations, 23 hook handlers
2019-12-06 18:28:57,836 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2019-12-06 18:28:58,400 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2019-12-06 18:28:58,511 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2019-12-06 18:28:59,644 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-12-06 18:29:00,737 - octoprint.util.pip - INFO - Version of pip is 19.3.1
2019-12-06 18:29:00,739 - 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-12-06 18:29:00,740 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-12-06 18:29:00,746 - octoprint.plugin.core - INFO - Initialized 15 plugin implementation(s)
2019-12-06 18:29:00,779 - octoprint.plugin.core - INFO - 19 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
| !Bed Visualizer (0.1.11) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_bedlevelvisualizer
| !BLTouch Plugin (0.3.3) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_BLTouch
| 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
| Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
| Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
| !HeaterTimeout (0.0.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_HeaterTimeout
| Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
| 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
| !Resource Monitor (0.1.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_resource_monitor
| Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
| Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
2019-12-06 18:29:00,795 - octoprint.environment - INFO - Detected environment is Python 2.7.16 under Linux (linux2). Details:
| hardware:
| cores: 4
| freq: 1200.0
| ram: 917016576
| os:
| id: linux
| platform: linux2
| plugins:
| pi_support:
| model: Raspberry Pi 3 Model B Rev 1.2
| octopi_version: 0.17.0
| python:
| pip: 19.3.1
| version: 2.7.16
| virtualenv: /home/pi/oprint
2019-12-06 18:29:00,807 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2019-12-06 18:29:00,828 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2019-12-06 18:29:01,622 - octoprint.server - INFO - Shutting down intermediary server...
2019-12-06 18:29:02,102 - octoprint.server - INFO - Intermediary server shut down
2019-12-06 18:29:02,105 - octoprint.events - INFO - Processing startup event, this is our first event
2019-12-06 18:29:02,106 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2019-12-06 18:29:02,110 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2019-12-06 18:29:02,145 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2019-12-06 18:29:02,176 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-12-06 18:29:02,656 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial port"
2019-12-06 18:29:02,662 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2019-12-06 18:29:02,666 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2019-12-06 18:29:02,689 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2019-12-06 18:29:02,690 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance "Greg's OctoPrint"' for _http._tcp
2019-12-06 18:29:02,693 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial port" to "Detecting baudrate"
2019-12-06 18:29:02,707 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance "Greg's OctoPrint"' for _octoprint._tcp
2019-12-06 18:29:02,713 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance "Greg's OctoPrint" for SSDP
2019-12-06 18:29:02,785 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2019-12-06 18:29:02,787 - octoprint.server - INFO - Server started successfully in safe mode as requested from config, removing flag
2019-12-06 18:29:02,999 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2019-12-06 18:29:03,354 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2019-12-06 18:29:03,507 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 1.1s
2019-12-06 18:29:03,711 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-12-06 18:29:03,799 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 0.83s
2019-12-06 18:29:04,067 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting baudrate" to "Operational"
2019-12-06 18:29:04,081 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-12-06 18:29:04,198 - octoprint.plugins.pluginmanager - INFO - Loaded plugin notices data from https://plugins.octoprint.org/notices.json
2019-12-06 18:29:04,213 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python2 -m pip" as command to invoke pip
2019-12-06 18:29:04,215 - 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-12-06 18:29:04,216 - octoprint.util.pip - INFO - ==> pip ok -> yes
2019-12-06 18:29:04,499 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.71s
2019-12-06 18:29:04,635 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http://X.X.X.93/'}
2019-12-06 18:29:04,804 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.74s
2019-12-06 18:29:04,815 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.72
2019-12-06 18:29:04,993 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 7}
2019-12-06 18:29:05,824 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.72
2019-12-06 18:29:06,021 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin TH3D U1.R2.18"
2019-12-06 18:29:06,333 - octoprint.plugins.tracking - INFO - Sent tracking event pong, payload: {'plugins': u''}
2019-12-06 18:29:06,494 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.72
2019-12-06 18:29:06,855 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.66s
2019-12-06 18:29:07,018 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.9s
2019-12-06 18:29:07,101 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'python': '2.7.16', 'ram': 917016576, 'octopi_version': '0.17.0', 'version': u'1.3.12', 'pip': '19.3.1', 'cores': 4, 'freq': 1200.0, 'pi_model': 'Raspberry Pi 3 Model B Rev 1.2', 'os': 'linux'}
2019-12-06 18:29:07,834 - octoprint.plugins.tracking - INFO - Sent tracking event printer_connected, payload: {u'printer_baudrate': 0, u'printer_port': 'AUTO', 'firmware_name': 'Marlin TH3D U1.R2.18'}
2019-12-06 18:29:07,838 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.89s
2019-12-06 18:29:07,964 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.87s
2019-12-06 18:29:08,981 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 1.0s
2019-12-06 18:29:08,982 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.91s
2019-12-06 18:29:18,041 - octoprint.server.preemptive_cache - INFO - ... done in 13.41s
2019-12-06 18:29:18,043 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'https://dbzpr.ddns.net/'}
2019-12-06 18:29:22,876 - octoprint.server.preemptive_cache - INFO - ... done in 4.83s
2019-12-06 18:29:22,877 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'query_string': 'l10n=en', 'path': '/', 'base_url': 'http://X.X.X.96/'}
2019-12-06 18:29:27,867 - octoprint.server.preemptive_cache - INFO - ... done in 4.99s
2019-12-06 18:31:11,650 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.72
2019-12-06 18:31:11,837 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:X.X.X.72
2019-12-06 18:31:13,365 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:X.X.X.72
2019-12-06 18:31:13,486 - octoprint.server.util.flask - INFO - Passively logging in user USER from ::ffff:X.X.X.72
2019-12-06 18:31:14,970 - octoprint.server.util.sockjs - INFO - User USER logged in on the socket from client ::ffff:X.X.X.72
2019-12-06 18:31:26,457 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Offline"
I found an article on redit whre it talks about USB buffer sizes and the rate octoprint likes to send GCODE commands at. URL is https://www.reddit.com/r/ender3/comments/ase533/octoprint_quality_issues/
@foosel @OutsourcedGuru do you think this is the issue I am running into with Octoprint? The reporters issue seems to describe exactly what is going on with me.
Is there a way to slow Octoprint down for testing? I have realized that it I can complete smaller print jobs with no problem, but the longer ones is where I am having issues.
Marlin's receive buffer would be one of the primary culprits for blobbing/stuttering during printing. It doesn't sound like you're experiencing that, though.
I'm going to guess that foosel will ask you 1) to turn on serial logging, 2) repeat your test and 3) supply that log.
Printing the 3D micro test print from Octoprint rendered this tonight....
I'm printing from SD now and keeping that for comparison.
Is this by any chance GEEETECH orange?
esun PETG semi transparent orange.
I looks like the GEEETECH orange I once ordered. But it was supposed to be non transparent.
You might indicate the temperature that you're trying to use for the PETG. I see some evidence of adhesion problem on the raft on the left.
So does the hotend stall in place for a second or so during the print? If so, then chase the receive buffer we talked about. If not then it's probably worthwhile trying to get the temperature dialed in. If it were me, I'd try PLA.
@OutsourcedGuru thats the way that print came out when Octoprint prints it. If I run the same gcode from the SD card then it prints just fine. Just a little bit of stringing - which PETG is notorious for. My initial printing temp in Cura is set to 230 and printing temp is 240. I print with a raft for adhesion.
When printing PETG I like to use the coasting setting in cura 
Not bad Octoprint... ! This was a 1 hr 10 min print job with PETG. No errors in log either.
I decided to Order the Creality v1.1.5 silent board. Switched code from TH3Ds unified firmware to Marlin2.0-bugfix. Works great with my BLTouchV3.1.
I also increased the buffers and changed the baudrate to 250000 based on a post I read from someone else on RedIt who had a similar issue as me.
Now it's time to reprint the 3D micro test. Fingers Crossed......
Hi, it's been a month. Have you noticed any change or improvement?
