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
beta7/26/2010 12:45:03 PM – (not
logged in) (xx.xx.xxx.xxx)> 220
ftp.xxxxxxxxxx.com7/26/2010 12:45:03 PM – (not
logged in) (xx.xx.xxx.xxx)> AUTH TLS7/26/2010 12:45:04 PM – (not
logged in) (xx.xx.xxx.xxx)> 234 Using
authentication type TLS7/26/2010 12:45:04 PM – (not
logged in) (xx.xx.xxx.xxx)> SSL
connection established7/26/2010 12:45:04 PM – (not
logged in) (xx.xx.xxx.xxx)> PBSZ 07/26/2010 12:45:04 PM – (not
logged in) (xx.xx.xxx.xxx)> 200
PBSZ=07/26/2010 12:45:05 PM – (not
logged in) (xx.xx.xxx.xxx)> PROT P7/26/2010 12:45:05 PM – (not
logged in) (xx.xx.xxx.xxx)> 200
Protection level set to P7/26/2010 12:45:05 PM – (not
logged in) (xx.xx.xxx.xxx)> USER username7/26/2010 12:45:05 PM – (not
logged in) (xx.xx.xxx.xxx)> 331
Password required for username7/26/2010 12:45:05 PM – (not
logged in) (xx.xx.xxx.xxx)> PASS xxxxxxxxxx7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> 230 Logged on7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> OPTS utf8 on7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> 200 UTF8 mode
enabled7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> PWD7/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 I7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> 200 Type set to I7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> PASV7/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)> LIST7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> 150 Connection
accepted7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> SSL connection for
data connection established7/26/2010 12:45:05 PM – username
(xx.xx.xxx.xxx)> 226 Transfer OK7/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.
Best Answer
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 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.