Retry storage failures when downloading zip used in Run-From-Package

Author: balag0

src/WebJobs.Script.WebHost/ContainerManagement/LinuxContainerInitializationHostService.cs

@@ -9,6 +9,7 @@
 using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
 using Microsoft.WindowsAzure.Storage.Blob;
+using Microsoft.WindowsAzure.Storage.RetryPolicies;
 using Newtonsoft.Json;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.ContainerManagement
@@ -104,9 +105,14 @@ public virtual async Task<string> Read(string uri)
             // When the blob doesn't exist it just means the container is waiting for specialization.
             // Don't treat this as a failure.
             var cloudBlockBlob = new CloudBlockBlob(new Uri(uri));
-            if (await cloudBlockBlob.ExistsAsync(null, null, _cancellationToken))
+
+            var blobRequestOptions = new BlobRequestOptions
+            {
+                RetryPolicy = new LinearRetry(TimeSpan.FromMilliseconds(500), 3)
+            };
+            if (await cloudBlockBlob.ExistsAsync(blobRequestOptions, null, _cancellationToken))
             {
-                return await cloudBlockBlob.DownloadTextAsync(null, null, null, null, _cancellationToken);
+                return await cloudBlockBlob.DownloadTextAsync(null, null, blobRequestOptions, null, _cancellationToken);
             }
 
             return string.Empty;

src/WebJobs.Script.WebHost/Management/InstanceManager.cs

@@ -3,10 +3,12 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.IO.Compression;
 using System.Net.Http;
 using System.Threading.Tasks;
+using Microsoft.Azure.WebJobs.Script.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.WebHost.Configuration;
 using Microsoft.Azure.WebJobs.Script.WebHost.Models;
 using Microsoft.Extensions.Logging;
@@ -20,17 +22,19 @@ public class InstanceManager : IInstanceManager
         private static HostAssignmentContext _assignmentContext;
 
         private readonly ILogger _logger;
+        private readonly IMetricsLogger _metricsLogger;
         private readonly IEnvironment _environment;
         private readonly IOptionsFactory<ScriptApplicationHostOptions> _optionsFactory;
         private readonly HttpClient _client;
         private readonly IScriptWebHostEnvironment _webHostEnvironment;
 
         public InstanceManager(IOptionsFactory<ScriptApplicationHostOptions> optionsFactory, HttpClient client, IScriptWebHostEnvironment webHostEnvironment,
-            IEnvironment environment, ILogger<InstanceManager> logger)
+            IEnvironment environment, ILogger<InstanceManager> logger, IMetricsLogger metricsLogger)
         {
             _client = client ?? throw new ArgumentNullException(nameof(client));
             _webHostEnvironment = webHostEnvironment ?? throw new ArgumentNullException(nameof(webHostEnvironment));
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
+            _metricsLogger = metricsLogger;
             _environment = environment ?? throw new ArgumentNullException(nameof(environment));
             _optionsFactory = optionsFactory ?? throw new ArgumentNullException(nameof(optionsFactory));
         }
