STP issue with Script

I have a WinSCP script that is getting a directory listing from a remote site that is created by a C# application. This works fine when I use WinSCP with FTP, but when I use SFTP, I receive the an error code of 1 and the process fails. It appears that I am connected to the site, but for some reason the directory listing is not working. I am unfamiliar with the WinSCP logs and what they mean. Any insite into what we are doing wrong, would be greatly appreciated. Thank you for your help!

Here is the log:

. 2009-05-07 16:20:21.089 --------------------------------------------------------------------------
. 2009-05-07 16:20:21.089 WinSCP Version 4.1.6 (Build 412) (OS 5.2.3790 Service Pack 2)
. 2009-05-07 16:20:21.089 Login time: Thursday, May 07, 2009 4:20:21 PM
. 2009-05-07 16:20:21.089 --------------------------------------------------------------------------
. 2009-05-07 16:20:21.089 Session name: xxxxx
. 2009-05-07 16:20:21.089 Host name: xxx (Port: 22)
. 2009-05-07 16:20:21.089 User name: xxx (Password: Yes, Key file: No)
. 2009-05-07 16:20:21.089 Tunnel: No
. 2009-05-07 16:20:21.089 Transfer Protocol: SFTP
. 2009-05-07 16:20:21.089 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2009-05-07 16:20:21.104 Proxy: none
. 2009-05-07 16:20:21.104 SSH protocol version: 2; Compression: No
. 2009-05-07 16:20:21.104 Bypass authentication: No
. 2009-05-07 16:20:21.104 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2009-05-07 16:20:21.104 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2009-05-07 16:20:21.104 SSH Bugs: -,-,-,-,-,-,-,-
. 2009-05-07 16:20:21.104 SFTP Bugs: -,-
. 2009-05-07 16:20:21.104 Return code variable: Autodetect; Lookup user groups: Yes
. 2009-05-07 16:20:21.104 Shell: default, EOL: 0
. 2009-05-07 16:20:21.104 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2009-05-07 16:20:21.104 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2009-05-07 16:20:21.104 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2009-05-07 16:20:21.104 Cache directory changes: Yes, Permanent: Yes
. 2009-05-07 16:20:21.104 DST mode: 1
. 2009-05-07 16:20:21.104 --------------------------------------------------------------------------
. 2009-05-07 16:20:21.104 Looking up host "xxx"
. 2009-05-07 16:20:23.245 Connecting to 137.236.181.10 port 22
. 2009-05-07 16:20:23.339 Server version: SSH-2.0-OpenSSH_3.7.1p2 (with Xpedite proprietary back-end)
. 2009-05-07 16:20:23.339 We claim version: SSH-2.0-WinSCP_release_4.1.6
. 2009-05-07 16:20:23.354 SSPI: acquired credentials for: xxx
. 2009-05-07 16:20:23.354 Constructed service principal name 'host/xxx'
. 2009-05-07 16:20:23.354 GSSKEX disabled: The specified target is unknown or unreachable

