This is a problem I encounter just recently after running the same setup successfully for like a year. I upgraded octoprint to 1.60 yesterday and had 1 successfull print immediately after upgrading. Today the issue appeared and persists.
Octoprint turns off tool heating and bedheating right when the print starts. I can (and did) set the target temperatures for both again manually, I saw them drop back to 0 a few times until they finally stay up.
I am aware that the description of this issue is very similar to an issue ovisopa reported in January 2019, in that case the culprit was the ABL Expert Plugin. However, I am not using that plugin.
I tried it then in safe mode and the same thing happened so it's rather not caused by a plugin.
I turned on serial logging and what I see is:
2021-04-29 15:41:43,398 - Recv: T:18.36 /0.00 B:18.98 /0.00 @:0 B@:0
2021-04-29 15:41:45,398 - Recv: T:19.22 /0.00 B:18.36 /0.00 @:0 B@:0
2021-04-29 15:41:47,349 - Changing monitoring state from "Operational" to "Starting"
2021-04-29 15:41:47,403 - Send: N0 M110 N0*125
2021-04-29 15:41:47,405 - Communication timeout while printing, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.
2021-04-29 15:41:47,407 - Send: N1 M105*38
2021-04-29 15:41:47,416 - Recv: T:19.06 /0.00 B:17.89 /0.00 @:0 B@:0
2021-04-29 15:41:47,421 - Recv: ok
2021-04-29 15:41:47,424 - Recv: ok T:19.06 /0.00 B:17.89 /0.00 @:0 B@:0
2021-04-29 15:41:47,427 - Changing monitoring state from "Starting" to "Printing"
2021-04-29 15:41:47,440 - Send: N2 M140 S60*81
2021-04-29 15:41:47,447 - Recv: ok
2021-04-29 15:41:47,449 - Send: N3 M105*36
2021-04-29 15:41:47,457 - Recv: ok T:19.06 /0.00 B:17.89 /60.00 @:0 B@:0
2021-04-29 15:41:47,459 - Send: N4 M190 S60*90
2021-04-29 15:41:47,465 - Recv: T:19.06 /0.00 B:17.89 /60.00 @:0 B@:0 W:?
2021-04-29 15:41:48,473 - Recv: T:19.77 /0.00 B:17.89 /60.00 @:0 B@:0 W:?
2021-04-29 15:41:49,398 - Recv: T:18.67 /0.00 B:17.42 /60.00 @:0 B@:127
2021-04-29 15:41:49,465 - Recv: T:20.20 /0.00 B:19.45 /60.00 @:0 B@:127 W:?
2021-04-29 15:41:49,467 - Recv: echo:busy: processing
2021-04-29 15:41:49,468 - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
<snip>
g
2021-04-29 15:44:12,490 - Recv: T:19.96 /0.00 B:60.41 /60.00 @:0 B@:0 W:1
2021-04-29 15:44:13,425 - Recv: T:20.90 /0.00 B:60.15 /60.00 @:0 B@:0
2021-04-29 15:44:13,490 - Recv: T:20.90 /0.00 B:60.15 /60.00 @:0 B@:0 W:0
2021-04-29 15:44:13,500 - Recv: echo:busy: processing
2021-04-29 15:44:14,402 - Recv: ok
2021-04-29 15:44:14,404 - Send: N5 M113 S2*100
2021-04-29 15:44:14,408 - Recv: ok
2021-04-29 15:44:14,410 - Send: N6 M104 S225*102
2021-04-29 15:44:14,413 - Recv: ok
2021-04-29 15:44:14,415 - Send: N7 M105*32
2021-04-29 15:44:14,429 - Recv: ok T:22.30 /225.00 B:60.08 /60.00 @:0 B@:0
2021-04-29 15:44:14,433 - Send: N8 M109 S225*101
2021-04-29 15:44:14,444 - Recv: T:22.30 /225.00 B:60.08 /60.00 @:0 B@:0 W:?
2021-04-29 15:44:15,425 - Recv: T:21.52 /225.00 B:59.93 /60.00 @:127 B@:0
2021-04-29 15:44:15,446 - Recv: T:21.52 /225.00 B:59.93 /60.00 @:127 B@:0 W:?
2021-04-29 15:44:16,443 - Recv: T:21.13 /225.00 B:59.49 /60.00 @:127 B@:0 W:?
2021-04-29 15:44:16,446 - Recv: echo:busy: processing
2021-04-29 15:44:17,426 - Recv: T:21.60 /225.00 B:59.00 /60.00 @:127 B@:0
2021-04-29 15:44:17,443 - Recv: T:21.60 /225.00 B:59.00 /60.00 @:127 B@:0 W:?
2021-04-29 15:44:18,443 - Recv: T:22.93 /225.00 B:58.88 /60.00 @:127 B@:127 W:?
2021-04-29 15:44:18,447 - Recv: echo:busy: processing
<snip>
g
2021-04-29 15:46:29,448 - Recv: T:226.87 /225.00 B:60.10 /60.00 @:38 B@:0
2021-04-29 15:46:29,463 - Recv: T:226.87 /225.00 B:60.10 /60.00 @:38 B@:0 W:1
2021-04-29 15:46:30,464 - Recv: T:227.12 /225.00 B:60.09 /60.00 @:37 B@:0 W:0
2021-04-29 15:46:30,479 - Recv: echo:busy: processing
2021-04-29 15:46:31,329 - Recv: ok
2021-04-29 15:46:31,333 - Send: N9 M82*16
2021-04-29 15:46:31,344 - Recv: ok
2021-04-29 15:46:31,348 - Send: N10 M201 X500.00 Y500.00 Z100.00 E5000.00*59
2021-04-29 15:46:31,356 - Recv: ok
2021-04-29 15:46:31,359 - Send: N11 M203 X500.00 Y500.00 Z10.00 E50.00*8
2021-04-29 15:46:31,368 - Recv: ok
2021-04-29 15:46:31,371 - Send: N12 M204 P500.00 R1000.00 T500.00*79
2021-04-29 15:46:31,378 - Recv: ok
2021-04-29 15:46:31,381 - Send: N13 M205 X8.00 Y8.00 Z0.40 E5.00*9
2021-04-29 15:46:31,384 - Recv: ok
2021-04-29 15:46:31,387 - Send: N14 M220 S100*84
2021-04-29 15:46:31,390 - Recv: ok
2021-04-29 15:46:31,393 - Send: N15 M221 S100*84
2021-04-29 15:46:31,396 - Recv: ok
2021-04-29 15:46:31,399 - Send: N16 G91*38
2021-04-29 15:46:31,402 - Recv: ok
2021-04-29 15:46:31,404 - Send: N17 G1 E-2 F2700*7
2021-04-29 15:46:31,407 - Recv: ok
2021-04-29 15:46:31,410 - Send: N18 G1 E-2 Z0.2 F2400*93
2021-04-29 15:46:31,417 - Recv: ok
2021-04-29 15:46:31,422 - Send: N19 G1 E-2 F3700*8
2021-04-29 15:46:31,425 - Recv: ok
2021-04-29 15:46:31,428 - Send: N20 G1 X5 Y5 F3000*126
2021-04-29 15:46:31,431 - Recv: ok
2021-04-29 15:46:31,434 - Send: N21 G1 Z10*96
2021-04-29 15:46:31,441 - Recv: ok
2021-04-29 15:46:31,444 - Send: N22 G90*32
2021-04-29 15:46:31,449 - Recv: T:227.62 /225.00 B:60.12 /60.00 @:30 B@:0
2021-04-29 15:46:31,453 - Recv: ok
2021-04-29 15:46:31,455 - Send: N23 G1 X0 Y235*28
2021-04-29 15:46:31,458 - Recv: ok
2021-04-29 15:46:31,460 - Send: N24 M106 S0*81
2021-04-29 15:46:31,463 - Recv: ok
2021-04-29 15:46:31,465 - Send: N25 M104 S0*82
2021-04-29 15:46:31,476 - Recv: ok
2021-04-29 15:46:31,479 - Send: N26 M140 S0*81
2021-04-29 15:46:31,490 - Recv: ok
2021-04-29 15:46:31,493 - Send: N27 M84 X Y E*78
2021-04-29 15:46:33,449 - Recv: T:227.62 /0.00 B:59.84 /0.00 @:0 B@:0
2021-04-29 15:46:33,498 - Recv: echo:busy: processing
2021-04-29 15:46:35,449 - Recv: T:227.00 /0.00 B:59.52 /0.00 @:0 B@:0
2021-04-29 15:46:35,499 - Recv: echo:busy: processing
2021-04-29 15:46:37,448 - Recv: T:226.56 /0.00 B:58.79 /0.00 @:0 B@:0
2021-04-29 15:46:37,499 - Recv: echo:busy: processing
2021-04-29 15:46:38,445 - Recv: ok
2021-04-29 15:46:38,448 - Send: N28 G28*41
2021-04-29 15:46:39,449 - Recv: T:225.12 /0.00 B:58.54 /0.00 @:0 B@:0
2021-04-29 15:46:40,456 - Recv: echo:busy: processing
2021-04-29 15:46:41,449 - Recv: T:223.48 /0.00 B:58.54 /0.00 @:0 B@:0
2021-04-29 15:46:42,456 - Recv: echo:busy: processing
2021-04-29 15:46:43,449 - Recv: T:221.70 /0.00 B:58.54 /0.00 @:0 B@:0
2021-04-29 15:46:44,457 - Recv: echo:busy: processing
So, the issue happens at (or shortly before) 15:46:31,460
I took a look into the octoprint.log:
2021-04-29 15:41:47,427 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2021-04-29 15:41:49,468 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2021-04-29 15:44:14,405 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2021-04-29 15:46:52,643 - octoprint.util.comm - INFO - Pausing/resuming job on behalf of user dp
(Yes, I hit the Pause-button immediately when I saw it dropping to 0)
So, nothing.
Systeminfo Bundle
octoprint-systeminfo-20210429155840.zip (101.2 KB)
Additional information about your setup
OctoPrint version 1.6.0 , OctoPi version 0.18.0 , printer Ender3, firmware Marlin (bugfix, been running for 1,5 years), ff 88.0, recent changes: update of octoprint
I came here in the hope of finding other reports but I saw none. Setting the target temperatures manually again and again during strt is possible but no fun. Any pointers where to search very much appreciated, TIA
edit: Typo