Post a reply

Options
Add an Attachment

If you do not want to add an Attachment to your Post, please leave the Fields blank.

(maximum 10 MB; please compress large files; only common media, archive, text and programming file formats are allowed)

Options

Topic review

davidcbcs

Connection abort from command line, but works from GUI

That's what I was suspecting. Any ideas on how we could prevent a re-transmit in that situation?
martin

Re: Connection abort from command line, but works from GUI

OK, I see. The connection aborts after WinSCP asked the server to rename the temporary upload file to the final name. Although the connection aborted, the rename actually succeeded. After reconnect, WinSCP assumed the temporary upload file was lost somehow and restarts the transfer. It's complicated situation for WinSCP to decide if everything went fine or not.
davidcbcs

Connection abort from command line, but works from GUI

Here is a snippet of the log where it re-starts.
martin

Re: Connection abort from command line, but works from GUI

Please post session log file of that scenario.
davidcbcs

Connection abort from command line, but works from GUI

We continue to have connection aborts, but the files eventually upload. We are living with this.
But once and a while, there is a problem when a file finishes uploading and there is a disconnect, and then it starts uploading another copy of the same file. Is there a way to have it not overwrite the existing file if it is re-trying the upload?
davidcbcs

Re: Connection abort from command line, but works from GUI

It turns out that it doesn't work consistently.

FYI – I could not find the -nopreservetime switch in the documentation. When I add -nopreservetime to my script, I get the message:
Unknown switch 'nopreservetime'
martin

Re: Connection abort from command line, but works from GUI

And does it work consistently with "Preserve timestamp" off? Did you try that in scripting? Use -nopreservetime.
davidcbcs

Re: Connection abort from command line, but works from GUI

I tried turning off "Optimize connection buffer size" but that didn't work.
I did get a successful transfer with the GUI at 7:54 after turning off the "Preserve timestamp" option. The log is attached.
I believe the Windows firewall is disabled for WinSCP. I do have access to the server-side logs, but I haven't seen anything useful.
martin

Re: Connection abort from command line, but works from GUI

Would turning off "Optimize connection buffer size" make any difference?
If you ever manage do a successful transfer in the GUI again, please post the logs.
Do you have access to server-side logs? Do they show anything useful?
Can you try turning off a local firewall?
davidcbcs

Re: Connection abort from command line, but works from GUI

Strange, WinSCP in GUI mode w/ binary transfer now does multiple re-connects. FileZilla still works. Here is the log.
martin

Re: Connection abort from command line, but works from GUI

Please post logs for all of those (FileZilla, successful GUI transfer).

Though note that the failed transfers in previous GUI log were also using binary mode.
davidcbcs

Re: Connection abort from command line, but works from GUI

The file uploads eventually. It goes for a second, disconnects, re-connects, and then goes for a second, over and over. With FileZilla FTP it uploads a 44MB file in 10 seconds. With WinSCP and all the re-tries, it takes 43 minutes.

I tried WinSCP GUI again and changed the transfer settings to "binary" and the file uploaded in seconds. Then I tried changing the command line script to:
put -transfer=binary upload.zip

but there is no change, it keeps re-trying.
martin

Re: Connection abort from command line, but works from GUI

@davidcbcs: So can you upload the file anyhow now? Using any other SFTP client? Haven't you run out of disk space/user quota?
davidcbcs

Re: Connection abort from command line, but works from GUI

Unfortunately, today it is failing in the GUI also. Attached is the log.
martin

Re: Connection abort from command line, but works from GUI

@davidcbcs: Please post separate scripting and GUI logs showing a fresh upload (with no .filepart file in the target folder prior to the upload).
davidcbcs

Connection abort from command line, but works from GUI

I am seeing a similar issue where the put from a script fails, but the GUI uploads successfully. Attached is a log file with a failure at the top and success at the bottom of the log (until I aborted the transfer). Can I get that debug version also?

Thanks!
martin

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.
jpantera

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.
martin

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)
jpantera

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