Octolapse never resumes printing after taking snapshot

[skorokithakis]

As detailed in #88 (which I unwittingly hijacked, I'm sorry, I'm trying to make amends by opening this issue), Octolapse sometimes takes a snapshot but never resumes printing afterwards.

Here's a video of it happening, and it also answers the question of what happened to my previous cat print.

[FormerLurker]

Thanks! I've been looking into this but haven't figured it out yet. Will start again after work tomorrow.

[FormerLurker]

@skorokithakis , can you try re-installing from the plugin manager with this URL: https://github.com/FormerLurker/Octolapse/archive/master.zip

I added some additional logging, and made a few changes that might get rid of the freeze issue. If you do experience a freeze, hopefully there will be more debug info available.

Thanks!

[skorokithakis]

Will do! Have you added truncating the log before each print so we don't have to restart the server every time?

[FormerLurker]

Sorry, no. I'm trying to get the python logger to recreate the log if the file does not exist, but for some reason it is resisting me :) Sorry to put you through so many reboots. I will work on this as soon as I verify that this freeze bug is fixed, or at least greatly reduced.

[skorokithakis]

I think what's happening is that the logger keeps the file open until you restart the server, so the file handle is never closed. You need to actively close the file first, otherwise the logger will never even check for a new file.

[FormerLurker]

There is a fix for this in Python 3.6. I probably need to write my own file handler to do this for 2.7 so that I can check the stream before emitting a value.

Speaking of the logger, I just added some code to make it asynchronous. I discovered that the logger was causing a lot of latency, but only every once in a while! In the worst case it causes the printer to stutter for a second or two, leaving blobs on the surface of my print. I'm about to push this up to master.

[FormerLurker]

Hey, I found a way to truncate the log file from the command line if you're using some flavor of linux. I telnet into the pi, go to the following directory: ~/.octoprint/logs

and execute: truncate -s 0 plugin_octolapse.log

Then I can execute the following: tail -f plugin_octolapse.log

which lets me watch the debug output as it is generated.

Let me know if you're using windows and I'll dig up a command for that too.

[skorokithakis]

Oh, no, I'm using Raspbian, that should work fine, thanks! I'm going to print something now, so I'll send you the logs shortly (if the problem happens).

[FormerLurker]

Excellent. I am glad to report the asynchronous logging seems to have fixed the stuttering I was experiencing. If you are just installing now you should have the upgrade. I'm getting a flawless benchy!

If you have success too I'm going to drop v0.2.3. I believe I've fixed the initial install issues and several other problems folks have reported.

[skorokithakis]

I keep getting popups on Octoprint with this error message:

Position - Coordinates (X:None,Y:None,Z:None,E:0.00000) are out of the printer area! Cannot resume position tracking until the axis is homed, or until absolute coordinates are received.

[FormerLurker]

Hmm. Might be 1 of 2 things:

1. Missing absolute mode command (g90 I think)

2. Stupid initial install bug that might not be fixed.

If 2 a reboot will fix and I'll go back to the drawing board on it. If 1, just set xyz axis mode to absolute or add the GCode to the top of your start GCode.

Check the position state info panel to confirm item 1. A print needs to be running for this to work.

On Mon, Mar 26, 2018, 5:46 PM Stavros Korokithakis notifications@github.com wrote:

I keep getting popups on Octoprint with this error message:

Position - Coordinates (X:None,Y:None,Z:None,E:0.00000) are out of the printer area! Cannot resume position tracking until the axis is homed, or until absolute coordinates are received.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376336188, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuC-I1fRbU_lkge4kgPQZM43aNYmMks5tiW-6gaJpZM4S6bht .

[skorokithakis]

Hmm no, I did add a G90. Will reboot and retry, thanks!

[skorokithakis]

I didn't get the error now, but still no messages captured. Start of the log:

