FtpServer
  1. FtpServer
  2. FTPSERVER-111

Data channel cannot be opened in active mode

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.0.0-RC1
    • Component/s: Core
    • Labels:
      None
    • Environment:
      Solaris, Linux, maybe others (Windows seems to work)

      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

        Activity

        Rico Neubauer created issue -
        Hide
        Rico Neubauer added a comment -

        Patch

        Show
        Rico Neubauer added a comment - Patch
        Rico Neubauer made changes -
        Field Original Value New Value
        Attachment apache-ftpserver-111-patch.txt [ 12368403 ]
        Hide
        Niklas Gustavsson added a comment -

        Could you please provide a test case (like those in org.apache.ftpserver.clienttests) for this issue? I'm assuming this happens when the client sends the same port twice in the PORT command?

        Show
        Niklas Gustavsson added a comment - Could you please provide a test case (like those in org.apache.ftpserver.clienttests) for this issue? I'm assuming this happens when the client sends the same port twice in the PORT command?
        Hide
        Frank van der Kleij added a comment -

        I have a similar error (after your patch) on MacOSX in active mode (Java 1.4):

        [ WARN] 2007-11-17 18:34:36,050 FtpDataConnection.getDataSocket()
        java.net.BindException: Address already in use
        at java.net.PlainSocketImpl.socketBind(Native Method)
        at java.net.PlainSocketImpl.bind(PlainSocketImpl.java:359)
        at java.net.Socket.bind(Socket.java:562)
        at java.net.Socket.<init>(Socket.java:364)
        at java.net.Socket.<init>(Socket.java:266)
        at org.apache.ftpserver.IODataConnectionFactory.createDataSocket(IODataConnectionFactory.java:265)
        at org.apache.ftpserver.IODataConnectionFactory.openConnection(IODataConnectionFactory.java:232)
        at org.apache.ftpserver.command.LIST.execute(LIST.java:92)
        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.io.IOConnection.run(IOConnection.java:153)
        at java.lang.Thread.run(Thread.java:613)

        Show
        Frank van der Kleij added a comment - I have a similar error (after your patch) on MacOSX in active mode (Java 1.4): [ WARN] 2007-11-17 18:34:36,050 FtpDataConnection.getDataSocket() java.net.BindException: Address already in use at java.net.PlainSocketImpl.socketBind(Native Method) at java.net.PlainSocketImpl.bind(PlainSocketImpl.java:359) at java.net.Socket.bind(Socket.java:562) at java.net.Socket.<init>(Socket.java:364) at java.net.Socket.<init>(Socket.java:266) at org.apache.ftpserver.IODataConnectionFactory.createDataSocket(IODataConnectionFactory.java:265) at org.apache.ftpserver.IODataConnectionFactory.openConnection(IODataConnectionFactory.java:232) at org.apache.ftpserver.command.LIST.execute(LIST.java:92) 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.io.IOConnection.run(IOConnection.java:153) at java.lang.Thread.run(Thread.java:613)
        Hide
        Frank van der Kleij added a comment -

        I retested it on the branch1.4 branch and I was not able to reproduce the error I described above.

        Show
        Frank van der Kleij added a comment - I retested it on the branch1.4 branch and I was not able to reproduce the error I described above.
        Hide
        Brooks Lyrette added a comment -

        I'm seeing the same issue in M3 running on solaris.

        Show
        Brooks Lyrette added a comment - I'm seeing the same issue in M3 running on solaris.
        Hide
        Niklas Gustavsson added a comment -

        Fixed

        Show
        Niklas Gustavsson added a comment - Fixed
        Niklas Gustavsson made changes -
        Assignee Niklas Gustavsson [ niklas ]
        Resolution Fixed [ 1 ]
        Status Open [ 1 ] Closed [ 6 ]
        Fix Version/s 1.0.0-RC1 [ 12313542 ]

          People

          • Assignee:
            Niklas Gustavsson
            Reporter:
            Rico Neubauer
          • Votes:
            2 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development