Octoprint: Upload via watched folder does not reset job data, leading to wrong progress reporting

[caffeineflo]

First and foremost, I think similar activity has been reported in #1603 and other issues that have been opened. It was mentioned that more information might be helpful, so here I am trying to provide that information.

What were you doing?

Had a smaller print (GCODE file size: ~300kb) with the Filename "Dupont_Mount-PLA.gcode" that printed well. I later created a new GCODE file that was significantly larger (2.7MB) that had the same filename and got uploaded to my octoprint server to the watched folder. At this time, the 300kb file was still "loaded and armed" but finished on Octoprint.
I started the new file by clicking the print button in the 'state' box, which printed the new 2.7MB file, yet didn't update the state's GCODE file size indicator.

The print started to print with the 0-100% status bar going to 740%, then stopped before the GCODE file ended with the fans on and the both the heater 1 and the HBP going. No disconnect or anything that would further indicate the situation.
Had to cancel the print to get it to stop. As I was printing over night, the print was left at 740% for about 6 hrs at least.

What did you expect to happen?

The print to finish normally

What happened instead?

Stopped at the last position that was sent to the printer.

Branch & Commit or Version of OctoPrint

origin/master 1.3.1

Printer model & used firmware incl. version

Latest version of marlin on their RCBugFix Branch (commit 9b55159)

Browser and Version of Browser, Operating System running Browser

Latest Chrome, latest macOS (still a stupid name, os x was soo much better)

Link to octoprint.log

https://gist.github.com/caffeineflo/7c7e09eecee67cf6ed8c3ddac740f06c

Link to contents of terminal tab or serial.log

https://gist.github.com/caffeineflo/7c7e09eecee67cf6ed8c3ddac740f06c

Link to contents of Javascript console in the browser

Not applicable

Screenshot(s) showing the problem:

N/A

I have read the FAQ.

[gu1234]

Had a similar issue, I noticed that the screen on my Prusa MK2 goes blank for a second (as if the RAMBO board restarts). This happens usually early in the prints and some times on the first layer. Never happened to me when printing directly from the SD card.

The log on octoprint didn't have anything out of the ordinary

[nophead]

This is because you are losing the USB connection and that is resetting you
board, although I would expect the reset to shut of the heaters. Losing the
USB connection is a hardware problem, not a software one.

On 8 February 2017 at 22:11, Ofir [e-mail] wrote:

Had a similar issue, I noticed that the screen on my Prusa MK2 goes blank
for a second (as if the RAMBO board restarts). This happens usually early
in the prints and some times on the first layer. Never happened to me when
printing directly from the SD card

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/foosel/OctoPrint/issues/1760#issuecomment-278478530,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAijhd8NY7SXPFECRQO26qpKH0PBUlLXks5raj2cgaJpZM4L63RG
.

[caffeineflo]

@nophead Where in my log files did you see that the USB connection was lost?
I couldn't find anything pointing towards a lost connection.

[nophead]

Sorry, I was replying to @gu1234

I think your issue is the firmware and OctoPrint don't agree what the checksum is for this line.

N83671 M117 [##########################################################################] 740%*63

How it got to 740% seems like a bug as well.

[Blue-Marlin]

That many '#' are a challenge for firmwares (Marlin). The status line is usually not longer than 22 chars, the reserved space not more than 22*3+1 (utf8).

[caffeineflo]

You just killed that plugin ... we'll see if that's getting better now ;) Thanks!

[foosel]

While that plugin should not produce lines like this (and I'll have to take a look at some error checks to make it so that it ignores faulty progress data), the more concerning issue here is that apparently your printed file kept growing in size even after you started the job, which would explain how it could even go past 100%. The size of and position in the file is all that OctoPrint has for tracking progress here. It assumes the size to not change after start. Apparently that is not the case here and the question is why.

From your description it sounds like overwriting it via the watched folder for some reason didn't trigger the job data to be refreshed. Which would be a bug. I'll have to look into this, I'm currently still out of commission though, so this will take at least until next week.

In any case, this looks like it's caused by a combination of wrong progress reporting and the Display Progress plugin not being resilient against that leading to a way too long M117 line to be produced which then caused the communication issue. Disabling the plugin or reselecting the equally named file uploaded through the watched folder prior to a second print should be a workaround until this is fixed.

[caffeineflo]

Disabling the plugin or reselecting the equally named file uploaded through the watched folder prior to a second print should be a workaround until this is fixed.

This is what I usually did and never had this issue before. I also never experienced the issue when the new file was only slightly larger than the original file. This was the first case where the new file was larger by a multiple of 10 and more.

[foosel]

Ok, so I found two things. One was that as expected the upload via the watched folder was actually missing the reselect that is necessary to refresh the data about the current job. So that's fixed now.

The other was that contrary to what I assumed the used library for detecting file creation did trigger immediately on file creation, not when the file was fully there - that was something that came up in the discussions in #1765 and turned out to be right (thanks @nophead). So OctoPrint could move the file over to the uploads folder while it was still being written. And the way how linux file systems work caused that to not cause any obvious issues at all, other than immediately selecting it then could cause the wrong file size to still be reported. Windows behaves differently here again and at least so far I couldn't reproduce that specific scenario there, even when copying a file from a network source.

In any case, what it will now do on a creation event is not trigger the move immediately but instead polling the file size every second. Once it is stable for the past five polls, it will trigger the move. We still might have to experiment with those values, but at least in my initial tests they looked fine.

Example (started circling with the cursor once the file was copied fully to the watched folder):

Update in the file list after upload takes a smidge longer because that requires a full fetch of the whole file list and that simply takes longer than just pushing a new size to the client, especially with a long file list.

As you see above I pushed these changes to the maintenance branch and will also merge them to devel ASAP. They'll be released with 1.3.2.

[caffeineflo]

Great! Thanks @foosel

I'll give it a try tonight

[caffeineflo]

@foosel Tried it again and had no issues whatsoever! Thanks for the fix

[foosel]

1.3.2 was just released.