2018-03-26 21:52:09,897 Printer event received:Disconnecting.
2018-03-26 21:52:09,899 Printer disconnecting.
2018-03-26 21:52:09,902 Printer event received:Connecting.
2018-03-26 21:52:09,956 Printer event received:PrinterStateChanged.
2018-03-26 21:52:09,975 Printer event received:PrinterStateChanged.
2018-03-26 21:52:09,978 Printer event received:PrinterStateChanged.
2018-03-26 21:52:10,044 Printer event received:PrinterStateChanged.
2018-03-26 21:52:10,054 Printer event received:Connected.
2018-03-26 21:52:10,126 Printer event received:FirmwareData.
2018-03-26 21:52:12,766 Printer event received:FileSelected.
2018-03-26 21:52:14,532 Printer event received:UpdatedFiles.
2018-03-26 21:52:14,558 Printer event received:FirmwareData.
2018-03-26 21:52:22,939 Printer event received:PrinterStateChanged.
2018-03-26 21:52:22,958 Print Start Detected.  Command: M110 N0, Tags:set(['trigger:comm.start_print', 'trigger:comm.reset_line_numbers'])
2018-03-26 21:52:22,981 Print Start Detected.  Command: M190 S50, Tags:set(['trigger:comm.start_print', 'source:file', 'filepos:118', 'fileline:1', 'trigger:printer.start_print', 'api:job', 'source:api'])
2018-03-26 21:52:22,982 Print start detected, attempting to start timelapse.
2018-03-26 21:52:22,984 Printer event received:PrintStarted.
2018-03-26 21:52:23,084 Creating Layer Trigger - TriggerHeight:0.0 (none = layer change), RequiresZHop:False
2018-03-26 21:52:23,084 Extruder Triggers - OnExtrudingStart:True, OnExtruding:True, OnPrimed:True, OnRetractingStart:None OnRetracting:None, OnPartiallyRetracted:False, OnRetracted:True, ONDetractingStart:False, OnDetracting:False, OnDetracted:False
2018-03-26 21:52:23,087 Print Started - Timelapse Started.
2018-03-26 21:52:54,752 Queuing Command: Command Type:temperature, gcode:M105, cmd: M105, tags: set(['trigger:comm.handle_timeout'])
2018-03-26 21:52:54,754 Sent to printer: Command Type:None, gcode:M82, cmd: M82, tags: set(['filepos:167', 'source:file', 'fileline:4'])
2018-03-26 21:53:26,545 Queuing Command: Command Type:temperature, gcode:M105, cmd: M105, tags: set(['trigger:comm.handle_timeout'])
2018-03-26 21:53:26,545 Extruder Changed: E:0.0, Retraction:0 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:False-True, IsRetractingStart:False-False, IsRetracting:False-False, IsPartiallyRetracted:False-False, IsRetracted:False-False, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2018-03-26 21:53:46,945 Queuing Command: Command Type:None, gcode:M117, cmd: M117 [          ]   0%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-26 21:53:46,946 Sent to printer: Command Type:temperature, gcode:M105, cmd: M105, tags: set(['trigger:comm.handle_timeout'])
2018-03-26 21:53:47,043 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:53:47,044 Queuing Command: Command Type:None, gcode:G28, cmd: G28, tags: set(['source:file', 'fileline:5', 'filepos:177'])
2018-03-26 21:53:47,046 Received G28 -
2018-03-26 21:53:47,047 Printer event received:Home.
2018-03-26 21:53:47,049 homing to payload:Home.
2018-03-26 21:53:47,051 Sent to printer: Command Type:None, gcode:M117, cmd: M117 [          ]   0%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-26 21:53:47,052 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:53:47,055 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['source:file', 'filepos:221', 'fileline:6'])
2018-03-26 21:53:47,056 Received Linear Move
2018-03-26 21:53:47,058 Sent to printer: Command Type:None, gcode:G28, cmd: G28, tags: set(['source:file', 'fileline:5', 'filepos:177'])
2018-03-26 21:53:47,059 Position - Unable to update the X/Y/Z axis position, the axis mode (relative/absolute) has not been explicitly set via G90/G91.
2018-03-26 21:53:47,062 Position Change - G1 Z15.0 F6000 - Absolute Move From(X:None,Y:None,Z:None,E:0) - To(X:None,Y:None,Z:None,E:0)
2018-03-26 21:53:47,063 A position altering command has been detected.  Fetching and updating position.  Position Command: G1 Z15.0 F6000
2018-03-26 21:53:47,063 Octolapse is requesting a position.
2018-03-26 21:53:47,064 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 21:53:47,065 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 21:53:47,152 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 21:53:47,155 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 21:53:49,028 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:53:49,033 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:53:54,033 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:53:59,035 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:54:04,037 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:54:09,038 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:54:14,039 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:54:16,569 Printer event received:PositionUpdate.
2018-03-26 21:54:16,577 Sending saved command - G1 Z15.0 F6000.
2018-03-26 21:54:16,578 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 21:54:16,582 Received Linear Move
2018-03-26 21:54:16,583 Position - Unable to update the X/Y/Z axis position, the axis mode (relative/absolute) has not been explicitly set via G90/G91.
2018-03-26 21:54:16,583 Position Change - G1 Z15.0 F6000 - Absolute Move From(X:0.0,Y:0.0,Z:0.0,E:0.0) - To(X:0.0,Y:0.0,Z:0.0,E:0.0)
2018-03-26 21:54:16,585 Position Acquired
2018-03-26 21:54:16,585 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 21:54:16,590 Printer event received:PositionUpdate.
2018-03-26 21:54:16,590 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 21:54:16,590 Queuing Command: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['source:file', 'filepos:249', 'fileline:7'])
2018-03-26 21:54:16,591 Received G92 - Set Position.  Command:{0}, XOffset:{1}, YOffset:0, ZOffset:0, EOffset:0.0
2018-03-26 21:54:16,591 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,591 Printer event received:ZChange.
2018-03-26 21:54:16,597 Queuing Command: Command Type:None, gcode:G1, cmd: G1 F200 E8, tags: set(['fileline:8', 'source:file', 'filepos:270'])
2018-03-26 21:54:16,599 Received Linear Move
2018-03-26 21:54:16,600 Position - Unable to update the X/Y/Z axis position, the axis mode (relative/absolute) has not been explicitly set via G90/G91.
2018-03-26 21:54:16,600 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,602 Position Change - G1 F200 E8 - Absolute Move From(X:0.0,Y:0.0,Z:0.0,E:0.0) - To(X:0.0,Y:0.0,Z:0.0,E:0.0)
2018-03-26 21:54:16,604 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,606 Sent to printer: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['source:file', 'filepos:249', 'fileline:7'])
2018-03-26 21:54:16,607 Queuing Command: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:9', 'source:file', 'filepos:277'])
2018-03-26 21:54:16,608 Received G92 - Set Position.  Command:{0}, XOffset:{1}, YOffset:0, ZOffset:0, EOffset:0.0
2018-03-26 21:54:16,609 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,609 Sent to printer: Command Type:None, gcode:G1, cmd: G1 F200 E8, tags: set(['fileline:8', 'source:file', 'filepos:270'])
2018-03-26 21:54:16,618 Queuing Command: Command Type:None, gcode:G90, cmd: G90, tags: set(['fileline:10', 'filepos:311', 'source:file'])
2018-03-26 21:54:16,621 Received G90 - Switching to absolute x,y,z coordinates.
2018-03-26 21:54:16,622 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,623 Queuing Command: Command Type:None, gcode:M107, cmd: M107, tags: set(['source:file', 'fileline:11', 'filepos:341'])
2018-03-26 21:54:16,623 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,624 Sent to printer: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:9', 'source:file', 'filepos:277'])
2018-03-26 21:54:16,624 Sent to printer: Command Type:None, gcode:G90, cmd: G90, tags: set(['fileline:10', 'filepos:311', 'source:file'])
2018-03-26 21:54:16,650 Queuing Command: Command Type:None, gcode:G0, cmd: G0 F1500 X59.966 Y79.046 Z0.28, tags: set(['fileline:12', 'source:file', 'filepos:372'])
2018-03-26 21:54:16,650 Received Rapid Linear Move
2018-03-26 21:54:16,651 Position Change - G0 F1500 X59.966 Y79.046 Z0.28 - Absolute Move From(X:0.0,Y:0.0,Z:0.0,E:0.0) - To(X:59.966,Y:79.046,Z:0.28,E:0.0)
2018-03-26 21:54:16,653 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,657 Sent to printer: Command Type:None, gcode:M107, cmd: M107, tags: set(['source:file', 'fileline:11', 'filepos:341'])
2018-03-26 21:54:16,659 Queuing Command: Command Type:None, gcode:G1, cmd: G1 F600 X60.611 Y78.609 E0.03429, tags: set(['fileline:13', 'source:file', 'filepos:417'])
2018-03-26 21:54:16,660 Received Linear Move
2018-03-26 21:54:16,661 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,663 Position Change - G1 F600 X60.611 Y78.609 E0.03429 - Absolute Move From(X:59.966,Y:79.046,Z:0.28,E:0.0) - To(X:60.611,Y:78.609,Z:0.28,E:0.0)
2018-03-26 21:54:16,663 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,664 Sent to printer: Command Type:None, gcode:G0, cmd: G0 F1500 X59.966 Y79.046 Z0.28, tags: set(['fileline:12', 'source:file', 'filepos:372'])
2018-03-26 21:54:16,668 Printer event received:ZChange.
2018-03-26 21:54:16,669 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X61.297 Y78.24 E0.06857, tags: set(['source:file', 'filepos:444', 'fileline:14'])
2018-03-26 21:54:16,670 Received Linear Move
2018-03-26 21:54:16,671 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,673 Position Change - G1 X61.297 Y78.24 E0.06857 - Absolute Move From(X:60.611,Y:78.609,Z:0.28,E:0.0) - To(X:61.297,Y:78.24,Z:0.28,E:0.0)
2018-03-26 21:54:16,676 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,676 Sent to printer: Command Type:None, gcode:G1, cmd: G1 F600 X60.611 Y78.609 E0.03429, tags: set(['fileline:13', 'source:file', 'filepos:417'])
2018-03-26 21:54:16,677 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X61.297 Y78.24 E0.06857, tags: set(['source:file', 'filepos:444', 'fileline:14'])
2018-03-26 21:54:16,677 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X62.018 Y77.943 E0.10289, tags: set(['source:file', 'filepos:472', 'fileline:15'])
2018-03-26 21:54:16,677 Received Linear Move
2018-03-26 21:54:16,678 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,678 Position Change - G1 X62.018 Y77.943 E0.10289 - Absolute Move From(X:61.297,Y:78.24,Z:0.28,E:0.0) - To(X:62.018,Y:77.943,Z:0.28,E:0.0)
2018-03-26 21:54:16,678 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,681 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X62.766 Y77.721 E0.13724, tags: set(['filepos:500', 'source:file', 'fileline:16'])
2018-03-26 21:54:16,683 Received Linear Move
2018-03-26 21:54:16,684 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,684 Position Change - G1 X62.766 Y77.721 E0.13724 - Absolute Move From(X:62.018,Y:77.943,Z:0.28,E:0.0) - To(X:62.766,Y:77.721,Z:0.28,E:0.0)
2018-03-26 21:54:16,688 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,689 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X63.532 Y77.577 E0.17154, tags: set(['source:file', 'fileline:17', 'filepos:528'])
2018-03-26 21:54:16,690 Received Linear Move
2018-03-26 21:54:16,691 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,692 Position Change - G1 X63.532 Y77.577 E0.17154 - Absolute Move From(X:62.766,Y:77.721,Z:0.28,E:0.0) - To(X:63.532,Y:77.577,Z:0.28,E:0.0)
2018-03-26 21:54:16,692 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,692 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X62.018 Y77.943 E0.10289, tags: set(['source:file', 'filepos:472', 'fileline:15'])
2018-03-26 21:54:16,693 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X62.766 Y77.721 E0.13724, tags: set(['filepos:500', 'source:file', 'fileline:16'])
2018-03-26 21:54:16,697 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X64.55 Y77.509 E0.21645, tags: set(['fileline:18', 'source:file', 'filepos:555'])
2018-03-26 21:54:16,701 Received Linear Move
2018-03-26 21:54:16,703 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,704 Position Change - G1 X64.55 Y77.509 E0.21645 - Absolute Move From(X:63.532,Y:77.577,Z:0.28,E:0.0) - To(X:64.55,Y:77.509,Z:0.28,E:0.0)
2018-03-26 21:54:16,705 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,705 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X63.532 Y77.577 E0.17154, tags: set(['source:file', 'fileline:17', 'filepos:528'])
2018-03-26 21:54:16,705 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X84.344 Y77.512 E1.08764, tags: set(['source:file', 'fileline:19', 'filepos:583'])
2018-03-26 21:54:16,706 Received Linear Move
2018-03-26 21:54:16,706 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,706 Position Change - G1 X84.344 Y77.512 E1.08764 - Absolute Move From(X:64.55,Y:77.509,Z:0.28,E:0.0) - To(X:84.344,Y:77.512,Z:0.28,E:0.0)
2018-03-26 21:54:16,707 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,707 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X64.55 Y77.509 E0.21645, tags: set(['fileline:18', 'source:file', 'filepos:555'])
2018-03-26 21:54:16,713 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X85.123 Y77.552 E1.12198, tags: set(['source:file', 'fileline:20', 'filepos:611'])
2018-03-26 21:54:16,714 Received Linear Move
2018-03-26 21:54:16,715 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,716 Position Change - G1 X85.123 Y77.552 E1.12198 - Absolute Move From(X:84.344,Y:77.512,Z:0.28,E:0.0) - To(X:85.123,Y:77.552,Z:0.28,E:0.0)
2018-03-26 21:54:16,718 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,720 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X84.344 Y77.512 E1.08764, tags: set(['source:file', 'fileline:19', 'filepos:583'])
2018-03-26 21:54:16,722 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X85.893 Y77.672 E1.15627, tags: set(['fileline:21', 'source:file', 'filepos:639'])
2018-03-26 21:54:16,723 Received Linear Move
2018-03-26 21:54:16,723 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,724 Position Change - G1 X85.893 Y77.672 E1.15627 - Absolute Move From(X:85.123,Y:77.552,Z:0.28,E:0.0) - To(X:85.893,Y:77.672,Z:0.28,E:0.0)
2018-03-26 21:54:16,724 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,724 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X85.123 Y77.552 E1.12198, tags: set(['source:file', 'fileline:20', 'filepos:611'])
2018-03-26 21:54:16,728 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X86.627 Y77.863 E1.18966, tags: set(['fileline:22', 'filepos:667', 'source:file'])
2018-03-26 21:54:16,729 Received Linear Move
2018-03-26 21:54:16,731 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,731 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X85.893 Y77.672 E1.15627, tags: set(['fileline:21', 'source:file', 'filepos:639'])
2018-03-26 21:54:16,732 Position Change - G1 X86.627 Y77.863 E1.18966 - Absolute Move From(X:85.893,Y:77.672,Z:0.28,E:0.0) - To(X:86.627,Y:77.863,Z:0.28,E:0.0)
2018-03-26 21:54:16,732 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 21:54:16,745 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X88.44 Y78.434 E1.27332, tags: set(['fileline:23', 'filepos:694', 'source:file'])
2018-03-26 21:54:16,746 Received Linear Move
2018-03-26 21:54:16,747 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 21:54:16,747 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X86.627 Y77.863 E1.18966, tags: set(['fileline:22', 'filepos:667', 'source:file'])
2018-03-26 21:54:16,748 Position Change - G1 X88.44 Y78.434 E1.27332 - Absolute Move From(X:86.627,Y:77.863,Z:0.28,E:0.0) - To(X:88.44,Y:78.434,Z:0.28,E:0.0)
2018-03-26 21:54:16,749 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True

