Why would I not be getting a response back from the FTP server?

1

A while I back, I created an app which utilized FluentFTP to list and download files from an FTP server. Within the past month, the app started timing out whenever performing any FTP action using the library. I examined the logs generated by FluentFTP and the actions were being performed successfully but it wasn't being disposed properly. I tried both GetListing and Download and ran into the same error. Looking at the stack trace, the common point of failure seems to be happening at GetReply() which the source code says:

Retrieves a reply from the server. Do not execute this method unless you are sure that a reply has been sent, i.e., you executed a command. Doing so will cause the code to hang indefinitely waiting for a server reply that is never coming.

It seems to me that for some reason I'm not getting a response from the FTP server when I should be. However, I'm at a loss as to why. I can use a standalone FTP client like WinSCP without any trouble. The barebones .NET FtpWebRequest and FtpWebResponse also work. I tried testing at home and it works normally. I checked with my IT department and they claim they haven't made any recent changes. I haven't changed my code. This happens regardless of the server I connect to.

Any help would be greatly appreciated.

Here's my test code. (I ran this under vanilla .NET. The timeout also occured under .NET core, it just didn't raise any exceptions):

    private static void ListViaFluentFtp()
    {
        FtpTrace.AddListener(new ConsoleTraceListener());
        var ftpClient = new FtpClient("test.rebex.net", "demo", "password");
        ftpClient.Connect();
        ftpClient.GetListing("/"); //TimeOutException here
    }

Here's the log generated by FleuntFTP:

# Connect()
Status:   Connecting to 195.144.107.198:21
Response: 220 Microsoft FTP Service
Status:   Detected FTP server: WindowsServerIIS
Command:  USER demo
Response: 331 Password required for demo.
Command:  PASS ***
Response: 230 User logged in.
Command:  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
Status:   Text encoding: System.Text.UTF8Encoding
Command:  OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
Command:  SYST
Response: 215 Windows_NT

# GetListing("/", Auto)
Command:  TYPE I
Response: 200 Type set to I.

# OpenPassiveDataStream(AutoPassive, "LIST /", 0)
Command:  EPSV
Response: 229 Entering Extended Passive Mode (|||1033|)
Status:   Connecting to 195.144.107.198:1033
Command:  LIST /
Response: 125 Data connection already open; Transfer starting.
+---------------------------------------+
Listing:  10-27-15  03:46PM       <DIR>          pub
Listing:  04-08-14  03:09PM                  403 readme.txt
-----------------------------------------
Status:   Disposing FtpSocketStream...

# CloseDataStream()
The thread 0x5b4 has exited with code 0 (0x0).
Status:   Disposing FtpSocketStream...
Exception thrown: 'System.TimeoutException' in FluentFTP.dll
An unhandled exception of type 'System.TimeoutException' occurred in FluentFTP.dll
Timed out trying to read data from the socket stream!

Here's the stack trace:

System.TimeoutException
  HResult=0x80131505
  Message=Timed out trying to read data from the socket stream!
  Source=FluentFTP
  StackTrace:
   at FluentFTP.FtpSocketStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at FluentFTP.FtpSocketStream.ReadLine(Encoding encoding)
   at FluentFTP.FtpClient.GetReply()
   at FluentFTP.FtpClient.CloseDataStream(FtpDataStream stream)
   at FluentFTP.FtpDataStream.Close()
   at FluentFTP.FtpClient.GetListingInternal(String listcmd, FtpListOption options, Boolean retry)
   at FluentFTP.FtpClient.GetListing(String path, FtpListOption options)
   at FluentFTP.FtpClient.GetListing(String path)
   at FtPNetTest.Program.Main(String[] args) in C:\Users\jevensen\source\repos\FtpTest\FtPNetTest\Program.cs:line 18

Here's the log for Download (This was before the latest update that effectively ignores the timeout):

# Connect()
Status:   Connecting to 195.144.107.198:21
Response: 220 Microsoft FTP Service
Status:   Detected FTP server: WindowsServerIIS
Command:  USER demo
Response: 331 Password required for demo.
Command:  PASS ***
Response: 230 User logged in.
Command:  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
Status:   Text encoding: System.Text.UTF8Encoding
Command:  OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
Command:  SYST
Response: 215 Windows_NT

# Download("/readme.txt")

# OpenRead("/readme.txt", Binary, 0)
Command:  TYPE I
Response: 200 Type set to I.

