Our Products:   CompleteFTP  edtFTPnet/Free  edtFTPnet/PRO  edtFTPj/Free  edtFTPj/PRO
Ask a Question

Intermittent TLS Handshake failure

0 votes
2.3k views
in CompleteFTP by (120 points)

Hi, we're seeing intermittent connection issues where it appears to be failing on the TLS handshake.  Though a user is able to connect multiple times, then this issue will show up, and the next connection may work without any issues.

I've seen the issue when connection with an OTS FTP product (FileZilla) as well as with the primay means of middleware infrastructure.

We're using v8.0.0 of CompleteFTP, logs at the time the issue occurs are as follows:

Thanks for any input in advance!

2016-05-17 14:28:02,409 DEBUG SocketListener [Site.1:Default Site] BeginAccept (port 21) 
2016-05-17 14:28:02,409 DEBUG SocketListener [Site.1:Default Site] Allowed connection on port 21 from xxx.xxx.xxx.xxx due to rule Allow all 
2016-05-17 14:28:02,409 DEBUG FTPConfiguration [Site.1:Default Site] Using UTF8 encoding 
2016-05-17 14:28:02,409 DEBUG FTPSession [Site.1:Default Site] Launching login timeout (60000 ms): Session.17:Default Site:user? 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Site.1:Default Site] CMD< 220 xxxxx FTP Server 
2016-05-17 14:28:02,409 DEBUG FTPSession [Site.1:Default Site] setting state to AwaitAuth 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Site.1:Default Site] BeginSend:40 bytes 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] CMD> AUTH TLS 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] Processed command AUTH TLS 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] CMD< 234 AUTH TLS successful. 
2016-05-17 14:28:02,409 DEBUG FTPSession [Session.17:Default Site:user?] setting state to AwaitUser 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] BeginSend:26 bytes 
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] securing connection 
2016-05-17 14:28:02,409 ERROR FTPConnection [Session.17:Default Site:user?] send failed 
System.ArgumentException: SecureSocket.EndSend: null ti
   at kEvHWYY0mkEU98llip7.Jx3FoOY4b9u58G4h4cA.UfS3pFiyZRv(IAsyncResult )
   at H0IUrEMKcOPyruXnaNd.ED3kKLMTm8wckg6wYJ2.IGWSUYE4CP(IAsyncResult )
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] Closing connection 
2016-05-17 14:28:02,409 DEBUG UserSession [Session.17:Default Site:user?] ReleaseResources() 
2016-05-17 14:28:02,409 DEBUG FTPSession [Session.17:Default Site:user?] Released transfer resources 
2016-05-17 14:28:02,409 WARN FTPConnection [Session.17:Default Site:user?] Error calling Socket.BeginClose() 
System.NullReferenceException: Object reference not set to an instance of an object.
   at shoHk3t9IrjE0VqpKoM.Jf7TMdtbH6YTBCsqDsv.HGkAWiwIGXU(AsyncCallback , Object )
   at kEvHWYY0mkEU98llip7.Jx3FoOY4b9u58G4h4cA.S4oAnt9Nscf(AsyncCallback , Object )
   at kEvHWYY0mkEU98llip7.Jx3FoOY4b9u58G4h4cA.nOCAnlfmlPA(Int32 , AsyncCallback , Object )
   at H0IUrEMKcOPyruXnaNd.ED3kKLMTm8wckg6wYJ2.Close()
2016-05-17 14:28:02,409 DEBUG SocketController [Session.17:Default Site:user?] Dispose() 
2016-05-17 14:28:02,409 DEBUG SocketController [Session.17:Default Site:user?] CloseConnection(e=null) 
2016-05-17 14:28:02,409 DEBUG SocketController [Session.17:Default Site:user?] Closed socket 
2016-05-17 14:28:02,409 DEBUG TransferBuffer [Session.17:Default Site:user?] Close() called when open 
2016-05-17 14:28:02,409 DEBUG SocketController [Session.17:Default Site:user?] OnReceive closing (socket not connected) 
2016-05-17 14:28:02,409 DEBUG SocketController [Session.17:Default Site:user?] CloseConnection(e=null) 
2016-05-17 14:28:02,409 ERROR SocketController [Session.17:Default Site:user?] OnReceive - caught exception - closing: Socket closed before handshake is complete (1) 
2016-05-17 14:28:02,409 DEBUG SocketController [Session.17:Default Site:user?] CloseConnection(e=Socket closed before handshake is complete (1)) 
2016-05-17 14:28:02,409 DEBUG SecureSocket [Session.17:Default Site:user?] OnHandshakeComplete(False,Socket closed before handshake is complete (1)) 
2016-05-17 14:28:02,409 ERROR SecureSocket [Session.17:Default Site:user?] Exception during handshake: Socket closed before handshake is complete (1) 
2016-05-17 14:28:02,409 ERROR FTPConnection [Session.17:Default Site:user?] send failed 
System.IO.IOException: Socket closed before handshake is complete (1)
   at kEvHWYY0mkEU98llip7.Jx3FoOY4b9u58G4h4cA.EwgAnpE0xAK(gTjCmaYespHHAD0rYOg )
   at H0IUrEMKcOPyruXnaNd.ED3kKLMTm8wckg6wYJ2.IGWSUYE4CP(IAsyncResult )
2016-05-17 14:28:02,409 DEBUG FTPConnection [Session.17:Default Site:user?] Closing connection 
by (2.7k points)
Do you see an error in the server-log?
by (120 points)
The log in the initial post is from the Diagnostics.log file running @ Debug level.

Is there somewhere else I should be looking?  
Client application logs don't show anything helpful.
by (2.7k points)
Oh, sorry, I got my wires crossed.  I thought the logs were from our .NET client, which look similar.  I'll keep investigating and get back to you...
by (2.7k points)
The logs show that there was an internal error during the handshake.  It may have been caused by something the client did, but even in that case our software certainly didn't handle it correctly.  Is it possible for you to run the server with the logging level set to All and then send us the appropriate part of the log file when the error recurs?  The file is likely to be large, so it's probably best if you open a support ticket in our helpdesk system - enterprisedt.com/help.
by (162k points)
Actually since you are on 8.0, you should upgrade to 9.0 - there have been a lot of fixes including some changes to handshake code.
by (120 points)
Having a little trouble gathering logs at the "All" level.  It looks as though the log files for the times the error occurs when the level is at 'All" are missing entirely.  ie I have a Diagnostics.log, and then it jumps straight t .log.3, .log.5, etc. with the missing files corresponding to the times that logging was set highly

I'm trying to narrow the window where the intensive logging occurs to try and capture the relevant lines.

@support2, currently migrating to version 9 would be a last resort option, unfortunately, as it wuld not be a quick process on this solution.

1 Answer

0 votes
by (2.7k points)
When you say some log-files are missing.  Are you referring to the listing you see in CompleteFTP Manager or to the listing you see in Windows Explorer?  If it's the former then please have a look directly in the log files directory, which you can find at C:\ProgramData\Enterprise Distributed Technologies\Complete FTP\Logs.  We have an outstanding bug where the listing in CompleteFTP Manager is incorrect if large amounts of logging are produced, in which case the listing goes out of date.
by (120 points)
Both the listing and the physical file had gone missing.  Unsure exactly what had happened at the time.  However I was able to later capture two instances of the error with verbose logging enabled, and have raised a support ticket, as advised above.  Thanks.

Categories

EnterpriseDT 2020
...