File Transfer timing out - Host is not communicating for 15 seconds

Advertisement

roisin
Joined:
Posts:
5
Location:
Ireland

File Transfer timing out - Host is not communicating for 15 seconds

Hi,

We have a Windows batch script running on a client's site to transfer files to and from our AWS S3 buckets using WinSCP & AWS Transfer host. (They are on the latest version of WinSCP).

The script transfers all files in a particular folder to our S3 bucket – using code such as:
"C:\Program Files (x86)\WinSCP\WinSCP.com" ^
  /log=%filename% /ini=nul ^
  /command ^
    "open sftp://USERNAME@AWSENDPOINT -hostkey=""KEY"" -privatekey=""PATH TO KEY "" -passphrase=""KEY"" -rawsettings SendBuf=0" ^
    "lcd ""C:\FilesToUpload""" ^
    "cd ""in/""" ^
    "put -nopermissions -nopreservetime *" ^
There are a maximum of 5 files to be transferred nightly, and the total size is approx 2 MB.

This works nightly on 15 client sites with no issues, but approx 2 weeks ago it stopped working on one client site.

The issue is that the script stops after transferring only one file, giving a message:
. 2023-07-27 02:31:27.615 Script: Authenticated.
. 2023-07-27 02:31:27.615 Doing startup conversation with host.
< 2023-07-27 02:31:27.615 Script: Starting the session...
> 2023-07-27 02:31:27.615 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2023-07-27 02:31:29.505 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2023-07-27 02:31:29.505 SFTP version 3 negotiated.
. 2023-07-27 02:31:29.505 We believe the server has signed timestamps bug
. 2023-07-27 02:31:29.505 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
. 2023-07-27 02:31:29.505 Changing directory to "/in".
. 2023-07-27 02:31:29.505 Getting real path for '/in'
> 2023-07-27 02:31:29.505 Type: SSH_FXP_REALPATH, Size: 12, Number: 4880
< 2023-07-27 02:31:29.521 Type: SSH_FXP_NAME, Size: 24, Number: 4880
. 2023-07-27 02:31:29.521 Real path is '/in'
. 2023-07-27 02:31:29.521 Trying to open directory "/in".
> 2023-07-27 02:31:29.521 Type: SSH_FXP_LSTAT, Size: 12, Number: 5127
< 2023-07-27 02:31:29.656 Type: SSH_FXP_ATTRS, Size: 29, Number: 5127
. 2023-07-27 02:31:29.656 Getting current directory name.
. 2023-07-27 02:31:29.656 Startup conversation with host finished.
< 2023-07-27 02:31:29.656 Script: Session started.
. 2023-07-27 02:31:29.656 File: 'FILE NAME' [2023-07-26T01:10:03.832Z] [22442]
. 2023-07-27 02:31:29.656 Copying "FILE NAME" to remote directory started.
. 2023-07-27 02:31:29.656 Binary transfer mode selected.
. 2023-07-27 02:31:29.656 Opening remote file.
> 2023-07-27 02:31:29.656 Type: SSH_FXP_OPEN, Size: 61, Number: 5379
< 2023-07-27 02:31:29.703 Type: SSH_FXP_HANDLE, Size: 10, Number: 5379
> 2023-07-27 02:31:29.719 Type: SSH_FXP_WRITE, Size: 22464, Number: 5894
> 2023-07-27 02:31:29.719 Type: SSH_FXP_CLOSE, Size: 10, Number: 6148
. 2023-07-27 02:31:46.125 Waiting for data timed out, asking user what to do.
. 2023-07-27 02:31:46.125 Asking user:
. 2023-07-27 02:31:46.125 **Host is not communicating for 15 seconds.
. 2023-07-27 02:31:46.125 
. 2023-07-27 02:31:46.125 Wait for another 15 seconds?** ()
< 2023-07-27 02:31:46.125 Script: Host is not communicating for more than 15 seconds.
< 2023-07-27 02:31:46.125 Still waiting...
< 2023-07-27 02:31:46.125 Note: If the problem repeats, try turning off 'Optimize connection buffer size'.
< 2023-07-27 02:31:46.125 Warning: Aborting this operation will close connection!
. 2023-07-27 02:31:49.238 Data has arrived, closing query to user.
. 2023-07-27 02:31:49.238 Answer: OK
. 2023-07-27 02:31:49.238 Network error: Software caused connection abort
. 2023-07-27 02:31:49.238 Connection was lost, asking what to do.
. 2023-07-27 02:31:49.238 Asking user:
. 2023-07-27 02:31:49.238 Network error: Software caused connection abort ()
< 2023-07-27 02:31:49.238 Script: Network error: Software caused connection abort
. 2023-07-27 02:31:55.488 Answer: Retry
< 2023-07-27 02:31:55.488 Script: Searching for host...
. 2023-07-27 02:31:55.488 Looking up host "AWS ENDPOINT" for SSH connection
. 2023-07-27 02:31:55.488 Connecting to ip address port 22
. 2023-07-27 02:31:55.488 Connected to ip address
We have checked the client firewall, and all is ok – we have a similar script that downloads a file from our S3 to their network and this works perfectly every night.
From the logs we can see that the connection is being made successfully and it's authenticating ok, it's just not getting a response on time to finish the transfer.

