Problems with SFTP and empty directories

Hi i've just upgraded to 5.1.6, and are still seeing the problems like described in:

https://winscp.net/tracker/706

When loggin in to a FTP server with an empty directory, i get the below.

. 2013-08-12 17:00:16.024 --------------------------------------------------------------------------
. 2013-08-12 17:00:16.040 Connecting to XXX ...
. 2013-08-12 17:00:16.071 Connected with XXX, negotiating SSL connection...
< 2013-08-12 17:00:16.071 XXX. Welcome
> 2013-08-12 17:00:16.071 AUTH SSL
< 2013-08-12 17:00:16.118 234 AUTH Command OK. Initializing SSL connection.
. 2013-08-12 17:00:16.649 SSL connection established. Waiting for welcome message...
> 2013-08-12 17:00:16.649 USER XXX
< 2013-08-12 17:00:16.665 331 Password required for XXX.
> 2013-08-12 17:00:16.665 PASS **********
< 2013-08-12 17:00:16.681 230 Login OK. Proceed.
> 2013-08-12 17:00:16.681 SYST
< 2013-08-12 17:00:16.681 215 UNIX Type: L8
> 2013-08-12 17:00:16.681 FEAT
< 2013-08-12 17:00:16.696 211-Features supported:
< 2013-08-12 17:00:16.696 COMB target;source_list
< 2013-08-12 17:00:16.696 REST STREAM
< 2013-08-12 17:00:16.696 SIZE
< 2013-08-12 17:00:16.696 MDTM
< 2013-08-12 17:00:16.696 XCRC filename;start;end
< 2013-08-12 17:00:16.696 SSCN
< 2013-08-12 17:00:16.696 MLST Size*;Modify*;Create;Type*;Unique;Perm*;Lang;Media-Type;CharSet;
< 2013-08-12 17:00:16.696 MODE Z
< 2013-08-12 17:00:16.696 XNOP
< 2013-08-12 17:00:16.696 211 END
> 2013-08-12 17:00:16.696 PBSZ 0
< 2013-08-12 17:00:16.696 200 PBSZ Command OK. Protection buffer size set to 0.
> 2013-08-12 17:00:16.696 PROT P
< 2013-08-12 17:00:16.712 200 PROT Command OK. Using Private data connection
. 2013-08-12 17:00:16.712 Connected
. 2013-08-12 17:00:16.712 --------------------------------------------------------------------------
. 2013-08-12 17:00:16.712 Using FTP protocol.
. 2013-08-12 17:00:16.712 Doing startup conversation with host.
> 2013-08-12 17:00:16.712 PWD
< 2013-08-12 17:00:16.728 257 "/" is current folder.
. 2013-08-12 17:00:16.728 Getting current directory name.
. 2013-08-12 17:00:16.728 Startup conversation with host finished.
< 2013-08-12 17:00:16.728 Script: Active session: [1] XXX
> 2013-08-12 17:00:16.728 Script: option transfer binary
< 2013-08-12 17:00:16.728 Script: transfer binary
> 2013-08-12 17:00:16.728 Script: option batch abort
< 2013-08-12 17:00:16.728 Script: batch abort
> 2013-08-12 17:00:16.728 Script: option confirm off
< 2013-08-12 17:00:16.728 Script: confirm off
> 2013-08-12 17:00:16.728 Script: lcd f:\XXX
< 2013-08-12 17:00:16.728 Script: f:\XXX
> 2013-08-12 19:00:43.092 Script: get A* -delete
. 2013-08-12 19:00:43.092 Retrieving directory listing...
> 2013-08-12 19:00:43.092 TYPE A
< 2013-08-12 19:00:43.092 200 Type set to A.
> 2013-08-12 19:00:43.092 PASV
< 2013-08-12 19:00:43.124 227 Entering Passive Mode (212,130,240,223,109,96).
. 2013-08-12 19:00:43.124 Error retrieving server address, cannot test if address is routable
> 2013-08-12 19:00:43.124 MLSD
< 2013-08-12 19:00:43.155 150 Opening BINARY mode data connection for MLSD /.
. 2013-08-12 19:00:43.171 SSL connection established
. 2013-08-12 19:00:43.186 Could not retrieve directory listing
< 2013-08-12 19:00:43.264 226 Transfer complete. 0 bytes transferred. 0 bps.
. 2013-08-12 19:00:43.264 Asking user:
. 2013-08-12 19:00:43.264 Error listing directory '/'. ("Error retrieving server address, cannot test if address is routable","Could not retrieve directory listing","Transfer complete. 0 bytes transferred. 0 bps.")
< 2013-08-12 19:00:43.264 Script: Error listing directory '/'.
< 2013-08-12 19:00:43.264 Script: Error retrieving server address, cannot test if address is routable
< 2013-08-12 19:00:43.264 Could not retrieve directory listing
< 2013-08-12 19:00:43.264 Transfer complete. 0 bytes transferred. 0 bps.
. 2013-08-12 19:00:43.264 Script: Failed
. 2013-08-12 19:00:43.264 Script: Exit code: 1
. 2013-08-12 19:00:43.264 Disconnected from server

