[0.80.3] server keeps sending commands during M190/M109

brucehvn

I know I started a thread about this months ago, but I can't find it now. When I switched to one of the Marlin RC branches, I lost the ability to print from the RS web interface. Whenever I start a print, the server keeps sending the gcode to the printer even though the printer is stopped with an M190 or M109 command waiting for the the bed or the hotend to heat up ending up with a mess and I have to stop the print immediately.

After that, I only printed from the SD card or from scripts I wrote that would upload gcode to the SD card and then I would also start the SD card print via a script as well.

I also didn't print a lot over the past few months and have been doing some printer upgrades, etc.

Well now I'm running the latest Marlin bugfix-1.1.x branch code and I decided to give RS a try again, but it did the same thing. Below I'm including a snippet from the beginning of the gcode I uploaded to RS and the log output from RS.

This is with the armel version of RS running on a pcduino2 board. Everything used to work fine when I was running the old 1.0 release of Marlin, but newer releases aren't working for me.

GCODE beginning:

; generated by Slic3r 1.2.9 on 2017-06-21 at 00:59:48

; external perimeters extrusion width = 0.40mm

; perimeters extrusion width = 0.56mm

; infill extrusion width = 0.56mm

; solid infill extrusion width = 0.56mm

; top infill extrusion width = 0.56mm

M107

M190 S125 ; set bed temperature

M104 S255 ; set temperature

;G1 Z10 F150 ; lift nozzle

M109 S255 ; wait for temperature to be reached

G21 ; set units to millimeters

G90 ; use absolute coordinates

M82 ; use absolute distances for extrusion

G92 E0

G10 ; retract

G92 E0

G1 Z0.320 F7800.000

G1 X83.943 Y80.601 F7800.000

G11 ; unretract

G92 E0

G1 X85.590 Y79.651 E0.14623 F1200.000

Repetier Server Log Beginning

< 1:22:46.915: N108 M532 X0 L0

> 1:22:46.964: ok

< 1:22:46.965: N109 M531 ripple-test

< 1:22:46.965: N110 M530 S1 L80

> 1:22:46.970: ok

< 1:22:47.001: N111 <U+FEFF>; generated by Slic3r 1.2.9 on 2017-06-21 at 00:59:48

< 1:22:47.001: N112 M107

< 1:22:47.002: N113 M190 S125 ; set bed temperature

< 1:22:47.002: N114 M104 S255 ; set temperature

> 1:22:47.003: ok

< 1:22:47.003: N115 M109 S255 ; wait for temperature to be reached

< 1:22:47.004: N116 G21 ; set units to millimeters

> 1:22:47.011: echo:Unknown command: " "

> 1:22:47.011: ok

< 1:22:47.012: N117 G90 ; use absolute coordinates

< 1:22:47.012: N118 M82 ; use absolute distances for extrusion

> 1:22:47.015: T:28.50 /0.00 B:120.00 /125.00 @:0 B@:65 W:?

> 1:22:47.130: T:28.69 /0.00 B:120.00 /125.00 @:0 B@:127

> 1:22:48.014: T:28.69 /0.00 B:120.00 /125.00 @:0 B@:127 W:?

> 1:22:48.133: T:28.75 /0.00 B:120.02 /125.00 @:0 B@:127

> 1:22:49.014: T:28.69 /0.00 B:120.15 /125.00 @:0 B@:127 W:?

> 1:22:49.133: T:28.69 /0.00 B:120.15 /125.00 @:0 B@:127

> 1:22:50.013: T:28.62 /0.00 B:120.30 /125.00 @:0 B@:127 W:?

> 1:22:50.133: T:28.62 /0.00 B:120.30 /125.00 @:0 B@:127

> 1:22:51.013: Warning: Communication timeout - resetting communication buffer.

> 1:22:51.013: Connection status: Buffered:92, Manual Commands: 0, Job Commands: 5000

> 1:22:51.013: Buffer used:92 Enforced free byte:15 lines stored:6

< 1:22:51.014: N119 G92 E0

> 1:22:51.014: T:28.81 /0.00 B:120.56 /125.00 @:0 B@:127 W:?

