[BUG] "FILAMENT_RUNOUT_SCRIPT M600" does not send host action commands after filament runout

[hometinker12]

Bug Description

I have been having an issue with the latest release version of marlin 2.0 where a filament runout no longer sends the host action commands to Octoprint.

My Configurations

Marlin Config Files.zip

Octoprint_serial_Log.log

Steps to Reproduce

1. Configure #define FILAMENT_RUNOUT_SCRIPT "M600"
2. Start a 'streaming' print with Octoprint
3. Trigger a filament runout

Expected behavior: I expect FILAMENT_RUNOUT_SCRIPT "M600" to function the same as a manually entered M600 into the serial console.

All host action commands are sent:

2020-06-05 15:40:36,192 - Recv: ok
2020-06-05 15:40:36,196 - Changing monitoring state from "Printing" to "Pausing"
2020-06-05 15:40:36,208 - Send: N4140 M400*22
2020-06-05 15:40:36,448 - Recv: ok
2020-06-05 15:40:36,451 - Send: N4141 M600*21
2020-06-05 15:40:36,453 - Recv: //action:paused
2020-06-05 15:40:36,454 - Printer signalled that it paused, switching state...
2020-06-05 15:40:38,472 - Recv: echo:busy: processing
2020-06-05 15:40:43,796 - Recv: //action:notification Print Paused
2020-06-05 15:40:49,484 - Recv: echo:busy: processing
2020-06-05 15:41:00,947 - Recv: echo:Insert filament and press button
2020-06-05 15:41:00,965 - Recv: //action:prompt_end
2020-06-05 15:41:00,974 - Recv: //action:prompt_begin Nozzle Parked
2020-06-05 15:41:00,983 - Recv: //action:prompt_button Continue
2020-06-05 15:41:00,995 - Recv: //action:prompt_show
2020-06-05 15:41:01,483 - Recv: echo:busy: paused for user
2020-06-05 15:41:45,950 - Recv: echo:Press button to heat nozzle
2020-06-05 15:41:45,953 - Recv: //action:prompt_end
2020-06-05 15:41:45,961 - Recv: //action:prompt_begin HeaterTimeout
2020-06-05 15:41:45,968 - Recv: //action:prompt_button Reheat
2020-06-05 15:41:45,981 - Recv: //action:prompt_show
2020-06-05 15:41:47,485 - Recv: echo:busy: paused for user
2020-06-05 15:42:50,875 - Recv: //action:notification Print Paused
2020-06-05 15:42:50,885 - Recv: echo:Insert filament and press button
2020-06-05 15:42:50,889 - Recv: //action:prompt_end
2020-06-05 15:42:50,905 - Recv: //action:prompt_begin Reheat Done
2020-06-05 15:42:50,913 - Recv: //action:prompt_button Continue
2020-06-05 15:42:50,922 - Recv: //action:prompt_show
2020-06-05 15:42:51,487 - Recv: echo:busy: paused for user
2020-06-05 15:43:09,957 - Recv: //action:prompt_end
2020-06-05 15:43:09,968 - Recv: //action:prompt_begin Paused
2020-06-05 15:43:09,977 - Recv: //action:prompt_button PurgeMore
2020-06-05 15:43:09,987 - Recv: //action:prompt_button Continue
2020-06-05 15:43:09,998 - Recv: //action:prompt_show
2020-06-05 15:43:11,488 - Recv: echo:busy: processing
2020-06-05 15:43:27,628 - Recv: //action:prompt_end
2020-06-05 15:43:27,642 - Recv: //action:prompt_begin Paused
2020-06-05 15:43:27,654 - Recv: //action:prompt_button PurgeMore
2020-06-05 15:43:27,662 - Recv: //action:prompt_button Continue
2020-06-05 15:43:27,671 - Recv: //action:prompt_show
2020-06-05 15:43:29,488 - Recv: echo:busy: paused for user
2020-06-05 15:43:37,492 - Recv: echo:busy: processing
2020-06-05 15:43:38,354 - Recv: //action:resumed
2020-06-05 15:43:38,358 - Printer signalled that it resumed, switching state...
2020-06-05 15:43:38,362 - Changing monitoring state from "Pausing" to "Resuming"
2020-06-05 15:43:38,438 - Recv: //action:notification Printing...
2020-06-05 15:43:38,450 - Recv: ok
2020-06-05 15:43:38,458 - Send: N4142 M114*20

Actual behavior: [What actually happens]

