After print job completes issue

b3st0fth3w0rst · April 22, 2020, 4:14am

What is the problem?
Nothing i seem to put in the "After print job completes" seems to work.

What did you already try to solve it?
Cr10s Pro using the Cura slicer.
Currently, in Cura's 'End G-Code' section there is:
G91 ;Relative positioning
G1 E-4 Z20 F2400 ;Retract and raise Z
G90 ;Absolute positioning
G1 Y300;Present print
M106 S0 ;Turn-off fan
M104 S0 ;Turn-off hotend
M140 S0 ;Turn-off bed
M84 X Y E ;Disable all steppers but Z

The above works fine and as expected.

The prblem comes when....

I have added a USB relay to control the power to the printer so that i can shut it down after prints complete. An easy task i thought.
Using the "GCODE System Command" plugin, i've created two commands...

OCTO901:
sleep 30

and...

OCTO900:
/home/pi/dev/scripts/power_cut.sh

power_cut.sh contains:
#!/bin/bash
sleep 60
gpio export 2 out
gpio -g write 2 1
echo "0" > /home/pi/dev/scripts/state
sh /home/pi/dev/scripts/usb_cut.sh &

usb_cut.sh contains:
#!/bin/bash
sleep 30
gpio export 3 out
gpio -g write 3 1

I then put in Octoprints 'After print job completes' section:
M400
OCTO901
M400
OCTO900

The issue...when the print completes...the print head never moves as per the Cura's 'End G-Code' script. If i do not use the OCTO codes, the Cura's 'End G-Code' executes fine. I've also verified that, when saved to a file, the gcode does contain Cura's 'End G-Code' script.
As a result the print head stays on the print and burns a hole into the print.

Things i've tried...

Just putting Cura's 'End G-Code' script into Octoprints 'After print job completes' section...same result. The print head stays on the print and burns a hole in it.
G91 ;Relative positioning
G1 E-4 Z20 F2400 ;Retract and raise Z
G90 ;Absolute positioning
G1 Y300;Present print
M106 S0 ;Turn-off fan
M104 S0 ;Turn-off hotend
M140 S0 ;Turn-off bed
M84 X Y E ;Disable all steppers but Z
M400
OCTO901
M400
OCTO900

I've also noticed, that with short, lest than 1 minute test prints, the setup above works fine and the print head is lifted off the print at completion and the bed is moved all the way forward. But with actual prints that take hours...once complete, it seems like the end GCODE to lift the head and present the print doesn't execute.

I'm not a GCODE expert, but i'm all out of ideas on how to make this work.
All i want is, when the print is finished...

the print head is lifted from the print
octoprint executes the power_cut.sh script to activate the realy to cut power to the printer.

I feel like this should be fairly simple and maybe i'm just missing, or not understanding how GCODE works, but i'm out of ideas.

When i look at the logs...it seems that the OCTO commands get executed, but the then octoprint tires to send more commands after. This is where i'm getting confused. Are the commands not executed linearly? One line at a time in order? If thats the case...then OCTO900 (Call to execute power_cut.sh) should be the last command issued.

I'm at a loss, and frustrated. Please help me understand.

Logs from last print: https://www.dropbox.com/s/s58k3gj25vnj8ox/serial.log?dl=0

b3st0fth3w0rst · April 22, 2020, 4:39am

Currently i am executing the scripts manually via the Telegram plugin. I've setup custom 'Printer On/Off' system commands. When i ge tthe notification that the print is finished i use the telegram /sys command to send the "off" command. Works fine if i guess...if i'm awake to turn off the printer.

kantlivelong · April 22, 2020, 5:40pm

The OCTO gcode commands implemented via the octoprint.comm.protocol.gcode.queuing hook are run before they are sent but they are not necessarily serialized. ~~It would be great if octoprint.comm.protocol.gcode.sending could accept modification or at least the ability to discard the command.~~

Though since your move is run before any OCTO command I'm not entirely sure what the issue could be other than sleep causing issues. If implemented in your firmware it would probably be better to use G4.

Though OctoPrint-PSUControl might be better suited for this though I always cringe at the idea of cutting all power to the controller rather than simply cutting supplies required for heating/movement.

OutsourcedGuru · April 22, 2020, 6:03pm