< 1:22:51.015: N120 G10 ; retract

< 1:22:51.015: N121 G92 E0

< 1:22:51.016: N122 G1 Z0.320 F7800.000

> 1:22:51.132: T:28.81 /0.00 B:120.56 /125.00 @:0 B@:127

> 1:22:52.013: T:28.91 /0.00 B:120.75 /125.00 @:0 B@:127 W:?

> 1:22:52.131: T:28.91 /0.00 B:120.75 /125.00 @:0 B@:127

Repetier

Seems like you have set timeout to 4 seconds. If you set it that short you should activate busy protocol in marlin. That would send a "busy:" every 2 seconds and also prevents the timeout in this case as it would send it while waiting for temperature to be reached. Should also solve your current problem, also I think it should not happen anyway here since M109 is listed as slow command not triggering timeout if send recently.
N111 <U+FEFF>; generated by Slic3r 1.2.9 on 2017-06-21 at 00:59:48
shows that the file contains a utf-8 BOM. But that helps analysing in this case. Last ok therefore belongs to M109. Since it works with old marlin my guess is that the ok from M109 now comes before it is finished. But that should be ok anyway. Will try upgrading my latest marlin and see if I can reproduce it.

brucehvn

Do you think that BOM might be causing an issue:
N111 <U+FEFF>; generated by Slic3r 1.2.9 on 2017-06-21 at 00:59:48

Normally it looks like RS doesn't send comments to the printer, but in this case it's sending this line along which is probably generating the:

1:22:47.011: echo:Unknown command: " "

Maybe that's throwing everything off after that.

That was the log file unaltered taken from the server, but displayed in a terminal which is why that BOM showed up like that.

Also, which timeout are you referring to that's set to 4 seconds? I don't think I knowingly changed any setting regarding a communication timeout. When running gcode from my scripts, I do see the busy messages coming in from the printer.

Repetier

I think the BOM made it send the line but seems to do no harm.

Timeout is in printer configuration Connection->Communication Timeout
but a sI said if firmware has busy enabled (advanced config I guess) it should not happen. Maybe also the reason I did not see the problem.

Repetier

Ok have just tested with 1.1.3 from 5. June with busy disabled but it worked as expected. No timeout from M190 and M109. It waited also timeout was set to 4 seconds.

What happens with this simple script:
M190 S55
M117 Hi

should show no timeout also it has to wait for M117.

brucehvn

So last night, I stripped down the gcode file I was trying to print to just one layer and removed all the extrudes, just to see what would happen with and without the BOM (just to rule that out). I got the same behavior. I'll post some of the beginning of that log file below.

I then started a print from the SD card via a script which allows me to capture the output from the printer. I'll put the beginning of the gcode file from the SD card and the messages that were being received from the printer.

I'll try the two commands you posted above to see what happens. BTW, my communication timeout in the RS UI shows 3 seconds. I'm not sure if that's the default or if I ever modified that value or not.

Beginning of logfile from a no BOM version of the gcode

< 2:40:22.631: N18 M532 X0.0000 L0

< 2:40:22.639: N19 M532 X0 L0

> 2:40:22.640: ok

< 2:40:22.641: N20 M531 bom-test-3

< 2:40:22.641: N21 M530 S1 L0

> 2:40:22.651: ok

> 2:40:22.652: ok

< 2:40:22.726: N22 M107

< 2:40:22.727: N23 M532 X0.4424 L0

< 2:40:22.727: N24 M190 S80 ; set bed temperature

< 2:40:22.728: N25 M532 X0.8849 L0

< 2:40:22.729: N26 M104 S200 ; set temperature

> 2:40:22.731: T:26.94 /0.00 B:29.51 /0.00 @:0 B@:0

> 2:40:22.735: ok

> 2:40:22.736: ok

< 2:40:22.737: N27 M532 X1.3274 L0

> 2:40:22.740: T:26.94 /0.00 B:29.51 /80.00 @:0 B@:0 W:?

> 2:40:23.723: T:27.00 /0.00 B:29.49 /80.00 @:0 B@:127

