Our Products:   CompleteFTP  edtFTPnet/Free  edtFTPnet/PRO  edtFTPj/Free  edtFTPj/PRO
Ask a Question

edtFTPj/Free: on passive mode returns private IP

0 votes
2.7k views
in FAQ: edtFTPj/Free by (120 points)

I'm experiencing problems with edtFTPj, deployed on AWS: regardless of what settings I set in advanced connection/server settings I'm getting "Error: Server returned unroutable private IP address in PASV reply " testing my server with https://ftptest.net/ and in server logs I see:

2016-04-19 06:21:48 INFO  FtpLoggingFilter:84 - RECEIVED: PASS *****
2016-04-19 06:21:48 INFO  PASS:246 - Login success - test2
2016-04-19 06:21:48 INFO  FtpLoggingFilter:157 - SENT: 230 User logged in, proceed.

2016-04-19 06:21:48 INFO  FtpLoggingFilter:84 - RECEIVED: TYPE I
2016-04-19 06:21:48 INFO  FtpLoggingFilter:157 - SENT: 200 Command TYPE okay.

2016-04-19 06:21:59 INFO  FtpLoggingFilter:84 - RECEIVED: MKD 945811551
2016-04-19 06:21:59 INFO  MKD:109 - Directory create : test2 - /945811551
2016-04-19 06:21:59 INFO  FtpLoggingFilter:157 - SENT: 257 "/945811551" created.

2016-04-19 06:22:01 INFO  FtpLoggingFilter:84 - RECEIVED: CWD 945811551
2016-04-19 06:22:01 INFO  FtpLoggingFilter:157 - SENT: 250 Directory changed to /945811551

2016-04-19 06:22:07 INFO  FtpLoggingFilter:84 - RECEIVED: SYST
2016-04-19 06:22:07 INFO  FtpLoggingFilter:157 - SENT: 215 UNIX Type: Apache FtpServer

2016-04-19 06:22:07 INFO  FtpLoggingFilter:84 - RECEIVED: PWD
2016-04-19 06:22:07 INFO  FtpLoggingFilter:157 - SENT: 257 "/945811551" is current directory.

2016-04-19 06:22:07 INFO  FtpLoggingFilter:84 - RECEIVED: PASV
2016-04-19 06:22:07 INFO  FtpLoggingFilter:157 - SENT: 227 Entering Passive Mode (172,31,30,187,200,147)


where 172.31.30.187 is mu EC2 instance's private IP.

 

in code:

            ftp.setRemoteHost(AppConstants.FTPServer.HOST);
            ftp.setRemotePort(AppConstants.FTPServer.PORT);
            ftp.setUserName(username);
            ftp.setPassword(password);
      ftp.getAdvancedFTPSettings().setActiveIPAddress(AppConstants.FTPServer.HOST);
            ftp.getAdvancedFTPSettings().setConnectMode(FTPConnectMode.PASV);
            ftp.getAdvancedFTPSettings().setAutoPassiveIPSubstitution(true); // AWS has problems with this
            ftp.getAdvancedFTPSettings().setActivePortRange(3000, 4000);

 

where AppConstants.FTPServer.HOST value in my public IP, I'm 100% sure with logs.

 

What I do wrong and how to fix this?

by (162k points)
Setting setAutoPassiveIPSubstitution(true) should work - what problem does AWS have with this?
by (120 points)
As you can see I have it set to true - edt seems to ignore this, returns private IP. I use free version 2.4.0 . Please disregard the comment concerning AWS has problems, it was about port range shall be opened.
by (162k points)
Enable debug logging and post a small segment of the log file at the debug level.
by (120 points)
here's the small piece around the passive mode host set to private:
https://www.dropbox.com/s/fwu21846zo83wry/edt_passive_mode_wrong_host.log?dl=0
here's the full log after server restart (pretty big, sorry - you might need it) https://www.dropbox.com/s/39px7wp3xse2gcm/PixelapCoreServer.log?dl=0
by (162k points)
We need the edtFTPj log, not the server log.
by (120 points)
clientside log you mean? The logs I've attached are serverside including edtFTPj lib log.
here's what ftptest.net shows:


