uploading problem with script
I set up a scheduled job using script to upload a file to a FTPS server. Most of the time it works fine, but once a while the uploading process hangs. After I explicitly add certificate fingerprint as the parameter (/certificate="xx:xx:...."), the problem still exists. I am not sure if it is caused by client side or server side. The following is the WinSCP log. How do I debug this problem? Thanks for your help!
. 2012-03-11 10:12:44.441 --------------------------------------------------------------------------
. 2012-03-11 10:12:44.441 WinSCP Version 4.3.2 (Build 1201) (OS 5.2.3790 Service Pack 2)
. 2012-03-11 10:12:44.441 Login time: Tuesday, March 11, 2012 10:12:44 AM
. 2012-03-11 10:12:44.441 --------------------------------------------------------------------------
. 2012-03-11 10:12:44.441 Session name: TestSession@11.22.33.44
. 2012-03-11 10:12:44.441 Host name: 11.22.33.44 (Port: 990)
. 2012-03-11 10:12:44.441 User name: TestUser (Password: Yes, Key file: No)
. 2012-03-11 10:12:44.441 Tunnel: No
. 2012-03-11 10:12:44.441 Transfer Protocol: FTP
. 2012-03-11 10:12:44.441 Ping type: C, Ping interval: 30 sec; Timeout: 15 sec
. 2012-03-11 10:12:44.441 Proxy: none
. 2012-03-11 10:12:44.441 FTP: FTPS: Implicit SSL/TLS; Passive: Yes [Force IP: Yes]
. 2012-03-11 10:12:44.441 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2012-03-11 10:12:44.441 Cache directory changes: Yes, Permanent: Yes
. 2012-03-11 10:12:44.441 DST mode: 1
. 2012-03-11 10:12:44.441 --------------------------------------------------------------------------
. 2012-03-11 10:12:44.628 Connecting to 11.22.33.44:990 ...
. 2012-03-11 10:12:44.691 Connected with 11.22.33.44:990, negotiating SSL connection...
. 2012-03-11 10:12:44.894 SSL connection established. Waiting for welcome message...
< 2012-03-11 10:12:45.128 220 Serv-U FTP Server v10.5 ready...
> 2012-03-11 10:12:45.128 USER TestUser
< 2012-03-11 10:12:45.206 331 User name okay, need password.
> 2012-03-11 10:12:45.206 PASS *********
< 2012-03-11 10:12:45.269 230 User logged in, proceed.
> 2012-03-11 10:12:45.269 SYST
< 2012-03-11 10:12:45.331 215 UNIX Type: L8
> 2012-03-11 10:12:45.331 FEAT
< 2012-03-11 10:12:45.394 211-Extensions supported
< 2012-03-11 10:12:45.394 UTF8
< 2012-03-11 10:12:45.394 OPTS MODE;MLST;UTF8
< 2012-03-11 10:12:45.394 CLNT
< 2012-03-11 10:12:45.394 CSID Name; Version;
< 2012-03-11 10:12:45.394 HOST domain
< 2012-03-11 10:12:45.394 SITE PSWD;SET;ZONE;CHMOD;MSG;EXEC;HELP
< 2012-03-11 10:12:45.394 AUTH TLS;SSL;TLS-C;TLS-P;
< 2012-03-11 10:12:45.394 PBSZ
< 2012-03-11 10:12:45.394 PROT
< 2012-03-11 10:12:45.394 CCC
< 2012-03-11 10:12:45.394 SSCN
< 2012-03-11 10:12:45.394 RMDA directoryname
< 2012-03-11 10:12:45.394 DSIZ
< 2012-03-11 10:12:45.394 AVBL
< 2012-03-11 10:12:45.394 EPRT
< 2012-03-11 10:12:45.394 EPSV
< 2012-03-11 10:12:45.394 MODE Z
< 2012-03-11 10:12:45.394 THMB BMP|JPEG|GIF|TIFF|PNG max_width max_height pathname
< 2012-03-11 10:12:45.394 REST STREAM
< 2012-03-11 10:12:45.394 SIZE
< 2012-03-11 10:12:45.394 MDTM
< 2012-03-11 10:12:45.394 MDTM YYYYMMDDHHMMSS[+-TZ];filename
< 2012-03-11 10:12:45.394 MFMT
< 2012-03-11 10:12:45.394 MFCT
< 2012-03-11 10:12:45.394 MFF Create;Modify;
< 2012-03-11 10:12:45.394 XCRC filename;start;end
< 2012-03-11 10:12:45.394 MLST Type*;Size*;Create;Modify*;Perm;Win32.ea;Win32.dt;Win32.dl
< 2012-03-11 10:12:45.394 211 End (for details use "HELP commmand" where command is the command of interest)
> 2012-03-11 10:12:45.394 CLNT FileZilla
< 2012-03-11 10:12:45.440 200 Noted.
> 2012-03-11 10:12:45.440 OPTS UTF8 ON
< 2012-03-11 10:12:45.503 200 OPTS UTF8 is set to ON.
> 2012-03-11 10:12:45.503 PBSZ 0
< 2012-03-11 10:12:45.565 200 PBSZ command OK. Protection buffer size set to 0.
> 2012-03-11 10:12:45.565 PROT P
< 2012-03-11 10:12:45.612 200 PROT command OK. Using private data connection.
. 2012-03-11 10:12:45.612 Connected
. 2012-03-11 10:12:45.612 --------------------------------------------------------------------------
. 2012-03-11 10:12:45.612 Using FTP protocol.
. 2012-03-11 10:12:45.612 Doing startup conversation with host.
> 2012-03-11 10:12:45.628 PWD
< 2012-03-11 10:12:45.675 257 "/" is current directory.
. 2012-03-11 10:12:45.675 Getting current directory name.
. 2012-03-11 10:12:45.675 Startup conversation with host finished.
< 2012-03-11 10:12:45.675 Script: Active session: [1] TestUser@11.22.33.44
> 2012-03-11 10:12:45.675 Script: option confirm off
< 2012-03-11 10:12:45.675 Script: confirm off
> 2012-03-11 10:12:45.675 Script: pwd
< 2012-03-11 10:12:45.675 Script: /
> 2012-03-11 10:12:45.675 Script: ascii
< 2012-03-11 10:12:45.675 Script: transfer ascii
> 2012-03-11 10:12:45.690 Script: put testfile.txt
. 2012-03-11 10:12:45.690 Copying 1 files/directories to remote directory "/"
. 2012-03-11 10:12:45.690 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 01; Resume: S (102400); CalcS: No; Mask:
. 2012-03-11 10:12:45.690 TM: A; ClAr: No; CPS: 0; ExclM(No):
. 2012-03-11 10:12:45.690 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2012-03-11 10:12:45.690 File: "testfile.txt"
. 2012-03-11 10:12:45.690 Copying "testfile.txt" to remote directory started.
. 2012-03-11 10:12:45.690 Ascii transfer mode selected.
. 2012-03-11 10:12:45.690 Starting upload of testfile.txt
> 2012-03-11 10:12:45.690 TYPE A
< 2012-03-11 10:12:45.753 200 Type set to A.
> 2012-03-11 10:12:45.753 PASV
< 2012-03-11 10:12:45.815 227 Entering Passive Mode (10,11,10,44,7,208)
. 2012-03-11 10:12:45.815 Using host address 11.22.33.44 instead of the one suggested by the server: 10.11.10.44
> 2012-03-11 10:12:45.815 LIST
< 2012-03-11 10:12:45.878 150 Opening ASCII mode data connection for /bin/ls.
< 2012-03-11 10:17:45.851 451 Operation aborted due to ABOR command.
. 2012-03-11 10:17:45.851 Copying files to remote side failed.
* 2012-03-11 10:17:45.851 (ExtException) Using host address 11.22.33.44 instead of the one suggested by the server: 10.11.10.44
* 2012-03-11 10:17:45.851 Copying files to remote side failed.
* 2012-03-11 10:17:45.851 Operation aborted due to ABOR command.
. 2012-03-11 10:17:45.851 Asking user:
. 2012-03-11 10:17:45.851 Error transferring file 'testfile.txt'. ("Using host address 11.22.33.44 instead of the one suggested by the server: 10.11.10.44","Copying files to remote side failed.","Operation aborted due to ABOR command.")
I also got the log from the server side - FTP SSL data socket timed out during SSL shutdown sequence. The FTPS client did not complete SSL shutdown, please contact client manufacturer.
. 2012-03-11 10:12:44.441 --------------------------------------------------------------------------
. 2012-03-11 10:12:44.441 WinSCP Version 4.3.2 (Build 1201) (OS 5.2.3790 Service Pack 2)
. 2012-03-11 10:12:44.441 Login time: Tuesday, March 11, 2012 10:12:44 AM
. 2012-03-11 10:12:44.441 --------------------------------------------------------------------------
. 2012-03-11 10:12:44.441 Session name: TestSession@11.22.33.44
. 2012-03-11 10:12:44.441 Host name: 11.22.33.44 (Port: 990)
. 2012-03-11 10:12:44.441 User name: TestUser (Password: Yes, Key file: No)
. 2012-03-11 10:12:44.441 Tunnel: No
. 2012-03-11 10:12:44.441 Transfer Protocol: FTP
. 2012-03-11 10:12:44.441 Ping type: C, Ping interval: 30 sec; Timeout: 15 sec
. 2012-03-11 10:12:44.441 Proxy: none
. 2012-03-11 10:12:44.441 FTP: FTPS: Implicit SSL/TLS; Passive: Yes [Force IP: Yes]
. 2012-03-11 10:12:44.441 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2012-03-11 10:12:44.441 Cache directory changes: Yes, Permanent: Yes
. 2012-03-11 10:12:44.441 DST mode: 1
. 2012-03-11 10:12:44.441 --------------------------------------------------------------------------
. 2012-03-11 10:12:44.628 Connecting to 11.22.33.44:990 ...
. 2012-03-11 10:12:44.691 Connected with 11.22.33.44:990, negotiating SSL connection...
. 2012-03-11 10:12:44.894 SSL connection established. Waiting for welcome message...
< 2012-03-11 10:12:45.128 220 Serv-U FTP Server v10.5 ready...
> 2012-03-11 10:12:45.128 USER TestUser
< 2012-03-11 10:12:45.206 331 User name okay, need password.
> 2012-03-11 10:12:45.206 PASS *********
< 2012-03-11 10:12:45.269 230 User logged in, proceed.
> 2012-03-11 10:12:45.269 SYST
< 2012-03-11 10:12:45.331 215 UNIX Type: L8
> 2012-03-11 10:12:45.331 FEAT
< 2012-03-11 10:12:45.394 211-Extensions supported
< 2012-03-11 10:12:45.394 UTF8
< 2012-03-11 10:12:45.394 OPTS MODE;MLST;UTF8
< 2012-03-11 10:12:45.394 CLNT
< 2012-03-11 10:12:45.394 CSID Name; Version;
< 2012-03-11 10:12:45.394 HOST domain
< 2012-03-11 10:12:45.394 SITE PSWD;SET;ZONE;CHMOD;MSG;EXEC;HELP
< 2012-03-11 10:12:45.394 AUTH TLS;SSL;TLS-C;TLS-P;
< 2012-03-11 10:12:45.394 PBSZ
< 2012-03-11 10:12:45.394 PROT
< 2012-03-11 10:12:45.394 CCC
< 2012-03-11 10:12:45.394 SSCN
< 2012-03-11 10:12:45.394 RMDA directoryname
< 2012-03-11 10:12:45.394 DSIZ
< 2012-03-11 10:12:45.394 AVBL
< 2012-03-11 10:12:45.394 EPRT
< 2012-03-11 10:12:45.394 EPSV
< 2012-03-11 10:12:45.394 MODE Z
< 2012-03-11 10:12:45.394 THMB BMP|JPEG|GIF|TIFF|PNG max_width max_height pathname
< 2012-03-11 10:12:45.394 REST STREAM
< 2012-03-11 10:12:45.394 SIZE
< 2012-03-11 10:12:45.394 MDTM
< 2012-03-11 10:12:45.394 MDTM YYYYMMDDHHMMSS[+-TZ];filename
< 2012-03-11 10:12:45.394 MFMT
< 2012-03-11 10:12:45.394 MFCT
< 2012-03-11 10:12:45.394 MFF Create;Modify;
< 2012-03-11 10:12:45.394 XCRC filename;start;end
< 2012-03-11 10:12:45.394 MLST Type*;Size*;Create;Modify*;Perm;Win32.ea;Win32.dt;Win32.dl
< 2012-03-11 10:12:45.394 211 End (for details use "HELP commmand" where command is the command of interest)
> 2012-03-11 10:12:45.394 CLNT FileZilla
< 2012-03-11 10:12:45.440 200 Noted.
> 2012-03-11 10:12:45.440 OPTS UTF8 ON
< 2012-03-11 10:12:45.503 200 OPTS UTF8 is set to ON.
> 2012-03-11 10:12:45.503 PBSZ 0
< 2012-03-11 10:12:45.565 200 PBSZ command OK. Protection buffer size set to 0.
> 2012-03-11 10:12:45.565 PROT P
< 2012-03-11 10:12:45.612 200 PROT command OK. Using private data connection.
. 2012-03-11 10:12:45.612 Connected
. 2012-03-11 10:12:45.612 --------------------------------------------------------------------------
. 2012-03-11 10:12:45.612 Using FTP protocol.
. 2012-03-11 10:12:45.612 Doing startup conversation with host.
> 2012-03-11 10:12:45.628 PWD
< 2012-03-11 10:12:45.675 257 "/" is current directory.
. 2012-03-11 10:12:45.675 Getting current directory name.
. 2012-03-11 10:12:45.675 Startup conversation with host finished.
< 2012-03-11 10:12:45.675 Script: Active session: [1] TestUser@11.22.33.44
> 2012-03-11 10:12:45.675 Script: option confirm off
< 2012-03-11 10:12:45.675 Script: confirm off
> 2012-03-11 10:12:45.675 Script: pwd
< 2012-03-11 10:12:45.675 Script: /
> 2012-03-11 10:12:45.675 Script: ascii
< 2012-03-11 10:12:45.675 Script: transfer ascii
> 2012-03-11 10:12:45.690 Script: put testfile.txt
. 2012-03-11 10:12:45.690 Copying 1 files/directories to remote directory "/"
. 2012-03-11 10:12:45.690 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 01; Resume: S (102400); CalcS: No; Mask:
. 2012-03-11 10:12:45.690 TM: A; ClAr: No; CPS: 0; ExclM(No):
. 2012-03-11 10:12:45.690 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2012-03-11 10:12:45.690 File: "testfile.txt"
. 2012-03-11 10:12:45.690 Copying "testfile.txt" to remote directory started.
. 2012-03-11 10:12:45.690 Ascii transfer mode selected.
. 2012-03-11 10:12:45.690 Starting upload of testfile.txt
> 2012-03-11 10:12:45.690 TYPE A
< 2012-03-11 10:12:45.753 200 Type set to A.
> 2012-03-11 10:12:45.753 PASV
< 2012-03-11 10:12:45.815 227 Entering Passive Mode (10,11,10,44,7,208)
. 2012-03-11 10:12:45.815 Using host address 11.22.33.44 instead of the one suggested by the server: 10.11.10.44
> 2012-03-11 10:12:45.815 LIST
< 2012-03-11 10:12:45.878 150 Opening ASCII mode data connection for /bin/ls.
< 2012-03-11 10:17:45.851 451 Operation aborted due to ABOR command.
. 2012-03-11 10:17:45.851 Copying files to remote side failed.
* 2012-03-11 10:17:45.851 (ExtException) Using host address 11.22.33.44 instead of the one suggested by the server: 10.11.10.44
* 2012-03-11 10:17:45.851 Copying files to remote side failed.
* 2012-03-11 10:17:45.851 Operation aborted due to ABOR command.
. 2012-03-11 10:17:45.851 Asking user:
. 2012-03-11 10:17:45.851 Error transferring file 'testfile.txt'. ("Using host address 11.22.33.44 instead of the one suggested by the server: 10.11.10.44","Copying files to remote side failed.","Operation aborted due to ABOR command.")
I also got the log from the server side - FTP SSL data socket timed out during SSL shutdown sequence. The FTPS client did not complete SSL shutdown, please contact client manufacturer.
