Prusa-firmware: [BUG] Inactivity Timeout at end of print

[brettvitaz]

Printer type
MK3S

Printer firmware version
3.9.0-3421

MMU Upgrade
MMU2S

MMU upgrade firmware version
1.0.6

SD card or USB/Octoprint
Print from SD Card, Octoprint is connected

Describe the bug
Occasionally after printing has appeared to complete, the printer head will move to the front right, unload the filament and prompt to load new filament. Then it will move to the rear left as if to complete, then it will start moving toward the center and display "Inactivity Timeout" on the screen. The printer must be reset to continue.

To Reproduce
Printing certain gcode files causes this more often, but I have not made an effort to recreate error due to time and filament required.

Expected behavior
Print to complete without unloading filament, and without needing reset.

G-code
Sensor_Head_0.2mm_PLA_MK3SMMU2S_1h42m.gcode.zip

Video
_I will take this if necessary._

Octoprint terminal output

Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: USART2 rx Full!!!
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 0
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: mmu_get_response() returning: 1
Recv: MMU starts responding
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: LA10C: Linear Advance mode: UNKNOWN
Recv: echo:Advance K=0.00
Recv: Sensor_Head_0.2mm_PLA_MK3SMMU2S_1h42m.gcode
Recv: SD printing byte 4067422/4067787
Recv: 01:46
Recv: ok
Send: M27
Recv: echo:busy: processing
Recv: NORMAL MODE: Percent done: 100; print time remaining in mins: 0
Recv: SILENT MODE: Percent done: 255; print time remaining in mins: -1
Recv: NORMAL MODE: Percent done: 100; print time remaining in mins: 0
Recv: SILENT MODE: Percent done: 100; print time remaining in mins: 0
Recv: echo:Unknown command: ".01170"(2)
Recv: fsensor_checkpoint_print
Recv: ok
Send: M105
Recv: echo:Enqueing to the front: "M600"
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: mmu_get_response - begin move: unload
Recv: MMU <= 'U0'
Recv: Unloading finished 1
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: MMU => 'ok'
Recv: mmu_get_response() returning: 1
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: mmu_get_response - begin move: load
Recv: MMU <= 'T0'
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: MMU <= 'A'
Recv: echo:busy: processing
Recv: MMU => 'ok'
Recv: mmu_get_response() returning: 1
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: MMU can_load:
Recv: echo: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: Oecho: cold extrusion prevented
Recv: O succeeded.
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo:busy: paused for user
Recv: echo:busy: paused for user
Recv: echo: cold extrusion prevented
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:busy: processing
Recv: echo:enqueing "M220 S100"
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: ok T:145.3 /0.0 B:55.9 /0.0 T0:145.3 /0.0 @:0 B@:0 P:37.1 A:42.0
Send: M27
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: echo: cold extrusion prevented
Recv: Done printing file
Changing monitoring state from "Printing from SD" to "Finishing"
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:1 hours 48 minutes
Recv: Done printing file
Recv: echo:17 hours 55 minutes
Recv: Done printiDone printing file
Recv: echo:1065 hours 41 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: DoDone printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Done printing file
Recv: echo:17 hours 2 minutes
Recv: Error:Printer halted. kill() called!
Changing monitoring state from "Finishing" to "Error: Printer halted. kill() called!"
Send: M112
Send: N3 M112*34
Send: N4 M104 T0 S0*37
Send: N5 M140 S0*96
Changing monitoring state from "Error: Printer halted. kill() called!" to "Offline (Error: Printer halted. kill() called!)"
Connection closed, closing down monitor

[awenelo]

Can you try slicing it in PrusaSlicer 2.2.0?
I think that it might have something with the text at the end of the file(probably generated by a bug), which the printer doesn't appear to like(starts at Recv: echo:Unknown command: ".01170"(2)). By loading the Gcode into Cura's Gcode viewer, it appears that the move to the center is caused by this section (loading it in without this section results in a normal final nozzle position, with this section results in a nozzle position above the center of the print) Also, before this section happens, M104 S0 and M140 S0 are executed which turn off the nozzle and bed, but this section tells the printer to extrude, indicating further that this text is not intentional.

.01170
G1 X96.757 Y141.706 E0.01181
G1 X96.935 Y141.775 E0.00496
G1 X106.895 Y141.775 E0.25952
G1 X113.107 Y139.446 E0.17287
G1 X112.896 Y139.300 E0.00670
G1 X111.999 Y138.464 E0.03195
G1 X111.551 Y138.201 E0.01354
G1 X111.103 Y138.075 E0.01213
G1 X110.654 Y138.053 E0.01170
G1 X110.206 Y138.120 E0.01181
G1 X109.758 Y138.293 E0.01252
G1 X109.309 Y138.601 E0.01418
G1 X108.413 Y139.437 E0.03195
G1 X107.965 Y139.700 E0.01354
G1 X107.516 Y139.826 E0.01213
G1 X

[brettvitaz]

I will try that. I am now also inclined to blame the Toshiba FlashAir SD card since I have seen on a few occasions that a copied gcode file would report as "incomplete". I pulled the file from the SD card that I posted here.

[brettvitaz]

It's pretty obvious that the gcode was corrupt. Closing