FTP with HTTP Connect Proxy - Can't open data Connection (425)

Question

Hello,

I encounter some issue with Rebex FTP but only for one of my FTP's Provider. I succeed to access FTP through FileZilla but not with FTP Rebex.

It seems FileZilla use the Proxy for each action but not the Rebex one.

See my logs below (reach max characters):

Comments

REBEX :

2017-06-12 10:40:41.743 Opening log file.
2017-06-12 10:40:41.743 INFO Ftp(1)[10] Info: Connecting to ProviderIP:21 using Ftp 4.0.4700.0.
2017-06-12 10:40:41.743 INFO Ftp(1)[10] Info: Using proxy HTTP CONNECT lupxy001:8080.
2017-06-12 10:40:41.806 DEBUG Ftp(1)[10] Info: Connection succeeded.
2017-06-12 10:40:41.806 VERBOSE Ftp(1)[10] Info: Received data over control connection:
 0000 |32-32-30-20-75-6B-74-66 6D-6F-6E-64-64-6C-70-31| 220 uktfmonddlp1
 0010 |20-4D-69-63-72-6F-73-6F 66-74-20-46-54-50-20-53|  Microsoft FTP S
 0020 |65-72-76-69-63-65-20-28 56-65-72-73-69-6F-6E-20| ervice (Version
 0030 |35-2E-30-29-2E-0D-0A                           | 5.0)...
2017-06-12 10:40:41.806 VERBOSE Ftp(1)[10] Info: Response available to be received on control connection.
2017-06-12 10:40:41.806 INFO Ftp(1)[10] Response: 220 uktfmonddlp1 Microsoft FTP Service (Version 5.0).
2017-06-12 10:40:41.806 VERBOSE Ftp(1)[10] Info: Sent data over control connection:
 0000 |55-53-45-52-20-50-57-43 0D-0A                  | USER TOTO..
2017-06-12 10:40:41.806 INFO Ftp(1)[10] Command: USER TOTO
2017-06-12 10:40:41.852 VERBOSE Ftp(1)[10] Info: Received data over control connection:
 0000 |33-33-31-20-50-61-73-73 77-6F-72-64-20-72-65-71| 331 Password req
 0010 |75-69-72-65-64-20-66-6F 72-20-50-57-43-2E-0D-0A| uired for TOTO...
2017-06-12 10:40:41.852 VERBOSE Ftp(1)[10] Info: Response available to be received on control connection.
2017-06-12 10:40:41.852 INFO Ftp(1)[10] Response: 331 Password required for TOTO.
2017-06-12 10:40:41.852 VERBOSE Ftp(1)[10] Info: Sent data over control connection:
 0000 |50-41-53-53-20-**-**-** **-**-**-**-**-**-0D-0A| PASS *********..
2017-06-12 10:40:41.852 INFO Ftp(1)[10] Command: PASS *********
2017-06-12 10:40:41.884 VERBOSE Ftp(1)[10] Info: Received data over control connection:
 0000 |32-33-30-20-55-73-65-72 20-50-57-43-20-6C-6F-67| 230 User TOTO log
 0010 |67-65-64-20-69-6E-2E-0D 0A                     | ged in...
2017-06-12 10:40:41.884 VERBOSE Ftp(1)[10] Info: Response available to be received on control connection.
2017-06-12 10:40:41.884 INFO Ftp(1)[10] Response: 230 User TOTO logged in.
2017-06-12 10:40:41.884 DEBUG Ftp(1)[10] Info: Starting data transfer.
2017-06-12 10:40:41.884 VERBOSE Ftp(1)[10] Info: Sent data over control connection:
 0000 |54-59-50-45-20-49-0D-0A                        | TYPE I..
2017-06-12 10:40:41.884 INFO Ftp(1)[10] Command: TYPE I
2017-06-12 10:40:41.915 VERBOSE Ftp(1)[10] Info: Received data over control connection:
 0000 |32-30-30-20-54-79-70-65 20-73-65-74-20-74-6F-20| 200 Type set to
 0010 |49-2E-0D-0A                                    | I...
2017-06-12 10:40:41.915 VERBOSE Ftp(1)[10] Info: Response available to be received on control connection.
2017-06-12 10:40:41.915 INFO Ftp(1)[10] Response: 200 Type set to I.
2017-06-12 10:40:41.915 VERBOSE Ftp(1)[10] Info: Sent data over control connection:
 0000 |50-41-53-56-0D-0A                              | PASV..
