M114 Pre-Print Test Fails

[FormerLurker]

Some recent printers do not support M114, and to test for this a check was added to the Octolapse print start routine. If the M114 test doesn't pass, Octolapse shows a help toast. However, this test should not fail unless M114 isn't supported.

One user has reported M114 problems even though a seemingly valid response was given:

Send: N6 M114*33 Recv: X:220.00 Y:220.00 Z:10.00 E:-1.00 Count X:17600 Y:17600 Z:16000 Recv: ok

Send: N7 M400*32 Recv: ok

I may have to disable this test if I cannot figure out why this has failed.

[simpat1zq]

So, I tested my theory that maybe the negative value for 'e' was causing the issue, but it was not. I extruded 2mm, and the 'e' value became positive 1. I tried printing again and got this same error about m114.

Let me know if there's anything else you want me to try.

[FormerLurker]

Yes, please switch your logging profile to 'log everything'. If that profile doesn't exist (it should), click the link next to the logging profile dropdown:

Then 'Add Profile':

Finally select 'Log Everything' from the 'Profile to Import' box and save:

Now your 'logging' profile drop down should look like this:

Then, just to get a nice clean log file, click the pen next to the logging drop down to edit the profile, and click 'Clear All Logs':

I'd like to test this button anyway, and have been dreaming of clean logs ever since I added it :)

Next, try to start a print. It will fail. Then switch your logging profile back to 'Log All Errors' edit the profile and click Download Log:

You can always download it the old way, through Octoprint, if you want.

Paste the log file results to gist. Hopefully that will give me enough ammo to figure out what is going on.

[simpat1zq]

Sorry. I was already gathering that verbose log before you posted, so I didn't clear them. But there wasn't really a whole lot before this in the logs. It looks like it's timing out. In your code, I believe the timeout is set to 600. Is that 600ms? I know it shouldn't take that long, but that might be what needs adjusting.

plugin_octolapse-1.log

2020-02-25 15:17:49,418 - octolapse.gcode_position - VERBOSE - Getting current position tuple.

2020-02-25 15:17:49,418 - octolapse.gcode_position - VERBOSE - Getting previous position tuple.

2020-02-25 15:17:49,419 - octolapse.gcode_position - VERBOSE - Getting current position tuple.

2020-02-25 15:17:49,419 - octolapse.trigger - INFO - Extruder Triggers - on_extruding_start:trigger_on, on_extruding:trigger_on, on_primed:trigger_on, on_retracting_start: on_retracting:, on_partially_retracted:forbidden, on_retracted:trigger_on, ONDeretractingStart:, on_deretracting:forbidden, on_deretracted:forbidden

2020-02-25 15:17:49,419 - octolapse.trigger - INFO - Creating Timer Trigger - Seconds:30, require_zhop:False

2020-02-25 15:17:49,419 - octolapse.timelapse - INFO - Octolapse is requesting a position.

2020-02-25 15:17:49,419 - octolapse.timelapse - VERBOSE - Queuing: M114

2020-02-25 15:17:49,419 - octolapse.gcode_position - VERBOSE - Updating current position from gcode.

2020-02-25 15:17:49,420 - octolapse.timelapse - DEBUG - The position request is being sent

2020-02-25 15:17:49,420 - octolapse.timelapse - DEBUG - Sent: M114

2020-02-25 15:18:07,722 - octolapse.__init__ - VERBOSE - Printer event received:DisplayLayerProgress_progressChanged.

2020-02-25 15:18:49,420 - octolapse.timelapse - WARNING - Warning:  A timeout occurred while requesting the current position.

2020-02-25 15:18:49,421 - octolapse.__init__ - ERROR - Unable to start the timelapse.  Error Details: Your printer does not support M114, and is incompatible with Octolapse.
Traceback (most recent call last):
  File "/home/hass/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_octolapse/__init__.py", line 2737, in start_timelapse
    snapshot_plans=snapshot_plans
  File "/home/hass/OctoPrint/venv/local/lib/python2.7/site-packages/octoprint_octolapse/timelapse.py", line 227, in start_timelapse
    'm114_not_supported'
TimelapseStartException

2020-02-25 15:18:49,443 - octolapse.__init__ - VERBOSE - Printer event received:PrintCancelling.

2020-02-25 15:18:49,443 - octolapse.__init__ - INFO - Print cancelling.

2020-02-25 15:18:49,445 - octolapse.__init__ - VERBOSE - Printer event received:PrinterStateChanged.

2020-02-25 15:18:49,447 - octolapse.__init__ - VERBOSE - Printer event received:PositionUpdate.

2020-02-25 15:18:49,448 - octolapse.timelapse - VERBOSE - Sending: M108

[simpat1zq]

And this is weird too. Here's what I see in the terminal:

Changing monitoring state from "Operational" to "Starting"
Send: N2 M117 ETA: -*97
Recv: ok
Send: N3 M114*36
Changing monitoring state from "Starting" to "Cancelling"
Recv: X:220.00 Y:220.00 Z:20.00 E:1.00 Count X:17600 Y:17600 Z:32000
Recv: ok