We have tried running this script at various times during the day and it's still has the same results, so it's not timing or anything holding onto the files.
I have the adding the following to the script : -nopermissions & rawsettings SendBuf=0, this has not helped.

I should also mention that the script is run nightly by a Windows Scheduled task (by an account that does have all the correct permissions). But even when we run it manually at other times, we still get the same results.

This is only happening on one client site - what other things should we check?

Thanks for your help.

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
40,605
Location:
Prague, Czechia

Re: File Transfer timing out - Host is not communicating for 15 seconds

Please attach full session log file. Can you upload the same file in WinSCP GUI? Or in any other SFTP client? (when running them on the same machine, where the script fails) Can you post log files for that too?

Reply with quote

roisin
Joined:
Posts:
5
Location:
Ireland

Hi, thanks for getting back to me. Attached is the full session log. I have also tried to transfer the file using the GUI, and got the error in the attach jpg file. I was able to skip though. This is the reason I added the -nopermission to the script, I thought this would resolve this. I am not sure how to get the logs for the transfer in the GUI , sorry.
Kind Regards,
Roisin

winscp error.jpg

Reply with quote

Advertisement

martin
Site Admin
martin avatar

In GUI you are connecting to 34.247.198.164, while in script to 63.34.123.174. So those are not comparable logs.

Reply with quote

roisin
Joined:
Posts:
5
Location:
Ireland

Hi Martin, thanks for getting back to me. I know the IP is different, we are using an AWS SFTP transfer endpoint URL as the host, so this resolves to a pool of different IP addresses. It will not be the same IP address.
However, I added the -timeout=120 tag to the script and this allowed us to isolate the problem to one particular file. It seems there was a field in one of the text files which contained a large number of spaces. When we removed this, the transfer worked. We are continuing to monitor and test this.
Do you know why this happens?
Kind Regards,
Roisin

Reply with quote

martin
Site Admin
martin avatar

No idea. Can you upload that file in the GUI? If you can, please post comparable logs of a failed upload in script and a successful upload of the same file in GUI.

Reply with quote

Advertisement

Kush
Guest

Martin Never Actually Provides Resolution to multiple posts of connection dropping to AWS.

Many users have provided endless logs, and never see a resolution. I don't think the WinSCP can or ever will provide a resolution to this issue.

Reply with quote

martin
Site Admin
martin avatar

Re: Martin Never Actually Provides Resolution to multiple posts of connection dropping to AWS.

@Kush: Can you post link to those posts with "endless logs" to which I didn't provide resolution? Or can you actually post the logs yourself?

Reply with quote

Advertisement

You can post new topics in this forum