> 2:40:23.743: T:27.00 /0.00 B:29.49 /80.00 @:0 B@:127 W:?

> 2:40:24.722: T:26.97 /0.00 B:29.74 /80.00 @:0 B@:127

> 2:40:24.743: T:26.97 /0.00 B:29.74 /80.00 @:0 B@:127 W:?

> 2:40:25.722: T:27.00 /0.00 B:29.97 /80.00 @:0 B@:127

> 2:40:25.742: T:27.00 /0.00 B:29.97 /80.00 @:0 B@:127 W:?

> 2:40:26.722: T:27.00 /0.00 B:30.34 /80.00 @:0 B@:127

> 2:40:26.741: Warning: Communication timeout - resetting communication buffer.

> 2:40:26.742: Connection status: Buffered:80, Manual Commands: 1, Job Commands: 214

> 2:40:26.742: Buffer used:80 Enforced free byte:17 lines stored:4

< 2:40:26.742: M117 ETA 02:36:47 day 22

> 2:40:26.743: T:27.00 /0.00 B:30.34 /80.00 @:0 B@:127 W:?

< 2:40:26.743: N28 M109 S200 ; wait for temperature to be reached

< 2:40:26.743: N29 M532 X1.7699 L0

< 2:40:26.744: N30 G21 ; set units to millimeters

> 2:40:27.721: T:26.97 /0.00 B:30.70 /80.00 @:0 B@:127

> 2:40:27.741: T:26.97 /0.00 B:30.70 /80.00 @:0 B@:127 W:?

> 2:40:28.721: T:27.03 /0.00 B:31.12 /80.00 @:0 B@:127

> 2:40:28.741: T:26.97 /0.00 B:31.21 /80.00 @:0 B@:127 W:?

> 2:40:29.737: T:26.91 /0.00 B:31.60 /80.00 @:0 B@:127

Beginning gcode from SD card

M107

M190 S125

M104 S255

M109 S255

G21

G90

M82

G92 E0

G10

G92 E0

G1 Z0.32 F7800

G1 X83.943 Y80.601 F7800

G11

G92 E0

G1 X85.59 Y79.651 E0.14623 F1200

G1 X87 Y79.429 E0.25596

G1 X107 Y79.429 E1.79368

G1 X108.86 Y79.824 E1.9399

Captured printer output when printing above SD card file

echo:Now fresh file: RIPTEST.GCD

File opened: RIPTEST.GCD Size: 429683

File selected

T:30.34 /0.00 B:120.05 /125.00 @:0 B@:64 W:?

T:30.34 /0.00 B:120.00 /125.00 @:0 B@:127 W:?

T:30.34 /0.00 B:120.15 /125.00 @:0 B@:127 W:?

T:30.39 /0.00 B:120.30 /125.00 @:0 B@:127 W:?

...

T:30.69 /0.00 B:125.00 /125.00 @:0 B@:84 W:2

T:30.69 /0.00 B:125.00 /125.00 @:0 B@:89 W:1

T:30.69 /0.00 B:125.00 /125.00 @:0 B@:92 W:0

T:30.69 /255.00 B:125.00 /125.00 @:0 B@:94 W:?

T:30.69 /255.00 B:125.00 /125.00 @:127 B@:96 W:?

T:30.97 /255.00 B:125.00 /125.00 @:127 B@:97 W:?

T:31.72 /255.00 B:125.00 /125.00 @:127 B@:98 W:?

T:33.02 /255.00 B:125.17 /125.00 @:127 B@:65 W:?

T:35.13 /255.00 B:125.17 /125.00 @:127 B@:64 W:?

T:37.93 /255.00 B:125.17 /125.00 @:127 B@:61 W:?

...

T:256.67 /255.00 B:125.00 /125.00 @:17 B@:75 W:2

T:255.00 /255.00 B:125.00 /125.00 @:49 B@:75 W:1

T:255.00 /255.00 B:125.00 /125.00 @:47 B@:75 W:0

X:189.00 Y:184.00 Z:10.00 E:0.00 Count X:30240 Y:29440 Z:80000

