Troubleshooting Azure App Service FTP Login Attempt Issues
Working on a service hosted on Azure App Service and using Azure App Service as FTP I had an issue while downloading multiple files in a loop. After few successfull connections FluentFTP was throwing an error that user cannot log in, and no matter how many retries were specified in FluentFTP options it could not recover. Having some brief investigation, conclusion was that FTP server is an issue here. Thread on Microsoft MSDN (Msdn Thread) stated that 3 connections per second is a limit and since in FTP manner, one CRUD operation is one connection and doing that in a loop, we were easily exceding this limit.
530 User cannot log in log trace:
2021-02-24 14:56:02.601 +00:00 [Information] Status: Connecting to xx.xx.xx.xx:21
2021-02-24 14:56:02.613 +00:00 [Information] Response: 220 Microsoft FTP Service
2021-02-24 14:56:02.614 +00:00 [Information] Status: Detected FTP server: WindowsServerIIS
2021-02-24 14:56:02.617 +00:00 [Information] Command: AUTH TLS
2021-02-24 14:56:02.624 +00:00 [Information] Response: 234 AUTH command ok. Expecting TLS Negotiation.
2021-02-24 14:56:02.629 +00:00 [Information] Status: FTPS Authentication Successful
2021-02-24 14:56:02.630 +00:00 [Information] Command: USER xxx\$xxxftp
2021-02-24 14:56:02.634 +00:00 [Information] Response: 331 Password required
2021-02-24 14:56:02.635 +00:00 [Information] Command: PASS ***
2021-02-24 14:56:02.696 +00:00 [Information] Response: 230 User logged in.
2021-02-24 14:56:02.697 +00:00 [Information] Command: PBSZ 0
2021-02-24 14:56:02.702 +00:00 [Information] Response: 200 PBSZ command successful.
2021-02-24 14:56:02.703 +00:00 [Information] Command: PROT P
2021-02-24 14:56:02.707 +00:00 [Information] Response: 200 PROT command successful.
2021-02-24 14:56:02.708 +00:00 [Information] Command: FEAT
2021-02-24 14:56:02.711 +00:00 [Information] Response: 211 END
2021-02-24 14:56:02.712 +00:00 [Information] Status: Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
2021-02-24 14:56:02.713 +00:00 [Information] Command: OPTS UTF8 ON
2021-02-24 14:56:02.716 +00:00 [Information] Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
2021-02-24 14:56:02.716 +00:00 [Information] Command: SYST
2021-02-24 14:56:02.719 +00:00 [Information] Response: 215 Windows_NT
2021-02-24 14:56:02.720 +00:00 [Information] Command: TYPE I
2021-02-24 14:56:02.723 +00:00 [Information] Response: 200 Type set to I.
2021-02-24 14:56:02.724 +00:00 [Information] Command: PASV
2021-02-24 14:56:02.727 +00:00 [Information] Response: 227 Entering Passive Mode (xx,xxx,xxx,xxx,xx,x).
2021-02-24 14:56:02.728 +00:00 [Information] Status: Connecting to xx.xx.xx.xx:10246
2021-02-24 14:56:02.731 +00:00 [Information] Command: RETR /site/ftp/xxx.pdf
2021-02-24 14:56:02.736 +00:00 [Information] Response: 125 Data connection already open; Transfer starting.
2021-02-24 14:56:02.741 +00:00 [Information] Status: FTPS Authentication Successful
2021-02-24 14:56:02.835 +00:00 [Information] Response: 226 Transfer complete.
2021-02-24 14:56:02.836 +00:00 [Information] Command: QUIT
2021-02-24 14:56:02.842 +00:00 [Information] Response: 221 Goodbye.
2021-02-24 14:56:02.854 +00:00 [Information] Status: Connecting to xx.xxx.xxx.xxx:21
2021-02-24 14:56:02.861 +00:00 [Information] Response: 220 Microsoft FTP Service
2021-02-24 14:56:02.861 +00:00 [Information] Status: Detected FTP server: WindowsServerIIS
2021-02-24 14:56:02.862 +00:00 [Information] Command: AUTH TLS
2021-02-24 14:56:02.865 +00:00 [Information] Response: 234 AUTH command ok. Expecting TLS Negotiation.
2021-02-24 14:56:02.870 +00:00 [Information] Status: FTPS Authentication Successful
2021-02-24 14:56:02.872 +00:00 [Information] Command: USER xxxftp\$xxxftp
2021-02-24 14:56:02.874 +00:00 [Information] Response: 331 Password required
2021-02-24 14:56:02.875 +00:00 [Information] Command: PASS***
2021-02-24 14:56:02.884 +00:00 [Information] Response: 530 User cannot log in.
2021-02-24 14:56:02.884 +00:00 [Information] Command: QUIT
2021-02-24 14:56:02.887 +00:00 [Information] Response: 221 Goodbye.
Workaround to this issue is to use Retry Pattern, which in our case was Polly library. After implementing Polly retry pattern we could successfully complete required operation and longest wait time was 8 seconds until it recovered and logged in correctly to complete download from FTP.
Mockup code below uses Polly with maximum 5 attempts until circuit breaks, each attempt retry wait time is increased by 2 seconds. Unsuccessfull attempt is logged as warning with details about error and total duration time.
private Polly.Retry.RetryPolicy retryPolicy;
public FtpServerDocumentReader()
{
retryPolicy = Policy.Handle<Exception>().WaitAndRetry(5,retryAttempt => TimeSpan.FromSeconds(Math.Pow(2, retryAttempt)),
onRetry: (response, calculatedWaitDuration) =>
{
logger.LogWarning($"Failed attempt. Waited for {calculatedWaitDuration}. Retrying. {response.Message} - {response.StackTrace}");
});
}
private void InitializeFtpConnection(FtpClient _ftpClient)
{
if (!_ftpClient.IsConnected)
{
_ftpClient.EncryptionMode = FtpEncryptionMode.Explicit;
_ftpClient.SslProtocols = SslProtocols.Tls12;
_ftpClient.DataConnectionType = FtpDataConnectionType.PASV;
_ftpClient.RetryAttempts = 10;
_ftpClient.OnLogEvent = OnFTPLogEvent;
_ftpClient.ValidateCertificate += new FtpSslValidation(OnValidateCertificate);
retryPolicy.Execute(() =>
{
_ftpClient.Connect();
});
}
}
private void UploadFile(string filename, byte[] file, FileStorageLocation toLocation = FileStorageLocation.Archive)
{
FtpStatus result = new FtpStatus();
using (var _ftpClient = new FtpClient(_activeAddress, _username, _password))
{
try
{
InitializeFtpConnection(_ftpClient);
result = _ftpClient.Upload(file, $"{GetBaseUrl(toLocation)}/{filename}");
if (result == FtpStatus.Success)
{
_logger.LogInformation($"File {filename} uploaded to {toLocation} on FTP server");
}
}
catch (Exception e)
{
_logger.LogError(e, $"Failed uploading a file to the server. Filename: {filename}, username: {_username}, server: {_archiveAddress}");
}
}
}