Timelapse no longer works on update to 1.3.4

[kidtire]

What were you doing?

[Please be as specific as possible here. The maintainers will need to reproduce your issue in order to fix it and that is not possible if they don't know what you did to get it to happen in the first place.

Ideally provide exact steps to follow in order to reproduce your problem:

Setup: Qidi Tech I dual extruder printer, Raspberry Pi 3, Pi Camera Module v2

1. Run Octoprint v1.3.2
2. Setup camera and time-lapse feature
3. Note that it works, i.e., produces a time-lapse movie after every print
4. Update to Octoprint 1.3.4
5. Change default printer back (other bug sets it)
6. Time-lapse appears to be working but doesn't save images or make a time-lapse movie
7. Note that all the test stream and imaging works in the interface.
8. Note that you can directly stream or take a snapshot from the URLs
9. COMPLETELY reformatted SD card on Raspberry Pi (3)

If you encountered a problem with specific files of any sorts, make sure to also include a link to a file with which to reproduce the problem.]

What did you expect to happen?

Expected a time-lapse movie.

What happened instead?

No time-lapse movie was produced. However, the time-lapse menu says it is disabled while printing as it did in the last release.

Did the same happen when running OctoPrint in safe mode?

I cannot run Octoprint in safe mode due to needing the GPX plug-in for my Qidi Tech I printer.

Branch & Commit or Version of OctoPrint

OctoPrint 1.3.4 (master branch)

Operating System running OctoPrint

OctoPi 0.13.0 on Raspberry Pi 3

[OctoPi, Linux, Windows, MacOS, something else? With version please. OctoPi's version can be found in /etc/octopi_version]

Printer model & used firmware incl. version

Qidi Tech I

Browser and Version of Browser, Operating System running Browser

Safari - 10.1.1

Link to octoprint.log

(edited by @foosel: replaced log dump with link to log for reasons of readability)

https://gist.github.com/foosel/5ace5601d0a20f25b46a78d90907f63f

Link to contents of terminal tab or serial.log

It prints ok, it just isn't turning on time-lapse for some reason.

Link to contents of Javascript console in the browser

[Info] Starting dependency resolution... (packed_core.js, line 12820) [Info] ... dependency resolution done (packed_core.js, line 12921) [Info] Initial application setup done, connecting to server... (packed_core.js, line 13150) [Info] Connected to the server (packed_core.js, line 11368) [Info] Finalizing application startup (packed_core.js, line 13154) [Info] Going to bind 31 view models... (packed_core.js, line 13058) [Info] Did not bind view model (4) (packed_core.js, line 13099) "CoreWizardAclViewModel" "to target" "#wizard_plugin_corewizard_acl" "since it does not exist" [Info] Did not bind view model (4) (packed_core.js, line 13099) "CoreWizardPrinterProfileViewModel" "to target" "#wizard_plugin_corewizard_printerprofile" "since it does not exist" [Info] Did not bind view model (4) (packed_core.js, line 13099) "CoreWizardWebcamViewModel" "to target" "#wizard_plugin_corewizard_webcam" "since it does not exist" [Info] Did not bind view model (4) (packed_core.js, line 13099) "CoreWizardServerCommandsViewModel" "to target" "#wizard_plugin_corewizard_servercommands" "since it does not exist" [Info] Did not bind view model (4) (packed_core.js, line 13099) "CuraViewModel" "to target" "#wizard_plugin_cura" "since it does not exist" [Info] Did not bind view model (4) (packed_core.js, line 13099) "SoftwareUpdateViewModel" "to target" "#wizard_plugin_softwareupdate" "since it does not exist" [Info] ... binding done (packed_core.js, line 13132) [Info] Application startup complete (packed_core.js, line 13143)

Screenshot(s)/video(s) showing the problem:

[If applicable. Always include if unsure or reporting UI issues.]

I have read the FAQ.

[foosel]

You didn't mention it explicitly, so just for the record: You did verify that "Timelapse Mode" is not set to off? Just to rule out that for whatever reason the update disabled it and that's the issue:

I don't see any timelapse related errors in your log and cannot reproduce this right now, hence I'm asking.

[JohnOCFII]

As a data point, time lapses are working fine for me with 1.3.4 (rc/maintenance branch)

[kidtire]

It is set on. It is currently in the middle of a long print so shows that you cannot change settings now.

On Jun 19, 2017, at 2:52 AM, Gina Häußge notifications@github.com wrote:

You didn't mention it explicitly, so just for the record: You did verify that "Timelapse Mode" is not set to off? Just to rule out that for whatever reason the update disabled it and that's the issue:

I don't see any timelapse related errors in your log and cannot reproduce this right now, hence I'm asking.

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

[foosel]

Still cannot reproduce this, anyone else?

[foosel]

Alternatively, @kidtire is there any chance I might take a look at this instance myself? Port forwarding or something?

[kidtire]

Maybe. I have been out of town so would likely have to be at the printer so you could try things.

[foosel]

@kidtire just shoot me an email at gina -at- octoprint.org if you happen to have some URL I can take a look at. Also happy to coordinate via live chat or something. I'd just like to take a look myself because right now I'm really not able to reproduce this at all, all working fine here just like before.

[kidtire]

Update: I completely re-mastered the pi with the new Octopi v0.14, and reconfigured it from scratch.

I installed the GPX plug-in as I have a Qidi Tech printer on this Octopi config.

I have never been able to print OTHER than from SD card. So, I tried again uploading some gcode to the pi then printing from there, just in case. It tried to start the print but hung waiting. However, it did create a super boring time-lapse of the printer just waiting.

Then I printed from the SD card and it printed but no time-lapse, just as before.

[kidtire]

Update 2:

I tried an external USB webcam to see if it was specific to the PiCam used and that had no effect. This is a webcam that I am using successfully on another Octopi config on my Prusa so I know it works somewhere.

[foosel]

Then I printed from the SD card and it printed but no time-lapse, just as before.

How do you start that SD card print? As far as I know it's not possible yet to start SD prints through OctoPrint when using the GPX plugin (@markwal, please correct me on this if I'm wrong), and if you don't start a print through OctoPrint it has no way to KNOW you started a print and hence to also start a timelapse.

