New update 1.2.14 creates connection problems

[atc1441]

I updated the new version of octoprint today.

every time i try to start a print the connect gets lost. if i go back to the last version 1.2.10 everything works fine.

it is a delta printer and the printer don't get any Gcode after i start the print.

[GitIssueBot]

Hi @atc1441,

It looks like there is some information missing from your bug report that will be needed in order to solve the problem. Please take a look at the Contribution Guidelines which will provide you with a template to fill out here so that your bug report is ready to be investigated (I promise I'll go away then too!).

If you did not intend to report a bug, please take special note of the title format to use as described in the Contribution Guidelines.

I'm marking this one now as needing some more information. Please understand that if you do not provide that information within the next two weeks (until 2016-08-11 18:50) I'll close this ticket so it doesn't clutter the bug tracker. This is nothing personal, so please just be considerate and help the maintainers solve this problem quickly by following the guidelines linked above. Remember, the less time the devs have to spend running after information on tickets, the more time they have to actually solve problems and add awesome new features. Thank you!

Best regards,
~ Your friendly GitIssueBot

PS: I'm just an automated script, not a human being, so don't expect any replies from me :) Your ticket is read by humans too, I'm just not one of them.

[foosel]

Fill out the full ticket template please, as linked by the bot. There's simply no way to analyse this without the information requested therein.

[jdcasey]

I'm not sure if this is the same issue the original reporter is running into, but I just updated to the latest OctoPrint. I had been running whatever version the updater recommended last time (I didn't check before updating, much to my chagrin), and ran a successful print not more than half an hour ago. After updating and trying a LOT of variations of rebooting the system, restarting the Arduino, rebooting everything, I'm stuck.

What were you doing?

I uploaded/sliced a STL file, and tried to print directly from the upload-and-slice dialog. That timed out, so I rebooted the system and tried to open the gcode file and start printing. Things were unresponsive so I wound up completely rebooting and reloading the web UI with the key combination that I believe will discard cached javascript. Things were better, but the error happened when I tried to print again.

What did you expect to happen?

I expected it to warm up and start printing just like it used to

What happened instead?

It started warming up and then the graph hung and it never started printing. The terminal showed error messages.

Branch & Commit or Version of OctoPrint

Version: 1.2.14 (master branch)

Printer model & used firmware incl. version

RepRap Prusa i3 / Marlin firmware (not sure of the version, but I think it's in the terminal log)

Browser and Version of Browser, Operating System running Browser

Firefox 47.0 on OS X El Capitain

Link to contents of terminal tab or serial.log

Terminal: https://gist.github.com/jdcasey/87893f396db2735fc0bde017d4b59bef

I deleted the log file to figure out if the stacktrace I saw would come back. I think it was old, related to the timeout seen in the terminal, but I can probably go trigger the problem again and include it.

[jdcasey]

BTW, here's the gcode (attached)
coin-cell-holder-24.5mm.gcode.txt

[atc1441]

Seems like the same issue

mine acted the same

i don't have any log because i reinstalled the old version.

[KevMags]

Same here. Heats bed then stalls, eventually times out. Too bad that I updated 3 Pis before doing a test print.

[jdcasey]

@foosel Hopefully my error report above is enough to remove the "incomplete ticket" label?

[foosel]

Your firmware is sending heaps of garbage. Or at the very least OctoPrint is receiving heaps of garbage. If suggest to roll back to 1.2.13 to see if that fixes it. That would get I'd another data point. On first glance this does look some serious noise on the line though.

Instructions for a roll back on OctoPi:

cd ~/OctoPrint
source ~/oprint/bin/activate
git reset --hard 1.2.13
python setup.py clean
python setup.py install
sudo service octoprint restart

To find out your former version, look into octoprint.log - the full version number gets logged on every start up of the server there (another reason why everyone should always provide a fully filled out ticket template, even when just posting a "me too" ;))

For the record, I've been printing one test print after the other over the past week with what is now 1.2.14. So whatever it is (if it is the update), it is something that depends on the environment as well. Exact firmware, settings etc could all be a factor here. Please provide more data :)

[foosel]

OK guys, I need more data points here from all of you. What firmwares are these, how's the printer connected (usb or direct connection). And terminal output and octoprint.log from everyone please.

@jdcasey usually it is the original poster who's supposed to provide that, but yes

[foosel]

