Octoprint: M112 is not sent immediately

[KevinOConnor]

What were you doing?

I am printing a gcode file that has a long running command (such as M109) from OctoPrint. I then type "M112" into the OctoPrinter terminal tab.

Specifically, for testing purposes, a gcode file containing:

G28
M109 S70

exhibits the problem.

What did you expect to happen?

I expected OctoPrint to immediately transmit the M112 to the printer firmware. That is, when I issued an M112 (emergency stop) gcode from the OctoPrint terminal, I expected the printer to immediately halt.

Note that if I type G28 and/or M109 S70 directly into the OctoPrint terminal tab, and then type M112 into the OctoPrint terminal tab - then OctoPrint behaves as expected and will immediately transmit the M112 to the firmware. The firmware then immediately stops the action. The problem only manifests when the long running command is sent from a gcode file that is being printed.

What happened instead?

OctoPrint waits until the current command finishes, and then transmits the M112. In the example (G28; M109) gcode file described above, if the M112 is typed into the terminal during the G28 then OctoPrint will wait until the G28 finishes (but before sending the M109). If the M112 is issued after the G28 finishes then OctoPrint waits until after the M109 completes.

Did the same happen when running OctoPrint in safe mode?

Yes.

Version of OctoPrint

OctoPrint 1.3.11rc2 running on OctoPi 0.14.0

Operating System running OctoPrint

OctoPrint 1.3.11rc2 running on OctoPi 0.14.0

Printer model & used firmware incl. version

This is with the Klipper firmware (I am the main developer of Klipper). It occurs on most recent Klipper (v0.7.0) and has been reported on a variety of actual physical printers. I do not believe this is related to the printer firmware as I've confirmed that OctoPrint is not transmitting the M112 immediately.

Browser and version of browser, operating system running browser

Firefox 65.0.2 (64-bit) on Linux. It is not believed to be related to browser.

Link to octoprint.log

octoprint.log

Link to contents of terminal tab or serial.log

serial.log

Link to contents of Javascript console in the browser

N/A

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

N/A

I have read the FAQ.

[ManuelMcLure]

This is with Marlin? Do you have EMERGENCY_PARSER enabled in your Configuration_adv,h file? If not, try enabling it and see if this makes things work correctly. I do not believe this is an Octoprint issue but rather a Marlin configuration issue.

[foosel]

I would second that question. Also please provide a serial.log that includes connecting to the printer. This might also yield some clues.

[KevinOConnor]

Thanks. This is with the Klipper firmware (https://github.com/KevinOConnor/klipper). It is not using Marlin.

Here is the second serial log (as requested).
serial2.log
(This time, I waited until after the g28 completed before typing "m112" into the terminal tab.) Just for completeness, here is the octoprint log from the above serial log:
octoprint2.log

Here is the test gcode file I am printing:
testm109.gcode.txt. Again, the procedure to reproduce is: upload this file to OctoPrint, print the file via OctoPrint, then type M112 into the OctoPrint terminal tab.

-Kevin

[foosel]

So, while Klipper doesn't report the EMERGENCY_PARSER capability (or any capability for that matter, see below), in the case of the M112 that shouldn't matter, as that will be sent not once but even twice, jumping the send queue and ignoring any kind of missing acknowledgements in the process:

https://github.com/foosel/OctoPrint/blob/18e7d2b72ad73c5d8e522cebbc001d0e8a3dff14/src/octoprint/util/comm.py#L3604-L3636

The problem however - which I just saw - is that the processing of commands to be sent makes a difference between commands sent while a file is printing vs while the printer is idle. And that's the issue here. Before the M112 ever gets into the queuing stage, it first gets thrown into the internal command queue reserved for commands coming in during a print job, and that here only gets processed after the long running command returns.

Solution is to modify the behaviour of M112 (and other emergency codes) and give it utmost priority in each and every case even if a print job is running. However, since this is not a regression in 1.3.11rc2 and in fact a bug that has been in there since at least 2016 if not longer, a fix for this will have to wait until 1.3.12.

---

Side note:

2019-04-05 12:28:55,932 - Send: N1 M115*39
2019-04-05 12:28:55,985 - Recv: ok

It would be great if Klipper did respond to an M115 with an actual identification string and ideally also its capabilities expressed in a capability report

---

Side note 2:

2019-04-05 12:29:40,950 - Changing monitoring state from "Printing" to "Printing"

How?!

[KevinOConnor]

2019-04-05 12:29:40,950 - Changing monitoring state from "Printing" to "Printing"

How?!

I'm not sure if that was a rhetorical question or not. To the best of my knowledge, this install is a standard OctoPrint installation that I've variously upgraded over the last year or so. I don't recall ever installing a plugin on this 3d printer. The only customization I'm aware of are the steps described at: https://github.com/KevinOConnor/klipper/blob/master/docs/Installation.md#configuring-octoprint-to-use-klipper . I updated to v1.3.11rc2 yesterday for this bug report. Alas, there wasn't a print on this particular printer in the last several days, so I can't say if the "Printing to Printing" message was there previously. The message does not appear to be specific to the testm109.gcode file (it seems to show up for any gcode file I now print on this printer) and does not appear to be related to "safe mode" (it shows up in regular mode as well).

Another 3d printer that I have running stock "OctoPrint 1.3.10 running on OctoPi 0.16.0" and Klipper does not show these "Printing to Printing" message.

Thanks.
-Kevin

EDIT: I erroneously typed "1.3.12rc2" when I meant "1.3.11rc2".

[foosel]

Not a rhetorical question, just outright puzzlement. I'll have to see if I can reproduce that, it looks... off.

I just got an idea though what the reason for this might be.

[foosel]

Idea turned out to be right, so that "Starting.... Starting" nonsense will be fixed in 1.3.11rc3 (because THAT was a regression).

[foosel]

M112 (and other emergency codes) will now jump the internal command queue even when printing and sent immediately (and if EMERGENCY_PARSER support is detected, even force sent).

Patch is applied to maintenance, soon devel, to be released with 1.3.12.

[KevinOConnor]

I can confirm this is fixed in v1.3.12. Thanks!

-Kevin