Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

PSU idle timer ignores non-Marlin (Klipper) g-codes and shuts down when not idle!! #172

Closed
CharlieTemplar opened this issue Mar 6, 2021 · 14 comments
Closed

PSU idle timer ignores non-Marlin (Klipper) g-codes and shuts down when not idle!! #172

CharlieTemplar opened this issue Mar 6, 2021 · 14 comments
Labels
bug completed

Comments

@CharlieTemplar
Copy link

CharlieTemplar commented Mar 6, 2021 •
edited
Loading

What were you doing?

DELTA_CALIBRATE METHOD=manual
after going thru 6 of the 7 points, manually adjusting the z-height with TESTZ command and then moving on to next point with ACCEPT command

What did you expect to happen?

complete the calibration steps and SAVE_CONFIG

What happened instead?

the PSU Plugin decided what I was doing was not worthy of staying powered on for and abruptly shut-off, losing all of the operations and data captured up to that point.

Version of OctoPrint-PSUControl

PSU Control (0.1.11)

Operating System running OctoPrint

Raspbian GNU/Linux 8.0 (jessie)

Printer model & used firmware incl. version

Delta / SKR1.3 / raspi2b / ATX PSU

Link to octoprint.log with octoprnt.plugins.psucontrol set to DEBUG

added below, FULL octoprint.log with DEBUG enabled on octoprint AND the plugin. plus serial.log of the entire conversation
serial.log
octoprint.log

Wiring diagram

NA
@kantlivelong
Copy link
Owner

logs?

@CharlieTemplar
Copy link
Author

CharlieTemplar commented Mar 6, 2021 •
edited
Loading

haven't enabled DEBUG for this as wasn't expecting these commands to be ignored.
I have since turned on DEBUG on the plugin and it doesn't say anything... except isPSUOn : true

2021-03-06 13:50:36,021 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-03-06 14:00:08,135 - octoprint.plugins.logging - INFO - Setting logger octoprint.plugins.psucontrol level to 10
2021-03-06 14:00:11,600 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:16,604 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:21,612 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:26,619 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:31,626 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:36,632 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:41,639 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:46,646 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:51,654 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:00:56,663 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
...

2021-03-06 14:10:32,558 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:10:37,565 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:10:42,569 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:10:47,576 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:10:52,585 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 14:10:57,590 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
...

2021-03-06 14:17:21,622 - octoprint.server.heartbeat - INFO - Server heartbeat <3
...

2021-03-06 14:35:49,759 - octoprint.plugins.psucontrol - INFO - Idle timeout reached after 25 minute(s). Turning heaters off prior to shutting off PSU.
2021-03-06 14:35:49,763 - octoprint.plugins.psucontrol - DEBUG - Heater bed already off.
2021-03-06 14:35:49,765 - octoprint.plugins.psucontrol - DEBUG - Heater tool0 already off.
2021-03-06 14:35:49,768 - octoprint.plugins.psucontrol - DEBUG - Heater tool0 = 19.1C
2021-03-06 14:35:49,770 - octoprint.plugins.psucontrol - INFO - Heaters below temperature.
2021-03-06 14:35:49,785 - octoprint.plugins.psucontrol - INFO - Switching PSU Off
2021-03-06 14:35:49,787 - octoprint.plugins.psucontrol - DEBUG - Switching PSU Off Using GPIO: 4
2021-03-06 14:35:49,954 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Offline"
2021-03-06 14:35:49,967 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-03-06 14:35:50,117 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: False

I was running though the klipper style commands during this. The idle timer is set for 25 mins and probably G28 will not be classed as idle so probably ran G28 at 14:10:49 and everything else was Klipper macros and commands...

@kantlivelong
Copy link
Owner

Going to need full logs. May as well include serial logs.

@CharlieTemplar
Copy link
Author

CharlieTemplar commented Mar 6, 2021 •
edited
Loading

Serial logs not enabled nor is general DEBUG, just DEBUG on plugin and the full log is the same as above except I chopped of the repeated isPSUon and some of the heartbeats every 15 mins, otherwise, that was all she wrote...
FULL logs below!

