Strange Behavior when passive port specification is explicit

[Jagtar Singh <js...@hotmail.com>]

Hi,

We configured apache ftp server (v 1.0.6) for passive mode operation. Server is behind firewall so we specified port range (50000-55000) asking firewall admin to open the same range.On client side (connecting via external ip) we don't get response to PASV command (when doing dir). On server side we get this exception in log (excerpt below). We thought it's a firewall issue.
Strangely, we removed passive configuration from xml and everything started to work. Ports being used were 60000+ which we didn't ask admins to open. 
Also from internal IP, it never gave any issue.
Please explain the behavior because mostly we need passive port specification due to restrictive firewalls. I'm afraid this might cause problem.
Thanks in advance.J.--[ INFO] 2013-03-28 04:40:53,825 [admin] [][cl.ie.nt.ip] RECEIVED: PASV[DEBUG] 2013-03-28 04:40:53,825 [admin] [][cl.ie.nt.ip] Initiating passive data connection[DEBUG] 2013-03-28 04:40:53,826 [admin] [][cl.ie.nt.ip] Opening passive data connection on address "/int.ern.al.ip" and port 52103[DEBUG] 2013-03-28 04:40:53,826 [admin] [][cl.ie.nt.ip] Passive data connection created on address "/int.ern.al.ip" and port 52103[DEBUG] 2013-03-28 04:40:53,827 [admin] [][cl.ie.nt.ip] Firing a WRITE event for session 2[DEBUG] 2013-03-28 04:40:53,828 [admin] [][cl.ie.nt.ip] Firing a WRITE event for session 2[DEBUG] 2013-03-28 04:40:53,828 [admin] [][cl.ie.nt.ip] Event WRITE has been fired for session 2[DEBUG] 2013-03-28 04:40:53,828 [admin] [][cl.ie.nt.ip] Firing a WRITE event for session 2[DEBUG] 2013-03-28 04:40:53,829 [admin] [][cl.ie.nt.ip] Firing a MESSAGE_SENT event for session 2[DEBUG] 2013-03-28 04:40:53,829 [admin] [][cl.ie.nt.ip] Adding event MESSAGE_SENT to session 2Queue : [MESSAGE_SENT, ]
[DEBUG] 2013-03-28 04:40:53,829 [admin] [][cl.ie.nt.ip] Event MESSAGE_SENT has been fired for session 2[DEBUG] 2013-03-28 04:40:53,829 [admin] [][cl.ie.nt.ip] Firing a EXCEPTION_CAUGHT event for session 2[DEBUG] 2013-03-28 04:40:53,830 [admin] [][cl.ie.nt.ip] Adding event EXCEPTION_CAUGHT to session 2Queue : [MESSAGE_SENT, , EXCEPTION_CAUGHT, ]
[DEBUG] 2013-03-28 04:40:53,830 [admin] [][cl.ie.nt.ip] Event EXCEPTION_CAUGHT has been fired for session 2[DEBUG] 2013-03-28 04:40:53,830 [admin] [][cl.ie.nt.ip] Firing a SESSION_CLOSED event for session 2[DEBUG] 2013-03-28 04:40:53,830 [admin] [][cl.ie.nt.ip] Adding event SESSION_CLOSED to session 2Queue : [MESSAGE_SENT, , EXCEPTION_CAUGHT, , SESSION_CLOSED, ]
[DEBUG] 2013-03-28 04:40:53,830 [admin] [][cl.ie.nt.ip] Event SESSION_CLOSED has been fired for session 2[DEBUG] 2013-03-28 04:40:53,830 [admin] [][cl.ie.nt.ip] Event WRITE has been fired for session 2[DEBUG] 2013-03-28 04:40:53,831 [admin] [][cl.ie.nt.ip] Event WRITE has been fired for session 2[DEBUG] 2013-03-28 04:40:53,831 [admin] [][cl.ie.nt.ip] Event MESSAGE_RECEIVED has been fired for session 2[DEBUG] 2013-03-28 04:40:53,831 [] [][] Event MESSAGE_RECEIVED has been fired for session 2[DEBUG] 2013-03-28 04:40:53,831 [] [][] Firing a MESSAGE_SENT event for session 2[DEBUG] 2013-03-28 04:40:53,831 [admin] [][cl.ie.nt.ip] Firing a MESSAGE_SENT event for session 2[ INFO] 2013-03-28 04:40:53,831 [admin] [][cl.ie.nt.ip] SENT: 227 Entering Passive Mode (ex,te,rnl,ip,203,135)
[DEBUG] 2013-03-28 04:40:53,831 [admin] [][cl.ie.nt.ip] Event MESSAGE_SENT has been fired for session 2[DEBUG] 2013-03-28 04:40:53,831 [] [][] Event MESSAGE_SENT has been fired for session 2[DEBUG] 2013-03-28 04:40:53,831 [] [][] Firing a EXCEPTION_CAUGHT event for session 2[DEBUG] 2013-03-28 04:40:53,831 [admin] [][cl.ie.nt.ip] Firing a EXCEPTION_CAUGHT event for session 2[ WARN] 2013-03-28 04:40:53,833 [admin] [][cl.ie.nt.ip] EXCEPTION :java.io.IOException: An existing connection was forcibly closed by the remote host	at sun.nio.ch.SocketDispatcher.read0(Native Method)	at sun.nio.ch.SocketDispatcher.read(Unknown Source)	at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)	at sun.nio.ch.IOUtil.read(Unknown Source)	at sun.nio.ch.SocketChannelImpl.read(Unknown Source)	at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:280)	at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:44)	at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:695)	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:68)	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1141)	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)	at java.lang.Thread.run(Unknown Source)[ERROR] 2013-03-28 04:40:53,835 [admin] [][cl.ie.nt.ip] Exception caught, closing sessionjava.io.IOException: An existing connection was forcibly closed by the remote host	at sun.nio.ch.SocketDispatcher.read0(Native Method)	at sun.nio.ch.SocketDispatcher.read(Unknown Source)	at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)	at sun.nio.ch.IOUtil.read(Unknown Source)	at sun.nio.ch.SocketChannelImpl.read(Unknown Source)	at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:280)	at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:44)	at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:695)	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:68)	at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1141)	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)	at java.lang.Thread.run(Unknown Source)[DEBUG] 2013-03-28 04:40:53,836 [admin] [][cl.ie.nt.ip] Event EXCEPTION_CAUGHT has been fired for session 2[DEBUG] 2013-03-28 04:40:53,836 [] [][] Event EXCEPTION_CAUGHT has been fired for session 2[DEBUG] 2013-03-28 04:40:53,836 [] [][] Firing a SESSION_CLOSED event for session 2[DEBUG] 2013-03-28 04:40:53,836 [admin] [][cl.ie.nt.ip] Firing a SESSION_CLOSED event for session 2[ INFO] 2013-03-28 04:40:53,836 [admin] [][cl.ie.nt.ip] CLOSED--