FtpServer
  1. FtpServer
  2. FTPSERVER-339

Commands Dropped After Successful File Upload

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Critical Critical
    • Resolution: Unresolved
    • Affects Version/s: 1.0.3
    • Fix Version/s: 1.0.7, 1.1.0
    • Component/s: None
    • Labels:
      None

      Description

      After my ftp client successfully uploads a file, it sends a QUIT request. This QUIT request doesn't always appear to be logged by the FtpServer which results in the connection idling and the FtpServer subsequently closes the connection. We experience this issue often when uploading large files (2+GB) or multiple medium size files (~1 GB). When the QUIT is received before the FtpServer issues a 226 transfer complete message, the server sends a 226 transfer complete message , the a 221 goodbye message before closing the connection. When the QUIT is received after the FtpServer issues a 226 transfer complete message, sometimes the QUIT is processed on the existing thread and sometimes it is processed on a new thread. In either case, the server sends a 221 goodbye message and closed the connection. This leads me to believe that a QUIT message could be sent to the server in the time between when the first thread is being closed and the second thread is being opened. Below are logs from my FtpServer that illustrate all of these scenarios.

      This issue occurs very frequently and is resulting in the user believing their uploads failed.

      QUIT received before 226 transfer complete sent:
      2009-11-04 14:32:31,936 [pool-4-thread-8] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /1024/2009/11/02/7558_7W5oJqfN_event.wmv
      2009-11-04 14:32:31,937 [pool-4-thread-8] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection.
      2009-11-04 14:32:32,104 [pool-4-thread-8] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - RECEIVED: QUIT
      2009-11-04 14:32:32,104 [pool-4-thread-8] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete.
      2009-11-04 14:32:32,105 [pool-4-thread-8] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 221 Goodbye.
      2009-11-04 14:32:32,105 [pool-4-thread-8] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED

      QUIT received after 226 transfer complete sent on the same thread:
      2009-11-03 19:25:23,958 [pool-4-thread-697] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /1017/2009/10/09/7235_xVJpQ8tT_event.wmv
      2009-11-03 19:25:23,958 [pool-4-thread-697] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection.
      2009-11-03 19:25:23,968 [pool-4-thread-697] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete.
      2009-11-03 19:25:23,991 [pool-4-thread-697] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - RECEIVED: QUIT
      2009-11-03 19:25:23,992 [pool-4-thread-697] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 221 Goodbye.
      2009-11-03 19:25:23,992 [pool-4-thread-697] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED

      QUIT received after the 226 transfer complete sent on a new thread:
      2009-11-03 04:43:16,551 [pool-4-thread-662] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /1030/2009/11/02/7580_GxDwum7M_event.wmv
      2009-11-03 04:43:16,552 [pool-4-thread-662] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection.
      2009-11-03 04:43:16,552 [pool-4-thread-662] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete.
      2009-11-03 04:43:16,595 [pool-4-thread-667] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - RECEIVED: QUIT
      2009-11-03 04:43:16,598 [pool-4-thread-667] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 221 Goodbye.
      2009-11-03 04:43:16,598 [pool-4-thread-667] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED

      QUIT NOT received because the FtpServer is between threads:
      2009-11-04 02:05:18,328 [pool-4-thread-16] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /1051/2008/11/15/7400_NHftLRzu_event.mp4
      2009-11-04 02:05:18,329 [pool-4-thread-16] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection.
      2009-11-04 02:05:18,397 [pool-4-thread-16] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete.
      2009-11-04 02:08:18,394 [pool-4-thread-106] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - IDLE
      2009-11-04 02:08:18,394 [pool-4-thread-106] INFO org.apache.ftpserver.impl.DefaultFtpHandler - Session idle, closing
      2009-11-04 02:08:18,395 [pool-4-thread-106] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED

        Activity

        Niklas Gustavsson made changes -
        Fix Version/s 1.0.7 [ 12316510 ]
        Fix Version/s 1.0.6 [ 12315314 ]
        Hide
        Aniceto Pérez y Madrid added a comment -

        That is correct. The user who always was having problems is not having problems since upgrade to 1.0.6. I'll keep this under close surveillance for two weeks.

        Show
        Aniceto Pérez y Madrid added a comment - That is correct. The user who always was having problems is not having problems since upgrade to 1.0.6. I'll keep this under close surveillance for two weeks.
        Hide
        Niklas Gustavsson added a comment -

        Meaning you don't see the problem?

        Show
        Niklas Gustavsson added a comment - Meaning you don't see the problem?
        Hide
        Aniceto Pérez y Madrid added a comment -

        Version 1.0.6-SNAPSHOT works fine.
        Thanks

        Show
        Aniceto Pérez y Madrid added a comment - Version 1.0.6-SNAPSHOT works fine. Thanks
        Hide
        Aniceto Pérez y Madrid added a comment -

        Access fixed

        Show
        Aniceto Pérez y Madrid added a comment - Access fixed
        Hide
        Aniceto Pérez y Madrid added a comment -

        Better. No error, but it asks me for user and password

        Show
        Aniceto Pérez y Madrid added a comment - Better. No error, but it asks me for user and password
        Hide
        Niklas Gustavsson added a comment -

        Yes, the 1.0.x branch is the most stable version of FtpServer available.

        Could you please try using https, it might be a proxy interfering with your checkout.

        Show
        Niklas Gustavsson added a comment - Yes, the 1.0.x branch is the most stable version of FtpServer available. Could you please try using https, it might be a proxy interfering with your checkout.
        Hide
        Aniceto Pérez y Madrid added a comment -

        I can't import sources. I get this message "access to '/repos/asf/!svn/act/f0673f83-627e-2b42-ac4b-b61036a4472b' forbidden"

        Show
        Aniceto Pérez y Madrid added a comment - I can't import sources. I get this message "access to '/repos/asf/!svn/act/f0673f83-627e-2b42-ac4b-b61036a4472b' forbidden"
        Hide
        Aniceto Pérez y Madrid added a comment -

        I don't mind to use trunk or branch, but this server is in production. I prefer my customer not to behead me. I think the branch is more stable than the trunk, isn't it?

        Show
        Aniceto Pérez y Madrid added a comment - I don't mind to use trunk or branch, but this server is in production. I prefer my customer not to behead me. I think the branch is more stable than the trunk, isn't it?
        Hide
        Niklas Gustavsson added a comment -

        Then it would be great if you would be able to perform the tests as described in the comment above. The most significant issue is that currently released versions of FtpServer ships with old releases of MINA and many things has been fixed in MINA since.

        Show
        Niklas Gustavsson added a comment - Then it would be great if you would be able to perform the tests as described in the comment above. The most significant issue is that currently released versions of FtpServer ships with old releases of MINA and many things has been fixed in MINA since.
        Hide
        Aniceto Pérez y Madrid added a comment -

        I've done all tests with 1.0.4

        Show
        Aniceto Pérez y Madrid added a comment - I've done all tests with 1.0.4
        Hide
        Niklas Gustavsson added a comment -

        If you do not want to use FtpServer trunk, you can also go for the 1.0.x branch: http://svn.apache.org/repos/asf/mina/ftpserver/branches/1.0.x/

        Show
        Niklas Gustavsson added a comment - If you do not want to use FtpServer trunk, you can also go for the 1.0.x branch: http://svn.apache.org/repos/asf/mina/ftpserver/branches/1.0.x/
        Hide
        Niklas Gustavsson added a comment -

        I've spoken to Emmanuel on this problem and we would like you to try upgrading both FtpServer and MINA. Could you attempt to upgrade to FtpServer trunk? Or if that's not possible, FtpServer 1.0.5 with a drop in replacement of MINA to version 2.0.2. The MINA version in FtpServer 1.0.3 has known problems.

        Show
        Niklas Gustavsson added a comment - I've spoken to Emmanuel on this problem and we would like you to try upgrading both FtpServer and MINA. Could you attempt to upgrade to FtpServer trunk? Or if that's not possible, FtpServer 1.0.5 with a drop in replacement of MINA to version 2.0.2. The MINA version in FtpServer 1.0.3 has known problems.
        Hide
        Aniceto Pérez y Madrid added a comment -

        Any action?

        Show
        Aniceto Pérez y Madrid added a comment - Any action?
        Hide
        Aniceto Pérez y Madrid added a comment -

        I think there is no QUIT. Mainly because my client application only issues a QUIT when trying to upload a new file. Here is an excerpt of the client

        boolean b = doFtpConnect();
        boolean c = doFtpUpload();

        where

        private boolean doFtpConnect() {
        if (ftp != null)

        { /* if a connection was open before, close it with QUIT */ ftp.disconnect(true); }

        ftp = new it.sauronsoftware.ftp4j.FTPClient();
        ftp.connect(ftpHost, ftpPort);
        ftp.login(ftpUser, ftpPasswd);
        ftp.setPassive(jchkPasivo.isSelected());
        ftp.setType(FTPClient.TYPE_BINARY);
        ftp.changeDirectory(ftpDir);

        //create path if if doesn't exist
        for (String s : FilenameFormatter.getRuta(idfichero)) {
        try

        { ftp.changeDirectory(s); }

        catch (FTPException e)

        {//no existe ftp.createDirectory(s); ftp.changeDirectory(s); }

        }

        //if it was previously uploaded, get the size already there
        FTPFile[] list = ftp.list(Integer.toString(idfichero) + ".*");
        for (FTPFile fl : list) {
        if (fl.getName().equals(filenameremoto))

        { bytesFicheroEnServidor = (int) fl.getSize(); break; }

        else if (fl.getName().indexOf(Integer.toString(idfichero) + ".") == 0)

        { bytesFicheroEnServidor = 0; ftp.deleteFile(fl.getName()); }

        }

        return ok;
        }

        boolean doFtpUpload() {

        try

        { /* *********** the client stucks here *********** */ ftp.upload(filenameremoto, new FileInputStream(filelocal), bytesFicheroEnServidor, bytesFicheroEnServidor, this); /* *********** it does not receive the transfer complete message, and so it waits it forever ***** */ }

        finally

        { uploading = false; showMsgLogDetallado("End upload cmd"); }

        return ok;
        }

        Show
        Aniceto Pérez y Madrid added a comment - I think there is no QUIT. Mainly because my client application only issues a QUIT when trying to upload a new file. Here is an excerpt of the client boolean b = doFtpConnect(); boolean c = doFtpUpload(); where private boolean doFtpConnect() { if (ftp != null) { /* if a connection was open before, close it with QUIT */ ftp.disconnect(true); } ftp = new it.sauronsoftware.ftp4j.FTPClient(); ftp.connect(ftpHost, ftpPort); ftp.login(ftpUser, ftpPasswd); ftp.setPassive(jchkPasivo.isSelected()); ftp.setType(FTPClient.TYPE_BINARY); ftp.changeDirectory(ftpDir); //create path if if doesn't exist for (String s : FilenameFormatter.getRuta(idfichero)) { try { ftp.changeDirectory(s); } catch (FTPException e) {//no existe ftp.createDirectory(s); ftp.changeDirectory(s); } } //if it was previously uploaded, get the size already there FTPFile[] list = ftp.list(Integer.toString(idfichero) + ".*"); for (FTPFile fl : list) { if (fl.getName().equals(filenameremoto)) { bytesFicheroEnServidor = (int) fl.getSize(); break; } else if (fl.getName().indexOf(Integer.toString(idfichero) + ".") == 0) { bytesFicheroEnServidor = 0; ftp.deleteFile(fl.getName()); } } return ok; } boolean doFtpUpload() { try { /* *********** the client stucks here *********** */ ftp.upload(filenameremoto, new FileInputStream(filelocal), bytesFicheroEnServidor, bytesFicheroEnServidor, this); /* *********** it does not receive the transfer complete message, and so it waits it forever ***** */ } finally { uploading = false; showMsgLogDetallado("End upload cmd"); } return ok; }
        Hide
        Niklas Gustavsson added a comment -

        Very interesting, this shows if its a QUIT that is received at 2011-02-16 11:04:24,729, it is lost between MINA receives it from the network and before its handed off to the FtpServer handler.

        I will later today create an updated patch which also logs from the filter chain, especially the codec. Thanks for your assistance in this matter!

        Show
        Niklas Gustavsson added a comment - Very interesting, this shows if its a QUIT that is received at 2011-02-16 11:04:24,729, it is lost between MINA receives it from the network and before its handed off to the FtpServer handler. I will later today create an updated patch which also logs from the filter chain, especially the codec. Thanks for your assistance in this matter!
        Hide
        Aniceto Pérez y Madrid added a comment -

        Here I'm again. And there is no QUIT command

        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Event MESSAGE_RECEIVED has been fired for session 4
        [DEBUG] 2011-02-16 11:04:24,729 [] [] Firing a MESSAGE_RECEIVED event for session 4
        [DEBUG] 2011-02-16 11:04:24,729 [] [] Processing a MESSAGE_RECEIVED for session 4
        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Firing a MESSAGE_RECEIVED event for session 4
        [ INFO] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] RECEIVED: STOR 27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb
        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Handler received message STOR 27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb
        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Handled received request STOR 27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb
        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] About to execute command org.apache.ftpserver.command.impl.STOR@ee1ede for request
        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Executing command org.apache.ftpserver.command.impl.STOR@ee1ede for request
        [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Checking authorization for /ambito/0000000/0020000/0027700/27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Checking if file exists
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Authorized
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a WRITE event for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a WRITE event for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event WRITE has been fired for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a WRITE event for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event WRITE has been fired for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event WRITE has been fired for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4
        Queue : [MESSAGE_SENT, ]

        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, ]

        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Opening passive data connection
        [DEBUG] 2011-02-16 11:04:24,749 [userftp] [01.01.01.01] Passive data connection opened
        [DEBUG] 2011-02-16 11:04:24,749 [userftp] [01.01.01.01] Checking authorization for /ambito/0000000/0020000/0027700/27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb
        [DEBUG] 2011-02-16 11:04:24,749 [userftp] [01.01.01.01] Checking if file exists
        [DEBUG] 2011-02-16 11:04:24,750 [userftp] [01.01.01.01] Authorized
        [ INFO] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] File uploaded /ambito/0000000/0020000/0027700/27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb
        [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Firing a WRITE event for session 4
        [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Firing a WRITE event for session 4
        [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Event WRITE has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Firing a WRITE event for session 4
        [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Event WRITE has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Event WRITE has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Executed command org.apache.ftpserver.command.impl.STOR@ee1ede for request
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Event MESSAGE_RECEIVED has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [] [] Event MESSAGE_RECEIVED has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [] [] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, ]

        [DEBUG] 2011-02-16 11:06:33,985 [] [] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [] [] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4
        [ INFO] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] SENT: 150 File status okay; about to open data connection.^M

        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [] [] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, ]
        [DEBUG] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,986 [] [] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:06:33,986 [] [] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,986 [] [] Firing a MESSAGE_SENT event for session 4
        [DEBUG] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4
        [ INFO] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] SENT: 226 Transfer complete.^M

        [DEBUG] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:33,986 [] [] Event MESSAGE_SENT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:55,342 [userftp] [01.01.01.01] Firing a EXCEPTION_CAUGHT event for session 4
        [DEBUG] 2011-02-16 11:06:55,342 [userftp] [01.01.01.01] Adding event EXCEPTION_CAUGHT to session 4
        Queue : [EXCEPTION_CAUGHT, ]

        [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Event EXCEPTION_CAUGHT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Firing a EXCEPTION_CAUGHT event for session 4
        [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Firing a SESSION_CLOSED event for session 4
        [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Firing a EXCEPTION_CAUGHT event for session 4
        [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Adding event SESSION_CLOSED to session 4
        Queue : [SESSION_CLOSED, ]

        [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Event SESSION_CLOSED has been fired for session 4
        [ WARN] 2011-02-16 11:06:55,344 [userftp] [01.01.01.01] EXCEPTION :
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        [ERROR] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Exception caught, closing session
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Event EXCEPTION_CAUGHT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:55,345 [] [] Event EXCEPTION_CAUGHT has been fired for session 4
        [DEBUG] 2011-02-16 11:06:55,345 [] [] Firing a SESSION_CLOSED event for session 4
        [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Firing a SESSION_CLOSED event for session 4
        [ INFO] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] CLOSED
        [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Closing session
        [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Statistics login and connection count decreased due to session close
        [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Session closed
        [DEBUG] 2011-02-16 11:06:55,346 [userftp] [01.01.01.01] Event SESSION_CLOSED has been fired for session 4
        [DEBUG] 2011-02-16 11:06:55,346 [] [] Event SESSION_CLOSED has been fired for session 4
        ~

        Show
        Aniceto Pérez y Madrid added a comment - Here I'm again. And there is no QUIT command [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Event MESSAGE_RECEIVED has been fired for session 4 [DEBUG] 2011-02-16 11:04:24,729 [] [] Firing a MESSAGE_RECEIVED event for session 4 [DEBUG] 2011-02-16 11:04:24,729 [] [] Processing a MESSAGE_RECEIVED for session 4 [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Firing a MESSAGE_RECEIVED event for session 4 [ INFO] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] RECEIVED: STOR 27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Handler received message STOR 27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Handled received request STOR 27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] About to execute command org.apache.ftpserver.command.impl.STOR@ee1ede for request [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Executing command org.apache.ftpserver.command.impl.STOR@ee1ede for request [DEBUG] 2011-02-16 11:04:24,729 [userftp] [01.01.01.01] Checking authorization for /ambito/0000000/0020000/0027700/27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Checking if file exists [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Authorized [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a WRITE event for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a WRITE event for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event WRITE has been fired for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a WRITE event for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event WRITE has been fired for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event WRITE has been fired for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4 Queue : [MESSAGE_SENT, ] [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4 Queue : [MESSAGE_SENT, , MESSAGE_SENT, ] [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:04:24,730 [userftp] [01.01.01.01] Opening passive data connection [DEBUG] 2011-02-16 11:04:24,749 [userftp] [01.01.01.01] Passive data connection opened [DEBUG] 2011-02-16 11:04:24,749 [userftp] [01.01.01.01] Checking authorization for /ambito/0000000/0020000/0027700/27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb [DEBUG] 2011-02-16 11:04:24,749 [userftp] [01.01.01.01] Checking if file exists [DEBUG] 2011-02-16 11:04:24,750 [userftp] [01.01.01.01] Authorized [ INFO] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] File uploaded /ambito/0000000/0020000/0027700/27786.0a1ec24b9f9b3be91a44ef4865eea0a1f4829eeb [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Firing a WRITE event for session 4 [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Firing a WRITE event for session 4 [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Event WRITE has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Firing a WRITE event for session 4 [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Event WRITE has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,984 [userftp] [01.01.01.01] Event WRITE has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Executed command org.apache.ftpserver.command.impl.STOR@ee1ede for request [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Event MESSAGE_RECEIVED has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [] [] Event MESSAGE_RECEIVED has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:06:33,985 [] [] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4 Queue : [MESSAGE_SENT, , MESSAGE_SENT, ] [DEBUG] 2011-02-16 11:06:33,985 [] [] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [] [] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4 [ INFO] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] SENT: 150 File status okay; about to open data connection.^M [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:06:33,985 [] [] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,985 [userftp] [01.01.01.01] Adding event MESSAGE_SENT to session 4 Queue : [MESSAGE_SENT, , MESSAGE_SENT, ] [DEBUG] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,986 [] [] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:06:33,986 [] [] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,986 [] [] Firing a MESSAGE_SENT event for session 4 [DEBUG] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] Firing a MESSAGE_SENT event for session 4 [ INFO] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] SENT: 226 Transfer complete.^M [DEBUG] 2011-02-16 11:06:33,986 [userftp] [01.01.01.01] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:33,986 [] [] Event MESSAGE_SENT has been fired for session 4 [DEBUG] 2011-02-16 11:06:55,342 [userftp] [01.01.01.01] Firing a EXCEPTION_CAUGHT event for session 4 [DEBUG] 2011-02-16 11:06:55,342 [userftp] [01.01.01.01] Adding event EXCEPTION_CAUGHT to session 4 Queue : [EXCEPTION_CAUGHT, ] [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Event EXCEPTION_CAUGHT has been fired for session 4 [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Firing a EXCEPTION_CAUGHT event for session 4 [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Firing a SESSION_CLOSED event for session 4 [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Firing a EXCEPTION_CAUGHT event for session 4 [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Adding event SESSION_CLOSED to session 4 Queue : [SESSION_CLOSED, ] [DEBUG] 2011-02-16 11:06:55,343 [userftp] [01.01.01.01] Event SESSION_CLOSED has been fired for session 4 [ WARN] 2011-02-16 11:06:55,344 [userftp] [01.01.01.01] EXCEPTION : java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) [ERROR] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Exception caught, closing session java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Event EXCEPTION_CAUGHT has been fired for session 4 [DEBUG] 2011-02-16 11:06:55,345 [] [] Event EXCEPTION_CAUGHT has been fired for session 4 [DEBUG] 2011-02-16 11:06:55,345 [] [] Firing a SESSION_CLOSED event for session 4 [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Firing a SESSION_CLOSED event for session 4 [ INFO] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] CLOSED [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Closing session [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Statistics login and connection count decreased due to session close [DEBUG] 2011-02-16 11:06:55,345 [userftp] [01.01.01.01] Session closed [DEBUG] 2011-02-16 11:06:55,346 [userftp] [01.01.01.01] Event SESSION_CLOSED has been fired for session 4 [DEBUG] 2011-02-16 11:06:55,346 [] [] Event SESSION_CLOSED has been fired for session 4 ~
        Hide
        Aniceto Pérez y Madrid added a comment -

        At this moment no exceptions are thrown. I'll keep an eye on it to report ASAP.

        Show
        Aniceto Pérez y Madrid added a comment - At this moment no exceptions are thrown. I'll keep an eye on it to report ASAP.
        Hide
        Niklas Gustavsson added a comment -

        Adding another log statement even earlier in our code.

        Index: src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java
        ===================================================================
        — src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (revision 996857)
        +++ src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (working copy)
        @@ -175,6 +175,8 @@
        public void messageReceived(final FtpIoSession session,
        final FtpRequest request) throws Exception {
        try {
        + LOG.debug("Handler received request {}", request);
        +
        session.updateLastAccessTime();

        String commandName = request.getCommand();
        @@ -206,9 +208,13 @@
        return;
        } else if (ftpletRet != FtpletResult.SKIP) {

        + LOG.debug("About to execute command {} for request {}", command, request);
        +
        if (command != null) {
        synchronized (session) {
        + LOG.debug("Executing command {} for request {}", command, request);
        command.execute(session, context, request);
        + LOG.debug("Executed command {} for request {}", command, request);
        }
        } else {
        session.write(LocalizedFtpReply.translate(session, request,
        Index: src/main/java/org/apache/ftpserver/listener/nio/FtpHandlerAdapter.java
        ===================================================================
        — src/main/java/org/apache/ftpserver/listener/nio/FtpHandlerAdapter.java (revision 996857)
        +++ src/main/java/org/apache/ftpserver/listener/nio/FtpHandlerAdapter.java (working copy)
        @@ -21,6 +21,7 @@

        import org.apache.ftpserver.ftplet.FtpReply;
        import org.apache.ftpserver.ftplet.FtpRequest;
        +import org.apache.ftpserver.impl.DefaultFtpHandler;
        import org.apache.ftpserver.impl.DefaultFtpRequest;
        import org.apache.ftpserver.impl.FtpHandler;
        import org.apache.ftpserver.impl.FtpIoSession;
        @@ -29,6 +30,8 @@
        import org.apache.mina.core.session.IdleStatus;
        import org.apache.mina.core.session.IoSession;
        import org.apache.mina.filter.logging.MdcInjectionFilter;
        +import org.slf4j.Logger;
        +import org.slf4j.LoggerFactory;

        /**

        • <strong>Internal class, do not use directly.</strong>
          @@ -39,6 +42,9 @@
          *
          */
          public class FtpHandlerAdapter implements IoHandler {
          +
          + private final Logger LOG = LoggerFactory.getLogger(FtpHandlerAdapter.class);
          +
          private FtpServerContext context;

        private FtpHandler ftpHandler;
        @@ -56,6 +62,8 @@

        public void messageReceived(IoSession session, Object message)
        throws Exception {
        + LOG.debug("Handler received message {}", message);
        +
        FtpIoSession ftpSession = new FtpIoSession(session, context);
        FtpRequest request = new DefaultFtpRequest(message.toString());

        Show
        Niklas Gustavsson added a comment - Adding another log statement even earlier in our code. Index: src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java =================================================================== — src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (revision 996857) +++ src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (working copy) @@ -175,6 +175,8 @@ public void messageReceived(final FtpIoSession session, final FtpRequest request) throws Exception { try { + LOG.debug("Handler received request {}", request); + session.updateLastAccessTime(); String commandName = request.getCommand(); @@ -206,9 +208,13 @@ return; } else if (ftpletRet != FtpletResult.SKIP) { + LOG.debug("About to execute command {} for request {}", command, request); + if (command != null) { synchronized (session) { + LOG.debug("Executing command {} for request {}", command, request); command.execute(session, context, request); + LOG.debug("Executed command {} for request {}", command, request); } } else { session.write(LocalizedFtpReply.translate(session, request, Index: src/main/java/org/apache/ftpserver/listener/nio/FtpHandlerAdapter.java =================================================================== — src/main/java/org/apache/ftpserver/listener/nio/FtpHandlerAdapter.java (revision 996857) +++ src/main/java/org/apache/ftpserver/listener/nio/FtpHandlerAdapter.java (working copy) @@ -21,6 +21,7 @@ import org.apache.ftpserver.ftplet.FtpReply; import org.apache.ftpserver.ftplet.FtpRequest; +import org.apache.ftpserver.impl.DefaultFtpHandler; import org.apache.ftpserver.impl.DefaultFtpRequest; import org.apache.ftpserver.impl.FtpHandler; import org.apache.ftpserver.impl.FtpIoSession; @@ -29,6 +30,8 @@ import org.apache.mina.core.session.IdleStatus; import org.apache.mina.core.session.IoSession; import org.apache.mina.filter.logging.MdcInjectionFilter; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; /** <strong>Internal class, do not use directly.</strong> @@ -39,6 +42,9 @@ * */ public class FtpHandlerAdapter implements IoHandler { + + private final Logger LOG = LoggerFactory.getLogger(FtpHandlerAdapter.class); + private FtpServerContext context; private FtpHandler ftpHandler; @@ -56,6 +62,8 @@ public void messageReceived(IoSession session, Object message) throws Exception { + LOG.debug("Handler received message {}", message); + FtpIoSession ftpSession = new FtpIoSession(session, context); FtpRequest request = new DefaultFtpRequest(message.toString());
        Hide
        Aniceto Pérez y Madrid added a comment -

        The log entries have been added, and the previous logs are a bad and a good transfer. Forget the previous build error message, it was my fault.

        Show
        Aniceto Pérez y Madrid added a comment - The log entries have been added, and the previous logs are a bad and a good transfer. Forget the previous build error message, it was my fault.
        Hide
        Niklas Gustavsson added a comment -

        Does the build fail due to this, if not, you can probably ignore the warning?

        As noted on the mailing list, my patch was missing some placeholders, here's a new attempt:

        Index: src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java
        ===================================================================
        — src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (revision 996857)
        +++ src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (working copy)
        @@ -175,6 +175,8 @@
        public void messageReceived(final FtpIoSession session,
        final FtpRequest request) throws Exception {
        try {
        + LOG.debug("Handled received request {}", request);
        +
        session.updateLastAccessTime();

        String commandName = request.getCommand();
        @@ -206,9 +208,13 @@
        return;
        } else if (ftpletRet != FtpletResult.SKIP) {

        + LOG.debug("About to execute command {} for request {}", command, request);
        +
        if (command != null) {
        synchronized (session) {
        + LOG.debug("Executing command {} for request {}", command, request);
        command.execute(session, context, request);
        + LOG.debug("Executed command {} for request {}", command, request);
        }
        } else {
        session.write(LocalizedFtpReply.translate(session, request,

        Show
        Niklas Gustavsson added a comment - Does the build fail due to this, if not, you can probably ignore the warning? As noted on the mailing list, my patch was missing some placeholders, here's a new attempt: Index: src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java =================================================================== — src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (revision 996857) +++ src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (working copy) @@ -175,6 +175,8 @@ public void messageReceived(final FtpIoSession session, final FtpRequest request) throws Exception { try { + LOG.debug("Handled received request {}", request); + session.updateLastAccessTime(); String commandName = request.getCommand(); @@ -206,9 +208,13 @@ return; } else if (ftpletRet != FtpletResult.SKIP) { + LOG.debug("About to execute command {} for request {}", command, request); + if (command != null) { synchronized (session) { + LOG.debug("Executing command {} for request {}", command, request); command.execute(session, context, request); + LOG.debug("Executed command {} for request {}", command, request); } } else { session.write(LocalizedFtpReply.translate(session, request,
        Hide
        Aniceto Pérez y Madrid added a comment -

        This is the log
        [DEBUG] 2011-02-15 12:52:34,331 [gest_docs] [82.159.138.50] Checking authorization for /ambito/0000000/0020000/0027700/27755.a948aad5e59ed11224394bdafdf96c16268255a1
        [DEBUG] 2011-02-15 12:52:34,331 [gest_docs] [82.159.138.50] Checking if file exists
        [DEBUG] 2011-02-15 12:52:34,331 [gest_docs] [82.159.138.50] Authorized
        [ INFO] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] File uploaded /ambito/0000000/0020000/0027700/27755.a948aad5e59ed11224394bdafdf96c16268255a1
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a WRITE event for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a WRITE event for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a WRITE event for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Executed command org.apache.ftpserver.command.impl.STOR@1b01afa for request
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event MESSAGE_RECEIVED has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [] [] Event MESSAGE_RECEIVED has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [] [] Firing a MESSAGE_SENT event for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [] [] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [] [] Firing a MESSAGE_SENT event for session 7
        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7
        [ INFO] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] SENT: 150 File status okay; about to open data connection.^M

        [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [] [] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 7
        Queue : [MESSAGE_SENT, ]

        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 7
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, ]

        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [] [] Firing a MESSAGE_SENT event for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [] [] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [] [] Firing a MESSAGE_SENT event for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7
        [ INFO] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] SENT: 226 Transfer complete.^M

        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:09,320 [] [] Event MESSAGE_SENT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 7
        [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Adding event EXCEPTION_CAUGHT to session 7
        Queue : [EXCEPTION_CAUGHT, ]

        [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 7
        [DEBUG] 2011-02-15 12:54:30,662 [gest_docs] [82.159.138.50] Adding event SESSION_CLOSED to session 7
        Queue : [EXCEPTION_CAUGHT, , SESSION_CLOSED, ]

        [DEBUG] 2011-02-15 12:54:30,662 [gest_docs] [82.159.138.50] Event SESSION_CLOSED has been fired for session 7
        [DEBUG] 2011-02-15 12:54:30,662 [] [] Firing a EXCEPTION_CAUGHT event for session 7
        [DEBUG] 2011-02-15 12:54:30,662 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 7
        [ WARN] 2011-02-15 12:54:30,663 [gest_docs] [82.159.138.50] EXCEPTION :
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        [ERROR] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Exception caught, closing session
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        [DEBUG] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:30,664 [] [] Event EXCEPTION_CAUGHT has been fired for session 7
        [DEBUG] 2011-02-15 12:54:30,664 [] [] Firing a SESSION_CLOSED event for session 7
        [DEBUG] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 7
        [ INFO] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] CLOSED
        [DEBUG] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Closing session
        [DEBUG] 2011-02-15 12:54:30,665 [gest_docs] [82.159.138.50] Statistics login and connection count decreased due to session close
        [DEBUG] 2011-02-15 12:54:30,665 [gest_docs] [82.159.138.50] Session closed
        [DEBUG] 2011-02-15 12:54:30,665 [gest_docs] [82.159.138.50] Event SESSION_CLOSED has been fired for session 7
        [DEBUG] 2011-02-15 12:54:30,665 [] [] Event SESSION_CLOSED has been fired for session 7

        As you see no QUIT command is received. This is a working session log
        [DEBUG] 2011-02-15 12:51:22,193 [gest_docs] [82.159.138.50] Checking authorization for /ambito/0000000/0020000/0027700/27754.7b7161cb2cf5682bbc99bbf2d99dfc22cb30b9d1
        [DEBUG] 2011-02-15 12:51:22,193 [gest_docs] [82.159.138.50] Checking if file exists
        [DEBUG] 2011-02-15 12:51:22,194 [gest_docs] [82.159.138.50] Authorized
        [ INFO] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] File uploaded /ambito/0000000/0020000/0027700/27754.7b7161cb2cf5682bbc99bbf2d99dfc22cb30b9d1
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Executed command org.apache.ftpserver.command.impl.STOR@1b01afa for request
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event MESSAGE_RECEIVED has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [] [] Event MESSAGE_RECEIVED has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [] [] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [] [] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [] [] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6
        [ INFO] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] SENT: 150 File status okay; about to open data connection.^M

        [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [] [] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 6
        Queue : [MESSAGE_SENT, ]

        [DEBUG] 2011-02-15 12:52:29,311 [] [] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [] [] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 6
        Queue : [MESSAGE_SENT, ]

        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [] [] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6
        [ INFO] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] SENT: 226 Transfer complete.^M

        [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:29,311 [] [] Event MESSAGE_SENT has been fired for session 6
        [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Firing a MESSAGE_RECEIVED event for session 6
        [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Adding event MESSAGE_RECEIVED to session 6
        Queue : [MESSAGE_RECEIVED, ]

        [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Event MESSAGE_RECEIVED has been fired for session 6
        [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Firing a MESSAGE_RECEIVED event for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Processing a MESSAGE_RECEIVED for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a MESSAGE_RECEIVED event for session 6
        [ INFO] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] RECEIVED: QUIT
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Handled received request QUIT
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] About to execute command org.apache.ftpserver.command.impl.QUIT@1636e4e for request
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Executing command org.apache.ftpserver.command.impl.QUIT@1636e4e for request
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6
        [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 6
        Queue : [MESSAGE_SENT, ]

        Tell me what you need

        Show
        Aniceto Pérez y Madrid added a comment - This is the log [DEBUG] 2011-02-15 12:52:34,331 [gest_docs] [82.159.138.50] Checking authorization for /ambito/0000000/0020000/0027700/27755.a948aad5e59ed11224394bdafdf96c16268255a1 [DEBUG] 2011-02-15 12:52:34,331 [gest_docs] [82.159.138.50] Checking if file exists [DEBUG] 2011-02-15 12:52:34,331 [gest_docs] [82.159.138.50] Authorized [ INFO] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] File uploaded /ambito/0000000/0020000/0027700/27755.a948aad5e59ed11224394bdafdf96c16268255a1 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a WRITE event for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a WRITE event for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a WRITE event for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Executed command org.apache.ftpserver.command.impl.STOR@1b01afa for request [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event MESSAGE_RECEIVED has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,319 [] [] Event MESSAGE_RECEIVED has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,319 [] [] Firing a MESSAGE_SENT event for session 7 [DEBUG] 2011-02-15 12:54:09,319 [] [] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,319 [] [] Firing a MESSAGE_SENT event for session 7 [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7 [ INFO] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] SENT: 150 File status okay; about to open data connection.^M [DEBUG] 2011-02-15 12:54:09,319 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [] [] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7 [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 7 Queue : [MESSAGE_SENT, ] [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7 [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 7 Queue : [MESSAGE_SENT, , MESSAGE_SENT, ] [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [] [] Firing a MESSAGE_SENT event for session 7 [DEBUG] 2011-02-15 12:54:09,320 [] [] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [] [] Firing a MESSAGE_SENT event for session 7 [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 7 [ INFO] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] SENT: 226 Transfer complete.^M [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:09,320 [] [] Event MESSAGE_SENT has been fired for session 7 [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 7 [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Adding event EXCEPTION_CAUGHT to session 7 Queue : [EXCEPTION_CAUGHT, ] [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 7 [DEBUG] 2011-02-15 12:54:30,661 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 7 [DEBUG] 2011-02-15 12:54:30,662 [gest_docs] [82.159.138.50] Adding event SESSION_CLOSED to session 7 Queue : [EXCEPTION_CAUGHT, , SESSION_CLOSED, ] [DEBUG] 2011-02-15 12:54:30,662 [gest_docs] [82.159.138.50] Event SESSION_CLOSED has been fired for session 7 [DEBUG] 2011-02-15 12:54:30,662 [] [] Firing a EXCEPTION_CAUGHT event for session 7 [DEBUG] 2011-02-15 12:54:30,662 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 7 [ WARN] 2011-02-15 12:54:30,663 [gest_docs] [82.159.138.50] EXCEPTION : java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) [ERROR] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Exception caught, closing session java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) [DEBUG] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 7 [DEBUG] 2011-02-15 12:54:30,664 [] [] Event EXCEPTION_CAUGHT has been fired for session 7 [DEBUG] 2011-02-15 12:54:30,664 [] [] Firing a SESSION_CLOSED event for session 7 [DEBUG] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 7 [ INFO] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] CLOSED [DEBUG] 2011-02-15 12:54:30,664 [gest_docs] [82.159.138.50] Closing session [DEBUG] 2011-02-15 12:54:30,665 [gest_docs] [82.159.138.50] Statistics login and connection count decreased due to session close [DEBUG] 2011-02-15 12:54:30,665 [gest_docs] [82.159.138.50] Session closed [DEBUG] 2011-02-15 12:54:30,665 [gest_docs] [82.159.138.50] Event SESSION_CLOSED has been fired for session 7 [DEBUG] 2011-02-15 12:54:30,665 [] [] Event SESSION_CLOSED has been fired for session 7 As you see no QUIT command is received. This is a working session log [DEBUG] 2011-02-15 12:51:22,193 [gest_docs] [82.159.138.50] Checking authorization for /ambito/0000000/0020000/0027700/27754.7b7161cb2cf5682bbc99bbf2d99dfc22cb30b9d1 [DEBUG] 2011-02-15 12:51:22,193 [gest_docs] [82.159.138.50] Checking if file exists [DEBUG] 2011-02-15 12:51:22,194 [gest_docs] [82.159.138.50] Authorized [ INFO] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] File uploaded /ambito/0000000/0020000/0027700/27754.7b7161cb2cf5682bbc99bbf2d99dfc22cb30b9d1 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Executed command org.apache.ftpserver.command.impl.STOR@1b01afa for request [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event MESSAGE_RECEIVED has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,310 [] [] Event MESSAGE_RECEIVED has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,310 [] [] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:29,310 [] [] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,310 [] [] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6 [ INFO] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] SENT: 150 File status okay; about to open data connection.^M [DEBUG] 2011-02-15 12:52:29,310 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:29,311 [] [] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 6 Queue : [MESSAGE_SENT, ] [DEBUG] 2011-02-15 12:52:29,311 [] [] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:29,311 [] [] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 6 Queue : [MESSAGE_SENT, ] [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,311 [] [] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6 [ INFO] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] SENT: 226 Transfer complete.^M [DEBUG] 2011-02-15 12:52:29,311 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:29,311 [] [] Event MESSAGE_SENT has been fired for session 6 [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Firing a MESSAGE_RECEIVED event for session 6 [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Adding event MESSAGE_RECEIVED to session 6 Queue : [MESSAGE_RECEIVED, ] [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Event MESSAGE_RECEIVED has been fired for session 6 [DEBUG] 2011-02-15 12:52:32,817 [gest_docs] [82.159.138.50] Firing a MESSAGE_RECEIVED event for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Processing a MESSAGE_RECEIVED for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a MESSAGE_RECEIVED event for session 6 [ INFO] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] RECEIVED: QUIT [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Handled received request QUIT [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] About to execute command org.apache.ftpserver.command.impl.QUIT@1636e4e for request [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Executing command org.apache.ftpserver.command.impl.QUIT@1636e4e for request [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a WRITE event for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Event WRITE has been fired for session 6 [DEBUG] 2011-02-15 12:52:32,818 [gest_docs] [82.159.138.50] Adding event MESSAGE_SENT to session 6 Queue : [MESSAGE_SENT, ] Tell me what you need
        Hide
        Aniceto Pérez y Madrid added a comment -

        I'm having some problems when building the project. Using maven 3

        [INFO] — maven-bundle-plugin:1.4.1:bundle (default-bundle) @ ftpserver-core —
        [WARNING] Warning building bundle org.apache.ftpserver:ftpserver-core:bundle:1.0.5 : There are split packages, use directive -split-package:=(merge-first|merge-last) on instruction to get rid of this warning: org.apache.ftpserver, classpath: [Jar:., Jar:ftplet-api, Jar:slf4j-api, Jar:mina-core, Jar:spring-context, Jar:aopalliance, Jar:spring-beans, Jar:spring-core, Jar:jcl-over-slf4j] from: G:\eclisewshelios\ftpmina\target\classes

        and it repeats some times. I don't know what I have to do.

        Show
        Aniceto Pérez y Madrid added a comment - I'm having some problems when building the project. Using maven 3 [INFO] — maven-bundle-plugin:1.4.1:bundle (default-bundle) @ ftpserver-core — [WARNING] Warning building bundle org.apache.ftpserver:ftpserver-core:bundle:1.0.5 : There are split packages, use directive -split-package:=(merge-first|merge-last) on instruction to get rid of this warning: org.apache.ftpserver, classpath: [Jar:., Jar:ftplet-api, Jar:slf4j-api, Jar:mina-core, Jar:spring-context, Jar:aopalliance, Jar:spring-beans, Jar:spring-core, Jar:jcl-over-slf4j] from: G:\eclisewshelios\ftpmina\target\classes and it repeats some times. I don't know what I have to do.
        Hide
        Niklas Gustavsson added a comment -

        I'm thinking something like:

            1. Eclipse Workspace Patch 1.0
              #P ftpserver-core
              Index: src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java
              ===================================================================
            • src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (revision 996857)
              +++ src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (working copy)
              @@ -175,6 +175,8 @@
              public void messageReceived(final FtpIoSession session,
              final FtpRequest request) throws Exception {
              try {
              + LOG.debug("Handled received request {}", request);
              +
              session.updateLastAccessTime();

        String commandName = request.getCommand();
        @@ -206,9 +208,13 @@
        return;
        } else if (ftpletRet != FtpletResult.SKIP) {

        + LOG.debug("About to execute command {} for request", command, request);
        +
        if (command != null) {
        synchronized (session) {
        + LOG.debug("Executing command {} for request", command, request);
        command.execute(session, context, request);
        + LOG.debug("Executed command {} for request", command, request);
        }
        } else {
        session.write(LocalizedFtpReply.translate(session, request,

        Show
        Niklas Gustavsson added a comment - I'm thinking something like: Eclipse Workspace Patch 1.0 #P ftpserver-core Index: src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java =================================================================== src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (revision 996857) +++ src/main/java/org/apache/ftpserver/impl/DefaultFtpHandler.java (working copy) @@ -175,6 +175,8 @@ public void messageReceived(final FtpIoSession session, final FtpRequest request) throws Exception { try { + LOG.debug("Handled received request {}", request); + session.updateLastAccessTime(); String commandName = request.getCommand(); @@ -206,9 +208,13 @@ return; } else if (ftpletRet != FtpletResult.SKIP) { + LOG.debug("About to execute command {} for request", command, request); + if (command != null) { synchronized (session) { + LOG.debug("Executing command {} for request", command, request); command.execute(session, context, request); + LOG.debug("Executed command {} for request", command, request); } } else { session.write(LocalizedFtpReply.translate(session, request,
        Hide
        Aniceto Pérez y Madrid added a comment -

        At line 210 there is this code

        if (command != null) {
        synchronized (session)

        { command.execute(session, context, request); }

        } else {

        What kind of logging do you need/suggest?

        Show
        Aniceto Pérez y Madrid added a comment - At line 210 there is this code if (command != null) { synchronized (session) { command.execute(session, context, request); } } else { What kind of logging do you need/suggest?
        Hide
        Niklas Gustavsson added a comment -

        Sorry for the slow response. Looking at the debug trace where QUIT is not handled, would the QUIT message be what is received at "2009-11-06 06:27:53,220"? It would be interesting to add some debug logging in DefaultFtpHandler around the syncronization block at row 210. Would you be able to perform such tests? I will also attempt to reproduce the problem.

        Show
        Niklas Gustavsson added a comment - Sorry for the slow response. Looking at the debug trace where QUIT is not handled, would the QUIT message be what is received at "2009-11-06 06:27:53,220"? It would be interesting to add some debug logging in DefaultFtpHandler around the syncronization block at row 210. Would you be able to perform such tests? I will also attempt to reproduce the problem.
        Hide
        Aniceto Pérez y Madrid added a comment -

        The exception happens before QUIT command. I know because my client program gets hold at 100% xfer but doesn't returns from the upload call.This is the debugged log.
        [DEBUG] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 23
        [DEBUG] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 23
        [ INFO] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] SENT: 226 Transfer complete.^M

        [DEBUG] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 23
        [DEBUG] 2011-02-14 11:00:55,069 [] [] Event MESSAGE_SENT has been fired for session 23
        [DEBUG] 2011-02-14 11:01:16,441 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 23
        [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Adding event EXCEPTION_CAUGHT to session 23
        Queue : [EXCEPTION_CAUGHT, ]

        [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 23
        [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 23
        [DEBUG] 2011-02-14 11:01:16,442 [] [] Firing a EXCEPTION_CAUGHT event for session 23
        [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Adding event SESSION_CLOSED to session 23
        Queue : [SESSION_CLOSED, ]

        [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Event SESSION_CLOSED has been fired for session 23
        [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 23
        [ WARN] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] EXCEPTION :
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        [ERROR] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Exception caught, closing session
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        [DEBUG] 2011-02-14 11:01:16,443 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 23
        [DEBUG] 2011-02-14 11:01:16,443 [] [] Event EXCEPTION_CAUGHT has been fired for session 23
        [DEBUG] 2011-02-14 11:01:16,443 [] [] Firing a SESSION_CLOSED event for session 23
        [DEBUG] 2011-02-14 11:01:16,443 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 23
        [ INFO] 2011-02-14 11:01:16,443 [gest_docs] [82.159.138.50] CLOSED

        Show
        Aniceto Pérez y Madrid added a comment - The exception happens before QUIT command. I know because my client program gets hold at 100% xfer but doesn't returns from the upload call.This is the debugged log. [DEBUG] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 23 [DEBUG] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] Firing a MESSAGE_SENT event for session 23 [ INFO] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] SENT: 226 Transfer complete.^M [DEBUG] 2011-02-14 11:00:55,068 [gest_docs] [82.159.138.50] Event MESSAGE_SENT has been fired for session 23 [DEBUG] 2011-02-14 11:00:55,069 [] [] Event MESSAGE_SENT has been fired for session 23 [DEBUG] 2011-02-14 11:01:16,441 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 23 [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Adding event EXCEPTION_CAUGHT to session 23 Queue : [EXCEPTION_CAUGHT, ] [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 23 [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 23 [DEBUG] 2011-02-14 11:01:16,442 [] [] Firing a EXCEPTION_CAUGHT event for session 23 [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Adding event SESSION_CLOSED to session 23 Queue : [SESSION_CLOSED, ] [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Event SESSION_CLOSED has been fired for session 23 [DEBUG] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Firing a EXCEPTION_CAUGHT event for session 23 [ WARN] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] EXCEPTION : java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) [ERROR] 2011-02-14 11:01:16,442 [gest_docs] [82.159.138.50] Exception caught, closing session java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) [DEBUG] 2011-02-14 11:01:16,443 [gest_docs] [82.159.138.50] Event EXCEPTION_CAUGHT has been fired for session 23 [DEBUG] 2011-02-14 11:01:16,443 [] [] Event EXCEPTION_CAUGHT has been fired for session 23 [DEBUG] 2011-02-14 11:01:16,443 [] [] Firing a SESSION_CLOSED event for session 23 [DEBUG] 2011-02-14 11:01:16,443 [gest_docs] [82.159.138.50] Firing a SESSION_CLOSED event for session 23 [ INFO] 2011-02-14 11:01:16,443 [gest_docs] [82.159.138.50] CLOSED
        Hide
        Aniceto Pérez y Madrid added a comment -

        I'm experiencing this error from time to time. In some cases the issue can be reproduced. And it's very annoying not to trust a ftp server

        [ WARN] 2011-02-11 13:50:25,883 [xxxxx] [88.15.84.116] EXCEPTION :
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at java.lang.Thread.run(Thread.java:619)
        [ERROR] 2011-02-11 13:50:25,884 [xxxxxx] [88.15.84.116] Exception caught, closing session
        java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
        at sun.nio.ch.IOUtil.read(IOUtil.java:206)
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at java.lang.Thread.run(Thread.java:619)
        [ INFO] 2011-02-11 13:50:25,884 [gest_docs] [88.15.84.116] CLOSED

        Show
        Aniceto Pérez y Madrid added a comment - I'm experiencing this error from time to time. In some cases the issue can be reproduced. And it's very annoying not to trust a ftp server [ WARN] 2011-02-11 13:50:25,883 [xxxxx] [88.15.84.116] EXCEPTION : java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:619) [ERROR] 2011-02-11 13:50:25,884 [xxxxxx] [88.15.84.116] Exception caught, closing session java.io.IOException: Connection reset by peer at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:619) [ INFO] 2011-02-11 13:50:25,884 [gest_docs] [88.15.84.116] CLOSED
        Niklas Gustavsson made changes -
        Fix Version/s 1.1.0 [ 12313458 ]
        Niklas Gustavsson made changes -
        Fix Version/s 1.0.6 [ 12315314 ]
        Fix Version/s 1.1.0 [ 12313458 ]
        Fix Version/s 1.0.5 [ 12314821 ]
        Niklas Gustavsson made changes -
        Fix Version/s 1.0.5 [ 12314821 ]
        Fix Version/s 1.0.4 [ 12314283 ]
        Hide
        Niklas Gustavsson added a comment -

        Would it be possible for you to debug or add logging statements to org.apache.ftpserver.impl.DefaultFtpHandler.messageReceived(FtpIoSession, FtpRequest) to see how it behaves for the QUIT requests?

        Show
        Niklas Gustavsson added a comment - Would it be possible for you to debug or add logging statements to org.apache.ftpserver.impl.DefaultFtpHandler.messageReceived(FtpIoSession, FtpRequest) to see how it behaves for the QUIT requests?
        Niklas Gustavsson made changes -
        Field Original Value New Value
        Assignee Niklas Gustavsson [ niklas ]
        Fix Version/s 1.0.4 [ 12314283 ]
        Fix Version/s 1.1.0 [ 12313458 ]
        Hide
        Nick Padgett added a comment -

        Here's what the logs look like when the QUIT message is successfully processed:

        2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /803/2009/10/19/7344_U4BW46bp_event.wmv
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, ]

        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection.

        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34
        Queue : [MESSAGE_SENT, ]

        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_RECEIVED to session 34
        Queue : [MESSAGE_SENT, , MESSAGE_RECEIVED, ]

        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete.

        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - RECEIVED: QUIT
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34
        Queue : [MESSAGE_SENT, ]

        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, ]

        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.command.impl.QUIT - QUIT received, closing session
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a CLOSE event for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a CLOSE event for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event CLOSE has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event CLOSE has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34
        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event SESSION_CLOSED to session 34
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, , SESSION_CLOSED, ]

        2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 221 Goodbye.

        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Closing session
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Statistics login and connection count decreased due to session close
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Session closed
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 34
        2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 34

        Show
        Nick Padgett added a comment - Here's what the logs look like when the QUIT message is successfully processed: 2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /803/2009/10/19/7344_U4BW46bp_event.wmv 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34 Queue : [MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, ] 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection. 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34 Queue : [MESSAGE_SENT, ] 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_RECEIVED to session 34 Queue : [MESSAGE_SENT, , MESSAGE_RECEIVED, ] 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete. 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a MESSAGE_RECEIVED for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_RECEIVED event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - RECEIVED: QUIT 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34 Queue : [MESSAGE_SENT, ] 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 34 Queue : [MESSAGE_SENT, , MESSAGE_SENT, ] 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.command.impl.QUIT - QUIT received, closing session 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a CLOSE event for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a CLOSE event for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event CLOSE has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event CLOSE has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 34 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event SESSION_CLOSED to session 34 Queue : [MESSAGE_SENT, , MESSAGE_SENT, , SESSION_CLOSED, ] 2009-11-05 14:24:59,109 [NioProcessor-1] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 221 Goodbye. 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Closing session 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Statistics login and connection count decreased due to session close 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Session closed 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 34 2009-11-05 14:24:59,109 [pool-4-thread-23] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 34
        Hide
        Nick Padgett added a comment -

        I turned on DEBUG logging and replicated the issue. You'll notice there is a MESSAGE_RECEIVED event that was fired. I believe that was the QUIT message that I sent that is being ignored.

        2009-11-06 06:27:53,219 [pool-4-thread-11] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /803/2009/10/19/7344_ZvIVzV5d_event.wmv
        2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 25
        2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 25
        2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 25
        2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 25
        2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 25
        2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 25
        2009-11-06 06:27:53,219 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,219 [NioProcessor-8] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 25
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, ]
        2009-11-06 06:27:53,219 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 25
        2009-11-06 06:27:53,220 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 25
        2009-11-06 06:27:53,220 [NioProcessor-8] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 25
        Queue : [MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, ]
        2009-11-06 06:27:53,220 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection.
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25
        2009-11-06 06:27:53,267 [pool-4-thread-11] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete.
        2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25
        2009-11-06 06:29:34,248 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 25
        2009-11-06 06:29:34,248 [NioProcessor-8] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event SESSION_CLOSED to session 25
        Queue : [SESSION_CLOSED, ]
        2009-11-06 06:29:34,248 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 25
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 25
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 25
        2009-11-06 06:29:34,249 [pool-4-thread-32] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Closing session
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Statistics login and connection count decreased due to session close
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Session closed
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 25
        2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 25

        Show
        Nick Padgett added a comment - I turned on DEBUG logging and replicated the issue. You'll notice there is a MESSAGE_RECEIVED event that was fired. I believe that was the QUIT message that I sent that is being ignored. 2009-11-06 06:27:53,219 [pool-4-thread-11] INFO org.apache.ftpserver.command.impl.STOR - File uploaded /803/2009/10/19/7344_ZvIVzV5d_event.wmv 2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 25 2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 25 2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 25 2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a WRITE event for session 25 2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 25 2009-11-06 06:27:53,219 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event WRITE has been fired for session 25 2009-11-06 06:27:53,219 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,219 [NioProcessor-8] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 25 Queue : [MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, ] 2009-11-06 06:27:53,219 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 25 2009-11-06 06:27:53,220 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_RECEIVED has been fired for session 25 2009-11-06 06:27:53,220 [NioProcessor-8] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event MESSAGE_SENT to session 25 Queue : [MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, , MESSAGE_SENT, ] 2009-11-06 06:27:53,220 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status okay; about to open data connection. 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,220 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a MESSAGE_SENT event for session 25 2009-11-06 06:27:53,267 [pool-4-thread-11] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer complete. 2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:27:53,267 [pool-4-thread-11] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event MESSAGE_SENT has been fired for session 25 2009-11-06 06:29:34,248 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 25 2009-11-06 06:29:34,248 [NioProcessor-8] DEBUG org.apache.mina.filter.executor.OrderedThreadPoolExecutor - Adding event SESSION_CLOSED to session 25 Queue : [SESSION_CLOSED, ] 2009-11-06 06:29:34,248 [NioProcessor-8] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 25 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 25 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event for session 25 2009-11-06 06:29:34,249 [pool-4-thread-32] INFO org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Closing session 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Statistics login and connection count decreased due to session close 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.ftpserver.impl.DefaultFtpHandler - Session closed 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 25 2009-11-06 06:29:34,249 [pool-4-thread-32] DEBUG org.apache.mina.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been fired for session 25
        Nick Padgett created issue -

          People

          • Assignee:
            Niklas Gustavsson
            Reporter:
            Nick Padgett
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:

              Development