Can't set target temperature until I 'Load filament' on the LCD

accountnumber3 · May 21, 2019, 10:34pm

What is the problem?
Print job starts but target temperature is zero. Every time I try to set the target it resets to zero. The only way to actually start the print is to go to the printer's lcd screen and 'load filament'. Then I can do whatever I want.

What did you already try to solve it?
Reboot/restart/upgrade octoprint/octopi/printer. It has been like this for a few versions but I never got around to posting about it and I haven't been able to print anything for months because of a bent bed plate.

Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, octoprint.log, serial.log or output on terminal tab, ...)
I'm not at home, I can get this later. Maker Select V2. I mostly wanted to see if it is a known issue and post about it now before I forget for another 6 months.

franzbischoff · May 22, 2019, 12:17am

Check the gcode you are trying to print. Doesn't it force to temperature zero? Any plugin for extruder temp timeout?

accountnumber3 · May 22, 2019, 1:31am

I'm gonna guess that's M109? Looks good to me but I don't really know what I'm looking at.

I found the log files but I don't see any M* commands.

M190 S60.000000
M109 S180.000000
;Sliced at: Tue 21-05-2019 15:53:27
;Basic settings: Layer height: 0.1 Walls: 0.8 Fill: 15
;Print time: 1 hour 13 minutes
;Filament used: 1.545m 4.0g
;Filament cost: 0.09
;M190 S60 ;Uncomment to add your own bed temperature line
;M109 S180 ;Uncomment to add your own temperature line
G21        ;metric values
G90        ;absolute positioning
M82        ;set extruder to absolute mode
M107       ;start with the fan off
G28 X0 Y0  ;move X/Y to min endstops
G28 Z0     ;move Z to min endstops
G1 Z15.0 F4800 ;move the platform down 15mm
G92 E0                  ;zero the extruded length
G1 F140 E30              ;extrude 3mm of feed stock
G1 X20 Y0 F140 E30
G92 E0                  ;zero the extruded length again
G1 F4800
;Put printing message on LCD screen
M117 Printing...

;Layer count: 73
;LAYER:0

accountnumber3 · May 22, 2019, 1:37am

Ewald_Ikemann · May 22, 2019, 10:41am

Could you nevertheless share the log files?

accountnumber3 · May 22, 2019, 5:30pm

I signed up with my github account but I don't see where to sign in on the desktop site. Edit: I found the login link. Such a weird UX.

I didn't realize that the plugins list Could scroll. I've uninstalled and disabled every plugin that didn't look important and I was able to gain control of the temperature setting sooner, but it still exhibited the same behavior - can't control the temperature until it has reached the target temp in the code file.

I'm pretty good at reading log files. I'll share it once I get a chance to sanitize.

Is there an easy way to factory reset octoprint without reinstalling?

accountnumber3 · May 23, 2019, 7:15am

I'm still working on sanitizing the logs and reproducing the issue but I do see this - this is an attempt that was cancelled because the nozzle was clogged. Not a whole lot but maybe that error is useful? It's all over the log (72 times in 2 days).

2019-05-22 08:41:41,594 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: Dice_Tower_with_Storage_-_Step_DSidedwNut_flattop.gcode, owner: dummy, user: dummy
2019-05-22 08:41:41,620 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-05-22 08:41:41,668 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-05-22 08:41:41,679 - octoprint.plugins.pi_support - ERROR - Got an error while trying to fetch the current throttle state via "/usr/bin/vcgencmd get_throttled"
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support/__init__.py", line 263, in _check_throttled_state
    state = get_vcgencmd_throttled_state(command)
  File "/home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support/__init__.py", line 140, in get_vcgencmd_throttled_state
    raise ValueError("cannot parse \"{}\" output: {}".format(command, output))
ValueError: cannot parse "/usr/bin/vcgencmd get_throttled" output: error=1 error_msg="Command not registered"

2019-05-22 08:41:42,374 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': 'b94d3da98080ab1222cc6f9582081f1dc756936d'}
2019-05-22 08:47:08,081 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Cancelling"2019-05-22 08:47:08,121 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: local, path: Dice_Tower_with_Storage_-_Step_DSidedwNut_flattop.gcode, owner: dummy, user: dummy

