I have added this issue to the tracker:
https://winscp.net/tracker/1977
https://winscp.net/tracker/1977
- martin
Post a reply
Before posting, please read how to report bug or request support effectively.
Bug reports without an attached log file are usually useless.
Topic review
- martin
Please respond with the logs to the email I've sent you.
- tgice
Hi Martin, I finally think I've captured a good debug trace of this event happening.
Could you email me about a private method of submitting them to you?
Could you email me about a private method of submitting them to you?
- martin
It just provides better logging for analysis. There's a link to instructions in the email I have sent you. The important is the trace log, not the session log (though please send that one too. Normal logging level is ok for a start).
- tgice
Hi Martin, thanks for your reply.
Do you think this debug version might solve my problem or just provide better logging for analysis?
If it's the latter, what log settings do you recommend? I assume you'd want the /log= option again and the highest loglevel?
Do you think this debug version might solve my problem or just provide better logging for analysis?
If it's the latter, what log settings do you recommend? I assume you'd want the /log= option again and the highest loglevel?
- martin
Re: SFTP "Remote side unexpectedly closed network connection" when session had succeeded
Thanks for your report.
I have sent you an email with a debug version of WinSCP to the address you have used to register on this forum.
I have sent you an email with a debug version of WinSCP to the address you have used to register on this forum.
- tgice
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:
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.
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:
. 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"
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.
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