SFTP "Remote side unexpectedly closed network connection" when session had succeeded
Hi,
I've recently had this problem crop up with one of my SFTP partners I've been using for several months. This issue appears to have happened a few times in those several months but is now possibly increasing in frequency.
I had the partner dig out SFTP server logs from their side when this happened last week and we reviewed them. One session where this below same issue happened had *server* logs (their side) that looked identical to other successful transfers where I saw no problem on the WinSCP side, so there doesn't seem to be much to trace on their side.
The command I ran was:
Any idea what might be causing this and whether there's an existing safe way that I could work around this in my scripting so that in situations like these (where there was some weird problem at the *very* end, but after all of the critical scripting actions completed successfully), I could somehow end up with a exit code 0 (short of having to parse the log file output and concluding that the transfer did actually work)?
I'm aware of this thread:
https://winscp.net/forum/viewtopic.php?t=29840
which seems to address a problem in the SFTP server OpenSSH version having to do with WinSCP version strings. Would that explain why I only *occasionally* have this problem with this partner server though? I mean it's something like 1 out of 20 or 30 transfers (maybe even less frequent) that this happens.
Here's the tail of the log:
I've recently had this problem crop up with one of my SFTP partners I've been using for several months. This issue appears to have happened a few times in those several months but is now possibly increasing in frequency.
I had the partner dig out SFTP server logs from their side when this happened last week and we reviewed them. One session where this below same issue happened had *server* logs (their side) that looked identical to other successful transfers where I saw no problem on the WinSCP side, so there doesn't seem to be much to trace on their side.
The command I ran was:
And you can see that at the very end, once the file has successfully been full uploaded and WinSCP has announced beginning the disconnect, we get a remote side closed message which of course causes the whole WinSCP command to fail with exit code 1, which forces me to have to review the situation.. 2021-04-06 05:02:58.815 Command-line: "\\***\bin\WinSCP.exe" /console=5.17.10 /consoleinstance=_2744_951 "/log=WinSCP-put-log.txt" "/loglevel=-1" "/command" "open sftp://***:***@***.com:10022" "cd /In" "put -nopreservetime -nopermissions forward_E406017.txt" "exit"
Any idea what might be causing this and whether there's an existing safe way that I could work around this in my scripting so that in situations like these (where there was some weird problem at the *very* end, but after all of the critical scripting actions completed successfully), I could somehow end up with a exit code 0 (short of having to parse the log file output and concluding that the transfer did actually work)?
I'm aware of this thread:
https://winscp.net/forum/viewtopic.php?t=29840
which seems to address a problem in the SFTP server OpenSSH version having to do with WinSCP version strings. Would that explain why I only *occasionally* have this problem with this partner server though? I mean it's something like 1 out of 20 or 30 transfers (maybe even less frequent) that this happens.
Here's the tail of the log:
. 2021-04-06 05:03:04.971 --------------------------------------------------------------------------
. 2021-04-06 05:03:04.971 Using SFTP protocol.
. 2021-04-06 05:03:04.986 Doing startup conversation with host.
. 2021-04-06 05:03:05.111 SFTP version 3 negotiated.
. 2021-04-06 05:03:05.111 We believe the server has signed timestamps bug
. 2021-04-06 05:03:05.111 We will use UTF-8 strings until server sends an invalid UTF-8 string as with SFTP version 3 and older UTF-8 strings are not mandatory
. 2021-04-06 05:03:05.111 Getting current directory name.
. 2021-04-06 05:03:05.236 Startup conversation with host finished.
< 2021-04-06 05:03:05.236 Script: Active session: [1] ***@***.com
> 2021-04-06 05:03:05.236 Script: cd /In
. 2021-04-06 05:03:05.236 Cached directory change via "/In" to "/In".
. 2021-04-06 05:03:05.236 Getting current directory name.
< 2021-04-06 05:03:05.236 Script: /In
> 2021-04-06 05:03:05.236 Script: put -nopreservetime -nopermissions forward_E406017.txt
< 2021-04-06 05:03:05.252 Script: Using configured transfer settings different from factory defaults.
. 2021-04-06 05:03:05.252 Copying 1 files/directories to remote directory "/In" - total size: 662
. 2021-04-06 05:03:05.252 File: 'forward_E406017.txt' [2021-04-06T09:02:54.033Z] [662]
. 2021-04-06 05:03:05.252 Copying "forward_E406017.txt" to remote directory started.
. 2021-04-06 05:03:05.565 Transfer done: 'forward_E406017.txt' => '/In/forward_E406017.txt' [633]
. 2021-04-06 05:03:05.565 Copying finished: Transferred: 633, Elapsed: 0:00:00, CPS: 0/s
> 2021-04-06 05:03:05.565 Script: exit
. 2021-04-06 05:03:05.565 Script: Exit code: 0
. 2021-04-06 05:03:05.565 Closing connection.
. 2021-04-06 05:03:05.690 Remote side unexpectedly closed network connection
< 2021-04-06 05:03:05.690 Script: Remote side unexpectedly closed network connection
