Winscp.com and File Upload Getting Network error: Software caused connection abort

Advertisement

jpantera
Joined:
Posts:
14
Location:
Los Angeles, CA

Winscp.com and File Upload Getting Network error: Software caused connection abort

Hello WinSCP Support and Martin:

Just in the past few days, we've been getting a few different file transfers that are running with winscp.com and file uploads, that logs indicate they are transferring relatively small files (~ 2 MB), but for a few days straight, leaving a "<file-name>.filepart" partially downloaded file on the vendor's site, and failing to complete, eventually reconnecting, but getting an inability to proceed (see Log snippet below).

Is there a way to set some sort of KEEPALIVE or something to tell the script to either re-try, or the log below seems to be saying it wants a question answered to delete the ".FILEPART" file, and re-try that way?

.
.
.
> 2020-02-09 03:00:31.915 Type: SSH_FXP_LSTAT, Size: 10, Number: 4871
< 2020-02-09 03:00:31.931 Type: SSH_FXP_ATTRS, Size: 21, Number: 4871
. 2020-02-09 03:00:31.931 Getting current directory name.
. 2020-02-09 03:00:31.931 Startup conversation with host finished.
< 2020-02-09 03:00:31.931 Script: Session started.
. 2020-02-09 03:00:31.931 File: 'C:\TEMP\FILE1.txt' [2020-02-09T10:15:22.518Z] [3003577]
. 2020-02-09 03:00:31.931 Copying "C:\TEMP\FILE1.txt" to remote directory started.
. 2020-02-09 03:00:31.931 Binary transfer mode selected.
. 2020-02-09 03:00:31.931 Checking existence of file.
> 2020-02-09 03:00:31.931 Type: SSH_FXP_LSTAT, Size: 30, Number: 5127
< 2020-02-09 03:00:31.946 Type: SSH_FXP_STATUS, Size: 33, Number: 5127
< 2020-02-09 03:00:31.946 Status code: 2
. 2020-02-09 03:00:31.946 Checking existence of partially transfered file.
> 2020-02-09 03:00:31.946 Type: SSH_FXP_LSTAT, Size: 39, Number: 5383
< 2020-02-09 03:00:31.962 Type: SSH_FXP_ATTRS, Size: 29, Number: 5383
. 2020-02-09 03:00:31.962 Resuming file transfer.
. 2020-02-09 03:00:31.962 Opening remote file.
> 2020-02-09 03:00:31.962 Type: SSH_FXP_OPEN, Size: 47, Number: 5635
< 2020-02-09 03:00:31.978 Type: SSH_FXP_STATUS, Size: 33, Number: 5635
< 2020-02-09 03:00:31.978 Status code: 2, Message: 5635, Server: File not found, Language: en
> 2020-02-09 03:00:31.978 Type: SSH_FXP_LSTAT, Size: 39, Number: 5895
< 2020-02-09 03:00:31.993 Type: SSH_FXP_ATTRS, Size: 29, Number: 5895
* 2020-02-09 03:00:31.993 (ETerminal) No such file or directory.
* 2020-02-09 03:00:31.993 Error code: 2
* 2020-02-09 03:00:31.993 Error message from server (en): File not found
. 2020-02-09 03:00:31.993 Asking user:
. 2020-02-09 03:00:31.993 Cannot overwrite remote file '/FILE1.txt.filepart'.$$
. 2020-02-09 03:00:31.993
. 2020-02-09 03:00:31.993 Press 'Delete' to delete the file and create new one instead of overwriting it.$$ ("No such file or directory.
. 2020-02-09 03:00:31.993 Error code: 2
. 2020-02-09 03:00:31.993 Error message from server (en): File not found")
< 2020-02-09 03:00:31.993 Script: Cannot overwrite remote file '/FILE1.txt.filepart'.
< 2020-02-09 03:00:31.993 Script: No such file or directory.
< 2020-02-09 03:00:31.993 Error code: 2
< 2020-02-09 03:00:31.993 Error message from server (en): File not found
* 2020-02-09 03:00:31.993 (EScpSkipFile) Cannot overwrite remote file '/FILE1.txt.filepart'.$$
* 2020-02-09 03:00:31.993
* 2020-02-09 03:00:31.993 Press 'Delete' to delete the file and create new one instead of overwriting it.$$
* 2020-02-09 03:00:31.993 No such file or directory.
* 2020-02-09 03:00:31.993 Error code: 2
* 2020-02-09 03:00:31.993 Error message from server (en): File not found
. 2020-02-09 03:00:31.993 Script: Failed
. 2020-02-09 03:00:31.993 Script: Exit code: 1
. 2020-02-09 03:00:31.993 Closing connection.
. 2020-02-09 03:00:31.993 Sending special code: 12
. 2020-02-09 03:00:31.993 Sent EOF message

Thank you!
- Joe Pantera

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
34,276
Location:
Prague, Czechia

Re: Winscp.com and File Upload Getting Network error: Software caused connection abort

It seems that WinSCP does retry. But the server refused an access to the partially uploaded file. I do not know why. You should contact the server administrator. Alternatively, you can try to prevent WinSCP from resuming the transfer and retry from the scratch instead: -resumesupport=off:
https://winscp.net/eng/docs/scriptcommand_put#resumesupport
(though you may get the same problem actually)

Reply with quote

jpantera
Joined:
Posts:
14
Location:
Los Angeles, CA

GUI Works With "Enumerated 1 network events making 1 cumulative events for socket", while not script

Thank you, Martin. Will look into the resume option.

In our case, I think it may be a bit more than that.

Today, we had a fourth straight day this transfer has failed (never failed before that). File upload, we were able to successfully upload the file via the WinSCP GUI, but winscp.com, the scripted method, fails to connect.

i turned on debug level 2 error logging, for both winscp.com and the GUI.

Winscp.com Script Start:

> 2020-02-11 08:54:25.639 Script: put -preservetime C:/FILE*.TXT /
> 2020-02-11 08:54:25.639 Script: Switch: -preservetime
> 2020-02-11 08:54:25.639 Script: Parameter: C:/FILE*.TXT
> 2020-02-11 08:54:25.639 Script: Parameter: /
< 2020-02-11 08:54:25.639 Script: -preservetime C:/FILE*.TXT /
. 2020-02-11 08:54:25.670 Copying 1 files/directories to remote directory "./Prod/"
. 2020-02-11 08:54:25.670 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: No; Mask:
. 2020-02-11 08:54:25.670 TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; InclM: ; ResumeL: 0
. 2020-02-11 08:54:25.670 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2020-02-11 08:54:25.685 File: 'C:\FILE*.txt' [2020-02-11T10:15:32.815Z] [3014721]
. 2020-02-11 08:54:25.685 Copying "C:\FILE1.txt" to remote directory started.
. 2020-02-11 08:54:25.685 Binary transfer mode selected.
. 2020-02-11 08:54:25.685 Checking existence of file.
> 2020-02-11 08:54:25.685 Type: SSH_FXP_LSTAT, Size: 30, Number: 1287
> 2020-02-11 08:54:25.685 07,00,00,05,07,00,00,00,15,2F,50,72,6F,64,2F,47,4C,5F,30,32,31,31,32,30,32,
> 2020-02-11 08:54:25.685 30,2E,74,78,74,
. 2020-02-11 08:54:25.685 Sent 34 bytes

GUI Start:

. 2020-02-11 08:57:16.203 Copying 1 files/directories to remote directory "/"
. 2020-02-11 08:57:16.203 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2020-02-11 08:57:16.203 TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; InclM: ; ResumeL: 0
. 2020-02-11 08:57:16.203 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2020-02-11 08:57:16.203 File: 'C:\FILE1.txt' [2020-02-11T10:15:32.815Z] [3014721]
. 2020-02-11 08:57:16.203 Copying "C:\FILE1.txt" to remote directory started.
. 2020-02-11 08:57:16.203 Binary transfer mode selected.
. 2020-02-11 08:57:16.203 Checking existence of file.
> 2020-02-11 08:57:16.203 Type: SSH_FXP_LSTAT, Size: 30, Number: 19463
> 2020-02-11 08:57:16.203 07,00,00,4C,07,00,00,00,15,2F,50,72,6F,64,2F,47,4C,5F,30,32,31,31,32,30,32,
> 2020-02-11 08:57:16.203 30,2E,74,78,74,
. 2020-02-11 08:57:16.203 Sent 34 bytes


After the initial start, the process sends data, in what looks like 35840 byte packets.

The Winscp.com script command seems to send six of these into the "send buffer", log shows these events:

. 2020-02-11 08:54:26.076 Sent 35840 bytes
. 2020-02-11 08:54:26.076 There are 0 bytes remaining in the send buffer
. 2020-02-11 08:54:26.076 Looking for network events
. 2020-02-11 08:54:26.076 Timeout waiting for network events
. 2020-02-11 08:54:26.076 Write request offset: 137164, len: 35814
> 2020-02-11 08:54:26.076 Type: SSH_FXP_WRITE, Size: 35836, Number: 3334

After about six of these, it says it errors out:

. 2020-02-11 08:54:26.513 Sent 35840 bytes
. 2020-02-11 08:54:26.513 There are 35904 bytes remaining in the send buffer
. 2020-02-11 08:54:26.513 Looking for network events
. 2020-02-11 08:54:26.513 Timeout waiting for network events
. 2020-02-11 08:54:26.513 There are 35904 bytes remaining in the send buffer, need to send at least another 3136 bytes
. 2020-02-11 08:54:26.513 Looking for network events
. 2020-02-11 08:54:26.623 Timeout waiting for network events
. 2020-02-11 08:54:26.623 There are 35904 bytes remaining in the send buffer
. 2020-02-11 08:54:26.623 There are 35904 bytes remaining in the send buffer, need to send at least another 3136 bytes
. 2020-02-11 08:54:26.623 Looking for network events
. 2020-02-11 08:54:26.732 Timeout waiting for network events
. 2020-02-11 08:54:26.732 There are 35904 bytes remaining in the send buffer
. 2020-02-11 08:54:26.732 There are 35904 bytes remaining in the send buffer, need to send at least another 3136 bytes
. 2020-02-11 08:54:26.732 Looking for network events.
(This message repeats over and over..., and the process fails).


However, on the GUI side, these same sized packets transfer data, note the log events "Detected Network Event", and the "Enumerated 1 network events making 1 cumulative events for socket" (I'm also showing two iterations of this log, because the second one contains a "Session upkeep"):

. 2020-02-11 08:57:21.671 Sent 35840 bytes
. 2020-02-11 08:57:21.671 There are 0 bytes remaining in the send buffer
. 2020-02-11 08:57:21.671 Looking for network events
. 2020-02-11 08:57:21.671 Detected network event
. 2020-02-11 08:57:21.671 Enumerating network events for socket 1948
. 2020-02-11 08:57:21.671 Enumerated 1 network events making 1 cumulative events for socket 1948
. 2020-02-11 08:57:21.671 Handling network read event on socket 1948 with error 0
. 2020-02-11 08:57:21.671 Received 25 bytes (0)
. 2020-02-11 08:57:21.671 Read 4 bytes (21 pending)
. 2020-02-11 08:57:21.671 Read 21 bytes (0 pending)
< 2020-02-11 08:57:21.671 Type: SSH_FXP_STATUS, Size: 21, Number: 20742
< 2020-02-11 08:57:21.671 65,00,00,51,06,00,00,00,00,00,00,00,02,4F,4B,00,00,00,02,65,6E,
< 2020-02-11 08:57:21.671 Status code: 0
. 2020-02-11 08:57:21.671 Write request offset: 101350, len: 35814
> 2020-02-11 08:57:21.671 Type: SSH_FXP_WRITE, Size: 35836, Number: 21254

. 2020-02-11 08:57:21.750 Sent 35840 bytes
. 2020-02-11 08:57:21.750 There are 0 bytes remaining in the send buffer
. 2020-02-11 08:57:21.750 Looking for network events
. 2020-02-11 08:57:21.750 Detected network event
. 2020-02-11 08:57:21.750 Enumerating network events for socket 1948
. 2020-02-11 08:57:21.750 Enumerated 1 network events making 1 cumulative events for socket 1948
. 2020-02-11 08:57:21.750 Handling network read event on socket 1948 with error 0
. 2020-02-11 08:57:21.750 Received 25 bytes (0)
. 2020-02-11 08:57:21.750 Read 4 bytes (21 pending)
. 2020-02-11 08:57:21.750 Read 21 bytes (0 pending)
< 2020-02-11 08:57:21.750 Type: SSH_FXP_STATUS, Size: 21, Number: 20998
< 2020-02-11 08:57:21.750 65,00,00,52,06,00,00,00,00,00,00,00,02,4F,4B,00,00,00,02,65,6E,
< 2020-02-11 08:57:21.750 Status code: 0
. 2020-02-11 08:57:21.750 Session upkeep
. 2020-02-11 08:57:21.750 Looking for network events
. 2020-02-11 08:57:21.750 Timeout waiting for network events
. 2020-02-11 08:57:21.750 Write request offset: 137164, len: 35814
> 2020-02-11 08:57:21.750 Type: SSH_FXP_WRITE, Size: 35836, Number: 21510

The GUI successfully transfers the file.

The winscp.com script does not, it fails.

Any input on how or why this happens, would be helpful.

- Joe P.

Reply with quote

martin
Site Admin
martin avatar

Re: GUI Works With "Enumerated 1 network events making 1 cumulative events for socket", while not script

Thanks.
I have sent you an email with a debug version of WinSCP to the address you have used to register on this forum.

Reply with quote

Advertisement

You can post new topics in this forum