Upload fails after period of inactivity about fluentftp

[FanDjango]

Is there any way you might pick up the current master in this repo and play with that, produce a new log? I made some changes.

It might not help in this case, but it's a step forward. It depends a lot on how the timout is performed by the server. Some send a nice polite message before closing, others are more brutal.

My tests with proFTPd behave differently and I would ask you to help by testing this now on your IIS server.

[josecu08]

Sure, I've tested it on master. It still doesn't work. The log is the following:

# AutoConnect()

# AutoDetect(CloneConnection = False, FirstOnly = True, IncludeImplicit = True, AbortOnTimeout = True, RequireEncryption = False, ProtocolPriority = [Tls11, Tls12])
Status:   Auto-Detect trying encryption mode "Auto" with "Tls11, Tls12"

# Connect(False)
Status:   FluentFTP 48.0.3.0(.NET 6.0)
Status:   Connecting to IP #1= ***:21
Status:   Waiting for a response
Response: 220 Microsoft FTP Service [738868,903d]
Status:   Detected FTP server: WindowsServerIIS
Command:  AUTH TLS
Status:   Waiting for response to: AUTH TLS
Response: 234 AUTH command ok. Expecting TLS Negotiation. [36ms]
Warning:  SSL Buffering disabled because of .NET 5.0 and later
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, DiffieHellman, 0) [152ms]
Command:  USER ***
Status:   Waiting for response to: USER ***
Response: 331 Password required [40ms]
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in. [265ms]
Command:  PBSZ 0
Status:   Waiting for response to: PBSZ 0
Response: 200 PBSZ command successful. [47ms]
Command:  PROT P
Status:   Waiting for response to: PROT P
Response: 200 PROT command successful. [50ms]
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extended features supported:
Response: LANG EN*
Response: UTF8
Response: AUTH TLS;TLS-C;SSL;TLS-P;
Response: PBSZ
Response: PROT C;P;
Response: CCC
Response: HOST
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: 211 END [65ms]
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON. [66ms]
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 Windows_NT [47ms]
Status:   Active ServerHandler is: WindowsServerIIS
Status:   Listing parser set to: Windows
Command:  PWD
Status:   Waiting for response to: PWD
Response: 257 "/" is current directory. [105ms]
connected
upload 1

# UploadBytes("file/test1.txt", Overwrite, True)

# FileExists("file/test1.txt")
Command:  SIZE /file/test1.txt
Status:   Waiting for response to: SIZE /file/test1.txt
Response: 213 12 [116ms]

# DeleteFile("file/test1.txt")
Command:  DELE file/test1.txt
Status:   Waiting for response to: DELE file/test1.txt
Response: 250 DELE command successful. [50ms]

# OpenWrite("file/test1.txt", Binary, -1, False)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Type set to I. [42ms]

# OpenDataStreamAsync("STOR file/test1.txt", 0)

# OpenPassiveDataStreamAsync(PASV, "STOR file/test1.txt", 0)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (***). [34ms]
Status:   Connecting to IP #1= ***:50001
Command:  STOR file/test1.txt
Status:   Waiting for response to: STOR file/test1.txt
Response: 150 Opening BINARY mode data connection. [44ms]
Warning:  SSL Buffering disabled because of .NET 5.0 and later
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, DiffieHellman, 0) [99ms]
Status:   Uploaded 12 bytes
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Waiting for response to: STOR file/test1.txt
Response: 226 Transfer complete. [183ms]
delay expired
upload 2

# UploadBytes("file/test2.txt", Overwrite, True)

# FileExists("file/test2.txt")
Command:  SIZE /file/test2.txt
Status:   IOException for file  : Unable to write data to the transport connection: Broken pipe.
upload 3

# UploadBytes("file/test2.txt", Overwrite, True)

# FileExists("file/test2.txt")
Status:   Closing/Disposing FtpSocketStream(control connection)
Warning:  Reconnect needed due to disconnected control connection
Status:   Command stashed: SIZE /file/test2.txt