. 2009-05-07 16:20:23.354 Using SSH protocol version 2
. 2009-05-07 16:20:23.385 Doing Diffie-Hellman group exchange
. 2009-05-07 16:20:23.589 Doing Diffie-Hellman key exchange with hash SHA-1
. 2009-05-07 16:20:23.682 Host key fingerprint is:
. 2009-05-07 16:20:23.682 ssh-rsa 1024 23:a6:04:df:25:69:b8:e6:4a:64:d6:ea:53:9e:de:d3
. 2009-05-07 16:20:23.682 Initialised AES-128 CBC client->server encryption
. 2009-05-07 16:20:23.682 Initialised HMAC-SHA1 client->server MAC algorithm
. 2009-05-07 16:20:23.682 Initialised AES-128 CBC server->client encryption
. 2009-05-07 16:20:23.682 Initialised HMAC-SHA1 server->client MAC algorithm
! 2009-05-07 16:20:23.885 Using username "xxx".
. 2009-05-07 16:20:23.979 Keyboard-interactive authentication refused
. 2009-05-07 16:20:23.979 Prompt (6, SSH password, , &Password: )
. 2009-05-07 16:20:23.979 Using stored password.
. 2009-05-07 16:20:23.979 Sent password
. 2009-05-07 16:20:24.073 Access granted
. 2009-05-07 16:20:24.120 Opened channel for session
. 2009-05-07 16:20:24.182 Started a shell/command
. 2009-05-07 16:20:24.182 --------------------------------------------------------------------------
. 2009-05-07 16:20:24.182 Using SFTP protocol.
. 2009-05-07 16:20:24.182 Doing startup conversation with host.
> 2009-05-07 16:20:24.182 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2009-05-07 16:20:24.339 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2009-05-07 16:20:24.339 SFTP version 3 negotiated.
. 2009-05-07 16:20:24.339 We believe the server has signed timestamps bug
. 2009-05-07 16:20:24.339 We will use UTF-8 strings for status messages only
. 2009-05-07 16:20:24.339 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2009-05-07 16:20:24.339 Getting current directory name.
. 2009-05-07 16:20:24.339 Getting real path for '.'
> 2009-05-07 16:20:24.339 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2009-05-07 16:20:24.385 Type: SSH_FXP_NAME, Size: 23, Number: 16
. 2009-05-07 16:20:24.385 Real path is '/'
. 2009-05-07 16:20:24.385 Startup conversation with host finished.
. 2009-05-07 16:20:24.385 Listing directory "/".
> 2009-05-07 16:20:24.385 Type: SSH_FXP_OPENDIR, Size: 10, Number: 267
< 2009-05-07 16:20:24.651 Type: SSH_FXP_HANDLE, Size: 13, Number: 267
> 2009-05-07 16:20:24.651 Type: SSH_FXP_READDIR, Size: 13, Number: 524
< 2009-05-07 16:20:25.167 Type: SSH_FXP_NAME, Size: 5859, Number: 524
> 2009-05-07 16:20:25.167 Type: SSH_FXP_READDIR, Size: 13, Number: 780
< 2009-05-07 16:20:25.214 Type: SSH_FXP_STATUS, Size: 28, Number: 780
< 2009-05-07 16:20:25.214 Status/error code: 1
> 2009-05-07 16:20:25.214 Type: SSH_FXP_CLOSE, Size: 13, Number: 1028
. 2009-05-07 16:20:25.214 Closing connection.
. 2009-05-07 16:20:25.214 Sending special code: 12
. 2009-05-07 16:20:25.214 Sent EOF message

There's no error in the log file.
So probably there is some problem in your script. Please post the script and show how you run it as well.
See also how to troubleshoot scripting problems.

Hello
I also get a similar problem to that mentioned above. An ls command does not return a directory listing the log. It does return a directory listing on the remote server. I've used the 'downloading the most recent file' script from the winscp site (example.js) and also created a simple batch file to test whether the same logging problem happens. It does whether logging to txt or xml. Sorry if I am missing something obvious.


Batch file
----------
winscp.exe /script=c:\DRM\CMA\old\cma2.txt /log=c:\DRM\CMA\old\log.xml

Script file
----------
option batch on
option confirm off
open cma74@202.135.116.217
cd /from-post/cma
ls spedy*.txt
option transfer ascii
get spedy*.txt c:\DRM\CMA\old\
close
exit