2017-06-12 10:40:41.915 INFO Ftp(1)[10] Command: PASV
2017-06-12 10:40:41.946 VERBOSE Ftp(1)[10] Info: Received data over control connection:
 0000 |32-32-37-20-45-6E-74-65 72-69-6E-67-20-50-61-73| 227 Entering Pas
 0010 |73-69-76-65-20-4D-6F-64 65-20-28-31-35-39-2C-32| sive Mode (ProviderIP
 0020 |32-30-2C-35-36-2C-31-31 2C-31-33-39-2C-31-32-32| ,139,122
 0030 |29-0D-0A                                       | )..
2017-06-12 10:40:41.946 VERBOSE Ftp(1)[10] Info: Response available to be received on control connection.
2017-06-12 10:40:41.946 INFO Ftp(1)[10] Response: 227 Entering Passive Mode (ProviderIP,139,122)
2017-06-12 10:40:41.946 DEBUG Ftp(1)[10] Info: Establishing data connection to ProviderIP:35706.
2017-06-12 10:40:46.189 VERBOSE Ftp(1)[10] Info: Sent data over control connection:
 0000 |53-54-4F-52-20-72-65-71 75-65-73-74-2F-44-44-34| STOR request/DD4
 0010 |50-57-43-2E-72-65-71-0D 0A                     | TOTO.req..
2017-06-12 10:40:46.189 INFO Ftp(1)[10] Command: STOR request/DD4TOTO.req
2017-06-12 10:40:47.203 VERBOSE Ftp(1)[10] Info: No response available on control connection.
2017-06-12 10:40:58.357 VERBOSE Ftp(1)[10] Info: No response available on control connection.
2017-06-12 10:40:59.246 VERBOSE Ftp(1)[10] Info: Received data over control connection:
 0000 |34-32-35-20-43-61-6E-27 74-20-6F-70-65-6E-20-64| 425 Can't open d
 0010 |61-74-61-20-63-6F-6E-6E 65-63-74-69-6F-6E-2E-0D| ata connection..
 0020 |0A                                             | .
2017-06-12 10:40:59.246 VERBOSE Ftp(1)[10] Info: Response available to be received on control connection.
2017-06-12 10:40:59.246 INFO Ftp(1)[10] Response: 425 Can't open data connection.
2017-06-12 10:40:59.246 DEBUG Ftp(1)[10] Info: Error while starting data transfer: Rebex.Net.FtpException: Can't open data connection (425).
   at Rebex.Net.Ftp.2aYAeNZ(String , Boolean , OTxlj , Int64 , String , String , Int64 , FtpTransferState )
2017-06-12 10:40:59.262 DEBUG Ftp(1)[10] Info: Error while initializing data connection.
2017-06-12 10:40:59.262 ERROR Ftp(1)[10] Info: Rebex.Net.FtpException: Can't open data connection (425).
   at Rebex.Net.Ftp.2aYAeNZ(String , Boolean , OTxlj , Int64 , String , String , Int64 , FtpTransferState )
   at Rebex.Net.Ftp.1Qy0ja(String , String , Stream , Int64 , Int64 , 27NpLhZ )

---

FileZilla :