Filament runout sensor is triggered, the host commands are only partially sent, no pause command nor resume command are sent to the host. In this case octoprint will get stuck in a communication timeout trying to send the next set of GCODE until the filament is changed:

2020-06-05 15:27:23,388 - Recv: ok
2020-06-05 15:27:23,395 - Send: N1924 G1 F2400 X104.186 Y94.262 E212.06936*6
2020-06-05 15:27:23,462 - Recv:  T:205.00 /205.00 B:18.59 /0.00 @:87 B@:0
2020-06-05 15:27:23,481 - Recv: //action:prompt_end
2020-06-05 15:27:23,490 - Recv: //action:prompt_begin FilamentRunout T0
2020-06-05 15:27:23,500 - Recv: //action:prompt_show
2020-06-05 15:27:23,513 - Recv: //action:paused filament_runout 0
2020-06-05 15:27:25,019 - Recv: ok
2020-06-05 15:27:25,041 - Send: N1925 G1 X123.506 Y94.262 E213.15363*103
2020-06-05 15:27:25,467 - Recv:  T:205.00 /205.00 B:18.59 /0.00 @:81 B@:0
2020-06-05 15:27:27,467 - Recv:  T:205.00 /205.00 B:18.75 /0.00 @:82 B@:0
2020-06-05 15:27:29,467 - Recv:  T:204.82 /205.00 B:18.59 /0.00 @:100 B@:0
2020-06-05 15:27:29,489 - 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.
2020-06-05 15:27:29,501 - Send: N1926 M105*27
2020-06-05 15:27:31,467 - Recv:  T:205.00 /205.00 B:18.59 /0.00 @:95 B@:0
2020-06-05 15:27:33,488 - Recv:  T:205.54 /205.00 B:18.75 /0.00 @:60 B@:0
2020-06-05 15:27:33,505 - 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.
2020-06-05 15:27:33,516 - Send: N1927 M105*26

Additional Information

I change value of host_action_paused(false) to host_action_paused(true) in the runout.cpp and now I receive the correct //action:paused command before the M600 is run, but I still do not receive the resume command or any of the other host action prompts. This is a bit better but requires me to manually 'resume' the print from Octoprint post filament change.

runout.cpp

...
#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); //******changed this*****
    }
    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(false);
    }
    SERIAL_ECHOPGM(" " ACTION_REASON_ON_FILAMENT_RUNOUT " ");
    SERIAL_CHAR(tool);
    SERIAL_EOL();
  #endif // HOST_ACTION_COMMANDS
...

[spmgit]

I am also having a similar issue since compiling 2.0.5.3.

My Configurations

Marlin_Configs_2.0.5.3.zip

I was in the middle of a two day print when this failed, and thought it was an Octoprint issue, so
I changed the Max. consecutive timeouts while printing and Max. consecutive timeouts during long running commands values in Octoprint from 5 to 999 to see if I could change the behavior from the Octoprint side. I then inserted a short piece of filament and restarted the print. I unfortunately forgot to enable the serial log, but here is the end of my terminal log from Octoprint:

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.
[...]
Recv: ok
Recv: ok
Send: N2318 G1 X125.565 Y435.694 E770.5683594
Send: N2319 G1 X125.096 Y435.716 E770.6620587
Recv: Error:Line Number is not Last Line Number+1, Last Line: 2232
Recv: Resend: 2233
Printer requested line 2233 but no sufficient history is available, can't resend
Changing monitoring state from "Printing" to "Error: Printer requested line 2233 but no sufficient history is available, can't resend"
Send: M112
Send: N2320 M11218
Send: N2321 M104 T0 S019
Changing monitoring state from "Error: Printer requested line 2233 but no sufficient history is available, can't resend" to "Offline (Error: Printer requested line 2233 but no sufficient history is available, can't resend)"
Connection closed, closing down monitor

I will see if I have some time this weekend to recreate the issue with full logging. I will also recompile with the runout.cpp change mentioned by hometinker12, because in my opinion having to manually 'resume' the print is better than having it fail completely in the middle of a two day print.

[boelle]

@hometinker12 still an issue?

[hometinker12]

@hometinker12 still an issue?

Yes, this is still an issue.

[github-actions]

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.

[elliot-codes]

Still an issue for usb - octoprint connections.
Related: #12315
Reopen!

[thinkyhead]

This may be a host issue. The code change cited above makes no sense because it breaks up the "paused" line in two, where the second part is meaningless, and the host message for "paused" has not changed in any meaningful way since the original addition of host prompt support in #13039.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.