Oh, and also the electronics used please. There must be some common factor here.

[jdcasey]

After rolling back to 1.2.13, here's my terminal as I start that print I was trying: https://gist.github.com/jdcasey/80cdde193537244d6e4327f13f778359

Oh, and I realized I still have the old octoprint.log from 1.2.14 in my download cache:
octoprint.log.txt

The octoprint log from after the rollback:
octoprint.1.2.13.log.txt

As far as firmware, I'm not sure how to get at that information (I'm still learning the ropes here), but in the terminal log I reported above, it had:

FIRMWARE_NAME:Marlin V1; Sprinter/grbl mashup for gen6 FIRMWARE_URL:http://www.mendel-parts.com PROTOCOL_VERSION:1.0 MACHINE_TYPE:REPRAPGURU EXTRUDER_COUNT:1

I am using a USB connection from a RPi3B+ to an Arduino Mega. The RPi is using the OctoPi image, but was previously updated to a newer version of Octoprint after flashing the image IIRC.

I'm not sure what other electronics you're interested in... /me watches other comments...I'm running RAMPS 1.4 as well.

[KevMags]

Ramps 1.4 running Marlin RC7. Direct serial connection to Pi3.

Version 1.2.14 (master branch)

serial.log.TXT

octoprint.log.txt

[foosel]

@KevMags can you also provide a serial.log with an active print? I only see a connect and subsequent temperature queries in the one you posted :/

@jdcasey hm, nothing unusual in there that immediately jumps to my eye... I was talking about the printer electronics. RAMPS, Rumba, whatever it is that hosts your stepper drivers and is on the other end of the cable you plugged into the Pi.

[KevMags]

Rolled back to 1.2.13, worked fine. Updated again. Erased all logs. Connected. Clicked icon "load and print". Unhandled Com error. Reconnected, clicked on "load file" icon. Clicked on "print" button.
Unhandled Com error, bed still maintaining 60C.

Reconnected, restarted OctoPrint to write log files.

serial.log.txt
octoprint.log.txt

[foosel]

@KevMags What's written to the Terminal tab when that "Unhandled Com Error" happens?

[foosel]

FYI, I've put further roll-outs of 1.2.14 on hold until we've gotten to the bottom of this.