Log
---
. 2009-07-03 09:40:39.985 --------------------------------------------------------------------------
. 2009-07-03 09:40:39.985 WinSCP Version 4.1.9 (Build 416) (OS 5.1.2600 Service Pack 2)
. 2009-07-03 09:40:39.985 Login time: Friday, 3 July 2009 9:40:39 a.m.
. 2009-07-03 09:40:39.985 --------------------------------------------------------------------------
. 2009-07-03 09:40:39.985 Session name: cma74@202.135.116.217
. 2009-07-03 09:40:39.985 Host name: 202.135.116.217 (Port: 22)
. 2009-07-03 09:40:39.985 User name: cma74 (Password: Yes, Key file: No)
. 2009-07-03 09:40:39.985 Tunnel: No
. 2009-07-03 09:40:39.985 Transfer Protocol: SFTP (SCP)
. 2009-07-03 09:40:39.985 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2009-07-03 09:40:39.985 Proxy: none
. 2009-07-03 09:40:39.985 SSH protocol version: 2; Compression: No
. 2009-07-03 09:40:39.985 Bypass authentication: No
. 2009-07-03 09:40:39.985 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2009-07-03 09:40:39.985 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2009-07-03 09:40:39.985 SSH Bugs: -,-,-,-,-,-,-,-
. 2009-07-03 09:40:39.985 SFTP Bugs: -,-
. 2009-07-03 09:40:39.985 Return code variable: Autodetect; Lookup user groups: Yes
. 2009-07-03 09:40:39.985 Shell: default, EOL: 0
. 2009-07-03 09:40:39.985 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2009-07-03 09:40:39.985 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2009-07-03 09:40:39.985 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2009-07-03 09:40:39.985 Cache directory changes: Yes, Permanent: Yes
. 2009-07-03 09:40:39.985 DST mode: 1
. 2009-07-03 09:40:39.985 --------------------------------------------------------------------------
. 2009-07-03 09:40:39.985 Looking up host "202.135.116.217"
. 2009-07-03 09:40:39.985 Connecting to 202.135.116.217 port 22
. 2009-07-03 09:40:40.204 Server version: SSH-1.99-OpenSSH_3.4p1
. 2009-07-03 09:40:40.204 We claim version: SSH-2.0-WinSCP_release_4.1.9
. 2009-07-03 09:40:40.204 SSPI: acquired credentials for: medleyd@NZBLOOD.CO.NZ
. 2009-07-03 09:40:40.204 Cannot convert IP address to SPN: DNS is not trusted
. 2009-07-03 09:40:40.204 GSSKEX disabled: The operation completed successfully.