# OpenPassiveDataStream(AutoPassive, "RETR /readme.txt", 0)
Command:  EPSV
Response: 229 Entering Extended Passive Mode (|||1027|)
Status:   Connecting to 195.144.107.198:1027
Command:  RETR /readme.txt
Response: 125 Data connection already open; Transfer starting.
Status:   Disposing FtpSocketStream...
The thread 0x4830 has exited with code 0 (0x0).
The thread 0x3f88 has exited with code 0 (0x0).
The thread 0x4c20 has exited with code 0 (0x0).
Status:   Disposing FtpSocketStream...
Status:   Disposing FtpSocketStream...
Exception thrown: 'FluentFTP.FtpException' in FluentFTP.dll
An unhandled exception of type 'FluentFTP.FtpException' occurred in FluentFTP.dll
Error while downloading the file from the server. See InnerException for more info.

The stack trace:

This exception was originally thrown at this call stack:
    FluentFTP.FtpSocketStream.Read(byte[], int, int)
    FluentFTP.FtpSocketStream.ReadLine(System.Text.Encoding)
    FluentFTP.FtpClient.GetReply()
    FluentFTP.FtpClient.DownloadFileInternal(string, System.IO.Stream, long, System.Action<FluentFTP.FtpProgress>)

EDIT: Here are the level 1 logs from WinSCP doing the same thing:

. 2020-01-23 08:55:54.627 --------------------------------------------------------------------------
. 2020-01-23 08:55:54.628 WinSCP Version 5.13 (Build 8172) (OS 10.0.18362 - Windows 10 Enterprise)
. 2020-01-23 08:55:54.629 Configuration: C:\Users\***\Downloads\WinSCP\WinSCP.ini
. 2020-01-23 08:55:54.629 Log level: Debug 1
. 2020-01-23 08:55:54.629 Local account: OFFICE\***
. 2020-01-23 08:55:54.629 Working directory: C:\Users\***\Downloads\WinSCP
. 2020-01-23 08:55:54.629 Process ID: 5352
. 2020-01-23 08:55:54.631 Command-line: "C:\Users\***\Downloads\WinSCP\WinSCP.exe" 
. 2020-01-23 08:55:54.639 Time zone: Current: GMT-8, Standard: GMT-8 (Pacific Standard Time), DST: GMT-7 (Pacific Daylight Time), DST Start: 3/8/2020, DST End: 11/1/2020
. 2020-01-23 08:55:54.639 Login time: Thursday, January 23, 2020 8:55:54 AM
. 2020-01-23 08:55:54.639 --------------------------------------------------------------------------
. 2020-01-23 08:55:54.640 Session name: demo@test.rebex.net (Ad-Hoc site)
. 2020-01-23 08:55:54.640 Host name: test.rebex.net (Port: 21)
. 2020-01-23 08:55:54.640 User name: demo (Password: Yes, Key file: No, Passphrase: No)
. 2020-01-23 08:55:54.640 Transfer Protocol: FTP
. 2020-01-23 08:55:54.640 Ping type: Dummy, Ping interval: 30 sec; Timeout: 15 sec
. 2020-01-23 08:55:54.640 Disable Nagle: No
. 2020-01-23 08:55:54.640 Proxy: None
. 2020-01-23 08:55:54.640 Send buffer: 262144
. 2020-01-23 08:55:54.640 UTF: Auto
. 2020-01-23 08:55:54.640 FTPS: None [Client certificate: No]
. 2020-01-23 08:55:54.640 FTP: Passive: Yes [Force IP: Auto]; MLSD: Auto [List all: Auto]; HOST: Auto
. 2020-01-23 08:55:54.640 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2020-01-23 08:55:54.640 Cache directory changes: Yes, Permanent: Yes
. 2020-01-23 08:55:54.640 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2020-01-23 08:55:54.640 Timezone offset: 0h 0m
. 2020-01-23 08:55:54.640 --------------------------------------------------------------------------
. 2020-01-23 08:55:54.757 Session upkeep
. 2020-01-23 08:55:54.897 Connecting to test.rebex.net ...
. 2020-01-23 08:55:54.963 Connected with test.rebex.net. Waiting for welcome message...
< 2020-01-23 08:55:55.299 220 Microsoft FTP Service
> 2020-01-23 08:55:55.299 USER demo
< 2020-01-23 08:55:55.468 331 Password required for demo.
> 2020-01-23 08:55:55.468 PASS ********
< 2020-01-23 08:55:55.635 230 User logged in.
> 2020-01-23 08:55:55.636 SYST
. 2020-01-23 08:55:55.804 The server is probably running Windows, assuming that directory listing timestamps are affected by DST.
< 2020-01-23 08:55:55.804 215 Windows_NT
> 2020-01-23 08:55:55.804 FEAT
< 2020-01-23 08:55:55.970 211-Extended features supported:
< 2020-01-23 08:55:55.970  LANG EN*
< 2020-01-23 08:55:55.970  UTF8
< 2020-01-23 08:55:55.970  AUTH TLS;TLS-C;SSL;TLS-P;
< 2020-01-23 08:55:55.970  PBSZ
< 2020-01-23 08:55:55.970  PROT C;P;
< 2020-01-23 08:55:55.970  CCC
< 2020-01-23 08:55:55.970  HOST
< 2020-01-23 08:55:55.970  SIZE
< 2020-01-23 08:55:55.973  MDTM
< 2020-01-23 08:55:55.973  REST STREAM
< 2020-01-23 08:55:55.973 211 END
> 2020-01-23 08:55:55.973 OPTS UTF8 ON
< 2020-01-23 08:55:56.140 200 OPTS UTF8 command successful - UTF8 encoding now ON.
. 2020-01-23 08:55:56.140 Session upkeep
. 2020-01-23 08:55:56.193 Connected
. 2020-01-23 08:55:56.193 Got reply 1 to the command 1
. 2020-01-23 08:55:56.193 --------------------------------------------------------------------------
. 2020-01-23 08:55:56.193 Using FTP protocol.
. 2020-01-23 08:55:56.197 Doing startup conversation with host.
. 2020-01-23 08:55:56.197 Session upkeep
> 2020-01-23 08:55:56.207 PWD
< 2020-01-23 08:55:56.373 257 "/" is current directory.
. 2020-01-23 08:55:56.373 Got reply 1 to the command 16
. 2020-01-23 08:55:56.373 Getting current directory name.
. 2020-01-23 08:55:56.440 Retrieving directory listing...
> 2020-01-23 08:55:56.440 TYPE A
< 2020-01-23 08:55:56.607 200 Type set to A.
> 2020-01-23 08:55:56.612 PASV
< 2020-01-23 08:55:56.781 227 Entering Passive Mode (195,144,107,198,4,10).
> 2020-01-23 08:55:56.781 LIST -a
. 2020-01-23 08:55:56.781 Connecting to 195.144.107.198:1034 ...
< 2020-01-23 08:55:56.952 150 Opening ASCII mode data connection.
. 2020-01-23 08:55:57.119 Data connection closed
. 2020-01-23 08:55:57.119 12-03-15  08:14PM       <DIR>          aspnet_client
. 2020-01-23 08:55:57.119 10-27-15  03:46PM       <DIR>          pub
. 2020-01-23 08:55:57.119 04-08-14  03:09PM                  403 readme.txt
< 2020-01-23 08:55:57.119 226 Transfer complete.
. 2020-01-23 08:55:57.119 Directory listing successful
. 2020-01-23 08:55:57.122 Got reply 1 to the command 2
. 2020-01-23 08:55:57.122 Detecting timezone difference...
. 2020-01-23 08:55:57.122 Retrieving file information...
> 2020-01-23 08:55:57.122 PWD
< 2020-01-23 08:55:57.310 257 "/" is current directory.
> 2020-01-23 08:55:57.310 CWD /readme.txt
< 2020-01-23 08:55:57.481 550 The filename, directory name, or volume label syntax is incorrect. 
> 2020-01-23 08:55:57.481 TYPE I
< 2020-01-23 08:55:57.646 200 Type set to I.
> 2020-01-23 08:55:57.646 SIZE /readme.txt
< 2020-01-23 08:55:57.814 213 403
> 2020-01-23 08:55:57.814 MDTM /readme.txt
< 2020-01-23 08:55:57.980 213 20140408140939
. 2020-01-23 08:55:57.980 Retrieving file information successful
. 2020-01-23 08:55:57.980 Got reply 1 to the command 1024
. 2020-01-23 08:55:57.983 Timezone difference of +9 detected using file /readme.txt (Listing: 2014-04-08T23:09:00.000Z, UTF: 2014-04-08T14:09:00.000Z)
. 2020-01-23 08:55:57.984 ..;D;0;1899-12-30T08:00:00.000Z;0;"" [0];"" [0];---------;0
. 2020-01-23 08:55:57.984 aspnet_client;D;0;2015-12-03T19:14:00.000Z;1;"" [0];"" [0];---------;0
. 2020-01-23 08:55:57.984 pub;D;0;2015-10-27T14:46:00.000Z;1;"" [0];"" [0];---------;0
. 2020-01-23 08:55:57.984 readme.txt;-;403;2014-04-08T14:09:00.000Z;1;"" [0];"" [0];---------;0
. 2020-01-23 08:55:57.984 Session upkeep
. 2020-01-23 08:55:58.012 Startup conversation with host finished.
. 2020-01-23 08:55:58.156 Session upkeep
. 2020-01-23 08:55:58.658 Session upkeep
. 2020-01-23 08:55:59.158 Session upkeep
. 2020-01-23 08:55:59.656 Session upkeep
. 2020-01-23 08:56:00.157 Session upkeep
. 2020-01-23 08:56:00.612 Copying 1 files/directories to local directory "C:\Users\***\Documents\" - total size: 403
. 2020-01-23 08:56:00.612   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2020-01-23 08:56:00.612   TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; InclM: ; ResumeL: 0
. 2020-01-23 08:56:00.612   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2020-01-23 08:56:00.615 File: '/readme.txt' [2014-04-08T14:09:00.000Z] [403]
. 2020-01-23 08:56:00.655 Copying "/readme.txt" to local directory started.
. 2020-01-23 08:56:00.655 Binary transfer mode selected.
. 2020-01-23 08:56:00.655 Starting download of /readme.txt
. 2020-01-23 08:56:00.656 Asking user:
. 2020-01-23 08:56:00.656 **Overwrite local file 'readme.txt'?**
. 2020-01-23 08:56:00.656 
. 2020-01-23 08:56:00.656 Destination directory already contains file 'readme.txt'.
. 2020-01-23 08:56:00.656 Choose, if you want to overwrite the file or skip this transfer and keep existing file.
. 2020-01-23 08:56:00.656  
. 2020-01-23 08:56:00.656 New:          403 bytes, 4/8/2014 7:09 AM
. 2020-01-23 08:56:00.656 Existing:     403 bytes, 4/8/2014 7:09:39 AM ()
. 2020-01-23 08:56:01.161 Session upkeep
. 2020-01-23 08:56:01.658 Session upkeep
. 2020-01-23 08:56:01.908 Transfer progress: Transferred: 0, Left: 0:00:00, CPS: 0/s
> 2020-01-23 08:56:01.911 TYPE I
< 2020-01-23 08:56:02.079 200 Type set to I.
> 2020-01-23 08:56:02.079 PASV
< 2020-01-23 08:56:02.245 227 Entering Passive Mode (195,144,107,198,4,6).
> 2020-01-23 08:56:02.245 RETR readme.txt
. 2020-01-23 08:56:02.245 Connecting to 195.144.107.198:1030 ...
< 2020-01-23 08:56:02.597 150 Opening BINARY mode data connection.
. 2020-01-23 08:56:02.746 Data connection closed
< 2020-01-23 08:56:02.746 226 Transfer complete.
. 2020-01-23 08:56:02.747 Preserving timestamp [2014-04-08T14:09:00.000Z]
. 2020-01-23 08:56:02.747 Download successful
. 2020-01-23 08:56:02.747 Got reply 1 to the command 4
. 2020-01-23 08:56:02.748 Transfer done: '/readme.txt' => 'C:\Users\***\Documents\readme.txt' [403]
. 2020-01-23 08:56:02.748 Copying finished: Transferred: 403, Elapsed: 0:00:02, CPS: 2,583/s
. 2020-01-23 08:56:03.163 Session upkeep
. 2020-01-23 08:56:03.660 Session upkeep
. 2020-01-23 08:56:04.156 Session upkeep
. 2020-01-23 08:56:04.654 Session upkeep
. 2020-01-23 08:56:05.157 Session upkeep
. 2020-01-23 08:56:05.661 Session upkeep
. 2020-01-23 08:56:06.174 Got reply 1004 to the command 4
. 2020-01-23 08:56:06.174 Disconnected from server
.net
ftp
fluentftp
asked on Stack Overflow Jan 23, 2020 by greenjaed • edited Jan 29, 2020 by greenjaed

0 Answers

Nobody has answered this question yet.


User contributions licensed under CC BY-SA 3.0