Hi,
We have been running ftpserver 1.0.6 in a production environment for
several years. Last week we encountered an issue that we have not
encountered before.
We began to see intermittent failures when trying to enter passive mode. A
review of our logs showed multiple errors (sample trace below) with the
warning "Failed to open passive data connection... (Cannot find an
available passive port)". Our configuration includes a passive port range
of 800 ports, and based on our internal metrics and "netstat" output, we do
not believe we were using anywhere near this many ports at the time of
these errors. Restarting our java application resolved the issue.
Are there any known conditions where ftpserver could be consuming a larger
number of passive ports than expected? If so, what is the recommended
approach to detect and resolve?
Many thanks,
Mike
Detailed error trace:
Jun 25, 2015 12:07:03 PM org.apache.ftpserver.command.impl.PASV execute
WARNING: Failed to open passive data connection
org.apache.ftpserver.DataConnectionException: Cannot find an available
passive port.
at
org.apache.ftpserver.impl.IODataConnectionFactory.initPassiveDataConnection(IODataConnectionFactory.java:170)
at org.apache.ftpserver.command.impl.PASV.execute(PASV.java:73)
at
org.apache.ftpserver.impl.DefaultFtpHandler.messageReceived(DefaultFtpHandler.java:210)
at
org.apache.ftpserver.listener.nio.FtpHandlerAdapter.messageReceived(FtpHandlerAdapter.java:61)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:716)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at
org.apache.ftpserver.listener.nio.FtpLoggingFilter.messageReceived(FtpLoggingFilter.java:85)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at
org.apache.mina.filter.logging.MdcInjectionFilter.filter(MdcInjectionFilter.java:136)
at
org.apache.mina.filter.util.CommonEventFilter.messageReceived(CommonEventFilter.java:70)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at
org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutputImpl.flush(ProtocolCodecFilter.java:427)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:245)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(OrderedThreadPoolExecutor.java:780)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(OrderedThreadPoolExecutor.java:772)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThreadPoolExecutor.java:714)
at java.lang.Thread.run(Thread.java:722)
Jun 25, 2015 12:07:03 PM org.apache.mina.filter.logging.LoggingFilter log
INFO: SENT: 425 Can't open passive connection.
