[jira] Created: (FTPSERVER-339) Commands Dropped After Successful File Upload

Commands Dropped After Successful File Upload
---------------------------------------------

                 Key: FTPSERVER-339
                 URL: https://issues.apache.org/jira/browse/FTPSERVER-339
             Project: FtpServer
          Issue Type: Bug
    Affects Versions: 1.0.3
            Reporter: Nick Padgett
            Priority: Critical


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


--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.

    [ https://issues.apache.org/jira/browse/FTPSERVER-339?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12774282#action_12774282 ]

Nick Padgett commented on FTPSERVER-339:
----------------------------------------

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

> Commands Dropped After Successful File Upload
> ---------------------------------------------
>
>                 Key: FTPSERVER-339
>                 URL: https://issues.apache.org/jira/browse/FTPSERVER-339
>             Project: FtpServer
>          Issue Type: Bug
>    Affects Versions: 1.0.3
>            Reporter: Nick Padgett
>            Priority: Critical
>
> 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

--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.

    [ https://issues.apache.org/jira/browse/FTPSERVER-339?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12774284#action_12774284 ]

Nick Padgett commented on FTPSERVER-339:
----------------------------------------

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

> Commands Dropped After Successful File Upload
> ---------------------------------------------
>
>                 Key: FTPSERVER-339
>                 URL: https://issues.apache.org/jira/browse/FTPSERVER-339
>             Project: FtpServer
>          Issue Type: Bug
>    Affects Versions: 1.0.3
>            Reporter: Nick Padgett
>            Priority: Critical
>
> 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

--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.