What needs to be figured out now is a) if all of you really are seeing identical issues and b) what is causing this issue/these issues so that c) I can reproduce them (I can't at all right now) and fix it/them.

[foosel]

Copied over from #1426:

So here is a clip from the terminal after I preheat the heated bed, and extruder myself.

ecv: T:200.13 E:0 B:69.8
Recv: T:200.00 E:0 B:69.9
Recv: T:200.04 E:0 B:69.8
Recv: T:199.93 E:0 B:69.8
Recv: T:200.00 E:0 B:69.8
Recv: T:199.93 E:0 B:69.9
Recv: ok
Send: N6 M104 S200 T0*37
Recv: echo:Unknown command: ""
Recv: ok
Send: N7 M109 S200 T0*41
Recv: Error:Line�st Line Number+1, Last Line: 5
Recv: Resend: 6
Recv: ok
Send: N6 M104 S200 T0*37
Recv: echo:Unknown command: ""
Recv: ok
Send: N7 M109 S200 T0*41
Recv: Err�  ����Last Line Number+1, Last Line: 5
Recv: Resend: 6
Recv: ok
Send: N6 M104 S200 T0*37
Recv: echo:Unknown command: ""
Recv: ok
Send: N7 M109 S200 T0*41
ommunication timeout during an active resend, resending same line again to trigger response from printer. Configure long running commands or increase communication > timeout if that happens regularly on specific commands or long moves.
Send: N7 M109 S200 T0*41
Recv: Error:Line Num��r������1, Last Line: 5
See octoprint.log for details
Changing monitoring state from 'Printing' to 'Offline: See octoprint.log for details'
Connection closed, closing down monitor

so thats where I am, it's happened 3x I even rebooted the Pi just to make sure.

[KevMags]

Heats bed, prints "Bed Done" on LCD.
Seems to choke after: Send: N2 M109 S210.000000*71

Text cut and paste from terminal tab:
TerminalTab.txt

[foosel]

@KevMags try setting "Settings" > "Serial" > "Advanced options" > "Max. consecutive timeouts ..." to 0 please, save, reconnect:

Not sure if that will solve the problem or just possibly remove something masking the real issue.

[KevMags]

Having to cold boot ramps for it to accept any instructions after having trouble connecting (after setting timeouts to 0). It takes roughly 1-2 minutes after "Send: N2 M109 S210.000000*71" before it throws the error (before setting timeouts to 0). After setting timeouts to 0 it took....... Well it seems stuck now for about 10 minutes with no error and the nozzle never heats.

After about 10 minutes I restarted the Pi to force log write.

Aaaak! That printer is not responding to bed heating anymore. Moving to another printer.

Printer #2. Bed heats, OctoPrint sends:"Send: N2 M109 S210.000000*71". No nozzle heating, no errors after 5 minutes (timed).
Restart OctoPrint for force log file write.

Massive connection problems, unresponsive to bed heat commands.
Here we go, it is heating now. Aaaaand now we have some errors.
Annnnnd it is printing.

Here are the new files from different printer:
octoprint.log.txt
Printer2term.txt

Serial log is empty.
Will try again and report back.

[KevMags]

Printer #2 printed. After cancelling print, it no longer heats bed. Warm reboot Pi, no longer heats bead. Reset ramps with reset switch, bed heats, nozzle heats, and prints.

[foosel]

@KevMags so you are rather seeing a complete stop in responses from the printer for a time, but not the garbled response lines as observed by @jdcasey and @sLpFhaWK, correct? Looks like two symptoms then, probably of the same issue considering that they vanish when rolling back, but manifesting differently for you.

Is anyone (or all) of you familiar with git bisect? That plus a bit of testing would help pinpointing the exact commit that introduced the problem. I stared at the code for the past two hours and tried a bunch of ideas to reproduce the same issues, but so far I'm drawing a complete blank, I simply cannot reproduce any of the observed behaviours at all. Knowing at least which exact commit introduced the problem might help getting an idea what the issue is (and how to solve it).

In any case, I'll have to stop for today now, it's 1:30am here and it's getting hard to keep my eyes open, despite me desperately wanting to figure this out.

[KevMags]

I see garble responses at times. I am running 0 for timeouts now.

Printer #3
Heats bed and stabilizes at 60C, never prints "bed done" to LCD. Hangs after " N5 M190 S60*91"

Printer #3 Files:
Prntr3Term.txt
octoprint.log.txt

[KevMags]

Printer #1 will connect, shows proper temps but not respond to "print" or to manually set bed temp. No response in terminal window after "Send: N1 M190 S60.000000*113"

[foosel]

@jdcasey sounds familiar, big thanks for the help so far! Without being able to reproduce this myself I really am completely hamstrung.

Ok, could everyone who can reproduce these problems please try if the fix/revertTimeoutAdjustment branch solves the problem for them? That removes the re-setting of the read timeout on the serial to a shorter value during a heatup.

The fix has now been merged to the maintenance branch, please test THAT. See also this comment further below.

Updated test instructions as follows

---

To give this a whirl on OctoPi:

cd ~/OctoPrint
source ~/oprint/bin/activate
git fetch
git checkout maintenance
python setup.py clean
python setup.py install
sudo service octoprint restart

---

Instructions for manual install which followed the setup guide:

cd /path/to/OctoPrint
source venv/bin/activate
git fetch
git checkout maintenance
python setup.py clean
python setup.py install

• restart OctoPrint

[jdcasey]

@foosel I tried the top set of instructions above. It's printing now. I'd say whatever you changed, you got it.

[foosel]

That's good news I guess, although I'm completely baffled by this and don't understand how setting the timeout (which is basically all that I removed just now) can have these consequences O_O Not understanding why code creates an issue severely worries me because that means I can't avoid the core cause in the future.

@atc1441 @KevMags @sLpFhaWK could you give this a test as well?

[jdcasey]

@foosel Speaking as a python newbie, the only thing I can find in that latest commit that stands out is:

1f19fd1#diff-493d6fa72f9017192b4aaf4a824e2e0aL1358

There are two calls assigning values to self._serial.timeout that aren't in the reverted code. Everything else looks that same. Is it possible that that value cannot be changed in an open connection? Like I say, just guessing...

Ok, really time for bed here. 😄

[foosel]

@jdcasey It can, and it actually does it elsewhere in the code since a couple of years (e.g. during connection handshake). Plus it didn't cause any problems on my own printer here and I've been printing a lot over the past week to test the changes I did to the comm layer. So it's not a general issue, but it appears to be causing trouble for some people/machines.

I'm digging through my test hardware now to see if I can find anything with which I can reproduce this myself, to be able to better understand it. I'm also still worried a bit that the issue does manifest in separate ways and not 100% sure that there might not be another problem hidden in there.

Anyhow, a good night to you and big thanks again for the git bisect, that really made the difference between frustrated head scratching here and at least an idea where to dig to understand this (while of course also preparing a fix release once I'm sure it really only is this issue).

[foosel]

Good news. I could reproduce it on the UM I still had collecting dust in a cupboard. For me it shows the behaviour that @KevMags described, not the garbled messages observed by @jdcasey, @sLpFhaWK and also some people on the G+ community, and the fix instantly solves it.

That still doesn't explain what is going wrong there in the first place but at least it looks like pushing that fix out would solve it. Still, the more reports I can get to confirm this, the better, so please, test.

[foosel]

For reference, minimal test file: https://gist.github.com/foosel/2264d61a979833c616717095079742d9

[foosel]

The fix is now merged to maintenance, which also contains a fix for an issue with certain disconnect constellations as observed by @stema12 in #1425 and a compatibility fix for plugins which replace the serial object and don't return the amount of written bytes on their write implementation.

New instructions for testing and roll back afterwards as follows, please test and report back - I don't want to release this before I'm not sure it's really fixing the issue for everyone who so far chimed in here.

---

On OctoPi:

Testing:

cd ~/OctoPrint
source ~/oprint/bin/activate
git fetch
git checkout maintenance
python setup.py clean
python setup.py install
sudo service octoprint restart

Returning to "regular" checkout again after testing and rolling back to 1.2.13:

cd ~/OctoPrint
source ~/oprint/bin/activate
git fetch
git checkout master
git reset --hard 1.2.13
python setup.py clean
python setup.py install
sudo service octoprint restart

---

On a manual install which followed the setup guide:

Testing:

cd /path/to/OctoPrint
source venv/bin/activate
git fetch
git checkout maintenance
python setup.py clean
python setup.py install

and restart OctoPrint

Returning to "regular" checkout again after testing and rolling back to 1.2.13:

cd /path/to/OctoPrint
source venv/bin/activate
git fetch
git checkout master
git reset --hard 1.2.13
python setup.py clean
python setup.py install

and restart OctoPrint

[sLpFhaWK]

I will test but I won't be able to do it until later today after I. get home from work. I'm just getting ready now. glad to see it possibly resolved though!!

Sent from my iPhone

On Jul 29, 2016, at 04:01, Gina Häußge notifications@github.com wrote:

The fix is now merged to maintenance, which also contains a fix for an issue with certain disconnect constellations as observed by @stema12 in #1425 and a compatibility fix for plugins which replace the serial object and don't return the amount of written bytes on their write implementation.

New instructions for testing as follows, please test and report back - I don't want to release this before I'm not sure it's really fixing the issue for everyone who so far chimed in here.

To give this a whirl on OctoPi:

cd ~/OctoPrint
source ~/oprint/bin/activate
git fetch
git checkout maintenance
python setup.py clean
python setup.py install
sudo service octoprint restart
Instructions for manual install which followed the setup guide:

cd /path/to/OctoPrint
source venv/bin/activate
git fetch
git checkout maintenance
python setup.py clean
python setup.py install
restart OctoPrint
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

[stimpy23]

Sorry for my super-incomplete bug reporting, but I had similar errors after updating to 1.2.14 on my FlashForge Creator Pro with Sailfish v7.7 and testing your maintenance release solved 'em for me, so did reverting to 1.2.13 afterwards..
You guys are awesome! Was too lazy filing a complete bugreport yesterday late at night and today, I was able to read the whole story including a simple solution over here.. Thank you very much!

[foosel]

Everyone keep testing please. I'm not completely convinced that we got it after all. I was just going through my release checklist, this time also doing several previous/after tests against the UM and while I couldn't reproduce at all against 1.2.15.dev I could also sometimes not reproduce it against 1.2.14 and that worries me that there might still be something else in there.

I'm currently leaning towards leaving the 1.2.14 release disabled but not pushing 1.2.15 until after the weekend when hopefully more people have had a chance to test this thoroughly. I'll need your cooperation there however, because I only have one machine here that I can reproduce the problem semi reliably on and that is not the base of judgement I'd like here.

[KevMags]

Fixed all 3 of my printers. Thanks!!!

[foosel]

@KevMags Glad to hear, thanks for reporting back!

In the meantime I've dug a bit deeper still as to why I suddenly couldn't reproduce it reliably anymore against the same printer I could reproduce it just fine this very morning. Unreliable reproduction was on my test Pi2. Reliable reproduction on my development machine. So that got me thinking. Forcing a bit of a wait between sending the M109 and the consequent read timeout setting made it magically work on my workstation too. Reliably. Every single time. So my current guess is that there's something inside pyserial or possibly the underlying OS code that's responsible for this. Changing the read timeout constitutes as reconfiguring the port and my guess is that's bound to create trouble if there are still bytes being sent at another corner of the system via said port. Adding a little delay before changing the timeout gave the machine enough time to send all bytes over the line and empty its buffers so that the timeout switch didn't cause any harm.

I'm still not fully sure why there's a difference in behaviour between my regular to-go printer (no issue reproducible at all) and the UM I finally could trigger the problem on, but my guess would be either different buffer settings or chipsets or something along those lines.

At least, the current level of understanding of what's happening here makes me a bit more calm about pushing the fix as an actual fix. Still, I'll wait a couple more hours at a minimum, or possibly over the weekend, depending on how much feedback I get in the meantime. I really don't want to have to push the third release within 48 hours ;)

[jdcasey]

@foosel Okay, I updated to the maintenance branch and reinstalled. It's currently printing. Started without a hitch, and the terminal output looks clean.

[foosel]

@jdcasey great news then I guess! :)

That makes a 100% success rate so far over the posts on the G+ community and everyone who reported back here. And considering that I now have an idea about what went wrong I feel better about releasing this.

I'll still leave you people on the other side of the Atlantic a bit more testing time, so that @sLpFhaWK and @atc1441 also have a chance to join the party... I need a full night's sleep anyhow (hopefully without dreaming about OctoPrint's communication layer this time ;)) and hence will wait with the release until tomorrow morning.

Big thanks to everyone for reporting back their findings, and especially to @jdcasey for jumping through the hoops of the git bisect that uncovered the guilty commit!

[atc1441]

@foosel
Thank you for your sleepless nights and for the hard but good work on octoprint.
I didnt had the time to do a bigger bug search, sry for that. But this was my first post ever on github i must learn how to do a full bug report and to work with github :)

Have a nice day or night

[jdcasey]

@foosel I'm happy to help. It was fun debugging a software problem that could cause a fire. 😄 Most of my stuff is so boring by comparison.

[sLpFhaWK]

I am headed home now and when I get there I will apply the fix you have listed! 30-45 mins till I report back! thanks!

Sent from my iPhone

On Jul 29, 2016, at 15:31, Gina Häußge notifications@github.com wrote:

@jdcasey great news then I guess! :)