foosel · May 23, 2019, 7:50am

Please do not sanitize log files apart from stripping stuff like API keys or anything like that (which usually should not get logged by anything in core OctoPrint, but might be by third party plugins). I know you mean good, but I'd rather have too much information than too little.

Taking a look at the problem you have btw the most important and in fact crucial thing to post is a serial.log.

You might also want to try if the issue reproduces in safe mode if you haven't already done that.

accountnumber3 · May 23, 2019, 10:11am

Right, I understand. 90% of my career is reading log files. I have telegram plugin installed and it logged a lot of things I don't want public.

2019-05-22 10:32:05,150 - serial.log is currently not enabled, you can enable it via Settings > Serial Connection > Log communication to serial.log

I'll do that and try again.

accountnumber3 · May 24, 2019, 1:46pm

Ok I did that and started a print.

2019-05-22 10:32:05,150 - serial.log is currently not enabled, you can enable it via Settings > Serial Connection > Log communication to serial.log
2019-05-24 09:11:34,885 - Enabling serial logging
2019-05-24 09:11:36,881 - Send: M105
2019-05-24 09:11:36,889 - Recv: ok T:28.4 /0.0 B:27.6 /0.0 T0:28.4 /0.0 @:0 B@:0
2019-05-24 09:11:41,887 - Send: M105
2019-05-24 09:11:41,897 - Recv: ok T:28.4 /0.0 B:27.7 /0.0 T0:28.4 /0.0 @:0 B@:0
2019-05-24 09:11:41,926 - Changing monitoring state from "Operational" to "Starting"
2019-05-24 09:11:41,962 - Send: N0 M110 N0*125
2019-05-24 09:11:41,986 - Recv: ok
2019-05-24 09:11:41,994 - Changing monitoring state from "Starting" to "Printing"
2019-05-24 09:11:42,002 - Send: N1 M190 S60.000000*113
2019-05-24 09:11:43,010 - Recv: T:28.35 E:0 B:27.5
2019-05-24 09:11:44,011 - Recv: T:28.44 E:0 B:27.7
2019-05-24 09:11:45,012 - Recv: T:28.30 E:0 B:27.9
[SNIP]
2019-05-24 09:12:03,037 - Recv: T:28.38 E:0 B:34.1
2019-05-24 09:12:04,111 - Recv: T:28.30 E:0 B:34.5
2019-05-24 09:12:05,184 - Recv: T:28.35 E:0 B:34.7
2019-05-24 09:12:06,256 - Recv: T:28.24 E:0 B:35.3
2019-05-24 09:12:07,331 - Recv: T:28.30 E:0 B:35.7
2019-05-24 09:12:08,404 - Recv: T:28.27 E:0 B:35.8
2019-05-24 09:12:09,478 - Recv: T:28.38 E:0 B:36.2
2019-05-24 09:12:10,552 - Recv: T:28.41 E:0 B:36.6
2019-05-24 09:12:11,625 - Recv: T:28.24 E:0 B:37.0
2019-05-24 09:12:12,699 - Recv: T:28.30 E:0 B:37.3
2019-05-24 09:12:13,773 - Recv: T:28.30 E:0 B:37.7
2019-05-24 09:12:14,847 - Recv: T:28.30 E:0 B:38.0
2019-05-24 09:12:15,927 - Recv: T:28.38 E:0 B:38.4
2019-05-24 09:12:16,998 - Recv: T:28.32 E:0 B:38.6
2019-05-24 09:12:18,067 - Recv: T:28.24 E:0 B:39.0
2019-05-24 09:12:19,141 - Recv: T:28.32 E:0 B:39.4
2019-05-24 09:12:20,215 - Recv: T:28.38 E:0 B:39.7
2019-05-24 09:12:21,289 - Recv: T:28.38 E:0 B:40.0
2019-05-24 09:12:22,362 - Recv: T:28.38 E:0 B:40.2
2019-05-24 09:12:23,440 - Recv: T:28.38 E:0 B:40.6
2019-05-24 09:12:24,509 - Recv: T:28.38 E:0 B:41.0
2019-05-24 09:12:25,582 - Recv: T:28.32 E:0 B:41.0
2019-05-24 09:12:26,656 - Recv: T:28.30 E:0 B:41.3
2019-05-24 09:12:27,730 - Recv: T:28.44 E:0 B:41.7
2019-05-24 09:12:28,803 - Recv: T:28.30 E:0 B:42.0
2019-05-24 09:12:29,877 - Recv: T:28.32 E:0 B:42.2