Warning: Plaintext FTP is insecure. You should use explicit FTP over TLS.

Warning: Selected port (3232) is not the default port (21) of the selected protocol.

Status: Resolving address of ec2-52-11-95-149.us-west-2.compute.amazonaws.com

Status: Connecting to 52.11.95.149

Warning: The entered address does not resolve to an IPv6 address.

Status: Connected, waiting for welcome message...

Reply: 220 Service ready for new user.

Command: CLNT https://ftptest.net on behalf of 85.90.194.29

Reply: 530 Access denied.

Command: USER test2

Reply: 331 User name okay, need password for test2.

Command: PASS ********************************

Reply: 230 User logged in, proceed.

Command: SYST

Reply: 215 UNIX Type: Apache FtpServer

Command: FEAT

Reply: 211-Extensions supported

Reply: SIZE

Reply: MDTM

Reply: REST STREAM

Reply: LANG en;zh-tw;ja;is

Reply: MLST Size;Modify;Type;Perm

Reply: AUTH SSL

Reply: AUTH TLS

Reply: MODE Z

Reply: UTF8

Reply: TVFS

Reply: MD5

Reply: MMD5

Reply: MFMT

Reply: 211 End

Command: PWD

Reply: 257 "/" is current directory.

Status: Current path is /

Command: TYPE I

Reply: 200 Command TYPE okay.

Command: PASV

Reply: 227 Entering Passive Mode (172,31,30,187,160,126)

Error: Server returned unroutable private IP address in PASV reply
by (162k points)
See here for how to enable logging in edtFTPj

http://enterprisedt.com/products/edtftpj/doc/manual/html/howtosetuplogging.html

The client cannot influence the IP address returned by the server in the PASV command. Instead, it should substitute it with the IP it used to connect.
by (120 points)
2016-04-20 13:24:05 INFO  FtpLoggingFilter:84 - RECEIVED: PWD
2016-04-20 13:24:05 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:05 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_SENT to session 2
Queue : [MESSAGE_SENT, ]

2016-04-20 13:24:05 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:05 INFO  FtpLoggingFilter:157 - SENT: 257 "/" is current directory.


2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:05 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_RECEIVED to session 2
Queue : [MESSAGE_RECEIVED, ]

2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG ProtocolCodecFilter:213 - Processing a MESSAGE_RECEIVED for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_RECEIVED to session 2
Queue : [MESSAGE_RECEIVED, ]

2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG ProtocolCodecFilter:213 - Processing a MESSAGE_RECEIVED for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 INFO  FtpLoggingFilter:84 - RECEIVED: TYPE I
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_SENT to session 2
Queue : [MESSAGE_SENT, ]

2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:06 INFO  FtpLoggingFilter:157 - SENT: 200 Command TYPE okay.


2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_RECEIVED to session 2
Queue : [MESSAGE_RECEIVED, ]

2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG ProtocolCodecFilter:213 - Processing a MESSAGE_RECEIVED for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_RECEIVED to session 2
Queue : [MESSAGE_RECEIVED, ]

2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 DEBUG ProtocolCodecFilter:213 - Processing a MESSAGE_RECEIVED for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_RECEIVED event for session 2
2016-04-20 13:24:06 INFO  FtpLoggingFilter:84 - RECEIVED: PASV
2016-04-20 13:24:06 DEBUG IODataConnectionFactory:161 - Initiating passive data connection
2016-04-20 13:24:06 DEBUG IODataConnectionFactory:208 - Opening passive data connection on address "/172.31.30.187" and port 0
2016-04-20 13:24:06 DEBUG IODataConnectionFactory:213 - Passive data connection created on address "/172.31.30.187" and port 0
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a WRITE event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event WRITE has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event MESSAGE_SENT to session 2
Queue : [MESSAGE_SENT, ]

2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_RECEIVED has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a MESSAGE_SENT event for session 2
2016-04-20 13:24:06 INFO  FtpLoggingFilter:157 - SENT: 227 Entering Passive Mode (172,31,30,187,177,161)


