Here is some more information, it seems exactly after an hour, there is some
SSL handshake and cipher re-negotiation which fails with this message. The
State 1 is the cs_HANDSHAKE in
http://www.docjar.com/html/api/sun/security/ssl/SSLSocketImpl.java.html.
DEBUG 2012-09-17 14:27:43,148 pool-6-thread-21 D- U- S-
org.apache.ftpserver.command.impl.STOR - Exception getting the input data
stream
javax.net.ssl.SSLException: illegal change cipher spec msg, state = 1
at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1611)
....
-----Original Message-----
From: Sachin Shetty [mailto:[email protected]]
Sent: Wednesday, September 19, 2012 4:48 PM
To: 'Sachin Shetty'; '[email protected]'
Subject: RE: GnuTLS internal error in Filezilla
It seems it is happening exactly an hour after the upload begins. Any
timeouts that could be kicking in. The connections are not idle.
-----Original Message-----
From: Sachin Shetty [mailto:[email protected]]
Sent: Monday, September 17, 2012 8:14 PM
To: 'Sachin Shetty'; '[email protected]'
Subject: RE: GnuTLS internal error in Filezilla
I enabled debug and found this to be the problem.
INFO 2012-09-17 14:27:43,030 pool-6-thread-18 D- U- S-
org.apache.ftpserver.listener.nio.FtpLoggingFilter - RECEIVED: STOR
source_2364.txt
DEBUG 2012-09-17 14:27:43,148 pool-6-thread-21 D- U- S-
org.apache.ftpserver.command.impl.STOR - Exception getting the input data
stream
javax.net.ssl.SSLException: illegal change cipher spec msg, state = 1
at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1611)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1569)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:940
)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocket
Impl.java:1112)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java
:1139)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java
:1123)
at
org.apache.ftpserver.impl.IODataConnectionFactory.createDataSocket(IODataCon
nectionFactory.java:391)
at
org.apache.ftpserver.impl.IODataConnectionFactory.openConnection(IODataConne
ctionFactory.java:259)
at org.apache.ftpserver.command.impl.STOR.execute(STOR.java:133)
at
org.apache.ftpserver.impl.DefaultFtpHandler.messageReceived(DefaultFtpHandle
r.java:211)
at
org.apache.ftpserver.listener.nio.FtpHandlerAdapter.messageReceived(FtpHandl
erAdapter.java:62)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageRece
ived(DefaultIoFilterChain.java:716)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.ftpserver.listener.nio.FtpLoggingFilter.messageReceived(FtpLoggin
gFilter.java:85)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at
org.apache.mina.filter.logging.MdcInjectionFilter.filter(MdcInjectionFilter.
java:136)
at
org.apache.mina.filter.util.CommonEventFilter.messageReceived(CommonEventFil
ter.java:70)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutputImpl.f
lush(ProtocolCodecFilter.java:427)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCod
ecFilter.java:245)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(Ord
eredThreadPoolExecutor.java:780)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(Or
deredThreadPoolExecutor.java:772)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(Ordered
ThreadPoolExecutor.java:714)
at java.lang.Thread.run(Thread.java:619)
DEBUG 2012-09-17 14:27:43,148 pool-6-thread-21 D- U- S-
org.apache.ftpserver.command.impl.STOR - Exception getting the input data
stream
javax.net.ssl.SSLException: illegal change cipher spec msg, state = 1
at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:190)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1611)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.fatal(SSLSocketImpl.java:1569)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:940
)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocket
Impl.java:1112)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java
:1139)
at
com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java
:1123)
at
org.apache.ftpserver.impl.IODataConnectionFactory.createDataSocket(IODataCon
nectionFactory.java:391)
at
org.apache.ftpserver.impl.IODataConnectionFactory.openConnection(IODataConne
ctionFactory.java:259)
at org.apache.ftpserver.command.impl.STOR.execute(STOR.java:133)
at
org.apache.ftpserver.impl.DefaultFtpHandler.messageReceived(DefaultFtpHandle
r.java:211)
at
org.apache.ftpserver.listener.nio.FtpHandlerAdapter.messageReceived(FtpHandl
erAdapter.java:62)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageRece
ived(DefaultIoFilterChain.java:716)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.ftpserver.listener.nio.FtpLoggingFilter.messageReceived(FtpLoggin
gFilter.java:85)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at
org.apache.mina.filter.logging.MdcInjectionFilter.filter(MdcInjectionFilter.
java:136)
at
org.apache.mina.filter.util.CommonEventFilter.messageReceived(CommonEventFil
ter.java:70)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutputImpl.f
lush(ProtocolCodecFilter.java:427)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCod
ecFilter.java:245)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceive
d(DefaultIoFilterChain.java:434)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoF
ilterChain.java:46)
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageRec
eived(DefaultIoFilterChain.java:796)
at
org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(Ord
eredThreadPoolExecutor.java:780)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(Or
deredThreadPoolExecutor.java:772)
at
org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(Ordered
ThreadPoolExecutor.java:714)
at java.lang.Thread.run(Thread.java:619)
-----Original Message-----
From: Sachin Shetty [mailto:[email protected]]
Sent: Monday, September 17, 2012 4:27 PM
To: '[email protected]'
Subject: RE: GnuTLS internal error in Filezilla
Here is the client log, it works fine for almost an hour before it hits the
"Error: GnuTLS error -59: GnuTLS internal error." and then all of them fail
Response: 227 Entering Passive Mode (173,245,120,49,78,44)
Command: STOR source_2561.txt
Response: 150 File status okay; about to open data connection.
Response: 150 File status okay; about to open data connection.
Response: 226 Transfer complete.
Command: MFMT 20111108075428 source_2560.txt
Response: 226 Transfer complete.
Command: MFMT 20111108075402 source_256.txt
Response: 150 File status okay; about to open data connection.
Response: 213 ModifyTime=20111108075428; source_2560.txt
Status: File transfer successful, transferred 16 bytes
in 5 seconds
Status: Starting upload of
C:\sachin\temp\5k_folder\source_2562.txt
Command: PASV
Response: 213 ModifyTime=20111108075402; source_256.txt
Status: File transfer successful, transferred 16 bytes
in 5 seconds
Status: Starting upload of
C:\sachin\temp\5k_folder\source_2563.txt
Command: PASV
Response: 227 Entering Passive Mode (173,245,120,49,78,32)
Command: STOR source_2562.txt
Response: 227 Entering Passive Mode (173,245,120,49,78,42)
Command: STOR source_2563.txt
Response: 226 Transfer complete.
Command: MFMT 20111108075428 source_2561.txt
Response: 213 ModifyTime=20111108075428; source_2561.txt
Status: File transfer successful, transferred 16 bytes
in 4 seconds
Status: Starting upload of
C:\sachin\temp\5k_folder\source_2564.txt
Command: PASV
Response: 227 Entering Passive Mode (173,245,120,49,78,50)
Command: STOR source_2564.txt
Response: 150 File status okay; about to open data connection.
Response: 150 File status okay; about to open data connection.
Error: GnuTLS error -59: GnuTLS internal error.
Error: GnuTLS error -59: GnuTLS internal error.
Response: 425 Can't open data connection.
Error: File transfer failed
Status: Starting upload of
C:\sachin\temp\5k_folder\source_2562.txt
Status: Retrieving directory listing...
Command: PASV
Response: 425 Can't open data connection.
Error: File transfer failed
Status: Starting upload of
C:\sachin\temp\5k_folder\source_2563.txt
Status: Retrieving directory listing...
Response: 227 Entering Passive Mode (173,245,120,49,78,32)
Command: MLSD
Response: 150 File status okay; about to open data connection.
Response: 150 File status okay; about to open data connection.
Error: GnuTLS error -59: GnuTLS internal error.
Error: Transfer connection interrupted: ECONNABORTED
- Connection aborted
Error: GnuTLS error -59: GnuTLS internal error.
Response: 425 Can't open data connection.
Command: SIZE source_2562.txt
Error: File transfer failed
Status: Starting upload of
C:\sachin\temp\5k_folder\source_2563.txt
Status: Retrieving directory listing...
-----Original Message-----
From: John Hartnup [mailto:[email protected]]
Sent: Monday, September 17, 2012 4:05 PM
To: [email protected]
Subject: Re: GnuTLS internal error in Filezilla
Get either client or server logs that show the PORT/PASV addresses. See if
there's any pattern in the working/broken port ranges.
One fairly common issue is that the firewall has a range of ports open,
that's smaller than the range the FTP client/server will try to use. So
everything works fine, until eventually a port outside the range is
requested.
On 17 September 2012 11:27, Sachin Shetty <[email protected]> wrote:
> Thanks for the response.
>
> It only stops working intermittently and interesting this is the
immediate
> error in the FtpLoggingFilter
>
> INFO 2012-09-16 11:32:56,015 pool-6-thread-19630 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 150 File status
> okay; about to open data connection.^M
> INFO 2012-09-16 11:32:56,015 pool-6-thread-19630 D- U- S-
> org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 425 Can't open
> data connection.^M
>
> Something happens in between the two log lines.
>
>
> -----Original Message-----
> From: John Hartnup [mailto:[email protected]]
> Sent: Monday, September 17, 2012 3:42 PM
> To: [email protected]
> Subject: Re: GnuTLS internal error in Filezilla
>
> It looks to me like a firewall blocking the data connection.
>
> Some firewalls deal with FTP by snooping on the control connection, and
> opening the appropriate ports when it sees a PORT or PASV
command/response.
> If the control connection is secured with SSL, the firewall can't see
> PORT/PASV, so it doesn't open the ports.
>
> This IETF draft goes into some detail (or skip to the appendix to find out
> how to fix it).
>
> On 17 September 2012 10:55, Sachin Shetty <[email protected]> wrote:
>
> > Hi,
> >
> >
> >
> > Any inputs on 425 Can't open data connection is really appreciated. It's
> > causing lot of problems and we aren't sure what we else we can look for.
> >
> >
> >
> > Thanks
> >
> > Sachin
> >
> >
> >
> > From: Sachin Shetty [mailto:[email protected]]
> > Sent: Friday, September 07, 2012 1:35 PM
> > To: '[email protected]'
> > Subject: GnuTLS internal error in Filezilla
> >
> >
> >
> > Hi,
> >
> > We have Apache FTP Server running in production for a while now, it's
> been
> > mostly rock solid, but we see the following issue pretty often in
> > production.
> >
> > Response: 150 File status okay; about to open data connection.
> > Error: GnuTLS error -59: GnuTLS internal error.
> > Response: 425 Can't open data connection.
> > Error: File transfer failed
> >
> > On the apache ftp server logs, all we see is:
> >
> > INFO 2012-09-05 05:04:16,087 pool-3-thread-350 D- U- S-
> > org.apache.ftpserver.listener.nio.FtpLoggingFilter - SENT: 425 Can't
open
> > data connection.^M
> >
> > Could it be one of the following:
> >
> > 1. All passive ports exhausted
> >
> > 2. We have a slightly different configuration, where we start 2
> listeners,
> > one with implicit SSL and one without. Both have the same passive port
> > range.
> >
> > Thanks
> > Sachin
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
> >
>
>
> --
> "There is no way to peace; peace is the way"
>
>
--
"There is no way to peace; peace is the way"
