Marlin: [BUG] Filament runout results in incorrect host action

[jborg]

Bug Description

For some reason it looks like the filament runout sensor on the latest bugfix-2.0.x sends host action "//action:paused//action:paused" (Note: repeated?) instead of the expected "//action:paused" to the host.
This results in OctoPrint not recognizing that the printer is paused and octo print starts complaining about communication timeout.

My Configurations

conf.zip

Steps to Reproduce

1. Start print from OctoPrint
2. Cut filament and observe the OctoPrint terminal

Expected behavior: [What you expect to happen]
OctoPrint terminal:

Recv: //action:paused
Printer signalled that it paused, switching state...
...

Actual behavior: [What actually happens]
OctoPrint terminal:

Recv: //action:paused//action:paused
Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
...

Additional Information

I've tested both with and without HOST_PROMPT_SUPPORT but I receive the same double "//action:paused//action:paused" event in both configurations.

[sjasonsmith]

I have a theory, but I've never looked at this code before and don't use this feature, so I'm not entirely sure it is correct.

In runout.cpp, the following code will send the paused message, because your filament runout script has M600 in it.

    if (run_runout_script
      && ( strstr(FILAMENT_RUNOUT_SCRIPT, "M600")
        || strstr(FILAMENT_RUNOUT_SCRIPT, "M125")
        #if ENABLED(ADVANCED_PAUSE_FEATURE)
          || strstr(FILAMENT_RUNOUT_SCRIPT, "M25")
        #endif
      )
    ) {
      host_action_paused(false);
    }

Then, when the M600 command actually executes, it calls pause_print in pause.cpp, which calls host_action_paused again.

host_action_paused is the function which generates the string that you are seeing.
I'm not sure what the correct fix is here. You could certainly comment out that line in runout.cpp to see if the double print goes away.

[github-actions[bot]]

This issue is stale because it has been open 30 days with no activity. Remove stale label / comment or this will be closed in 5 days.

[GMagician]

@sjasonsmith I'm think you are right about cause. But I don't know why this calls has been called here.. Maybe to inform quickly about what is happening? but, why not EOL?

[GMagician]

@sjasonsmith I read code there...it's without eol because it's supposed to print something just after it

[sjasonsmith]

This isn't an area of code I'm personally familiar with. I've never actually used the host messaging feature, let alone worked on it. I did a little triage into a possible cause, but am not actively trying to fix it.

[minosg]

@sjasonsmith I may be able to shed some light to what the code was probably intended to do.

The logic was originally that things happen in that order:

1. The code snippet you presented runs when a runout is triggered. It creates a message of the type //action:paused ..... with no line ending.
2. Then whatever the cause of the pause is completes the message and adds the line ending.
3. When host_action_pause is called again, it's argument is set to true, so it is terminated automatically.

You can see that from the output of a test job in 6.0.1 release branch.

Recv: //action:prompt_end Recv: //action:prompt_begin UI Pause Recv: //action:prompt_button Resume Recv: //action:prompt_show Recv: //action:notification Print Paused Recv: //action:prompt_end Recv: //action:prompt_begin FilamentRunout T0 Recv: //action:prompt_show Recv: //action:paused filament_runout 0 Recv: echo:busy: processing [...] Recv: echo:busy: processing [...] Recv: echo:busy: processing [...] Recv: ok Recv: //action:paused Printer signalled that it paused, switching state... Changing monitoring state from "Printing" to "Pausing" Send: N342 G1 X52.402 Y47.096 E0.14806*97 [...] Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves. Changing monitoring state from "Pausing" to "Paused"

The thing is that the printer will timeout regardless even in that case. I have been seeing the same behavior since I started playing with Marlin but could not definitely pin it down to a Marlin or an Octoprint bug. When you notice that the reason of the pause is not populated, as the user reports, then it could be something wrong in our side of the logic.

The make things even from fun I came across this bug in Octoprint's side describing this exact same behavior, and connect it to an earlier bug which I reported and has been fixed.

https://github.com/OctoPrint/OctoPrint/issues/3620

Bugception ;)

[sjasonsmith]

I really won’t be working on this one. I use neither filament runout nor host events. There’s no need for anyone to tag me in the responses.

[GMagician]

@minosg I don't use octoprint nor host action but for another purpose I was looking to this part of code.
I also noticed that code split message in 2 parts, 1st is '//action:paused' 2nd part is message completation but I can't see what can "execute another action pause" in between the 2 parts

[boelle]

the stale label was added to this one and the OP have not joined since then

what are the chances that anyone will touch this one?

[minosg]

@GMagician

Looking at the code snippet the reason is added as text in the end. If you modify the code to add an EOL by swapping false to true , and comment out the extra lines at the end of the code in runout.cpp you can workaround it.

  #if ENABLED(HOST_ACTION_COMMANDS)
    if (run_runout_script
      && ( strstr(FILAMENT_RUNOUT_SCRIPT, "M600")
        || strstr(FILAMENT_RUNOUT_SCRIPT, "M125")
        #if ENABLED(ADVANCED_PAUSE_FEATURE)
          || strstr(FILAMENT_RUNOUT_SCRIPT, "M25")
        #endif
      )
    ) {
      host_action_paused(true);
    }
    else {
      // Legacy Repetier command for use until newer version supports standard dialog
      // To be removed later when pause command also triggers dialog
      #ifdef ACTION_ON_FILAMENT_RUNOUT
        host_action(PSTR(ACTION_ON_FILAMENT_RUNOUT " T"), false);
        SERIAL_CHAR(tool);
        SERIAL_EOL();
      #endif

      host_action_pause(true);
    }
    //SERIAL_ECHOPGM(" " ACTION_REASON_ON_FILAMENT_RUNOUT " ");
    ///SERIAL_CHAR(tool);
    //SERIAL_EOL();

I have not fully tested the above though, so go nuts ;)

[GMagician]

@minosg this is not the solution. 'true' is not required because "pause cause" will be printer by code you commented.
This code has to be considered as a 2 part message. 1st part will echo "//action:paused" while 2nd part will show "why it has paused"
What I don't understand is how and who prints in between another "//action:paused". Probably a ISR but not sure how it can always interrupt in the same place (after a full message print)

what are the chances that anyone will touch this one?

@boelle if I can reproduce it I may try to solve it, even if I don't use these functions

[github-actions[bot]]

This issue has had no activity in the last 30 days. Please add a reply if you want to keep this issue active, otherwise it will be automatically closed within 7 days.