[markwal]

@foosel Actually you can start an SD card print in the normal way in OctoPrint. You can't however, upload to the SD card via serial streaming. Sailfish removed support for that at some point figuring it is too slow to be practical and the bytes could be put to better use on a different feature.

However, if @kidtire triggers starting the SD card print from the printer's LCD then, of course, there will be no timelapse. Similarly, if it is set to On Z Change, then there will also be no timelapse because OctoPrint doesn't know when the Z changes occur.

The log did look like GPX was having a problem and isn't in a state that will talk to the printer. I don't see a successful connect in the log. Do you have an octoprint.log from your more recent attempt on the fresh image? I suspect you need to save settings and choose your port and baud rate.

[kidtire]

I slice the model and copy the *.x3g file to an SD card then insert it into the printer.

Then I open OctoPrint in a web browser and refresh the SD card. Then, select the file and click "Print" and it prints. I always kick off the print from OctoPrint as then at least I can look in the "Terminal" tab and get some idea where it is in the print. I can also view the print action through the "Control" tab.

In 1.3.2 I would also get a time-lapse but no longer in 1.3.4.

I am attaching a combined log of the last few rolled over log files. The most recent print was started by the connected logged by this line: 2017-07-10 06:18:42,746 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.52

I will also attach the plugin manager log and the GPX log in case that helps.

octoprintlogs.zip

[kidtire]

I forgot to mention I do have the baud rate and port set: octoprint.plugins.GPX - INFO - GPXPrinter created, port: /dev/ttyACM0, baudrate: 115200

I have had some communication issues starting up sometimes but once it connects it is good. There are segments in the log that show some of these like this most recent one:

