Print stuck in "finishing" state and does never finish, still

Continuing the discussion from Print stuck in "finishing" state and does never finish:

What is the problem?

See title

What did you already try to solve it?

Restarted everything

Have you tried running in safe mode

Yes

Did running in safe mode solve the problem?

No

Systeminfo Bundle

You can download this in OctoPrint's System Information dialog ... no bundle, no support!)

WRITE HERE

Additional information about your setup

OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible

octoprint-systeminfo-20240505154405.zip (28.3 KB)

Can you please post the endcode of the Slicer/inside OctoPrint

from PrusaSlicer

{if max_layer_z < max_print_height}G1 Z{z_offset+min(max_layer_z+1, max_print_height)} F720 ; Move print head up{endif}
G1 X0 Y200 F3600 ; park
{if max_layer_z < max_print_height}G1 Z{z_offset+min(max_layer_z+49, max_print_height)} F720 ; Move print head further up{endif}
G4 ; wait
M221 S100 ; reset flow
M900 K0 ; reset LA
{if print_settings_id=~/.*(DETAIL @MK3|QUALITY @MK3|@0.25 nozzle MK3).*/}M907 E538 ; reset extruder motor current{endif}
M104 S0 ; turn off temperature
M140 S0 ; turn off heatbed
M107 ; turn off fan
M84 ; disable motors
; max_layer_z = [max_layer_z]

In the fourth line you have this:

https://reprap.org/wiki/G-code#G4:_Dwell

For you have no time given, it will wait until eternity.

But the gcode file is not complete, so is the print

so far as I know that's part of the standard configuration. I didn't add it. So I suppose I can remove it without issue. Some gcode files have it and some don't:

grep -c "G4 ; wait" *gcode | cut -d: -f2 
0
2
0
0
2
0
0
2
0
2
2
0
2
0
0
0

You are correct, I have one in my endcode here too.

What I have too, is an empty line at the end of the code.

Actually it gets turned into a S0 so it is more like an M400.
(Note to self - G4 is 2 fewer bytes than M400)

Ouch! Really?

I just sliced a small part, verified the wait command is commented out, then ran it. Same thing…the Prusa display says it's "Heating…" even though the temp values are dropping and Octoprint is stuck on "Finishing." The time lapse is done which was something I was wondering about, if there was some wait state introduced to block jobs running before the timelapse was complete. But nothing to that.

So this is some kind of misfeature. I could run without plugins/Safe Mode and see if it is any different. Odd that this isn't being seen by others.

The G4 is part of an If loop. With nothing there, the if loop will fail

It seems to be outside the two if/endif statements on the preceding lines.

Running in Safe Mode makes no difference. It is still stuck in "Finishing…" state, temps are still dropping, and the display says it's "Heating…"

Running this job one more time…verifying that I have set the machine correctly (the Raspberry π used to be connected to a different machine).

I have to disconnect/reconnect to resolve this. Not a huge issue but it seems unnecessary. the job should be marked as complete when it is complete.

Ok, it seems to have something to do with the built-in timelapse feature. As soon as that finished rendering the status changed to "Operational." I thought I have turned that off, as I already suspected that was what was creating the wait state. The Heating alert on the display makes no sense but whatever…one thing at a time.

I just confirmed that timelapse support is off and without 3rd party plugins (in Safe Mode), octolapse should not be in the mix.

There are still a lot of plugins loaded in Safe Mode…not sure I have the same understanding of the term. Running this little job one more time, with timelapse turned off and no octolapse.

I just ran the same job again, no time lapse was made this time, but there was a long (several minute) pause before the printer was shown as Operational. The fans are working the whole time, up to that point: is there some cooldown cycle in the gcode or the newest Prusa firmware that could be causing this?

