Connection closed by os during print
Repetier Server 1.4.1 / 1.4.2 on Rapsbery Pi.
Repetier firmware on Mega 2560 + RAMPS 1.4
For some reason I got my printer disconnected at random during last two weeks. No errors except "Connection closed by os during print" It could be during printing or even saw two times when printer was on idle. It could work fine for a day then error next day. Here while I am writing this it happened again.
I tried various connection settings, bitrates, ping-pong mode, buffer size - all the same.
I replaced power supply (2A, I used it with RS for years but with older RS version) with brand new 3A - did not help.
The last thing for me left to try - different USB cable (testing in progress).
But I think it could be some bug in RS, idk.
I will be glad for any ideas and things to check.
Thank you.
Print log for one the fails:
Repetier firmware on Mega 2560 + RAMPS 1.4
For some reason I got my printer disconnected at random during last two weeks. No errors except "Connection closed by os during print" It could be during printing or even saw two times when printer was on idle. It could work fine for a day then error next day. Here while I am writing this it happened again.
I tried various connection settings, bitrates, ping-pong mode, buffer size - all the same.
I replaced power supply (2A, I used it with RS for years but with older RS version) with brand new 3A - did not help.
The last thing for me left to try - different USB cable (testing in progress).
But I think it could be some bug in RS, idk.
I will be glad for any ideas and things to check.
Thank you.
Print log for one the fails:
Send:14:49:34.368: N31023 G1 X94.594 Y78.369 E0.6128
Recv:14:49:34.403: ok 31019
Send:14:49:34.403: N31024 G1 X94.122 Y78.520 E0.6404
Recv:14:49:34.432: ok 31020
Send:14:49:34.432: N31025 G1 X94.347 Y78.744 E0.6580
Recv:14:49:34.469: ok 31021
Send:14:49:34.470: N31026 G1 X93.809 Y78.829 E0.6883
Recv:14:49:34.472: ok 31022
Send:14:49:34.472: N31027 G1 X93.621 Y78.640 E0.7031
Recv:14:49:34.497: ok 31023
Send:14:49:34.497: N31028 G1 X93.563 Y78.654 E0.7064
Recv:14:49:34.534: ok 31024
Send:14:49:34.535: N31029 G1 X93.511 Y78.654 E0.7093
Recv:14:49:34.561: ok 31025
Send:14:49:34.561: N31030 G1 X93.055 Y78.541 E0.7354
Recv:14:49:34.566: ok 31026
Send:14:49:34.566: N31031 G1 X92.848 Y78.489 E0.7473
Recv:14:49:34.599: ok 31027
Send:14:49:34.599: N31032 G1 X93.079 Y78.721 E0.7655
Mesg:14:49:34.783: Connection closed by os during print ... trying reconnect for 10 seconds to continue ...
Mesg:14:49:36.844: Dtr: true Rts: true
Mesg:14:49:36.846: Connection continued
Send:14:49:36.856: N31033 M117 ETA 04:04:55 day 22
Send:14:49:36.856: N31034 G1 X92.957 Y78.672 E0.7729
Send:14:49:36.857: N31035 G1 X92.506 Y78.652 E0.7980
Send:14:49:36.857: N31036 G1 X92.324 Y78.589 E0.8086
Recv:14:49:37.760: Printer reset detected:start
Recv:14:49:38.181: start
Recv:14:49:38.182: Detected EEPROM version:20
Recv:14:49:38.182: Info:Autoleveling enabled
Recv:14:49:38.182: Transformation matrix: 0.999999 0.000000 0.001707 -0.000004 0.999998 0.002131 -0.001707 -0.002131 0.999996
Send:14:49:38.182: N0 M110 N0
Send:14:49:38.182: N1 M999 ; In case we did not reset recover from fatal state
Send:14:49:38.182: N0 M110 N0
Send:14:49:38.182: N1 M105 ; fetch first temperature
Send:14:49:38.182: N2 M105
Send:14:49:38.182: N3 M115 ; Check firmware and capabilities
Send:14:49:38.182: N4 M220 S100 ; set speed multiplier
Send:14:49:38.182: N5 M221 S100 ; set flow multiplier
Send:14:49:38.182: N6 M355 ; get light status
Send:14:49:38.182: N7 G92 E0 ; reset extruder position
Send:14:49:38.183: N8 G90 ; absolute coordinates
Recv:14:49:40.056: Free RAM:3369
Recv:14:49:40.056: SelectExtruder:0
Recv:14:49:40.060: FlowMultiply:100
Recv:14:49:40.060: ok
Recv:14:49:40.060: ok 1
Recv:14:49:40.060: DebugLevel:6
Send:14:49:40.060: N9 M105
Send:14:49:40.060: N10 M82 ; absolute E values
Send:14:49:40.061: N11 G21 ; units are mm
Mesg:14:49:40.061: info:Continue from fatal state
Recv:14:49:40.061: ok
Recv:14:49:40.061: ok 1
Send:14:49:40.061: N12 M114 ; check position
Recv:14:49:40.066: T:0.00 /0 B:0.00 /0 B@:0 @:0 T0:0.00 /0 @0:0 T1:0.00 /0 @1:0
Recv:14:49:40.066: ok 2
Send:14:49:40.066: N13 M111 S6 ; debug flags
Recv:14:49:40.068: T:0.00 /0 B:0.00 /0 B@:0 @:0 T0:0.00 /0 @0:0 T1:0.00 /0 @1:0
Recv:14:49:40.068: ok 3
Send:14:49:40.068: N14 M360 ; get configuration
Recv:14:49:40.077: FIRMWARE_NAME:Repetier_1.0.4 COMPILED:Sep 19 2022 FIRMWARE_URL:https://github.com/repetier/Repetier-Firmware/ PROTOCOL_VERSION:1.0 MACHINE_TYPE:Mendel EXTRUDER_COUNT:2 REPETIER_PROTOCOL:3
Recv:14:49:40.078: Cap:PROGRESS:1
Recv:14:49:40.078: Cap:AUTOREPORT_TEMP:1
Recv:14:49:40.079: Cap:HOST_RESCUE:1
Recv:14:49:40.080: Cap:EEPROM:1
Recv:14:49:40.080: Cap:AUTOLEVEL:1
Recv:14:49:40.081: Cap:Z_PROBE:1
Recv:14:49:40.081: Cap:SOFTWARE_POWER:1
Recv:14:49:40.082: Cap:TOGGLE_LIGHTS:0
Recv:14:49:40.082: Cap:PAUSESTOP:1
Recv:14:49:40.083: Cap:PREHEAT:1
Recv:14:49:40.085: Cap:EMERGENCY_PARSER:1
Recv:14:49:40.087: Printed filament:275.31m Printing time:2 days 15 hours 32 min
Recv:14:49:40.087: PrinterMode:FFF
Recv:14:49:40.088: ok 4
Recv:14:49:40.089: SpeedMultiply:100
Recv:14:49:40.089: ok 5
Send:14:49:40.089: N15 M539 S1
Send:14:49:40.089: @getip
Recv:14:49:41.091: FlowMultiply:100
Recv:14:49:41.091: ok 6
Recv:14:49:41.091: Info:No case lights
Recv:14:49:41.091: ok 7
Recv:14:49:41.091: ok 8
Recv:14:49:41.091: ok 9
Recv:14:49:41.091: T:0.00 /0 B:0.00 /0 B@:0 @:0 T0:0.00 /0 @0:0 T1:0.00 /0 @1:0
Recv:14:49:41.091: ok 10
Recv:14:49:41.091: ok 11
Recv:14:49:41.092: ok 12
Recv:14:49:41.092: X:0.00 Y:0.00 Z:0.000 E:0.0000
Recv:14:49:41.092: ok 13
Recv:14:49:41.092: DebugLevel:6
Recv:14:49:41.092: ok 14
Recv:14:49:41.092: Config:Baudrate:250000
Recv:14:49:41.092: Config:InputBuffer:127
Recv:14:49:41.092: Config:NumExtruder:2
Recv:14:49:41.092: Config:MixingExtruder:0
Syslog:
Sep 21 14:32:04 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:32:04 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:32:04 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:32:04 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:32:58 Repetier-Server wpa_supplicant[471]: wlan0: Failed to initiate sched scan
Sep 21 14:33:05 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:33:05 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:33:05 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:33:05 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:34:01 Repetier-Server dhcpcd[661]: wlan0: new hardware address: 06:07:a2:6e:50:c1
Sep 21 14:34:01 Repetier-Server NetworkManager[354]: <info> [1663770841.5007] device (wlan0): set-hw-addr: set MAC address to 06:07:A2:6E:50:C1 (scanning)
Sep 21 14:34:01 Repetier-Server kernel: [26580.707253] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sep 21 14:34:01 Repetier-Server kernel: [26580.707263] brcmfmac: power management disabled
Sep 21 14:34:01 Repetier-Server NetworkManager[354]: <info> [1663770841.6278] device (wlan0): supplicant interface state: inactive -> disconnected
Sep 21 14:34:01 Repetier-Server NetworkManager[354]: <info> [1663770841.6647] device (wlan0): supplicant interface state: disconnected -> inactive
Sep 21 14:34:01 Repetier-Server wpa_supplicant[471]: wlan0: Reject scan trigger since one is already pending
Sep 21 14:34:06 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:34:06 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:34:06 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:34:06 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:35:07 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:35:07 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:35:07 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:35:07 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:36:08 Repetier-Server wpa_supplicant[471]: wlan0: Failed to initiate sched scan
Sep 21 14:36:09 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:36:09 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:36:09 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:36:09 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:37:10 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:37:10 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:37:10 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:37:10 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:37:11 Repetier-Server wpa_supplicant[471]: wlan0: Failed to initiate sched scan
Sep 21 14:38:11 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:38:11 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:38:11 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:38:11 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:38:14 Repetier-Server wpa_supplicant[471]: wlan0: Failed to initiate sched scan
Sep 21 14:39:13 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:39:13 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:39:13 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:39:13 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:39:17 Repetier-Server dhcpcd[661]: wlan0: new hardware address: 3e:bb:2d:75:4a:8a
Sep 21 14:39:17 Repetier-Server NetworkManager[354]: <info> [1663771157.4509] device (wlan0): set-hw-addr: set MAC address to 3E:BB:2D:75:4A:8A (scanning)
Sep 21 14:39:17 Repetier-Server kernel: [26896.658829] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sep 21 14:39:17 Repetier-Server kernel: [26896.658874] brcmfmac: power management disabled
Sep 21 14:40:14 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:40:14 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:40:14 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:40:14 Repetier-Server systemd[1]: Started Time & Date Service.
Sep 21 14:41:15 Repetier-Server dbus[335]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service'
Sep 21 14:41:15 Repetier-Server systemd[1]: Starting Time & Date Service...
Sep 21 14:41:15 Repetier-Server dbus[335]: [system] Successfully activated service 'org.freedesktop.timedate1'
Sep 21 14:41:15 Repetier-Server systemd[1]: Started Time & Date Service.
(Also why it does "Starting Time & Date Service..." every minute? Is it okay?)
Server Log:
Server Log:
2022-09-21 13:31:08: Updating info for /var/lib/Repetier-Server/printer/Piper_Belt/jobs/00000003_burpBrog_optimized_600p.g printer Piper_Belt
2022-09-21 13:31:22: Time analysing /var/lib/Repetier-Server/printer/Piper_Belt/jobs/00000003_burpBrog_optimized_600p.g:13304210 us
2022-09-21 13:32:30: Websocket: Client closed connection unexpectedly
2022-09-21 14:49:34: error: Reading serial conection failed: End of file. Closing connection.
2022-09-21 14:49:34: Connection closed during print ... trying reconnect for 10 seconds to continue ...
2022-09-21 14:49:34: Port closed for Piper Belt
2022-09-21 14:49:34: Connection closed: Piper Belt
2022-09-21 14:49:36: Connection continued: Piper Belt
2022-09-21 14:49:42: Sending push message failed: Exception: Temporary DNS error while resolving: informer.repetier-apps.com
2022-09-21 16:25:37: Websocket opened
2022-09-21 16:28:12: Websocket: Client closed connection unexpectedly
Comments
you see your syslog is missing the crucial part where it disconnected, so please check around that timestamp and make sure both use same time zone.
In case you need to check it on system not that syslog rotates dayly so on 22. Sep it is /var/log/syslog.0 eventually already gzipped.
Most important line 1:
so this is just a hardware issue. As you see a hub that also connects the webcam disabled usb devices and linux assumes EMI (Electro Magnetic Intererence). Aftwerwards it reconnects everything but of course print was stopped. EMI is not really dependent on power. It can be just a cable that is now closer to a usb part or usb ground causing too much change due to induction.
You might want to try connecting the printer to one of the usb 2 ports and see if it gets better.
You should also try the serial connection option to reconnect and continue print after short interruption. Will not prevent the issue as that is hardware related, but tries to continue print without lost of moves. Works on many printers but not all - depends on serial driver if it resets printer or not on reconnect.
Hm.. first USB cable have a ferrite bead on it but it did not help as well
The reconnect option did not work, I tried it.
Okay, thank you for information. I will continue the testing and maybe replace Rapsberry Pi with Intel NUC with Linux on it to get more power and stability.
And I moved Repetier-Server to old Intel NUC after all, for better stability.