@CharlieTemplar
Copy link
Author

octoprint.log with octoprint DEBUG and plugin DEBUG and idle timer set to 2 mins

2021-03-06 15:08:40,587 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: False
2021-03-06 15:08:45,071 - octoprint.plugins.psucontrol - INFO - Switching PSU On
2021-03-06 15:08:45,074 - octoprint.plugins.psucontrol - DEBUG - Switching PSU On Using GPIO: 4
2021-03-06 15:08:45,223 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:08:50,233 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:08:52,308 - octoprint.events.fire - DEBUG - Firing event: Connecting (Payload: None)
2021-03-06 15:08:52,310 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:52,315 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:52,317 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:52,322 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:52,327 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:52,331 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:52,334 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:52,338 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:52,411 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:52,415 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:52,417 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:52,418 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:52,422 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:08:52,511 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Opening serial connection"
2021-03-06 15:08:52,519 - octoprint.util.comm - INFO - Connecting to port /tmp/printer, baudrate 250000
2021-03-06 15:08:52,528 - octoprint.events.fire - DEBUG - Firing event: PrinterStateChanged (Payload: {u'state_id': 'OPEN_SERIAL', u'state_string': u'Opening serial connection'})
2021-03-06 15:08:52,554 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:52,559 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:52,564 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:52,565 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:52,568 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:52,573 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:52,574 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:52,576 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial connection" to "Connecting"
2021-03-06 15:08:52,578 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:52,587 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:52,590 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:52,591 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:52,592 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:52,593 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:08:52,595 - octoprint.events.fire - DEBUG - Firing event: PrinterStateChanged (Payload: {u'state_id': 'CONNECTING', u'state_string': u'Connecting'})
2021-03-06 15:08:52,596 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:52,603 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:52,610 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:52,611 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:52,616 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-06 15:08:52,621 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:52,624 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:52,629 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:52,634 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-06 15:08:52,642 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:52,651 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:52,658 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:52,655 - octoprint.util.comm - INFO - Changing monitoring state from "Connecting" to "Operational"
2021-03-06 15:08:52,662 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:52,671 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:52,684 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:08:52,789 - octoprint.events.fire - DEBUG - Firing event: PrinterStateChanged (Payload: {u'state_id': 'OPERATIONAL', u'state_string': u'Operational'})
2021-03-06 15:08:52,790 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:52,797 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-03-06 15:08:52,808 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:52,809 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:52,811 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:52,812 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:52,814 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:52,815 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:52,821 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:52,827 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:52,833 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:52,835 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:52,840 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:52,845 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:08:52,852 - octoprint.events.fire - DEBUG - Firing event: Connected (Payload: {u'baudrate': 250000, u'port': u'/tmp/printer'})
2021-03-06 15:08:52,857 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:52,864 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:52,868 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:52,871 - octoprint.util.comm - INFO - Printer reports firmware name "Klipper"
2021-03-06 15:08:52,873 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:52,874 - octoprint.util.comm - INFO - Detected Klipper firmware, enabling relevant features for issue free communication
2021-03-06 15:08:52,878 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:52,884 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:52,886 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:52,893 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:52,895 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:52,899 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:52,903 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:52,906 - octoprint.plugins.firmwareupdater - INFO - Got CONNECTED event
2021-03-06 15:08:52,910 - octoprint.plugins.firmwareupdater - INFO - Run postflash flag is not set
2021-03-06 15:08:52,913 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:52,921 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:08:52,924 - octoprint.events.fire - DEBUG - Firing event: FirmwareData (Payload: {u'data': {u'FIRMWARE_VERSION': u'v0.9.1-278-g1c1c517', u'FIRMWARE_NAME': u'Klipper'}, u'name': u'Klipper'})
2021-03-06 15:08:52,929 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:52,935 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:52,941 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:52,943 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:52,945 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:52,947 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:52,950 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:52,951 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:52,954 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:52,957 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:52,959 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:52,961 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:52,963 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:08:55,241 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:08:56,733 - octoprint.events.fire - DEBUG - Firing event: FirmwareData (Payload: {u'data': {u'FIRMWARE_VERSION': u'v0.9.1-278-g1c1c517', u'FIRMWARE_NAME': u'Klipper'}, u'name': u'Klipper'})
2021-03-06 15:08:56,736 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:08:56,745 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:08:56,748 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:08:56,752 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:08:56,766 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:08:56,777 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:08:56,778 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:08:56,780 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:08:56,792 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:08:56,796 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:08:56,802 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:08:56,811 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:08:56,823 - octoprint.util.comm - WARNING - Received an error from the printer's firmware: Lost communication with MCU 'mcu'
| Last lines in terminal:
| Changing monitoring state from "Opening serial connection" to "Connecting"
| Connected to: Serial<id=0x6a761950, open=True>(port='/tmp/printer', baudrate=250000, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
| Send: N0 M110 N0*125
| Recv: ok
| Send: N0 M110 N0*125
| Changing monitoring state from "Connecting" to "Operational"
| Recv: ok
| Send: N0 M110 N0*125
| Recv: ok
| Send: N1 M115*39
| Recv: ok FIRMWARE_VERSION:v0.9.1-278-g1c1c517 FIRMWARE_NAME:Klipper
| Send: M115
| Recv: ok FIRMWARE_VERSION:v0.9.1-278-g1c1c517 FIRMWARE_NAME:Klipper
| Send: M503 S0
| Recv: // Lost communication with MCU 'mcu'
| Recv: // Once the underlying issue is corrected, use the
| Recv: // "FIRMWARE_RESTART" command to reset the firmware, reload the
| Recv: // config, and restart the host software.
| Recv: // Printer is shutdown
| Recv: !! Lost communication with MCU 'mcu'
2021-03-06 15:08:56,827 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:09:00,282 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:05,289 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:10,295 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:15,302 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:20,312 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:25,276 - octoprint.events.fire - DEBUG - Firing event: Home (Payload: None)
2021-03-06 15:09:25,279 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:09:25,286 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:09:25,322 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:09:25,323 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:25,327 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:09:25,340 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:09:25,357 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:09:25,369 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:09:25,375 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:09:25,382 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:09:25,389 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:09:25,392 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:09:25,397 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:09:25,400 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:09:30,335 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:35,347 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:40,353 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:45,361 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:50,368 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:09:55,376 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:00,384 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:01,590 - octoprint.plugins.logging - INFO - Setting logger octoprint level to 10
2021-03-06 15:10:01,591 - octoprint.plugins.logging - INFO - Setting logger octoprint.plugins.psucontrol level to 10
2021-03-06 15:10:04,062 - octoprint.events.fire - DEBUG - Firing event: SettingsUpdated (Payload: {u'effective_hash': '35892c156235529a53242cb3b33b3b42', u'config_hash': '5fc484a0e1b1f71b583c2d6c6f083b93'})
2021-03-06 15:10:04,063 - octoprint.events - DEBUG - Sending action to <function on_settings_update at 0x6ff2b430>
2021-03-06 15:10:04,070 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:10:04,074 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:10:04,077 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:10:04,081 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:10:04,086 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:10:04,089 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:10:04,091 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:10:04,094 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:10:04,096 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:10:04,100 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:10:04,102 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:10:04,105 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:10:04,109 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:10:05,405 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:10,411 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:15,417 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:20,424 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:25,431 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:28,058 - octoprint.events.fire - DEBUG - Firing event: Home (Payload: None)
2021-03-06 15:10:28,062 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:10:28,100 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:10:28,112 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:10:28,115 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:10:28,117 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:10:28,118 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:10:28,120 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:10:28,122 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:10:28,124 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:10:28,129 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:10:28,131 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:10:28,134 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:10:28,136 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:10:30,439 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:35,447 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:40,454 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:45,462 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:50,469 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:10:55,477 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:00,484 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:05,489 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:10,497 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:15,505 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:20,509 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:25,516 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:30,525 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:35,533 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:40,543 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:45,550 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:50,556 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:11:55,563 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:00,570 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:05,577 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:10,582 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:15,588 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:20,595 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:25,603 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2021-03-06 15:12:28,068 - octoprint.plugins.psucontrol - INFO - Idle timeout reached after 2 minute(s). Turning heaters off prior to shutting off PSU.
2021-03-06 15:12:28,071 - octoprint.plugins.psucontrol - DEBUG - Heater bed already off.
2021-03-06 15:12:28,073 - octoprint.plugins.psucontrol - DEBUG - Heater tool0 already off.
2021-03-06 15:12:28,074 - octoprint.plugins.psucontrol - DEBUG - Heater tool0 = 19.7C
2021-03-06 15:12:28,077 - octoprint.plugins.psucontrol - INFO - Heaters below temperature.
2021-03-06 15:12:28,085 - octoprint.plugins.psucontrol - INFO - Switching PSU Off
2021-03-06 15:12:28,089 - octoprint.plugins.psucontrol - DEBUG - Switching PSU Off Using GPIO: 4
2021-03-06 15:12:28,093 - octoprint.events.fire - DEBUG - Firing event: Disconnecting (Payload: None)
2021-03-06 15:12:28,132 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:12:28,170 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:12:28,225 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:12:28,247 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:12:28,252 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:12:28,256 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:12:28,259 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:12:28,257 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Offline"
2021-03-06 15:12:28,261 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:12:28,263 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:12:28,270 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:12:28,273 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:12:28,277 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:12:28,279 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:12:28,282 - octoprint.events.fire - DEBUG - Firing event: Disconnected (Payload: None)
2021-03-06 15:12:28,284 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:12:28,289 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:12:28,297 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2021-03-06 15:12:28,300 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:12:28,301 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:12:28,302 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:12:28,303 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:12:28,311 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:12:28,315 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:12:28,316 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:12:28,318 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:12:28,337 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:12:28,340 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:12:28,346 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:12:28,348 - octoprint.events.fire - DEBUG - Firing event: PrinterStateChanged (Payload: {u'state_id': u'OFFLINE', u'state_string': u'Offline'})
2021-03-06 15:12:28,351 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69a4b030>>
2021-03-06 15:12:28,356 - octoprint.plugin - DEBUG - Calling on_event on action_command_notification
2021-03-06 15:12:28,364 - octoprint.plugin - DEBUG - Calling on_event on action_command_prompt
2021-03-06 15:12:28,370 - octoprint.plugin - DEBUG - Calling on_event on announcements
2021-03-06 15:12:28,371 - octoprint.plugin - DEBUG - Calling on_event on file_check
2021-03-06 15:12:28,373 - octoprint.plugin - DEBUG - Calling on_event on firmware_check
2021-03-06 15:12:28,375 - octoprint.plugin - DEBUG - Calling on_event on pluginmanager
2021-03-06 15:12:28,377 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: False
2021-03-06 15:12:28,379 - octoprint.plugin - DEBUG - Calling on_event on softwareupdate
2021-03-06 15:12:28,385 - octoprint.plugin - DEBUG - Calling on_event on tracking
2021-03-06 15:12:28,389 - octoprint.plugin - DEBUG - Calling on_event on cancelobject
2021-03-06 15:12:28,392 - octoprint.plugin - DEBUG - Calling on_event on firmwareupdater
2021-03-06 15:12:28,393 - octoprint.plugin - DEBUG - Calling on_event on klipper
2021-03-06 15:12:28,397 - octoprint.plugin - DEBUG - Calling on_event on psucontrol
2021-03-06 15:12:33,387 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: False

serial.log

2021-03-06 14:50:58,200 - serial.log is currently not enabled, you can enable it via Settings > Serial Connection > Log communication to serial.log
2021-03-06 15:08:12,053 - Enabling serial logging
2021-03-06 15:08:52,500 - Changing monitoring state from "Offline" to "Opening serial connection"
2021-03-06 15:08:52,539 - Connecting to port /tmp/printer, baudrate 250000
2021-03-06 15:08:52,576 - Changing monitoring state from "Opening serial connection" to "Connecting"
2021-03-06 15:08:52,601 - Connected to: Serial<id=0x6a761950, open=True>(port='/tmp/printer', baudrate=250000, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2021-03-06 15:08:52,625 - Send: N0 M110 N0*125
2021-03-06 15:08:52,634 - Recv: ok
2021-03-06 15:08:52,646 - Send: N0 M110 N0*125
2021-03-06 15:08:52,654 - Changing monitoring state from "Connecting" to "Operational"
2021-03-06 15:08:52,790 - Recv: ok
2021-03-06 15:08:52,803 - Send: N0 M110 N0*125
2021-03-06 15:08:52,819 - Recv: ok
2021-03-06 15:08:52,834 - Send: N1 M115*39
2021-03-06 15:08:52,844 - Recv: ok FIRMWARE_VERSION:v0.9.1-278-g1c1c517 FIRMWARE_NAME:Klipper
2021-03-06 15:08:56,670 - Send: M115
2021-03-06 15:08:56,703 - Recv: ok FIRMWARE_VERSION:v0.9.1-278-g1c1c517 FIRMWARE_NAME:Klipper
2021-03-06 15:08:56,732 - Send: M503 S0
2021-03-06 15:08:56,768 - Recv: // Lost communication with MCU 'mcu'
2021-03-06 15:08:56,782 - Recv: // Once the underlying issue is corrected, use the
2021-03-06 15:08:56,800 - Recv: // "FIRMWARE_RESTART" command to reset the firmware, reload the
2021-03-06 15:08:56,804 - Recv: // config, and restart the host software.
2021-03-06 15:08:56,809 - Recv: // Printer is shutdown
2021-03-06 15:08:56,813 - Recv: !! Lost communication with MCU 'mcu'
2021-03-06 15:08:56,839 - Recv: ok
2021-03-06 15:08:57,654 - Send: M105
2021-03-06 15:08:57,658 - Recv: ok B:0.0 /0.0 T0:0.0 /0.0
2021-03-06 15:09:02,580 - Send: FIRMWARE_RESTART
2021-03-06 15:09:02,598 - Recv: ok
2021-03-06 15:09:02,603 - Recv: // Klipper state: Disconnect
2021-03-06 15:09:02,658 - Send: M105
2021-03-06 15:09:06,133 - Recv: ok T:0
2021-03-06 15:09:07,456 - Recv: // Klipper state: Ready
2021-03-06 15:09:07,661 - Send: M105
2021-03-06 15:09:07,665 - Recv: ok B:0.0 /0.0 T0:0.0 /0.0
2021-03-06 15:09:12,664 - Send: M105
2021-03-06 15:09:12,677 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:09:17,667 - Send: M105
2021-03-06 15:09:17,687 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:09:22,670 - Send: M105
2021-03-06 15:09:22,675 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:09:25,288 - Send: G28
2021-03-06 15:09:31,311 - Recv: ok
2021-03-06 15:09:32,678 - Send: M105
2021-03-06 15:09:32,694 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:09:37,680 - Send: M105
2021-03-06 15:09:37,695 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:09:42,684 - Send: M105
2021-03-06 15:09:42,688 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:09:47,687 - Send: M105
2021-03-06 15:09:47,703 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:09:52,690 - Send: M105
2021-03-06 15:09:52,700 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:09:57,694 - Send: M105
2021-03-06 15:09:57,706 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:02,699 - Send: M105
2021-03-06 15:10:02,709 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:07,701 - Send: M105
2021-03-06 15:10:07,713 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:12,705 - Send: M105
2021-03-06 15:10:12,714 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:17,708 - Send: M105
2021-03-06 15:10:17,720 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:10:22,710 - Send: M105
2021-03-06 15:10:22,731 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:27,717 - Send: M105
2021-03-06 15:10:27,730 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:28,059 - Send: G28
2021-03-06 15:10:28,933 - Recv: ok
2021-03-06 15:10:32,720 - Send: M105
2021-03-06 15:10:32,737 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:10:33,122 - Send: DELTA_CALIBRATE METHOD=manual
2021-03-06 15:10:33,144 - Recv: // Starting manual Z probe. Use TESTZ to adjust position.
2021-03-06 15:10:33,151 - Recv: // Finish with ACCEPT or ABORT command.
2021-03-06 15:10:33,258 - Recv: // Z position: ?????? --> 4.999 <-- ??????
2021-03-06 15:10:33,261 - Recv: ok
2021-03-06 15:10:37,723 - Send: M105
2021-03-06 15:10:37,740 - Recv: ok B:20.4 /0.0 T0:19.6 /0.0
2021-03-06 15:10:42,726 - Send: M105
2021-03-06 15:10:42,737 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:10:47,609 - Send: TESTZ z=-1
2021-03-06 15:10:47,651 - Recv: // Z position: ?????? --> 3.998 <-- 4.999
2021-03-06 15:10:47,658 - Recv: ok
2021-03-06 15:10:47,730 - Send: M105
2021-03-06 15:10:47,734 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:10:50,418 - Send: TESTZ z=-1
2021-03-06 15:10:50,448 - Recv: // Z position: ?????? --> 2.998 <-- 3.998
2021-03-06 15:10:50,454 - Recv: ok
2021-03-06 15:10:52,734 - Send: M105
2021-03-06 15:10:52,751 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:10:52,940 - Send: TESTZ z=-1
2021-03-06 15:10:52,949 - Recv: // Z position: ?????? --> 1.998 <-- 2.998
2021-03-06 15:10:52,963 - Recv: ok
2021-03-06 15:10:55,742 - Send: TESTZ z=-1
2021-03-06 15:10:55,762 - Recv: // Z position: ?????? --> 0.998 <-- 1.998
2021-03-06 15:10:55,770 - Recv: ok
2021-03-06 15:10:57,738 - Send: M105
2021-03-06 15:10:57,756 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:11:00,652 - Send: TESTZ z=-.1
2021-03-06 15:11:00,686 - Recv: // Z position: ?????? --> 0.898 <-- 0.998
2021-03-06 15:11:00,694 - Recv: ok
2021-03-06 15:11:02,740 - Send: M105
2021-03-06 15:11:02,758 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:11:04,049 - Send: TESTZ z=-.1
2021-03-06 15:11:04,076 - Recv: // Z position: ?????? --> 0.798 <-- 0.898
2021-03-06 15:11:04,084 - Recv: ok
2021-03-06 15:11:07,438 - Send: TESTZ z=-.1
2021-03-06 15:11:07,454 - Recv: // Z position: ?????? --> 0.698 <-- 0.798
2021-03-06 15:11:07,465 - Recv: ok
2021-03-06 15:11:07,742 - Send: M105
2021-03-06 15:11:07,745 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:11,176 - Send: TESTZ z=-.1
2021-03-06 15:11:11,220 - Recv: // Z position: ?????? --> 0.598 <-- 0.698
2021-03-06 15:11:11,231 - Recv: ok
2021-03-06 15:11:12,746 - Send: M105
2021-03-06 15:11:12,761 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:14,926 - Send: TESTZ z=-.1
2021-03-06 15:11:14,947 - Recv: // Z position: ?????? --> 0.498 <-- 0.598
2021-03-06 15:11:14,965 - Recv: ok
2021-03-06 15:11:17,750 - Send: M105
2021-03-06 15:11:17,770 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:17,955 - Send: TESTZ z=-.1
2021-03-06 15:11:17,979 - Recv: // Z position: ?????? --> 0.398 <-- 0.498
2021-03-06 15:11:17,994 - Recv: ok
2021-03-06 15:11:21,135 - Send: TESTZ z=-.1
2021-03-06 15:11:21,152 - Recv: // Z position: ?????? --> 0.298 <-- 0.398
2021-03-06 15:11:21,163 - Recv: ok
2021-03-06 15:11:22,759 - Send: M105
2021-03-06 15:11:22,763 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:11:24,117 - Send: TESTZ z=-.1
2021-03-06 15:11:24,163 - Recv: // Z position: ?????? --> 0.198 <-- 0.298
2021-03-06 15:11:24,172 - Recv: ok
2021-03-06 15:11:27,526 - Send: TESTZ z=-.1
2021-03-06 15:11:27,546 - Recv: // Z position: ?????? --> 0.098 <-- 0.198
2021-03-06 15:11:27,565 - Recv: ok
2021-03-06 15:11:27,756 - Send: M105
2021-03-06 15:11:27,759 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:30,010 - Send: TESTZ z=-.1
2021-03-06 15:11:30,037 - Recv: // Z position: ?????? --> -0.002 <-- 0.098
2021-03-06 15:11:30,044 - Recv: ok
2021-03-06 15:11:32,760 - Send: M105
2021-03-06 15:11:32,775 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:37,763 - Send: M105
2021-03-06 15:11:37,780 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:42,766 - Send: M105
2021-03-06 15:11:42,771 - Recv: ok B:20.5 /0.0 T0:19.8 /0.0
2021-03-06 15:11:46,198 - Send: accept
2021-03-06 15:11:46,222 - Recv: // Starting manual Z probe. Use TESTZ to adjust position.
2021-03-06 15:11:46,238 - Recv: // Finish with ACCEPT or ABORT command.
2021-03-06 15:11:46,249 - Recv: // Z position: ?????? --> 4.998 <-- ??????
2021-03-06 15:11:46,252 - Recv: ok
2021-03-06 15:11:47,769 - Send: M105
2021-03-06 15:11:47,775 - Recv: ok B:20.5 /0.0 T0:19.7 /0.0
2021-03-06 15:11:52,772 - Send: M105
2021-03-06 15:11:52,783 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:11:57,776 - Send: M105
2021-03-06 15:11:57,796 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:12:02,815 - Send: M105
2021-03-06 15:12:02,831 - Recv: ok B:20.6 /0.0 T0:19.7 /0.0
2021-03-06 15:12:02,837 - Send: TESTZ z=-1
2021-03-06 15:12:02,847 - Recv: // Z position: ?????? --> 3.998 <-- 4.998
2021-03-06 15:12:02,861 - Recv: ok
2021-03-06 15:12:04,973 - Send: TESTZ z=-1
2021-03-06 15:12:05,011 - Recv: // Z position: ?????? --> 2.998 <-- 3.998
2021-03-06 15:12:05,018 - Recv: ok
2021-03-06 15:12:06,530 - Send: TESTZ z=-1
2021-03-06 15:12:06,551 - Recv: // Z position: ?????? --> 1.998 <-- 2.998
2021-03-06 15:12:06,574 - Recv: ok
2021-03-06 15:12:07,823 - Send: M105
2021-03-06 15:12:07,835 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:12:08,415 - Send: TESTZ z=-1
2021-03-06 15:12:08,445 - Recv: // Z position: ?????? --> 0.998 <-- 1.998
2021-03-06 15:12:08,455 - Recv: ok
2021-03-06 15:12:12,826 - Send: M105
2021-03-06 15:12:12,830 - Recv: ok B:20.6 /0.0 T0:19.8 /0.0
2021-03-06 15:12:15,908 - Send: TESTZ z=-.1
2021-03-06 15:12:15,954 - Recv: // Z position: ?????? --> 0.898 <-- 0.998
2021-03-06 15:12:15,966 - Recv: ok
2021-03-06 15:12:17,829 - Send: M105
2021-03-06 15:12:17,845 - Recv: ok B:20.6 /0.0 T0:19.7 /0.0
2021-03-06 15:12:20,776 - Send: TESTZ z=-.1
2021-03-06 15:12:20,800 - Recv: // Z position: ?????? --> 0.798 <-- 0.898
2021-03-06 15:12:20,811 - Recv: ok
2021-03-06 15:12:22,832 - Send: M105
2021-03-06 15:12:22,850 - Recv: ok B:20.6 /0.0 T0:19.7 /0.0
2021-03-06 15:12:25,258 - Send: TESTZ z=-.1
2021-03-06 15:12:25,306 - Recv: // Z position: ?????? --> 0.698 <-- 0.798
2021-03-06 15:12:25,315 - Recv: ok
2021-03-06 15:12:27,835 - Send: M105
2021-03-06 15:12:27,855 - Recv: ok B:20.6 /0.0 T0:19.7 /0.0
2021-03-06 15:12:28,244 - Connection closed, closing down monitor
2021-03-06 15:12:28,254 - Changing monitoring state from "Operational" to "Offline"

@CharlieTemplar
Copy link
Author

@kantlivelong What Information are you still Awaiting?
these are the FULL logs.

@kantlivelong
Copy link
Owner

kantlivelong commented Mar 6, 2021 •
edited
Loading

The octoprint.log is not complete. It lacks startup info or even a rollover notice thus it's a snippet. This ticket so far consisted of a painful attempt at getting logs when none were provided to begin with. Enable serial logs. Wipe the logs. Restart OctoPrint. Re-create issue. UPLOAD logs.

@CharlieTemplar
Copy link
Author

sorry that only including relevant logs caused you such pain :D
serial.log
octoprint.log

@kantlivelong
Copy link
Owner

kantlivelong commented Mar 6, 2021 •
edited
Loading

Not all that familiar with Klipper but I'd imagine the macros(or non-gcode commands) are mostly used outside of normal printing (with exception of tool changes maybe?). #166 once merged/released should fix that. For now you should be able to workaround by using a longer idle timeout as 2 minutes is pretty short (For instance Z probing can take 2+ minutes)

@CharlieTemplar
Copy link
Author

Lol, I set the timeout to 2 mins just to reproduce the issue quicker. Was 25 mins when I first encountered this!
I'll give it a try... is it just those 2 lines.

@CharlieTemplar
Copy link
Author

CharlieTemplar commented Mar 9, 2021 •
edited
Loading

What PSU control option causes the plugin to send the postPowerOn command(s) when printing?
When I press print, even though the PSU is on, PSU control still sends the postOnGcodeScript command:

2021-03-09 21:15:05,669 - Changing monitoring state from "Operational" to "Starting"
2021-03-09 21:15:05,757 - Send: N0 M110 N0*125
2021-03-09 21:15:05,761 - Recv: ok
2021-03-09 21:15:05,928 - PSUControl: ok
2021-03-09 21:15:05,969 - Send: N1 M140 S60*82
2021-03-09 21:15:05,996 - Recv: ok
2021-03-09 21:15:06,037 - Send: FIRMWARE_RESTART
2021-03-09 21:15:07,090 - Recv: ok
2021-03-09 21:15:07,098 - Recv: // Klipper state: Disconnect
2021-03-09 21:15:07,104 - Changing monitoring state from "Starting" to "Printing"
2021-03-09 21:15:07,147 - Send: N2 M105*37
2021-03-09 21:15:10,690 - Recv: ok T:0
2021-03-09 21:15:10,723 - Send: N3 M105*36
2021-03-09 21:15:10,730 - Recv: ok T:0
2021-03-09 21:15:10,739 - Send: N4 M190 S60*90
2021-03-09 21:15:10,746 - Recv: // Printer is not ready
2021-03-09 21:15:10,758 - Recv: // The klippy host software is attempting to connect.  Please
2021-03-09 21:15:10,760 - Recv: // retry in a few moments.
2021-03-09 21:15:10,764 - Recv: !! Printer is not ready
2021-03-09 21:15:10,808 - Changing monitoring state from "Printing" to "Cancelling"
2021-03-09 21:15:11,399 - Recv: ok
2021-03-09 21:15:11,416 - Send: N5 G28*22
2021-03-09 21:15:11,426 - Send: N6 M84*25
2021-03-09 21:15:11,434 - Recv: // Printer is not ready
2021-03-09 21:15:11,519 - Recv: // The klippy host software is attempting to connect.  Please
2021-03-09 21:15:11,534 - Recv: // retry in a few moments.
2021-03-09 21:15:11,545 - Recv: !! Printer is not ready

I implemented the above mentioned fix to recognise klipper commands, don't know if this is related

@kantlivelong
Copy link
Owner

Is this a separate issue? If so, open a new ticket with logs.

@kantlivelong
Copy link
Owner

This should be fixed with 23a88bb in devel.

@kantlivelong
Copy link
Owner

v1.0.0 released.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug completed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@kantlivelong @CharlieTemplar