Status:    Disconnected from server
Status:    Connecting to ProviderIP through HTTP proxy
Status:    Resolving address of lupxy001
Status:    Connecting to Proxy:8080...
Status:    Connection with proxy established, performing handshake...
Response:    Proxy reply: HTTP/1.1 200 Connection established
Status:    Connection established, waiting for welcome message...
Response:    220 uktfmonddlp1 Microsoft FTP Service (Version 5.0).
Command:    AUTH TLS
Response:    500 'AUTH TLS': command not understood
Command:    AUTH SSL
Response:    500 'AUTH SSL': command not understood
Status:    Insecure server, it does not support FTP over TLS.
Command:    USER PWC
Response:    331 Password required for TOTO.
Command:    PASS *********
Response:    230 User TOTO logged in.
Status:    Server does not support non-ASCII characters.
Status:    Logged in
Status:    Retrieving directory listing...
Command:    PWD
Response:    257 "/TOTO" is current directory.
Command:    TYPE I
Response:    200 Type set to I.
Command:    PASV
Response:    227 Entering Passive Mode (ProviderIP,145,249)
Command:    LIST
Status:    Connecting to Proxy:8080...
Status:    Connection with proxy established, performing handshake...
Response:    Proxy reply: HTTP/1.1 200 Connection established
Response:    125 Data connection already open; Transfer starting.
Response:    226 Transfer complete.
Status:    Directory listing of "/TOTO" successful
Status:    Connecting to ProviderIP through HTTP proxy
Status:    Resolving address of lupxy001
Status:    Connecting to Proxy:8080...
Status:    Connection with proxy established, performing handshake...
Response:    Proxy reply: HTTP/1.1 200 Connection established
Status:    Connection established, waiting for welcome message...
Response:    220 uktfmonddlp1 Microsoft FTP Service (Version 5.0).
Command:    AUTH TLS
Response:    500 'AUTH TLS': command not understood
Command:    AUTH SSL
Response:    500 'AUTH SSL': command not understood
Status:    Insecure server, it does not support FTP over TLS.
Command:    USER TOTO
Response:    331 Password required for TOTO.
Command:    PASS *********
Response:    230 User TOTO logged in.
Status:    Server does not support non-ASCII characters.
Status:    Logged in
Status:    Starting upload of TempFiles\DD4TOTO.req
Command:    CWD /TOTO/request
Response:    250 CWD command successful.
Command:    TYPE I
Response:    200 Type set to I.
Command:    PASV
Response:    227 Entering Passive Mode (ProviderIP,178,217)
Command:    STOR DD4TOTO.req
Status:    Connecting to Proxy:8080...
Status:    Connection with proxy established, performing handshake...
Response:    Proxy reply: HTTP/1.1 200 Connection established
Response:    125 Data connection already open; Transfer starting.
Response:    226 Transfer complete.
Status:    File transfer successful, transferred 8,110 bytes in 3 seconds
Status:    Retrieving directory listing of "/TOTO/request"...
Command:    PASV
Response:    227 Entering Passive Mode (ProviderIP,84,137)
Command:    LIST
Status:    Connecting to Proxy:8080...
Status:    Connection with proxy established, performing handshake...
Response:    Proxy reply: HTTP/1.1 200 Connection established
Response:    125 Data connection already open; Transfer starting.
Response:    226 Transfer complete.
Status:    Directory listing of "/TOTO/request" successful
Status:    Starting download of /TOTO/request/DD4TOTO.req
Command:    PASV
Response:    227 Entering Passive Mode (ProviderIP,18,73)
Command:    RETR DD4TOTO.req
Status:    Connecting to Proxy:8080...
Status:    Connection with proxy established, performing handshake...
Response:    Proxy reply: HTTP/1.1 200 Connection established
Response:    125 Data connection already open; Transfer starting.
Response:    226 Transfer complete.
Status:    File transfer successful, transferred 8,110 bytes in 4 seconds

Answer 1

Can you please try the same with the latest version. The version you used is from 2012.

If it is not working, please post here log with LogLevel.Debug.

Comments

It seems it still not working.

The problem is only visible with this Provider, is it possible the problem is with their FTP or only due to our fault ?

Logs :

