And to add, the post on delay is set to 0.5 secs for now. Let me know if you wanna se any other value there. (and a new set of files or whatever)
What I have seen from the terminal-window in octoprints UI was that a functioning "upload and start" looks like this in the gcodes:
2022-03-18 21:42:44,894 - Changing monitoring state from "Operational" to "Starting"
2022-03-18 21:42:44,954 - Send: N0 M110 N0*125
2022-03-18 21:42:44,967 - Recv: ok
2022-03-18 21:42:44,970 - Changing monitoring state from "Starting" to "Printing"
2022-03-18 21:42:44,978 - Send: N1 M73 P0 R2*22
2022-03-18 21:42:44,998 - Recv: NORMAL MODE: Percent done: 0; print time remaining in mins: 2; Change in mins: -1
2022-03-18 21:42:45,014 - Recv: SILENT MODE: Percent done: -1; print time remaining in mins: -1; Change in mins: -1
...
...
And the case where octoprint turns on the printer via PSU control but does not start the print afterwards looks like this:
2022-03-18 21:40:13,858 - Changing monitoring state from "Offline" to "Detecting serial connection"
2022-03-18 21:40:13,883 - Performing autodetection with 7 port/baudrate candidates: /dev/ttyACM0@115200, /dev/ttyACM0@250000, /dev/ttyACM0@230400, /dev/ttyACM0@57600, /dev/ttyACM0@38400, /dev/ttyACM0@19200, /dev/ttyACM0@9600
2022-03-18 21:40:13,884 - Trying port /dev/ttyACM0, baudrate 115200
2022-03-18 21:40:13,885 - Connecting to port /dev/ttyACM0, baudrate 115200
2022-03-18 21:40:13,899 - Handshake attempt #1 with timeout 2.0s
2022-03-18 21:40:13,902 - Connected to: Serial<id=0xa9ed3bd0, open=True>(port='/dev/ttyACM0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=2.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2022-03-18 21:40:13,904 - Send: N0 M110 N0*125
2022-03-18 21:40:14,948 - Recv: start
2022-03-18 21:40:14,953 - Changing monitoring state from "Detecting serial connection" to "Operational"
2022-03-18 21:40:14,998 - Send: N0 M110 N0*125
2022-03-18 21:40:15,018 - Recv: echo: 3.10.1-4697
...
...
Looks the same in serial.log.
What I can see from octoprint.log is when its not working its like this:
2022-03-18 21:40:13,990 - octoprint.filemanager.analysis - INFO - Starting analysis of local:filler_0.2mm_PLA_MK3S_2m.gcode
2022-03-18 21:40:14,005 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: filler_0.2mm_PLA_MK3S_2m.gcode, owner: Andreas, user: Andreas
2022-03-18 21:40:14,651 - octoprint.filemanager.analysis - INFO - Analysis of entry local:filler_0.2mm_PLA_MK3S_2m.gcode finished, needed 0.66s
2022-03-18 21:40:14,849 - octoprint.plugins.psucontrol - DEBUG - Polling PSU state...
2022-03-18 21:40:14,884 - octoprint.plugins.psucontrol_shelly - DEBUG - url=http://192.168.1.128/relay/0, status_code=200, text={"ison":true,"has_timer":false,"timer_started":0,"timer_duration":0,"timer_remaining":0,"overpower":false,"source":"http"}
2022-03-18 21:40:14,885 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2022-03-18 21:40:14,953 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Operational"
2022-03-18 21:40:14,997 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2022-03-18 21:40:15,004 - octoprint.plugins.firmwareupdater - INFO - Got CONNECTED event
2022-03-18 21:40:15,008 - octoprint.plugins.firmwareupdater - INFO - Run postflash flag is not set
2022-03-18 21:40:15,887 - octoprint.plugins.psucontrol - DEBUG - Polling PSU state...
2022-03-18 21:40:15,917 - octoprint.plugins.psucontrol_shelly - DEBUG - url=http://192.168.1.128/relay/0, status_code=200, text={"ison":true,"has_timer":false,"timer_started":0,"timer_duration":0,"timer_remaining":0,"overpower":false,"source":"http"}
2022-03-18 21:40:15,918 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2022-03-18 21:40:16,921 - octoprint.plugins.psucontrol - DEBUG - Polling PSU state...
With the file name of the job filler_0.2mm_PLA_MK3S_2m.gcode can be seen three times (Starting analysis, print job selected, Analysis finished)
Where in the working case (with PSU on beforehand) it looks like this:
2022-03-18 21:42:44,782 - octoprint.filemanager.analysis - INFO - Starting analysis of local:filler_0.2mm_PLA_MK3S_2m.gcode
2022-03-18 21:42:44,788 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: filler_0.2mm_PLA_MK3S_2m.gcode, owner: Andreas, user: Andreas
2022-03-18 21:42:44,844 - octoprint.plugins.psucontrol_shelly - DEBUG - url=http://192.168.1.128/relay/0, status_code=200, text={"ison":true,"has_timer":false,"timer_started":0,"timer_duration":0,"timer_remaining":0,"overpower":false,"source":"http"}
2022-03-18 21:42:44,845 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2022-03-18 21:42:44,894 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2022-03-18 21:42:44,907 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: filler_0.2mm_PLA_MK3S_2m.gcode, owner: Andreas, user: Andreas
2022-03-18 21:42:44,953 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2022-03-18 21:42:44,970 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2022-03-18 21:42:45,260 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': 'e48134b4454eb9504b8eacd02622ec58caf9456d'}
2022-03-18 21:42:45,450 - octoprint.filemanager.analysis - INFO - Analysis of entry local:filler_0.2mm_PLA_MK3S_2m.gcode finished, needed 0.67s
2022-03-18 21:42:45,846 - octoprint.plugins.psucontrol - DEBUG - Polling PSU state...
2022-03-18 21:42:45,876 - octoprint.plugins.psucontrol_shelly - DEBUG - url=http://192.168.1.128/relay/0, status_code=200, text={"ison":true,"has_timer":false,"timer_started":0,"timer_duration":0,"timer_remaining":0,"overpower":false,"source":"http"}
2022-03-18 21:42:45,878 - octoprint.plugins.psucontrol - DEBUG - isPSUOn: True
2022-03-18 21:42:46,881 - octoprint.plugins.psucontrol - DEBUG - Polling PSU state...
Where you can find the file name four times. And this essential line is missing in the not-working-case:
2022-03-18 21:42:44,907 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: filler_0.2mm_PLA_MK3S_2m.gcode, owner: Andreas, user: Andreas
I added octoprint.printer.standard.job to the debug logging and deleted the files and restarted Octoprint and redid all the steps.
octoprint-logs_2.zip (74.5 KB)
But I cant see anything here either?!