# Connect(True)
Warning:  Reconnect (Count: 1)
Status:   FluentFTP 48.0.3.0(.NET 6.0)
Status:   Connecting to IP #1= ***:21
Status:   Waiting for a response
Response: 220 Microsoft FTP Service [5,502m]
Status:   Detected FTP server: WindowsServerIIS
Command:  AUTH TLS
Status:   Waiting for response to: AUTH TLS
Response: 234 AUTH command ok. Expecting TLS Negotiation. [43ms]
Warning:  SSL Buffering disabled because of .NET 5.0 and later
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, DiffieHellman, 0) [95ms]
Command:  USER ***
Status:   Waiting for response to: USER ***
Response: 331 Password required [37ms]
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in. [32ms]
Command:  PBSZ 0
Status:   Waiting for response to: PBSZ 0
Response: 200 PBSZ command successful. [30ms]
Command:  PROT P
Status:   Waiting for response to: PROT P
Response: 200 PROT command successful. [34ms]
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extended features supported:
Response: LANG EN*
Response: UTF8
Response: AUTH TLS;TLS-C;SSL;TLS-P;
Response: PBSZ
Response: PROT C;P;
Response: CCC
Response: HOST
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: 211 END [37ms]
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON. [30ms]
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 Windows_NT [44ms]
Status:   Active ServerHandler is: WindowsServerIIS
Status:   Listing parser set to: Windows
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Type set to I. [37ms]

# SetWorkingDirectory("/")
Command:  CWD /
Status:   Waiting for response to: CWD /
Response: 250 CWD command successful. [46ms]

Status:   Executing stashed command

Command:  SIZE /file/test2.txt
Status:   Waiting for response to: SIZE /file/test2.txt
Response: 213 12 [39ms]

# DeleteFile("file/test2.txt")
Command:  DELE file/test2.txt
Status:   Waiting for response to: DELE file/test2.txt
Response: 250 DELE command successful. [47ms]

# OpenWrite("file/test2.txt", Binary, -1, False)

# OpenDataStreamAsync("STOR file/test2.txt", 0)

# OpenPassiveDataStreamAsync(PASV, "STOR file/test2.txt", 0)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (***). [46ms]
Status:   Connecting to IP #1= ***:50007
Command:  STOR file/test2.txt
Status:   Waiting for response to: STOR file/test2.txt
Response: 150 Opening BINARY mode data connection. [71ms]
Warning:  SSL Buffering disabled because of .NET 5.0 and later
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, DiffieHellman, 0) [81ms]
Status:   Uploaded 12 bytes
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Waiting for response to: STOR file/test2.txt
Response: 226 Transfer complete. [199ms]
done

[FanDjango]

Thanks. I'll work on using that status.

[FanDjango]

You might also like to look at #1410. We are also looking at ways to check for server availability at the users discretion, perhaps a new API function to help with that.

The problem is: You cannot check for connectivity without SENDind anything - and that send (at least in the case of FTP) must be a non destructive command (like NOOP). And you don't want to check all the time, because of the overhead.

In your case, we are getting an IOException on the SIZE command, which seems to be consumed erroneously. I'll look into that.

Bit difficult, as I cannot reproduce this specific behaviour even with your source code.

[josecu08]

Regarding #1410, I've tested the new IsStillConnected method. I get false when called after delay, however when I issue a reconnect I also get the broken pipe error.
Another possible solution might be to give the ability to configure KeepAlive (TcpKeepAliveTime, TcpKeepAliveInterval). In the past I've solved problems with half open connections severed by load balancers by changing those, as the ones configured by default are too long to be useful.

[FanDjango]

Regarding #1410, I've tested the new IsStillConnected method. I get false when called after delay, however when I issue a reconnect I also get the broken pipe error.

As you can see in #1410, that is still somewhat in progress. Please continue monitoring that or even test it again,

Another possible solution might be to give the ability to configure KeepAlive (TcpKeepAliveTime, TcpKeepAliveInterval). In the past I've solved problems with half open connections severed by load balancers by changing those, as the ones configured by default are too long to be useful.

Yes, I've seen these mentioned in the internet too when researching connection issues and have taken note that we might want a Config option to set these.

[FanDjango]

In your case, we are getting an IOException on the SIZE command, which seems to be consumed erroneously.

My statement is wrong.

Out entire automatic retry/reconnect logic relies on being able to detect a disconnection before entering a command. We are currently not able to retry a command after it fails due to a disconnection.

[FanDjango]

One suggestion I would make, is to check the returned value from the uploadbytes. It should be reporting a failure. I have tried to reproduce this and am not successful.