. 2009-07-03 09:40:40.204 Using SSH protocol version 2
. 2009-07-03 09:40:40.297 Doing Diffie-Hellman group exchange
. 2009-07-03 09:40:40.563 Doing Diffie-Hellman key exchange with hash SHA-1
. 2009-07-03 09:40:41.172 Host key fingerprint is:
. 2009-07-03 09:40:41.172 ssh-rsa 1024 4e:3a:34:f9:7e:da:f4:7d:2b:7e:f1:bb:5d:c8:c9:2d
. 2009-07-03 09:40:41.172 Initialised AES-256 CBC client->server encryption
. 2009-07-03 09:40:41.172 Initialised HMAC-SHA1 client->server MAC algorithm
. 2009-07-03 09:40:41.172 Initialised AES-256 CBC server->client encryption
. 2009-07-03 09:40:41.172 Initialised HMAC-SHA1 server->client MAC algorithm
! 2009-07-03 09:40:41.376 Using username "cma74".
. 2009-07-03 09:40:41.579 Keyboard-interactive authentication refused
. 2009-07-03 09:40:41.579 Prompt (6, SSH password, , &Password: )
. 2009-07-03 09:40:41.579 Using stored password.
. 2009-07-03 09:40:41.579 Sent password
. 2009-07-03 09:40:41.797 Access granted
. 2009-07-03 09:40:41.907 Opened channel for session
. 2009-07-03 09:40:42.016 Started a shell/command
. 2009-07-03 09:40:42.016 --------------------------------------------------------------------------
. 2009-07-03 09:40:42.016 Using SFTP protocol.
. 2009-07-03 09:40:42.016 Doing startup conversation with host.
> 2009-07-03 09:40:42.016 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2009-07-03 09:40:42.110 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2009-07-03 09:40:42.110 SFTP version 3 negotiated.
. 2009-07-03 09:40:42.110 We believe the server has signed timestamps bug
. 2009-07-03 09:40:42.110 We will use UTF-8 strings for status messages only
. 2009-07-03 09:40:42.110 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2009-07-03 09:40:42.110 Getting current directory name.
. 2009-07-03 09:40:42.110 Getting real path for '.'
> 2009-07-03 09:40:42.110 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2009-07-03 09:40:42.204 Type: SSH_FXP_NAME, Size: 23, Number: 16
. 2009-07-03 09:40:42.204 Real path is '/'
. 2009-07-03 09:40:42.204 Startup conversation with host finished.
. 2009-07-03 09:40:42.204 Cached directory change via "/from-post/cma" to "/from-post/cma".
. 2009-07-03 09:40:42.204 Getting current directory name.
. 2009-07-03 09:40:42.204 Listing directory "/from-post/cma".
> 2009-07-03 09:40:42.219 Type: SSH_FXP_OPENDIR, Size: 23, Number: 267
< 2009-07-03 09:40:42.313 Type: SSH_FXP_HANDLE, Size: 13, Number: 267
> 2009-07-03 09:40:42.313 Type: SSH_FXP_READDIR, Size: 13, Number: 524
< 2009-07-03 09:40:42.422 Type: SSH_FXP_NAME, Size: 491, Number: 524
> 2009-07-03 09:40:42.422 Type: SSH_FXP_READDIR, Size: 13, Number: 780
< 2009-07-03 09:40:42.516 Type: SSH_FXP_STATUS, Size: 28, Number: 780
< 2009-07-03 09:40:42.516 Status/error code: 1
> 2009-07-03 09:40:42.516 Type: SSH_FXP_CLOSE, Size: 13, Number: 1028
. 2009-07-03 09:40:42.516 Listing directory "/from-post/cma".
> 2009-07-03 09:40:42.516 Type: SSH_FXP_OPENDIR, Size: 23, Number: 1291
< 2009-07-03 09:40:42.626 Type: SSH_FXP_STATUS, Size: 24, Number: 1028
. 2009-07-03 09:40:42.626 Discarding reserved response
< 2009-07-03 09:40:42.719 Type: SSH_FXP_HANDLE, Size: 13, Number: 1291
> 2009-07-03 09:40:42.719 Type: SSH_FXP_READDIR, Size: 13, Number: 1548
< 2009-07-03 09:40:42.813 Type: SSH_FXP_NAME, Size: 491, Number: 1548
> 2009-07-03 09:40:42.813 Type: SSH_FXP_READDIR, Size: 13, Number: 1804
< 2009-07-03 09:40:42.938 Type: SSH_FXP_STATUS, Size: 28, Number: 1804
< 2009-07-03 09:40:42.938 Status/error code: 1
> 2009-07-03 09:40:42.938 Type: SSH_FXP_CLOSE, Size: 13, Number: 2052
. 2009-07-03 09:40:42.938 File: "/from-post/cma/SPEDY20090630062022.txt"
. 2009-07-03 09:40:42.938 Copying "/from-post/cma/SPEDY20090630062022.txt" to local directory started.
. 2009-07-03 09:40:42.938 Ascii transfer mode selected.
. 2009-07-03 09:40:42.938 Opening remote file.
> 2009-07-03 09:40:42.938 Type: SSH_FXP_OPEN, Size: 55, Number: 2307
< 2009-07-03 09:40:43.032 Type: SSH_FXP_STATUS, Size: 24, Number: 2052
. 2009-07-03 09:40:43.032 Discarding reserved response
< 2009-07-03 09:40:43.126 Type: SSH_FXP_HANDLE, Size: 13, Number: 2307
> 2009-07-03 09:40:43.126 Type: SSH_FXP_FSTAT, Size: 13, Number: 2568
> 2009-07-03 09:40:43.126 Type: SSH_FXP_READ, Size: 25, Number: 2821
< 2009-07-03 09:40:43.235 Type: SSH_FXP_ATTRS, Size: 37, Number: 2568
. 2009-07-03 09:40:43.235 Storing reserved response
< 2009-07-03 09:40:43.438 Status/error code: 1
. 2009-07-03 09:40:43.438 3 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2009-07-03 09:40:43.438 Type: SSH_FXP_CLOSE, Size: 13, Number: 3332
. 2009-07-03 09:40:43.438 File: "/from-post/cma/SPEDY20090609062023.txt"
. 2009-07-03 09:40:43.438 Copying "/from-post/cma/SPEDY20090609062023.txt" to local directory started.
. 2009-07-03 09:40:43.438 Ascii transfer mode selected.
. 2009-07-03 09:40:43.438 Opening remote file.
> 2009-07-03 09:40:43.438 Type: SSH_FXP_OPEN, Size: 55, Number: 3587
< 2009-07-03 09:40:43.547 Type: SSH_FXP_STATUS, Size: 24, Number: 3332
. 2009-07-03 09:40:43.547 Discarding reserved response
< 2009-07-03 09:40:43.641 Type: SSH_FXP_HANDLE, Size: 13, Number: 3587
> 2009-07-03 09:40:43.641 Type: SSH_FXP_FSTAT, Size: 13, Number: 3848
> 2009-07-03 09:40:43.641 Type: SSH_FXP_READ, Size: 25, Number: 4101
< 2009-07-03 09:40:43.751 Type: SSH_FXP_ATTRS, Size: 37, Number: 3848
. 2009-07-03 09:40:43.751 Storing reserved response
< 2009-07-03 09:40:43.954 Status/error code: 1
. 2009-07-03 09:40:43.954 3 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2009-07-03 09:40:43.954 Type: SSH_FXP_CLOSE, Size: 13, Number: 4612
. 2009-07-03 09:40:43.954 Closing connection.
. 2009-07-03 09:40:43.954 Sending special code: 12
. 2009-07-03 09:40:43.954 Sent EOF message

