afterPrintDone not executed once print ends

What is the problem?

So I've had Octoprint running for a looooooong time without any issues. A few days ago, I moved my install from a Pi3 to a Pi4, using the backup and restore in Octoprint. Stupidly, I also moved my install from Python 2.7(?) to 3. (Should have done one at a time but I was on a roll).

Since then, whenever a print ends, it doesn't seem to want to run my "afterPrintDone" gcode script, which used to turn off the heat on the extruder, the print bed, raise the extruder, and move the print out of the way.

The script is in /home/pi/.octoprint/scripts/gcode/afterPrintDone
644, pi:pi

Contents:

M104 S0; Set Hot-end to 0C (off)
M140 S0; Set bed to 0C (off)
{% snippet 'end_of_print_routine' %}

The snippet in turns contains:

G91           ; relative
G1 Z20 F300   ; raise Z a bit
G90           ; absolute
G1 X0 Y200 F2000 ; plate forward head out of the way

M114          ; get last_position
{% if last_position.z < 100 %}
G1 Z100 F300  ; raise to 100 if not already there
{% endif %}

M84           ; disable motors
M106 S0       ;disable fan

What did you already try to solve it?

I initially thought it was a fluke, but since then, I've tried many prints and they all do the same... Just sit there when the last layer is printed, melting whatever area was printed last.

I have looked at the terminal output and matched it to the gcode printed, and it gets all the way to the last line of the gcode file as expected, but sadly, doesn't execute the few commands in my afterPrintDone file.

After looking at the logs further, it seems like this is the culprit... but it has worked for ages, so I'm not sure what the problem is...

2022-01-28 20:22:34,370 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: MK3S/x-carriage-with-back-and-cable-holder.gcode, owner: pcbroch
2022-01-28 20:22:34,405 - octoprint.settings - ERROR - Exception while trying to render script gcode:afterPrintDone
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint/settings.py", line 1989, in loadScript
    script = template.render(**context)
  File "/home/pi/oprint/lib/python3.7/site-packages/jinja2/environment.py", line 1090, in render
    self.environment.handle_exception()
  File "/home/pi/oprint/lib/python3.7/site-packages/jinja2/environment.py", line 832, in handle_exception
    reraise(*rewrite_traceback_stack(source=source))
  File "/home/pi/oprint/lib/python3.7/site-packages/jinja2/_compat.py", line 28, in reraise
    raise value.with_traceback(tb)
  File "/home/pi/.octoprint/scripts/gcode/afterPrintDone", line 3, in top-level template code
    {% snippet 'end_of_print_routine' %}
  File "/home/pi/.octoprint/scripts/gcode/snippets/end_of_print_routine", line 7, in top-level template code
    {% if last_position.z < 100 %}
TypeError: '<' not supported between instances of 'NoneType' and 'int'

Have you tried running in safe mode?

no

Did running in safe mode solve the problem?

n/a

Systeminfo Bundle

https://drive.google.com/file/d/1-GXPwUvQqqcazoTTPZyHKQqe4yY-58GF/view?usp=sharing

Additional information about your setup

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

Octoprint Version 1.7.3
Octopi Version 0.18.0, running on Raspberry Pi 4 Model B Rev 1.1
Printer is Prusa Mk2

this looks to be the culprit, do you have the option in settings (serial connection > behavior) enabled to track position on pause?

The "Log position on pause" option is checked, which from my understanding is needed to populate the variables?

yes that's correct, that's why I was asking. the error seems to indicate that last_position.z is a NoneType rather than an actual integer. I suspect once the print is done maybe the z height is unknown at that time or not set? you might be able to modify the snippet in that case to something like

{% if last_position.z and last_position.z < 100 %}

Edit: but that would probably defeat the purpose....does the M114 command return the position?

I thought about that, but so far, according to my results, last_position.z has been NoneType 100% of the time, so it won't help much aside from preventing the script from failing. I might as well comment it out. I'm curious why it worked before.

I played with M114 in the terminal and it's consistant with the positions I'm moving the print head to... really odd.

All I'm trying to do here is get the z axis to a height that is consistent for most prints (i.e. 100, unless it's already higher). This was to counteract the effect of heat on the Pinda probe sensing and get similar results all the time when I'm doing "back to back" prints. Again, nothing critical, I'm mostly curious to find out why it worked with (the Pi 3 OR Python 2.??). Wish I'd installed on a different SD card instead of overwriting!

it looks like your log rolled over, octoprint.log doesn't include the error you copy pasted. would be good to see if in context. would also help having serial.log enabled as well.

You are right, the logfile seems to have rolled just after the print!!

Previous one is here:
https://drive.google.com/file/d/1G23JxrFqEw-F2_sjfpYz6L_XvkL4pjlx/view?usp=sharing

