mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Aniceto Pérez y Madrid (JIRA) <j...@apache.org>
Subject [jira] Commented: (FTPSERVER-339) Commands Dropped After Successful File Upload
Date Mon, 14 Feb 2011 10:37:57 GMT

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

Aniceto Pérez y Madrid commented on FTPSERVER-339:
--------------------------------------------------

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


> 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
>            Assignee: Niklas Gustavsson
>            Priority: Critical
>             Fix For: 1.0.6, 1.1.0
>
>
> 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.
-
For more information on JIRA, see: http://www.atlassian.com/software/jira

       

Mime
View raw message