[0.80.3] server keeps sending commands during M190/M109

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.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

«1

Comments

  • 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.
  • 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.
  • 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.
  • 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.

  • edited June 2017
    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.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
    ok
    ok
     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: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
    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
    echo:busy: processing
    echo:busy: processing
    echo:busy: processing
    X:105.76 Y:85.52 Z:0.32 E:0.00 Count X:16344 Y:13882 Z:2142

  • 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.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:?

  • 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.
  • edited June 2017
    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.
  • Here's the link to my Configuration.h/Configuration_adv.h

    https://drive.google.com/open?id=0ByWKg0tckgv2YU9oak54aWhCNm8
  • 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.
  • 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.
  • 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.
  • 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.
  • 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.
  • 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


  • 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.
  • 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

  • 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.
  • 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

  • It's crazy. When I run your code everything is ok also it look sver ysimilar to your log:

    < 14:19:35.780: N12 M532 X100.0000 L0
    > 14:19:36.073: ok N12 P15 B3
    < 14:19:36.073: N13 M532 X0 L0
    < 14:19:36.073: N14 M531 bom
    < 14:19:36.073: N15 M530 S1 L0
    < 14:19:36.077: N16 M107
    > 14:19:36.077: ok N13 P15 B3
    > 14:19:36.077: ok N14 P15 B3
    > 14:19:36.077: ok N15 P15 B3
    < 14:19:36.077: N17 M532 X0.4424 L0
    < 14:19:36.077: N18 M190 S55 ; set bed temperature
    < 14:19:36.077: N19 M532 X0.8849 L0
    < 14:19:36.077: N20 M104 S170 ; set temperature
    < 14:19:36.077: N21 M532 X1.3274 L0
    > 14:19:36.081: ok N16 P15 B3
    > 14:19:36.081: ok N17 P15 B3
    < 14:19:36.081: N22 M109 S170 ; wait for temperature to be reached
    < 14:19:36.081: N23 M532 X1.7699 L0
    > 14:19:36.085:  T:24.37 /0.00 B:24.88 /55.00 @:0 B@:0 W:?
    > 14:19:36.589:  T:24.30 /0.00 B:24.96 /55.00 @:0 B@:0
    > 14:19:37.085:  T:24.26 /0.00 B:24.96 /55.00 @:0 B@:0 W:?
    > 14:19:37.589:  T:24.30 /0.00 B:24.96 /55.00 @:0 B@:0
    > 14:19:38.084:  T:24.26 /0.00 B:24.92 /55.00 @:0 B@:0 W:?
    > 14:19:38.592:  T:24.34 /0.00 B:24.88 /55.00 @:0 B@:0
    > 14:19:39.088:  T:24.30 /0.00 B:24.92 /55.00 @:0 B@:127 W:?
    > 14:19:39.592:  T:24.34 /0.00 B:24.92 /55.00 @:0 B@:127
    > 14:19:40.088:  T:24.30 /0.00 B:25.14 /55.00 @:0 B@:127 W:?
    > 14:19:40.591:  T:24.30 /0.00 B:25.37 /55.00 @:0 B@:127
    > 14:19:41.087:  T:24.30 /0.00 B:25.71 /55.00 @:0 B@:127 W:?
    > 14:19:41.591:  T:24.34 /0.00 B:25.99 /55.00 @:0 B@:127
    > 14:19:42.090:  T:24.30 /0.00 B:26.39 /55.00 @:0 B@:127 W:?
    > 14:19:42.594:  T:24.26 /0.00 B:26.76 /55.00 @:0 B@:127
    > 14:19:43.090:  T:24.22 /0.00 B:27.27 /55.00 @:0 B@:127 W:?
    > 14:19:43.594:  T:24.26 /0.00 B:27.81 /55.00 @:0 B@:127
    > 14:19:44.090:  T:24.26 /0.00 B:28.38 /55.00 @:0 B@:127 W:?
    > 14:19:44.594:  T:24.30 /0.00 B:28.98 /55.00 @:0 B@:127
    > 14:19:45.089:  T:24.14 /0.00 B:29.63 /55.00 @:0 B@:127 W:?
    > 14:19:45.593:  T:24.22 /0.00 B:30.31 /55.00 @:0 B@:127
    > 14:19:46.089:  T:24.34 /0.00 B:31.07 /55.00 @:0 B@:127 W:?
    > 14:19:46.592:  T:24.34 /0.00 B:31.61 /55.00 @:0 B@:127
    > 14:19:47.092:  T:24.34 /0.00 B:32.32 /55.00 @:0 B@:127 W:?
    > 14:19:47.596:  T:24.34 /0.00 B:33.02 /55.00 @:0 B@:127
    > 14:19:48.092:  T:24.22 /0.00 B:33.85 /55.00 @:0 B@:127 W:?
    > 14:19:48.596:  T:24.18 /0.00 B:34.84 /55.00 @:0 B@:127
    > 14:19:49.091:  T:24.37 /0.00 B:35.52 /55.00 @:0 B@:127 W:?
    > 14:19:49.595:  T:24.34 /0.00 B:36.08 /55.00 @:0 B@:127
    > 14:19:50.091:  T:24.30 /0.00 B:36.75 /55.00 @:0 B@:127 W:?
    > 14:19:50.594:  T:24.26 /0.00 B:37.38 /55.00 @:0 B@:127
    > 14:19:51.094:  T:24.26 /0.00 B:38.08 /55.00 @:0 B@:127 W:?

    ok are a line up or down from different timings, but as you see no timeout also my timeout is 4s. So last thing I can imagine is that your printer config in server has somehow an influence. Can you post that as well? You have on home screen of serve a export function for each printers config.

    Ok and maybe the last thing that could be different: On which os and device are you running the server? If linux which of the 5 versions?
  • It's the armel version.  It's running on a pcduino2 board that has Linaro 12.10 as the OS.

    Welcome to Linaro 12.11 (GNU/Linux 3.4.29+ armv7l)

     * Documentation:  https://wiki.linaro.org/

    I'll get you the configs later today.  Any idea why ping pong mode doesn't seem to be working?  That probably would solve the issue for the most part.
  • The problem is that in your case the server does not recognice M190 as slow command. Question is why it gets recogniced in my version and your identical version does not do it. Ok I had to reduce the temperature for my printer but that should not make a difference.

    One other questions is, what would happen if you preheat the bed. Then M190 is finished fast so next waitingcommand would be M109 - does it also time out then for you?

  • Here is a link to my printer configuration.

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

    I ran a test where I pre-heated the bed to 80, then ran that same gcode.  It did return immediately from the M190, and when it hit the M109 for the extruder, it still kept sending commands even without an ok, and had the communication timeout.  After that, I changed my timeout to 4 secs to match yours, but still the same.

    <  0:41:53.612: N16 M532 X100.0000 L0
    >  0:41:53.618:  T:28.00 /0.00 B:80.05 /80.00 @:0 B@:42
    >  0:41:53.618: ok N16 P15 B3
    <  0:41:53.618: N17 M532 X0 L0
    >  0:41:53.625: ok N17 P15 B3
    <  0:41:53.625: N18 M531 bom-test-3
    >  0:41:53.633: ok N18 P15 B3
    <  0:41:53.633: N19 M530 S1 L0
    >  0:41:53.637: ok N19 P15 B3
    <  0:41:53.698: N20 M107
    >  0:41:53.703: ok N20 P15 B3
    <  0:41:53.703: N21 M532 X0.4424 L0
    >  0:41:53.711: ok N21 P15 B3
    <  0:41:53.711: N22 M190 S80 ; set bed temperature
    >  0:41:53.715: ok N22 P15 B3
    <  0:41:53.715: N23 M532 X0.8849 L0
    >  0:41:53.723: ok N23 P15 B3
    <  0:41:53.723: N24 M104 S200 ; set temperature
    >  0:41:53.735: ok N24 P15 B3
    <  0:41:53.735: N25 M532 X1.3274 L0
    >  0:41:53.751: ok N25 P15 B3
    <  0:41:53.751: N26 M109 S200 ; wait for temperature to be reached
    >  0:41:53.780:  T:28.00 /200.00 B:80.05 /80.00 @:0 B@:42 W:?
    >  0:41:54.617:  T:28.00 /200.00 B:80.05 /80.00 @:127 B@:41
    >  0:41:54.772:  T:28.00 /200.00 B:80.05 /80.00 @:127 B@:41 W:?
    >  0:41:55.616:  T:28.47 /200.00 B:80.05 /80.00 @:127 B@:40
    >  0:41:55.772:  T:28.50 /200.00 B:80.03 /80.00 @:127 B@:44 W:?
    >  0:41:56.620:  T:29.50 /200.00 B:79.90 /80.00 @:127 B@:70
    >  0:41:56.771:  T:29.53 /200.00 B:79.90 /80.00 @:127 B@:70 W:?
    >  0:41:57.619:  T:30.91 /200.00 B:79.90 /80.00 @:127 B@:71
    >  0:41:57.751: Warning: Communication timeout - resetting communication buffer.
    >  0:41:57.751: Connection status: Buffered:17, Manual Commands: 1, Job Commands: 214
    >  0:41:57.751: Buffer used:17 Enforced free byte:0 lines stored:1
    <  0:41:57.752: N27 M532 X1.7699 L0
    >  0:41:57.771:  T:31.14 /200.00 B:79.90 /80.00 @:127 B@:71 W:?
    >  0:41:58.619:  T:32.82 /200.00 B:80.03 /80.00 @:127 B@:46
    >  0:41:58.771:  T:33.23 /200.00 B:80.05 /80.00 @:127 B@:42 W:?

  • Ok, I have no idea how to reproduce this. Had some problems when I compiled firmware to 115200 baud and saw I got a timeout during connection, which I fixed for 0.85.2. After that I could also connect with and without ping-pong and you sample with your config on a pi with armhf code worked without problems. So try 0.85.2 when published in a short while. But as you said it only happend with one marlin version and I picked lasted RC after you complained. So maybe you need to update firmware to latest also I do not really see any firmware error here.
  • I just installed 0.85.2 and will run some tests.  Do you think slowing down the serial communications might have some effect?

    Do you think the problem is that because it doesn't seem to stop at the M190 command and because it won't get an OK until the bed is heated up, that's why it thinks the communication timed out?

    Is it RS that's timing and triggering that communication timeout message, or is it a hardware timeout.  Does RS send a command and if it hasn't received an OK or some response back in 4 seconds, it generates that error?  Seems like temperature responses are coming back, however.
  • Server is sending the commands. Marlin sends ok after the command is executed while repetier-firmware returns it already when it is parsed successfully. So that is ok. While heating Marlin sends temperatures which is also normal. The timeout comes from server as it doe snot detect M190 in your case. But everytime I run it, server detects it, which is the crazy thing I do not understand. Since it recognices it  for me I get no timeout while you get it. And as you said with the older marlin it also did understand it for you.

    Could you try and run it from server on windows instead of pcduino? That is the only thing I could  not test as I have none. I used a raspberry pi 3 with armhf version, so that I have at least the same compilation.
  • Ok, this is interesting.  Running the test gcode again, it looks like RS is trying to do ping pong mode correctly now.  But it still doesn't wait on the M190 or M109 commands.  Here's what it looks like to me is happening:

    1) Each line of gcode is being sent and RS is waiting for the ok response (ping pong mode).
    2) RS sends the M190 command, but for some reason doesn't recognize that as a blocking code, so it waits for the ok and sends nothing else.
    3) After 4 seconds waiting for the ok, it generates the timeout error.
    4) The timeout error seems to make it now skip waiting for the ok on the M190 and it sends the next command.
    5) Since the bed is heating up still, that next command times out after 4 seconds and another timeout error is generated.
    6) Since ping pong mode seems to be working now, this pattern continues.  RS sends a command, waits 4 seconds, the timeout message gets generated, then the next command is sent, and so on until everything is heated up and all the lines get resent and the print continues.

    So, to me, the root of all the evil here is why on my system, it's not recognizing the commands listed in the <blockingCommands> section of the marlin.xml file.

    Would it be possible to do a special build that puts out some extra logging around the portion of the code that compares the incoming gcode to the blocking commands to try and pinpoint why it's not recognizing a match?

    Here's a link to my last logfile:
    https://drive.google.com/open?id=0ByWKg0tckgv2WjFiZWtxUHU4WWs
  • BTW, I'm using the armel version since I have libc version 2.15.
  • I think I have found it. You have busy enabled so it ignores slow commands. In my case I have never seen a busy: so it does not assume it is enabled. In your case I bet it has seen busy since connection started so it assumes to see a busy: after 2 seconds. But Marlin has implemented the busy protocol wrong as M190/M109 do not report busy. I have already filed that bug report.

    2 possible solutions:
    1. Disabale busy in marlin
    2. Disable detection in server. In marlin.xml you have a line

    <response type="resetTimeout">^(echo:)?busy:</response>
    Comment it out or delete it and restart server. Then it does not detect you have busy so it does not rely on faulty implementation.

  • Ahh, interesting.  I just finished the Windows test.  Although, a little interesting in Windows was that on the first run, I did see it stop and wait for the M190, but on the M109, it generated the timeout messages again.  On the second run, it didn't stop for the M190 or the M109, and on the third try, it stopped for the M190 again, but not the M109.  So are you saying that if it saw any busy message at any time in this session that would trigger it to ignore the slow commands from then on for any prints in the session?

    I ran it a 4th time.  Here's how the total progression went:
    1) Fresh install of RS, first print, waited for M190, didn't wait for M109
    2) 2nd run of print job (same session), didn't wait for M190 or M109.
    3) At about 98% of the 2nd print job above, the server process seemed to lock up.  I could not stop the service and had to restart Windows
    4) First try at printing after rebooting, Waited for M190, but didn't wait for M109.
    5) Second try at printing in same session, didn't wait for M190 or M109.

    Now in the first runs, I didn't see any busy message in the logfile between the M190 and M109 commands (see below).  But I do see 6 instances of busy responses later on in the log.

    So, if I comment out the busy detection, what will happen during normal printing when a busy message actually gets sent?  I imagine it might get a timeout, but that will probably be ok because the server will resend that line after it's not busy, right?  Since that's only usually a few seconds I would guess that won't be a big issue.

    I'm going to switch back to the pcduino and try your theory out.  Crossing my fingers...

    <  1:58:50.961: N10 M532 X100.0000 L0
    >  1:58:50.970: ok N10 P15 B3
    <  1:58:50.983: N11 M532 X0 L0
    >  1:58:50.991: ok N11 P15 B3
    <  1:58:50.991: N12 M531 bom-test-3
    >  1:58:50.999: ok N12 P15 B3
    <  1:58:50.999: N13 M530 S1 L0
    >  1:58:51.007: ok N13 P15 B3
    <  1:58:51.041: N14 M107
    >  1:58:51.057: ok N14 P15 B3
    <  1:58:51.057: N15 M532 X0.4424 L0
    >  1:58:51.064: ok N15 P15 B3
    <  1:58:51.064: N16 M190 S50 ; set bed temperature
    >  1:58:51.074:  T:26.84 /0.00 B:30.59 /50.00 @:0 B@:0 W:?
    >  1:58:51.269:  T:26.81 /0.00 B:30.54 /50.00 @:0 B@:127
    >  1:59:49.085:  T:26.66 /0.00 B:49.97 /50.00 @:0 B@:62 W:3
    ----- snip -------
    >  1:59:52.083:  T:26.84 /0.00 B:50.10 /50.00 @:0 B@:51 W:0
    >  1:59:52.277:  T:26.87 /0.00 B:50.12 /50.00 @:0 B@:48
    >  1:59:52.804: ok N16 P15 B3
    <  1:59:52.804: M117 ETA 02:00:44 day 1
    >  1:59:52.812: ok P15 B3
    <  1:59:52.812: N17 M532 X0.8849 L0
    >  1:59:52.821: ok N17 P15 B3
    <  1:59:52.821: N18 M104 S80 ; set temperature
    >  1:59:52.829: ok N18 P15 B3
    <  1:59:52.829: N19 M532 X1.3274 L0
    >  1:59:52.837: ok N19 P15 B3
    <  1:59:52.837: N20 M109 S80 ; wait for temperature to be reached
    >  1:59:52.845:  T:26.84 /80.00 B:50.14 /50.00 @:0 B@:45 W:?
    >  1:59:53.276:  T:26.91 /80.00 B:50.14 /50.00 @:127 B@:45
    >  1:59:53.849:  T:26.84 /80.00 B:50.18 /50.00 @:127 B@:38 W:?
    >  1:59:54.275:  T:26.94 /80.00 B:50.16 /50.00 @:127 B@:41
    >  1:59:54.845:  T:27.09 /80.00 B:50.16 /50.00 @:127 B@:41 W:?
    >  1:59:55.283:  T:27.50 /80.00 B:50.12 /50.00 @:127 B@:47
    >  1:59:55.848:  T:28.12 /80.00 B:50.08 /50.00 @:127 B@:54 W:?
    >  1:59:56.283:  T:28.97 /80.00 B:50.16 /50.00 @:127 B@:38
    >  1:59:56.847:  T:30.00 /80.00 B:50.18 /50.00 @:127 B@:33 W:?
    >  1:59:57.282:  T:30.86 /80.00 B:50.10 /50.00 @:127 B@:47
    >  1:59:57.843: Warning: Communication timeout - resetting communication buffer.
    >  1:59:57.843: Connection status: Buffered:16, Manual Commands: 2, Job Commands: 214
    >  1:59:57.843: Buffer used:16 Enforced free byte:0 lines stored:1
    <  1:59:57.843: M117 ETE 00:00:58
    >  1:59:57.847:  T:31.92 /80.00 B:50.10 /50.00 @:127 B@:46 W:?
    >  1:59:58.282:  T:33.06 /80.00 B:50.10 /50.00 @:127 B@:45
    >  1:59:58.847:  T:34.40 /80.00 B:50.16 /50.00 @:127 B@:32 W:?
    >  1:59:59.281:  T:35.86 /80.00 B:50.08 /50.00 @:127 B@:46
    >  1:59:59.846:  T:38.06 /80.00 B:50.14 /50.00 @:127 B@:33 W:?
    >  2:00:00.284:  T:39.27 /80.00 B:50.10 /50.00 @:127 B@:39
    >  2:00:00.846:  T:41.39 /80.00 B:50.10 /50.00 @:127 B@:38 W:?
    >  2:00:01.284:  T:42.41 /80.00 B:50.08 /50.00 @:127 B@:40
    >  2:00:01.849:  T:44.64 /80.00 B:50.06 /50.00 @:127 B@:42 W:?
    >  2:00:02.285:  T:45.81 /80.00 B:50.08 /50.00 @:127 B@:38
    >  2:00:02.846: Warning: Communication timeout - resetting communication buffer.
    >  2:00:02.846: Connection status: Buffered:18, Manual Commands: 1, Job Commands: 214
    >  2:00:02.846: Buffer used:18 Enforced free byte:0 lines stored:1
    <  2:00:02.846: N21 M532 X1.7699 L0
    >  2:00:02.848:  T:48.30 /80.00 B:50.04 /50.00 @:127 B@:44 W:?
    >  2:00:03.283:  T:49.61 /80.00 B:50.06 /50.00 @:127 B@:39
    >  2:00:03.848:  T:51.88 /80.00 B:50.04 /50.00 @:127 B@:42 W:?
    >  2:00:04.282:  T:53.60 /80.00 B:50.08 /50.00 @:127 B@:33
    >  2:00:04.848:  T:55.45 /80.00 B:50.03 /50.00 @:127 B@:44 W:?
    >  2:00:05.284:  T:57.35 /80.00 B:50.01 /50.00 @:127 B@:47
    >  2:00:05.847:  T:59.38 /80.00 B:50.01 /50.00 @:127 B@:46 W:?
    >  2:00:06.282:  T:61.21 /80.00 B:50.06 /50.00 @:127 B@:35
    >  2:00:06.860:  T:62.97 /80.00 B:50.06 /50.00 @:127 B@:34 W:?
    >  2:00:07.281:  T:64.84 /80.00 B:50.06 /50.00 @:127 B@:34
    >  2:00:07.852: Warning: Communication timeout - resetting communication buffer.
    >  2:00:07.852: Connection status: Buffered:23, Manual Commands: 1, Job Commands: 214
    >  2:00:07.852: Buffer used:23 Enforced free byte:0 lines stored:1
    <  2:00:07.852: M117 ETA 02:01:04 day 1

Sign In or Register to comment.