Printer Disconnects Partway Through First Layer

I've been working to get Repetier Server setup to monitor prints on a gCreate gMax 2 Pro and have had an issue where the print will fail after getting partway through the first layer. After a couple minutes the printer might or might not reconnect but I would like to avoid having to wonder if the print will finish or not. I'm running off of a Windows laptop and have tried all the USB ports and have assigned the printer to different COM ports to see if that was an issue. 

Connection Settings:
Ping-Pong Mode - On
BAUD Rate - 115200
Continue Print After Fast Reconnect - On
Buffer Size - 63
Communication Timeout - 25s

Here's a copy of the log from the most recent failure:

Recv:16:47:56.324: X:29.1990 Y:290.5460 Z:0.3600 E:3372.7017 Count X:3759 Y:24667 Z:582
Recv:16:47:58.330: X:29.1990 Y:290.5460 Z:0.3600 E:3372.7017 Count X:9738 Y:30645 Z:800
Recv:16:48:00.335: X:154.8790 Y:415.0950 Z:0.3600 E:3393.5029 Count X:9230 Y:30048 Z:781
Recv:16:48:02.324: X:154.8790 Y:415.0950 Z:0.3600 E:3393.5029 Count X:3198 Y:24015 Z:542
Recv:16:48:04.330: X:29.1990 Y:288.2830 Z:0.3600 E:3414.4919 Count X:6845 Y:27572 Z:705
Mesg:16:48:32.122: Warning: Communication timeout - resetting communication buffer.
Mesg:16:48:32.122: Connection status: Buffered:41, Manual Commands: 2, Job Commands: 5000
Mesg:16:48:32.122: Buffer used:41 Enforced free byte:0 lines stored:1
Mesg:16:48:58.131: Warning: Communication timeout - resetting communication buffer.
Mesg:16:48:58.131: Connection status: Buffered:17, Manual Commands: 2, Job Commands: 5000
Mesg:16:48:58.131: Buffer used:17 Enforced free byte:0 lines stored:1
Mesg:16:49:24.142: Warning: Communication timeout - resetting communication buffer.
Mesg:16:49:24.142: Connection status: Buffered:25, Manual Commands: 2, Job Commands: 5000
Mesg:16:49:24.142: Buffer used:25 Enforced free byte:0 lines stored:1
Mesg:16:49:24.142: Warning: Too many timeouts without response - disabling timeout message!
Mesg:16:52:26.192: Looks like printer is not powered any more. Closing connection.
Mesg:16:52:29.939: Printer reset requested false
Mesg:16:52:29.939: Dtr: false Rts: false
Mesg:16:52:29.970: Dtr: true Rts: true
Recv:16:52:31.883: Response while unconnected://action:notification M117 Finished
Recv:16:52:31.883: Connection verified by:ok
Recv:16:52:31.913: FIRMWARE_NAME:Marlin 2.0.9.3 (Mar 8 2022 11:23:16) SOURCE_CODE_URL:github.com/MarlinFirmware/Marlin PROTOCOL_VERSION:1.0 MACHINE_TYPE:gMax 2 PRO Copperhead EXTRUDER_COUNT:1 UUID:cede2a2f-41a2-4748-9b12-c55c62f367ff
Recv:16:52:31.913: Cap:QUOTED_STRINGS:1
Recv:16:52:31.913: Cap:SERIAL_XON_XOFF:0
Recv:16:52:31.913: Cap:BINARY_FILE_TRANSFER:0
Recv:16:52:31.913: Cap:EEPROM:1
Recv:16:52:31.913: Cap:VOLUMETRIC:1
Recv:16:52:31.913: Cap:AUTOREPORT_POS:1
Recv:16:52:31.913: Cap:AUTOREPORT_TEMP:1
Recv:16:52:31.913: Cap:PROGRESS:0
Recv:16:52:31.913: Cap:PRINT_JOB:1
Recv:16:52:31.913: Cap:AUTOLEVEL:1
Recv:16:52:31.913: Cap:RUNOUT:1
Recv:16:52:31.913: Cap:Z_PROBE:1
Recv:16:52:31.913: Cap:LEVELING_DATA:1
Recv:16:52:31.913: Cap:BUILD_PERCENT:1
Recv:16:52:31.913: Cap:SOFTWARE_POWER:0
Recv:16:52:31.913: Cap:TOGGLE_LIGHTS:0
Recv:16:52:31.913: Cap:CASE_LIGHT_BRIGHTNESS:0
Recv:16:52:31.913: Cap:EMERGENCY_PARSER:1
Recv:16:52:31.913: Cap:HOST_ACTION_COMMANDS:1
Recv:16:52:31.913: Cap:PROMPT_SUPPORT:1
Recv:16:52:31.913: Cap:SDCARD:1
Recv:16:52:31.913: Cap:REPEAT:1
Recv:16:52:31.913: Cap:SD_WRITE:1
Recv:16:52:31.913: Cap:AUTOREPORT_SD_STATUS:1
Recv:16:52:31.913: Cap:LONG_FILENAME:1
Recv:16:52:31.913: Cap:EXTENDED_M20:1
Recv:16:52:31.913: Cap:THERMAL_PROTECTION:1
Recv:16:52:31.913: Cap:MOTION_MODES:0
Recv:16:52:31.913: Cap:ARCS:1
Recv:16:52:31.913: Cap:BABYSTEPPING:1
Recv:16:52:31.913: Cap:CHAMBER_TEMPERATURE:0
Recv:16:52:31.913: Cap:COOLER_TEMPERATURE:0
Recv:16:52:31.913: Cap:MEATPACK:0
Recv:16:52:31.913: Cap:CONFIG_EXPORT:0
Recv:16:52:31.913: area:{full:{min:{x:-40.0000,y:-3.0000,z:0.0000},max:{x:458.0000,y:458.0000,z:610.0000}},work:{min:{x:0.0000,y:0.0000,z:0.0000},max:{x:458.0000,y:458.0000,z:610.0000}}}
Recv:16:52:31.913: X:157.1420 Y:415.0950 Z:50.3600 E:0.0000 Count X:12571 Y:33208 Z:40288 (2)
Recv:16:52:40.832: X:-40.0000 Y:458.0000 Z:50.3600 E:0.0000 Count X:-3200 Y:36640 Z:40288 (2)
Recv:16:55:44.848: echo:M112 Shutdown
Mesg:16:55:44.880: Firmware stopped! You can only send host and shell commands until you hit emergency stop or restart the printer. Eventually running print is stopped.
Mesg:16:55:44.880: Error:Printer halted. kill() called!
Mesg:16:55:44.880: Firmware stopped! You can only send host and shell commands until you hit emergency stop or restart the printer. Eventually running print is stopped.
Mesg:16:55:44.880: //action:poweroff
Mesg:16:56:48.269: Connection closed by os.


