M114 error with Prusa Mini+

[hasko]

The M114 test fails in Prusa Mini+ with the latest (4.3.1) firmware, OctoPi 0.18.0, OctoPrint 1.5.3, OctoLapse 0.4.1 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.

Originally posted by @hasko in #459 (comment)

[hasko]

After staring at timelapse.py for a while I saw that in line 117 the _position_signal is set:

    self._position_signal.set()

I wonder why because at this time no position request should have been send. Maybe that introduces a race condition. In lines 277+ the flag is cleared but as this is asynchronous, couldn't it be that it interferes with on_position_received?

I didn't look at the whole code, so I might be missing something. Also, I am printing right now, so I can't test for the next 13 hours or so.

[FormerLurker]

That set doesn't cause any issues as it's cleared in get_position_async on line 277 here:

        if self._position_signal.is_set():
            self._position_signal.clear()
            if tags is None:
                tags = set()

The question is why is it taking so long to get a position request back. The request was sent an no position was delivered in 1 minute (from 12:23:26 to 12:24:26).

Why don't you clear the log (see the logging profile, edit it, and click clear all logs) and produce a full log of the startup. I want to see when the position is returned. It might also be a good idea to see the serial log of this (from OctoPrint Settings -> Logs), so maybe enable that logger before you start.

Also, do you have any other gcode scripts that run, like maybe in Octoprint or some other plugin?

Finally, what other plugins are active? This could be a conflict. I just got a video today of someone doing a timelapse on a mini, but maybe it really is the most recent firmware? Have you upgraded recently, and was it working before?

[jbienz]

Hey @hasko, just making sure you saw my comment here. I fought with this for over an hour, but when I power cycled my mini+ it went away. Seems very strange. Not sure if it's a firmware issue or if something got the printer in a bad state. Wondering if you're able to get working again with the reboot.

[FormerLurker]

Very odd. The only reason m114 should be delayed is that either an m400 was sent, or the printer is busy (warm up and wait, wait for user input, etc...)

[hasko]

@jbienz yes, I saw that comment, thank you. Unfortunately, power cycling didn't fix it for me. The issue is repeatable.

@FormerLurker I will send the logs tomorrow when my current print is done. In terms of other plugins I have only BedVisualizer 1.0.1 (don't think it makes a difference) and OctoRant 1.2.3 (send Discord messages, slight chance it interferes because it notifies on print start; I will try to disable it).

I haven't tried OctoLapse with older firmware.

You are right about the 1 minute difference, that's weird. I hadn't noticed because it's the same second almost the same microsecond, in fact 1 minute and 30 milliseconds. Very odd. Almost as if there was another timeout involved. How else could it be so precisely a minute?

[FormerLurker]

thanks @hasko. Looking forward to seeing the logs.

[hasko]

@FormerLurker here are the logs:

• serial.log
• octolapse

Fun fact: I've increased the short_timeout value in timelapse.py to 61 seconds and now the position information arrives promptly after 61 seconds plus 30 milliseconds. This cannot be a coincidence. It really seems that the incoming printer response is buffered until the timeout has expired, and then it is readily available. But of course, by then it is too late.

Is it possible that the wait(timeout) blocks also the thread that is receiving responses from the printer? Should this happen in a separate thread?

[FormerLurker]

So, I think the issue is that the new buddy firmware seems to respond with an OK to M114, but isn't sending the position until after it sees another command (M108 in the case of your log). Try this:

Go to the OctoPrint terminal and send an M114, then record the response. Then send M108 and record the response. Paste in all the results in here please.

[FormerLurker]

Possible related issue on the Buddy Repository?

[jbienz]

Watching this discussion with interest. FYI, I also have BedVisualizer but do not have OctoRant. I've only experienced this issue once and I completed another 8.5 hour print last night with successful Octolapse.

In case it helps with troubleshooting, I'm running:

Firmware: 4.3.1+2759
Bootloader: 1.0.0
Buddy Board: 1.0.5

[hasko]

So, I think the issue is that the new buddy firmware seems to respond with an OK to M114, but isn't sending the position until after it sees another command (M108 in the case of your log). Try this:

Go to the OctoPrint terminal and send an M114, then record the response. Then send M108 and record the response. Paste in all the results in here please.

I tried but it seems that the firmware responds immediately to an M114, see below. I tried this from the OctoPrint terminal when the printer was idle.

2021-03-20 10:09:48,285 - Enabling serial logging
2021-03-20 10:09:48,323 - Recv:  T:14.64 /0.00 B:14.90 /0.00 A:25.83 /0.00 @:0 B@:0
[...]
2021-03-20 10:10:20,310 - Recv:  T:14.91 /0.00 B:14.84 /0.00 A:25.47 /0.00 @:0 B@:0
2021-03-20 10:10:21,085 - Send: M114
2021-03-20 10:10:21,097 - Recv: X:180.40 Y:-3.00 Z:0.00 E:0.00 Count X:18040 Y:-300 Z:0
2021-03-20 10:10:21,099 - Recv: ok
2021-03-20 10:10:22,309 - Recv:  T:14.87 /0.00 B:14.95 /0.00 A:26.22 /0.00 @:0 B@:0
2021-03-20 10:10:24,309 - Recv:  T:14.60 /0.00 B:14.84 /0.00 A:25.55 /0.00 @:0 B@:0
2021-03-20 10:10:26,310 - Recv:  T:14.73 /0.00 B:14.90 /0.00 A:25.83 /0.00 @:0 B@:0
2021-03-20 10:10:28,311 - Recv:  T:14.91 /0.00 B:14.84 /0.00 A:25.83 /0.00 @:0 B@:0
2021-03-20 10:10:30,311 - Recv:  T:14.69 /0.00 B:15.04 /0.00 A:25.83 /0.00 @:0 B@:0
2021-03-20 10:10:32,312 - Recv:  T:14.91 /0.00 B:15.00 /0.00 A:25.83 /0.00 @:0 B@:0
2021-03-20 10:10:34,314 - Recv:  T:14.64 /0.00 B:14.90 /0.00 A:25.83 /0.00 @:0 B@:0
2021-03-20 10:10:35,800 - Send: M108
2021-03-20 10:10:35,814 - Recv: ok
2021-03-20 10:10:36,317 - Recv:  T:14.82 /0.00 B:14.95 /0.00 A:25.83 /0.00 @:0 B@:0

I've also tried the repeated M114/M119 sequence they suggest in the Buddy issue you've mentioned but the output looked all right; no messing up of M114 and M119 responses.

[samuelfugarino]

Anybody find a solution. I'm having the same issue. When I disable Octolapse, my Mini+ prints like it always has. When I enable Octolapse when I press print the print never starts. After several seconds I get a popup error notification saying my printer does not support the M114 command and that I should update my printer's firmware.

[FormerLurker]

I've added this to the milestones, but am really confused since I see people using Octolapse with a mini on youtube all the time. I think I need to get my hands on one to test with the debugger.