2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:117 - Event MESSAGE_SENT has been fired for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a EXCEPTION_CAUGHT event for session 2
2016-04-20 13:24:06 DEBUG OrderedThreadPoolExecutor:431 - Adding event EXCEPTION_CAUGHT to session 2
Queue : [EXCEPTION_CAUGHT, ]
by (120 points)
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a EXCEPTION_CAUGHT event for session 2
2016-04-20 13:24:06 DEBUG IoFilterEvent:68 - Firing a EXCEPTION_CAUGHT event for session 2
2016-04-20 13:24:06 WARN  FtpLoggingFilter:130 - EXCEPTION :
java.lang.AbstractMethodError: org.apache.ftpserver.listener.nio.FtpHandlerAdapter.inputClosed(Lorg/apache/mina/core/session/IoSession;)V
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.inputClosed(DefaultIoFilterChain.java:834)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.inputClosed(DefaultIoFilterChain.java:938)
    at org.apache.mina.core.filterchain.IoFilterAdapter.inputClosed(IoFilterAdapter.java:137)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.inputClosed(DefaultIoFilterChain.java:938)
    at org.apache.mina.core.filterchain.IoFilterAdapter.inputClosed(IoFilterAdapter.java:137)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.inputClosed(DefaultIoFilterChain.java:938)
    at org.apache.mina.core.filterchain.IoFilterAdapter.inputClosed(IoFilterAdapter.java:137)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.inputClosed(DefaultIoFilterChain.java:938)
    at org.apache.mina.core.filterchain.IoFilterAdapter.inputClosed(IoFilterAdapter.java:137)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.inputClosed(DefaultIoFilterChain.java:938)
    at org.apache.mina.core.filterchain.IoFilterAdapter.inputClosed(IoFilterAdapter.java:137)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:48)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.inputClosed(DefaultIoFilterChain.java:938)
    at org.apache.mina.core.filterchain.IoFilterAdapter.inputClosed(IoFilterAdapter.java:137)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextInputClosed(DefaultIoFilterChain.java:611)
    at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireInputClosed(DefaultIoFilterChain.java:604)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:729)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:668)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:657)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1121)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
by (162k points)
None of this logging looks familiar. Where's the logging outputted by edtFTPj?
by (120 points)
I've set -Dedtftp.log.level=DEBUG to my Tomcat's JAVA_OPTS so it suppose to turn logging on. What would be the marks showing I'm getting edt logs?
Please note I have lines like
2016-04-20 13:24:06 INFO  FtpLoggingFilter:157 - SENT: 227 Entering Passive Mode (172,31,30,187,177,161)
on my logs. These are edt classes logs, right?
by (2.7k points)
This is not logging from edtFTPj.  Apache Mina is mentioned in the stack-trace and I suspect all of the logging is from there.   Mina seems to contain an FTP server.  edtFTPj is an FTP client library.
by (120 points)
Please say what is filter/mark for edtFTPj logs, please?
There are definitely fpt-related:

2016-04-27 15:30:14 INFO  FtpLoggingFilter:157 - SENT: 211-Extensions supported

 SIZE

 MDTM

 REST STREAM

 LANG en;zh-tw;ja;is

 MLST Size;Modify;Type;Perm

 AUTH SSL

 AUTH TLS

 MODE Z

 UTF8

 TVFS

 MD5

 MMD5

 MFMT

211 End

2016-04-27 15:30:15 INFO  FtpLoggingFilter:84 - RECEIVED: PASV
2016-04-27 15:30:15 DEBUG IODataConnectionFactory:161 - Initiating passive data connection
2016-04-27 15:30:15 DEBUG IODataConnectionFactory:208 - Opening passive data connection on address "/172.31.30.187" and port 0
2016-04-27 15:30:15 DEBUG IODataConnectionFactory:213 - Passive data connection created on address "/172.31.30.187" and port 0
by (120 points)
Oh! I think I got you! It's probably related to http://stackoverflow.com/questions/21015542/using-apache-ftp-server-in-passive-mode-not-working-connection-refused-by-serv described here. But I'm not implementing apache's server on my own, I use the default they provide. Will continue digging.

Please log in or register to answer this question.

EnterpriseDT 2020
...