X:83.94 Y:80.60 Z:0.32 E:0.00 Count X:30240 Y:29440 Z:78200

echo:busy: processing

X:83.91 Y:80.65 Z:0.32 E:0.00 Count X:17818 Y:13230 Z:2132

X:103.89 Y:100.89 Z:0.32 E:0.00 Count X:17847 Y:16659 Z:2070

echo:busy: processing

X:105.76 Y:85.52 Z:0.32 E:0.00 Count X:16344 Y:13882 Z:2142

brucehvn

Here is the log from running a gcode file with the two commands you requested earlier. The UI showed it completely printed in just a couple seconds and the bed continued to heat after it was done.

< 23:22:05.276: N13 M532 X0 L0

< 23:22:05.277: N14 M531 repetier-test

< 23:22:05.278: N15 M530 S1 L0

> 23:22:05.279: ok

> 23:22:05.283: ok

< 23:22:05.305: N16 M190 S55

< 23:22:05.306: N17 M532 X33.3333 L0

< 23:22:05.307: M117 Hi

< 23:22:05.307: N18 M532 X66.6666 L0

> 23:22:05.382: T:24.59 /0.00 B:26.31 /55.00 @:0 B@:0 W:?

> 23:22:06.102: T:24.56 /0.00 B:26.44 /55.00 @:0 B@:127

> 23:22:06.312: T:24.56 /0.00 B:26.47 /55.00 @:0 B@:127 W:?

> 23:22:07.102: T:24.50 /0.00 B:26.50 /55.00 @:0 B@:127

> 23:22:07.311: T:24.53 /0.00 B:26.56 /55.00 @:0 B@:127 W:?

> 23:22:08.102: T:24.53 /0.00 B:26.94 /55.00 @:0 B@:127

> 23:22:08.315: T:24.53 /0.00 B:27.00 /55.00 @:0 B@:127 W:?

> 23:22:09.102: T:24.50 /0.00 B:27.22 /55.00 @:0 B@:127

> 23:22:09.314: T:24.47 /0.00 B:27.34 /55.00 @:0 B@:127 W:?

> 23:22:10.101: T:24.66 /0.00 B:27.78 /55.00 @:0 B@:127

> 23:22:10.314: T:24.53 /0.00 B:27.84 /55.00 @:0 B@:127 W:?

> 23:22:11.101: T:24.50 /0.00 B:28.11 /55.00 @:0 B@:127

> 23:22:11.313: T:24.50 /0.00 B:28.27 /55.00 @:0 B@:127 W:?

> 23:22:12.100: T:24.56 /0.00 B:28.48 /55.00 @:0 B@:127

> 23:22:12.313: T:24.53 /0.00 B:28.60 /55.00 @:0 B@:127 W:?

> 23:22:13.103: T:24.59 /0.00 B:28.94 /55.00 @:0 B@:127

> 23:22:13.312: T:24.53 /0.00 B:29.01 /55.00 @:0 B@:127 W:?

> 23:22:14.103: T:24.62 /0.00 B:29.26 /55.00 @:0 B@:127

> 23:22:14.312: T:24.50 /0.00 B:29.33 /55.00 @:0 B@:127 W:?

> 23:22:15.102: T:24.62 /0.00 B:29.63 /55.00 @:0 B@:127

> 23:22:15.311: T:24.59 /0.00 B:29.74 /55.00 @:0 B@:127 W:?

> 23:22:16.102: T:24.53 /0.00 B:29.97 /55.00 @:0 B@:127

> 23:22:16.311: T:24.50 /0.00 B:29.99 /55.00 @:0 B@:127 W:?

Repetier

Ok, strange results. From sd I see busy: so it is enabled, but does not start action if commands come from server. Have to activate it for me to see if I get the same. That would be an error.

Also I see my simple test gets no timeout. So that leaves your gcode sample for testing.

Could you put your firmware config in a dropbox or so for testing in case I can not reproduce it.

brucehvn

Thought I was on to something, but I guess not.