@@ -80,21 +84,40 @@ public async Task<string> ValidateContext(HostAssignmentContext assignmentContex
         {
             _logger.LogInformation($"Validating host assignment context (SiteId: {assignmentContext.SiteId}, SiteName: '{assignmentContext.SiteName}')");
 
-            var zipUrl = assignmentContext.ZipUrl;
-            if (!string.IsNullOrEmpty(zipUrl))
+            string error = null;
+            HttpResponseMessage response = null;
+            try
             {
-                // make sure the zip uri is valid and accessible
-                var request = new HttpRequestMessage(HttpMethod.Head, zipUrl);
-                var response = await _client.SendAsync(request);
-                if (!response.IsSuccessStatusCode)
+                var zipUrl = assignmentContext.ZipUrl;
+                if (!string.IsNullOrEmpty(zipUrl))
                 {
-                    string error = $"Invalid zip url specified (StatusCode: {response.StatusCode})";
-                    _logger.LogError(error);
-                    return error;
+                    // make sure the zip uri is valid and accessible
+                    await Utility.InvokeWithRetriesAsync(async () =>
+                    {
+                        try
+                        {
+                            using (_metricsLogger.LatencyEvent(MetricEventNames.LinuxContainerSpecializationZipHead))
+                            {
+                                var request = new HttpRequestMessage(HttpMethod.Head, zipUrl);
+                                response = await _client.SendAsync(request);
+                                response.EnsureSuccessStatusCode();
+                            }
+                        }
+                        catch (Exception e)
+                        {
+                            _logger.LogError(e, $"{MetricEventNames.LinuxContainerSpecializationZipHead} failed");
+                            throw;
+                        }
+                    }, maxRetries: 2, retryInterval: TimeSpan.FromSeconds(0.3)); // Keep this less than ~1s total
                 }
             }
+            catch (Exception e)
+            {
+                error = $"Invalid zip url specified (StatusCode: {response?.StatusCode})";
+                _logger.LogError(e, "ValidateContext failed");
+            }
 
-            return null;
+            return error;
         }
 
         private async Task Assign(HostAssignmentContext assignmentContext)
@@ -140,32 +163,55 @@ private async Task ApplyContext(HostAssignmentContext assignmentContext)
                 var filePath = Path.GetTempFileName();
                 await DownloadAsync(zipUri, filePath);
 
-                _logger.LogInformation($"Extracting files to '{options.ScriptPath}'");
-                ZipFile.ExtractToDirectory(filePath, options.ScriptPath, overwriteFiles: true);
-                _logger.LogInformation($"Zip extraction complete");
+                using (_metricsLogger.LatencyEvent(MetricEventNames.LinuxContainerSpecializationZipExtract))
+                {
+                    _logger.LogInformation($"Extracting files to '{options.ScriptPath}'");
+                    ZipFile.ExtractToDirectory(filePath, options.ScriptPath, overwriteFiles: true);
+                    _logger.LogInformation($"Zip extraction complete");
+                }
             }
         }
 
         private async Task DownloadAsync(Uri zipUri, string filePath)
         {
-            var zipPath = $"{zipUri.Authority}{zipUri.AbsolutePath}";
-            _logger.LogInformation($"Downloading zip contents from '{zipPath}' to temp file '{filePath}'");
+            string cleanedUrl;
+            Utility.TryCleanUrl(zipUri.AbsoluteUri, out cleanedUrl);
+
+            _logger.LogInformation($"Downloading zip contents from '{cleanedUrl}' to temp file '{filePath}'");
+
+            HttpResponseMessage response = null;
 
-            var response = await _client.GetAsync(zipUri);
-            if (!response.IsSuccessStatusCode)
+            await Utility.InvokeWithRetriesAsync(async () =>
             {
-                string error = $"Error downloading zip content {zipPath}";
-                _logger.LogError(error);
-                throw new InvalidDataException(error);
-            }
+                try
+                {
+                    using (_metricsLogger.LatencyEvent(MetricEventNames.LinuxContainerSpecializationZipDownload))
+                    {
+                        var request = new HttpRequestMessage(HttpMethod.Get, zipUri);
+                        response = await _client.SendAsync(request);
+                        response.EnsureSuccessStatusCode();
+                    }
+                }
+                catch (Exception e)
+                {
+                    string error = $"Error downloading zip content {cleanedUrl}";
+                    _logger.LogError(e, error);
+                    throw;
+                }
 
-            using (var content = await response.Content.ReadAsStreamAsync())
-            using (var stream = new FileStream(filePath, FileMode.Create, FileAccess.Write, FileShare.None, bufferSize: 4096, useAsync: true))
+                _logger.LogInformation($"{response.Content.Headers.ContentLength} bytes downloaded");
+            }, 2, TimeSpan.FromSeconds(0.5));
+
+            using (_metricsLogger.LatencyEvent(MetricEventNames.LinuxContainerSpecializationZipWrite))
             {
-                await content.CopyToAsync(stream);
-            }
+                using (var content = await response.Content.ReadAsStreamAsync())
+                using (var stream = new FileStream(filePath, FileMode.Create, FileAccess.Write, FileShare.None, bufferSize: 4096, useAsync: true))
+                {
+                    await content.CopyToAsync(stream);
+                }
 
-            _logger.LogInformation($"{response.Content.Headers.ContentLength} bytes downloaded");
+                _logger.LogInformation($"{response.Content.Headers.ContentLength} bytes written");
+            }
         }
 
         public IDictionary<string, string> GetInstanceInfo()

src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs

@@ -70,6 +70,7 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi
             services.AddSingleton<IScriptWebHostEnvironment, ScriptWebHostEnvironment>();
             services.AddSingleton<IStandbyManager, StandbyManager>();
             services.TryAddSingleton<IScriptHostBuilder, DefaultScriptHostBuilder>();
+            services.AddSingleton<IMetricsLogger, WebHostMetricsLogger>();
 
             // Linux container services
             services.AddLinuxContainerServices();

src/WebJobs.Script/Diagnostics/MetricEventNames.cs