[skorokithakis]

Start of my Gcode file:

;FLAVOR:Marlin
;TIME:795
;Filament used: 0.589434m
;Layer height: 0.2
;Generated with Cura_SteamEngine 3.2.1
M190 S50
M104 S200
M109 S200
M82 ;absolute extrusion mode
G28 ;Home
G1 Z15.0 F6000 ;Move the platform down 15mm
G92 E0 ; Prime the extruder
G1 F200 E8 ; Extrude
G92 E0
G90 ; Set to absolute positioning
;LAYER_COUNT:15
;LAYER:0
M107
G0 F1500 X59.966 Y79.046 Z0.28
;TYPE:SKIRT
G1 F600 X60.611 Y78.609 E0.03429

[FormerLurker]

Move G90 right above this command:

G28 ;Home

There are several commands after the home command that seem to be causing problems:

2018-03-26 21:53:47,058 Sent to printer: Command Type:None, gcode:G28, cmd: G28, tags: set(['source:file', 'fileline:5', 'filepos:177'])2018-03-26 21:53:47,059 Position - Unable to update the X/Y/Z axis position, the axis mode (relative/absolute) has not been explicitly set via G90/G91.

It's obvious that this part of Octolapse needs to be more fault tolerant, but for now either move G90 above the home command or set XYZ axis to absolute. I'll create an issue when I figure out what needs to be done. Octolapse should be able to pick back up once it discovers the current position.