If you have any ideas, that would be great!

Comments

  • You should enable logging so you see full communication. But from what I can see I'd guess that the firmware does not return anything on commands being send causing the timeouts. When we get no response after several timeouts we assume a more severe problem and close connection from our side. That happened here and then after a new connect to usb port we get responses again. Can you say if windows thinks communication COM port  is a FTDI chip? Just to rule out you are the victim of a fake FTDI chip where the driver wants to disturb. Don't know about current state of FTDI actions against fake FTDI chips, but they were doing nasty things to communication in the past if they detected a fake.

    Other reason might be electrical nature disturbing communication. If that is always on first layer it might be when heated bed stops heating. You might try a print without heating to see if heaters disturb communication. You get lots of cild extrusion prevented I guess but that is ok then.

    And last on reconnect it gets "M112" from the reconnect that was meant for before. It does not reset as it did in the past so in server setup you might want to change "Emergency Solution" to only try to reset.
  • Windows has the COM port labeled as a Microsoft chip, is there a better way to grab the manufacturer information than through the COM ports in device manager?

    I have tried prints with and without the heated bed to no avail.

    Changed "Emergency Solution" to reconnect only and that didn't help.

    The model I have been trying to print is very large (18in x 18in x 4in) and has very long moves on the first layer. I've upped the Communication Timeout to 45s to see if that was the issue. I was able to get a much smaller print to fully complete using these settings but no such luck on two different larger prints. I waited a bit this time for the printer to reconnect 5ish minutes later and attempted to resume the print. The printer again disconnected a couple lines later.  I've included this log below.

    Recv:17:29:34.134: X:29.1990 Y:195.5110 Z:0.3600 E:1616.3480 Count X:13103 Y:26408 Z:621
    Recv:17:29:34.525: echo:busy: processing
    Recv:17:29:36.134: X:29.1990 Y:195.5110 Z:0.3600 E:1616.3480 Count X:19053 Y:32358 Z:503
    Recv:17:29:36.352: ok
    Send:17:29:36.352: M117 ETE 21:46:26
    Recv:17:29:36.352: //action:notification ETE 21:46:26
    Recv:17:29:36.352: ok
    Send:17:29:36.352: N149 G1 X249.914 Y415.095 E1652.91986
    Recv:17:29:36.447: ok
    Send:17:29:36.447: N150 G1 X29.199 Y194.38 E1689.5467
    Recv:17:29:38.134: X:249.9140 Y:415.0950 Z:0.3600 E:1652.9198 Count X:15152 Y:28366 Z:619
    Recv:17:29:38.448: echo:busy: processing
    Recv:17:29:40.135: X:249.9140 Y:415.0950 Z:0.3600 E:1652.9198 Count X:9171 Y:22385 Z:519
    Recv:17:29:40.438: echo:busy: processing
    Recv:17:29:42.134: X:249.9140 Y:415.0950 Z:0.3600 E:1652.9198 Count X:2906 Y:16120 Z:187
    Recv:17:29:42.285: ok
    Send:17:29:42.285: N151 G1 X29.199 Y193.248 E1689.67953
    Recv:17:29:42.391: ok
    Send:17:29:42.391: N152 G1 X251.046 Y415.095 E1726.49422
    Recv:17:29:44.129: X:29.1990 Y:193.2480 Z:0.3600 E:1689.6796 Count X:7407 Y:20531 Z:434
    Recv:17:29:44.391: echo:busy: processing
    Recv:17:29:46.133: X:29.1990 Y:193.2480 Z:0.3600 E:1689.6796 Count X:13323 Y:26447 Z:618
    Recv:17:29:46.391: echo:busy: processing
    Recv:17:29:48.133: X:29.1990 Y:193.2480 Z:0.3600 E:1689.6796 Count X:19520 Y:32644 Z:481
    Recv:17:29:48.275: ok
    Send:17:29:48.275: M117 Layer 1/169
    Recv:17:29:48.291: //action:notification Layer 1/169
    Recv:17:29:48.291: ok
    Send:17:29:48.291: N153 M73 P1 R1306 Q1 S1306
    Recv:17:29:48.291: ok
    Send:17:29:48.291: N154 G1 X252.177 Y415.095 E1726.62693
    Recv:17:29:48.382: ok
    Send:17:29:48.382: N155 G1 X29.199 Y192.117 E1763.62931
    Recv:17:29:50.130: X:252.1770 Y:415.0950 Z:0.3600 E:1726.6270 Count X:15078 Y:28111 Z:617
    Recv:17:29:50.380: echo:busy: processing
    Recv:17:29:52.134: X:252.1770 Y:415.0950 Z:0.3600 E:1726.6270 Count X:9131 Y:22165 Z:510
    Recv:17:29:52.380: echo:busy: processing
    Recv:17:29:54.123: X:252.1770 Y:415.0950 Z:0.3600 E:1726.6270 Count X:2902 Y:15936 Z:181
    Recv:17:29:54.290: ok
    Send:17:29:54.290: N156 G1 X29.199 Y190.986 E1763.76202
    Recv:17:29:54.382: ok
    Send:17:29:54.382: N157 G1 X253.308 Y415.095 E1800.95208
    Recv:17:29:56.130: X:29.1990 Y:190.9860 Z:0.3600 E:1763.7620 Count X:7458 Y:20401 Z:429
    Recv:17:29:56.384: echo:busy: processing
    Recv:17:29:58.133: X:29.1990 Y:190.9860 Z:0.3600 E:1763.7620 Count X:13435 Y:26378 Z:614
    Recv:17:29:58.380: echo:busy: processing
    Recv:17:30:00.121: X:29.1990 Y:190.9860 Z:0.3600 E:1763.7620 Count X:19411 Y:32354 Z:485
    Recv:17:30:00.306: ok
    Send:17:30:00.306: M117 ETA 15:15:58 day 30
    Recv:17:30:00.321: //action:notification ETA 15:15:58 day 30
    Recv:17:30:00.321: ok
    Send:17:30:00.321: N158 G1 X254.44 Y415.095 E1801.08491
    Recv:17:30:00.414: ok
    Send:17:30:00.414: N159 G1 X29.199 Y189.854 E1838.46282
    Recv:17:30:02.129: X:254.4400 Y:415.0950 Z:0.3600 E:1801.0850 Count X:15569 Y:28421 Z:610
    Recv:17:30:02.414: echo:busy: processing
    Recv:17:30:04.133: X:254.4400 Y:415.0950 Z:0.3600 E:1801.0850 Count X:9375 Y:22227 Z:515
    Recv:17:30:04.414: echo:busy: processing
    Recv:17:30:06.140: X:254.4400 Y:415.0950 Z:0.3600 E:1801.0850 Count X:3181 Y:16033 Z:193
    Recv:17:30:06.401: ok
    Send:17:30:06.401: M117 ETE 21:45:57
    Recv:17:30:06.401: //action:notification ETE 21:45:57
    Recv:17:30:06.401: ok
    Send:17:30:06.401: N160 G1 X29.199 Y188.723 E1838.59554
    Recv:17:30:06.497: ok
    Send:17:30:06.497: N161 G1 X255.571 Y415.095 E1876.16113
    Recv:17:30:08.127: X:29.1990 Y:188.7230 Z:0.3600 E:1838.5956 Count X:7146 Y:19908 Z:408
    Recv:17:30:08.491: echo:busy: processing
    Recv:17:30:10.132: X:29.1990 Y:188.7230 Z:0.3600 E:1838.5956 Count X:13089 Y:25850 Z:607
    Recv:17:30:10.494: echo:busy: processing
    Recv:17:30:12.136: X:29.1990 Y:188.7230 Z:0.3600 E:1838.5956 Count X:19314 Y:32076 Z:488
    Recv:17:30:12.484: ok
    Send:17:30:12.484: N162 G1 X256.703 Y415.095 E1876.29396
    Recv:17:30:12.581: ok
    Send:17:30:12.581: N163 G1 X29.199 Y187.591 E1914.04741
    Recv:17:30:14.138: X:256.7030 Y:415.0950 Z:0.3600 E:1876.2939 Count X:15986 Y:28658 Z:602
    Recv:17:30:14.588: echo:busy: processing
    Recv:17:30:16.140: X:256.7030 Y:415.0950 Z:0.3600 E:1876.2939 Count X:10014 Y:22686 Z:536
    Recv:17:30:16.577: echo:busy: processing
    Recv:17:30:18.130: X:256.7030 Y:415.0950 Z:0.3600 E:1876.2939 Count X:4042 Y:16714 Z:241
    Recv:17:30:18.580: echo:busy: processing
    Recv:17:30:18.612: ok
    Send:17:30:18.612: M117 Layer 1/169
    Recv:17:30:18.612: //action:notification Layer 1/169
    Recv:17:30:18.612: ok
    Send:17:30:18.612: N164 G1 X29.199 Y186.46 E1914.18013
    Recv:17:30:18.713: ok
    Send:17:30:18.713: N165 G1 X257.834 Y415.095 E1952.12126
    Recv:17:30:20.136: X:29.1990 Y:186.4600 Z:0.3600 E:1914.1802 Count X:6557 Y:19138 Z:371
    Recv:17:30:20.699: echo:busy: processing
    Recv:17:30:22.136: X:29.1990 Y:186.4600 Z:0.3600 E:1914.1802 Count X:12466 Y:25047 Z:594
    Recv:17:30:22.705: echo:busy: processing
    Recv:17:30:24.140: X:29.1990 Y:186.4600 Z:0.3600 E:1914.1802 Count X:18376 Y:30956 Z:526
    Recv:17:30:24.710: echo:busy: processing
    Recv:17:30:24.793: ok
    Send:17:30:24.793: N166 G1 X258.965 Y415.095 E1952.25397
    Recv:17:30:24.884: ok
    Send:17:30:24.884: N167 G1 X29.199 Y185.329 E1990.38279
    Recv:17:30:26.128: X:258.9650 Y:415.0950 Z:0.3600 E:1952.2540 Count X:17041 Y:29531 Z:575
    Recv:17:30:26.881: echo:busy: processing
    Recv:17:30:28.134: X:258.9650 Y:415.0950 Z:0.3600 E:1952.2540 Count X:11102 Y:23593 Z:563
    Mesg:17:31:12.890: Warning: Communication timeout - resetting communication buffer.
    Mesg:17:31:12.890: Connection status: Buffered:41, Manual Commands: 2, Job Commands: 5000
    Mesg:17:31:12.890: Buffer used:41 Enforced free byte:0 lines stored:1
    Mesg:17:31:58.898: Warning: Communication timeout - resetting communication buffer.
    Mesg:17:31:58.898: Connection status: Buffered:13, Manual Commands: 2, Job Commands: 5000
    Mesg:17:31:58.898: Buffer used:13 Enforced free byte:0 lines stored:1
    Mesg:17:32:44.899: Warning: Communication timeout - resetting communication buffer.
    Mesg:17:32:44.899: Connection status: Buffered:13, Manual Commands: 2, Job Commands: 5000
    Mesg:17:32:44.899: Buffer used:13 Enforced free byte:0 lines stored:1
    Mesg:17:32:44.899: Warning: Too many timeouts without response - disabling timeout message!
    Send:17:33:30.900: M117 ETA 15:15:59 day 30
    Send:17:34:16.906: M117 ETE 21:45:34
    Send:17:35:02.907: M117 Layer 1/169
    Send:17:35:48.919: M117 ETA 15:20:40 day 30
    Send:17:36:34.920: M117 ETE 21:45:34
  • The emergency change was not for the error. It was to prevent printer shutting down on reconnect if it gets the delayed M112 and because M112 does not reset with your firmwares setting.

    You also seem to have the checkbox "Port is visible when firmware is not running" checked. This is for printers using e.g. RAMBO board where the serial is always visible even if no communication is possible. Normally Prusa MKS. Should be disabled normally as it closes connection after 10 sequential errors. On the other hand this causes the restart after some minutes, also it was not meant for that:-)

    What you clearly see is that after every g-code send you get an "ok" as answer. When you see " echo:busy: processing" it means firmware is busy with a longer move and "ok" will come a bit later. Valid for timeout seconds. When you have this you set timeout normally to 3 seconds. Longer delays are communicated by firmware by busy every 2s. At the point where it starts hanging you get no busy and no ok any more. It is just like firmware stopped sending anything, which is the cause of the problem. Log is not 100% complete as you have filters enabled for temperature responses/commands. What I miss is that after each timeout you should see firmware sending a command - but I assume it is a M105 that you filtered. Starting 17:33:30.900 I also see other commands getting send.

    Haven't seen microsoft chips for serial so far - guess it is the microsoft driver. Device manager sounds correct. There are several tabs and in one you can see many attributes that show the device. But since it is not FTDI driver that is not that relevant.

    You can try a different/shorter/better protected usb cable or other usb ports. Try usb 2 not 3. Normally it works all the time if communication is up to standard, but with noise etc it seems they do not always recover from errors. Not the first one I observer stopping to send data until reconnect. On linux systems we have a usb reconnect on timeout for such issues where we disconnect usb port software side to reset driver. Unfortunately not on windows.
Sign In or Register to comment.