Sadly, the serial.log wasn't enabled. I did catch the end of the print in the terminal window though.

[--gcode commands from gcode file being printed --]
Send: N302970 G1 X130.992 Y84.259 E0.0306*90
Recv: ok
Send: N302971 G1 X130.589 Y84.492 E0.0174*91
Recv: ok
Send: N302972 M105*26
Recv: ok T:239.9 /240.0 B:75.0 /75.0 T0:239.9 /240.0 @:68 B@:45
Send: N302973 G1 X130.555 Y84.458 E0.0018*85
Recv: ok
Send: N302974 G1 X130.414 Y84.317 F710*120
Recv: ok
Send: N302975 G1 E-1.2000 F1800*40
Recv: ok
[--Last line of my gcode file being printed--]
Changing monitoring state from "Printing" to "Finishing"
Send: N302976 M117 [##########] 100%*15
Recv: ok
Send: N302977 M400*31
Recv: ok
Send: N302978 M117 [##########] 100%*1
Recv: ok
Changing monitoring state from "Finishing" to "Operational"
Send: M105
Recv: ok T:240.0 /240.0 B:75.0 /75.0 T0:240.0 /240.0 @:67 B@:43
Send: M105
Recv: ok T:239.9 /240.0 B:75.0 /75.0 T0:239.9 /240.0 @:68 B@:41
Send: G91
Recv: ok
[--Me realizing it's not executing the code and moving Y--]
Send: G0 Y10 F6000
Recv: ok
Send: G90
Recv: ok
Send: M105
Recv: ok T:240.0 /240.0 B:75.0 /75.0 T0:240.0 /240.0 @:67 B@:42
Send: M105
Recv: ok T:240.2 /240.0 B:75.0 /75.0 T0:240.2 /240.0 @:64 B@:41
Send: G91
Recv: ok
[--Me realizing it's not executing the code and moving Z--]
Send: G0 Z10 F200
Recv: ok
Send: G90
Recv: ok
Send: M105
Recv: ok T:240.2 /240.0 B:75.0 /75.0 T0:240.2 /240.0 @:64 B@:41
Send: M105
[--only temp reports after that--]

According to this, the M114 is never sent. It's almost like it's trying to render the snippet before it sends the M114. I wonder if I adding M114 as a post-print command in my slicer would allow things to move on...

Past my bedtime for tonight. I have more things to print tomorrow, I'll try adding an M114 at the end of my gcode tomorrow.

EDIT: Seems like I may have been lucky with the "Slower" Pi3 maybe? Very similar issue here: https://community.octoprint.org/t/get-the-correct-last-position-in-gcode-script/14946/2

Yeah, that's what it looks like. I'm surprised the dwell command doesn't help in this situation either. Your idea of putting the M114 in your slicer's end gocde scripts is not a bad idea though. That might help with the situation, and maybe the dwell after the M114 in the slicer's end script would delay enough for OctoPrint to get the M114 response.

Just a quick followup. I ran a new print this morning, and with the M114 in my slicer end of print commands, the last_position.z gets a proper value.

I'll send another batch of parts and try something else. Go back to the M114 command in the snippet called by afterPrintDone, but have the M114 a few lines higher, so it's done before I move the print bed forward and the x-axis back to 0. This should give time for the command to come back with a value, and because I'm after the Z position, it won't change value.

G91           ; relative
G1 Z20 F300   ; raise Z a bit
G90           ; absolute
;--- MOVED TO HERE
M114          ; get last_position
G1 X0 Y200 F2000 ; plate forward head out of the way

; --- MOVED FROM HERE 
;  M114          ; get last_position
{% if last_position.z < 100 %}
G1 Z100 F300  ; raise to 100 if not already there
{% endif %}

M84           ; disable motors
M106 S0       ;disable fan

BTW: If you wait for a move or something else to finish, you can uses this one: M400

https://reprap.org/wiki/G-code#M400:_Wait_for_current_moves_to_finish

1 Like

Thanks, I didn't know this. It seems to work without it, but it probably doesn't hurt to have it in there too!

1 Like

I'm still fighting with this and I'm seeing some odd behaviour. My afterPrintDone calls a snippet. This snippet sends M114. No matter how much waiting inside the snippet I do, last_position.z is always empty.

In contrast, if I send M114 from afterPrintDone instead and call the snippet right after, then using last_position.z in my snippet works perfectly.

Did I miss doc somewhere that explains this behaviour in a snippet?

Someone else seems to have noticed the same here:

Gcode scripts are evaluated once, when they are triggered - the variables are not 'live' they will be constant throughout the script. Not sure if it's in documentation somewhere - I just know that is the case knowing OctoPrint's code base.

1 Like

Wonder if using include or import in lieu of snippet would make a difference relative to the context, or possibly using caller()?

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.