In my case, I added a sound event thing to my printer where I had R2D2 whistle to alert me that the print job was finished. It was probably OCTO805 as I recall. The problem was that the underlying aplay command is perhaps three or five seconds long. In gcode terms, that's a long time. So in addition to including OCTO805 in the long-running gcode list in OctoPrint's settings, it's good form to call the script with an ampersand at the end (run in the background).

~/scripts/myscript.sh &

So that would immediately return control back to the main Python thread and things will behave better.

b3st0fth3w0rst · April 22, 2020, 6:54pm

Interesting. I'll take a look at the OctoPrint-PSUControl. I've tried the G4 command and the issue is the same.
I hit the G4, then it shuts down the printer, leaving the head on the print.

I'm printing something now. I've removed all OCTO gcode and everything from the 'After print job' section of octoprint. Only the End Gcode from Cura is present. I expect the print head to be lifted off the print and the bed moved all the way forward, but the machine will stay on.

b3st0fth3w0rst · April 22, 2020, 6:57pm

@OutsourcedGuru

I can't remember if i tried running the script in the background. I want to say i did but not sure.
I'll try again and see what happens...

kantlivelong · April 22, 2020, 8:27pm

So it turns out that octoprint.comm.protocol.gcode.sending can actually be used instead of ...queuing.

Thanks @foosel for correcting my brain.

@b3st0fth3w0rst you're welcome to try a test build to see if it helps once I wrap it up.

b3st0fth3w0rst · April 22, 2020, 8:33pm

i am happy to help out with the testing

kantlivelong · April 22, 2020, 8:41pm

@b3st0fth3w0rst https://github.com/kantlivelong/OctoPrint-GCodeSystemCommands/archive/hook_change.zip

Install using the plugin manager but give it the URL above. There are some other changes included with it as well.

b3st0fth3w0rst · April 22, 2020, 8:42pm

My last print just finished.
I took @OutsourcedGuru suggestion and added an & to run in the background.
Print finished, raised the print head, moved the bed forward, and 60 seconds later, the relay was flipped and the power turned off.

Thought i tried that before, but apparently not lol

b3st0fth3w0rst · April 22, 2020, 9:35pm

Just tested it and it worked. When the print finished, the print head was lifted and the bed slid forward. 60 seconds later, the relays were flipped and the printer was turned off.

kantlivelong · April 22, 2020, 9:45pm

Ayy!

That was with your original config right?

b3st0fth3w0rst · April 22, 2020, 10:46pm

Yup...They way i imagined it would work originally.

I left the stock END GCODE from cura (Raises hotend, slides the bed out, and disables the motors, heaters, and fans)
Created and OCTO900 that executes '/home/pi/dev/scripts/power_cut.sh' with no '&'.
I put OCTO900 in the long running command list
In Octoprint's 'After job completes' field, i have a single entry, 'OCTO900'
power_cut.sh contains:
#!/bin/bash
sleep 60
gpio export 2 out
gpio -g write 2 1
echo "0" > /home/pi/dev/scripts/state
sh /home/pi/dev/scripts/usb_cut.sh &

Worked as expected on my last print (with you change).
I'll be setiing up a print for tonight. I'll chime back with the result.

Thanks a lot. Definitely relieved some frustration lol. I just couldn't figure out what was going on lol.

kantlivelong · April 22, 2020, 11:03pm

Awesome!

Thanks for your bringing it up and working through the motions. An official release will likely be pushed soon.

b3st0fth3w0rst · April 22, 2020, 11:20pm

No problem. Thank you for fixing it so quick.

OutsourcedGuru · April 22, 2020, 11:54pm

You might also try pushing that ampersand up a level rather than in the line at the end of your script.

OllisGit · April 23, 2020, 2:09pm

Hi @kantlivelong,

I looked into your implementation.
You changed from queuing to sending, be aware that now your plugin-code is executed in the comm.sending_thread, each communication-delay between OP and the printer is error prone.

Currently I have a huge discussion about layer-shifting, see https://github.com/OllisGit/OctoPrint-DisplayLayerProgress/issues/124

My DLP use the sending approach a couple of years, but now the users reported errors.
Now I switched back to queuing and it seems like that the issue is solved.
In between I changed the code in the sending-hook to an async-queue to reduce the delay (works for couple of people).
You can take a look into the my implementation about the async-queue, maybe it helps.

BR
Olli