So, in actuality, your 2 line gcode didn't show that printing was complete until the bed was heated up to temperature, but it didn't stop issuing the commands at the M190. The progress bar in the UI went to 100% almost immediately, but that didn't go away until the bed finished heating and RS got the rest of the "oks" from Marlin.

I'll zip up my config files and put them on google drive.

brucehvn

Here's the link to my Configuration.h/Configuration_adv.h

https://drive.google.com/open?id=0ByWKg0tckgv2YU9oak54aWhCNm8

Repetier

Fr 2 times I could reproduce this. Then I added a breakpoint to debug the problem and it did not appear any more.
In any case I have reported the missing busy problem to marlin and also added a reset timeout on "ok" received. To me it appeared after M190 was finished so it put out M109 from active commands and then saw it took more then timeout seconds. This would be catched by the reset on "ok".

Your log looks a bit different since it started during M109, but you are also not using the develop version which already disables temp. fetching with M105 what might make a difference. Will do some more tests with it enabled.

brucehvn

What I thought might be causing issues was the auto temp reporting which is controlled by M155 S0/S1. That makes it so that client software like RS/RH doesn't have to do the M105 queries as Marlin auto sends the temperature values at all times. It doesn't seem to be spitting out the temperatures when the printer is first turned on, so I'm not sure if RS is actually aware of that capability and using it, because I do see it get turned on at some point. It definitely interferes with my scripts that try to load files to the sd card, etc. and I have to issue a M155 S0 to turn it off before hand. But my scripts are very simplistic in the communication handling, so that might be more of the problem in that case. I will try my larger test gcode file through RS with auto temp reporting turned off and see if that makes any difference.

Repetier

The autoreport was my invention, so server knows it (at least next release but seems it was already in 0.80.3). If you check in server installation dir/firmwares the marlin.xml you see:
<response type="autoreportTempSupported">^Cap:AUTOREPORT_TEMP:(\d)</response>

So when marlin has cap feature on server will detect it and enable. You can comment out that line if you do not want this.

brucehvn

I commented out the capability check for autotemp as you described above, but it had no affect on the problem. Ran a sample gcode that prints one layer with no extrusion (dry run) and it still blasted through the temp commands without waiting. I had already kind of ruled out autotemp as a problem, but this just confirmed it is not an issue.

Repetier

You can try new 0.85.0 version where I made some changes so I did not get the error any more. Maybe it helps also in your case with the same fix.

brucehvn

I installed 0.85.0 and it appears the same problem is there. Although, it looks like maybe my test gcode might have printed ok as from the log file it appears that RS maintained all the lines that didn't actually make it through while the printer was heating up and resent those lines after the fact. My test gcode only prints one layer and it's not extruding anything, so I can't tell for sure. I'm not sure on a full gcode file with many layers if it would be able to store all the lines or not.

Here is a link to the full log of the entire print: https://drive.google.com/open?id=0ByWKg0tckgv2Z3NPQ2pSOGtqQ2M

Repetier

Could you enable advanced ok in marlin configuration, so we see where the ok belongs to. Without knowing which line ok belongs to it is guessing and knowing is more critical here.

After that you might try enabling ping-pong mode. Then it must wait for the ok before sending next line which might help until we know what is confusing here the server.

brucehvn

Turned on advanced ok. From what I can see all the Ok's are coming back, but after the M190 to set the bed temp and wait, Marlin doesn't send the ok until the bed has heated up which I think is correct, isn't it? If it was an M140, it would return back right away.

Here's a link to the complete log file for the entire print with advanced ok:
https://drive.google.com/open?id=0ByWKg0tckgv2V1Fmb3lNZ2V6YXM

Repetier

Could you please send me the gcode where it happens. Can not reproduce this way. Looks like server does not recognice M190 but when I do it it does, so maybe something in your gcode is different that is not visible directly.

brucehvn

Ok, here is the gcode. I turned on ping pong mode, but it still looks like it's doing the exact same thing. Does that have anything to do with advanced ok being turned on? I tried restarting the RS service, but it still wouldn't wait for anything.

This gcode will print one layer, but will not extrude anything.

https://drive.google.com/open?id=0ByWKg0tckgv2Ti1aZlFMVkh0SGM