Random exception "SSL Encryption has already been enabled on this stream."

[adrianm64]

FTP Server OS: Unix / Windows / Embedded Windows

FTP Server Type: Vsftpd / glFTPd / BFTPd / ProFTPD / Pure-FTPd / IBM CS FTP (z/OS, OS/400) / Windows CE / Windows Server IIS / Vax / VMS / OpenVMS / Tandem / HP NonStop WindowsServerIIS

Client Computer OS: Windows / Ubuntu / Debian / Linux Mint / Arch Linux Windows

FluentFTP Version: ? 50.0.1

Framework: .NET 2 / 3.5 / 4 / 5 / 6 / 7 / 8 / UWP / Xamarin / Mono DotNet 6

Sometimes get exception "SSL Encryption has already been enabled on this stream." Only pattern I can see it is always happen after "Reconnect (Count: 2)" Using Config.EncryptionMode = FtpEncryptionMode.Implicit

Logs :

>         GetListing("Prod/From_PN/*.xml", Auto)
>         OpenDataStream("LIST /Prod/From_PN/*.xml", 0)
Testing connectivity using Socket.Poll()...
Reconnect due to disconnected control connection
>         Connect(True)
Reconnect (Count: 2)
FluentFTP 50.0.1.0(.NET 6.0) FtpClient
>         Disconnect()
Command:  QUIT
FtpClient.Disconnect(): Exception caught and discarded while closing control connection
* IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
* SocketException: An existing connection was forcibly closed by the remote host.
  SocketErrorCode = ConnectionReset
  ErrorCode = 10054
  NativeErrorCode = 10054
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)```
Connecting to IP #1= ***:990
SSL Encryption has already been enabled on this stream.
* InvalidOperationException: SSL Encryption has already been enabled on this stream.
   at FluentFTP.FtpSocketStream.ActivateEncryption(String targetHost, X509CertificateCollection clientCerts, SslProtocols sslProtocols)
   at FluentFTP.FtpClient.Connect(Boolean reConnect)
   at FluentFTP.FtpClient.OpenDataStream(String command, Int64 restart)
   at FluentFTP.FtpClient.GetListingInternal(String listcmd, FtpListOption options, Boolean retry)
   at FluentFTP.FtpClient.GetListing(String path, FtpListOption options)
   at FluentFTP.FtpClient.GetListing(String path)

[FanDjango]

I think you are experiencing two problems here.

1. It seems that authentication for an implicit encryption connection fails on a reconnect. That would be a bug and needs to be debugged/fixed. I will investigate this some more when I have time.

2. You should not really be having a reconnect take place. This is only done in certain cases that are considered recoverable. Sadly, your log does not show what was happening prior to the reconnect attempt.

[adrianm64]

Thank you for your looking into it.

1. Tried to look in the code and can't say I understand the state handling and how streams are reused on reconnect. Is activating encryption on an already encrypted stream an state error? Maybe a fix is to just convert it into a nop (and a warning in the log).

2. Not sure why the reason for the reconnect matters but the line before the log in the first post just says.

   Response: 226 Transfer complete. [37ms]

   and that was 10 minutes earlier

[FanDjango]

and that was 10 minutes earlier

Aha. Probably, the server closed the control connection after inactivity timeout (say, 5 minutes default, depends on config of the server).

So when you request the next API function that involves communicating with the server, an automatic reconnect is done(attempted).

So that gives a chance to circumvent the problem: You might check the connection state (IsConnected) prior to further actions.

Nonetheless I will look into why a reconnect in implicit mode fails. Given that the connection is down, the stream should have been "cleaned" up.

Reconnect due to disconnected control connection
>         Connect(True)
Reconnect (Count: 2)
FluentFTP 50.0.1.0(.NET 6.0) FtpClient
>         Disconnect()
Command:  QUIT

I am missing many log messages in that sequence. Create a verbose log of these. Also, I need the messages prior to Reconnect due to disconnected control connection, to see any stream cleanup, i.e. after Response: 226 Transfer complete. [37ms].

[FanDjango]

One more thing: The code should not attempt a reconnect solely to disconnect (for the QUIT) command, so I need to analyze with a more detailed log, what is going on here...

[FanDjango]

The reconnect count is 2. Any reconnects in the log prior to that one? How did they fare?

[adrianm64]

What do you mean with verbose log? Have searched the documentation but can't find anything about logging levels.

Here is a complete session log

2024-10-11T12:20:11.7691619+02:00   [DBG]   >         GetListing("Prod/From_PN/*.xml", Auto)
2024-10-11T12:20:11.7728736+02:00   [DBG]   Reconnect needed due to disconnected control connection
2024-10-11T12:20:11.7729868+02:00   [DBG]   Command stashed: PWD
2024-10-11T12:20:11.7742493+02:00   [DBG]   >         Connect(True)
2024-10-11T12:20:11.7743053+02:00   [DBG]   Cannot reconnect, reverting to full connect
2024-10-11T12:20:11.7745565+02:00   [DBG]   FluentFTP 50.0.1.0(.NET 6.0) FtpClient
2024-10-11T12:20:11.7772644+02:00   [DBG]   Connecting to IP #1= ***:990
2024-10-11T12:20:11.8458197+02:00   [DBG]   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 255) [50ms]
2024-10-11T12:20:11.8479585+02:00   [DBG]   Waiting for a response
2024-10-11T12:20:11.8502087+02:00   [DBG]   Response: 220 Microsoft FTP Service [739169,431d]
2024-10-11T12:20:11.8521922+02:00   [DBG]   Status:   Detected FTP server: WindowsServerIIS
2024-10-11T12:20:11.8526212+02:00   [DBG]   Command:  USER ***
2024-10-11T12:20:11.8532503+02:00   [DBG]   Waiting for response to: USER ***
2024-10-11T12:20:11.8652690+02:00   [DBG]   Response: 331 Password required [12ms]
2024-10-11T12:20:11.8660115+02:00   [DBG]   Command:  PASS ***
2024-10-11T12:20:11.8660899+02:00   [DBG]   Waiting for response to: PASS ***
2024-10-11T12:20:11.8786877+02:00   [DBG]   Response: 230 User logged in. [12ms]
2024-10-11T12:20:11.8803569+02:00   [DBG]   Command:  PBSZ 0
2024-10-11T12:20:11.8804144+02:00   [DBG]   Waiting for response to: PBSZ 0
2024-10-11T12:20:11.8924471+02:00   [DBG]   Response: 200 PBSZ command successful. [12ms]
2024-10-11T12:20:11.8924754+02:00   [DBG]   Command:  PROT P
2024-10-11T12:20:11.8925139+02:00   [DBG]   Waiting for response to: PROT P
2024-10-11T12:20:11.9045303+02:00   [DBG]   Response: 200 PROT command successful. [12ms]
2024-10-11T12:20:11.9047233+02:00   [DBG]   Command:  FEAT
2024-10-11T12:20:11.9047700+02:00   [DBG]   Waiting for response to: FEAT
2024-10-11T12:20:11.9172043+02:00   [DBG]   >>>
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: 211-Extended features supported:
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: LANG EN*
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: UTF8
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: AUTH TLS;TLS-C;SSL;TLS-P;
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: PBSZ
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: PROT C;P;
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: CCC
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: HOST
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: SIZE
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: MDTM
2024-10-11T12:20:11.9172043+02:00   [DBG]   Response: REST STREAM
2024-10-11T12:20:11.9172043+02:00   [DBG]   <<<
2024-10-11T12:20:11.9172474+02:00   [DBG]   Response: 211 END [12ms]
2024-10-11T12:20:11.9241629+02:00   [DBG]   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
2024-10-11T12:20:11.9241902+02:00   [DBG]   Command:  OPTS UTF8 ON
2024-10-11T12:20:11.9242383+02:00   [DBG]   Waiting for response to: OPTS UTF8 ON
2024-10-11T12:20:11.9362091+02:00   [DBG]   Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON. [11ms]
2024-10-11T12:20:11.9362371+02:00   [DBG]   Command:  SYST
2024-10-11T12:20:11.9362795+02:00   [DBG]   Waiting for response to: SYST
2024-10-11T12:20:11.9482220+02:00   [DBG]   Response: 215 Windows_NT [11ms]
2024-10-11T12:20:11.9494554+02:00   [DBG]   Active ServerHandler is: WindowsServerIIS
2024-10-11T12:20:11.9498280+02:00   [DBG]   Listing parser set to: Windows
2024-10-11T12:20:11.9498793+02:00   [DBG]   Command:  PWD
2024-10-11T12:20:11.9500622+02:00   [DBG]   Waiting for response to: PWD
2024-10-11T12:20:11.9619534+02:00   [DBG]   Response: 257 "/" is current directory. [11ms]
2024-10-11T12:20:11.9622311+02:00   [DBG]   
2024-10-11T12:20:11.9622685+02:00   [DBG]   Executing stashed command
2024-10-11T12:20:11.9622774+02:00   [DBG]   
2024-10-11T12:20:11.9622915+02:00   [DBG]   Command:  PWD
2024-10-11T12:20:11.9623331+02:00   [DBG]   Waiting for response to: PWD
2024-10-11T12:20:11.9742799+02:00   [DBG]   Response: 257 "/" is current directory. [11ms]
2024-10-11T12:20:11.9777718+02:00   [DBG]   Command:  TYPE I
2024-10-11T12:20:11.9778307+02:00   [DBG]   Waiting for response to: TYPE I
2024-10-11T12:20:11.9898885+02:00   [DBG]   Response: 200 Type set to I. [12ms]
2024-10-11T12:20:11.9900965+02:00   [DBG]   >         OpenDataStream("LIST /Prod/From_PN/*.xml", 0)
2024-10-11T12:20:11.9926621+02:00   [DBG]   >         OpenPassiveDataStream(PASV, "LIST /Prod/From_PN/*.xml", 0)
2024-10-11T12:20:11.9926930+02:00   [DBG]   Command:  PASV
2024-10-11T12:20:11.9927344+02:00   [DBG]   Waiting for response to: PASV
2024-10-11T12:20:12.0048399+02:00   [DBG]   Response: 227 Entering Passive Mode (195,67,14,6,192,89). [12ms]
2024-10-11T12:20:12.0059048+02:00   [DBG]   Connecting to IP #1= ***:49241
2024-10-11T12:20:12.0183176+02:00   [DBG]   Command:  LIST /Prod/From_PN/*.xml
2024-10-11T12:20:12.0183873+02:00   [DBG]   Waiting for response to: LIST /Prod/From_PN/*.xml
2024-10-11T12:20:12.0308284+02:00   [DBG]   Response: 125 Data connection already open; Transfer starting. [12ms]
2024-10-11T12:20:12.0313213+02:00   [DBG]   SSL Buffering disabled because of .NET 5.0 and later
2024-10-11T12:20:12.0444376+02:00   [DBG]   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 255) [13ms]
2024-10-11T12:20:12.0444685+02:00   [DBG]   +---------------------------------------+
2024-10-11T12:20:12.0564264+02:00   [DBG]   -----------------------------------------
2024-10-11T12:20:12.0568291+02:00   [DBG]   Disposing(sync) FtpSocketStream(data connection of FtpClient)
2024-10-11T12:20:12.0580302+02:00   [DBG]   >         CloseDataStream()
2024-10-11T12:20:12.0581164+02:00   [DBG]   Waiting for response to: LIST /Prod/From_PN/*.xml
2024-10-11T12:20:12.0581595+02:00   [DBG]   Response: 226 Transfer complete. [39ms]
2024-10-11T12:30:10.9956428+02:00   [DBG]   >         GetListing("Prod/From_PN/*.xml", Auto)
2024-10-11T12:30:10.9958189+02:00   [DBG]   >         OpenDataStream("LIST /Prod/From_PN/*.xml", 0)
2024-10-11T12:30:10.9958821+02:00   [DBG]   Testing connectivity using Socket.Poll()...
2024-10-11T12:30:10.9961749+02:00   [DBG]   Disposing(sync) FtpSocketStream(control connection of FtpClient)
2024-10-11T12:30:11.0093363+02:00   [DBG]   Reconnect due to disconnected control connection
2024-10-11T12:30:11.0093819+02:00   [DBG]   >         Connect(True)
2024-10-11T12:30:11.0093949+02:00   [DBG]   Reconnect (Count: 1)
2024-10-11T12:30:11.0094401+02:00   [DBG]   FluentFTP 50.0.1.0(.NET 6.0) FtpClient
2024-10-11T12:30:11.0094592+02:00   [DBG]   Connecting to IP #1= ***:990
2024-10-11T12:30:11.0351494+02:00   [DBG]   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 255) [13ms]
2024-10-11T12:30:11.0352208+02:00   [DBG]   Waiting for a response
2024-10-11T12:30:11.0471467+02:00   [DBG]   Response: 220 Microsoft FTP Service [9,984m]
2024-10-11T12:30:11.0472067+02:00   [DBG]   Status:   Detected FTP server: WindowsServerIIS
2024-10-11T12:30:11.0472337+02:00   [DBG]   Command:  USER ***
2024-10-11T12:30:11.0472926+02:00   [DBG]   Waiting for response to: USER ***
2024-10-11T12:30:11.0597927+02:00   [DBG]   Response: 331 Password required [12ms]
2024-10-11T12:30:11.0598329+02:00   [DBG]   Command:  PASS ***
2024-10-11T12:30:11.0599037+02:00   [DBG]   Waiting for response to: PASS ***
2024-10-11T12:30:11.0724525+02:00   [DBG]   Response: 230 User logged in. [12ms]
2024-10-11T12:30:11.0724992+02:00   [DBG]   Command:  PBSZ 0
2024-10-11T12:30:11.0725474+02:00   [DBG]   Waiting for response to: PBSZ 0
2024-10-11T12:30:11.0845573+02:00   [DBG]   Response: 200 PBSZ command successful. [12ms]
2024-10-11T12:30:11.0846446+02:00   [DBG]   Command:  PROT P
2024-10-11T12:30:11.0846978+02:00   [DBG]   Waiting for response to: PROT P
2024-10-11T12:30:11.0966366+02:00   [DBG]   Response: 200 PROT command successful. [11ms]
2024-10-11T12:30:11.0966883+02:00   [DBG]   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
2024-10-11T12:30:11.0967081+02:00   [DBG]   Command:  OPTS UTF8 ON
2024-10-11T12:30:11.0967594+02:00   [DBG]   Waiting for response to: OPTS UTF8 ON
2024-10-11T12:30:11.1088670+02:00   [DBG]   Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON. [12ms]
2024-10-11T12:30:11.1089497+02:00   [DBG]   Command:  SYST
2024-10-11T12:30:11.1090355+02:00   [DBG]   Waiting for response to: SYST
2024-10-11T12:30:11.1210494+02:00   [DBG]   Response: 215 Windows_NT [12ms]
2024-10-11T12:30:11.1210954+02:00   [DBG]   Active ServerHandler is: WindowsServerIIS
2024-10-11T12:30:11.1211303+02:00   [DBG]   Listing parser set to: Windows
2024-10-11T12:30:11.1211493+02:00   [DBG]   Command:  TYPE I
2024-10-11T12:30:11.1211845+02:00   [DBG]   Waiting for response to: TYPE I
2024-10-11T12:30:11.1330886+02:00   [DBG]   Response: 200 Type set to I. [11ms]
2024-10-11T12:30:11.1333445+02:00   [DBG]   >         SetWorkingDirectory("/")
2024-10-11T12:30:11.1333725+02:00   [DBG]   Command:  CWD /
2024-10-11T12:30:11.1334239+02:00   [DBG]   Waiting for response to: CWD /
2024-10-11T12:30:11.1457673+02:00   [DBG]   Response: 250 CWD command successful. [12ms]
2024-10-11T12:30:11.1459016+02:00   [DBG]   >         OpenPassiveDataStream(PASV, "LIST /Prod/From_PN/*.xml", 0)
2024-10-11T12:30:11.1459358+02:00   [DBG]   Command:  PASV
2024-10-11T12:30:11.1460119+02:00   [DBG]   Waiting for response to: PASV
2024-10-11T12:30:11.1785214+02:00   [DBG]   Response: 227 Entering Passive Mode (195,67,14,6,192,18). [32ms]
2024-10-11T12:30:11.1786410+02:00   [DBG]   Connecting to IP #1= ***:49170
2024-10-11T12:30:11.1911698+02:00   [DBG]   Command:  LIST /Prod/From_PN/*.xml
2024-10-11T12:30:11.1912492+02:00   [DBG]   Waiting for response to: LIST /Prod/From_PN/*.xml
2024-10-11T12:30:11.2038147+02:00   [DBG]   Response: 125 Data connection already open; Transfer starting. [12ms]
2024-10-11T12:30:11.2039005+02:00   [DBG]   SSL Buffering disabled because of .NET 5.0 and later
2024-10-11T12:30:11.2169407+02:00   [DBG]   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 255) [13ms]
2024-10-11T12:30:11.2169834+02:00   [DBG]   +---------------------------------------+
2024-10-11T12:30:11.2290214+02:00   [DBG]   -----------------------------------------
2024-10-11T12:30:11.2290756+02:00   [DBG]   Disposing(sync) FtpSocketStream(data connection of FtpClient)
2024-10-11T12:30:11.2293472+02:00   [DBG]   >         CloseDataStream()
2024-10-11T12:30:11.2293843+02:00   [DBG]   Waiting for response to: LIST /Prod/From_PN/*.xml
2024-10-11T12:30:11.2294514+02:00   [DBG]   Response: 226 Transfer complete. [38ms]
2024-10-11T12:40:10.9899378+02:00   [DBG]   >         GetListing("Prod/From_PN/*.xml", Auto)
2024-10-11T12:40:10.9900873+02:00   [DBG]   >         OpenDataStream("LIST /Prod/From_PN/*.xml", 0)
2024-10-11T12:40:10.9901110+02:00   [DBG]   Testing connectivity using Socket.Poll()...
2024-10-11T12:40:10.9901595+02:00   [DBG]   Reconnect due to disconnected control connection
2024-10-11T12:40:10.9901742+02:00   [DBG]   >         Connect(True)
2024-10-11T12:40:10.9901800+02:00   [DBG]   Reconnect (Count: 2)
2024-10-11T12:40:10.9902687+02:00   [DBG]   FluentFTP 50.0.1.0(.NET 6.0) FtpClient
2024-10-11T12:40:10.9905148+02:00   [DBG]   >         Disconnect()
2024-10-11T12:40:10.9905813+02:00   [DBG]   Command:  QUIT
2024-10-11T12:40:10.9908989+02:00   [DBG]   >>>
2024-10-11T12:40:10.9908989+02:00   [DBG]   FtpClient.Disconnect(): Exception caught and discarded while closing control connection
2024-10-11T12:40:10.9908989+02:00   [DBG]   * IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
2024-10-11T12:40:10.9908989+02:00   [DBG]   * SocketException: An existing connection was forcibly closed by the remote host.
2024-10-11T12:40:10.9908989+02:00   [DBG]     SocketErrorCode = ConnectionReset
2024-10-11T12:40:10.9908989+02:00   [DBG]     ErrorCode = 10054
2024-10-11T12:40:10.9908989+02:00   [DBG]     NativeErrorCode = 10054
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpSocketStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpSocketStream.WriteLine(Encoding encoding, String buf)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.ExecuteInternal(String command)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpClient.Execute(String command)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpClient.Disconnect()
2024-10-11T12:40:10.9908989+02:00   [DBG]   <<<
2024-10-11T12:40:11.0009885+02:00   [DBG]   Connecting to IP #1= ***:990
2024-10-11T12:40:11.0138143+02:00   [UNH]   >>> 85  0   [WhGroup.Balder.PostNordIntegration.Startup]    
2024-10-11T12:40:11.0138143+02:00   [UNH]   SSL Encryption has already been enabled on this stream.
2024-10-11T12:40:11.0138143+02:00   [UNH]   * InvalidOperationException: SSL Encryption has already been enabled on this stream.
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpSocketStream.ActivateEncryption(String targetHost, X509CertificateCollection clientCerts, SslProtocols sslProtocols)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.Connect(Boolean reConnect)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.OpenDataStream(String command, Int64 restart)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.GetListingInternal(String listcmd, FtpListOption options, Boolean retry)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.GetListing(String path, FtpListOption options)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.GetListing(String path)
2024-10-11T12:40:11.0138143+02:00   [UNH]   <<<

[FanDjango]

This one is fine. Let me look at it...

[FanDjango]

As a first thing that I notice, you might want to do a

client.Connect()

before you go off and do the first GetListing().

2024-10-11T12:20:11.7691619+02:00   [DBG]   >         GetListing("Prod/From_PN/*.xml", Auto)
2024-10-11T12:20:11.7728736+02:00   [DBG]   Reconnect needed due to disconnected control connection
2024-10-11T12:20:11.7729868+02:00   [DBG]   Command stashed: PWD
2024-10-11T12:20:11.7742493+02:00   [DBG]   >         Connect(True)
2024-10-11T12:20:11.7743053+02:00   [DBG]   Cannot reconnect, reverting to full connect

That's not a clean start to an FTP session.

[FanDjango]

2024-10-11T12:20:12.0313213+02:00 [DBG] SSL Buffering disabled because of .NET 5.0 and later

This message tells me you are not on the latest FluentFTP version. I would get some more debug messages if you were up to date...

I see that you are on V50.0.1, we've reached V51... by now.

[FanDjango]

2024-10-11T12:20:12.0581164+02:00   [DBG]   Waiting for response to: LIST /Prod/From_PN/*.xml
2024-10-11T12:20:12.0581595+02:00   [DBG]   Response: 226 Transfer complete. [39ms]
2024-10-11T12:30:10.9956428+02:00   [DBG]   >         GetListing("Prod/From_PN/*.xml", Auto)
2024-10-11T12:30:10.9958189+02:00   [DBG]   >         OpenDataStream("LIST /Prod/From_PN/*.xml", 0)
2024-10-11T12:30:10.9958821+02:00   [DBG]   Testing connectivity using Socket.Poll()...
2024-10-11T12:30:10.9961749+02:00   [DBG]   Disposing(sync) FtpSocketStream(control connection of FtpClient)
2024-10-11T12:30:11.0093363+02:00   [DBG]   Reconnect due to disconnected control connection
2024-10-11T12:30:11.0093819+02:00   [DBG]   >         Connect(True)
2024-10-11T12:30:11.0093949+02:00   [DBG]   Reconnect (Count: 1)

This sequence tells me that sometime between 12:20 and 12:30 (the client is not notified) the connection was dropped by the server. FluentFTP has no way of noticing that until the time (12:30) when you again request a listing. At that point the first reconnect is automatically attempted. So far so good...

This happens "again and again", I suppose, as you seem to have a loop in your code doing a GetListing every 10 minutes?

Ok, a first way to avoid the reconnects is to perhaps try using NOOPs by way of activating the NOOP daemon.

[FanDjango]

The reconnects, though, should work. But there seems to be a bug indicated by the following sequence:

2024-10-11T12:40:10.9901110+02:00   [DBG]   Testing connectivity using Socket.Poll()...
2024-10-11T12:40:10.9901595+02:00   [DBG]   Reconnect due to disconnected control connection

No command is stashed. I will investigate.

But:

In the newest V51.... we no longer use Socket.Poll(), that code has changed. What is the chance that you can use the newest version?

Note that I still consider this statement of mine to be true:

I think you are experiencing two problems here.

Would be nice to avoid the reconnects altogether. But I would still like to find out why they are failing, and now I have a few clues, thanks to the complete log

[FanDjango]

I think I can actually reproduce this here locally - once again, thanks for the log. Stand by for a while.

[adrianm64]

Your analysis is correct. I have a timer running looking for new files every 10 minutes. It has been running for a long time but problems started appearing recently.

FluentFtp replaces the old FtpWebRequest for me so the code relies on auto connect/reconnect instead of explicit session management.

If this is not the correct way to use the library I can easily add session management with explicit connect/disconnect in the timer loop.

[FanDjango]

Slowly, slowly.

I finally understand the problem(s).

First of all, some of the code in FluentFTP pertaining to this scenario has changed.

Socket.Poll is no longer used and stream disposal has been cleaned up, provided with more log messages etc.

So this sequence here is actually a bug that has been fixed by now, in part:

2024-10-11T12:40:10.9901110+02:00   [DBG]   Testing connectivity using Socket.Poll()...
2024-10-11T12:40:10.9901595+02:00   [DBG]   Reconnect due to disconnected control connection
2024-10-11T12:40:10.9901742+02:00   [DBG]   >         Connect(True)
2024-10-11T12:40:10.9901800+02:00   [DBG]   Reconnect (Count: 2)
2024-10-11T12:40:10.9902687+02:00   [DBG]   FluentFTP 50.0.1.0(.NET 6.0) FtpClient
2024-10-11T12:40:10.9905148+02:00   [DBG]   >         Disconnect()
2024-10-11T12:40:10.9905813+02:00   [DBG]   Command:  QUIT
2024-10-11T12:40:10.9908989+02:00   [DBG]   >>>
2024-10-11T12:40:10.9908989+02:00   [DBG]   FtpClient.Disconnect(): Exception caught and discarded while closing control connection
2024-10-11T12:40:10.9908989+02:00   [DBG]   * IOException: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host..
2024-10-11T12:40:10.9908989+02:00   [DBG]   * SocketException: An existing connection was forcibly closed by the remote host.
2024-10-11T12:40:10.9908989+02:00   [DBG]     SocketErrorCode = ConnectionReset
2024-10-11T12:40:10.9908989+02:00   [DBG]     ErrorCode = 10054
2024-10-11T12:40:10.9908989+02:00   [DBG]     NativeErrorCode = 10054
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](TIOAdapter writeAdapter, ReadOnlyMemory`1 buffer)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at System.Net.Security.SslStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpSocketStream.Write(Byte[] buffer, Int32 offset, Int32 count)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpSocketStream.WriteLine(Encoding encoding, String buf)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.ExecuteInternal(String command)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpClient.Execute(String command)
2024-10-11T12:40:10.9908989+02:00   [DBG]      at FluentFTP.FtpClient.Disconnect()
2024-10-11T12:40:10.9908989+02:00   [DBG]   <<<
2024-10-11T12:40:11.0009885+02:00   [DBG]   Connecting to IP #1= ***:990
2024-10-11T12:40:11.0138143+02:00   [UNH]   >>> 85  0   [WhGroup.Balder.PostNordIntegration.Startup]    
2024-10-11T12:40:11.0138143+02:00   [UNH]   SSL Encryption has already been enabled on this stream.
2024-10-11T12:40:11.0138143+02:00   [UNH]   * InvalidOperationException: SSL Encryption has already been enabled on this stream.
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpSocketStream.ActivateEncryption(String targetHost, X509CertificateCollection clientCerts, SslProtocols sslProtocols)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.Connect(Boolean reConnect)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.OpenDataStream(String command, Int64 restart)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.GetListingInternal(String listcmd, FtpListOption options, Boolean retry)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.GetListing(String path, FtpListOption options)
2024-10-11T12:40:11.0138143+02:00   [UNH]      at FluentFTP.FtpClient.GetListing(String path)