Donne wrote:

An ls command does not return a directory listing the log. It does return a directory listing on the remote server.

Sorry I do not understand this part. ls command should list remote directory. Do you expect it to list local one?

Hi. The log does not show the same results as what is displayed onscreen when ls command is run on the remote server.

Log returns:
. 2009-07-03 09:40:42.204 Listing directory "/from-post/cma".
> 2009-07-03 09:40:42.219 Type: SSH_FXP_OPENDIR, Size: 23, Number: 267
< 2009-07-03 09:40:42.313 Type: SSH_FXP_HANDLE, Size: 13, Number: 267
> 2009-07-03 09:40:42.313 Type: SSH_FXP_READDIR, Size: 13, Number: 524
< 2009-07-03 09:40:42.422 Type: SSH_FXP_NAME, Size: 491, Number: 524
> 2009-07-03 09:40:42.422 Type: SSH_FXP_READDIR, Size: 13, Number: 780
< 2009-07-03 09:40:42.516 Type: SSH_FXP_STATUS, Size: 28, Number: 780
< 2009-07-03 09:40:42.516 Status/error code: 1

Whereas onscreen result is:
winscp> ls
drwxrwx--- 2 cma74 501 4096 Jun 30 6:22:32 2009 .
drwxrwx--- 6 cma74 501 4096 Feb 12 15:54:46 2009 ..
-rw-rw-r-- 1 516 516 648 Jun 30 6:22:32 2009 SPEDY20090630062022.txt
-rw-rw-r-- 1 516 516 643 Jun 9 6:22:30 2009 SPEDY20090609062023.txt
winscp>

I think this is because of UTF-8 encoding but I cannot override this. The result is that example.js returns 'no file in the log' when there files on the remote server.

Donne wrote:

Hi. The log does not show the same results as what is displayed onscreen when ls command is run on the remote server.

OK, I see. No it does not. Check XML logging if you want to extract listing from log file.

Hi,
I have the same issue with winscp. I am using winscp in c# application to download the files from secured ftp which is in linux server. Any one is having the solution please let me know. The same code works fine for me for the secured ftp setup in windows server. Hope the isse is with UTF-8 format.

Please help me.....
Thanks,Shinil

spk wrote:

I have the same issue with winscp. I am using winscp in c# application to download the files from secured ftp which is in linux server. Any one is having the solution please let me know. The same code works fine for me for the secured ftp setup in windows server. Hope the isse is with UTF-8 format.

Can you repeat what the problem is?

Thanks, I got the solution, when I used stored session in my C# code (winscp.StandardInput.WriteLine("open mysession")) by setting up the utf=1 in ini file it worked fine. For this I have to use the stored session in my code and have to create a session using the winscp tool, instead of using the stored session how can I set the utf=1 in c# code itself? can you please help me in this.

Anonymous wrote:

Thanks, I got the solution, when I used stored session in my C# code (winscp.StandardInput.WriteLine("open mysession")) by setting up the utf=1 in ini file it worked fine. For this I have to use the stored session in my code and have to create a session using the winscp tool, instead of using the stored session how can I set the utf=1 in c# code itself? can you please help me in this.

You can generate the INI file from your code and use it when running WinSCP.