2017-06-13 14:06:07.871 Opening log file.
2017-06-13 14:06:07.871 Using FileLogWriter version 2.5.6339.0.
2017-06-13 14:06:07.897 INFO Ftp(1)[13] Info: Connecting to ProviderIP:21 using Ftp.
2017-06-13 14:06:07.898 INFO Ftp(1)[13] Info: Assembly: Rebex.Ftp 2017 R3 for .NET 4.0-4.7 (Trial)
2017-06-13 14:06:07.899 DEBUG Ftp(1)[13] Info: Platform: Windows 6.1.7601 32-bit; CLR: 4.0.30319.42000
2017-06-13 14:06:07.899 DEBUG Ftp(1)[13] Info: Culture: en; Windows-1252
2017-06-13 14:06:07.899 INFO Ftp(1)[13] Info: Using proxy HTTP CONNECT Proxy:8080.
2017-06-13 14:06:07.908 DEBUG ProxySocket(1)[13] Proxy: Resolving 'Proxy'.
2017-06-13 14:06:07.912 DEBUG ProxySocket(1)[5] Proxy: Connecting to proxy at ProxyIP:8080.
2017-06-13 14:06:08.100 DEBUG ProxySocket(1)[9] Proxy: Connection initialized successfully.
2017-06-13 14:06:08.101 DEBUG Ftp(1)[13] Info: Connection succeeded.
2017-06-13 14:06:08.114 INFO Ftp(1)[13] Response: 220 uktfmonddlp1 Microsoft FTP Service (Version 5.0).
2017-06-13 14:06:08.118 INFO Ftp(1)[13] Command: USER TOTO
2017-06-13 14:06:08.143 INFO Ftp(1)[13] Response: 331 Password required for TOTO.
2017-06-13 14:06:08.144 INFO Ftp(1)[13] Command: PASS *********
2017-06-13 14:06:08.163 INFO Ftp(1)[13] Response: 230 User TOTO logged in.
2017-06-13 14:06:08.181 DEBUG Ftp(1)[13] Info: Starting data transfer.
2017-06-13 14:06:08.181 INFO Ftp(1)[13] Command: TYPE I
2017-06-13 14:06:08.196 INFO Ftp(1)[13] Response: 200 Type set to I.
2017-06-13 14:06:08.198 INFO Ftp(1)[13] Command: PASV
2017-06-13 14:06:08.219 INFO Ftp(1)[13] Response: 227 Entering Passive Mode (ProviderIP,18,46)
2017-06-13 14:06:08.222 DEBUG Ftp(1)[13] Info: Establishing data connection to ProviderIP:4654.
2017-06-13 14:06:08.222 DEBUG ProxySocket(2)[13] Proxy: Resolving 'Proxy'.
2017-06-13 14:06:08.223 DEBUG ProxySocket(2)[10] Proxy: Connecting to proxy at ProxyIP:8080.
2017-06-13 14:06:11.904 DEBUG ProxySocket(2)[9] Proxy: Connection initialized successfully.
2017-06-13 14:06:11.904 DEBUG Ftp(1)[13] Info: Established data connection from LocalIP:8635.
2017-06-13 14:06:11.905 INFO Ftp(1)[13] Command: STOR File.req
2017-06-13 14:06:25.687 INFO Ftp(1)[13] Response: 425 Can't open data connection.
2017-06-13 14:06:25.689 DEBUG Ftp(1)[13] Info: Error while starting data transfer: Rebex.Net.FtpException: Can't open data connection (425).
   at Rebex.Net.Ftp.QU(String C, Boolean V, KSG Z, IQ N, Int64 Q, FtpTransferState M)
2017-06-13 14:06:25.689 DEBUG Ftp(1)[13] Info: Error while initializing data connection.
2017-06-13 14:06:25.690 ERROR Ftp(1)[13] Info: Rebex.Net.FtpException: Can't open data connection (425).
   at Rebex.Net.Ftp.QU(String C, Boolean V, KSG Z, IQ N, Int64 Q, FtpTransferState M)
   at Rebex.Net.Ftp.VL(String C, String V, Stream Z, Int64 N, Int64 Q, IQ M)

---

This seems that the proxy or server are doing something non-standard. Also, it seems Filezilla is able to apply some kind of workaround for this. Unfortunately, we are not able to see from Filezilla log, how it is done.
If you send us Wireshark (https://www.wireshark.org) network capture for the Filezilla upload, we should be able to add the same workaround. In this case, send the capture to support@rebex.net, I also suggest you to start capture after authentication (just before upload) to omit credentials, which are not necessary to reconstruct the workaround.

---

I succeed to fix the problem by using the property :
FTP.Settings.IgnorePassiveModeAddress = true
But I don't understand why neither the possible impact I can encounter with this kind of property. Do you have any idea or suggests ?

---

The IgnorePassiveModeAddress  option causes that the IP address announced by the server is ignored and data connection is established to IP address used by control connection (basically the connection made by Connect() method). It is useful to workaround cases where FTP server announces local address instead of public address.

Since you replaced original IP values in the log with "ProviderIP", I cannot tell much to this. But I suppose the server announced a local IP, instead of public IP.

The strange thing is, that the proxy pretend to establish data connection, see log line "Proxy: Connection initialized successfully."
Either the proxy lies (no connection was established in real) or the server is not listening on IP it announced (e.g. it uses more IP addresses but listens on one only).

Either way, the data connection was not opened. You can see from log timing, that th server waited 14 seconds for data connection to be opened, then it gave up. See:
2017-06-13 14:06:11.905 INFO Ftp(1)[13] Command: STOR File.req
2017-06-13 14:06:25.687 INFO Ftp(1)[13] Response: 425 Can't open data connection.