So I waited a bit and it was clear the T:28.x E:0 was not going to change. I tried to set via GUI and it reset to zero. I set the temp via the LCD:

2019-05-24 09:12:41,686 - Recv: T:28.24 E:0 B:45.1
2019-05-24 09:12:42,760 - Recv: T:29.15 E:0 B:45.4

It started moving. Target temp is now 180 in the GUI. I set the temp to 200 via the GUI and it reset to 180.

2019-05-24 09:13:01,011 - Recv: T:57.88 E:0 B:49.4
2019-05-24 09:13:02,084 - Recv: T:60.21 E:0 B:49.6
2019-05-24 09:13:03,158 - Recv: T:62.44 E:0 B:49.8
2019-05-24 09:13:04,232 - Recv: T:64.76 E:0 B:50.0
2019-05-24 09:13:04,238 - Recv: ok
2019-05-24 09:13:04,250 - Send: N2 M104 S200*101
2019-05-24 09:13:04,256 - Recv: ok
2019-05-24 09:13:04,261 - Send: N3 M104 S180*111
2019-05-24 09:13:04,267 - Recv: ok
2019-05-24 09:13:04,271 - Send: N4 M104 S5*100
2019-05-24 09:13:04,278 - Recv: ok
2019-05-24 09:13:04,282 - Send: N5 M109 S180.000000*74
2019-05-24 09:13:05,305 - Recv: T:67.3 E:0 W:?
2019-05-24 09:13:06,379 - Recv: T:69.6 E:0 W:?
2019-05-24 09:13:07,452 - Recv: T:72.0 E:0 W:?
2019-05-24 09:13:08,526 - Recv: T:74.3 E:0 W:?

From this point on, I touch nothing.

2019-05-24 09:14:00,057 - Recv: T:176.5 E:0 W:?
2019-05-24 09:14:01,132 - Recv: T:178.0 E:0 W:?
2019-05-24 09:14:02,212 - Recv: T:179.3 E:0 W:9
2019-05-24 09:14:03,280 - Recv: T:180.6 E:0 W:8
2019-05-24 09:14:04,353 - Recv: T:181.8 E:0 W:7
2019-05-24 09:14:05,426 - Recv: T:182.5 E:0 W:6
2019-05-24 09:14:06,500 - Recv: T:183.3 E:0 W:5
2019-05-24 09:14:07,574 - Recv: T:183.8 E:0 W:4
2019-05-24 09:14:08,648 - Recv: T:184.2 E:0 W:9
2019-05-24 09:14:09,721 - Recv: T:184.2 E:0 W:9
2019-05-24 09:14:10,795 - Recv: T:184.3 E:0 W:9
2019-05-24 09:14:11,868 - Recv: T:184.2 E:0 W:9
2019-05-24 09:14:12,941 - Recv: T:183.9 E:0 W:9
2019-05-24 09:14:14,015 - Recv: T:183.9 E:0 W:8
2019-05-24 09:14:15,094 - Recv: T:183.5 E:0 W:7
2019-05-24 09:14:16,162 - Recv: T:183.1 E:0 W:6
2019-05-24 09:14:17,236 - Recv: T:182.9 E:0 W:5
2019-05-24 09:14:18,310 - Recv: T:182.4 E:0 W:4
2019-05-24 09:14:19,384 - Recv: T:182.0 E:0 W:3
2019-05-24 09:14:20,458 - Recv: T:181.3 E:0 W:2
2019-05-24 09:14:21,531 - Recv: T:180.9 E:0 W:1
2019-05-24 09:14:22,604 - Recv: T:180.1 E:0 W:0
2019-05-24 09:14:22,645 - Recv: ok
2019-05-24 09:14:22,650 - Send: N6 M104 S200*97
2019-05-24 09:14:22,655 - Recv: ok
2019-05-24 09:14:22,662 - Send: N7 G21*29
2019-05-24 09:14:22,668 - Recv: ok
2019-05-24 09:14:22,673 - Send: N8 G90*24
2019-05-24 09:14:22,678 - Recv: ok
2019-05-24 09:14:22,683 - Send: N9 M82*16
2019-05-24 09:14:22,688 - Recv: ok
2019-05-24 09:14:22,693 - Send: N10 M107*20
2019-05-24 09:14:22,698 - Recv: ok
2019-05-24 09:14:22,706 - Send: N11 G28 X0 Y0*34
2019-05-24 09:14:28,810 - Recv: ok
2019-05-24 09:14:28,816 - Send: N12 G28 Z0*106
2019-05-24 09:14:30,336 - Recv: ok
2019-05-24 09:14:30,348 - Send: N13 G1 Z15.0 F4800*16
2019-05-24 09:14:30,356 - Recv: ok
2019-05-24 09:14:30,362 - Send: N14 G92 E0*114
2019-05-24 09:14:30,367 - Recv: ok
2019-05-24 09:14:30,372 - Send: N15 G1 F140 E30*41
2019-05-24 09:14:30,379 - Recv: ok
2019-05-24 09:14:30,384 - Send: N16 G1 X20 Y0 F140 E30*25
2019-05-24 09:14:30,390 - Recv: ok
2019-05-24 09:14:30,395 - Send: N17 G92 E0*113
2019-05-24 09:14:30,401 - Recv: ok
2019-05-24 09:14:30,407 - Send: N18 G1 F4800*123
2019-05-24 09:14:30,413 - Recv: ok
2019-05-24 09:14:30,418 - Send: N19 M117 Printing...*35
2019-05-24 09:14:30,424 - Recv: ok
2019-05-24 09:14:30,429 - Send: N20 M107*23
2019-05-24 09:14:30,434 - Recv: ok

