File Transfer timing out - Host is not communicating for 15 seconds
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 *" ^
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
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.