2017-07-09 21:03:40,409 - octoprint.util.comm - ERROR - Unexpected error while writing to serial port Traceback (most recent call last): File "/home/pi/oprint/local/lib/python2.7/site-packages/OctoPrint-1.3.4-py2.7.egg/octoprint/util/comm.py", line 2260, in _do_send_without_checksum result = self._serial.write(to_send) File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_GPX/gpxprinter.py", line 131, in write self._append(gpx.write("%s" % data)) IOError: [Errno 5] Input/output error

[foosel]

I now was able to take a look at @kidtire 's instance and could reproduce the problem. I also saw what's happening: when printing from SD via the GPX plugin, the PrintStarted event never gets fired, which the timelapse component needs however to know it's supposed to start recording. I couldn't test if the PrintDone event (used for stopping recording and triggering timelapse creation) was also missing due to cancelling the print causing the printer to go into "please click some button on the controller to proceed" mode, so that should be looked at as well.

On the affected instance I got these events on a print start:

• FileSelected
• PrinterStateChanged

On my own (printing from SD but not via GPX) I got this:

• FileSelected
• PrinterStateChanged
• PrintStarted

The latter also fired a lot of CaptureStart and CaptureDone then - which makes sense, timelapse there works just fine.

In any case, @markwal, I'll need your assistance on this. The only idea I have right now is something in the SD print start against the GPX plugin causes the print start sequence in on_comm_print_job_started to never properly trigger. I have no idea right now however how that could be achieved and I don't know the GPX plugin's internals enough to even get an inkling of that.

The relevant bits in OctoPrint are these lines. The funny thing is that I could definitely see it performing the state change, sending the M110, M23 and M24 and also starting up the regular sd status poll timer (which btw seems to report the wrong format). So the routine in there should have performed correctly. However, on_comm_print_job_started either wasn't actually called, or it was called but the event never made it through (O_O).

@markwal is there any way to test some prints with the GPX plugin against some kind of virtual printer with a virtual SD?

[markwal]

@foosel Unfortunately, no, no virtual x3g printer still. :-(

I did repro however and I'm not sure why I wasn't able to repro earlier. The problem is caused by a combination of GPX always return 0 bytes as the size of any SD card file (x3g doesn't return the actual size) and a new line introduced by 4c65313c (I put notes on the commit) that results in the payload being empty.

[markwal]

I'm not sure the best way to fix this:

• I could come up with a different lie on the file sizes (1 byte?) in the plugin or
• we could change _payload_for_print_job_event to have 0 be the default size instead of None and go ahead and return it
• or we could have None still be the default, but count an actual "0" as ok and None suppresses...
• or we could only allow 0 for non-LOCAL file paths

What do you think?

[foosel]

This is something that came up in #1917 #1963 - although in a different context - and was fixed in d39c124f35b53a02b80134af28962fe26dc4b1d2 already. File size there is made optional, so if it's None or 0 or what not, no harm done. That will be rolled out with 1.3.5.

I'll most likely not get a full release out for that until after my overdue vacation at the start of August (also because I know myself, if I just put out a new stable release I'll feel anxious to check my work related mails during my vacation all the time ;)), but I'll try to get a first RC out.

[foosel]

Btw, thanks for looking into this and good catch!

[foosel]

I just managed to make my virtual printer behave similar to the GPX ones by removing all reports of size, was able to reproduce the issue on master/1.3.4 and could confirm that it is gone on maintenance and hence the future 1.3.5.

So marking this as solved, caused by the same issue that caused #1917 #1963.

[foosel]

... Not #1917 but #1963. I have no idea how I mixed up those two tickets. Edited above.

[motley74]

Thanks for looking into this, it has been bugging me for over a month now and just decided to look into it and I found this issue reported. I am switching to the maintenance branch now which I have been meaning to do for a while.

[foosel]

@motley74 it's fixed in 1.3.5 which was released yesterday.