[josecu08]

Just to clarify, the issue is not a blocker for me. I've mitigated it by issuing a reconnect (the command fails, but it updates the internal state so that the next command is successful), I could use your suggestion to avoid doing it every time as it returns Failed.

BTW, I've tested the latest implementation of IsStillConnected and throws and exception. I call it after the delay, here is the stack trace just in case it helps:

# IsStillConnected(10000)
Command:  NOOP
Unhandled exception. System.IO.IOException: Unable to write data to the transport connection: Broken pipe.
 ---> System.Net.Sockets.SocketException (32): Broken pipe
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.CreateException(SocketError error, Boolean forAsyncThrow)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.SendAsyncForNetworkStream(Socket socket, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.SendAsyncForNetworkStream(ReadOnlyMemory`1 buffer, SocketFlags socketFlags, CancellationToken cancellationToken)
   at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteSingleChunk[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at FluentFTP.FtpSocketStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Streams/FtpSocketStream.cs:line 763
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at FluentFTP.FtpSocketStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token)
   at FluentFTP.FtpSocketStream.WriteLineAsync(Encoding encoding, String buf, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Streams/FtpSocketStream.cs:line 786
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at FluentFTP.FtpSocketStream.WriteLineAsync(Encoding encoding, String buf, CancellationToken token)
   at FluentFTP.AsyncFtpClient.NoopAsync(Boolean ignoreNoopInterval, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Client/AsyncClient/Noop.cs:line 26
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at FluentFTP.AsyncFtpClient.NoopAsync(Boolean ignoreNoopInterval, CancellationToken token)
   at FluentFTP.AsyncFtpClient.IsStillConnected(Int32 timeout, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Client/AsyncClient/IsStillConnected.cs:line 21
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at FluentFTP.AsyncFtpClient.IsStillConnected(Int32 timeout, CancellationToken token)
   at Program.<Main>$(String[] args) in /Users/josecu08/Desktop/FluentFTP/test/Program.cs:line 21
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
   at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
   at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
   at System.Threading.Tasks.Task.TrySetResult()
   at System.Threading.Tasks.Task.DelayPromise.CompleteTimedOut()
   at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
   at System.Threading.TimerQueue.FireNextTimers()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()
--- End of stack trace from previous location ---

   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.<WriteSingleChunk>g__CompleteWriteAsync|157_1[TIOAdapter](ValueTask writeTask, Byte[] bufferToReturn)
   at System.Net.Security.SslStream.WriteAsyncInternal[TIOAdapter](ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at FluentFTP.FtpSocketStream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Streams/FtpSocketStream.cs:line 763
   at FluentFTP.FtpSocketStream.WriteLineAsync(Encoding encoding, String buf, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Streams/FtpSocketStream.cs:line 786
   at FluentFTP.AsyncFtpClient.NoopAsync(Boolean ignoreNoopInterval, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Client/AsyncClient/Noop.cs:line 26
   at FluentFTP.AsyncFtpClient.IsStillConnected(Int32 timeout, CancellationToken token) in /Users/josecu08/Desktop/FluentFTP/FluentFTP/Client/AsyncClient/IsStillConnected.cs:line 21
   at Program.<Main>$(String[] args) in /Users/josecu08/Desktop/FluentFTP/test/Program.cs:line 21
   at Program.<Main>(String[] args)

[FanDjango]

Thanks for your patience.

I am very slowly getting to the core of the problem, but still very unsure of how to handle this.

BTW, I've tested the latest implementation of IsStillConnected and throws and exception. I call it after the delay, here is the stack trace just in case it helps:

Yes it does, it tells me I must further modify this new function to make it better - it currently just checks exceptions on the READ part. It should also do so on the SEND. So there will be another commit on master to make that work better.

[FanDjango]

Check out this one:

#1419

https://github.com/FanDjango/FluentFTP/tree/THREAD

[josecu08]

It works. It executes all commands after the delay without error.

[FanDjango]

Wohoo! But it will be a while until it is in NuGet, or even merged into Master. Still ironing out some things.

But BIG THANKS for such a quick test.

@robinrodricks Look see! Demon-Noop has passed it's first test in the wild.

[FanDjango]

This has moved to #1420, it has been improved further.