Thanks for hanging in there and helping me debug Octolapse!

On Mon, Mar 26, 2018 at 6:43 PM, Stavros Korokithakis < notifications@github.com> wrote:

Start of my Gcode file:

;FLAVOR:Marlin ;TIME:795 ;Filament used: 0.589434m ;Layer height: 0.2 ;Generated with Cura_SteamEngine 3.2.1 M190 S50 M104 S200 M109 S200 M82 ;absolute extrusion mode G28 ;Home G1 Z15.0 F6000 ;Move the platform down 15mm G92 E0 ; Prime the extruder G1 F200 E8 ; Extrude G92 E0 G90 ; Set to absolute positioning ;LAYER_COUNT:15 ;LAYER:0 M107 G0 F1500 X59.966 Y79.046 Z0.28 ;TYPE:SKIRT G1 F600 X60.611 Y78.609 E0.03429

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376347659, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuFWzy00fhPIw_Fbi0h6RdX6Yt_Pwks5tiX0cgaJpZM4S6bht .

[skorokithakis]

Oh no problem, I'm printing some stuff anyway, and if I can help FOSS at the same time, everybody wins! Will report back shortly!

[skorokithakis]

No, nothing. I set the G90 to the top of the file, but Octolapse still didn't detect anything :/

[skorokithakis]

2018-03-26 22:30:04,265 Queuing Command: Command Type:temperature, gcode:M105, cmd: M105, tags: set(['trigger:comm.handle_timeout'])
2018-03-26 22:30:04,271 Sent to printer: Command Type:None, gcode:M82, cmd: M82, tags: set(['filepos:167', 'source:file', 'fileline:4'])
2018-03-26 22:30:36,044 Queuing Command: Command Type:temperature, gcode:M105, cmd: M105, tags: set(['trigger:comm.handle_timeout'])
2018-03-26 22:30:36,044 Extruder Changed: E:0.0, Retraction:0 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:False-True, IsRetractingStart:False-False, IsRetracting:False-False, IsPartiallyRetracted:False-False, IsRetracted:False-False, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2018-03-26 22:30:51,234 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:30:51,239 Sent to printer: Command Type:temperature, gcode:M105, cmd: M105, tags: set(['trigger:comm.handle_timeout'])
2018-03-26 22:30:51,442 Queuing Command: Command Type:None, gcode:M117, cmd: M117 [          ]   0%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-26 22:30:51,445 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:30:51,447 Queuing Command: Command Type:None, gcode:G90, cmd: G90, tags: set(['filepos:201', 'fileline:5', 'source:file'])
2018-03-26 22:30:51,449 Received G90 - Switching to absolute x,y,z coordinates.
2018-03-26 22:30:51,451 Sent to printer: Command Type:None, gcode:M117, cmd: M117 [          ]   0%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-26 22:30:51,457 Queuing Command: Command Type:None, gcode:G28, cmd: G28, tags: set(['filepos:211', 'source:file', 'fileline:6'])
2018-03-26 22:30:51,459 Received G28 -
2018-03-26 22:30:51,461 Sent to printer: Command Type:None, gcode:G90, cmd: G90, tags: set(['filepos:201', 'fileline:5', 'source:file'])
2018-03-26 22:30:51,464 Printer event received:Home.
2018-03-26 22:30:51,464 homing to payload:Home.
2018-03-26 22:30:51,469 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['filepos:255', 'source:file', 'fileline:7'])
2018-03-26 22:30:51,470 Sent to printer: Command Type:None, gcode:G28, cmd: G28, tags: set(['filepos:211', 'source:file', 'fileline:6'])
2018-03-26 22:30:51,472 Received Linear Move
2018-03-26 22:30:51,474 Position Change - G1 Z15.0 F6000 - Absolute Move From(X:None,Y:None,Z:None,E:0) - To(X:None,Y:None,Z:15.0,E:0)
2018-03-26 22:30:51,475 A position altering command has been detected.  Fetching and updating position.  Position Command: G1 Z15.0 F6000
2018-03-26 22:30:51,476 Octolapse is requesting a position.
2018-03-26 22:30:51,479 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 22:30:51,481 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 22:30:51,556 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 22:30:51,557 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 22:30:52,783 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:30:52,786 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:30:57,783 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:31:02,786 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:31:07,787 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:31:12,789 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:31:17,791 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:31:20,712 Printer event received:PositionUpdate.
2018-03-26 22:31:20,718 Printer event received:PositionUpdate.
2018-03-26 22:31:20,719 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 22:31:20,756 Sending saved command - G1 Z15.0 F6000.
2018-03-26 22:31:20,760 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 22:31:20,762 Received Linear Move
2018-03-26 22:31:20,763 Position Change - G1 Z15.0 F6000 - Absolute Move From(X:0.0,Y:0.0,Z:0.0,E:0.0) - To(X:0.0,Y:0.0,Z:15.0,E:0.0)
2018-03-26 22:31:20,763 Position Acquired
2018-03-26 22:31:20,764 Queuing Command: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:8', 'filepos:283', 'source:file'])
2018-03-26 22:31:20,765 Received G92 - Set Position.  Command:{0}, XOffset:{1}, YOffset:0, ZOffset:0, EOffset:0.0
2018-03-26 22:31:20,766 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 22:31:20,767 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 22:31:20,767 Printer event received:ZChange.
2018-03-26 22:31:20,768 Sent to printer: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:8', 'filepos:283', 'source:file'])
2018-03-26 22:31:20,774 Queuing Command: Command Type:None, gcode:G1, cmd: G1 F200 E8, tags: set(['fileline:9', 'source:file', 'filepos:304'])
2018-03-26 22:31:20,776 Received Linear Move
2018-03-26 22:31:20,777 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 22:31:20,779 Position Change - G1 F200 E8 - Absolute Move From(X:0.0,Y:0.0,Z:15.0,E:0.0) - To(X:0.0,Y:0.0,Z:15.0,E:0.0)
2018-03-26 22:31:20,782 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 22:31:20,783 Sent to printer: Command Type:None, gcode:G1, cmd: G1 F200 E8, tags: set(['fileline:9', 'source:file', 'filepos:304'])
2018-03-26 22:31:20,789 Queuing Command: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:10', 'filepos:311', 'source:file'])
2018-03-26 22:31:20,790 Received G92 - Set Position.  Command:{0}, XOffset:{1}, YOffset:0, ZOffset:0, EOffset:0.0
2018-03-26 22:31:20,791 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 22:31:20,792 Sent to printer: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:10', 'filepos:311', 'source:file'])
2018-03-26 22:31:20,792 Queuing Command: Command Type:None, gcode:M107, cmd: M107, tags: set(['source:file', 'fileline:11', 'filepos:341'])
2018-03-26 22:31:20,793 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 22:31:20,794 Sent to printer: Command Type:None, gcode:M107, cmd: M107, tags: set(['source:file', 'fileline:11', 'filepos:341'])
2018-03-26 22:31:20,804 Queuing Command: Command Type:None, gcode:G0, cmd: G0 F1500 X63.526 Y79.046 Z0.28, tags: set(['fileline:12', 'source:file', 'filepos:372'])
2018-03-26 22:31:20,807 Received Rapid Linear Move
2018-03-26 22:31:20,810 Position Change - G0 F1500 X63.526 Y79.046 Z0.28 - Absolute Move From(X:0.0,Y:0.0,Z:15.0,E:0.0) - To(X:63.526,Y:79.046,Z:0.28,E:0.0)
2018-03-26 22:31:20,812 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 22:31:20,816 Queuing Command: Command Type:None, gcode:G1, cmd: G1 F600 X64.171 Y78.609 E0.03078, tags: set(['fileline:13', 'source:file', 'filepos:417'])
2018-03-26 22:31:20,817 Received Linear Move
2018-03-26 22:31:20,820 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative).
2018-03-26 22:31:20,823 Position Change - G1 F600 X64.171 Y78.609 E0.03078 - Absolute Move From(X:63.526,Y:79.046,Z:0.28,E:0.0) - To(X:64.171,Y:78.609,Z:0.28,E:0.0)

