mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Nick Padgett (JIRA)" <j...@apache.org>
Subject [jira] Commented: (FTPSERVER-339) Commands Dropped After Successful File Upload
Date Fri, 06 Nov 2009 12:54:32 GMT

    [ 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.


Mime
View raw message