FubarDevelopment / FtpServer

Portable FTP server written in .NET
http://fubardevelopment.github.io/FtpServer/
MIT License
482 stars 163 forks source link

StreamPipeWriterService throws InvalidOperationException #86

Closed twodogmbh closed 5 years ago

twodogmbh commented 5 years ago

Unfortunately issue #82 is still not completely solved. The FTP client still occasionally throws "The server committed a protocol violation" exceptions.

The FTP server then shows an InvalidOperationException.

Here an extract of the FTP server log file with the exception:

[2019-11-12 07:49:53,877][ST][INF][Logger:FubarDev.FtpServer.FtpConnection][Thread:54]Connected from 127.0.0.1:61115 Properties: {}[EOL]
[2019-11-12 07:49:53,877][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,877][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Executing server command "SEND RESPONSE (220)" Properties: {}[EOL]
[2019-11-12 07:49:53,877][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:27]220 FTP Server Ready Properties: {}[EOL]
[2019-11-12 07:49:53,877][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,879][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:54]USER ftp Properties: {}[EOL]
[2019-11-12 07:49:53,880][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:54]Executing server command "SEND RESPONSE (331)" Properties: {}[EOL]
[2019-11-12 07:49:53,880][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:54]331 User ftp logged in, needs password Properties: {}[EOL]
[2019-11-12 07:49:53,880][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:54]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,884][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]PASS **************** (password omitted) Properties: {}[EOL]
[2019-11-12 07:49:53,885][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Executing server command "SEND RESPONSE (230)" Properties: {}[EOL]
[2019-11-12 07:49:53,885][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:27]230 Password ok, FTP server ready Properties: {}[EOL]
[2019-11-12 07:49:53,885][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,892][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]OPTS utf8 on Properties: {}[EOL]
[2019-11-12 07:49:53,893][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Executing server command "SEND RESPONSE (200)" Properties: {}[EOL]
[2019-11-12 07:49:53,893][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:27]200 Command okay. Properties: {}[EOL]
[2019-11-12 07:49:53,893][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,905][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:57]PWD  Properties: {}[EOL]
[2019-11-12 07:49:53,905][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:57]Executing server command "SEND RESPONSE (257)" Properties: {}[EOL]
[2019-11-12 07:49:53,905][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:57]257 "/" Properties: {}[EOL]
[2019-11-12 07:49:53,906][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:57]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,925][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:57]DELE sensordata/xxx.arf Properties: {}[EOL]
[2019-11-12 07:49:53,926][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:57]Executing server command "SEND RESPONSE (250)" Properties: {}[EOL]
[2019-11-12 07:49:53,926][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:57]250 File deleted successfully. Properties: {}[EOL]
[2019-11-12 07:49:53,926][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:57]Wait to read server commands Properties: {}[EOL]
[2019-11-12 07:49:53,932][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]QUIT  Properties: {}[EOL]
[2019-11-12 07:49:53,933][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Executing server command "SEND RESPONSE (221)" Properties: {}[EOL]
[2019-11-12 07:49:53,933][ST][DBG][Logger:FubarDev.FtpServer.ServerCommandHandlers.SendResponseServerCommandHandler][Thread:27]221 Service closing control connection. Properties: {}[EOL]
[2019-11-12 07:49:53,933][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Executing server command "CLOSE CONNECTION" Properties: {}[EOL]
[2019-11-12 07:49:53,933][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]StopAsync called Properties: {}[EOL]
[2019-11-12 07:49:53,934][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]Stopped sending responses Properties: {}[EOL]
[2019-11-12 07:49:53,934][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:59]Stopped reading commands Properties: {}[EOL]
[2019-11-12 07:49:53,936][ST][DBG][Logger:FubarDev.FtpServer.FtpConnection][Thread:27]StopAsync called Properties: {}[EOL]
[2019-11-12 07:49:53,941][ST][WRN][Logger:StreamPipeWriterService:Socket:Transmit][Thread:54]Flush failed with: Reading is already in progress.
 Properties: {}System.InvalidOperationException: Reading is already in progress.
   at System.IO.Pipelines.ThrowHelper.ThrowInvalidOperationException_AlreadyReading()
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.TryRead(ReadResult& result)
   at FubarDev.FtpServer.Networking.StreamPipeWriterService.FlushAsync(Stream stream, PipeReader reader, CancellationToken cancellationToken) in d:\a\1\s\src\FubarDev.FtpServer\Networking\StreamPipeWriterService.cs:line 141
   at FubarDev.FtpServer.Networking.StreamPipeWriterService.SafeFlushAsync(CancellationToken cancellationToken) in d:\a\1\s\src\FubarDev.FtpServer\Networking\StreamPipeWriterService.cs:line 181
[EOL]
[2019-11-12 07:49:53,950][ST][INF][Logger:FubarDev.FtpServer.FtpConnection][Thread:54]Connection closed Properties: {}[EOL]
fubar-coder commented 5 years ago

This error only appears when there is a ReadAsync or TryRead without an AdvanceTo, but I'm unable to reproduce the problem. I'll try to make a blind fix. Please test it with 3.1.2-ci.23 as soon as it's published (I guess in ca. 1 hour). Thank you in advance.

fubar-coder commented 5 years ago

You can download the packages from the following feed:

https://pkgs.dev.azure.com/fubar-development/ftp-server/_packaging/ftp-server-ci-builds%40Prerelease/nuget/v3/index.json

twodogmbh commented 5 years ago

Thank you for the fix. With the version 3.1.2-ci.23 the exception in the StreamPipeWriterService does not occur anymore. (At least not until now, but I have to continue watching our acceptance tests)

But now I get sporadically the following exception on the client side. When trying to call a FTP delete command:

System.Net.WebException: Unable to connect to the remote server
   at System.Net.FtpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   at System.Net.WebRequest.<>c.<GetResponseAsync>b__68_2(IAsyncResult iar)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)

There is no exception in the FTP server log. When I call the command 100ms later again it is successful. This never happened in the previous versions. I don't know if this could issue could be related to your latest changes.

fubar-coder commented 5 years ago

Is it possible for you to provide a unit test?

I also promoted 3.1.2-ci.42 to prerelease status where I fixed some corner cases (including an ObjectDisposedException).

EDIT: Maybe it's a saturation of the connection handling code. I had a similar (or the same) problem when I used the unit test for #82 and increased the maximum number of concurrent connections to 500.

EDIT 2: Yes, it seems like it's the same problem:

FubarDev.FtpServer.Tests.Issues.Issue82ProtocolViolation.TestParallelRequests

System.Net.WebException : Unable to connect to the remote server
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw(Exception source)
   at System.Net.FtpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   at System.Net.WebRequest.<>c.<GetResponseAsync>b__68_2(IAsyncResult iar)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at FubarDev.FtpServer.Tests.Issues.Issue82ProtocolViolation.GetFilesAsync() in D:\OpenSource\FtpServer\test\FubarDev.FtpServer.Tests\Issues\Issue82ProtocolViolation.cs:line 46
   at FubarDev.FtpServer.Tests.Issues.Issue82ProtocolViolation.TestParallelRequests() in D:\OpenSource\FtpServer\test\FubarDev.FtpServer.Tests\Issues\Issue82ProtocolViolation.cs:line 34
--- End of stack trace from previous location where exception was thrown ---

EDIT 3: It seems unlikely that I can improve this situation, so I suggest that you use some tool like Polly or request throttling.