[FormerLurker]

Can you post the gcode, log and the settings again (Déjà vu, I know)? I'll run a test print as soon as I get it.

On Mon, Mar 26, 2018 at 7:11 PM, Stavros Korokithakis < notifications@github.com> wrote:

No, nothing. I set the G90 to the top of the file, but Octolapse still didn't detect anything :/

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376352671, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuNYQkCzVWllqczniW9y51vcL6e6pks5tiYOugaJpZM4S6bht .

[skorokithakis]

There's something odd going on, because I sliced the file again and now it's working. I think there may have been some problem with Octoprint not reading the file from disk again because I reprinted it :/

I'll print a few more and let you know if either problem happens again, thanks!

[FormerLurker]

It is definitely troubling. Ill get another pi so I can do some initial install testing and see if I can reproduce the problem. Apparently deleting the plugin is not enough.

On Mon, Mar 26, 2018, 7:24 PM Stavros Korokithakis notifications@github.com wrote:

There's something odd going on, because I sliced the file again and now it's working. I think there may have been some problem with Octoprint not reading the file from disk again because I reprinted it :/

I'll print a few more and let you know if either problem happens again, thanks!

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376354862, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuGg87kVSjMohU7t5hfFfll12EZyTks5tiYangaJpZM4S6bht .

[skorokithakis]

You need to make sure you delete the .egg-info dirs and clean the .pyc files as well. Am I mistaken, or does my log above indeed show that the G90 command was correctly sent before everything else, and that there's a bug when considering absolute/relative positioning?

What could have changed the positioning? Which commands?

[FormerLurker]

I will try to delete those directories. The log is confusing, but could be due to the settings not being copied correctly into the timelapse class. I make copies of the settings when a timelapse is running so that it is unaffected by settings changes (except for debug settings, but that was intentional).

Can you post the gcode file that failed, or at least the first few layers? I'd like to run it through the debugger and see what heppens.

[skorokithakis]

Unfortunately I'm not sure whether what Octoprint was printing was what I thought it was printing, because I think it kept the file open while I replaced it, so it was printing an old file. I don't have a backup of the failing file, I'm afraid.

[skorokithakis]

Ah, here, it happened again with this one: https://www.eternum.io/ipfs/QmTChvJJDZirPDZuViTPFz4EswvS3ec4FrZQRwWRcyyWpH

[skorokithakis]

Start of the log:

2018-03-26 23:15:38,046 Print Start Detected.  Command: M110 N0, Tags:set(['trigger:comm.start_print', 'trigger:comm.reset_line_numbers'])
2018-03-26 23:15:38,048 Print Start Detected.  Command: M190 S50, Tags:set(['trigger:comm.start_print', 'source:file', 'filepos:118', 'fileline:1', 'trigger:printer.start_print', 'api:job', 'source:api'])
2018-03-26 23:15:38,063 Print start detected, attempting to start timelapse.
2018-03-26 23:15:38,086 Printer event received:PrintStarted.
2018-03-26 23:15:38,195 Creating Layer Trigger - TriggerHeight:0.0 (none = layer change), RequiresZHop:False
2018-03-26 23:15:38,196 Extruder Triggers - OnExtrudingStart:True, OnExtruding:True, OnPrimed:True, OnRetractingStart:None OnRetracting:None, OnPartiallyRetracted:False, OnRetracted:True, ONDetractingStart:False, OnDetracting:False, OnDetracted:False
2018-03-26 23:15:38,201 Print Started - Timelapse Started.
2018-03-26 23:15:38,203 Queuing Command: Command Type:None, gcode:G90, cmd: G90, tags: set(['filepos:201', 'fileline:5', 'source:file'])
2018-03-26 23:15:38,206 Received G90 - Switching to absolute x,y,z coordinates.
2018-03-26 23:15:38,207 Sent to printer: Command Type:None, gcode:M82, cmd: M82, tags: set(['filepos:167', 'source:file', 'fileline:4'])
2018-03-26 23:15:38,311 Queuing Command: Command Type:None, gcode:M117, cmd: M117 [          ]   0%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-26 23:15:38,312 Extruder Changed: E:0.0, Retraction:0 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:False-True, IsRetractingStart:False-False, IsRetracting:False-False, IsPartiallyRetracted:False-False, IsRetracted:False-False, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2018-03-26 23:15:38,314 Sent to printer: Command Type:None, gcode:G90, cmd: G90, tags: set(['filepos:201', 'fileline:5', 'source:file'])
2018-03-26 23:15:38,326 Queuing Command: Command Type:None, gcode:G28, cmd: G28, tags: set(['filepos:211', 'source:file', 'fileline:6'])
2018-03-26 23:15:38,330 Received G28 - 
2018-03-26 23:15:38,331 Sent to printer: Command Type:None, gcode:M117, cmd: M117 [          ]   0%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-26 23:15:38,331 Printer event received:Home.
2018-03-26 23:15:38,331 homing to payload:Home.
2018-03-26 23:15:38,344 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['filepos:255', 'source:file', 'fileline:7'])
2018-03-26 23:15:38,345 Received Linear Move
2018-03-26 23:15:38,346 Position Change - G1 Z15.0 F6000 - Absolute Move From(X:None,Y:None,Z:None,E:0) - To(X:None,Y:None,Z:15.0,E:0) 
2018-03-26 23:15:38,350 Sent to printer: Command Type:None, gcode:G28, cmd: G28, tags: set(['filepos:211', 'source:file', 'fileline:6'])
2018-03-26 23:15:38,350 A position altering command has been detected.  Fetching and updating position.  Position Command: G1 Z15.0 F6000
2018-03-26 23:15:38,351 Octolapse is requesting a position.
2018-03-26 23:15:38,352 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 23:15:38,353 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 23:15:38,438 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 23:15:38,535 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 23:15:38,691 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:15:43,693 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:15:48,694 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:15:53,696 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:15:58,697 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:16:03,699 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:16:07,616 Printer event received:PositionUpdate.
2018-03-26 23:16:07,621 Sent to printer: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-26 23:16:07,621 Printer event received:PositionUpdate.
2018-03-26 23:16:07,623 Sending saved command - G1 Z15.0 F6000.
2018-03-26 23:16:07,627 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 23:16:07,628 Received Linear Move
2018-03-26 23:16:07,630 Position Change - G1 Z15.0 F6000 - Absolute Move From(X:0.0,Y:0.0,Z:0.0,E:0.0) - To(X:0.0,Y:0.0,Z:15.0,E:0.0) 
2018-03-26 23:16:07,630 Position Acquired
2018-03-26 23:16:07,631 Queuing Command: Command Type:None, gcode:G92, cmd: G92 E0, tags: set(['fileline:8', 'filepos:283', 'source:file'])
2018-03-26 23:16:07,631 Received G92 - Set Position.  Command:{0}, XOffset:{1}, YOffset:0, ZOffset:0, EOffset:0.0
2018-03-26 23:16:07,631 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True
2018-03-26 23:16:07,633 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z15.0 F6000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-26 23:16:07,634 Printer event received:ZChange.
2018-03-26 23:16:07,639 Queuing Command: Command Type:None, gcode:G1, cmd: G1 F200 E8, tags: set(['fileline:9', 'source:file', 'filepos:304'])
2018-03-26 23:16:07,642 Received Linear Move
2018-03-26 23:16:07,643 Position - Unable to update the extruder position, the extruder mode (relative/absolute) has been selected (absolute/relative). 
2018-03-26 23:16:07,643 Position Change - G1 F200 E8 - Absolute Move From(X:0.0,Y:0.0,Z:15.0,E:0.0) - To(X:0.0,Y:0.0,Z:15.0,E:0.0) 
2018-03-26 23:16:07,647 Triggered E:0.0, Retraction:0 IsExtruding:False-None, IsExtrudingStart:False-None, IsPrimed:True-True, IsRetracting:False-None, IsRetracted:False-None, IsDetracting:False-None, IsTriggered:True

