Batch script started failing - Timeout detected (solved)
I have a batch script that uses WinSCP to push new files to a remote directory over FTP. The files are around 80mb/ea and connections are 40/15mb fibre.
The script ran perfectly for over a year however now fails with error: Timeout detected. (data connection)
There is no change to configuration at the destination as far as I know. I can connect and transfer files as normal with FileZilla.
Can anyone suggest what the issue might be? Log sample and scripts below.
pushfiles.bat
--------------
set year=%DATE:~6,4%
set day=%DATE:~0,2%
set mnt=%DATE:~3,2%
IF %day% LSS 10 SET day=0%day:~1,1%
IF %mnt% LSS 10 SET mnt=0%mnt:~1,1%
set backuptime=%year%-%mnt%-%day%
C:\backups\winscp.exe /console /script=script.txt /log="C:\backups\logs\%backuptime%.log"
EXIT
script.txt
-----------
open ftp://username:password@ftp.domain.com
option transfer binary
put -neweronly C:\backups\*.* /mount/backups/
close
exit
log
----
2018-01-28 11:35:00.378 Connecting to ftp.domain.com...
. 2018-01-28 11:35:00.456 Connected with ftp.domain.com. Waiting for welcome message...
< 2018-01-28 11:35:00.472 220 Your FTP server ready.
> 2018-01-28 11:35:00.472 USER username
< 2018-01-28 11:35:00.503 331 Password required for username.
> 2018-01-28 11:35:00.503 PASS ********
< 2018-01-28 11:35:01.003 230 User usernme logged in.
> 2018-01-28 11:35:01.003 SYST
< 2018-01-28 11:35:01.081 215 UNIX Type: L8
> 2018-01-28 11:35:01.081 FEAT
< 2018-01-28 11:35:01.113 211- Extensions supported:
< 2018-01-28 11:35:01.113 AUTH TLS
< 2018-01-28 11:35:01.113 PBSZ
< 2018-01-28 11:35:01.113 PROT
< 2018-01-28 11:35:01.113 SIZE
< 2018-01-28 11:35:01.113 MDTM
< 2018-01-28 11:35:01.128 MFMT
< 2018-01-28 11:35:01.128 REST STREAM
< 2018-01-28 11:35:01.128 UTF8
< 2018-01-28 11:35:01.128 MLST type*;modify*;size*;UNIX.mode*;UNIX.owner*;UNIX.group*;
< 2018-01-28 11:35:01.144 MLSD
< 2018-01-28 11:35:01.144 211 End.
> 2018-01-28 11:35:01.144 OPTS UTF8 ON
< 2018-01-28 11:35:01.191 200 OK, UTF-8 enabled
< 2018-01-28 11:35:01.191 Script: Connected
. 2018-01-28 11:35:01.191 Connected
. 2018-01-28 11:35:01.191 Doing startup conversation with host.
< 2018-01-28 11:35:01.191 Script: Starting the session...
> 2018-01-28 11:35:01.191 PWD
< 2018-01-28 11:35:01.222 257 "/" is current directory.
. 2018-01-28 11:35:01.222 Changing directory to "/".
> 2018-01-28 11:35:01.222 CWD /
< 2018-01-28 11:35:01.253 250 CWD command successful.
. 2018-01-28 11:35:01.253 Getting current directory name.
> 2018-01-28 11:35:01.253 PWD
< 2018-01-28 11:35:01.285 257 "/" is current directory.
. 2018-01-28 11:35:01.285 Startup conversation with host finished.
< 2018-01-28 11:35:01.285 Script: Session started.
. 2018-01-28 11:35:01.285 File: 'C:\backups\2018-01-22-0200.zip' [2018-01-22T02:03:20.265Z] [90381212]
. 2018-01-28 11:35:01.285 Copying "C:\backups\2018-01-22-0200.zip" to remote directory started.
. 2018-01-28 11:35:01.285 Binary transfer mode selected.
. 2018-01-28 11:35:01.285 Starting upload of C:\backups\2018-01-22-0200.zip
> 2018-01-28 11:35:01.285 CWD /primary/backups/mysql-dumps-ds/
< 2018-01-28 11:35:01.378 250 CWD command successful.
> 2018-01-28 11:35:01.378 PWD
< 2018-01-28 11:35:01.409 257 "/mount/backups" is current directory.
> 2018-01-28 11:35:01.409 TYPE A
< 2018-01-28 11:35:01.456 200 Type set to A.
> 2018-01-28 11:35:01.456 PASV
< 2018-01-28 11:35:01.488 227 Entering Passive Mode (217,155,46,234,253,218)
> 2018-01-28 11:35:01.488 MLSD
. 2018-01-28 11:35:16.160 Timeout detected. (data connection)
. 2018-01-28 11:35:16.160 Copying files to remote side failed.
. 2018-01-28 11:35:16.160 Connection was lost, asking what to do.
. 2018-01-28 11:35:16.160 Asking user:
. 2018-01-28 11:35:16.160 Lost connection. ("Timeout detected. (data connection)","Copying files to remote side failed.")
< 2018-01-28 11:35:16.160 Script: Lost connection.
< 2018-01-28 11:35:16.160 Script: Timeout detected. (data connection)
< 2018-01-28 11:35:16.160 Copying files to remote side failed.
The script ran perfectly for over a year however now fails with error: Timeout detected. (data connection)
There is no change to configuration at the destination as far as I know. I can connect and transfer files as normal with FileZilla.
Can anyone suggest what the issue might be? Log sample and scripts below.
pushfiles.bat
--------------
set year=%DATE:~6,4%
set day=%DATE:~0,2%
set mnt=%DATE:~3,2%
IF %day% LSS 10 SET day=0%day:~1,1%
IF %mnt% LSS 10 SET mnt=0%mnt:~1,1%
set backuptime=%year%-%mnt%-%day%
C:\backups\winscp.exe /console /script=script.txt /log="C:\backups\logs\%backuptime%.log"
EXIT
script.txt
-----------
open ftp://username:password@ftp.domain.com
option transfer binary
put -neweronly C:\backups\*.* /mount/backups/
close
exit
log
----
2018-01-28 11:35:00.378 Connecting to ftp.domain.com...
. 2018-01-28 11:35:00.456 Connected with ftp.domain.com. Waiting for welcome message...
< 2018-01-28 11:35:00.472 220 Your FTP server ready.
> 2018-01-28 11:35:00.472 USER username
< 2018-01-28 11:35:00.503 331 Password required for username.
> 2018-01-28 11:35:00.503 PASS ********
< 2018-01-28 11:35:01.003 230 User usernme logged in.
> 2018-01-28 11:35:01.003 SYST
< 2018-01-28 11:35:01.081 215 UNIX Type: L8
> 2018-01-28 11:35:01.081 FEAT
< 2018-01-28 11:35:01.113 211- Extensions supported:
< 2018-01-28 11:35:01.113 AUTH TLS
< 2018-01-28 11:35:01.113 PBSZ
< 2018-01-28 11:35:01.113 PROT
< 2018-01-28 11:35:01.113 SIZE
< 2018-01-28 11:35:01.113 MDTM
< 2018-01-28 11:35:01.128 MFMT
< 2018-01-28 11:35:01.128 REST STREAM
< 2018-01-28 11:35:01.128 UTF8
< 2018-01-28 11:35:01.128 MLST type*;modify*;size*;UNIX.mode*;UNIX.owner*;UNIX.group*;
< 2018-01-28 11:35:01.144 MLSD
< 2018-01-28 11:35:01.144 211 End.
> 2018-01-28 11:35:01.144 OPTS UTF8 ON
< 2018-01-28 11:35:01.191 200 OK, UTF-8 enabled
< 2018-01-28 11:35:01.191 Script: Connected
. 2018-01-28 11:35:01.191 Connected
. 2018-01-28 11:35:01.191 Doing startup conversation with host.
< 2018-01-28 11:35:01.191 Script: Starting the session...
> 2018-01-28 11:35:01.191 PWD
< 2018-01-28 11:35:01.222 257 "/" is current directory.
. 2018-01-28 11:35:01.222 Changing directory to "/".
> 2018-01-28 11:35:01.222 CWD /
< 2018-01-28 11:35:01.253 250 CWD command successful.
. 2018-01-28 11:35:01.253 Getting current directory name.
> 2018-01-28 11:35:01.253 PWD
< 2018-01-28 11:35:01.285 257 "/" is current directory.
. 2018-01-28 11:35:01.285 Startup conversation with host finished.
< 2018-01-28 11:35:01.285 Script: Session started.
. 2018-01-28 11:35:01.285 File: 'C:\backups\2018-01-22-0200.zip' [2018-01-22T02:03:20.265Z] [90381212]
. 2018-01-28 11:35:01.285 Copying "C:\backups\2018-01-22-0200.zip" to remote directory started.
. 2018-01-28 11:35:01.285 Binary transfer mode selected.
. 2018-01-28 11:35:01.285 Starting upload of C:\backups\2018-01-22-0200.zip
> 2018-01-28 11:35:01.285 CWD /primary/backups/mysql-dumps-ds/
< 2018-01-28 11:35:01.378 250 CWD command successful.
> 2018-01-28 11:35:01.378 PWD
< 2018-01-28 11:35:01.409 257 "/mount/backups" is current directory.
> 2018-01-28 11:35:01.409 TYPE A
< 2018-01-28 11:35:01.456 200 Type set to A.
> 2018-01-28 11:35:01.456 PASV
< 2018-01-28 11:35:01.488 227 Entering Passive Mode (217,155,46,234,253,218)
> 2018-01-28 11:35:01.488 MLSD
. 2018-01-28 11:35:16.160 Timeout detected. (data connection)
. 2018-01-28 11:35:16.160 Copying files to remote side failed.
. 2018-01-28 11:35:16.160 Connection was lost, asking what to do.
. 2018-01-28 11:35:16.160 Asking user:
. 2018-01-28 11:35:16.160 Lost connection. ("Timeout detected. (data connection)","Copying files to remote side failed.")
< 2018-01-28 11:35:16.160 Script: Lost connection.
< 2018-01-28 11:35:16.160 Script: Timeout detected. (data connection)
< 2018-01-28 11:35:16.160 Copying files to remote side failed.
Last edited by chris.dempsey on 2018-01-28 14:58; edited 1 time in total