Something is pausing my print randomly

LordDarkneo · November 26, 2020, 5:32pm

What is the problem?

For an unknown reason, Octoprint is trigerring a pause on my prints. The behavior really to be a M600 like command (putting the nozzle on Z+5 and X0) and perfoming a filament retraction for like 30mm (my CR-10 bowden tube). I checked the Gcode: No M600 command in it. I am actually to print the exact same file through USB.

What did you already try to solve it?

Check the Gcode
Activate Serial logs (to ensure the issue was not ink to other threads)
On-going: Printing the same Gcode from SD
Next: Printing through Octoprint without any plugins activated.
I also tried several pausing conditions:

Pausing from octoprint: the print is paused and the nozzle secured. The printer displays "Paused" and the filament is not pulled out. When resuming the print from octoprint, everything is starting back
Pausing triggered by the filament sensor: I have exaclty the same behavior.

What's happening in my case: the job is paused AND the filament is pulled out. I absolutely need to click my CR10, first to reheat the nozzle. Once done, I need to click again to pull the filament in (and purge the nozzle) and finally I can either resume the print or perform another purge. Resuming the print from octoprint has no effect.

Have you tried running in safe mode and if so did it solve the issue?

not yet tried

Complete Logs

octoprint.log: https://www.dropbox.com/s/il4bkgb94jdz411/octoprint%20(4).log?dl=0
serial.log: https://www.dropbox.com/s/tzk3i9mlxsht9um/serial%20(1).log?dl=0

Additional information about your setup

Octoprint: 1.4.2
OctoPi: 0.17.0
Print: CR-10 v2
Running on: Marlin 2.0.7.2

Ewald_Ikemann · November 26, 2020, 5:25pm

Referring to the serial.log, it's the printer that initiates the pause:

2020-11-26 08:54:47,573 - Recv: //action:paused filament_runout 0
2020-11-26 08:54:47,766 - Recv:  T:200.17 /200.00 B:50.10 /50.00 @:50 B@:0
2020-11-26 08:54:48,234 - Recv: Not SD printing
2020-11-26 08:54:48,832 - Recv: ok N190225 P14 B3
2020-11-26 08:54:48,838 - Send: N190226 G0 X197.315 Y227.475*31
2020-11-26 08:54:48,841 - Recv: //action:paused
2020-11-26 08:54:48,842 - Printer signalled that it paused, switching state...
2020-11-26 08:54:48,844 - Changing monitoring state from "Printing" to "Pausing"
2020-11-26 08:54:48,842 - Printer signalled that it paused, switching state...
2020-11-26 08:54:48,844 - Changing monitoring state from "Printing" to "Pausing"

Check the wiring of the filament sensor for bad contacts.

And please disable the debug. It fills the octoprint.log with an overload of informations that ar usefull for programming, but not in this case.

LordDarkneo · November 26, 2020, 6:59pm

Hi and thanks for your answer.