[FormerLurker]

OK, I am able to reproduce it now, which means I'll be able to fix it pretty quickly I think! THANKS!

[skorokithakis]

Fantastic! Let me know when I can update and I'll test for the issue this thread is actually about :P

[FormerLurker]

FYI, this will take some time to fix unfortunately. Octolapse is not getting all of the gcodes from the very beginning of the file from Octoprint. This has been a problem in the past, but I thought it was fixed. I'm trying some different things, but might have to dig into the OctoPrint code to figure out what's going on.

In the meanwhile make your start gcode around the home command look like this:

M82 ;absolute extrusion mode G90 ; Set to absolute positioning G28 ;Home M82 ;absolute extrusion mode G90 ; Set to absolute positioning

I'm 99% sure that will work for now. Hopefully I'll have the real fix soon.

[skorokithakis]

Hmm, why is it not getting the codes? Maybe I can help.

[skorokithakis]

Oh, also, the pausing problem happened again. Log just when it happened:

2018-03-27 00:09:36,891 A snapshot is triggering
2018-03-27 00:09:36,893 About to take a snapshot.  Triggering Command: G0 F9000 X80.847 Y86
2018-03-27 00:09:36,898 Snapshot Gcode - SnapshotCommandIndex:5, EndIndex13, Gcode:
2018-03-27 00:09:36,899     M83
2018-03-27 00:09:36,904     G1 E-0.60000 F2400
2018-03-27 00:09:36,905     G91
2018-03-27 00:09:36,905     G1 Z0.500 F9000
2018-03-27 00:09:36,906     G90
2018-03-27 00:09:36,906     G1 X100.000 Y150.000
2018-03-27 00:09:36,906     G1 X80.847 Y85.859
2018-03-27 00:09:36,907     G91
2018-03-27 00:09:36,907     G1 Z-0.500
2018-03-27 00:09:36,907     G1 E0.60000 F2400
2018-03-27 00:09:36,908     G90
2018-03-27 00:09:36,908     M82
2018-03-27 00:09:36,908     G1 F5400
2018-03-27 00:09:36,909     G0 F9000 X80.847 Y86
2018-03-27 00:09:36,909 Snapshot Position: (x:100.000000,y:150.000000)
2018-03-27 00:09:36,910 Return Position: (x:80.847000,y:85.859000)
2018-03-27 00:09:36,910 Sending snapshot start gcode and snapshot commands.
2018-03-27 00:09:36,910 Octolapse is requesting a position.
2018-03-27 00:09:36,910 Queuing Command: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,911 Received M83 - Switching Extruder to Relative Coordinates
2018-03-27 00:09:36,911 Extruder Changed: E:0.0, Retraction:0 IsExtruding:True-False, IsExtrudingStart:True-False, IsPrimed:False-True, IsRetractingStart:False-False, IsRetracting:False-False, IsPartiallyRetracted:False-False, IsRetracted:False-False, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2018-03-27 00:09:36,912 Position - Zhop:0.5
2018-03-27 00:09:36,912 Queuing Command: Command Type:None, gcode:G1, cmd: G1 E-0.60000 F2400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,912 Received Linear Move
2018-03-27 00:09:36,914 Sent to printer: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,917 Position Change - G1 E-0.60000 F2400 - Absolute Move From(X:80.847,Y:85.859,Z:1.58,E:816.21266) - To(X:80.847,Y:85.859,Z:1.58,E:815.61266) 
2018-03-27 00:09:36,924 Extruder Changed: E:-0.6, Retraction:0.6 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:True-False, IsRetractingStart:False-True, IsRetracting:False-True, IsPartiallyRetracted:False-False, IsRetracted:False-True, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2018-03-27 00:09:36,932 Position - Zhop:0.5
2018-03-27 00:09:36,933 Queuing Command: Command Type:None, gcode:G91, cmd: G91, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,933 Received G91 - Switching to relative x,y,z coordinates
2018-03-27 00:09:36,934 Extruder Changed: E:0.0, Retraction:0.6 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:False-False, IsRetractingStart:True-False, IsRetracting:True-False, IsPartiallyRetracted:False-False, IsRetracted:True-True, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False
2018-03-27 00:09:36,934 Position - Zhop:0.5
2018-03-27 00:09:36,935 Sent to printer: Command Type:None, gcode:G1, cmd: G1 E-0.60000 F2400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,935 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z0.500 F9000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,935 Received Linear Move
2018-03-27 00:09:36,936 Position Change - G1 Z0.500 F9000 - Relative Move From(X:80.847,Y:85.859,Z:1.58,E:815.61266) - To(X:80.847,Y:85.859,Z:2.08,E:815.61266) 
2018-03-27 00:09:36,936 Queuing Command: Command Type:None, gcode:G90, cmd: G90, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,936 Received G90 - Switching to absolute x,y,z coordinates.
2018-03-27 00:09:36,937 Sent to printer: Command Type:None, gcode:G91, cmd: G91, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,937 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X100.000 Y150.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,937 Received Linear Move
2018-03-27 00:09:36,938 Position Change - G1 X100.000 Y150.000 - Absolute Move From(X:80.847,Y:85.859,Z:2.08,E:815.61266) - To(X:100.0,Y:150.0,Z:2.08,E:815.61266) 
2018-03-27 00:09:36,938 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,938 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,939 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z0.500 F9000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,939 Printer event received:ZChange.
2018-03-27 00:09:36,940 Sent to printer: Command Type:None, gcode:G90, cmd: G90, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:36,940 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X100.000 Y150.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:37,237 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:37,924 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 00:09:39,729 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 00:09:44,731 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 00:09:49,732 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 00:09:54,734 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])