That makes a 100% success rate so far over the posts on the G+ community and everyone who reported back here. And considering that I now have an idea about what went wrong I feel better about releasing this.

I'll still leave you people on the other side of the Atlantic a bit more testing time, so that @sLpFhaWK and @atc1441 also have a chance to join the party... I need a full night's sleep anyhow (hopefully without dreaming about OctoPrint's communication layer this time ;)) and hence will wait with the release until tomorrow morning.

Big thanks to everyone for reporting back their findings, and especially to @jdcasey for jumping through the hoops of the git bisect that uncovered the guilty commit!

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

[sLpFhaWK]

I am happy to report that the fix worked for me, Printer heated up normally and started to print just like before. I'm glad it works, thanks everyone for the help!

[JustSid]

I'd also like to chime in, it works great for me again from the maintenance branch. Thank you so much for the quick fix @foosel!

[BinaryConstruct]

From my testing the maintenance branch also fixes the comms issues I was having with 1.2.14.

Hardware:
RPi 3 with OctoPi
Sanguinololu with Marlin RC_bugfix https://github.com/MarlinFirmware/Marlin/commits/RCBugFix
Ramps + Arduino Mega with Marlin RC_Bugfix

[foosel]

Thanks everyone! 1.2.15 release with the fix is now published. I for one wish everyone a nice weekend, I know I really need mine now ;)