If you remove the execpetion messages:

2024-10-11T12:40:10.9901110+02:00   [DBG]   Testing connectivity using Socket.Poll()...
2024-10-11T12:40:10.9901595+02:00   [DBG]   Reconnect due to disconnected control connection
2024-10-11T12:40:10.9901742+02:00   [DBG]   >         Connect(True)
2024-10-11T12:40:10.9901800+02:00   [DBG]   Reconnect (Count: 2)
2024-10-11T12:40:10.9902687+02:00   [DBG]   FluentFTP 50.0.1.0(.NET 6.0) FtpClient
2024-10-11T12:40:10.9905148+02:00   [DBG]   >         Disconnect()
2024-10-11T12:40:10.9905813+02:00   [DBG]   Command:  QUIT
2024-10-11T12:40:11.0009885+02:00   [DBG]   Connecting to IP #1= ***:990

This: Reconnect due to disconnected control connection simply invokes Connect() without any cleanup of the SslStream, the underlying streams etc. I will fix that.

It's a bug, long undiscovered. Why you are hitting it after all this time, I dunno. It's in OpenDataStream.cs, Line 26-28. It depends on the Socket.Poll being called, and that is rather undetermined, depends on timing and your parameter.

There are not many things you can try out:

1. In your current client code: Disable Socket Polling (set the time to zero). See what happens, how the behaviour changes.
2. Experiment using

               client.Config.Noop = true;
               client.Config.NoopInterval = 5000;
               client.Config.NoopTestConnectivity = true;