[FormerLurker]

It has something to do with how octoprint sends asynchronous events. Check out timelapse.py, and search for 'queuing' to find the GCode queuing fn. The top dozen or so lines here start the timelapse. While it is starting, some codes must never be sent to the plugin. Look through the log for linenumbers. You see 1, bit a few lines es are skipped.

On Mar 26, 2018 8:37 PM, "Stavros Korokithakis" notifications@github.com wrote:

Hmm, why is it not getting the codes? Maybe I can help.

— You are receiving this because you were assigned.

Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376366777, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuPaCqP1TxlnPcPPNaP8vxdR6elzkks5tiZfFgaJpZM4S6bht .

[FormerLurker]

Is it possible that the skirt is at a slightly different layer height than the first layer of the part? I haven't had a chance to look at that issue yet.

On Mon, Mar 26, 2018, 8:39 PM Stavros Korokithakis notifications@github.com wrote:

Oh, also, the pausing problem happened again. Log just when it happened:

2018-03-27 00:09:36,891 A snapshot is triggering 2018-03-27 00:09:36,893 About to take a snapshot. Triggering Command: G0 F9000 X80.847 Y86 2018-03-27 00:09:36,898 Snapshot Gcode - SnapshotCommandIndex:5, EndIndex13, Gcode: 2018-03-27 00:09:36,899 M83 2018-03-27 00:09:36,904 G1 E-0.60000 F2400 2018-03-27 00:09:36,905 G91 2018-03-27 00:09:36,905 G1 Z0.500 F9000 2018-03-27 00:09:36,906 G90 2018-03-27 00:09:36,906 G1 X100.000 Y150.000 2018-03-27 00:09:36,906 G1 X80.847 Y85.859 2018-03-27 00:09:36,907 G91 2018-03-27 00:09:36,907 G1 Z-0.500 2018-03-27 00:09:36,907 G1 E0.60000 F2400 2018-03-27 00:09:36,908 G90 2018-03-27 00:09:36,908 M82 2018-03-27 00:09:36,908 G1 F5400 2018-03-27 00:09:36,909 G0 F9000 X80.847 Y86 2018-03-27 00:09:36,909 Snapshot Position: (x:100.000000,y:150.000000) 2018-03-27 00:09:36,910 Return Position: (x:80.847000,y:85.859000) 2018-03-27 00:09:36,910 Sending snapshot start gcode and snapshot commands. 2018-03-27 00:09:36,910 Octolapse is requesting a position. 2018-03-27 00:09:36,910 Queuing Command: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,911 Received M83 - Switching Extruder to Relative Coordinates 2018-03-27 00:09:36,911 Extruder Changed: E:0.0, Retraction:0 IsExtruding:True-False, IsExtrudingStart:True-False, IsPrimed:False-True, IsRetractingStart:False-False, IsRetracting:False-False, IsPartiallyRetracted:False-False, IsRetracted:False-False, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False 2018-03-27 00:09:36,912 Position - Zhop:0.5 2018-03-27 00:09:36,912 Queuing Command: Command Type:None, gcode:G1, cmd: G1 E-0.60000 F2400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,912 Received Linear Move 2018-03-27 00:09:36,914 Sent to printer: Command Type:None, gcode:M83, cmd: M83, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,917 Position Change - G1 E-0.60000 F2400 - Absolute Move From(X:80.847,Y:85.859,Z:1.58,E:816.21266) - To(X:80.847,Y:85.859,Z:1.58,E:815.61266) 2018-03-27 00:09:36,924 Extruder Changed: E:-0.6, Retraction:0.6 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:True-False, IsRetractingStart:False-True, IsRetracting:False-True, IsPartiallyRetracted:False-False, IsRetracted:False-True, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False 2018-03-27 00:09:36,932 Position - Zhop:0.5 2018-03-27 00:09:36,933 Queuing Command: Command Type:None, gcode:G91, cmd: G91, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,933 Received G91 - Switching to relative x,y,z coordinates 2018-03-27 00:09:36,934 Extruder Changed: E:0.0, Retraction:0.6 IsExtruding:False-False, IsExtrudingStart:False-False, IsPrimed:False-False, IsRetractingStart:True-False, IsRetracting:True-False, IsPartiallyRetracted:False-False, IsRetracted:True-True, IsDetractingStart:False-False, IsDetracting:False-False, IsDetracted:False-False 2018-03-27 00:09:36,934 Position - Zhop:0.5 2018-03-27 00:09:36,935 Sent to printer: Command Type:None, gcode:G1, cmd: G1 E-0.60000 F2400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,935 Queuing Command: Command Type:None, gcode:G1, cmd: G1 Z0.500 F9000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,935 Received Linear Move 2018-03-27 00:09:36,936 Position Change - G1 Z0.500 F9000 - Relative Move From(X:80.847,Y:85.859,Z:1.58,E:815.61266) - To(X:80.847,Y:85.859,Z:2.08,E:815.61266) 2018-03-27 00:09:36,936 Queuing Command: Command Type:None, gcode:G90, cmd: G90, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,936 Received G90 - Switching to absolute x,y,z coordinates. 2018-03-27 00:09:36,937 Sent to printer: Command Type:None, gcode:G91, cmd: G91, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,937 Queuing Command: Command Type:None, gcode:G1, cmd: G1 X100.000 Y150.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,937 Received Linear Move 2018-03-27 00:09:36,938 Position Change - G1 X100.000 Y150.000 - Absolute Move From(X:80.847,Y:85.859,Z:2.08,E:815.61266) - To(X:100.0,Y:150.0,Z:2.08,E:815.61266) 2018-03-27 00:09:36,938 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,938 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,939 Sent to printer: Command Type:None, gcode:G1, cmd: G1 Z0.500 F9000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,939 Printer event received:ZChange. 2018-03-27 00:09:36,940 Sent to printer: Command Type:None, gcode:G90, cmd: G90, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:36,940 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X100.000 Y150.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:37,237 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:37,924 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin']) 2018-03-27 00:09:39,729 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature']) 2018-03-27 00:09:44,731 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature']) 2018-03-27 00:09:49,732 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature']) 2018-03-27 00:09:54,734 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376367083, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuH_KShx5qbizNmSAkO84cX-HKKj8ks5tiZg0gaJpZM4S6bht .