With files there it works fine... This is across several FTP servers

Any ideas???

regards,
Jesper

Sorry its not SFTP, FTPS!

Please attach a complete session log file using the latest beta version.

martin wrote:

Please attach a complete session log file using the latest beta version.

Here you go, same problem it seems.

. 2013-08-14 10:29:16.332 --------------------------------------------------------------------------
. 2013-08-14 10:29:16.332 WinSCP Version 5.2.3 (Build 3436) (OS 5.2.3790 Service Pack 2)
. 2013-08-14 10:29:16.347 Configuration: C:\Program Files\WinSCPbeta\WinSCP.ini
. 2013-08-14 10:29:16.363 Local account: XXX
. 2013-08-14 10:29:16.363 Working directory: C:\Program Files\WinSCPbeta
. 2013-08-14 10:29:16.363 Process ID: 7768
. 2013-08-14 10:29:16.363 Command-line: "C:\Program Files\WinSCPbeta\WinSCP.exe" /console=523 /consoleinstance=_10312_336 "/script=XXX" "/log=a.log"
. 2013-08-14 10:29:16.363 Time zone: Current: GMT+2, Standard: GMT+1, DST: GMT+2, DST Start: 31-03-2013, DST End: 27-10-2013
. 2013-08-14 10:29:16.363 Login time: 14. august 2013 10:29:16
. 2013-08-14 10:29:16.363 --------------------------------------------------------------------------
. 2013-08-14 10:29:16.363 Script: Retrospectivelly logging previous script records:
> 2013-08-14 10:29:16.363 Script: open XXX
. 2013-08-14 10:29:16.363 --------------------------------------------------------------------------
. 2013-08-14 10:29:16.363 Session name: XXX (Site)
. 2013-08-14 10:29:16.363 Host name: XXX (Port: 21)
. 2013-08-14 10:29:16.363 User name: XXX (Password: Yes, Key file: No)
. 2013-08-14 10:29:16.363 Tunnel: No
. 2013-08-14 10:29:16.363 Transfer Protocol: FTP
. 2013-08-14 10:29:16.363 Ping type: C, Ping interval: 30 sec; Timeout: 15 sec
. 2013-08-14 10:29:16.363 Proxy: SOCKS4
. 2013-08-14 10:29:16.363 HostName: 10.11.76.3 (Port: 1080); Username: ; Passwd: No
. 2013-08-14 10:29:16.363 FTP: FTPS: Explicit SSL; Passive: Yes [Force IP: A]; MLSD: A [List all: A]
. 2013-08-14 10:29:16.363 Session reuse: Yes
. 2013-08-14 10:29:16.363 TLS/SSL versions: SSLv2-TLSv1.2
. 2013-08-14 10:29:16.363 Local directory: default, Remote directory: home, Update: No, Cache: No
. 2013-08-14 10:29:16.363 Cache directory changes: No, Permanent: No
. 2013-08-14 10:29:16.363 DST mode: 1; Timezone offset: 0h 0m
. 2013-08-14 10:29:16.363 --------------------------------------------------------------------------
. 2013-08-14 10:29:16.379 Connecting to XXX ...
. 2013-08-14 10:29:16.379 Proxy layer changed state from unconnected to connecting
. 2013-08-14 10:29:16.379 TLS layer changed state from unconnected to connecting
. 2013-08-14 10:29:16.379 Proxy layer changed state from connecting to connected
. 2013-08-14 10:29:16.379 TLS layer changed state from connecting to connected
. 2013-08-14 10:29:16.379 Connected with XXX, negotiating TLS connection...
< 2013-08-14 10:29:16.394 220 XXX
> 2013-08-14 10:29:16.394 AUTH SSL
< 2013-08-14 10:29:16.582 234 AUTH Command OK. Initializing SSL connection.
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 read server hello A
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 read server certificate A
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 read server done A
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 write client key exchange A
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 write change cipher spec A
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 write finished A
. 2013-08-14 10:29:16.863 TLS connect: SSLv3 flush data
. 2013-08-14 10:29:16.894 TLS connect: SSLv3 read server session ticket A
. 2013-08-14 10:29:16.894 TLS connect: SSLv3 read finished A
. 2013-08-14 10:29:16.894 Using TLSv1, cipher TLSv1/SSLv3: AES256-SHA, 2048 bit RSA
. 2013-08-14 10:29:16.894 TLS connection established. Waiting for welcome message...
> 2013-08-14 10:29:16.894 USER XXX
< 2013-08-14 10:29:16.894 331 Password required for XXX.
> 2013-08-14 10:29:16.894 PASS **********
< 2013-08-14 10:29:16.910 230 Login OK. Proceed.
> 2013-08-14 10:29:16.910 SYST
< 2013-08-14 10:29:16.926 215 UNIX Type: L8
> 2013-08-14 10:29:16.926 FEAT
< 2013-08-14 10:29:16.926 211-Features supported:
< 2013-08-14 10:29:16.926 COMB target;source_list
< 2013-08-14 10:29:16.926 REST STREAM
< 2013-08-14 10:29:16.926 SIZE
< 2013-08-14 10:29:16.926 MDTM
< 2013-08-14 10:29:16.926 XCRC filename;start;end
< 2013-08-14 10:29:16.926 SSCN
< 2013-08-14 10:29:16.926 MLST Size*;Modify*;Create;Type*;Unique;Perm*;Lang;Media-Type;CharSet;
< 2013-08-14 10:29:16.926 XNOP
< 2013-08-14 10:29:16.926 211 END
> 2013-08-14 10:29:16.926 PBSZ 0
< 2013-08-14 10:29:16.941 200 PBSZ Command OK. Protection buffer size set to 0.
> 2013-08-14 10:29:16.941 PROT P
< 2013-08-14 10:29:16.941 200 PROT Command OK. Using Private data connection
. 2013-08-14 10:29:16.941 Connected
. 2013-08-14 10:29:16.941 Got reply 1 to the command 1
. 2013-08-14 10:29:16.941 --------------------------------------------------------------------------
. 2013-08-14 10:29:16.941 Using FTP protocol.
. 2013-08-14 10:29:16.941 Doing startup conversation with host.
> 2013-08-14 10:29:16.941 PWD
< 2013-08-14 10:29:16.957 257 "/" is current folder.
. 2013-08-14 10:29:16.957 Got reply 1 to the command 16
. 2013-08-14 10:29:16.957 Getting current directory name.
. 2013-08-14 10:29:16.957 Startup conversation with host finished.
< 2013-08-14 10:29:16.957 Script: Active session: [1] XXX
. 2013-08-14 10:29:16.957 Session upkeep
> 2013-08-14 10:29:16.957 Script: option transfer binary
< 2013-08-14 10:29:16.957 Script: transfer binary
. 2013-08-14 10:29:16.957 Session upkeep
> 2013-08-14 10:29:16.957 Script: option batch abort
< 2013-08-14 10:29:16.957 Script: batch abort
. 2013-08-14 10:29:16.957 Session upkeep
> 2013-08-14 10:29:16.957 Script: option confirm off
< 2013-08-14 10:29:16.957 Script: confirm off
. 2013-08-14 10:29:16.957 Session upkeep
> 2013-08-14 10:29:16.957 Script: lcd XXX
< 2013-08-14 10:29:16.957 Script: XXX
. 2013-08-14 10:29:16.957 Session upkeep
> 2013-08-14 10:29:16.957 Script: get A* -delete
. 2013-08-14 10:29:16.957 Retrieving directory listing...
> 2013-08-14 10:29:16.957 TYPE A
< 2013-08-14 10:29:16.972 200 Type set to A.
> 2013-08-14 10:29:16.972 PASV
< 2013-08-14 10:29:16.972 227 Entering Passive Mode (212,130,240,223,109,96).
. 2013-08-14 10:29:16.972 Error retrieving server address, cannot test if address is routable
> 2013-08-14 10:29:16.972 MLSD
. 2013-08-14 10:29:16.972 Proxy layer changed state from unconnected to connecting
. 2013-08-14 10:29:16.988 Proxy layer changed state from connecting to connected
< 2013-08-14 10:29:16.988 150 Opening BINARY mode data connection for MLSD /.
. 2013-08-14 10:29:17.004 Trying reuse main TLS session ID
. 2013-08-14 10:29:17.004 TLS layer changed state from none to connected
. 2013-08-14 10:29:17.019 Session ID reused
. 2013-08-14 10:29:17.019 TLS connection established
. 2013-08-14 10:29:17.035 TLS layer changed state from connected to aborted
. 2013-08-14 10:29:17.035 Could not retrieve directory listing
. 2013-08-14 10:29:17.035 Got reply 4 to the command 2
< 2013-08-14 10:29:17.082 226 Transfer complete. 0 bytes transferred. 0 bps.
. 2013-08-14 10:29:17.082 Asking user:
. 2013-08-14 10:29:17.082 Error listing directory '/'. ("Error retrieving server address, cannot test if address is routable","Could not retrieve directory listing","Transfer complete. 0 bytes transferred. 0 bps.")
< 2013-08-14 10:29:17.082 Script: Error listing directory '/'.
< 2013-08-14 10:29:17.097 Script: Error retrieving server address, cannot test if address is routable
< 2013-08-14 10:29:17.097 Could not retrieve directory listing
< 2013-08-14 10:29:17.097 Transfer complete. 0 bytes transferred. 0 bps.
. 2013-08-14 10:29:17.097 Script: Failed
. 2013-08-14 10:29:17.097 Session upkeep
. 2013-08-14 10:29:17.097 Script: Exit code: 1
. 2013-08-14 10:29:17.097 Got reply 1004 to the command 2
. 2013-08-14 10:29:17.097 Disconnected from server

