I reviewed more log files and I discovered this was using IPSwitch before, then when it was moved to WinSCP, we started observing the reported behavior, but also have other scripts that are running WinSCP and do not have this issue.
Attached bellow is one log sample.
You mention I could have something to do with the server supporting MLST, how can I find out is this particular FTP server has this issue?
Starting LeadImport.wsf on 7/21/2014 12:00:02 PM
currentUser: aftprocess
Creating WinSCP Client
ftpClient.FtpToolPath: C:\Program Files\WinSCP\WinSCP.exe
ftpSourceFilePath: Inbound!Client:/pick/
ftpDestinationFilePath: local:
FilePathToDecrypt: C:\AFT\ClientFiles\Client\In\Filename.zip.pgp
Executing commands
commandLine: "C:\Program Files\WinSCP\WinSCP.exe" /console /log="C:\DOCUME~1\AFTPRO~1\LOCALS~1\Temp\radBA66A.tmp" /script="C:\DOCUME~1\AFTPRO~1\LOCALS~1\Temp\rad58B8C.tmp"
executing command
--- Start of Std Out ---
--- End of Std Out ---
command exit code: 0
--- Start of WinSCP Session Log ---
. 2014-07-21 12:00:03.327 --------------------------------------------------------------------------
. 2014-07-21 12:00:03.327 WinSCP Version 5.5.4 (Build 4433) (OS 5.2.3790 Service Pack 1 - Microsoft Windows Server 2003 R2)
. 2014-07-21 12:00:03.343 Configuration: C:\Program Files\WinSCP\WinSCP.ini
. 2014-07-21 12:00:03.343 Local account: TRITON\aftprocess
. 2014-07-21 12:00:03.343 Working directory: c:\CareNet_Apps\Scripts\LeadImport
. 2014-07-21 12:00:03.343 Process ID: 3180
. 2014-07-21 12:00:03.343 Command-line: "C:\Program Files\WinSCP\WinSCP.exe" /console /log="C:\DOCUME~1\AFTPRO~1\LOCALS~1\Temp\radBA66A.tmp" /script="C:\DOCUME~1\AFTPRO~1\LOCALS~1\Temp\rad58B8C.tmp"
. 2014-07-21 12:00:03.343 Time zone: Current: GMT-5, Standard: GMT-6 (Central Standard Time), DST: GMT-5 (Central Daylight Time), DST Start: 3/9/2014, DST End: 11/2/2014
. 2014-07-21 12:00:03.343 Login time: Monday, July 21, 2014 12:00:03 PM
. 2014-07-21 12:00:03.343 --------------------------------------------------------------------------
. 2014-07-21 12:00:03.343 Script: Retrospectively logging previous script records:
> 2014-07-21 12:00:03.343 Script: option batch abort
< 2014-07-21 12:00:03.343 Script: batch abort
> 2014-07-21 12:00:03.343 Script: option confirm off
< 2014-07-21 12:00:03.343 Script: confirm off
> 2014-07-21 12:00:03.343 Script: open Inbound!Client
. 2014-07-21 12:00:03.343 --------------------------------------------------------------------------
. 2014-07-21 12:00:03.343 Session name: Inbound!Client (Site)
. 2014-07-21 12:00:03.343 Host name: afts.Client.com (Port: 22)
. 2014-07-21 12:00:03.343 User name: Carenet01 (Password: Yes, Key file: No)
. 2014-07-21 12:00:03.343 Tunnel: No
. 2014-07-21 12:00:03.343 Transfer Protocol: SFTP (SCP)
. 2014-07-21 12:00:03.343 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2014-07-21 12:00:03.343 Proxy: none
. 2014-07-21 12:00:03.343 Send buffer: 262144
. 2014-07-21 12:00:03.343 SSH protocol version: 2; Compression: No
. 2014-07-21 12:00:03.343 Bypass authentication: No
. 2014-07-21 12:00:03.343 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2014-07-21 12:00:03.343 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2014-07-21 12:00:03.343 SSH Bugs: A,A,A,A,A,A,A,A,A,A
. 2014-07-21 12:00:03.343 Simple channel: Yes
. 2014-07-21 12:00:03.343 Return code variable: Autodetect; Lookup user groups: A
. 2014-07-21 12:00:03.343 Shell: default
. 2014-07-21 12:00:03.343 EOL: 0, UTF: 2
. 2014-07-21 12:00:03.343 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2014-07-21 12:00:03.343 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2014-07-21 12:00:03.343 SFTP Bugs: A,A
. 2014-07-21 12:00:03.343 SFTP Server: default
. 2014-07-21 12:00:03.343 Local directory: C:\AFT\ClientFiles\Client\In, Remote directory: /pick, Update: Yes, Cache: Yes
. 2014-07-21 12:00:03.343 Cache directory changes: Yes, Permanent: Yes
. 2014-07-21 12:00:03.343 DST mode: 1; Timezone offset: 0h 0m
. 2014-07-21 12:00:03.343 --------------------------------------------------------------------------
. 2014-07-21 12:00:03.343 Looking up host "afts.Client.com"
. 2014-07-21 12:00:03.499 Connecting to 198.245.32.76 port 22
. 2014-07-21 12:00:03.624 Server version: SSH-2.0-XXXXXX Client AFT
. 2014-07-21 12:00:03.624 Using SSH protocol version 2
. 2014-07-21 12:00:03.624 We claim version: SSH-2.0-WinSCP_release_5.5.4
. 2014-07-21 12:00:03.686 Doing Diffie-Hellman group exchange
. 2014-07-21 12:00:03.827 Doing Diffie-Hellman key exchange with hash SHA-1
. 2014-07-21 12:00:05.046 Verifying host key rsa2 0x11,0xc2023e8c8a99da23 0a318193bade21b8 40f641796eca8d8e 5495c08174125b18 afbea8da80f97d21 afb715774c72cfc1 6895f202f56037f8 1c929c0380faf54c 7f5818cda89f8341 edd23e8732210cfb 45b704a2aaa5f471 73ad4dea6c0e4f0c c9c0a546a073fa06 d3750860abee7246 ef56ab8f7b14713a 983236500dac8b71 0bf06a413bfcbbe9 8e5dbbbcf6a3b51c 8360da7193a0de44 9b30d34c80fdfd36 e1b00442ab99c2b9 e7a3999455d9837c ff37d433ebbcdb3c d2470b42e276b47a e0d03c8198fe4458 e153a41a97861634 e25f1fcbdf6b4e44 f4342e5ee384b222 074c2383b0d49604 59d448ecae823696 c0eabd86385d6743 aa6356163724a8f7 with fingerprint ssh-rsa 2048 59:80:dc:36:bd:a1:02:cb:ac:3c:35:21:5f:cd:d3:ce
. 2014-07-21 12:00:05.046 Host key matches cached key
. 2014-07-21 12:00:05.046 Host key fingerprint is:
. 2014-07-21 12:00:05.046 ssh-rsa 2048 59:80:dc:36:bd:a1:02:cb:ac:3c:35:21:5f:cd:d3:ce
. 2014-07-21 12:00:05.046 Initialised AES-256 CBC client->server encryption
. 2014-07-21 12:00:05.046 Initialised HMAC-SHA1 client->server MAC algorithm
. 2014-07-21 12:00:05.046 Initialised AES-256 CBC server->client encryption
. 2014-07-21 12:00:05.046 Initialised HMAC-SHA1 server->client MAC algorithm
! 2014-07-21 12:00:05.218 Using username "username".
. 2014-07-21 12:00:05.296 Attempting keyboard-interactive authentication
. 2014-07-21 12:00:05.343 Prompt (6, SSH server authentication, Using keyboard-interactive authentication., Enter password: )
. 2014-07-21 12:00:05.343 Using stored password.
. 2014-07-21 12:00:05.421 Access granted
. 2014-07-21 12:00:05.421 Opening session as main channel
. 2014-07-21 12:00:05.483 Opened main channel
. 2014-07-21 12:00:05.640 Started a shell/command
. 2014-07-21 12:00:05.640 --------------------------------------------------------------------------
. 2014-07-21 12:00:05.640 Using SFTP protocol.
. 2014-07-21 12:00:05.640 Doing startup conversation with host.
> 2014-07-21 12:00:05.640 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2014-07-21 12:00:05.702 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2014-07-21 12:00:05.702 SFTP version 3 negotiated.
. 2014-07-21 12:00:05.702 We believe the server has signed timestamps bug
. 2014-07-21 12:00:05.702 We will use UTF-8 strings when appropriate
. 2014-07-21 12:00:05.702 Changing directory to "/pick".
. 2014-07-21 12:00:05.702 Getting real path for '/pick'
> 2014-07-21 12:00:05.702 Type: SSH_FXP_REALPATH, Size: 14, Number: 16
< 2014-07-21 12:00:05.765 Type: SSH_FXP_NAME, Size: 31, Number: 16
. 2014-07-21 12:00:05.765 Real path is '/pick'
. 2014-07-21 12:00:05.765 Trying to open directory "/pick".
> 2014-07-21 12:00:05.765 Type: SSH_FXP_LSTAT, Size: 14, Number: 263
< 2014-07-21 12:00:05.827 Type: SSH_FXP_ATTRS, Size: 21, Number: 263
. 2014-07-21 12:00:05.827 Getting current directory name.
. 2014-07-21 12:00:05.827 Startup conversation with host finished.
< 2014-07-21 12:00:05.827 Script: Active session: [1] Inbound!Client
> 2014-07-21 12:00:05.827 Script: get "/pick/Filename.zip.pgp" "C:\AFT\ClientFiles\Client\In\"
. 2014-07-21 12:00:05.827 Listing file "/pick/Filename.zip.pgp".
> 2014-07-21 12:00:05.827 Type: SSH_FXP_LSTAT, Size: 44, Number: 519
< 2014-07-21 12:00:05.905 Type: SSH_FXP_ATTRS, Size: 29, Number: 519
. 2014-07-21 12:00:05.905 Filename.zip.pgp;-;43270;2014-07-21T13:12:40.000Z;"" [0];"" [0];rw-rw-rw-;1
. 2014-07-21 12:00:05.921 File: '/pick/Filename.zip.pgp' [2014-07-21T13:12:40.000Z] [43270]
. 2014-07-21 12:00:05.921 Copying "/pick/Filename.zip.pgp" to local directory started.
. 2014-07-21 12:00:05.921 Binary transfer mode selected.
. 2014-07-21 12:00:05.921 Opening remote file.
> 2014-07-21 12:00:05.921 Type: SSH_FXP_OPEN, Size: 52, Number: 771
< 2014-07-21 12:00:05.983 Type: SSH_FXP_HANDLE, Size: 10, Number: 771
> 2014-07-21 12:00:05.983 Type: SSH_FXP_FSTAT, Size: 10, Number: 1032
< 2014-07-21 12:00:06.046 Type: SSH_FXP_ATTRS, Size: 29, Number: 1032
. 2014-07-21 12:00:06.046 Confirming overwriting of file.
> 2014-07-21 12:00:06.046 Type: SSH_FXP_READ, Size: 22, Number: 1285
< 2014-07-21 12:00:06.374 Status code: 1
. 2014-07-21 12:00:06.374 18 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2014-07-21 12:00:06.374 Type: SSH_FXP_CLOSE, Size: 10, Number: 4100
< 2014-07-21 12:00:06.421 Type: SSH_FXP_STATUS, Size: 22, Number: 3333
< 2014-07-21 12:00:06.421 Type: SSH_FXP_STATUS, Size: 22, Number: 3589
< 2014-07-21 12:00:06.515 Type: SSH_FXP_STATUS, Size: 22, Number: 3845
> 2014-07-21 12:00:06.561 Script: exit
. 2014-07-21 12:00:06.561 Script: Exit code: 0
. 2014-07-21 12:00:06.561 Closing connection.
. 2014-07-21 12:00:06.561 Sending special code: 12
. 2014-07-21 12:00:06.561 Sent EOF message
--- End of WS WinSCP Session Log ---