[skorokithakis]

I don't think so... Would that matter? It pauses much, much later, sometimes more than halfway into the print.

[FormerLurker]

Geesh, I'm sorry, I thought we were talking about the double snapshot issue. It has been a long couple of days :)

On Mon, Mar 26, 2018, 9:05 PM Stavros Korokithakis notifications@github.com wrote:

I don't think so... Would that matter? It pauses much, much later, sometimes more than halfway into the print.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376371633, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuPmF5e0oO8VzqMjmHV9tO_aIelJYks5tiZ5-gaJpZM4S6bht .

[skorokithakis]

Oh! Hmm, I don't think so, that happens before it starts printing the skirt. It hasn't done it since, have you managed to reproduce it with my gcode?

[FormerLurker]

I've been looking at the start up issue (missed m83). I should create another issue for that, I keep getting confused. Do you have the terminal log for the lockup? I bet we are missing an ok. I probably need to change the timeouts for the position requests and retry the request, or maybe fake an ok.

If we aren't missing an ok, the solution is less clear, but maybe cleaner.

On Mon, Mar 26, 2018, 9:07 PM Brad Hochgesang hochgebe@gmail.com wrote:

Geesh, I'm sorry, I thought we were talking about the double snapshot issue. It has been a long couple of days :)

On Mon, Mar 26, 2018, 9:05 PM Stavros Korokithakis < notifications@github.com> wrote:

I don't think so... Would that matter? It pauses much, much later, sometimes more than halfway into the print.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376371633, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuPmF5e0oO8VzqMjmHV9tO_aIelJYks5tiZ5-gaJpZM4S6bht .

[skorokithakis]

Hmm, what do you mean by terminal log? I pasted the Octolapse log higher up from when it happened, is the terminal log different?

[FormerLurker]

From the terminal tab in octoprint (I should log these optionally myself). It can be in the serial.log file too, but only if it is enabled.

On Mon, Mar 26, 2018, 9:17 PM Stavros Korokithakis notifications@github.com wrote:

Hmm, what do you mean by terminal log? I pasted the Octolapse log higher up from when it happened, is the terminal log different?

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376373534, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuIV9ncrECbvXOSTRHJy7GfM14Iumks5tiaEagaJpZM4S6bht .

[skorokithakis]

Oh, I'm afraid not, I've already started printing something else :/ I'll copy that log the next time this happens.

[FormerLurker]

Are these pauses ever total lockups, or does the print eventually continue every time. This could me a known issue with m400 m114 combos. If it seems to lock up, give it a few minutes and see if it ever continues. If it doesn't, go to the terminal tab, click advanced, and click force ok. Then give me logs! I'm craving some of that logfile action.

I'm thinking about ways to avoid the m114 entirely. I may ask Gina (octoprint) if she can help figure out what is happening

On Mon, Mar 26, 2018, 9:20 PM Stavros Korokithakis notifications@github.com wrote:

Oh, I'm afraid not, I've already started printing something else :/ I'll copy that log the next time this happens.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/FormerLurker/Octolapse/issues/100#issuecomment-376374069, or mute the thread https://github.com/notifications/unsubscribe-auth/Af0UuLsYggQLpUCFM05xxDXayqQKUid-ks5tiaHRgaJpZM4S6bht .

[skorokithakis]

No, it never continues, it just stays there. This happened the first time, with the cat, I woke up hours later and it had just melted onto the hotend.

[skorokithakis]

I'll try the "force ok" method the next time it freezes!

[skorokithakis]

Nope, it still froze. Force acknowledgement did nothing :/

Log:

2018-03-27 16:36:00,375 Position Change - G1 X100.000 Y150.000 - Absolute Move From(X:104.239,Y:104.239,Z:24.98,E:540.23157) - To(X:100.0,Y:150.0,Z:24.98,E:540.23157) 
2018-03-27 16:36:00,375 Sent to printer: Command Type:None, gcode:G1, cmd: G1 X100.000 Y150.000, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 16:36:00,376 Queuing Command: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 16:36:00,376 Sent to printer: Command Type:None, gcode:M400, cmd: M400, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 16:36:00,376 Queuing Command: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 16:36:00,377 Sent to printer: Command Type:None, gcode:M114, cmd: M114, tags: set(['trigger:printer.commands', 'plugin:octolapse', 'source:plugin'])
2018-03-27 16:36:00,632 Queuing Command: Command Type:None, gcode:M117, cmd: M117 [######### ]  91%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-27 16:36:00,634 Sent to printer: Command Type:None, gcode:M117, cmd: M117 [######### ]  91%, tags: set(['plugin:displayprogress', 'source:plugin', 'trigger:printer.commands'])
2018-03-27 16:36:05,104 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 16:36:10,105 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 16:36:15,107 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 16:36:20,107 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 16:36:25,109 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 16:36:30,111 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])
2018-03-27 16:36:35,114 Queuing Command: Command Type:temperature_poll, gcode:M105, cmd: M105, tags: set(['trigger:comm.poll_temperature'])

And it keeps polling.

Recv: ok 6578
Recv: ok 6579
Send: N6583 M117 [######### ]  91%*20
Recv: ok 6580
Recv: ok 6581
Recv: wait
Recv: wait
Recv: wait
Recv: wait

And then it keeps waiting.

[FormerLurker]

Can you give me more of the plugin_octolapse.log file, maybe from before the previous snapshot was started?

You aren't printing with linear advance enabled by chance are you? Just curious because it causes a similar issue on the Mk2.

[skorokithakis]

Hmm I'll try, but basically if I do anything else with the printer I lose my spot and can't ever find it again. If not, I'll try to reproduce it again.

What's linear advance?

[FormerLurker]

Linear advance is a feature that responds to the nonlinear filament flow and tries to keep it constant despite changing pressures during extrusion. In some cases (prusa MK2/Mk2s) It overloads the board on the printer causing serial communication issues. Can you remind me what printer/firmware version are you running? I'll do some research.

In the meanwhile, maybe you can turn on serial logging so I can get some more detailed information about the lockup? It will be a big file, but you should be able to post the entire thing. Also, just post the entire plugin_octoprint.log somewhere too next time it happens and I'll review them both.

[skorokithakis]

I'm using a Wanhao i3, with the stock firmware it comes with. Sure, I'll enable serial debug and report back!

[FormerLurker]

I saw some people saying that Octoprint runs better on the Wanhao if the baud rate is set to 250000. Can you go to connection panel and see if it is connecting at 250000 baud?

[skorokithakis]

Yep, it is. I think this is probably a race condition, I've been printing fine for years and this only happens after taking the snapshot, hmm.