SFTP Failures
We are currently having an SFTP issue. Our one ETL job uses winscp to secure ftp (sftp) get a file from a remote vendor. This job has been running every day for a couple of years. Recently (the last month or so) the ftp step has started to fail. It used to be a time or two a week, but in the last 2 weeks it has been every day. The log files always say the same thing… it connects, appears to find the remote file and start the copy, then fails to open the local file (which should be a new file). Then it must try again and appears that it can't find both local and remote files at that point. The strange thing is that if you rerun the job, the job runs fine. We've even gone to the extent of putting in a loop that if it fails on the first attempt, it will wait for 15 minutes and then try again. But still, the first time the job runs (which tries to ftp twice, 15 minutes apart), it fails. Then if you rerun the job, it will work (usually on the first try, but sometimes it works on the second). We've changed the time that the job runs, but that doesn't seem to help. There is another job that gets a much smaller file from the same location, that runs about 30 minutes before this job, that works fine, the first time, all the time. The file we are trying to get is large, ~ 84 Mb, so I don't know if that has anything to do with it or not. Our job also does a SFTP directory (ls) command before it does the ftp get step, to be sure the file is there before we go get it. This step always works, so it's not a problem with being able to communicate with the remote site. We are on version4.2.1 (Build 428). I've listed the commands and then the log file that is generated below. Any help would be greatly appreciated as our job runs daily. Thanks. :D
######################################################################
# Automatically answer all prompts negatively not to stall
# the script on errors
######################################################################
#
option batch on
#
######################################################################
# Disable overwrite confirmations that conflict with the previous
######################################################################
#
option confirm off
#
######################################################################
# Connect to remote server defined in the winscp GUI.
######################################################################
#
open "user@sftp.sitename.com"
#
######################################################################
# Set the transfer type as ascii, binary, or auto.
######################################################################
#
option transfer "Auto"
#
######################################################################
# Change the local directory
######################################################################
#
lcd "E:\DS\PROD\Data\Jobs\P_11776_ApplicantFileFromPosMgr2Lawson"
#
######################################################################
# Change the remote directory.
# Note: Use CD with nothing to change to the home directory.
######################################################################
#
cd "/users/name"
#
######################################################################
# Get a file from the remote server.
# Note: Use the -nopreservetime to cause timestamp on the local file
# Note: to be the time the get command was executed.
# Note: The name must match case.
######################################################################
#
get -nopreservetime "japplicanttable.txt" "E:\DS\PROD\Data\Jobs\P_11776_ApplicantFileFromPosMgr2Lawson\japplicanttable.txt.2011-12-15_07-03-46-46_8838"
#
######################################################################
# Disconnect from the remote server
######################################################################
#
close
#
######################################################################
# Exit WinSCP
######################################################################
#
exit
Log File:
. 2011-12-15 07:03:46.772 --------------------------------------------------------------------------
. 2011-12-15 07:03:46.772 WinSCP Version 4.2.1 (Build 428) (OS 5.2.3790 Service Pack 2)
. 2011-12-15 07:03:46.772 Login time: Thursday, December 15, 2011 7:03:46 AM
. 2011-12-15 07:03:46.772 --------------------------------------------------------------------------
. 2011-12-15 07:03:46.772 Session name: user@sftp.sitename.com
. 2011-12-15 07:03:46.772 Host name: sftp.healthcaresource.com (Port: 22)
. 2011-12-15 07:03:46.772 User name: user (Password: Yes, Key file: No)
. 2011-12-15 07:03:46.772 Tunnel: No
. 2011-12-15 07:03:46.772 Transfer Protocol: SFTP
. 2011-12-15 07:03:46.772 Ping type: -, Ping interval: 30 sec; Timeout: 120 sec
. 2011-12-15 07:03:46.772 Proxy: none
. 2011-12-15 07:03:46.772 SSH protocol version: 2; Compression: No
. 2011-12-15 07:03:46.772 Bypass authentication: No
. 2011-12-15 07:03:46.772 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2011-12-15 07:03:46.772 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2011-12-15 07:03:46.772 SSH Bugs: -,-,-,-,-,-,-,-,-
. 2011-12-15 07:03:46.772 SFTP Bugs: -,-
. 2011-12-15 07:03:46.772 Return code variable: Autodetect; Lookup user groups: Yes
. 2011-12-15 07:03:46.772 Shell: default, EOL: 0
. 2011-12-15 07:03:46.772 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: No
. 2011-12-15 07:03:46.772 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2011-12-15 07:03:46.772 Local directory: default, Remote directory: home, Update: No, Cache: No
. 2011-12-15 07:03:46.772 Cache directory changes: No, Permanent: Yes
. 2011-12-15 07:03:46.772 DST mode: 1
. 2011-12-15 07:03:46.772 --------------------------------------------------------------------------
. 2011-12-15 07:03:46.772 Looking up host "sftp.sitename.com"
. 2011-12-15 07:03:46.772 Connecting to 99.999.999.99 port 22
. 2011-12-15 07:03:46.803 Server version: SSH-2.0-WS_FTP-SSH_6.1.1
. 2011-12-15 07:03:46.803 Using SSH protocol version 2
. 2011-12-15 07:03:46.803 We claim version: SSH-2.0-WinSCP_release_4.2.1
. 2011-12-15 07:03:46.819 Using Diffie-Hellman with standard group "group14"
. 2011-12-15 07:03:46.819 Doing Diffie-Hellman key exchange with hash SHA-1
. 2011-12-15 07:03:47.131 Host key fingerprint is:
. 2011-12-15 07:03:47.131 ssh-rsa 1024 44:cc:3d:4d:c8:b8:b2:93:a0:4f:19:2c:2b:df:28:92
. 2011-12-15 07:03:47.131 Initialised AES-256 CBC client->server encryption
. 2011-12-15 07:03:47.131 Initialised HMAC-SHA1 client->server MAC algorithm
. 2011-12-15 07:03:47.147 Initialised AES-256 CBC server->client encryption
. 2011-12-15 07:03:47.147 Initialised HMAC-SHA1 server->client MAC algorithm
! 2011-12-15 07:03:47.163 Using username "user".
. 2011-12-15 07:03:47.350 Prompt (6, SSH password, , &Password: )
. 2011-12-15 07:03:47.350 Using stored password.
. 2011-12-15 07:03:47.350 Sent password
. 2011-12-15 07:03:47.381 Access granted
. 2011-12-15 07:03:47.397 Opened channel for session
. 2011-12-15 07:03:47.584 Started a shell/command
. 2011-12-15 07:03:47.584 --------------------------------------------------------------------------
. 2011-12-15 07:03:47.584 Using SFTP protocol.
. 2011-12-15 07:03:47.584 Doing startup conversation with host.
> 2011-12-15 07:03:47.584 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2011-12-15 07:03:47.600 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2011-12-15 07:03:47.600 SFTP version 4 negotiated.
. 2011-12-15 07:03:47.600 We will use UTF-8 strings when appropriate
. 2011-12-15 07:03:47.600 Getting current directory name.
. 2011-12-15 07:03:47.600 Getting real path for '.'
> 2011-12-15 07:03:47.600 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2011-12-15 07:03:47.678 Type: SSH_FXP_NAME, Size: 36, Number: 16
. 2011-12-15 07:03:47.678 Real path is '/users/name'
. 2011-12-15 07:03:47.678 Startup conversation with host finished.
. 2011-12-15 07:03:47.678 Changing directory to "/users/name".
. 2011-12-15 07:03:47.678 Getting real path for '/users/name'
> 2011-12-15 07:03:47.678 Type: SSH_FXP_REALPATH, Size: 23, Number: 272
< 2011-12-15 07:03:47.709 Type: SSH_FXP_NAME, Size: 36, Number: 272
. 2011-12-15 07:03:47.709 Real path is '/users/name'
. 2011-12-15 07:03:47.709 Trying to open directory "/users/name".
> 2011-12-15 07:03:47.709 Type: SSH_FXP_LSTAT, Size: 27, Number: 519
< 2011-12-15 07:03:47.756 Type: SSH_FXP_ATTRS, Size: 38, Number: 519
. 2011-12-15 07:03:47.756 Getting current directory name.
. 2011-12-15 07:03:47.756 Listing file "japplicanttable.txt".
> 2011-12-15 07:03:47.756 Type: SSH_FXP_LSTAT, Size: 47, Number: 775
< 2011-12-15 07:03:47.788 Type: SSH_FXP_ATTRS, Size: 46, Number: 775
. 2011-12-15 07:03:47.788 File: "/users/name/japplicanttable.txt"
. 2011-12-15 07:03:47.788 Copying "/users/name/japplicanttable.txt" to local directory started.
. 2011-12-15 07:03:47.788 Ascii transfer mode selected.
. 2011-12-15 07:03:47.788 Opening remote file.
> 2011-12-15 07:03:47.788 Type: SSH_FXP_OPEN, Size: 52, Number: 1027
< 2011-12-15 07:03:48.803 Type: SSH_FXP_STATUS, Size: 42, Number: 1027
< 2011-12-15 07:03:48.803 Status/error code: 4, Message: 1027, Server: Failed to open local file, Language:
* 2011-12-15 07:03:48.803 (ETerminal) General failure (server should provide error description).
* 2011-12-15 07:03:48.803 Error code: 4
* 2011-12-15 07:03:48.803 Error message from server: Failed to open local file
* 2011-12-15 07:03:48.803 Request code: 3
. 2011-12-15 07:03:48.803 Asking user:
. 2011-12-15 07:03:48.803 Cannot open remote file '/users/name/japplicanttable.txt'. ("General failure (server should provide error description).
. 2011-12-15 07:03:48.803 Error code: 4
. 2011-12-15 07:03:48.803 Error message from server: Failed to open local file
. 2011-12-15 07:03:48.803 Request code: 3")
* 2011-12-15 07:03:48.819 (EScpSkipFile) Cannot open remote file '/users/name/japplicanttable.txt'.
* 2011-12-15 07:03:48.819 General failure (server should provide error description).
* 2011-12-15 07:03:48.819 Error code: 4
* 2011-12-15 07:03:48.819 Error message from server: Failed to open local file
* 2011-12-15 07:03:48.819 Request code: 3
. 2011-12-15 07:03:48.819 Closing connection.
. 2011-12-15 07:03:48.819 Sending special code: 12
. 2011-12-15 07:03:48.819 Sent EOF message
######################################################################
# Automatically answer all prompts negatively not to stall
# the script on errors
######################################################################
#
option batch on
#
######################################################################
# Disable overwrite confirmations that conflict with the previous
######################################################################
#
option confirm off
#
######################################################################
# Connect to remote server defined in the winscp GUI.
######################################################################
#
open "user@sftp.sitename.com"
#
######################################################################
# Set the transfer type as ascii, binary, or auto.
######################################################################
#
option transfer "Auto"
#
######################################################################
# Change the local directory
######################################################################
#
lcd "E:\DS\PROD\Data\Jobs\P_11776_ApplicantFileFromPosMgr2Lawson"
#
######################################################################
# Change the remote directory.
# Note: Use CD with nothing to change to the home directory.
######################################################################
#
cd "/users/name"
#
######################################################################
# Get a file from the remote server.
# Note: Use the -nopreservetime to cause timestamp on the local file
# Note: to be the time the get command was executed.
# Note: The name must match case.
######################################################################
#
get -nopreservetime "japplicanttable.txt" "E:\DS\PROD\Data\Jobs\P_11776_ApplicantFileFromPosMgr2Lawson\japplicanttable.txt.2011-12-15_07-03-46-46_8838"
#
######################################################################
# Disconnect from the remote server
######################################################################
#
close
#
######################################################################
# Exit WinSCP
######################################################################
#
exit
Log File:
. 2011-12-15 07:03:46.772 --------------------------------------------------------------------------
. 2011-12-15 07:03:46.772 WinSCP Version 4.2.1 (Build 428) (OS 5.2.3790 Service Pack 2)
. 2011-12-15 07:03:46.772 Login time: Thursday, December 15, 2011 7:03:46 AM
. 2011-12-15 07:03:46.772 --------------------------------------------------------------------------
. 2011-12-15 07:03:46.772 Session name: user@sftp.sitename.com
. 2011-12-15 07:03:46.772 Host name: sftp.healthcaresource.com (Port: 22)
. 2011-12-15 07:03:46.772 User name: user (Password: Yes, Key file: No)
. 2011-12-15 07:03:46.772 Tunnel: No
. 2011-12-15 07:03:46.772 Transfer Protocol: SFTP
. 2011-12-15 07:03:46.772 Ping type: -, Ping interval: 30 sec; Timeout: 120 sec
. 2011-12-15 07:03:46.772 Proxy: none
. 2011-12-15 07:03:46.772 SSH protocol version: 2; Compression: No
. 2011-12-15 07:03:46.772 Bypass authentication: No
. 2011-12-15 07:03:46.772 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2011-12-15 07:03:46.772 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2011-12-15 07:03:46.772 SSH Bugs: -,-,-,-,-,-,-,-,-
. 2011-12-15 07:03:46.772 SFTP Bugs: -,-
. 2011-12-15 07:03:46.772 Return code variable: Autodetect; Lookup user groups: Yes
. 2011-12-15 07:03:46.772 Shell: default, EOL: 0
. 2011-12-15 07:03:46.772 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: No
. 2011-12-15 07:03:46.772 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2011-12-15 07:03:46.772 Local directory: default, Remote directory: home, Update: No, Cache: No
. 2011-12-15 07:03:46.772 Cache directory changes: No, Permanent: Yes
. 2011-12-15 07:03:46.772 DST mode: 1
. 2011-12-15 07:03:46.772 --------------------------------------------------------------------------
. 2011-12-15 07:03:46.772 Looking up host "sftp.sitename.com"
. 2011-12-15 07:03:46.772 Connecting to 99.999.999.99 port 22
. 2011-12-15 07:03:46.803 Server version: SSH-2.0-WS_FTP-SSH_6.1.1
. 2011-12-15 07:03:46.803 Using SSH protocol version 2
. 2011-12-15 07:03:46.803 We claim version: SSH-2.0-WinSCP_release_4.2.1
. 2011-12-15 07:03:46.819 Using Diffie-Hellman with standard group "group14"
. 2011-12-15 07:03:46.819 Doing Diffie-Hellman key exchange with hash SHA-1
. 2011-12-15 07:03:47.131 Host key fingerprint is:
. 2011-12-15 07:03:47.131 ssh-rsa 1024 44:cc:3d:4d:c8:b8:b2:93:a0:4f:19:2c:2b:df:28:92
. 2011-12-15 07:03:47.131 Initialised AES-256 CBC client->server encryption
. 2011-12-15 07:03:47.131 Initialised HMAC-SHA1 client->server MAC algorithm
. 2011-12-15 07:03:47.147 Initialised AES-256 CBC server->client encryption
. 2011-12-15 07:03:47.147 Initialised HMAC-SHA1 server->client MAC algorithm
! 2011-12-15 07:03:47.163 Using username "user".
. 2011-12-15 07:03:47.350 Prompt (6, SSH password, , &Password: )
. 2011-12-15 07:03:47.350 Using stored password.
. 2011-12-15 07:03:47.350 Sent password
. 2011-12-15 07:03:47.381 Access granted
. 2011-12-15 07:03:47.397 Opened channel for session
. 2011-12-15 07:03:47.584 Started a shell/command
. 2011-12-15 07:03:47.584 --------------------------------------------------------------------------
. 2011-12-15 07:03:47.584 Using SFTP protocol.
. 2011-12-15 07:03:47.584 Doing startup conversation with host.
> 2011-12-15 07:03:47.584 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2011-12-15 07:03:47.600 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2011-12-15 07:03:47.600 SFTP version 4 negotiated.
. 2011-12-15 07:03:47.600 We will use UTF-8 strings when appropriate
. 2011-12-15 07:03:47.600 Getting current directory name.
. 2011-12-15 07:03:47.600 Getting real path for '.'
> 2011-12-15 07:03:47.600 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2011-12-15 07:03:47.678 Type: SSH_FXP_NAME, Size: 36, Number: 16
. 2011-12-15 07:03:47.678 Real path is '/users/name'
. 2011-12-15 07:03:47.678 Startup conversation with host finished.
. 2011-12-15 07:03:47.678 Changing directory to "/users/name".
. 2011-12-15 07:03:47.678 Getting real path for '/users/name'
> 2011-12-15 07:03:47.678 Type: SSH_FXP_REALPATH, Size: 23, Number: 272
< 2011-12-15 07:03:47.709 Type: SSH_FXP_NAME, Size: 36, Number: 272
. 2011-12-15 07:03:47.709 Real path is '/users/name'
. 2011-12-15 07:03:47.709 Trying to open directory "/users/name".
> 2011-12-15 07:03:47.709 Type: SSH_FXP_LSTAT, Size: 27, Number: 519
< 2011-12-15 07:03:47.756 Type: SSH_FXP_ATTRS, Size: 38, Number: 519
. 2011-12-15 07:03:47.756 Getting current directory name.
. 2011-12-15 07:03:47.756 Listing file "japplicanttable.txt".
> 2011-12-15 07:03:47.756 Type: SSH_FXP_LSTAT, Size: 47, Number: 775
< 2011-12-15 07:03:47.788 Type: SSH_FXP_ATTRS, Size: 46, Number: 775
. 2011-12-15 07:03:47.788 File: "/users/name/japplicanttable.txt"
. 2011-12-15 07:03:47.788 Copying "/users/name/japplicanttable.txt" to local directory started.
. 2011-12-15 07:03:47.788 Ascii transfer mode selected.
. 2011-12-15 07:03:47.788 Opening remote file.
> 2011-12-15 07:03:47.788 Type: SSH_FXP_OPEN, Size: 52, Number: 1027
< 2011-12-15 07:03:48.803 Type: SSH_FXP_STATUS, Size: 42, Number: 1027
< 2011-12-15 07:03:48.803 Status/error code: 4, Message: 1027, Server: Failed to open local file, Language:
* 2011-12-15 07:03:48.803 (ETerminal) General failure (server should provide error description).
* 2011-12-15 07:03:48.803 Error code: 4
* 2011-12-15 07:03:48.803 Error message from server: Failed to open local file
* 2011-12-15 07:03:48.803 Request code: 3
. 2011-12-15 07:03:48.803 Asking user:
. 2011-12-15 07:03:48.803 Cannot open remote file '/users/name/japplicanttable.txt'. ("General failure (server should provide error description).
. 2011-12-15 07:03:48.803 Error code: 4
. 2011-12-15 07:03:48.803 Error message from server: Failed to open local file
. 2011-12-15 07:03:48.803 Request code: 3")
* 2011-12-15 07:03:48.819 (EScpSkipFile) Cannot open remote file '/users/name/japplicanttable.txt'.
* 2011-12-15 07:03:48.819 General failure (server should provide error description).
* 2011-12-15 07:03:48.819 Error code: 4
* 2011-12-15 07:03:48.819 Error message from server: Failed to open local file
* 2011-12-15 07:03:48.819 Request code: 3
. 2011-12-15 07:03:48.819 Closing connection.
. 2011-12-15 07:03:48.819 Sending special code: 12
. 2011-12-15 07:03:48.819 Sent EOF message
