[
https://issues.apache.org/jira/browse/FTPSERVER-339?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12994765#comment-12994765
]
Aniceto Pérez y Madrid commented on FTPSERVER-339:
--------------------------------------------------
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
> 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