I also tried upping that timeout in the timelapse.py file to 6000. And that didn't make any changes. It's like there's something locked up after OL puts out that M114, and it doesn't unlock until the print is marked failed by OP.

[simpat1zq]

Also, is it possible for me to roll back to dev2? I need to print some stuff and I would like to have the timelapses.

[FormerLurker]

The timeout is in seconds, and your log suggests it's not waiting. Perhaps this is a race condition since those calls are threaded. I will dig in.

Since you've been altering the code anyway, why not just delete this code in timelapse.py on line 224:

        if not self._test_position_request():
            raise TimelapseStartException(
                "Your printer does not support M114, and is incompatible with Octolapse.",
                'm114_not_supported'
            )

That should solve the issue.

[simpat1zq]

Thank you. I'll try that out.

EDIT: Removing that code worked for me. It is printing.

[FormerLurker]

I think I've figured it out, though I have no idea how it works at all, lol! The fix will be tricky. I will post when it's figured out.

[FormerLurker]

Hey, when your print is done, maybe you can try again with this build: https://github.com/FormerLurker/Octolapse/archive/devel.zip

I haven't run this on my printer yet, only the debugger. Will run a few tests tonight if possible, else tomorrow.

[simpat1zq]

How do I load that build? Will it override the existing?

[FormerLurker]

Sure, just use the plugin manager, click 'get more' and paste in that archive link. I also dealt with the other issue (vase mode is missing).

[FormerLurker]

Oh, and yes, it will overwrite the existing version. You won't lose any settings or anything like that. No need to uninstall.

[simpat1zq]

Good news. It is printing. However, I did get the following error:

Settings Load Error Octolapse was unable to load the current settings. Status: error. Error: NOT FOUND

But I am pretty sure I’ve randomly received that error before many times.

[FormerLurker]

Well, mostly good! Maybe a new issue for that settings error?

[FormerLurker]

I created issue #461 to deal with the settings issue, and will close this one for now. Thank you so much for reporting and helping me figure this out!

Closed!

[rizwansarwar]

M114 is now supported in ET4 firmware 1.1.7 (in beta at the moment).

[jbienz]

I know this issue is old and closed, but I wanted to add a note here because I was fighting with the M114 not supported error tonight on the new Prusa Mini+. I spent more than an hour disabling plugins and rebooting the Pi but nothing changed. I could actually see the log from the printer freeze up and then unfreeze. On a whim, I decided to reboot the Mini+ and everything started working again.

[hasko]

I can confirm that it occurs in Prusa Mini+ with the latest (4.3.1) firmware, OctoPi 0.18.0, OctoPrint 1.5.3 with a GCode file from PrusaSlicer with "verbose" switched on.

As you can see below, the command is displayed in the terminal as sent and received "ok" but there's a bunch of temperature messages, which I omitted, before the actual position is returned.

[...]
Changing monitoring state from "Operational" to "Starting"
[...]
Send: N15 M114*19
Recv: ok
[...]
Changing monitoring state from "Starting" to "Cancelling"
Send: N16 M108*29
Recv: X:180.40 Y:-3.00 Z:0.00 E:0.00 Count X:18040 Y:-300 Z:0
Recv: ok
Changing monitoring state from "Cancelling" to "Printing"
Send: N17 M84*41
Recv: ok
Send: N18 M104 T0 S0*24
Recv: ok
Send: N19 M140 S0*93
Recv: ok
Send: N20 M106 S0*85
Recv: ok
Changing monitoring state from "Printing" to "Operational"

Also, here is the end of the debug log:

2021-03-18 12:23:26,718 - octolapse.trigger - INFO - Creating Layer Trigger - TriggerHeight:0.0 (none = layer change), RequiresZHop:False
2021-03-18 12:23:26,718 - octolapse.timelapse - INFO - Testing M114 Support.
2021-03-18 12:23:26,719 - octolapse.timelapse - INFO - Octolapse is requesting a position.
2021-03-18 12:23:26,721 - octolapse.timelapse - DEBUG - The position request is being sent
2021-03-18 12:24:26,722 - octolapse.timelapse - WARNING - Warning:  A timeout occurred while requesting the current position.
2021-03-18 12:24:26,723 - octolapse.__init__ - ERROR - Unable to start the timelapse.  Error Details: Your printer does not support M114, and is incompatible with Octolapse.
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint_octolapse/__init__.py", line 2777, in start_timelapse
    snapshot_plans=snapshot_plans
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint_octolapse/timelapse.py", line 227, in start_timelapse
    raise TimelapseStartException(message, 'm114_not_supported')
octoprint_octolapse.timelapse.TimelapseStartException
2021-03-18 12:24:26,752 - octolapse.timelapse - INFO - Octolapse has received a position request response.
2021-03-18 12:24:26,800 - octolapse.timelapse - DEBUG - Releasing job-on-hold lock.