Temp target ignored, nozzle changes to 170 degrees before first layer

Get Help
1

Hi, I added a Pi with Octoprint to my Ender 6 running a BTT mainboard with Marlin firmware. When I start a print using the screen, it works just fine. But when I start a print from Octoprint, the following happens:

  1. Printer heats bed to 60 and nozzle to 150
  2. Printer starts probing (BLTOUCH)
  3. Just before the first layer, the printer should heat to 195 (which is stated in the GCODE file), but instead the printer heats to 170 degrees and beeps at me because it's preventing cold extrusion.

Tried printing the same GCODE file from the printer screen, that works. It doesn't matter what nozzle temperature I use in my slicer, it's being changed to 170 degrees when I use octoprint.

This is the start of my gcode file, I don't think this is the problem:

M201 X5000 Y5000 Z100 E1000 ; sets maximum accelerations, mm/sec^2
M203 X500 Y500 Z10 E100 ; sets maximum feedrates, mm/sec
M204 P200 R1000 T200 ; sets acceleration (P, T) and retract acceleration (R), mm/sec^2
M205 X10.00 Y10.00 Z0.30 E0.50 ; sets the jerk limits, mm/sec
M205 S0 T0 ; sets the minimum extruding and travel feed rate, mm/sec
M107
;TYPE:Custom
G90 ; use absolute coordinates
M83 ; extruder relative mode
M104 S150 ; set extruder temp for auto bed leveling
M140 S60 ; set bed temp
M190 S60 ; wait for bed temp
G28 ; home all
G29 ; auto bed levelling
G1 Z50 F240
G1 X2 Y10 F3000
M104 S195 ; set extruder temp
M109 S195 ; wait for extruder temp
G1 Z0.28 F240
G92 E0
G1 Y190 E15 F1500 ; intro line

Serial.log which shows that the temp target changes to 170 before the first layer:

2021-02-19 13:07:28,579 - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-02-19 13:07:28,622 - 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
2021-02-19 13:07:28,623 - Trying port /dev/ttyACM0, baudrate 115200
2021-02-19 13:07:28,624 - Connecting to port /dev/ttyACM0, baudrate 115200
2021-02-19 13:07:28,630 - Handshake attempt #1 with timeout 2.0s
2021-02-19 13:07:28,632 - Connected to: Serial<id=0x72f23870, open=True>(port='/dev/ttyACM0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=2.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2021-02-19 13:07:28,635 - Send: N0 M110 N0*125
2021-02-19 13:07:30,638 - Handshake attempt #2 with timeout 2.0s
2021-02-19 13:07:30,653 - Send: N0 M110 N0*125
2021-02-19 13:07:32,523 - Recv: DIGIPOTS Loading
2021-02-19 13:07:32,530 - Recv: DIGIPOTS Loaded
2021-02-19 13:07:33,762 - Recv: DIGIPOTS Loading
2021-02-19 13:07:33,764 - Handshake attempt #3 with timeout 2.0s
2021-02-19 13:07:33,778 - Send: N0 M110 N0*125
2021-02-19 13:07:33,781 - Recv: DIGIPOTS Loaded
2021-02-19 13:07:33,840 - Recv: echo:V82 stored settings retrieved (646 bytes; crc 243)
2021-02-19 13:07:35,500 - Recv: Testing X connection... OK
2021-02-19 13:07:35,509 - Recv: Testing Y connection... OK
2021-02-19 13:07:35,515 - Recv: Testing Z connection... OK
2021-02-19 13:07:35,518 - Recv: Testing E connection... OK
2021-02-19 13:07:36,014 - Recv: echo:SD card ok
2021-02-19 13:07:36,019 - Trying port /dev/ttyACM0, baudrate 250000
2021-02-19 13:07:36,032 - Handshake attempt #1 with timeout 2.0s
2021-02-19 13:07:36,039 - Recv: ok
2021-02-19 13:07:36,043 - Send: N0 M110 N0*125
2021-02-19 13:07:36,049 - Changing monitoring state from "Detecting serial connection" to "Operational"
2021-02-19 13:07:36,127 - Recv: ok
2021-02-19 13:07:36,129 - Recv: ok
2021-02-19 13:07:36,131 - Recv: ok
2021-02-19 13:07:36,133 - Send: N0 M110 N0*125
2021-02-19 13:07:36,165 - Recv: ok
2021-02-19 13:07:36,177 - Send: N1 M115*39
2021-02-19 13:07:36,248 - Recv: FIRMWARE_NAME:Marlin 2.0.7.2 (Feb 17 2021 20:20:58) SOURCE_CODE_URL:https://github.com/MarlinFirmware/Marlin PROTOCOL_VERSION:1.0 MACHINE_TYPE:Ender-5 Plus EXTRUDER_COUNT:1 UUID:5a37052e-424e-4819-8efe-d9ce53788ab2
2021-02-19 13:07:36,251 - Recv: Cap:SERIAL_XON_XOFF:0
2021-02-19 13:07:36,254 - Recv: Cap:BINARY_FILE_TRANSFER:0
2021-02-19 13:07:36,267 - Recv: Cap:EEPROM:1
2021-02-19 13:07:36,276 - Recv: Cap:VOLUMETRIC:1
2021-02-19 13:07:36,280 - Recv: Cap:AUTOREPORT_TEMP:1
2021-02-19 13:07:36,286 - Recv: Cap:PROGRESS:0
2021-02-19 13:07:36,291 - Recv: Cap:PRINT_JOB:1
2021-02-19 13:07:36,298 - Recv: Cap:AUTOLEVEL:1
2021-02-19 13:07:36,304 - Recv: Cap:RUNOUT:1
2021-02-19 13:07:36,309 - Recv: Cap:Z_PROBE:1
2021-02-19 13:07:36,314 - Recv: Cap:LEVELING_DATA:1
2021-02-19 13:07:36,319 - Recv: Cap:BUILD_PERCENT:1
2021-02-19 13:07:36,323 - Recv: Cap:SOFTWARE_POWER:0
2021-02-19 13:07:36,326 - Recv: Cap:TOGGLE_LIGHTS:0
2021-02-19 13:07:36,330 - Recv: Cap:CASE_LIGHT_BRIGHTNESS:0
2021-02-19 13:07:36,334 - Recv: Cap:EMERGENCY_PARSER:0
2021-02-19 13:07:36,338 - Recv: Cap:PROMPT_SUPPORT:0
2021-02-19 13:07:36,341 - Recv: Cap:SDCARD:1
2021-02-19 13:07:36,345 - Recv: Cap:AUTOREPORT_SD_STATUS:0
2021-02-19 13:07:36,348 - Recv: Cap:LONG_FILENAME:1
2021-02-19 13:07:36,353 - Recv: Cap:THERMAL_PROTECTION:1
2021-02-19 13:07:36,359 - Recv: Cap:MOTION_MODES:0
2021-02-19 13:07:36,363 - Recv: Cap:ARCS:1
2021-02-19 13:07:36,368 - Recv: Cap:BABYSTEPPING:1
2021-02-19 13:07:36,373 - Recv: Cap:CHAMBER_TEMPERATURE:0
2021-02-19 13:07:36,379 - Recv: ok
2021-02-19 13:07:36,381 - Send: M20
2021-02-19 13:07:36,384 - Recv: Begin file list
2021-02-19 13:07:36,388 - Recv: End file list
2021-02-19 13:07:36,390 - Recv: ok
2021-02-19 13:07:36,392 - Send: M420V1
2021-02-19 13:07:36,398 - Recv: Bed Level Correction Matrix:
2021-02-19 13:07:36,400 - Recv: +1.000000 +0.000000 -0.000110
2021-02-19 13:07:36,402 - Recv: +0.000000 +1.000000 +0.000684
2021-02-19 13:07:36,404 - Recv: +0.000110 -0.000684 +1.000000
2021-02-19 13:07:36,405 - Recv: echo:Bed Leveling OFF
2021-02-19 13:07:36,408 - Recv: ok
2021-02-19 13:07:36,410 - Send: M851
2021-02-19 13:07:36,414 - Recv: Probe Offset X-20.70 Y-7.00 Z-2.95
2021-02-19 13:07:36,416 - Recv: ok
2021-02-19 13:07:36,417 - Send: M155 S2
2021-02-19 13:07:36,419 - Recv: ok
2021-02-19 13:07:38,430 - Recv:  T:90.81 /0.00 B:58.93 /0.00 @:0 B@:0
2021-02-19 13:07:40,423 - Recv:  T:89.87 /0.00 B:58.80 /0.00 @:0 B@:0
2021-02-19 13:07:42,423 - Recv:  T:88.93 /0.00 B:58.78 /0.00 @:0 B@:0
2021-02-19 13:07:42,990 - Changing monitoring state from "Operational" to "Starting"
2021-02-19 13:07:43,072 - Send: N0 M110 N0*125
2021-02-19 13:07:43,081 - Recv: ok
2021-02-19 13:07:43,082 - Changing monitoring state from "Starting" to "Printing"
2021-02-19 13:07:43,088 - Send: N1 M201 X5000 Y5000 Z100 E1000*15
2021-02-19 13:07:43,091 - Recv: ok
2021-02-19 13:07:43,093 - Send: N2 M203 X500 Y500 Z10 E100*14
2021-02-19 13:07:43,097 - Recv: ok
2021-02-19 13:07:43,099 - Send: N3 M204 P200 R1000 T200*81
2021-02-19 13:07:43,101 - Recv: ok
2021-02-19 13:07:43,103 - Send: N4 M205 X10.00 Y10.00 Z0.30 E0.50*56
2021-02-19 13:07:43,105 - Recv: ok
2021-02-19 13:07:43,107 - Send: N5 M205 S0 T0*38
2021-02-19 13:07:43,109 - Recv: ok
2021-02-19 13:07:43,111 - Send: N6 M107*35
2021-02-19 13:07:43,112 - Recv: ok
2021-02-19 13:07:43,114 - Send: N7 G90*23
2021-02-19 13:07:43,118 - Recv: ok
2021-02-19 13:07:43,121 - Send: N8 M83*16
2021-02-19 13:07:43,123 - Recv: ok
2021-02-19 13:07:43,127 - Send: N9 M104 S150*104
2021-02-19 13:07:43,131 - Recv: ok
2021-02-19 13:07:43,133 - Send: N10 M140 S60*98
2021-02-19 13:07:43,137 - Recv: ok
2021-02-19 13:07:43,140 - Send: N11 M190 S60*110
2021-02-19 13:07:43,146 - Recv:  T:88.62 /150.00 B:58.78 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:44,147 - Recv:  T:88.23 /150.00 B:58.67 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:44,423 - Recv:  T:88.12 /150.00 B:58.76 /60.00 @:127 B@:0
2021-02-19 13:07:45,146 - Recv:  T:87.84 /150.00 B:58.57 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:45,156 - Recv: echo:busy: processing
2021-02-19 13:07:45,159 - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2021-02-19 13:07:46,146 - Recv:  T:87.71 /150.00 B:58.53 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:46,423 - Recv:  T:87.70 /150.00 B:58.55 /60.00 @:127 B@:0
2021-02-19 13:07:47,147 - Recv:  T:87.81 /150.00 B:58.50 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:47,156 - Recv: echo:busy: processing
2021-02-19 13:07:48,147 - Recv:  T:88.25 /150.00 B:58.50 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:48,423 - Recv:  T:88.35 /150.00 B:58.49 /60.00 @:127 B@:0
2021-02-19 13:07:49,146 - Recv:  T:89.00 /150.00 B:58.45 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:49,155 - Recv: echo:busy: processing
2021-02-19 13:07:50,146 - Recv:  T:90.00 /150.00 B:58.35 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:50,424 - Recv:  T:90.38 /150.00 B:58.42 /60.00 @:127 B@:0
2021-02-19 13:07:51,147 - Recv:  T:91.16 /150.00 B:58.33 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:51,155 - Recv: echo:busy: processing
2021-02-19 13:07:52,147 - Recv:  T:92.80 /150.00 B:58.35 /60.00 @:127 B@:0 W:?
2021-02-19 13:07:52,423 - Recv:  T:93.03 /150.00 B:58.31 /60.00 @:127 B@:15
2021-02-19 13:07:53,147 - Recv:  T:94.32 /150.00 B:58.22 /60.00 @:127 B@:80 W:?
2021-02-19 13:07:53,157 - Recv: echo:busy: processing
2021-02-19 13:07:54,147 - Recv:  T:96.05 /150.00 B:58.20 /60.00 @:127 B@:127 W:?
2021-02-19 13:07:54,424 - Recv:  T:96.64 /150.00 B:58.22 /60.00 @:127 B@:127
2021-02-19 13:07:55,148 - Recv:  T:97.80 /150.00 B:58.19 /60.00 @:127 B@:127 W:?
2021-02-19 13:07:55,156 - Recv: echo:busy: processing
2021-02-19 13:07:56,151 - Recv:  T:99.97 /150.00 B:58.16 /60.00 @:127 B@:127 W:?
2021-02-19 13:07:56,423 - Recv:  T:100.22 /150.00 B:58.16 /60.00 @:127 B@:127
2021-02-19 13:07:57,147 - Recv:  T:101.89 /150.00 B:58.07 /60.00 @:127 B@:127 W:?
2021-02-19 13:07:57,156 - Recv: echo:busy: processing
2021-02-19 13:07:58,147 - Recv:  T:103.69 /150.00 B:58.19 /60.00 @:127 B@:127 W:?
2021-02-19 13:07:58,423 - Recv:  T:104.33 /150.00 B:58.23 /60.00 @:127 B@:127
2021-02-19 13:07:59,147 - Recv:  T:105.62 /150.00 B:58.16 /60.00 @:127 B@:127 W:?
2021-02-19 13:07:59,154 - Recv: echo:busy: processing
2021-02-19 13:08:00,147 - Recv:  T:107.95 /150.00 B:58.35 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:00,423 - Recv:  T:108.25 /150.00 B:58.33 /60.00 @:127 B@:127
2021-02-19 13:08:01,147 - Recv:  T:109.84 /150.00 B:58.40 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:01,159 - Recv: echo:busy: processing
2021-02-19 13:08:02,154 - Recv:  T:111.87 /150.00 B:58.37 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:02,423 - Recv:  T:112.52 /150.00 B:58.41 /60.00 @:127 B@:127
2021-02-19 13:08:03,149 - Recv: echo:busy: processing
2021-02-19 13:08:03,165 - Recv:  T:113.84 /150.00 B:58.52 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:04,163 - Recv:  T:116.15 /150.00 B:58.57 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:04,423 - Recv:  T:116.48 /150.00 B:58.62 /60.00 @:127 B@:127
2021-02-19 13:08:05,149 - Recv: echo:busy: processing
2021-02-19 13:08:05,163 - Recv:  T:118.09 /150.00 B:58.75 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:06,163 - Recv:  T:120.01 /150.00 B:58.74 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:06,423 - Recv:  T:120.66 /150.00 B:58.87 /60.00 @:127 B@:127
2021-02-19 13:08:07,149 - Recv: echo:busy: processing
2021-02-19 13:08:07,164 - Recv:  T:121.97 /150.00 B:58.96 /60.00 @:127 B@:127 W:?
2021-02-19 13:08:08,164 - Recv:  T:124.15 /150.00 B:59.17 /60.00 @:127 B@:127 W:9
2021-02-19 13:08:08,423 - Recv:  T:124.46 /150.00 B:59.17 /60.00 @:127 B@:127
2021-02-19 13:08:09,148 - Recv: echo:busy: processing
2021-02-19 13:08:09,164 - Recv:  T:126.04 /150.00 B:59.18 /60.00 @:127 B@:127 W:8
2021-02-19 13:08:10,164 - Recv:  T:127.96 /150.00 B:59.38 /60.00 @:127 B@:127 W:7
2021-02-19 13:08:10,423 - Recv:  T:128.56 /150.00 B:59.38 /60.00 @:127 B@:127
2021-02-19 13:08:11,148 - Recv: echo:busy: processing
2021-02-19 13:08:11,164 - Recv:  T:129.79 /150.00 B:59.57 /60.00 @:127 B@:120 W:6
2021-02-19 13:08:12,164 - Recv:  T:131.66 /150.00 B:59.62 /60.00 @:127 B@:122 W:5
2021-02-19 13:08:12,424 - Recv:  T:132.21 /150.00 B:59.64 /60.00 @:127 B@:123
2021-02-19 13:08:13,148 - Recv: echo:busy: processing
2021-02-19 13:08:13,164 - Recv:  T:133.74 /150.00 B:59.83 /60.00 @:127 B@:103 W:4
2021-02-19 13:08:14,164 - Recv:  T:135.51 /150.00 B:59.96 /60.00 @:127 B@:94 W:3
2021-02-19 13:08:14,424 - Recv:  T:136.15 /150.00 B:60.00 /60.00 @:127 B@:92
2021-02-19 13:08:15,149 - Recv: echo:busy: processing
2021-02-19 13:08:15,164 - Recv:  T:137.37 /150.00 B:60.08 /60.00 @:127 B@:87 W:2
2021-02-19 13:08:16,164 - Recv:  T:139.25 /150.00 B:60.14 /60.00 @:127 B@:87 W:1
2021-02-19 13:08:16,424 - Recv:  T:139.77 /150.00 B:60.28 /60.00 @:127 B@:69
2021-02-19 13:08:17,148 - Recv: echo:busy: processing
2021-02-19 13:08:17,164 - Recv:  T:141.25 /150.00 B:60.42 /60.00 @:127 B@:54 W:0
2021-02-19 13:08:17,512 - Recv: ok
2021-02-19 13:08:17,516 - Send: N12 M113 S2*82
2021-02-19 13:08:18,425 - Recv:  T:143.58 /150.00 B:60.53 /60.00 @:87 B@:42
2021-02-19 13:08:19,513 - Recv: echo:busy: processing
2021-02-19 13:08:20,424 - Recv:  T:146.90 /150.00 B:60.74 /60.00 @:34 B@:15
2021-02-19 13:08:21,513 - Recv: echo:busy: processing
2021-02-19 13:08:22,424 - Recv:  T:149.69 /150.00 B:60.95 /60.00 @:0 B@:0
2021-02-19 13:08:23,513 - Recv: echo:busy: processing
2021-02-19 13:08:25,162 - Recv:  T:151.97 /150.00 B:61.09 /60.00 @:0 B@:0
2021-02-19 13:08:25,513 - Recv: echo:busy: processing
2021-02-19 13:08:28,521 - 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-02-19 13:08:28,525 - Send: N13 M105*21
2021-02-19 13:08:28,747 - Recv: echo:busy: processing
2021-02-19 13:08:28,761 - Recv:  T:152.16 /150.00 B:61.16 /60.00 @:0 B@:0
2021-02-19 13:08:30,747 - Recv: echo:busy: processing
2021-02-19 13:08:30,763 - Recv:  T:151.30 /150.00 B:61.08 /60.00 @:3 B@:0
2021-02-19 13:08:32,747 - Recv: echo:busy: processing
2021-02-19 13:08:32,762 - Recv:  T:150.12 /150.00 B:61.15 /60.00 @:28 B@:0
2021-02-19 13:08:34,753 - Recv: echo:busy: processing
2021-02-19 13:08:34,763 - Recv:  T:148.84 /150.00 B:61.10 /60.00 @:56 B@:0
2021-02-19 13:08:36,752 - Recv: echo:busy: processing
2021-02-19 13:08:36,765 - Recv:  T:147.65 /150.00 B:61.09 /60.00 @:82 B@:0
2021-02-19 13:08:36,795 - Recv: X:150.70 Y:137.00 Z:17.00 E:0.00 Count A:23016 B:1096 Z:6800
2021-02-19 13:08:38,753 - Recv: echo:busy: processing
2021-02-19 13:08:38,764 - Recv:  T:146.96 /150.00 B:61.01 /60.00 @:97 B@:0
2021-02-19 13:08:39,857 - Recv: X:18.00 Y:249.00 Z:20.00 E:0.00 Count A:21360 B:-18480 Z:8000
2021-02-19 13:08:40,752 - Recv: echo:busy: processing
2021-02-19 13:08:40,766 - Recv:  T:146.91 /170.00 B:60.95 /60.00 @:127 B@:0
2021-02-19 13:08:42,753 - Recv: echo:busy: processing
2021-02-19 13:08:42,766 - Recv:  T:147.57 /170.00 B:60.91 /60.00 @:127 B@:0
2021-02-19 13:08:44,753 - Recv: echo:busy: processing
2021-02-19 13:08:44,766 - Recv:  T:149.11 /170.00 B:60.82 /60.00 @:127 B@:0
2021-02-19 13:08:46,752 - Recv: echo:busy: processing
2021-02-19 13:08:46,768 - Recv:  T:151.17 /170.00 B:60.73 /60.00 @:127 B@:0
2021-02-19 13:08:48,752 - Recv: echo:busy: processing
2021-02-19 13:08:48,765 - Recv:  T:153.87 /170.00 B:60.74 /60.00 @:127 B@:0
2021-02-19 13:08:50,752 - Recv: echo:busy: processing
2021-02-19 13:08:50,768 - Recv:  T:156.65 /170.00 B:60.56 /60.00 @:127 B@:0
2021-02-19 13:08:52,753 - Recv: echo:busy: processing
2021-02-19 13:08:52,772 - Recv:  T:159.42 /170.00 B:60.57 /60.00 @:127 B@:0
2021-02-19 13:08:54,753 - Recv: echo:busy: processing
2021-02-19 13:08:54,771 - Recv:  T:162.93 /170.00 B:60.50 /60.00 @:101 B@:0
2021-02-19 13:08:56,753 - Recv: echo:busy: processing
2021-02-19 13:08:56,771 - Recv:  T:165.99 /170.00 B:60.44 /60.00 @:53 B@:0
2021-02-19 13:08:58,753 - Recv: echo:busy: processing
2021-02-19 13:08:58,771 - Recv:  T:168.87 /170.00 B:60.32 /60.00 @:12 B@:0
2021-02-19 13:09:01,784 - 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-02-19 13:09:01,789 - Send: N14 M105*18
2021-02-19 13:09:04,233 - Recv: echo:busy: processing
2021-02-19 13:09:04,243 - Recv:  T:171.62 /170.00 B:59.96 /60.00 @:0 B@:18
2021-02-19 13:09:06,232 - Recv: echo:busy: processing
2021-02-19 13:09:06,244 - Recv:  T:170.76 /170.00 B:60.00 /60.00 @:20 B@:6
2021-02-19 13:09:08,232 - Recv: echo:busy: processing
2021-02-19 13:09:08,243 - Recv:  T:169.65 /170.00 B:59.67 /60.00 @:48 B@:50
2021-02-19 13:09:10,236 - Recv:  T:168.39 /170.00 B:59.79 /60.00 @:78 B@:31
2021-02-19 13:09:10,253 - Recv: echo:busy: processing
2021-02-19 13:09:12,236 - Recv:  T:167.48 /170.00 B:59.67 /60.00 @:98 B@:49
2021-02-19 13:09:12,250 - Recv: echo:busy: processing
2021-02-19 13:09:14,245 - Recv:  T:167.10 /170.00 B:59.57 /60.00 @:107 B@:67
2021-02-19 13:09:14,254 - Recv: echo:busy: processing
2021-02-19 13:09:15,747 - Recv: echo:Insert filament and press button
2021-02-19 13:09:16,244 - Recv:  T:167.40 /170.00 B:59.62 /60.00 @:102 B@:66
2021-02-19 13:09:16,253 - Recv: echo:busy: paused for user
2021-02-19 13:09:18,244 - Recv:  T:168.32 /170.00 B:59.58 /60.00 @:84 B@:79
2021-02-19 13:09:18,260 - Recv: echo:busy: paused for user
2021-02-19 13:09:20,244 - Recv:  T:169.44 /170.00 B:59.62 /60.00 @:63 B@:84
2021-02-19 13:09:20,254 - Recv: echo:busy: paused for user
2021-02-19 13:09:22,245 - Recv:  T:170.70 /170.00 B:59.74 /60.00 @:38 B@:77
2021-02-19 13:09:22,259 - Recv: echo:busy: paused for user
2021-02-19 13:09:24,245 - Recv:  T:171.86 /170.00 B:59.77 /60.00 @:15 B@:84
2021-02-19 13:09:24,262 - Recv: echo:busy: paused for user
2021-02-19 13:09:26,245 - Recv:  T:172.17 /170.00 B:59.91 /60.00 @:11 B@:72
2021-02-19 13:09:26,263 - Recv: echo:busy: paused for user
2021-02-19 13:09:28,245 - Recv:  T:172.05 /170.00 B:60.00 /60.00 @:14 B@:66
2021-02-19 13:09:28,261 - Recv: echo:busy: paused for user
2021-02-19 13:09:30,245 - Recv:  T:171.27 /170.00 B:60.15 /60.00 @:32 B@:50
2021-02-19 13:09:30,259 - Recv: echo:busy: paused for user
2021-02-19 13:09:32,245 - Recv:  T:170.29 /170.00 B:60.28 /60.00 @:51 B@:35
2021-02-19 13:09:32,265 - Recv: echo:busy: paused for user
2021-02-19 13:09:34,245 - Recv:  T:169.41 /170.00 B:60.36 /60.00 @:68 B@:24
2021-02-19 13:09:34,260 - Recv: echo:busy: paused for user
2021-02-19 13:09:36,245 - Recv:  T:168.65 /170.00 B:60.45 /60.00 @:82 B@:6
2021-02-19 13:09:36,261 - Recv: echo:busy: paused for user
2021-02-19 13:09:38,245 - Recv:  T:168.33 /170.00 B:60.51 /60.00 @:88 B@:0
2021-02-19 13:09:38,261 - Recv: echo:busy: paused for user
2021-02-19 13:09:40,245 - Recv:  T:168.51 /170.00 B:60.50 /60.00 @:83 B@:0
2021-02-19 13:09:40,258 - Recv: echo:busy: paused for user
2021-02-19 13:09:42,245 - Recv:  T:169.13 /170.00 B:60.60 /60.00 @:70 B@:0
2021-02-19 13:09:42,260 - Recv: echo:busy: paused for user
2021-02-19 13:09:44,249 - Recv:  T:169.84 /170.00 B:60.59 /60.00 @:55 B@:0
2021-02-19 13:09:44,264 - Recv: echo:busy: paused for user
2021-02-19 13:09:46,248 - Recv:  T:170.70 /170.00 B:60.49 /60.00 @:38 B@:0
2021-02-19 13:09:46,263 - Recv: echo:busy: paused for user
2021-02-19 13:09:48,248 - Recv:  T:171.27 /170.00 B:60.44 /60.00 @:27 B@:0
2021-02-19 13:09:48,264 - Recv: echo:busy: paused for user
2021-02-19 13:09:50,248 - Recv:  T:171.56 /170.00 B:60.41 /60.00 @:22 B@:0
2021-02-19 13:09:50,264 - Recv: echo:busy: paused for user
2021-02-19 13:09:52,248 - Recv:  T:171.39 /170.00 B:60.32 /60.00 @:26 B@:0
2021-02-19 13:09:52,266 - Recv: echo:busy: paused for user
2021-02-19 13:09:54,059 - Connection closed, closing down monitor
2021-02-19 13:09:54,072 - Changing monitoring state from "Printing" to "Offline"

Any help would be appreciated!

2

It looks like the printer may be trying to execute a filament change? OctoPrint does not tell it to heat to 170, only 150 - it changes that itself, then says echo:Insert filament and press button and paused for user.

3

Hello @Celeris !

The template you have deleted asked for running in safe mode. So did you and what was the result?

In the serial.log is this:

2021-02-19 13:07:43,127 - Send: N9 M104 S150*104
2021-02-19 13:07:43,131 - Recv: ok

You should put these :

Right after these:

You should not move around the hotend before the proper temperatures have settled.

4

Thanks for your response, I changed the gcode but it did not change the behaviour... Also, safe mode does not do anything for me...

5

I did not see that, thanks! This does seem like the issue. However, I have no clue why or how this is triggered. It only happens using octoprint, the same file prints just fine using the BTT display.

6

Please clarify. Also, share octoprint.log.

7

Well, the behaviour is exactly the same in safe mode.

octoprint.log (safe mode)

2021-02-19 13:58:00,673 - octoprint.startup - INFO - ******************************************************************************
2021-02-19 13:58:00,674 - octoprint.startup - INFO - Starting OctoPrint 1.5.3
2021-02-19 13:58:00,675 - octoprint.startup - INFO - Starting in SAFE MODE. Third party plugins will be disabled!
2021-02-19 13:58:00,675 - octoprint.startup - INFO - Reason for safe mode: setting in config.yaml
2021-02-19 13:58:00,676 - octoprint.startup - INFO - ******************************************************************************
2021-02-19 13:58:01,091 - octoprint.util.connectivity.connectivity_checker - INFO - Connectivity state is currently: online
2021-02-19 13:58:01,093 - octoprint.util.connectivity.connectivity_checker - INFO - Connecting to 8.8.8.8:53 is working
2021-02-19 13:58:01,093 - octoprint.util.connectivity.connectivity_checker - INFO - Resolving octoprint.org is working
2021-02-19 13:58:01,316 - octoprint.startup - INFO - Blacklist processing done, adding 12 blacklisted plugin versions: roomtemp (any), GcodeEditor (0.1.1), GcodeEditor (0.2.0), GcodeEditor (0.2.1), GcodeEditor (0.2.2), GcodeEditor (0.2.3), GcodeEditor (0.2.4), GcodeEditor (0.2.5), GcodeEditor (0.2.6), GcodeEditor (0.2.8), gcodeleveling (0.1.0), gcodeleveling (0.1.1)
2021-02-19 13:58:01,365 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2021-02-19 13:58:02,608 - octoprint.startup - INFO - Added settings overlay from plugin firmware_check
2021-02-19 13:58:02,610 - octoprint.plugin.core - INFO - Found 19 plugin(s) providing 17 mixin implementations, 34 hook handlers
2021-02-19 13:58:02,809 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2021-02-19 13:58:02,817 - octoprint.server - INFO - Intermediary server started
2021-02-19 13:58:02,846 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2021-02-19 13:58:03,226 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2021-02-19 13:58:03,230 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_SHOW (needs: "Need(method='role', value='plugin_action_command_notification_show')")
2021-02-19 13:58:03,231 - octoprint.server - INFO - Added new permission from plugin action_command_notification: PLUGIN_ACTION_COMMAND_NOTIFICATION_CLEAR (needs: "Need(method='role', value='plugin_action_command_notification_clear')")
2021-02-19 13:58:03,232 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: "Need(method='role', value='plugin_action_command_prompt_interact')")
2021-02-19 13:58:03,233 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: "Need(method='role', value='plugin_announcements_read')")
2021-02-19 13:58:03,235 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: "Need(method='role', value='plugin_announcements_read'), Need(method='role', value='plugin_announcements_manage')")
2021-02-19 13:58:03,236 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: "Need(method='role', value='plugin_appkeys_admin')")
2021-02-19 13:58:03,237 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: "Need(method='role', value='plugin_backup_access')")
2021-02-19 13:58:03,239 - octoprint.server - INFO - Added new permission from plugin firmware_check: PLUGIN_FIRMWARE_CHECK_DISPLAY (needs: "Need(method='role', value='plugin_firmware_check_display')")
2021-02-19 13:58:03,240 - octoprint.server - INFO - Added new permission from plugin logging: PLUGIN_LOGGING_MANAGE (needs: "Need(method='role', value='plugin_logging_manage')")
2021-02-19 13:58:03,241 - octoprint.server - INFO - Added new permission from plugin pi_support: PLUGIN_PI_SUPPORT_STATUS (needs: "Need(method='role', value='plugin_pi_support_check')")
2021-02-19 13:58:03,243 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_MANAGE (needs: "Need(method='role', value='plugin_pluginmanager_manage')")
2021-02-19 13:58:03,244 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_INSTALL (needs: "Need(method='role', value='plugin_pluginmanager_manage'), Need(method='role', value='plugin_pluginmanager_install')")
2021-02-19 13:58:03,245 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CHECK (needs: "Need(method='role', value='plugin_softwareupdate_check')")
2021-02-19 13:58:03,246 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_UPDATE (needs: "Need(method='role', value='plugin_softwareupdate_update')")
2021-02-19 13:58:03,248 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CONFIGURE (needs: "Need(method='role', value='plugin_softwareupdate_configure')")
2021-02-19 13:58:04,233 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python3 -m pip" as command to invoke pip
2021-02-19 13:58:05,085 - octoprint.util.pip - INFO - Version of pip is 20.3.3
2021-02-19 13:58:05,087 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2021-02-19 13:58:05,088 - octoprint.util.pip - INFO - ==> pip ok -> yes
2021-02-19 13:58:05,189 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2021-02-19 13:58:05,213 - octoprint.plugin.core - INFO - Initialized 17 plugin implementation(s)
2021-02-19 13:58:05,227 - octoprint.plugin.core - INFO - 19 plugin(s) registered with the system:
| !ABL Expert Plugin (0.6) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_ABL_Expert
|  Action Command Notification Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_notification
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/corewizard
|  Discovery (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/discovery
|  Error Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/errortracking
|  File Check (2020.8.7) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_file_check
|  Firmware Check (2021.2.4) (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_firmware_check
|  GCode Viewer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/gcodeviewer
|  Logging (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/logging
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pluginmanager
|  Software Update (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/softwareupdate
| !Tasmota (1.0.1) = /home/pi/oprint/lib/python3.7/site-packages/octoprint_tasmota
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2021-02-19 13:58:05,249 - octoprint.plugins.pi_support - WARNING - This Raspberry Pi is reporting problems that might lead to bad performance or errors caused by overheating or insufficient power.
!!! UNDERVOLTAGE REPORTED !!! Make sure that the power supply and power cable are capable of supplying enough voltage and current to your Pi.
2021-02-19 13:58:05,260 - octoprint.environment - INFO - Detected environment is Python 3.7.3 under Linux (linux). Details:
|  hardware:
|      cores: 4
|      freq: 1400.0
|      ram: 915718144
|  os:
|      bits: 32
|      id: linux
|      platform: linux
|  plugins:
|      pi_support:
|          model: Raspberry Pi 3 Model B Plus Rev 1.3
|          octopi_version: 0.18.0
|          throttle_state: '0x50000'
|  python:
|      pip: 20.3.3
|      version: 3.7.3
|      virtualenv: /home/pi/oprint
2021-02-19 13:58:05,277 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2021-02-19 13:58:05,305 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2021-02-19 13:58:06,139 - octoprint.server - INFO - Shutting down intermediary server...
2021-02-19 13:58:06,141 - octoprint.server - INFO - Intermediary server shut down
2021-02-19 13:58:06,143 - octoprint.events - INFO - Processing startup event, this is our first event
2021-02-19 13:58:06,144 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2021-02-19 13:58:06,148 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2021-02-19 13:58:06,152 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2021-02-19 13:58:06,153 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2021-02-19 13:58:06,155 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2021-02-19 13:58:06,968 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on besteprinterophetnetwerk._http._tcp.local.' for _http._tcp.local.
2021-02-19 13:58:07,793 - octoprint.plugins.discovery - INFO - Registered 'OctoPrint instance on besteprinterophetnetwerk._octoprint._tcp.local.' for _octoprint._tcp.local.
2021-02-19 13:58:07,826 - octoprint.plugins.discovery - INFO - Registered OctoPrint instance on besteprinterophetnetwerk for SSDP
2021-02-19 13:58:07,859 - octoprint.server - INFO - Listening on http://127.0.0.1:5000
2021-02-19 13:58:07,860 - octoprint.server - INFO - Server started successfully in safe mode as requested from config, removing flag
2021-02-19 13:58:08,162 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2021-02-19 13:58:08,507 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:10.0.0.237
2021-02-19 13:58:08,751 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:08,752 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:09,088 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python3 -m pip" as command to invoke pip
2021-02-19 13:58:09,093 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2021-02-19 13:58:09,118 - octoprint.util.pip - INFO - ==> pip ok -> yes
2021-02-19 13:58:09,210 - octoprint.plugins.softwareupdate - INFO - Minimum free storage across all update relevant locations is 11.9GB. That is considered sufficient for updating.
2021-02-19 13:58:09,210 - octoprint.plugins.softwareupdate - INFO - Fetching check overlays from https://plugins.octoprint.org/update_check_overlay.json
2021-02-19 13:58:10,277 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'base_url': 'http://besteprinterophetnetwerk.local/', 'path': '/', 'query_string': 'l10n=en'}
2021-02-19 13:58:10,444 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2021-02-19 13:58:12,501 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:12,529 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:31,250 - octoprint.server.preemptive_cache - INFO - ... done in 20.97s
2021-02-19 13:58:31,251 - octoprint.server.preemptive_cache - INFO - Preemptively caching / (ui _default) for {'base_url': 'http://besteprinterophetnetwerk/', 'path': '/', 'query_string': 'l10n=en'}
2021-02-19 13:58:31,563 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:31,565 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:31,774 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:31,775 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:32,425 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:32,426 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:33,074 - octoprint.server.util.sockjs - INFO - User admin logged in on the socket from client ::ffff:10.0.0.237
2021-02-19 13:58:33,102 - octoprint.server.util.sockjs - INFO - Client connection closed: ::ffff:10.0.0.237
2021-02-19 13:58:33,209 - octoprint.server.preemptive_cache - INFO - ... done in 1.96s
2021-02-19 13:58:33,425 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:10.0.0.237
2021-02-19 13:58:33,569 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:10.0.0.237
2021-02-19 13:58:33,624 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:33,625 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:33,669 - octoprint.server.util.flask - INFO - Passively logging in user admin from ::ffff:10.0.0.237
2021-02-19 13:58:33,670 - octoprint.access.users - INFO - Logged in user: admin
2021-02-19 13:58:36,359 - octoprint.server.util.sockjs - INFO - User admin logged in on the socket from client ::ffff:10.0.0.237
2021-02-19 13:58:36,370 - octoprint.server.util.sockjs - INFO - User admin logged in on the socket from client ::ffff:10.0.0.237
2021-02-19 13:58:54,592 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-02-19 13:58:54,651 - octoprint.util.comm - INFO - Serial detection: 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
2021-02-19 13:58:54,652 - octoprint.util.comm - INFO - Serial detection: Trying port /dev/ttyACM0, baudrate 115200
2021-02-19 13:58:54,653 - octoprint.util.comm - INFO - Connecting to port /dev/ttyACM0, baudrate 115200
2021-02-19 13:58:54,663 - octoprint.util.comm - INFO - Serial detection: Handshake attempt #1 with timeout 2.0s
2021-02-19 13:58:54,673 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-02-19 13:58:54,750 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial connection" to "Operational"
2021-02-19 13:58:54,764 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-02-19 13:58:54,852 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin 2.0.7.2 (Feb 17 2021"
2021-02-19 13:58:54,872 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2021-02-19 13:58:57,752 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: linear_bearing_mount_0.28mm_PLA_ENDER5PLUS_23h45m_(1).gcode, owner: admin, user: admin
2021-02-19 13:59:07,410 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: 3DBenchy_0.16mm_PLA_ENDER5PLUS_2h41m.gcode, owner: admin, user: admin
2021-02-19 13:59:17,783 - octoprint.util.comm - INFO - Starting job on behalf of user admin
2021-02-19 13:59:17,795 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2021-02-19 13:59:17,825 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: 3DBenchy_0.16mm_PLA_ENDER5PLUS_2h41m.gcode, owner: admin, user: admin
2021-02-19 13:59:17,886 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-02-19 13:59:17,897 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2021-02-19 13:59:19,970 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2021-02-19 14:00:55,480 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2021-02-19 14:01:06,490 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2021-02-19 14:01:39,736 - octoprint.util.comm - INFO - Communication timeout while printing, trying to trigger response from printer.
2021-02-19 14:02:27,313 - octoprint.util.comm - ERROR - Unexpected error while reading from serial port
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint/util/comm.py", line 3831, in _readline
    ret = self._serial.readline()
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint/util/comm.py", line 6455, in readline
    c = self.read(1)
  File "/home/pi/oprint/lib/python3.7/site-packages/serial/serialposix.py", line 596, in read
    'device reports readiness to read but returned no data '
serial.serialutil.SerialException: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2021-02-19 14:02:27,365 - octoprint.util.comm - ERROR - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2021-02-19 14:02:27,386 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:3831)"
2021-02-19 14:02:27,398 - octoprint.plugins.action_command_notification - INFO - Notifications cleared

Serial.log (safe mode):

2021-02-19 13:58:54,586 - Changing monitoring state from "Offline" to "Detecting serial connection"
2021-02-19 13:58:54,651 - 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
2021-02-19 13:58:54,652 - Trying port /dev/ttyACM0, baudrate 115200
2021-02-19 13:58:54,653 - Connecting to port /dev/ttyACM0, baudrate 115200
2021-02-19 13:58:54,663 - Handshake attempt #1 with timeout 2.0s
2021-02-19 13:58:54,671 - Connected to: Serial<id=0x730f1110, open=True>(port='/dev/ttyACM0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=2.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2021-02-19 13:58:54,673 - Send: N0 M110 N0*125
2021-02-19 13:58:54,684 - Recv: echo:Unknown command: "In X connT"
2021-02-19 13:58:54,696 - Recv: ok
2021-02-19 13:58:54,750 - Changing monitoring state from "Detecting serial connection" to "Operational"
2021-02-19 13:58:54,771 - Send: N0 M110 N0*125
2021-02-19 13:58:54,832 - Recv: ok
2021-02-19 13:58:54,833 - Recv: ok
2021-02-19 13:58:54,843 - Send: N1 M115*39
2021-02-19 13:58:54,850 - Recv: FIRMWARE_NAME:Marlin 2.0.7.2 (Feb 17 2021 20:20:58) SOURCE_CODE_URL:https://github.com/MarlinFirmware/Marlin PROTOCOL_VERSION:1.0 MACHINE_TYPE:Ender-5 Plus EXTRUDER_COUNT:1 UUID:5a37052e-424e-4819-8efe-d9ce53788ab2
2021-02-19 13:58:54,853 - Recv: Cap:SERIAL_XON_XOFF:0
2021-02-19 13:58:54,861 - Recv: Cap:BINARY_FILE_TRANSFER:0
2021-02-19 13:58:54,868 - Recv: Cap:EEPROM:1
2021-02-19 13:58:54,869 - Recv: Cap:VOLUMETRIC:1
2021-02-19 13:58:54,872 - Recv: Cap:AUTOREPORT_TEMP:1
2021-02-19 13:58:54,874 - Recv: Cap:PROGRESS:0
2021-02-19 13:58:54,877 - Recv: Cap:PRINT_JOB:1
2021-02-19 13:58:54,878 - Recv: Cap:AUTOLEVEL:1
2021-02-19 13:58:54,880 - Recv: Cap:RUNOUT:1
2021-02-19 13:58:54,888 - Recv: Cap:Z_PROBE:1
2021-02-19 13:58:54,905 - Recv: Cap:LEVELING_DATA:1
2021-02-19 13:58:54,919 - Recv: Cap:BUILD_PERCENT:1
2021-02-19 13:58:54,922 - Recv: Cap:SOFTWARE_POWER:0
2021-02-19 13:58:54,923 - Recv: Cap:TOGGLE_LIGHTS:0
2021-02-19 13:58:54,925 - Recv: Cap:CASE_LIGHT_BRIGHTNESS:0
2021-02-19 13:58:54,932 - Recv: Cap:EMERGENCY_PARSER:0
2021-02-19 13:58:54,949 - Recv: Cap:PROMPT_SUPPORT:0
2021-02-19 13:58:54,957 - Recv: Cap:SDCARD:1
2021-02-19 13:58:54,958 - Recv: Cap:AUTOREPORT_SD_STATUS:0
2021-02-19 13:58:54,966 - Recv: Cap:LONG_FILENAME:1
2021-02-19 13:58:54,982 - Recv: Cap:THERMAL_PROTECTION:1
2021-02-19 13:58:54,995 - Recv: Cap:MOTION_MODES:0
2021-02-19 13:58:55,001 - Recv: Cap:ARCS:1
2021-02-19 13:58:55,003 - Recv: Cap:BABYSTEPPING:1
2021-02-19 13:58:55,005 - Recv: Cap:CHAMBER_TEMPERATURE:0
2021-02-19 13:58:55,008 - Recv: ok
2021-02-19 13:58:55,011 - Send: M21
2021-02-19 13:58:55,017 - Recv: echo:SD card ok
2021-02-19 13:58:55,021 - Recv: ok
2021-02-19 13:58:55,023 - Send: M155 S2
2021-02-19 13:58:55,025 - Recv: ok
2021-02-19 13:58:55,026 - Send: M20
2021-02-19 13:58:55,028 - Recv: Begin file list
2021-02-19 13:58:55,037 - Recv: End file list
2021-02-19 13:58:55,038 - Recv: ok
2021-02-19 13:58:57,031 - Recv:  T:55.10 /0.00 B:43.84 /0.00 @:0 B@:0
2021-02-19 13:59:17,039 - Recv:  T:51.28 /0.00 B:43.27 /0.00 @:0 B@:0
2021-02-19 13:59:17,794 - Changing monitoring state from "Operational" to "Starting"
2021-02-19 13:59:17,886 - Send: N0 M110 N0*125
2021-02-19 13:59:17,894 - Recv: ok
2021-02-19 13:59:17,896 - Changing monitoring state from "Starting" to "Printing"
2021-02-19 13:59:17,904 - Send: N1 M201 X5000 Y5000 Z100 E1000*15
2021-02-19 13:59:17,911 - Recv: ok
2021-02-19 13:59:17,913 - Send: N2 M203 X500 Y500 Z10 E100*14
2021-02-19 13:59:17,916 - Recv: ok
2021-02-19 13:59:17,920 - Send: N3 M204 P200 R1000 T200*81
2021-02-19 13:59:17,929 - Recv: ok
2021-02-19 13:59:17,936 - Send: N4 M205 X10.00 Y10.00 Z0.30 E0.50*56
2021-02-19 13:59:17,940 - Recv: ok
2021-02-19 13:59:17,946 - Send: N5 M205 S0 T0*38
2021-02-19 13:59:17,948 - Recv: ok
2021-02-19 13:59:17,950 - Send: N6 M107*35
2021-02-19 13:59:17,951 - Recv: ok
2021-02-19 13:59:17,953 - Send: N7 G90*23
2021-02-19 13:59:17,954 - Recv: ok
2021-02-19 13:59:17,956 - Send: N8 M83*16
2021-02-19 13:59:17,957 - Recv: ok
2021-02-19 13:59:17,959 - Send: N9 M104 S150*104
2021-02-19 13:59:17,961 - Recv: ok
2021-02-19 13:59:17,962 - Send: N10 M140 S60*98
2021-02-19 13:59:17,964 - Recv: ok
2021-02-19 13:59:17,966 - Send: N11 M190 S60*110
2021-02-19 13:59:17,972 - Recv:  T:51.08 /150.00 B:43.22 /60.00 @:0 B@:0 W:?
2021-02-19 13:59:18,972 - Recv:  T:51.05 /150.00 B:43.25 /60.00 @:127 B@:127 W:?
2021-02-19 13:59:19,039 - Recv:  T:51.05 /150.00 B:43.25 /60.00 @:127 B@:127
2021-02-19 13:59:19,968 - Recv: echo:busy: processing
2021-02-19 13:59:19,969 - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2021-02-19 13:59:19,976 - Recv:  T:50.95 /150.00 B:43.13 /60.00 @:127 B@:127 W:?
2021-02-19 13:59:20,972 - Recv:  T:51.01 /150.00 B:43.24 /60.00 @:127 B@:127 W:?
2021-02-19 13:59:21,040 - Recv:  T:51.05 /150.00 B:43.24 /60.00 @:127 B@:127
2021-02-19 14:00:41,981 - Recv: echo:busy: processing
2021-02-19 14:00:42,978 - Recv:  T:152.08 /150.00 B:58.49 /60.00 @:4 B@:127 W:?
2021-02-19 14:00:43,041 - Recv:  T:152.08 /150.00 B:58.49 /60.00 @:4 B@:127
2021-02-19 14:00:43,987 - Recv:  T:151.92 /150.00 B:58.76 /60.00 @:8 B@:127 W:?
2021-02-19 14:00:43,990 - Recv: echo:busy: processing
2021-02-19 14:00:44,986 - Recv:  T:151.60 /150.00 B:58.95 /60.00 @:15 B@:127 W:?
2021-02-19 14:00:45,042 - Recv:  T:151.47 /150.00 B:58.96 /60.00 @:18 B@:127
2021-02-19 14:00:45,986 - Recv:  T:151.24 /150.00 B:59.17 /60.00 @:22 B@:127 W:9
2021-02-19 14:00:45,987 - Recv: echo:busy: processing
2021-02-19 14:00:46,986 - Recv:  T:150.72 /150.00 B:59.38 /60.00 @:33 B@:119 W:8
2021-02-19 14:00:47,042 - Recv:  T:150.72 /150.00 B:59.38 /60.00 @:33 B@:119
2021-02-19 14:00:47,986 - Recv:  T:150.26 /150.00 B:59.54 /60.00 @:42 B@:109 W:7
2021-02-19 14:00:47,988 - Recv: echo:busy: processing
2021-02-19 14:00:48,986 - Recv:  T:149.86 /150.00 B:59.80 /60.00 @:50 B@:85 W:6
2021-02-19 14:00:49,042 - Recv:  T:149.81 /150.00 B:59.62 /60.00 @:50 B@:114
2021-02-19 14:00:49,985 - Recv:  T:149.29 /150.00 B:59.92 /60.00 @:61 B@:84 W:5
2021-02-19 14:00:49,990 - Recv: echo:busy: processing
2021-02-19 14:00:50,986 - Recv:  T:148.91 /150.00 B:60.08 /60.00 @:69 B@:75 W:4
2021-02-19 14:00:51,042 - Recv:  T:148.91 /150.00 B:60.08 /60.00 @:69 B@:75
2021-02-19 14:00:51,986 - Recv:  T:148.61 /150.00 B:60.21 /60.00 @:74 B@:68 W:3
2021-02-19 14:00:51,990 - Recv: echo:busy: processing
2021-02-19 14:00:52,986 - Recv:  T:148.40 /150.00 B:60.37 /60.00 @:78 B@:54 W:2
2021-02-19 14:00:53,042 - Recv:  T:148.44 /150.00 B:60.41 /60.00 @:77 B@:50
2021-02-19 14:00:53,986 - Recv:  T:148.31 /150.00 B:60.54 /60.00 @:79 B@:36 W:1
2021-02-19 14:00:53,990 - Recv: echo:busy: processing
2021-02-19 14:00:54,986 - Recv:  T:148.27 /150.00 B:60.72 /60.00 @:80 B@:14 W:0
2021-02-19 14:00:55,042 - Recv:  T:148.27 /150.00 B:60.72 /60.00 @:80 B@:14
2021-02-19 14:00:55,476 - Recv: ok
2021-02-19 14:00:55,479 - Send: N12 M113 S2*82
2021-02-19 14:00:57,042 - Recv:  T:148.60 /150.00 B:60.96 /60.00 @:73 B@:0
2021-02-19 14:00:57,477 - Recv: echo:busy: processing
2021-02-19 14:00:59,044 - Recv:  T:149.23 /150.00 B:61.15 /60.00 @:60 B@:0
2021-02-19 14:00:59,482 - Recv: echo:busy: processing
2021-02-19 14:01:01,043 - Recv:  T:150.20 /150.00 B:61.28 /60.00 @:39 B@:0
2021-02-19 14:01:01,482 - Recv: echo:busy: processing
2021-02-19 14:01:03,117 - Recv:  T:150.87 /150.00 B:61.33 /60.00 @:27 B@:0
2021-02-19 14:01:03,483 - Recv: echo:busy: processing
2021-02-19 14:01:06,491 - 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-02-19 14:01:06,498 - Send: N13 M105*21
2021-02-19 14:01:06,713 - Recv: echo:busy: processing
2021-02-19 14:01:06,717 - Recv:  T:151.56 /150.00 B:61.49 /60.00 @:14 B@:0
2021-02-19 14:01:08,712 - Recv: echo:busy: processing
2021-02-19 14:01:08,722 - Recv:  T:151.49 /150.00 B:61.48 /60.00 @:15 B@:0
2021-02-19 14:01:10,713 - Recv: echo:busy: processing
2021-02-19 14:01:10,731 - Recv:  T:150.91 /150.00 B:61.46 /60.00 @:28 B@:0
2021-02-19 14:01:12,713 - Recv: echo:busy: processing
2021-02-19 14:01:12,725 - Recv:  T:150.20 /150.00 B:61.45 /60.00 @:42 B@:0
2021-02-19 14:01:14,713 - Recv: echo:busy: processing
2021-02-19 14:01:14,723 - Recv:  T:149.46 /150.00 B:61.31 /60.00 @:56 B@:0
2021-02-19 14:01:14,757 - Recv: X:150.70 Y:137.00 Z:17.00 E:0.00 Count A:23016 B:1096 Z:6800
2021-02-19 14:01:16,717 - Recv:  T:148.95 /150.00 B:61.30 /60.00 @:66 B@:0
2021-02-19 14:01:16,721 - Recv: echo:busy: processing
2021-02-19 14:01:17,819 - Recv: X:18.00 Y:249.00 Z:20.00 E:0.00 Count A:21360 B:-18480 Z:8000
2021-02-19 14:01:18,718 - Recv:  T:148.77 /170.00 B:61.28 /60.00 @:127 B@:0
2021-02-19 14:01:18,721 - Recv: echo:busy: processing
2021-02-19 14:01:20,718 - Recv:  T:149.00 /170.00 B:61.17 /60.00 @:127 B@:0
2021-02-19 14:01:20,721 - Recv: echo:busy: processing
2021-02-19 14:01:36,728 - Recv:  T:169.15 /170.00 B:60.57 /60.00 @:9 B@:0
2021-02-19 14:01:36,731 - Recv: echo:busy: processing
2021-02-19 14:01:39,736 - 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-02-19 14:01:39,742 - Send: N14 M105*18
2021-02-19 14:01:42,038 - Recv: echo:busy: processing
2021-02-19 14:01:42,048 - Recv:  T:171.58 /170.00 B:60.25 /60.00 @:0 B@:0
2021-02-19 14:01:44,038 - Recv: echo:busy: processing
2021-02-19 14:01:44,054 - Recv:  T:171.05 /170.00 B:60.21 /60.00 @:14 B@:0
2021-02-19 14:01:46,038 - Recv: echo:busy: processing
2021-02-19 14:01:46,055 - Recv:  T:169.90 /170.00 B:60.02 /60.00 @:43 B@:13
2021-02-19 14:01:48,038 - Recv: echo:busy: processing
2021-02-19 14:01:48,055 - Recv:  T:168.89 /170.00 B:59.99 /60.00 @:66 B@:11
2021-02-19 14:01:50,038 - Recv: echo:busy: processing
2021-02-19 14:01:50,055 - Recv:  T:167.76 /170.00 B:59.91 /60.00 @:91 B@:17
2021-02-19 14:01:52,050 - Recv:  T:167.15 /170.00 B:59.79 /60.00 @:106 B@:32
2021-02-19 14:01:52,053 - Recv: echo:busy: processing
2021-02-19 14:01:53,551 - Recv: echo:Insert filament and press button
2021-02-19 14:01:54,049 - Recv:  T:167.36 /170.00 B:59.66 /60.00 @:102 B@:51
2021-02-19 14:02:24,061 - Recv: echo:busy: paused for user
2021-02-19 14:02:26,056 - Recv:  T:171.19 /170.00 B:60.52 /60.00 @:27 B@:0
2021-02-19 14:02:26,066 - Recv: echo:busy: paused for user
2021-02-19 14:02:27,365 - Unexpected error while reading serial port, please consult octoprint.log for details: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:3831
2021-02-19 14:02:27,373 - Please see https://faq.octoprint.org/serialerror for possible reasons of this.
2021-02-19 14:02:27,385 - Changing monitoring state from "Printing" to "Offline (Error: SerialException: 'device reports readiness to read but returned no data (device disconnected or multiple access on port?)' @ comm.py:_readline:3831)"
2021-02-19 14:02:27,393 - Connection closed, closing down monitor

I do see the following every time I print, I really don't understand how it is triggered. There also isn't anything popping up on the display.

2021-02-19 14:01:53,551 - Recv: echo:Insert filament and press button
2021-02-19 14:01:54,049 - Recv:  T:167.36 /170.00 B:59.66 /60.00 @:102 B@:51
2021-02-19 14:01:54,053 - Recv: echo:busy: paused for user
8

Update: I added "M412 S0" to ignore the filament runout sensor to the GCODE and it works fine now.

Could it maybe be that octoprint sees the runout sensor value inverted?

1 Like
9

OctoPrint isn't involved here, this is completely on your firmware. You probably have it misconfigured.

To elaborate: Any line prefixed with Recv: in your serial.log is received from the printer's firmware, and that's what's reporting filament related messages. OctoPrint doesn't know whether you have a filament sensor or not, it doesn't care either, it doesn't interpret it in any way (and in fact it can't even) and relies completely on the firmware handling all of that.

11

Alright. However what still don't understand is why this issue doesn't occur when I print directly from SD, but I'll have a look at my firmware.

I'll just turn off the runout sensor untill I have that figured out. Thanks for the support!

1 Like
12

I can't tell you that either, but if you find it out I'd be interested in an update.

It could be that there are separate routines depending on whether a command is received from serial vs a file on the SD.

13

Creality firmware is known to be quite quirky

14

I'm running a btt skr mini e3 v2.0 with Marlin firmware actually, but yes I agree

1 Like
15

In my case it was solved by disabling Preheat button plugin