@@ -37,5 +37,11 @@ public static class MetricEventNames
         public const string SecretManagerAddOrUpdateFunctionSecret = "secretmanager.addorupdatefunctionsecret.{0}";
         public const string SecretManagerSetMasterKey = "secretmanager.setmasterkey.{0}";
         public const string SecretManagerPurgeOldSecrets = "secretmanager.purgeoldsecrets.{0}";
+
+        // Linux container specialization events
+        public const string LinuxContainerSpecializationZipExtract = "linux.container.specialization.zip.extract";
+        public const string LinuxContainerSpecializationZipDownload = "linux.container.specialization.zip.download";
+        public const string LinuxContainerSpecializationZipWrite = "linux.container.specialization.zip.write";
+        public const string LinuxContainerSpecializationZipHead = "linux.container.specialization.zip.head";
     }
 }

src/WebJobs.Script/Utility.cs

@@ -521,6 +521,24 @@ public static bool CheckAppOffline(string scriptPath)
             return false;
         }
 
+        public static bool TryCleanUrl(string url, out string cleaned)
+        {
+            cleaned = null;
+
+            Uri uri = null;
+            if (Uri.TryCreate(url, UriKind.Absolute, out uri))
+            {
+                cleaned = $"{uri.Scheme}://{uri.Host}{uri.AbsolutePath}";
+                if (uri.Query.Length > 0)
+                {
+                    cleaned += "...";
+                }
+                return true;
+            }
+
+            return false;
+        }
+
         private class FilteredExpandoObjectConverter : ExpandoObjectConverter
         {
             public override bool CanWrite => true;

test/WebJobs.Script.Tests.Integration/Management/InstanceManagerTests.cs

@@ -38,7 +38,7 @@ public InstanceManagerTests()
             _scriptWebEnvironment = new ScriptWebHostEnvironment(_environment);
 
             var optionsFactory = new TestOptionsFactory<ScriptApplicationHostOptions>(new ScriptApplicationHostOptions());
-            _instanceManager = new InstanceManager(optionsFactory, _httpClient, _scriptWebEnvironment, _environment, loggerFactory.CreateLogger<InstanceManager>());
+            _instanceManager = new InstanceManager(optionsFactory, _httpClient, _scriptWebEnvironment, _environment, loggerFactory.CreateLogger<InstanceManager>(), new TestMetricsLogger());
 
             InstanceManager.Reset();
         }
@@ -162,7 +162,10 @@ public async Task ValidateContext_InvalidZipUrl_ReturnsError()
             var logs = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
             Assert.Collection(logs,
                 p => Assert.StartsWith("Validating host assignment context (SiteId: 1234, SiteName: 'TestSite')", p),
-                p => Assert.StartsWith("Invalid zip url specified (StatusCode: NotFound)", p));
+                p => Assert.StartsWith("linux.container.specialization.zip.head failed", p),
+                p => Assert.StartsWith("linux.container.specialization.zip.head failed", p),
+                p => Assert.StartsWith("linux.container.specialization.zip.head failed", p),
+                p => Assert.StartsWith("ValidateContext failed", p));
         }
 
         [Fact]

test/WebJobs.Script.Tests/UtilityTests.cs

@@ -322,5 +322,23 @@ public void IsNullable_ReturnsExpectedResult(Type type, bool expected)
         {
             Assert.Equal(expected, Utility.IsNullable(type));
         }
+
+        [Theory]
+        [InlineData("", null, false)]
+        [InlineData(null, null, false)]
+        [InlineData("http://storage.blob.core.windows.net/functions/func.zip?sr=c&si=policy&sig=f%2BGLvBih%2BoFuQvckBSHWKMXwqGJHlPkESmZh9pjnHuc%3D",
+            "http://storage.blob.core.windows.net/functions/func.zip...", true)]
+        [InlineData("http://storage.blob.core.windows.net/functions/func.zip",
+            "http://storage.blob.core.windows.net/functions/func.zip", true)]
+        [InlineData("https://storage.blob.core.windows.net/functions/func.zip",
+            "https://storage.blob.core.windows.net/functions/func.zip", true)]
+        [InlineData("https://storage.blob.core.windows.net/functions/func.zip?",
+            "https://storage.blob.core.windows.net/functions/func.zip...", true)]
+        public void CleanUrlTests(string url, string expectedCleanUrl, bool cleanResult)
+        {
+            string cleanedUrl;
+            Assert.Equal(cleanResult, Utility.TryCleanUrl(url, out cleanedUrl));
+            Assert.Equal(expectedCleanUrl, cleanedUrl);
+        }
     }
 }