as said, the random "pause" trigerred is not the same than the one trigerred by the filament sensor. Or I missed something. I tested it by cutting the filament leaving the printer working. And the pause is "normal" (i.e. not taking the filament out). This is why I activated the debug - to ensure that this behavior was not linked to a plugin (the DLP raised my attention when logging:

octoprint.events.fire - DEBUG - Firing event: DisplayLayerProgress_feedrateChanged (Payload: {'changeFilamentTimeLeft': '-', 'feedrate': '9000', 'updateReason': 'feedrateChanged', 'totalHeight': '14.6', 'totalLayer': '73', 'estimatedEndTime': '21:18', 'changeFilamentCount': 0, 'estimatedChangedFilamentTime': '-', 'printTimeLeftInSeconds': 44639, 'totalHeightFormatted': '14.6', 'currentHeight': '2.00', 'printTimeLeft': u'12h23m59s', 'lastLayerDuration': '0h:17m:07s', 'averageLayerDurationInSeconds': 847, 'lastLayerDurationInSeconds': 1027, 'changeFilamentTimeLeftInSeconds': 0, 'averageLayerDuration': '0h:14m:07s', 'feedrateG1': '2700', 'feedrateG0': '9000', 'fanspeed': '100%', 'progress': '17', 'currentHeightFormatted': '2.0', 'currentLayer': '9'})

The word "changeFilament" as a variable, coupled with the M600 like behavior is quite... strange... (but as it only displays data, I do not think the plugin is in case, do you?)

Ewald_Ikemann · November 26, 2020, 6:24pm

This: 0, 'estimatedChangedFilamentTime' is for calculating the print time. It's not responsible for causing a filament change and/or a pause.

The reason that the event was fired, is that the feedrate was changed.

Please share a new octoprint.log without debug. 95 % is debug information and the last 5% don't show up the issue you mention.

LordDarkneo · November 26, 2020, 7:00pm

Erf, I am printing through SD (to see if I have the same behavior or not). Normally the line I have quoted is in the octoprint.log (and only viewable at debug level).
I have a previous try (without debugging level), that rooted me to this thread
But I think the problem is different for me...
octoprint (3).log (124.8 KB)

Ewald_Ikemann · November 26, 2020, 7:13pm

Do you have a serial.log of the moment the issue occurs?

Maybe @OllisGit can explain about this line:

octoprint.events.fire - DEBUG - Firing event: DisplayLayerProgress_feedrateChanged (Payload: {'changeFilamentTimeLeft': '-', 'feedrate': '9000', 'updateReason': 'feedrateChanged', 'totalHeight': '14.6', 'totalLayer': '73', 'estimatedEndTime': '21:18', 'changeFilamentCount': 0, 'estimatedChangedFilamentTime': '-', 'printTimeLeftInSeconds': 44639, 'totalHeightFormatted': '14.6', 'currentHeight': '2.00', 'printTimeLeft': u'12h23m59s', 'lastLayerDuration': '0h:17m:07s', 'averageLayerDurationInSeconds': 847, 'lastLayerDurationInSeconds': 1027, 'changeFilamentTimeLeftInSeconds': 0, 'averageLayerDuration': '0h:14m:07s', 'feedrateG1': '2700', 'feedrateG0': '9000', 'fanspeed': '100%', 'progress': '17', 'currentHeightFormatted': '2.0', 'currentLayer': '9'})

Charlie_Powell · November 26, 2020, 10:22pm

In OctoPrint 1.5.0, there is better logging of what this issue is caused by, it lists the plugin/user/action that caused the pausing. Maybe it would help your issue to upgrade, since you would be able to see more clearly. It's currently in RC phase, but the current one has been out for over a week and there have been no problems reported.

Worth a try?

It would make lines like this:

2020-11-26 08:54:48,845 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Pausing"

Much more useful to us.

You can also try safe mode, to rule out any plugins causing issues.

LordDarkneo · November 27, 2020, 8:50pm

Hello there and thanks for your messages.

Printing from SD card performed successfully, without any issues (no pauses during the print).
So I wanted to try the octoprint in safe mode... And after the reboot, here's what I have:

I tried to force the baudrate to 250000 (I know I set it up in the firmware):

Of course, I tried to plug my printer to my PC, and everything works fine (I even reflashed the printer through pronterface) and the issue with the RPI is still...

Do I need to reinstall all my octoprint?

Edit: That's really weird... I changed the USB cable (by 2 others) but the CR-10 is not recognized by the RPI.... the lsusb is not showing anything... but When i connect it to my computer, I can manage it through pronterface (with the USB cable I used for the RPI...

LordDarkneo · November 28, 2020, 11:03am

Hi there,
So... After upgrading the Octoprint on 1.5.0 rc3, upgrading python to 3.7.3, performing sevral reboots with still the same issue... I decided to reboot the printer... And the connection fixed itself.
To be totally clear, I had many "timeouts" when trying to connect. So I restarted the printer once again, and it is now recognized and connected to Octoprint.. I am printing in safe mode through octoprint, and see how it goes.
But after all this journey, could the problem be caused by an hardware problem (mother board)? Because I do not think those random behavior when rebooting the printer are normal....