Once the nozzle hit 184 and cooled down to 180 I see the new target sent, which I did not do
2019-05-24 09:14:22,650 - Send: N6 M104 S200*97

The nozzle is clogged, so I cancelled it

2019-05-24 09:11:41,994 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2019-05-24 09:11:42,007 - octoprint.plugins.pi_support - ERROR - Got an error while trying to fetch the current throttle state via "/usr/bin/vcgencmd get_throttled"
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support/__init__.py", line 263, in _check_throttled_state
    state = get_vcgencmd_throttled_state(command)
  File "/home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support/__init__.py", line 140, in get_vcgencmd_throttled_state
    raise ValueError("cannot parse \"{}\" output: {}".format(command, output))
ValueError: cannot parse "/usr/bin/vcgencmd get_throttled" output: error=1 error_msg="Command not registered"

2019-05-24 09:11:42,808 - octoprint.plugins.tracking - INFO - Sent tracking event print_started, payload: {'origin': 'local', 'file': 'b94d3da98080ab1222cc6f9582081f1dc756936d'}
2019-05-24 09:12:16,674 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-05-24 09:12:26,010 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 173709}
2019-05-24 09:17:01,188 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Cancelling"

No other logs are being updated.

pi@octopi:~/.octoprint/logs $ ls -alhrt
total 904K
-rw-r--r--  1 pi pi    0 Mar 18  2016 plugin_cura_engine.log
-rw-r--r--  1 pi pi  14K Dec  6 10:38 plugin_pluginmanager_console.log.2018-12-06
-rw-r--r--  1 pi pi 187K May 21 15:33 plugin_softwareupdate_console.log
-rw-r--r--  1 pi pi  148 May 22 08:36 serial.log.2019-05-22_08-36-06
-rw-r--r--  1 pi pi  569 May 22 08:37 plugin_pluginmanager_console.log
-rw-r--r--  1 pi pi  148 May 22 08:39 serial.log.2019-05-22_08-39-38
-rw-r--r--  1 pi pi 566K May 23 08:42 octoprint.log.2019-05-22
-rw-r--r--  1 pi pi  23K May 24 08:42 octoprint.log.2019-05-23
-rw-r--r--  1 pi pi  29K May 24 09:15 serial.log
drwxr-xr-x 14 pi pi 4.0K May 24 09:15 ..
-rw-r--r--  1 pi pi  29K May 24 09:17 serial.log.test1
drwxr-xr-x  2 pi pi 4.0K May 24 09:17 .
-rw-r--r--  1 pi pi  11K May 24 09:27 octoprint.log

