I have this very basic code that downloads a list of text files from an FTP server:
foreach (var fileUri in files)
{
try
{
var ftpRequest = (FtpWebRequest)FtpWebRequest.Create(fileUri);
ftpRequest.Method = WebRequestMethods.Ftp.DownloadFile;
ftpRequest.Credentials = new NetworkCredential("***", "***");
ftpRequest.UseBinary = false;
ftpRequest.Timeout = 10_000;
ftpRequest.ReadWriteTimeout = 10_000;
using (WebResponse response = await ftpRequest.GetResponseAsync().ConfigureAwait(false))
using (var stream = response.GetResponseStream())
{
// Copy the file to an Azure storage
await CopyAsync(stream, container, GetFilename(fileUri), false).ConfigureAwait(false);
}
}
catch (Exception e)
{
Logger.Error(Unknow, $"Error downloading {fileUri.AbsoluteUri}:\n{e}");
}
}
When ran from Visual Studio, this code works perfectly. But when ran as a web job in Azure, it only downloads a couple of files before hanging forever.
I get no timeout or exception.
I added some debug logs and discovered that it's stuck on GetResponseAsync()
.
I tried without the ConfigureAwait(false)
but got the same behaviour.
I also used this answer to check the network traces but all FTP commands I found in the logs were OK. I see the following lines for every file successfully downloaded but don't see any "incomplete" FTP command for the file that's blocking:
System.Net Information: 0 : [22712] FtpWebRequest#2543959::.ctor(ftp://<ftpserver>/<filename>)
System.Net Information: 0 : [21728] FtpWebRequest#2543959::BeginGetResponse(Method=RETR.)
System.Net Information: 0 : [21728] Associating FtpWebRequest#2543959 with FtpControlStream#64735656
System.Net Information: 0 : [21728] FtpControlStream#64735656 - Sending command [PASV]
System.Net Information: 0 : [9444] FtpControlStream#64735656 - Received response [227 Entering Passive Mode (104,45,19,12,117,54).]
System.Net Information: 0 : [9444] FtpControlStream#64735656 - Sending command [RETR <filename>]
System.Net Information: 0 : [17608] FtpControlStream#64735656 - Received response [150 Opening ASCII mode data connection for <filename> (19262 bytes)]
System.Net Information: 0 : [21804] FtpControlStream#64735656 - Received response [226 Transfer complete]
System.Net Information: 0 : [21804] FtpWebRequest#2543959::(Releasing FTP connection#64735656.)
Any help/lead will be greatly appreciated!
EDIT 1
I tried using WebClient
instead of FtpWebRequest
and got the same kind of result. It works perfectly on my machine but when running on Azure as a web job, it downloads a couple of files, and then hangs on the webClient.DownloadFileTaskAsync(...)
line. Also, just to be sure that my uploading to an Azure storage wasn't interfering in the process, I now simply download the files locally. And agin: no exception and no timeout. It just hangs forever.
EDIT 2
I tried removing the line that uploads the file to my Azure storage, just in case, but to no avail. Then, following the first commenter's suggestion, I added a "timeout wrapper" that essentially runs my code as a task, a Task.Delay(10_000)
, and wait for the first task to finish. If the download task finishes first, then everything is good, but if the Task.Delay(10_000)
finishes first, I simply abort the download request and try again. Doing this, I observe the following: at first, files are all downloaded at the first attempt. Then, some files need 2 attempts, and at some point, all files fail despite 10 attempts. So basically, everything starts well but quickly degrades.
Sooo... I feel a little bit dumb but the issue was not in the code as I surmised. It simply was a problem of CPU usage. I eventually discovered (with the help of Azure support) that I had other web jobs on the same App Service Plan and altogether, these web jobs were consuming too much CPU. But frankly, I find the symptoms very misleading.
Anyway, I hope this will help someone in the future.
TL;DR Always check your CPU usage!