3. Do number 2 especially in the new V51... (which also no longer even support socket polling.

   4. You yourself in your code could intersperse your 10 minute GetListings with a Execute('NOOP') command 5 times with 2 minutes in between <-----Good quick trick

[FanDjango]

If this is not the correct way to use the library I can easily add session management with explicit connect/disconnect in the timer loop.

Explicit session mgmnt should not be needed. I do it in some GUI applications, though, to show the user the state of the session, but for pure unmanned transfers, what for?

But try to use the lastest and greatest, I have been doing a lot of cleanup on stream disposal et al

[adrianm64]

Thank you for all your efforts. I really appreciate it.

My service application handles exceptions by restarting which works fine for this error. Just causes some red in the telemetry and entries in the event log. Will try latest version next week and see what happens.

[adrianm64]

Sorry for the lack of updates. The errors stopped coming before I had a chance to update to the latest version. Don't know what changed on the server since I have no control over it but now it is back to how it worked before.

Hopefully you got something out of it and once again thank you for your work.

[FanDjango]

Hopefully you got something out of it

Yes, very much so.

It's a bug, long undiscovered. Why you are hitting it after all this time, I dunno. It's in OpenDataStream.cs, Line 26-28. It depends on the Socket.Poll being called, and that is rather undetermined, depends on timing and your parameter.

I am still pondering on how to fix this - probably simply be removing this incomplete reconnect, as my tests show that it is not really necessary (I think!!!) instead of enhancing it with the needed stuff.

So, I will keep this open until the points are actually addressed. No need for you to do anything. And, thanks for your opening this issue.

[FanDjango]

After many tests I have decided to simply remove the offending code. Firstly, it won't work correctly, as it needs more that just a Connect()' to successfullyRecconnect...`. Secondly, this 'Disconnected' state is caught elsewhere. Thirdly, it is a very seldom occurence and it seems a very strange edge case.

This is merged and sometime it will find its way to a Nuget release.

[FanDjango]

And thus, I will now finally close this issue that had actually already been resolved with other measures.