You are viewing a plain text version of this content. The canonical link for it is here.
Posted to ftpserver-users@mina.apache.org by Sachin Shetty <ss...@egnyte.com> on 2011/12/10 18:20:04 UTC
FOUND THE REAL ISSUE - RE: Control connection closing on idle timeout even when data transfer is going on
I found the real issue here. I was misguided by Filezilla's dual connection
behavior where it always spawns a new connection for a data transfer and
leaved the original listing connection open. It's the listing connection
that times out, but the transfer connection is active and my assumption of
the root cause was wrong.
My real problem is the issue reported in various other cases like:
http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
y-peer,-help-td23269194.html
I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
causing the upload to go on for more than an hour. Filezilla transfers the
whole file and then fails with
Error: Connection timed out
Error: File transfer failed after transferring
2,392,064 bytes in 2551 seconds
FTP Logs:
INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
org.apache.ftpserver.command.impl.STOR - File uploaded
/Private/sshetty/9.doc
INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status
okay; about to open data connection.^M
INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
complete.^M
WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
)
at
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
IoProcessor.java:673)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
ingIoProcessor.java:646)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
ingIoProcessor.java:635)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
ollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
ctPollingIoProcessor.java:1079)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
64)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
at java.lang.Thread.run(Thread.java:619)
ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
)
at
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
IoProcessor.java:673)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
ingIoProcessor.java:646)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
ingIoProcessor.java:635)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
ollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
ctPollingIoProcessor.java:1079)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
64)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
va:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
08)
at java.lang.Thread.run(Thread.java:619)
INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
From: Sachin Shetty [mailto:sshetty@egnyte.com]
Sent: Monday, December 05, 2011 4:04 PM
To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
Subject: RE: Control connection closing on idle timeout even when data
transfer is going on
anybody?
this seems like a valid bug..
From: Sachin Shetty [mailto:sshetty@egnyte.com]
Sent: Sunday, December 04, 2011 1:56 PM
To: 'ftpserver-users@mina.apache.org'
Subject: Control connection closing on idle timeout even when data transfer
is going on
We have configured our ftp servers to set idle timeout to 15 minutes. When
we are transferring huge files where it takes more than 15 minutes, the
control connection is closed by the server, while the data connection
continues as usual.
I am not sure how the idle time out kicks in here, because even though there
is no activity on the control connection, the data connection is active.
Anybody faced same problem?
Thanks
Sachin
RE: FOUND THE REAL ISSUE - RE: Control connection closing on idle timeout even when data transfer is going on
Posted by Sachin Shetty <ss...@egnyte.com>.
So is there a way to inject keepalives probes in an ftp session? I have
tried the linux one below but that did not work
# cat /proc/sys/net/ipv4/tcp_keepalive_time
600
# cat /proc/sys/net/ipv4/tcp_keepalive_intvl
60
# cat /proc/sys/net/ipv4/tcp_keepalive_probes
20
Thanks
Sachin
-----Original Message-----
From: Sachin Shetty [mailto:sshetty@egnyte.com]
Sent: Tuesday, January 10, 2012 10:25 AM
To: 'ftpserver-users@mina.apache.org'
Subject: RE: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
I tried, but for some reason that won't work either. Where exactly do you
think we can configure TCP keepalive to be injected from?
Thanks
Sachin
-----Original Message-----
From: David Latorre [mailto:dvlato@gmail.com]
Sent: Monday, January 09, 2012 10:03 PM
To: ftpserver-users@mina.apache.org
Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
Hello Sachin,
Is it possible in your case to use TCP keepalive probes?
2012/1/9 Sachin Shetty <ss...@egnyte.com>:
> Hi All,
>
> Just wanted to update the findings on this issue. It was basically our
> firewall, and I suspect a good % of these "Control connection dead after
> successful file transfer" are caused by firewall timeouts.
>
> Basically there is no traffic on the control connection while a huge file
is
> being transferred and a firewall looking at the control connection as a
> plain tcp connection would come around and clear the connection (nat
tables)
> assuming it to be idle. Finally when the file transfer is complete and the
> ftp client polls the control connection for "Transfer Complete", it times
> out with "Control connection appears dead"
>
> We fixed it by increasing our ftp service idle connection timeout on the
> firewall, not a robust solution, but works for relatively larger uploads.
It
> still breaks for really large cases.
>
> This behavior is explained here:
> http://www.ncftp.com/ncftpd/doc/misc/ftp_and_firewalls.html: "Problems
> caused by the firewall prematurely timing out a valid FTP session"
>
> Thanks
> Sachin
> -----Original Message-----
> From: David Latorre [mailto:dvlato@gmail.com]
> Sent: Tuesday, December 13, 2011 12:04 AM
> To: ftpserver-users@mina.apache.org
> Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
> timeout even when data transfer is going on
>
> Hello Sachin,
>
>
> It seems this is a bug we should fix. Can you open a JIRA issue and
> provide a test case with it?
>
>
>
> 2011/12/10 Sachin Shetty <ss...@egnyte.com>
>
>> I found the real issue here. I was misguided by Filezilla's dual
> connection
>> behavior where it always spawns a new connection for a data transfer and
>> leaved the original listing connection open. It's the listing connection
>> that times out, but the transfer connection is active and my assumption
of
>> the root cause was wrong.
>>
>>
>>
>> My real problem is the issue reported in various other cases like:
>>
>>
>>
>
http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
>> 0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
>>
>>
>>
>
http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
>> y-peer,-help-td23269194.html
>>
>>
>>
>> I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
>> causing the upload to go on for more than an hour. Filezilla transfers
the
>> whole file and then fails with
>>
>>
>>
>> Error: Connection timed out
>>
>> Error: File transfer failed after
transferring
>> 2,392,064 bytes in 2551 seconds
>>
>>
>>
>>
>>
>> FTP Logs:
>>
>>
>>
>> INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.command.impl.STOR - File uploaded
>> /Private/sshetty/9.doc
>>
>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File
status
>> okay; about to open data connection.^M
>>
>>
>>
>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
>> complete.^M
>>
>>
>>
>> WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
>> )
>>
>> at
>>
>>
>
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>> IoProcessor.java:673)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:646)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:635)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>> ollingIoProcessor.java:67)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>> ctPollingIoProcessor.java:1079)
>>
>> at
>>
>>
>
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>> 64)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:886)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 08)
>>
>> at java.lang.Thread.run(Thread.java:619)
>>
>> ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
>> )
>>
>> at
>>
>>
>
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>> IoProcessor.java:673)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:646)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:635)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>> ollingIoProcessor.java:67)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>> ctPollingIoProcessor.java:1079)
>>
>> at
>>
>>
>
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>> 64)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:886)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 08)
>>
>> at java.lang.Thread.run(Thread.java:619)
>>
>> INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>> Sent: Monday, December 05, 2011 4:04 PM
>> To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
>> Subject: RE: Control connection closing on idle timeout even when data
>> transfer is going on
>>
>>
>>
>> anybody?
>>
>>
>>
>> this seems like a valid bug..
>>
>>
>>
>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>> Sent: Sunday, December 04, 2011 1:56 PM
>> To: 'ftpserver-users@mina.apache.org'
>> Subject: Control connection closing on idle timeout even when data
> transfer
>> is going on
>>
>>
>>
>> We have configured our ftp servers to set idle timeout to 15 minutes.
When
>> we are transferring huge files where it takes more than 15 minutes, the
>> control connection is closed by the server, while the data connection
>> continues as usual.
>>
>>
>>
>> I am not sure how the idle time out kicks in here, because even though
>> there
>> is no activity on the control connection, the data connection is active.
>>
>>
>>
>> Anybody faced same problem?
>>
>>
>>
>> Thanks
>>
>> Sachin
>>
>>
>
Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
Posted by sebb <se...@gmail.com>.
On 10 January 2012 04:55, Sachin Shetty <ss...@egnyte.com> wrote:
> I tried, but for some reason that won't work either. Where exactly do you
> think we can configure TCP keepalive to be injected from?
Sorry, I don't know about to configure TCP keepalive.
The way this is currently done in Commons Net is to (optionally) send
occasional NOOPs on the control connection,
Unfortunately many FTP servers don't support concurrent control and
data handling, so any unanswered NOOPs have to be collected before
getting the transfer done reply on the control connection.
If TCP keep-alive could be programmatically (re)configured on the
control connection, then it would be a better solution.
This assumes that the router regards keep-alives as being traffic.
That I don't know either ...
> Thanks
> Sachin
>
> -----Original Message-----
> From: David Latorre [mailto:dvlato@gmail.com]
> Sent: Monday, January 09, 2012 10:03 PM
> To: ftpserver-users@mina.apache.org
> Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
> timeout even when data transfer is going on
>
> Hello Sachin,
>
> Is it possible in your case to use TCP keepalive probes?
>
> 2012/1/9 Sachin Shetty <ss...@egnyte.com>:
>> Hi All,
>>
>> Just wanted to update the findings on this issue. It was basically our
>> firewall, and I suspect a good % of these "Control connection dead after
>> successful file transfer" are caused by firewall timeouts.
>>
>> Basically there is no traffic on the control connection while a huge file
> is
>> being transferred and a firewall looking at the control connection as a
>> plain tcp connection would come around and clear the connection (nat
> tables)
>> assuming it to be idle. Finally when the file transfer is complete and the
>> ftp client polls the control connection for "Transfer Complete", it times
>> out with "Control connection appears dead"
>>
>> We fixed it by increasing our ftp service idle connection timeout on the
>> firewall, not a robust solution, but works for relatively larger uploads.
> It
>> still breaks for really large cases.
>>
>> This behavior is explained here:
>> http://www.ncftp.com/ncftpd/doc/misc/ftp_and_firewalls.html: "Problems
>> caused by the firewall prematurely timing out a valid FTP session"
>>
>> Thanks
>> Sachin
>> -----Original Message-----
>> From: David Latorre [mailto:dvlato@gmail.com]
>> Sent: Tuesday, December 13, 2011 12:04 AM
>> To: ftpserver-users@mina.apache.org
>> Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
>> timeout even when data transfer is going on
>>
>> Hello Sachin,
>>
>>
>> It seems this is a bug we should fix. Can you open a JIRA issue and
>> provide a test case with it?
>>
>>
>>
>> 2011/12/10 Sachin Shetty <ss...@egnyte.com>
>>
>>> I found the real issue here. I was misguided by Filezilla's dual
>> connection
>>> behavior where it always spawns a new connection for a data transfer and
>>> leaved the original listing connection open. It's the listing connection
>>> that times out, but the transfer connection is active and my assumption
> of
>>> the root cause was wrong.
>>>
>>>
>>>
>>> My real problem is the issue reported in various other cases like:
>>>
>>>
>>>
>>
> http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
>>> 0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
>>>
>>>
>>>
>>
> http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
>>> y-peer,-help-td23269194.html
>>>
>>>
>>>
>>> I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
>>> causing the upload to go on for more than an hour. Filezilla transfers
> the
>>> whole file and then fails with
>>>
>>>
>>>
>>> Error: Connection timed out
>>>
>>> Error: File transfer failed after
> transferring
>>> 2,392,064 bytes in 2551 seconds
>>>
>>>
>>>
>>>
>>>
>>> FTP Logs:
>>>
>>>
>>>
>>> INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
>>> org.apache.ftpserver.command.impl.STOR - File uploaded
>>> /Private/sshetty/9.doc
>>>
>>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File
> status
>>> okay; about to open data connection.^M
>>>
>>>
>>>
>>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
>>> complete.^M
>>>
>>>
>>>
>>> WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
>>> )
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>>> IoProcessor.java:673)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>>> ingIoProcessor.java:646)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>>> ingIoProcessor.java:635)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>>> ollingIoProcessor.java:67)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>>> ctPollingIoProcessor.java:1079)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>>> 64)
>>>
>>> at
>>>
>>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>>> va:886)
>>>
>>> at
>>>
>>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>>> 08)
>>>
>>> at java.lang.Thread.run(Thread.java:619)
>>>
>>> ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>>> org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
>>> )
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>>> IoProcessor.java:673)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>>> ingIoProcessor.java:646)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>>> ingIoProcessor.java:635)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>>> ollingIoProcessor.java:67)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>>> ctPollingIoProcessor.java:1079)
>>>
>>> at
>>>
>>>
>>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>>> 64)
>>>
>>> at
>>>
>>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>>> va:886)
>>>
>>> at
>>>
>>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>>> 08)
>>>
>>> at java.lang.Thread.run(Thread.java:619)
>>>
>>> INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>>> Sent: Monday, December 05, 2011 4:04 PM
>>> To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
>>> Subject: RE: Control connection closing on idle timeout even when data
>>> transfer is going on
>>>
>>>
>>>
>>> anybody?
>>>
>>>
>>>
>>> this seems like a valid bug..
>>>
>>>
>>>
>>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>>> Sent: Sunday, December 04, 2011 1:56 PM
>>> To: 'ftpserver-users@mina.apache.org'
>>> Subject: Control connection closing on idle timeout even when data
>> transfer
>>> is going on
>>>
>>>
>>>
>>> We have configured our ftp servers to set idle timeout to 15 minutes.
> When
>>> we are transferring huge files where it takes more than 15 minutes, the
>>> control connection is closed by the server, while the data connection
>>> continues as usual.
>>>
>>>
>>>
>>> I am not sure how the idle time out kicks in here, because even though
>>> there
>>> is no activity on the control connection, the data connection is active.
>>>
>>>
>>>
>>> Anybody faced same problem?
>>>
>>>
>>>
>>> Thanks
>>>
>>> Sachin
>>>
>>>
>>
>
RE: FOUND THE REAL ISSUE - RE: Control connection closing on idle timeout even when data transfer is going on
Posted by Sachin Shetty <ss...@egnyte.com>.
I tried, but for some reason that won't work either. Where exactly do you
think we can configure TCP keepalive to be injected from?
Thanks
Sachin
-----Original Message-----
From: David Latorre [mailto:dvlato@gmail.com]
Sent: Monday, January 09, 2012 10:03 PM
To: ftpserver-users@mina.apache.org
Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
Hello Sachin,
Is it possible in your case to use TCP keepalive probes?
2012/1/9 Sachin Shetty <ss...@egnyte.com>:
> Hi All,
>
> Just wanted to update the findings on this issue. It was basically our
> firewall, and I suspect a good % of these "Control connection dead after
> successful file transfer" are caused by firewall timeouts.
>
> Basically there is no traffic on the control connection while a huge file
is
> being transferred and a firewall looking at the control connection as a
> plain tcp connection would come around and clear the connection (nat
tables)
> assuming it to be idle. Finally when the file transfer is complete and the
> ftp client polls the control connection for "Transfer Complete", it times
> out with "Control connection appears dead"
>
> We fixed it by increasing our ftp service idle connection timeout on the
> firewall, not a robust solution, but works for relatively larger uploads.
It
> still breaks for really large cases.
>
> This behavior is explained here:
> http://www.ncftp.com/ncftpd/doc/misc/ftp_and_firewalls.html: "Problems
> caused by the firewall prematurely timing out a valid FTP session"
>
> Thanks
> Sachin
> -----Original Message-----
> From: David Latorre [mailto:dvlato@gmail.com]
> Sent: Tuesday, December 13, 2011 12:04 AM
> To: ftpserver-users@mina.apache.org
> Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
> timeout even when data transfer is going on
>
> Hello Sachin,
>
>
> It seems this is a bug we should fix. Can you open a JIRA issue and
> provide a test case with it?
>
>
>
> 2011/12/10 Sachin Shetty <ss...@egnyte.com>
>
>> I found the real issue here. I was misguided by Filezilla's dual
> connection
>> behavior where it always spawns a new connection for a data transfer and
>> leaved the original listing connection open. It's the listing connection
>> that times out, but the transfer connection is active and my assumption
of
>> the root cause was wrong.
>>
>>
>>
>> My real problem is the issue reported in various other cases like:
>>
>>
>>
>
http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
>> 0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
>>
>>
>>
>
http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
>> y-peer,-help-td23269194.html
>>
>>
>>
>> I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
>> causing the upload to go on for more than an hour. Filezilla transfers
the
>> whole file and then fails with
>>
>>
>>
>> Error: Connection timed out
>>
>> Error: File transfer failed after
transferring
>> 2,392,064 bytes in 2551 seconds
>>
>>
>>
>>
>>
>> FTP Logs:
>>
>>
>>
>> INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.command.impl.STOR - File uploaded
>> /Private/sshetty/9.doc
>>
>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File
status
>> okay; about to open data connection.^M
>>
>>
>>
>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
>> complete.^M
>>
>>
>>
>> WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
>> )
>>
>> at
>>
>>
>
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>> IoProcessor.java:673)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:646)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:635)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>> ollingIoProcessor.java:67)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>> ctPollingIoProcessor.java:1079)
>>
>> at
>>
>>
>
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>> 64)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:886)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 08)
>>
>> at java.lang.Thread.run(Thread.java:619)
>>
>> ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
>> )
>>
>> at
>>
>>
>
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>> IoProcessor.java:673)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:646)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:635)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>> ollingIoProcessor.java:67)
>>
>> at
>>
>>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>> ctPollingIoProcessor.java:1079)
>>
>> at
>>
>>
>
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>> 64)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:886)
>>
>> at
>>
>>
>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 08)
>>
>> at java.lang.Thread.run(Thread.java:619)
>>
>> INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>> Sent: Monday, December 05, 2011 4:04 PM
>> To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
>> Subject: RE: Control connection closing on idle timeout even when data
>> transfer is going on
>>
>>
>>
>> anybody?
>>
>>
>>
>> this seems like a valid bug..
>>
>>
>>
>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>> Sent: Sunday, December 04, 2011 1:56 PM
>> To: 'ftpserver-users@mina.apache.org'
>> Subject: Control connection closing on idle timeout even when data
> transfer
>> is going on
>>
>>
>>
>> We have configured our ftp servers to set idle timeout to 15 minutes.
When
>> we are transferring huge files where it takes more than 15 minutes, the
>> control connection is closed by the server, while the data connection
>> continues as usual.
>>
>>
>>
>> I am not sure how the idle time out kicks in here, because even though
>> there
>> is no activity on the control connection, the data connection is active.
>>
>>
>>
>> Anybody faced same problem?
>>
>>
>>
>> Thanks
>>
>> Sachin
>>
>>
>
Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
Posted by David Latorre <dv...@gmail.com>.
Hello Sachin,
Is it possible in your case to use TCP keepalive probes?
2012/1/9 Sachin Shetty <ss...@egnyte.com>:
> Hi All,
>
> Just wanted to update the findings on this issue. It was basically our
> firewall, and I suspect a good % of these "Control connection dead after
> successful file transfer" are caused by firewall timeouts.
>
> Basically there is no traffic on the control connection while a huge file is
> being transferred and a firewall looking at the control connection as a
> plain tcp connection would come around and clear the connection (nat tables)
> assuming it to be idle. Finally when the file transfer is complete and the
> ftp client polls the control connection for "Transfer Complete", it times
> out with "Control connection appears dead"
>
> We fixed it by increasing our ftp service idle connection timeout on the
> firewall, not a robust solution, but works for relatively larger uploads. It
> still breaks for really large cases.
>
> This behavior is explained here:
> http://www.ncftp.com/ncftpd/doc/misc/ftp_and_firewalls.html: "Problems
> caused by the firewall prematurely timing out a valid FTP session"
>
> Thanks
> Sachin
> -----Original Message-----
> From: David Latorre [mailto:dvlato@gmail.com]
> Sent: Tuesday, December 13, 2011 12:04 AM
> To: ftpserver-users@mina.apache.org
> Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
> timeout even when data transfer is going on
>
> Hello Sachin,
>
>
> It seems this is a bug we should fix. Can you open a JIRA issue and
> provide a test case with it?
>
>
>
> 2011/12/10 Sachin Shetty <ss...@egnyte.com>
>
>> I found the real issue here. I was misguided by Filezilla's dual
> connection
>> behavior where it always spawns a new connection for a data transfer and
>> leaved the original listing connection open. It's the listing connection
>> that times out, but the transfer connection is active and my assumption of
>> the root cause was wrong.
>>
>>
>>
>> My real problem is the issue reported in various other cases like:
>>
>>
>>
> http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
>> 0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
>>
>>
>>
> http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
>> y-peer,-help-td23269194.html
>>
>>
>>
>> I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
>> causing the upload to go on for more than an hour. Filezilla transfers the
>> whole file and then fails with
>>
>>
>>
>> Error: Connection timed out
>>
>> Error: File transfer failed after transferring
>> 2,392,064 bytes in 2551 seconds
>>
>>
>>
>>
>>
>> FTP Logs:
>>
>>
>>
>> INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.command.impl.STOR - File uploaded
>> /Private/sshetty/9.doc
>>
>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status
>> okay; about to open data connection.^M
>>
>>
>>
>> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
>> complete.^M
>>
>>
>>
>> WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
>> )
>>
>> at
>>
>>
> org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>> IoProcessor.java:673)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:646)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:635)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>> ollingIoProcessor.java:67)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>> ctPollingIoProcessor.java:1079)
>>
>> at
>>
>>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>> 64)
>>
>> at
>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:886)
>>
>> at
>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 08)
>>
>> at java.lang.Thread.run(Thread.java:619)
>>
>> ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
>> )
>>
>> at
>>
>>
> org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
>> IoProcessor.java:673)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:646)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
>> ingIoProcessor.java:635)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
>> ollingIoProcessor.java:67)
>>
>> at
>>
>>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
>> ctPollingIoProcessor.java:1079)
>>
>> at
>>
>>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
>> 64)
>>
>> at
>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
>> va:886)
>>
>> at
>>
>>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
>> 08)
>>
>> at java.lang.Thread.run(Thread.java:619)
>>
>> INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
>> org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>> Sent: Monday, December 05, 2011 4:04 PM
>> To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
>> Subject: RE: Control connection closing on idle timeout even when data
>> transfer is going on
>>
>>
>>
>> anybody?
>>
>>
>>
>> this seems like a valid bug..
>>
>>
>>
>> From: Sachin Shetty [mailto:sshetty@egnyte.com]
>> Sent: Sunday, December 04, 2011 1:56 PM
>> To: 'ftpserver-users@mina.apache.org'
>> Subject: Control connection closing on idle timeout even when data
> transfer
>> is going on
>>
>>
>>
>> We have configured our ftp servers to set idle timeout to 15 minutes. When
>> we are transferring huge files where it takes more than 15 minutes, the
>> control connection is closed by the server, while the data connection
>> continues as usual.
>>
>>
>>
>> I am not sure how the idle time out kicks in here, because even though
>> there
>> is no activity on the control connection, the data connection is active.
>>
>>
>>
>> Anybody faced same problem?
>>
>>
>>
>> Thanks
>>
>> Sachin
>>
>>
>
RE: FOUND THE REAL ISSUE - RE: Control connection closing on idle timeout even when data transfer is going on
Posted by Sachin Shetty <ss...@egnyte.com>.
Hi All,
Just wanted to update the findings on this issue. It was basically our
firewall, and I suspect a good % of these "Control connection dead after
successful file transfer" are caused by firewall timeouts.
Basically there is no traffic on the control connection while a huge file is
being transferred and a firewall looking at the control connection as a
plain tcp connection would come around and clear the connection (nat tables)
assuming it to be idle. Finally when the file transfer is complete and the
ftp client polls the control connection for "Transfer Complete", it times
out with "Control connection appears dead"
We fixed it by increasing our ftp service idle connection timeout on the
firewall, not a robust solution, but works for relatively larger uploads. It
still breaks for really large cases.
This behavior is explained here:
http://www.ncftp.com/ncftpd/doc/misc/ftp_and_firewalls.html: "Problems
caused by the firewall prematurely timing out a valid FTP session"
Thanks
Sachin
-----Original Message-----
From: David Latorre [mailto:dvlato@gmail.com]
Sent: Tuesday, December 13, 2011 12:04 AM
To: ftpserver-users@mina.apache.org
Subject: Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
Hello Sachin,
It seems this is a bug we should fix. Can you open a JIRA issue and
provide a test case with it?
2011/12/10 Sachin Shetty <ss...@egnyte.com>
> I found the real issue here. I was misguided by Filezilla's dual
connection
> behavior where it always spawns a new connection for a data transfer and
> leaved the original listing connection open. It's the listing connection
> that times out, but the transfer connection is active and my assumption of
> the root cause was wrong.
>
>
>
> My real problem is the issue reported in various other cases like:
>
>
>
http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
> 0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
>
>
>
http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
> y-peer,-help-td23269194.html
>
>
>
> I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
> causing the upload to go on for more than an hour. Filezilla transfers the
> whole file and then fails with
>
>
>
> Error: Connection timed out
>
> Error: File transfer failed after transferring
> 2,392,064 bytes in 2551 seconds
>
>
>
>
>
> FTP Logs:
>
>
>
> INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.command.impl.STOR - File uploaded
> /Private/sshetty/9.doc
>
> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status
> okay; about to open data connection.^M
>
>
>
> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
> complete.^M
>
>
>
> WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
> )
>
> at
>
>
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
> IoProcessor.java:673)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:646)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:635)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
> ollingIoProcessor.java:67)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
> ctPollingIoProcessor.java:1079)
>
> at
>
>
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
> 64)
>
> at
>
>
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
> va:886)
>
> at
>
>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
> 08)
>
> at java.lang.Thread.run(Thread.java:619)
>
> ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
> )
>
> at
>
>
org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
> IoProcessor.java:673)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:646)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:635)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
> ollingIoProcessor.java:67)
>
> at
>
>
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
> ctPollingIoProcessor.java:1079)
>
> at
>
>
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
> 64)
>
> at
>
>
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
> va:886)
>
> at
>
>
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
> 08)
>
> at java.lang.Thread.run(Thread.java:619)
>
> INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
>
>
>
>
>
>
>
>
>
>
>
> From: Sachin Shetty [mailto:sshetty@egnyte.com]
> Sent: Monday, December 05, 2011 4:04 PM
> To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
> Subject: RE: Control connection closing on idle timeout even when data
> transfer is going on
>
>
>
> anybody?
>
>
>
> this seems like a valid bug..
>
>
>
> From: Sachin Shetty [mailto:sshetty@egnyte.com]
> Sent: Sunday, December 04, 2011 1:56 PM
> To: 'ftpserver-users@mina.apache.org'
> Subject: Control connection closing on idle timeout even when data
transfer
> is going on
>
>
>
> We have configured our ftp servers to set idle timeout to 15 minutes. When
> we are transferring huge files where it takes more than 15 minutes, the
> control connection is closed by the server, while the data connection
> continues as usual.
>
>
>
> I am not sure how the idle time out kicks in here, because even though
> there
> is no activity on the control connection, the data connection is active.
>
>
>
> Anybody faced same problem?
>
>
>
> Thanks
>
> Sachin
>
>
Re: FOUND THE REAL ISSUE - RE: Control connection closing on idle
timeout even when data transfer is going on
Posted by David Latorre <dv...@gmail.com>.
Hello Sachin,
It seems this is a bug we should fix. Can you open a JIRA issue and
provide a test case with it?
2011/12/10 Sachin Shetty <ss...@egnyte.com>
> I found the real issue here. I was misguided by Filezilla's dual connection
> behavior where it always spawns a new connection for a data transfer and
> leaved the original listing connection open. It's the listing connection
> that times out, but the transfer connection is active and my assumption of
> the root cause was wrong.
>
>
>
> My real problem is the issue reported in various other cases like:
>
>
> http://mail-archives.apache.org/mod_mbox/mina-dev/201102.mbox/%3C987378340.1
> 0467.1297432017841.JavaMail.tomcat@hel.zones.apache.org%3E
>
>
> http://old.nabble.com/-jira--Created:-%28FTPSERVER-295%29-Connection-reset-b
> y-peer,-help-td23269194.html
>
>
>
> I can reproduce this in filezilla, by setting a slow upload speed 1kbps,
> causing the upload to go on for more than an hour. Filezilla transfers the
> whole file and then fails with
>
>
>
> Error: Connection timed out
>
> Error: File transfer failed after transferring
> 2,392,064 bytes in 2551 seconds
>
>
>
>
>
> FTP Logs:
>
>
>
> INFO 2011-12-10 15:48:54,134 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.command.impl.STOR - File uploaded
> /Private/sshetty/9.doc
>
> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status
> okay; about to open data connection.^M
>
>
>
> INFO 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 226 Transfer
> complete.^M
>
>
>
> WARN 2011-12-10 15:48:54,138 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - 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:214
> )
>
> at
>
> org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
> IoProcessor.java:673)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:646)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:635)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
> ollingIoProcessor.java:67)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
> ctPollingIoProcessor.java:1079)
>
> at
>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
> 64)
>
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
> va:886)
>
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
> 08)
>
> at java.lang.Thread.run(Thread.java:619)
>
> ERROR 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.impl.DefaultFtpHandler - 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:214
> )
>
> at
>
> org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPolling
> IoProcessor.java:673)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:646)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPoll
> ingIoProcessor.java:635)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractP
> ollingIoProcessor.java:67)
>
> at
>
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(Abstra
> ctPollingIoProcessor.java:1079)
>
> at
>
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:
> 64)
>
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.ja
> va:886)
>
> at
>
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:9
> 08)
>
> at java.lang.Thread.run(Thread.java:619)
>
> INFO 2011-12-10 15:48:54,139 pool-3-thread-54 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - CLOSED
>
>
>
>
>
>
>
>
>
>
>
> From: Sachin Shetty [mailto:sshetty@egnyte.com]
> Sent: Monday, December 05, 2011 4:04 PM
> To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org'
> Subject: RE: Control connection closing on idle timeout even when data
> transfer is going on
>
>
>
> anybody?
>
>
>
> this seems like a valid bug..
>
>
>
> From: Sachin Shetty [mailto:sshetty@egnyte.com]
> Sent: Sunday, December 04, 2011 1:56 PM
> To: 'ftpserver-users@mina.apache.org'
> Subject: Control connection closing on idle timeout even when data transfer
> is going on
>
>
>
> We have configured our ftp servers to set idle timeout to 15 minutes. When
> we are transferring huge files where it takes more than 15 minutes, the
> control connection is closed by the server, while the data connection
> continues as usual.
>
>
>
> I am not sure how the idle time out kicks in here, because even though
> there
> is no activity on the control connection, the data connection is active.
>
>
>
> Anybody faced same problem?
>
>
>
> Thanks
>
> Sachin
>
>