FluentFTP: OpenRead and Multithreading causes stale data prior to command execution
FTP Server OS: Unix (Ubuntu 22.04)
FTP Server Type: Vsftpd
Client Computer OS: Windows
FluentFTP Version: 47.1.0
Framework: .NETCore 3.1
We are using the library in the azure logic apps FTP connector. One of customers reported an issue where we noticed the GetListing (in the asyncFTPClient) is returning an empty response. On checking the logs we see connection is getting stale somehow .We see these logs Status: Socket has stale data - prior to command execution
In some case it reconnects and gives a response after reconnecting but we notice some cases it returns empty response before reconnect. See logs below in both cases. We also see bunch of Testing connectivity using Socket.Poll() regularly.
We have 2 questions here
- What could cause connections getting stale like we see below?
- In case of stale responses we see empty responses being sent in some cases, could that be a bug?
Unfortunately we were not able to reproduce this with same vsftpd config customer has. But we have a feeling this has something to do with their SSL settings as the issue seemed to never happen with SSL disabled.
Could you share some insights on this?
Logs : Logs when empty response
Status: Testing connectivity using Socket.Poll()...
Status: Testing connectivity using Socket.Poll()...
Status: Testing connectivity using Socket.Poll()...
GetListing("/simulator/ftp/triggerCheck", Modify)
OpenDataStreamAsync("LIST /simulator/ftp/triggerCheck", 0)
OpenPassiveDataStreamAsync(AutoPassive, "LIST /simulator/ftp/triggerCheck", 0)
Status: Socket has stale data - prior to command execution
Logs when it waits for reconnect
> GetListing("/simulator/ftp/triggerCheck", Modify)
> OpenDataStreamAsync("LIST /simulator/ftp/triggerCheck", 0)
> OpenPassiveDataStreamAsync(AutoPassive, "LIST /simulator/ftp/triggerCheck", 0)
Status: Socket has stale data - prior to command execution
Status: The stale data was:
Stale: 226 Transfer complete.
Warning: Reconnect needed due to stale data present on control connection (SslSessionLength: 38)
Status: Command stashed: PASV
Status: Closing/Disposing FtpSocketStream(control connection)
> Connect(True)
Warning: Reconnect (Count: 2)
Status: FluentFTP 47.1.0.0(.NET Standard 2.1)
Status: Connecting to IP #1= ***:21
Status: Waiting for a response
Response: 220 (vsFTPd 3.0.5) [37.111m]
Status: Detected FTP server: VsFTPd
Command: AUTH TLS
Status: Waiting for response to: AUTH TLS
Response: 234 Proceed with negotiation. [3ms]
Status: FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, 44550, 256) [5ms]
Command: USER ***
Status: Waiting for response to: USER ***
Response: 331 Please specify the password. [45ms]
Command: PASS ***
Status: Waiting for response to: PASS ***
Response: 230 Login successful. [50ms]
Command: PBSZ 0
Status: Waiting for response to: PBSZ 0
Response: 200 PBSZ set to 0. [2ms]
Command: PROT P
Status: Waiting for response to: PROT P
Response: 200 PROT now Private. [2ms]
Command: FEAT
Status: Waiting for response to: FEAT
Response: 211-Features:Response: EPRTResponse: EPSVResponse: MDTMResponse: PASVResponse: PBSZResponse: PROTResponse: REST STREAMResponse: SIZEResponse: TVFS
Response: 211 End [5ms]
Status: Text encoding: System.Text.ASCIIEncoding+ASCIIEncodingSealed
Command: SYST
Status: Waiting for response to: SYST
Response: 215 UNIX Type: L8 [2ms]
Status: Listing parser set to: Unix
Command: TYPE I
Status: Waiting for response to: TYPE I
Response: 200 Switching to Binary mode. [2ms]
> SetWorkingDirectory("/")
Command: CWD /
Status: Waiting for response to: CWD /
Response: 250 Directory successfully changed. [2ms]
Command: PWD
Status: Waiting for response to: PWD
Response: 257 "/" is the current directory [2ms]
Status: Executing stashed command
Command: PASV
Status: Waiting for response to: PASV
Response: 227 Entering Passive Mode (10,116,2,37,39,33). [4ms]
Status: PASV advertised a non-routable IPAD. Using original connect dnsname/IPAD
Status: Connecting to IP #1= ***:10017
Command: LIST /simulator/ftp/triggerCheck
Status: Waiting for response to: LIST /simulator/ftp/triggerCheck
Response: 150 Here comes the directory listing. [2ms]
Status: FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, 44550, 256) [3ms]
+---------------------------------------+
Listing: -rw-r--r-- 1 2001 2001 12288 Aug 15 13:26 .Data_triggerCheck.txt.swp
Listing: -rw-rw-r-- 1 2001 2001 6 Aug 10 17:33 0357.txt
-----------------------------------------
Status: Closing/Disposing FtpSocketStream(data connection)
> CloseDataStream()
Status: Waiting for response to: LIST /simulator/ftp/triggerCheck
Response: 226 Directory send OK. [16ms]
Status: Closing/Disposing FtpSocketStream(data connection)
Status: Confirmed format Unix
> GetModifiedTime("/simulator/ftp/triggerCheck/.Data_triggerCheck.txt.swp")
Command: MDTM /simulator/ftp/triggerCheck/.Data_triggerCheck.txt.swp
Status: Waiting for response to: MDTM /simulator/ftp/triggerCheck/.Data_triggerCheck.txt.swp
Response: 213 20230815132651 [2ms]
> GetModifiedTime("/simulator/ftp/triggerCheck/0357.txt")
Command: MDTM /simulator/ftp/triggerCheck/0357.txt
Status: Waiting for response to: MDTM /simulator/ftp/triggerCheck/0357.txt
Response: 213 20230810173321 [2ms]
About this issue
- Original URL
- State: open
- Created 10 months ago
- Comments: 34 (1 by maintainers)
@anandgmenon - All latest fixes/changes have been released - https://www.nuget.org/packages/FluentFTP
@FanDjango, sorry for the delay. Was waiting for customers to try out bits with latest master and
IsStillConnected().Good news is the customer with the linux vsftpd server seems to have the issue resolved. We do not see any stale data in the logs anymore and the response of GetListing seems as expected. See logs in case you need them.
However for IBM server mentioned in #1385, even though we don’t see the stale data issue anymore, we somehow still see the File must be specified by library/file.member error. But symptoms are different at different times though. See logs of one scenario here and another one here. I suspect maybe it is unrelated to the original issue with
IsConnected. Could you take another look?Also wondering if the implementation of ~IsSupported~
IsStillConnectedis complete, can we have a release for that? Also if the IBM server issue is unrelated we could reopen #1385 and close this issue after the release probably.Yes, looks like same issue on different servers. I’m trying to get logs based on the latest version using
IsStillConnected()for both the scenarios. But we can have one issue to track bothI suggest we close this issue and you could open a new issue (with logs and so on) for anything going wrong with the new release.
Nuget Released!
Not so fast. I am not finished yet. I’ll tell you.
Yes, I have seen that in the previous log. It is as if, once one thread gets stale data, all other threads also get stale data. One bad thread then corrupts all the others.
I am working this issue here at the moment and must take these things step by step.
Please stand by, as I am in the process of reproducing the problem(s) on my system here.
I have a first question that comes up when I began to study your log, which is very impressive, thank you for that.
Do you use “
OpenRead(...0)” in your code? It is designated obsolete (it is ony for internal use nowadays) and has a serious caveat if you use it in your code: You must pick up the reply message (usingGetReply(...)) yourself, otherwise there is a (stale) message left on the socket? This might be the explanation for the “initial” error that is happening.I would reccomend a recode to use “
Download....” instead.Meanwhile I am investigating the next possible problem with
GetObjectInfo(...).I understand that the actual problem as seen by you is later and I will get to that.
Makes sense, I’ll try to share the logs with client ids attached. Might take a couple of days as its not reproducible from from our end and we need to hear back from the customer