Can explicitly ftps via Filezilla but not from code

Question

This was originally posted to StackOverflow, but because the code works and this is most likely a network/firewall issue, I figured I'd ask it here.

As the title states, I can connect to another machine from my server via FileZilla Client, but I cannot via code (.Net - FTPWebRequest)

I know the code is good, as it works from another machine. The particular machine I am having trouble with is behind a NAT, but the SA has opened all ports for traffic from the host we are trying to talk to.

Any suggestions - have I missed something obvious?

The exception I get from the attempted connection is:

"Unable to read data from the transport connection: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond."

And, the logs from the machine we are trying to connect show:

7/26/2010 12:40:23 PM - (not logged in) (xx.xx.xxx.xxx)> Connected, sending welcome message...

7/26/2010 12:40:23 PM - (not logged in) (xx.xx.xxx.xxx)> 220-FileZilla Server version 0.9.32 beta

7/26/2010 12:40:23 PM - (not logged in) (xx.xx.xxx.xxx)> 220 ftp.xxxxxxxxxx.com

7/26/2010 12:40:23 PM - (not logged in) (xx.xx.xxx.xxx)> AUTH TLS

7/26/2010 12:40:24 PM - (not logged in) (xx.xx.xxx.xxx)> 234 Using authentication type TLS

7/26/2010 12:41:24 PM - (not logged in) (xx.xx.xxx.xxx)> 421 Login time exceeded. Closing control connection.

7/26/2010 12:41:24 PM - (not logged in) (xx.xx.xxx.xxx)> disconnected.

EDIT: I am using passive mode for both the code and the filezilla connection. As requested, here is a log of a succesful ftps connection (LIST) from the code (on another machine):

7/26/2010 12:45:03 PM - (not logged in) (xx.xx.xxx.xxx)> Connected, sending welcome message...

7/26/2010 12:45:03 PM - (not logged in) (xx.xx.xxx.xxx)> 220-FileZilla Server version 0.9.32 beta

7/26/2010 12:45:03 PM - (not logged in) (xx.xx.xxx.xxx)> 220 ftp.xxxxxxxxxx.com

7/26/2010 12:45:03 PM - (not logged in) (xx.xx.xxx.xxx)> AUTH TLS

7/26/2010 12:45:04 PM - (not logged in) (xx.xx.xxx.xxx)> 234 Using authentication type TLS

7/26/2010 12:45:04 PM - (not logged in) (xx.xx.xxx.xxx)> SSL connection established

7/26/2010 12:45:04 PM - (not logged in) (xx.xx.xxx.xxx)> PBSZ 0

7/26/2010 12:45:04 PM - (not logged in) (xx.xx.xxx.xxx)> 200 PBSZ=0

7/26/2010 12:45:05 PM - (not logged in) (xx.xx.xxx.xxx)> PROT P

7/26/2010 12:45:05 PM - (not logged in) (xx.xx.xxx.xxx)> 200 Protection level set to P

7/26/2010 12:45:05 PM - (not logged in) (xx.xx.xxx.xxx)> USER username

7/26/2010 12:45:05 PM - (not logged in) (xx.xx.xxx.xxx)> 331 Password required for username

7/26/2010 12:45:05 PM - (not logged in) (xx.xx.xxx.xxx)> PASS xxxxxxxxxx

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 230 Logged on

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> OPTS utf8 on

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 200 UTF8 mode enabled

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> PWD

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 257 "/" is current directory.

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> CWD /

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 250 CWD successful. "/" is current directory.

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> TYPE I

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 200 Type set to I

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> PASV

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 227 Entering Passive Mode (xx,xx,xxx,xxx,xxx,xxx)

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> LIST

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 150 Connection accepted

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> SSL connection for data connection established

7/26/2010 12:45:05 PM - username (xx.xx.xxx.xxx)> 226 Transfer OK

7/26/2010 12:46:43 PM - username (xx.xx.xxx.xxx)> disconnected.

EDIT - and here is a log of a successful attempt from the same machine using FileZilla client

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> Connected, sending welcome message...

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> 220-FileZilla Server version 0.9.32 beta

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> 220 ftp.xxxxxxxx.com

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> SSL connection established

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> USER username

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> 331 Password required for username

7/28/2010 10:01:53 AM - (not logged in) (xx.xx.xxx.xxx)> PASS ********

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 230 Logged on

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> SYST

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 215 UNIX emulated by FileZilla

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> FEAT

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 211-Features:

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> MDTM

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> REST STREAM

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> SIZE

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> MLST type*;size*;modify*;

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> MLSD

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> AUTH SSL

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> AUTH TLS

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> UTF8

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> CLNT

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> MFMT

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 211 End

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> PBSZ 0

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 200 PBSZ=0

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> PROT P

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 200 Protection level set to P

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> PWD

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 257 "/" is current directory.

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> TYPE I

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 200 Type set to I

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> PASV

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 227 Entering Passive Mode (xx,xx,xxx,xxx,xxx,xxx)

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> MLSD

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 150 Connection accepted

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> SSL connection for data connection established

7/28/2010 10:01:53 AM - username (xx.xx.xxx.xxx)> 226 Transfer OK

7/28/2010 10:02:18 AM - username (xx.xx.xxx.xxx)> disconnected.

Answer 1

Dealing with these types of problems can be difficult because the logs usually tell you only part of what is happening.

Your best bet at this point is to use a packet capture and analysis software (like the most excellent - and free - wireshark) to see what is really going on the wire.

Make sure you capture all the traffic between your machine and the remote system and try to see what difference you can spot between a working connection and your code. That might give you an indication where the problem lies.

Do pay special attention to the way the TLS connection is negociated because it might point out to the actual issue (there is a pretty nice and simple to understand document that can be found at IBM's). For instance:

• If the connection stops after certificates have been exchanged, it is an indication that one of the parties cannot verify the other's certificate. This is a quite common source of problem with TLS software, especially when self-signed certificate or private roots are used.
• If the connection is broken in the first stage of the handshake, it can be that the client and server cannot agreed on what protocol to use (usually because one of the party restricts itself to "safe" protocols that the other does not support).
• If the server has set the "client certificate required" flag, then it could be that you haven't setup a client certificate for authentication.
• (etc)

If you see that the TLS channel has been successfully negociated, then you'll have to gring in the big guns: grab the server's private key and decode the TLS traffic. That will only be possible, however, if the TLS connection does not use DH key exchange so first, disable that in your server or client.

Once DH has been deactivated and you have the private key, you can follow the instructions on the Wireshark's wiki page about SSL/TLS which explains the process in quite a bit of details or this blog post that is perhaps a bit easier to follow.

Answer 2

have I missed something obvious

You might be making the mistake of thinking there is only one way of connecting to an ftp-server and hence assuming the your code is doing the same thing as the FileZilla Client.

You show the log when it does not connect. You need to compare it with a log of a successful connection to see how the client connects. (It may not be using AUTH TLS or may be using Passive Mode etc)

Also, I don't know anything about FileZilla, but that configuration (ie FTP, TLS and NAT) can cause problems, so much so that some FTP Servers describe themselves as NAT-Friendly.