[FTPSERVER-111] Data channel cannot be opened in active mode

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.0.0-RC1
• Component/s: Core
• Environment: Solaris, Linux, maybe others (Windows seems to work)
• Assignee: Niklas Therning
• Reporter: Rico Neubauer
• Created: 25/Oct/07 18:50
• Updated: 29/Dec/08 19:58
• Resolved: 29/Dec/08 19:58

Description

FTP-Server with active mode running on Solaris/Linux
Client connects to the server with active mode.
Issue list command -> ok
issue second list command -> client hangs

Client commands:
220 Service ready for new user.
Name (localhost:username): test
331 User name okay, need password for test.
Password:
230 User logged in, proceed.
Remote system type is UNIX.
ftp>
ftp>
ftp> ls
200 Command PORT okay.
150 File status okay; about to open data connection.
directory1
directory2
226 Closing data connection.
11 bytes received in 0.0099 seconds (1.08 Kbytes/s)
ftp> ls
200 Command PORT okay.
150 File status okay; about to open data connection.
<Client hangs here>

Server-Log:
15:38:08,581 INFO [UserManagerImpl] authenticate: Authentication for user <test> complete.
15:38:08,583 DEBUG [UserManagerImpl] setUserConfigurations: Setting up user permissions...
15:38:08,584 DEBUG [UserManagerImpl] setUserConfigurations: Write permission granted for user <test>
15:38:08,597 DEBUG [FTPServerFtplet] onLogin:PASS *****
15:38:08,627 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] WRITE: 230 User logged in, proceed.
15:38:08,628 INFO [PASS] Login success - test
15:38:08,629 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:08,629 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] SENT: 230 User logged in, proceed.
15:38:08,630 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:08,631 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:08,631 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] RECEIVED: SYST
15:38:08,632 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:08,632 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] WRITE: 215 UNIX Type: Apache FTP Server
15:38:08,634 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:08,634 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] SENT: 215 UNIX Type: Apache FTP Server
15:38:08,635 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:08,635 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:11,153 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] RECEIVED: PORT 10,0,0,239,129,181
15:38:11,156 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:11,157 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] WRITE: 510 PORT is disabled.
15:38:11,158 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:11,158 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] SENT: 510 PORT is disabled.
15:38:11,159 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:11,160 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:11,160 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] RECEIVED: NLST
15:38:11,161 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:11,161 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] WRITE: 150 File status okay; about to open data connection.
15:38:11,162 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] SENT: 150 File status okay; about to open data connection.
15:38:11,167 WARN [IODataConnectionFactory] FtpDataConnection.getDataSocket()
java.lang.NullPointerException
at java.net.Socket.<init>(Socket.java:358)
at java.net.Socket.<init>(Socket.java:208)
at org.apache.ftpserver.IODataConnectionFactory.createDataSocket(IODataConnectionFactory.java:261)
at org.apache.ftpserver.IODataConnectionFactory.openConnection(IODataConnectionFactory.java:232)
at org.apache.ftpserver.command.NLST.execute(NLST.java:81)
at org.apache.ftpserver.listener.FtpProtocolHandler.service(FtpProtocolHandler.java:195)
at org.apache.ftpserver.listener.FtpProtocolHandler.onRequestReceived(FtpProtocolHandler.java:122)
at org.apache.ftpserver.listener.mina.MinaFtpProtocolHandler.messageReceived(MinaFtpProtocolHandler.java:106)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:569)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:298)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:647)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:220)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:266)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
15:38:11,174 DEBUG [NLST] Exception getting the output data stream
java.lang.NullPointerException
at java.net.Socket.<init>(Socket.java:358)
at java.net.Socket.<init>(Socket.java:208)
at org.apache.ftpserver.IODataConnectionFactory.createDataSocket(IODataConnectionFactory.java:261)
at org.apache.ftpserver.IODataConnectionFactory.openConnection(IODataConnectionFactory.java:232)
at org.apache.ftpserver.command.NLST.execute(NLST.java:81)
at org.apache.ftpserver.listener.FtpProtocolHandler.service(FtpProtocolHandler.java:195)
at org.apache.ftpserver.listener.FtpProtocolHandler.onRequestReceived(FtpProtocolHandler.java:122)
at org.apache.ftpserver.listener.mina.MinaFtpProtocolHandler.messageReceived(MinaFtpProtocolHandler.java:106)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:569)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:298)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:647)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:220)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:266)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
15:38:11,175 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] WRITE: 425 Can't open data connection.
15:38:11,176 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:38:11,176 INFO [MinaFtpProtocolHandler] [/10.0.0.239:33204] SENT: 425 Can't open data connection.
15:38:11,177 DEBUG [ExecutorFilter] Launching thread for /10.0.0.239:33204
15:38:11,177 DEBUG [ExecutorFilter] Exiting since queue is empty for /10.0.0.239:33204
15:39:38,458 WARN [MinaFtpProtocolHandler] [/10.0.0.239:33204] EXCEPTION:
org.apache.mina.filter.codec.ProtocolDecoderException: java.nio.charset.MalformedInputException: Input length = 1 (Hexdump: empty)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:160)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:298)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:647)
at org.apache.mina.common.support.AbstractIoFilterChain$HeadFilter.messageReceived(AbstractIoFilterChain.java:498)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:298)
at org.apache.mina.common.support.AbstractIoFilterChain.fireMessageReceived(AbstractIoFilterChain.java:292)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:253)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:223)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(SocketIoProcessor.java:44)
at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:524)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:39)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
Caused by: java.nio.charset.MalformedInputException: Input length = 1
at java.nio.charset.CoderResult.throwException(CoderResult.java:260)
at org.apache.mina.common.ByteBuffer.getString(ByteBuffer.java:953)
at org.apache.mina.filter.codec.textline.TextLineDecoder.decodeAuto(TextLineDecoder.java:180)
at org.apache.mina.filter.codec.textline.TextLineDecoder.decode(TextLineDecoder.java:113)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:153)
... 14 more