Any chance of getting a test account on your server?

martin wrote:

Any chance of getting a test account on your server?

No unfortunately i don't think so. I can ask.

No unfortunately i don't think so. I can ask.

If not, can you please at least attach a relevant part of server's log?

martin wrote:

No unfortunately i don't think so. I can ask.

If not, can you please at least attach a relevant part of server's log?

Here is what i got:

2013-08-19 13:01:51 <IP-Address Masked> 21 ControlChannelOpened - - 0 0 0 0 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 AUTH SSL 234 0 0 22 10 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 USER XXX 331 0 0 69 17 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 PASS *** 230 0 0 362 16 ed10ca22-d9cd-4636-a318-d2a4e3075965 /
2013-08-19 13:01:51 <IP-Address Masked> 21 SYST - 215 0 0 53 6 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 FEAT - 211 0 0 313 6 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 OPTS UTF8+ON 200 0 0 85 14 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 PBSZ 0 200 0 0 69 8 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 PROT P 200 0 0 69 8 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 PWD - 257 0 0 69 5 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 CWD \ 250 0 0 69 7 ed10ca22-d9cd-4636-a318-d2a4e3075965 /
2013-08-19 13:01:51 <IP-Address Masked> 21 PWD - 257 0 0 69 5 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 CWD /XXX 250 0 0 69 14 ed10ca22-d9cd-4636-a318-d2a4e3075965 /XXX
2013-08-19 13:01:51 <IP-Address Masked> 21 PWD - 257 0 0 69 5 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 TYPE A 200 0 0 53 8 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:51 <IP-Address Masked> 21 PASV - 227 0 0 85 6 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 2046 DataChannelOpened - - 0 0 0 0 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 2046 DataChannelClosed - - 0 0 37 204 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 21 LIST -a 226 0 0 159 213 ed10ca22-d9cd-4636-a318-d2a4e3075965 /XXX
2013-08-19 13:01:52 <IP-Address Masked> 21 TYPE A 200 0 0 53 8 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 21 PASV - 227 0 0 85 6 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 2047 DataChannelOpened - - 0 0 0 0 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 2047 DataChannelClosed - - 0 0 37 204 ed10ca22-d9cd-4636-a318-d2a4e3075965 -
2013-08-19 13:01:52 <IP-Address Masked> 21 LIST - 226 0 0 159 210 ed10ca22-d9cd-4636-a318-d2a4e3075965 /XXX
2013-08-19 13:01:52 <IP-Address Masked> 21 ControlChannelClosed - - 0 0 5248 1221 ed10ca22-d9cd-4636-a318-d2a4e3075965 -

In your WinSCP log I can see WinSCP using MLSD command, while in the server's log, there's LIST -a. So it does not seem to be a corresponding log.

Also, can you send me an email, so I can send you back a debug version of WinSCP to track the problem? Please include link back to this topic in your email. Also note in this topic that you have sent the email. Thanks.

Email sent

This bug has been added to the tracker:
https://winscp.net/tracker/1068