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

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

        Fixed

        Show
        Niklas Gustavsson added a comment - Fixed
        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
        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
        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
        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?
        Rico Neubauer made changes -
        Field Original Value New Value
        Attachment apache-ftpserver-111-patch.txt [ 12368403 ]
        Hide
        Rico Neubauer added a comment -

        Patch

        Show
        Rico Neubauer added a comment - Patch
        Rico Neubauer created issue -

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development