I could reproduce the problem with a plain vanilla Apache ftp server (i.e. out of the box without custom FileSystemView or Ftplet) but here is the interesting thing, it only happens with ftpserver-core-1.1.0-SNAPSHOT.jar and not with 1.0.5.
Anybody aware of fixes in 1.0.5 that would make any difference? Upgrading our ftp install to 1.0.5 is not straightforward since we have used FtpLets and FileSystemView extensively and it seems quite a few class methods has changed there. Thanks Sachin -----Original Message----- From: Sachin Shetty [mailto:sshe...@egnyte.com] Sent: Wednesday, September 19, 2012 9:22 PM To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org' Subject: RE: GnuTLS internal error in Filezilla 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:sshe...@egnyte.com] Sent: Wednesday, September 19, 2012 4:48 PM To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org' 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:sshe...@egnyte.com] Sent: Monday, September 17, 2012 8:14 PM To: 'Sachin Shetty'; 'ftpserver-users@mina.apache.org' 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:sshe...@egnyte.com] Sent: Monday, September 17, 2012 4:27 PM To: 'ftpserver-users@mina.apache.org' 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:john.hart...@gmail.com] Sent: Monday, September 17, 2012 4:05 PM To: ftpserver-users@mina.apache.org 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 <sshe...@egnyte.com> 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:john.hart...@gmail.com] > Sent: Monday, September 17, 2012 3:42 PM > To: ftpserver-users@mina.apache.org > 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 <sshe...@egnyte.com> 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:sshe...@egnyte.com] > > Sent: Friday, September 07, 2012 1:35 PM > > To: 'ftpserver-users@mina.apache.org' > > 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"
