Printer turns off too early

Get Help
1

First about my setup. I have a uninterruptible power supply (UPS) in front of my printer. Also I have a relay board to control the power of my printer (like this)

What is the problem?
What it should do (and sometimes does) is to move away from the print at the end, wait for a certain temperatur to cool down and turn off. It always prints until the end, but in some cases the print just stops before moving away from the finished part. Seems like it send the print done event to early.
This ruins the surface of the print because the hot nozzle is in contact with the part.

Already tried a few things to figure this out, but I don't find the connection. For example I unplugged the power connection to the UPS (so the UPS is the only PowerSupply for the printer in that case) to see if it stops the printer. This works totally fine.
There are gcode files where it is unpredictable if it stops at the print or not (but I always use the same file/slicer/end-gcode). But now there is one gcodefile where I can reproduce the issue. So it will always stop at the surface.

Wwith this file I'm know able to narrow down the issue. So I connected the printer without the UPS to see if that helps and yes without it I don't have that issue. Still strange that it works fine when it's connected while printing. The thing is I still would like to keep the UPS, but currently it ruins way more that it saves.

This is the action which I use to turn off the printer

events:
  enabled: true
  subscriptions:
  - command:
    - printer_off.sh
    event: PrintDone
    type: system

This is the end of the gcode file:

G0 F12120 X69.986 Y29.291
G1 F1920 X70.136 Y29.141 E1140.41092
M107
G1 F4200 E1135.41092
G1 Z10.300
G0 F12120 X70.136 Y29.141 Z15.000
#End Gcode
T0
M104 S0
M140 S0
G91
G1 Z10 F1000
G90
G0 X20
G0 Y230
M109 R120

And this from the octoprint.log

2020-02-28 11:00:33,732 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-02-28 11:02:34,956 - octoprint.util.comm - INFO - Finished in 1762.310 s.
2020-02-28 11:02:34,964 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Finishing"
2020-02-28 11:02:34,973 - octoprint.printer.standard.job - INFO - Print job done - origin: local, path: print2.gcode, owner: myuser
2020-02-28 11:02:34,982 - octoprint.plugins.DisplayLayerProgress - INFO - Printing stopped. Detailed progress stopped.
2020-02-28 11:02:34,983 - octoprint.events - INFO - Executing a system command
2020-02-28 11:02:35,053 - octoprint.events - INFO - Executing a system command
2020-02-28 11:02:35,295 - octoprint.util.comm - ERROR - Unexpected error while reading from serial port
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 2793, in _readline
    ret = self._serial.readline()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint/util/comm.py", line 4932, in readline
    c = self.read(1)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/serial/serialposix.py", line 501, in read
    'device reports readiness to read but returned no data '
SerialException: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2020-02-28 11:02:35,296 - octoprint.util.comm - ERROR - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2020-02-28 11:02:35,308 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:2793)"

The errors seem expected to me because the printer is off at this time.
So my guess is that the event PrintDone is sent to early for some reason. Any ideas/suggestions?
EDIT: Probably not the best theory, because it works find without the UPS. As I mentioned, I don't see the connection.

OctoPrint version 1.3.12
OctoPi version 0.17.0
Hephestos i3
Marlin 1.1

2

Could you also share the serial.log and the complete octoprint.log?

3

Got this in the serial.log file.

2020-02-28 10:33:05,161 - serial.log is currently not enabled, you can enable it via Settings > Serial Connection > Log communication to serial.log

So to get something I will have to print the part again.

I already included everythig from the octoprint.log file that happened around the error.

But this are the lines after I started the print:

2020-02-28 10:33:12,969 - octoprint.plugins.stats - INFO - Printer Stats - on_event
2020-02-28 10:33:13,345 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2020-02-28 10:33:13,385 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2020-02-28 10:33:15,683 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2020-02-28 10:35:39,649 - octoprint.server.util.sockjs - INFO - Client connection closed: *scratched*
2020-02-28 10:39:42,065 - octoprint.server.api.system - INFO - Performing command for custom:lon
2020-02-28 10:40:20,522 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2020-02-28 10:45:33,726 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2020-02-28 11:00:33,732 - octoprint.server.heartbeat - INFO - Server heartbeat <3

I don't feel comfortable posting complete logfiles without knowing which (maybe) sensible data I provide. This is why I prefer to post defined sections, hope you understand.

4

Unless you are in the habit of printing sensitive passwords to your printer's display via M117, the serial.log will be completely safe to post and frankly, it's impossible to analyse this without it.

At least OctoPrint core will also never log any kind of credentials to the log. Can't vouch for third party plugins however.

5

I understand. I have a lot third party plugins, so I would prefer so post sections. Feels better.

I will enable serial log, print the file again and come back with the log.

Thanks!

6

Or you could just enable safe mode (which you should do anyhow, to rule out one of your many third party plugins to be at fault) and post a full log which would reduce the risk of you removing the clue by accident :wink:

For the record though: I see a ton of octoprint.logs with a multitude of third party plugins installed and so far have never come across any credentials in them, so I think you should be fine in any case.

7

Just tried it with safe mode and serial log enabled. The issue did not appear so it wouldn't make sense to post the logs for this.
So could be two things I guess.

  1. worked because of safe mode
  2. coincidence (because as I said it works for other files randomly too, but did not work with this file yet).

So I guess what I should do next is go back to normal mode and print again (with serial log enabled).

Edit: Already tried it again with normal mode and again no error. This issue is so weird. I think I have to wait until it reappears or could have starting it in save mode fixed something?

8

If I had a printer_off.sh script, I'm sure I'd put at least a five-minute delay in that. In fact, I'd probably even make it pretty smart:

  • verify that the script is running "in the background" rather than in the same thread
    • wait five minutes doing nothing
    • using curl, determine if the print status in OctoPrint is Operational rather than Printing
    • wait some more if it's still Printing
    • run a shutdown command for OctoPrint
    • wait another two minutes
    • optionally, test ps to see if OctoPrint is now stopped
    • toggle the UPS
9

Thanks for your suggestions. I totally get what you are saying. The thing is I sues that action/script for about 2-3 years and it always worked fine. It never triggered during a print, so that's fine. Seems like those issues came with the UPS which I added some months ago.

It seems to trigger the printdone event too early and also seems to have something to do with the UPS.

This issue did not only happens once, however and the last few prints after restarting in safemode and turing serial log on it did not happen. I did not do anything else to the system that might have fixed it.

So I guess I can only leave serial log on and see if it happens again.

10

Depending upon your firmware, you're probably queueing several commands to the printer which haven't run yet. So the firmware is still chugging along and OctoPrint thinks you're done.

1 Like
11

The thing is I have this one Gcode command which tells the printer to wait for a certain temperature of the nozzle. It works fine the last times.
Would your theory match with that information? Or wouldn’t/shouldn’t octoprint wait for the temperature too?

12

There are perhaps four blocking commands in Marlin related to temperature (I'd guess). If it's one of these then you might have to tell OctoPrint about it...(?) in the Settings under long-running commands.

Myself, I added to my own printer the ability to play R2D2-themed sound events. So at the end of something, it might play R2D2 whistling for attention. But since I hadn't run that in the background, it created a long-running event and OctoPrint thought the printer wasn't responding and caused problems.

13

It’s this one, you can find my full end gcode in the first post of this thread.
Doesn’t octoprint send the printdone event after the nozzle temp went to 120 decree C (in that case).
My guess would be that this must be true because it works in all the cases when the ups is not connected.
If it octoprint sends the printdone event directly after sending the last gcodeline, than it would always fail (and never wait for the temperature). So I would guess that octoprint „knows“ already that it has to wait.

14

Have you ever tried replacing that with just M104 S0?

15

It’s part of my end gcode, but I did not try to replace it. The reason why I want to wait for that certain temp is to leave the fans until than to cool down the nozzle, because turning it off immediately could cause a clogged up nozzle (diamond hotend, existing heat could go up to far).

16

With most printers, the hotend is cooled down to 50°C.
Instead of cooling down you may eject the filament from the hotend.

1 Like
17

OctoPrint considers a print done when it has sent the last command from the file and any end GCODE it has configured itself to the printer. Note that due to the nature of the communication protocol OctoPrint won't know when those commands are actually executed and can't wait for that (I know, it feels counter intuitive, but trust me, getting this to work reliably with the zoo of firmware variants out there simply proved impossible).

I'd suggest the following end GCODE in your slicer to combat that issue:

T0
M104 S0
M140 S0
G91
G1 Z10 F1000
G90 G0 X20
G0 Y230
M104 R120
M400
M109 R120

That M400 should (hopefully) only ever return an ok once all moves have finished, meaning OctoPrint won't be able to send the final M109 to the printer until then.

What I cannot tell you is why you only are observing this problem if the UPS is involved, I'd expect it to be reliably reproducible even without that.

18

I'm using a diamond hotend with three feeds. Ejecting at the end can clogg it up too. The DH is very sensible in that case.

@foosel thanks for your suggestion, will definitely try that.
I'm pretty sure it never happened without the UPS, but I also don't see why it should interfere.
Anyway in my last prints I can't reproduce this behaviour. It's pretty hard to debug if it only happens out of nowhere.

Edit: One more thing:

Wouldn't this mean that with my existing gcode file it should fail ALL the times? I mean, it would send the command, trigger the event and immediately shutdown the printer, but that doesn't happen (or only in those failing cases).
I don't get that together.

19

Yeah, and that's what confuses me here.

20

Well it did not fail most times, in fact this is why I used it for a long time.
So still confusing.