[ 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