It feels like octoprint is waiting for something to happen before setting the new target temp. I'll dig into the code if I have to, I was just hoping someone might already have an idea.

foosel · May 24, 2019, 2:27pm

Could you please provide the full serial.log instead of hand picked excerpts?

Ewald_Ikemann · May 24, 2019, 2:29pm

For the M190 command sets the bed temperature (https://reprap.org/wiki/G-code#M190:_Wait_for_bed_temperature_to_reach_target_temp),
you may have a look at the last value (B:) that is obviously rising:

2019-05-24 09:11:42,002 - Send: N1 M190 S60.000000*113 
2019-05-24 09:11:43,010 - Recv: T:28.35 E:0 B:27.5

2019-05-24 09:12:28,803 - Recv: T:28.30 E:0 B:42.0
2019-05-24 09:12:29,877 - Recv: T:28.32 E:0 B:42.2

That the extruder temperature shoots up to about 184°C is a bit normal. The firmware needs to be sure, that the temperature is reached. The hotend may need the PID values to be optimized.

Then:
Why do you use M104

2019-05-24 09:14:22,650 - Send: N6 M104 S200*97

when you first use M109?

2019-05-24 09:13:04,282 - Send: N5 M109 S180.000000*74

Honestly I see no sense to first set the extruder to 180°C and wait and the set it to 200°C but not to wait then. 20°C can make a difference and a hotend clogged.

OutsourcedGuru · May 24, 2019, 4:42pm

You might want to do a /usr/bin/vcgencmd get_throttled to see if you get something back. (It should be a single line with the word "throttled=something". If not, then you have something wrong with your Raspbian image.

accountnumber3 · May 25, 2019, 1:06pm

@OutsourcedGuru
/usr/bin/vcgencmd get_throttled error=1 error_msg="Command not registered"
I did have some trouble upgrading from a previous version, issues with pip. It might be worth a reinstall.

@ Ewald_Ikemann (Sorry, new users can only mention 2 users in a post.)
Right, I get that it goes up then comes down. I don't know the printer commands, that's handled by the slicer and by Octoprint. The slicer set the temp to 180 but I've been having trouble with print quality so I'm fiddling with the settings. This post is focused on why the printer doesn't heat up at all without manual intervention.

@foosel
First, thank you very much for OctoPrint. It's really well done in every way. That being said, I apologize for not posting the full logs - I work in product support so reading log files is what I do. I know what's relevant and what's not. Also, this is my first post on this forum and I completely missed the 'upload' button in the editor so handpicking excerpts was more for your convenience and to keep the size of the post down. What I've excluded is very much not relevant, but I've deleted all logs, rebooted, and started a print so I can capture the entire process for you. In doing so, I decided not to touch anything at all after clicking 'print'. Surprisingly, once the print bed reached its target temperature, the extruder started heating up. In hindsight, there's no problem here. I'm just being impatient about the temperature. When I first started using Octoprint about a year ago (and not very frequently), the bed and the extruder would heat up at the same time. Now the extruder waits for the bed to hit the target temp. This screenshot shows what I'm talking about:

I haven't read through the code yet but I'm assuming that this is expected behavior, and I'm ok with that. It was just a surprise to me because it is not what I had experienced previously. I'll provide the logs if you want, but I'm ok with marking this as solved.octoprint_logs.gz.zip (2.4 MB)

Edit: logs attached but man they're boring.

accountnumber3 · May 26, 2019, 7:48pm

It's the slicer.

Here is a file that came with the printer Butterfly.gcode (2.9 MB)
Here is the file I was trying to print class="attachment" href="/uploads/default/original/2X/6/631820bbcedc476614d250627449c0e224908993.gcode">Dice_Tower_with_Storage_-_Step_DSidedwNut_flattop.gcode (864.9 KB)
(new users can only upload one file per post, I guess)

I disconnected octoprint and printed from the SD card. Butterfly heats both at the same time. Dice tower waits for the bed before hearing the extruder. I just assumed it was Octoprint because I updated it a while back, but I did also fiddle with the slicer a good bit.