Run the part again and turn on serial logging. It sounds like the printer is seeing a "M190 R40" or "M109 R40" (this could also be done by your display if ir's a fancy-smacy one).

Where would those commands be coming from? I am not seeing them in the gcode files.

root@octopi:/home/paul/.octoprint/uploads# grep "M109 R40" *
root@octopi:/home/paul/.octoprint/uploads# grep "M190 R40" *

It may not be "R40", that's just the temp to wait for. Try "M109 R" and "M190 R".
Also check your OctoPrint Settings->Printer->GCODE Scripts->After print job completes

This is the post-job gcode…I assume it's stock as I have ever fooled with it.

G28 X0 ; home the X-axis
M84 ; disable motors
M104 S0 ; turn off heaters
M140 S0 ; turn off bed
M106 S255 ; set fan to full speed
M109 S50 T0 ; wait until heater is 50°
M107 ; turn off fan

My next test is a job from the SD card without octoprint but I think, from a recent calibration, that the same behavior occurs there too.

from serial.log, it spends a lot of time after reporting 100% done. I stopped it by hand, didn't feel like waiting but it might have been stuck there another 5 minutes or more.

2024-05-07 18:45:36,537 - Send: N341494 M73 P100 R0*43
2024-05-07 18:45:36,557 - Recv: NORMAL MODE: Percent done: 100; print time remaining in mins: 0; Change in mins: -1
2024-05-07 18:45:36,561 - Recv: SILENT MODE: Percent done: -1; print time remaining in mins: -1; Change in mins: -1
2024-05-07 18:45:36,562 - Recv: ok
2024-05-07 18:45:36,566 - Send: N341495 M73 Q100 S0*42
2024-05-07 18:45:36,578 - Recv: NORMAL MODE: Percent done: 100; print time remaining in mins: 0; Change in mins: -1
2024-05-07 18:45:36,586 - Recv: SILENT MODE: Percent done: 100; print time remaining in mins: 0; Change in mins: -1
2024-05-07 18:45:36,586 - Recv: ok
2024-05-07 18:45:36,594 - Send: N341496 M84*34
2024-05-07 18:45:36,598 - Recv: ok
2024-05-07 18:45:36,600 - Changing monitoring state from "Printing" to "Finishing"2024-05-07 18:45:36,641 - Send: N341497 M400*27
2024-05-07 18:45:36,649 - Recv: ok
2024-05-07 18:45:36,653 - Send: N341498 G28 X0*104
2024-05-07 18:45:36,669 - Recv: tmc2130_home_enter(axes_mask=0x01)
2024-05-07 18:45:37,332 - Recv:   0 step=61 mscnt= 989
2024-05-07 18:45:37,335 - Recv: tmc2130_goto_step 0 13 2 1000
2024-05-07 18:45:37,446 - Recv: tmc2130_home_exit tmc2130_sg_homing_axes_mask=0x01
2024-05-07 18:45:37,553 - Recv: T:208.4 /0.0 B:60.1 /0.0 T0:208.4 /0.0 @:0 B@:0 P:0.0 A:40.3
2024-05-07 18:45:37,556 - Recv: ok
2024-05-07 18:45:37,558 - Send: N341499 M84*45
2024-05-07 18:45:37,565 - Recv: ok
2024-05-07 18:45:37,566 - Send: N341500 M104 S0*86
2024-05-07 18:45:37,569 - Recv: ok
2024-05-07 18:45:37,570 - Send: N341501 M140 S0*87
2024-05-07 18:45:37,573 - Recv: ok
2024-05-07 18:45:37,574 - Send: N341502 M106 S255*84
2024-05-07 18:45:37,577 - Recv: ok
2024-05-07 18:45:37,578 - Send: N341503 M109 S50 T0*41
2024-05-07 18:45:37,585 - Recv: LCD status changed
[…]
2024-05-07 18:46:49,660 - Recv: echo:busy: processing
2024-05-07 18:46:49,758 - Recv: T:145.8 /50.0 B:56.5 /0.0 T0:145.8 /50.0 @:0 B@:0 P:0.0 A:38.5
2024-05-07 18:46:49,766 - Recv: T:145.8 E:0 W:?
2024-05-07 18:46:50,770 - Recv: T:145.0 E:0 W:?
2024-05-07 18:46:51,663 - Recv: echo:busy: processing
2024-05-07 18:46:51,761 - Recv: T:144.5 /50.0 B:56.2 /0.0 T0:144.5 /50.0 @:0 B@:0 P:0.0 A:38.3
2024-05-07 18:46:51,769 - Recv: T:144.5 E:0 W:?
2024-05-07 18:46:52,773 - Recv: T:143.7 E:0 W:?
2024-05-07 18:46:52,789 - Recv: ok
2024-05-07 18:46:52,791 - Recv: // action:cancel
2024-05-07 18:46:52,792 - Cancelling on request of the printer...
2024-05-07 18:46:52,796 - Send: N341504 M107*18
2024-05-07 18:46:52,798 - Changing monitoring state from "Finishing" to "Cancelling"
2024-05-07 18:46:52,869 - Recv: LCD status changed
2024-05-07 18:46:52,870 - Recv: ok
2024-05-07 18:46:52,871 - Send: N341505 M108*28
2024-05-07 18:46:52,893 - Recv: Unknown M code: M108
2024-05-07 18:46:52,893 - Recv: ok
2024-05-07 18:46:52,894 - Changing monitoring state from "Cancelling" to "Operational"
2024-05-07 18:46:52,900 - Send: M84
2024-05-07 18:46:52,904 - Recv: ok
2024-05-07 18:46:52,905 - Send: M104 T0 S0
2024-05-07 18:46:52,911 - Recv: ok
2024-05-07 18:46:52,912 - Send: M140 S0
2024-05-07 18:46:52,927 - Recv: ok
2024-05-07 18:46:52,929 - Send: M106 S0
2024-05-07 18:46:52,947 - Recv: LCD status changed

Bingo! So when the print is done (with this code)
The printer homes the X axis
Shuts down the steppers
Turns off all the heaters
Turns on the part cooling fan
Turns the hot end back on at 50 degrees
Then turns off the fan.
Now - since the hot end is probably way above 50, I predict the part cooler fan doesn't hardly turn on before it shuts off. A M109 S50 will not wait since the current temp exceeds the set point (but then again it's a Prusa) I don't use a Prusa or PSU Control, but after the print ends it homes X and just sits there - right?
I think the GCODE Scripts are empty on a new install, so someone had to add that.

so you suspect this line is the issue?

M109 S50 T0 ; wait until heater is 50°

Yes - take the "M104 S0" out above and change the "M109 S50 T0" to "M109 R50" if you want to run the fan until the hot end cools down. Then after the last "M107" add a line "M104 S0". That will, I think shut down the printer after whatever delay you have set up on PSU Control.