Ask a Question

SFTP Server stability affected by network quality

0 votes
by (230 points)

Recently we have added cellular connectivity at our client side for connecting to our SFTP Server, then we started to see events that our SFTP Server stopped working unexpectedly. Below are log lines extracted from two such events.

Is there any settings in the SFTP Server that we should make to remedy this situation?

Case 1 - Server Stopped after repeated error messages

11:22:02.334 Debug SFTP: Getting item info on '/Download/ATP.0091-13196': success.
11:22:02.365 Debug SFTP: Opening file '/Download/ATP.0091-13196' (Open, Read): success.
11:23:21.493 Debug SSH: Session 19: Sending keep-alive packet.
11:23:42.513 Debug SSH: Session 19: Sending keep-alive packet.
11:24:03.530 Debug SSH: Session 19: Sending keep-alive packet.
11:24:24.531 Debug SSH: Session 19: Sending keep-alive packet.
11:24:45.533 Debug SSH: Session 19: Sending keep-alive packet.
11:25:06.535 Debug SSH: Session 19: Sending keep-alive packet.
11:25:27.536 Debug SSH: Session 19: Sending keep-alive packet.
11:25:48.538 Debug SSH: Session 19: Sending keep-alive packet.
11:26:09.570 Debug SSH: Session 19: Sending keep-alive packet.
11:26:30.590 Debug SSH: Session 19: Sending keep-alive packet.
11:26:51.621 Debug SSH: Session 19: Sending keep-alive packet.
11:27:12.638 Debug SSH: Session 19: Sending keep-alive packet.
11:27:33.656 Debug SSH: Session 19: Sending keep-alive packet.
11:27:54.688 Debug SSH: Session 19: Sending keep-alive packet.
11:28:15.719 Debug SSH: Session 19: Sending keep-alive packet.
11:28:36.750 Debug SSH: Session 19: Sending keep-alive packet.
11:28:40.360 Error SSH: Session 19: Error while processing packet: System.Net.Sockets.SocketException (0x80004005): A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond
at coru.yuqz(Int32 rq, Int32 rr, Int32 rs, Int32 rt, SocketException ru)
11:28:40.360 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.360 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.375 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.391 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.407 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.407 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.422 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.438 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.438 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.438 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.453 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.453 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.453 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.469 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.469 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
11:28:40.485 Error SSH: Session 19: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)

Case 2 - Server Stopped after closing a connection

23:55:35.476 Debug Server: Session 37: Starting SftpModule(93) subsystem.
23:55:35.476 Debug SFTP: Getting item info on '/': success.
23:55:35.773 Debug SSH: Session 37: Received SSHMSGCHANNEL_REQUEST: exec('TIME').
23:55:35.773 Debug Server: Session 37: Starting ScpModule(94) subsystem.
23:55:35.773 Debug SCP: Getting item info on '/': success.
23:55:35.773 Debug SCP: Starting 'exec' subsystem for: TIME.
23:55:35.788 Debug SCP: Executing command: TIME
23:55:36.054 Debug SFTP: Getting item info on '/Download': success.
23:55:36.101 Debug SFTP: Opening directory '/Download': success.
23:55:36.194 Debug SFTP: Closing directory '/Download': success.
23:55:36.250 Debug SFTP: Getting item info on '/Download/ABKL.000-213818': success.
23:55:36.291 Debug SFTP: Getting item info on '/Download/ABKL.000-213818': success.
23:55:36.323 Debug SFTP: Opening file '/Download/ABKL.000-213818' (Open, Read): success.
23:55:49.777 Debug SFTP: Closing file '/Download/ABKL.000-213818': success.
23:55:49.876 Debug SFTP: Getting item info on '/Download/ATP.0091-13262': success.
23:55:49.923 Debug SFTP: Getting item info on '/Download/ATP.0091-13262': success.
23:55:49.954 Debug SFTP: Opening file '/Download/ATP.0091-13262' (Open, Read): success.
23:57:25.037 Debug SSH: Session 37: Sending keep-alive packet.
23:57:34.803 Info SSH: Session 37: Connection reset by peer.
23:57:34.803 Error SSH: Session 37: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
23:57:34.803 Error Server: Session 37: Error: corw: Error while sending packet data.
at coru.yuqw(copi ro)
at coph.wbak(Int32 afc, Byte[] afd, Int32 afe, Int32 aff)
at coph.wbak(Byte[] afg, Int32 afh, Int32 afi)
at cosd.rnij.ffaz()
23:57:34.803 Error SSH: Session 37: Error while sending packet data: System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at coru.yuqw(copi ro)
23:57:34.803 Debug SFTP: Closing file '/Download/ATP.0091-13262': success.
23:57:34.803 Info Server: Session 37: Closed connection from 210.3.164.82:49155.

Thanks in advance for your help.

Best Regards,
Stony Kong

Applies to: Rebex SFTP

1 Answer

0 votes
by (147k points)

According to the two logs, it does not look like the SFTP server stopped working. Instead, the SSH session's TCP connection failed (possibly due to a temporary outage of cellular connectivity), which resulted in various errors logged. However, the server should have stayed up an running, other connections should have not been affected, and it should have still been possible for the SFTP client to connect again and establish a new SSH session.

The error reporting could surely be improved (logging lot of identical "Error while sending packet data" does seem redundant). But the reason for the error is connectivity failure, and there is nothing a server can do about that, because this kind of error is beyond its control.

As for the errors, please note that the version of Rebex File Server you use is more than 3 years old and error logging has been improved since then.

by (230 points)
Dear Lukas,

Thank you for your reply.

We will double check if the problem (Windows reported the program has stopped working) would be related to our own code and we will also try using a newer Rebex package (2019R3) to see if the problem would be solved.

Thanks again for your support.

Best Regards,
Stony Kong
by (147k points)
If the program stopped working, that might indicate an unhandled exception. If no unhandled exception was reported when this occurred, consider registering an event handler for AppDomain.CurrentDomain.UnhandledException and logging the error.

We did fix one bug that could trigger an unhandled exception - it was located in the routine that sends those keep-alive packets, so it's quite possible this is affecting your application as well. This was fixed last years in R5.2. But 2019 R3 is still almost 3 years old and does not contain that fix yet.
...