kantlivelong · April 23, 2020, 2:30pm

@OllisGit Ah yeah, need to keep processing on the send hook to the bare minimum. I wonder how much time I can shave off by using:

if cmd[:4] !=  'OCTO':
    return

vs

match = re.search(r'^(OCTO[0-9]+)(?:\s(.*))?$', cmd)
if match is None:
    return

kantlivelong · April 23, 2020, 3:18pm

@OllisGit Ohh yeah def going to make that change...

import re
def testfunc(cmd):
    if cmd[:4] != 'OCTO':
        return


def testfunc2(cmd):
    match = re.search(r'^(OCTO[0-9]+)(?:\s(.*))?$', cmd)
    if match is None:
        return

i = 0
while i < 100000000:
    testfunc('OCTO999')
    i += 1

i = 0
while i < 100000000:
    testfunc2('OCTO999')
    i += 1

➜  ~ python -m cProfile test.py
         500000402 function calls (500000381 primitive calls) in 203.860 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
100000000   39.994    0.000  114.400    0.000 re.py:143(search)
100000000   40.342    0.000   40.342    0.000 re.py:230(_compile)
        2    0.000    0.000    0.000    0.000 sre_compile.py:228(_compile_charset)
        2    0.000    0.000    0.000    0.000 sre_compile.py:256(_optimize_charset)
        3    0.000    0.000    0.000    0.000 sre_compile.py:428(_simple)
        1    0.000    0.000    0.000    0.000 sre_compile.py:433(_compile_info)
        2    0.000    0.000    0.000    0.000 sre_compile.py:546(isstring)
        1    0.000    0.000    0.000    0.000 sre_compile.py:552(_code)
        1    0.000    0.000    0.000    0.000 sre_compile.py:567(compile)
      7/1    0.000    0.000    0.000    0.000 sre_compile.py:64(_compile)
       12    0.000    0.000    0.000    0.000 sre_parse.py:138(__len__)
       28    0.000    0.000    0.000    0.000 sre_parse.py:142(__getitem__)
        3    0.000    0.000    0.000    0.000 sre_parse.py:146(__setitem__)
       12    0.000    0.000    0.000    0.000 sre_parse.py:150(append)
     10/4    0.000    0.000    0.000    0.000 sre_parse.py:152(getwidth)
        1    0.000    0.000    0.000    0.000 sre_parse.py:190(__init__)
       27    0.000    0.000    0.000    0.000 sre_parse.py:194(__next)
       20    0.000    0.000    0.000    0.000 sre_parse.py:207(match)
       20    0.000    0.000    0.000    0.000 sre_parse.py:213(get)
        1    0.000    0.000    0.000    0.000 sre_parse.py:278(_escape)
      4/1    0.000    0.000    0.000    0.000 sre_parse.py:336(_parse_sub)
      4/1    0.000    0.000    0.000    0.000 sre_parse.py:414(_parse)
        1    0.000    0.000    0.000    0.000 sre_parse.py:68(__init__)
        1    0.000    0.000    0.000    0.000 sre_parse.py:725(parse)
        2    0.000    0.000    0.000    0.000 sre_parse.py:75(opengroup)
        2    0.000    0.000    0.000    0.000 sre_parse.py:86(closegroup)
        7    0.000    0.000    0.000    0.000 sre_parse.py:93(__init__)
        1   42.626   42.626  203.860  203.860 test.py:1(<module>)
100000000   19.376    0.000   19.376    0.000 test.py:2(testfunc)
100000000   27.458    0.000  141.858    0.000 test.py:7(testfunc2)
        1    0.000    0.000    0.000    0.000 {_sre.compile}
       31    0.000    0.000    0.000    0.000 {isinstance}
    90/87    0.000    0.000    0.000    0.000 {len}
       75    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        4    0.000    0.000    0.000    0.000 {method 'find' of 'bytearray' objects}
        1    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        2    0.000    0.000    0.000    0.000 {method 'remove' of 'list' objects}
100000000   34.065    0.000   34.065    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
       14    0.000    0.000    0.000    0.000 {min}
        6    0.000    0.000    0.000    0.000 {ord}
        1    0.000    0.000    0.000    0.000 {range}

foosel · April 23, 2020, 3:26pm

Rule of thumb: substring comparison > precompiled regex > jit compiled regex (with > meaning "is better than")