[Orchestrator] Add maximum retry count for missing packages (#342)

loic-sharma · web-flow · commit 7fe585017e5e · 2018-02-22T16:13:15.000-05:00
diff --git a/src/NuGet.Services.Validation.Orchestrator/NuGet.Services.Validation.Orchestrator.csproj b/src/NuGet.Services.Validation.Orchestrator/NuGet.Services.Validation.Orchestrator.csproj
@@ -102,7 +102,7 @@
   </ItemGroup>
   <ItemGroup>
     <PackageReference Include="NuGet.Services.Validation.Issues">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
   </ItemGroup>
   <ItemGroup>
diff --git a/src/NuGet.Services.Validation.Orchestrator/Program.cs b/src/NuGet.Services.Validation.Orchestrator/Program.cs
@@ -8,16 +8,14 @@ namespace NuGet.Services.Validation.Orchestrator
 {
     class Program
     {
-        private const string LoggingCategory = "Validation.Orchestrator";
-
         static int Main(string[] args)
         {
             if (!args.Contains(JobArgumentNames.Once))
             {
                 args = args.Concat(new[] { "-" + JobArgumentNames.Once }).ToArray();
             }
             var job = new Job();
-            JobRunner.Run(job, args).Wait();
+            JobRunner.Run(job, args).GetAwaiter().GetResult();
 
             // if configuration validation failed, return non-zero status so we can detect failures in automation
             return job.ConfigurationValidated ? 0 : 1;
diff --git a/src/NuGet.Services.Validation.Orchestrator/Telemetry/ITelemetryService.cs b/src/NuGet.Services.Validation.Orchestrator/Telemetry/ITelemetryService.cs
@@ -79,6 +79,13 @@ public interface ITelemetryService
         /// <param name="clientCode">The client code.</param>
         void TrackClientValidationIssue(string validatorType, string clientCode);
 
+        /// <summary>
+        /// A counter metric emitted when the orchestrator is requested to validate a package,
+        /// but, the package does not exist in the Gallery database even after <see cref="ValidationConfiguration.MissingPackageRetryCount"/>
+        /// retries.
+        /// </summary>
+        void TrackMissingPackageForValidationMessage(string packageId, string normalizedVersion, string validationTrackingId);
+
         /// <summary>
         /// A metric for the case when orchestrator sees a package marked as available, but the blob is missing
         /// in the public container.
diff --git a/src/NuGet.Services.Validation.Orchestrator/Telemetry/TelemetryService.cs b/src/NuGet.Services.Validation.Orchestrator/Telemetry/TelemetryService.cs
@@ -21,6 +21,7 @@ public class TelemetryService : ITelemetryService
         private const string ValidatorDurationSeconds = Prefix + "ValidatorDurationSeconds";
         private const string ValidatorStarted = Prefix + "ValidatorStarted";
         private const string ClientValidationIssue = Prefix + "ClientValidationIssue";
+        private const string MissingPackageForValidationMessage = Prefix + "MissingPackageForValidationMessage";
         private const string MissingNupkgForAvailablePackage = Prefix + "MissingNupkgForAvailablePackage";
 
         private const string FromStatus = "FromStatus";
@@ -140,6 +141,17 @@ public void TrackClientValidationIssue(string validatorType, string clientCode)
                 });
         }
 
+        public void TrackMissingPackageForValidationMessage(string packageId, string normalizedVersion, string validationTrackingId)
+            => _telemetryClient.TrackMetric(
+                    MissingPackageForValidationMessage,
+                    1,
+                    new Dictionary<string, string>
+                    {
+                        { PackageId, packageId },
+                        { NormalizedVersion, normalizedVersion },
+                        { ValidationTrackingId, validationTrackingId },
+                    });
+
         public void TrackMissingNupkgForAvailablePackage(string packageId, string normalizedVersion, string validationTrackingId)
             => _telemetryClient.TrackMetric(
                     MissingNupkgForAvailablePackage,
diff --git a/src/NuGet.Services.Validation.Orchestrator/ValidationConfiguration.cs b/src/NuGet.Services.Validation.Orchestrator/ValidationConfiguration.cs
@@ -21,6 +21,12 @@ public class ValidationConfiguration
         /// </summary>
         public string ValidationStorageConnectionString { get; set; }
 
+        /// <summary>
+        /// How many times the Orchestrator should retry to validate a package
+        /// that is missing from the Gallery database.
+        /// </summary>
+        public int MissingPackageRetryCount { get; set; }
+
         /// <summary>
         /// Time to wait between checking the state of a certain validation.
         /// </summary>
diff --git a/src/NuGet.Services.Validation.Orchestrator/ValidationMessageHandler.cs b/src/NuGet.Services.Validation.Orchestrator/ValidationMessageHandler.cs
@@ -4,30 +4,57 @@
 using System;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 using NuGet.Services.ServiceBus;
+using NuGet.Services.Validation.Orchestrator.Telemetry;
 using NuGetGallery;
 
 namespace NuGet.Services.Validation.Orchestrator
 {
     public class ValidationMessageHandler : IMessageHandler<PackageValidationMessageData>
     {
+        private readonly ValidationConfiguration _configs;
         private readonly ICorePackageService _galleryPackageService;
         private readonly IValidationSetProvider _validationSetProvider;
         private readonly IValidationSetProcessor _validationSetProcessor;
         private readonly IValidationOutcomeProcessor _validationOutcomeProcessor;
+        private readonly ITelemetryService _telemetryService;
         private readonly ILogger<ValidationMessageHandler> _logger;
 
         public ValidationMessageHandler(
+            IOptionsSnapshot<ValidationConfiguration> validationConfigsAccessor,
             ICorePackageService galleryPackageService,
             IValidationSetProvider validationSetProvider,
             IValidationSetProcessor validationSetProcessor,
             IValidationOutcomeProcessor validationOutcomeProcessor,
+            ITelemetryService telemetryService,
             ILogger<ValidationMessageHandler> logger)
         {
+            if (validationConfigsAccessor == null)
+            {
+                throw new ArgumentNullException(nameof(validationConfigsAccessor));
+            }
+
+            if (validationConfigsAccessor.Value == null)
+            {
+                throw new ArgumentException(
+                    $"The {nameof(IOptionsSnapshot<ValidationConfiguration>)}.{nameof(IOptionsSnapshot<ValidationConfiguration>.Value)} property cannot be null",
+                    nameof(validationConfigsAccessor));
+            }
+
+            if (validationConfigsAccessor.Value.MissingPackageRetryCount < 1)
+            {
+                throw new ArgumentOutOfRangeException(
+                    nameof(validationConfigsAccessor),
+                    $"{nameof(ValidationConfiguration)}.{nameof(ValidationConfiguration.MissingPackageRetryCount)} must be at least 1");
+            }
+
+            _configs = validationConfigsAccessor.Value;
             _galleryPackageService = galleryPackageService ?? throw new ArgumentNullException(nameof(galleryPackageService));
             _validationSetProvider = validationSetProvider ?? throw new ArgumentNullException(nameof(validationSetProvider));
             _validationSetProcessor = validationSetProcessor ?? throw new ArgumentNullException(nameof(validationSetProcessor));
             _validationOutcomeProcessor = validationOutcomeProcessor ?? throw new ArgumentNullException(nameof(validationOutcomeProcessor));
+            _telemetryService = telemetryService ?? throw new ArgumentNullException(nameof(telemetryService));
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
         }
 
@@ -48,10 +75,28 @@ public async Task<bool> HandleAsync(PackageValidationMessageData message)
                 if (package == null)
                 {
                     // no package in DB yet. Might have received message a bit early, need to retry later
-                    _logger.LogInformation("Did not find information in DB for package {PackageId} {PackageVersion}",
-                        message.PackageId,
-                        message.PackageVersion);
-                    return false;
+                    if (message.DeliveryCount - 1 >= _configs.MissingPackageRetryCount)
+                    {
+                        _logger.LogWarning("Could not find package {PackageId} {PackageVersion} in DB after {DeliveryCount} tries, dropping message",
+                            message.PackageId,
+                            message.PackageVersion,
+                            message.DeliveryCount);
+
+                        _telemetryService.TrackMissingPackageForValidationMessage(
+                            message.PackageId,
+                            message.PackageVersion,
+                            message.ValidationTrackingId.ToString());
+
+                        return true;
+                    }
+                    else
+                    {
+                        _logger.LogInformation("Could not find package {PackageId} {PackageVersion} in DB, retrying",
+                            message.PackageId,
+                            message.PackageVersion);
+
+                        return false;
+                    }
                 }
 
                 var validationSet = await _validationSetProvider.TryGetOrCreateValidationSetAsync(message.ValidationTrackingId, package);
diff --git a/src/NuGet.Services.Validation.Orchestrator/settings.json b/src/NuGet.Services.Validation.Orchestrator/settings.json
@@ -10,8 +10,9 @@
       }
     ],
     "ValidationStorageConnectionString": "",
+    "MissingPackageRetryCount":  15,
     "ValidationMessageRecheckPeriod": "00:01:00",
-    "NewValidationRequestDeduplicationWindow": "00:10:00"
+    "NewValidationRequestDeduplicationWindow": "00:20:00"
   },
   "Vcs": {
     "ContainerName": "validation",
diff --git a/src/PackageHash/PackageHash.csproj b/src/PackageHash/PackageHash.csproj
@@ -79,7 +79,7 @@
       <Version>1.1.2</Version>
     </PackageReference>
     <PackageReference Include="NuGet.Services.Cursor">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
   </ItemGroup>
   <Import Project="$(MSBuildToolsPath)\Microsoft.CSharp.targets" />
diff --git a/src/Validation.Common.Job/Validation.Common.Job.csproj b/src/Validation.Common.Job/Validation.Common.Job.csproj
@@ -70,16 +70,16 @@
       <Version>4.7.0-preview1-4886</Version>
     </PackageReference>
     <PackageReference Include="NuGet.Services.Configuration">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
     <PackageReference Include="NuGet.Services.Logging">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
     <PackageReference Include="NuGet.Services.Storage">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
     <PackageReference Include="NuGet.Services.Validation">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
     <PackageReference Include="NuGetGallery.Core">
       <Version>4.4.4-dev-23300</Version>
diff --git a/tests/NuGet.Services.Validation.Orchestrator.Tests/NuGet.Services.Validation.Orchestrator.Tests.csproj b/tests/NuGet.Services.Validation.Orchestrator.Tests/NuGet.Services.Validation.Orchestrator.Tests.csproj
@@ -69,7 +69,7 @@
       <Version>4.7.145</Version>
     </PackageReference>
     <PackageReference Include="NuGet.Services.Validation.Issues">
-      <Version>2.14.0</Version>
+      <Version>2.15.0</Version>
     </PackageReference>
     <PackageReference Include="System.Net.Http">
       <Version>4.3.3</Version>
diff --git a/tests/NuGet.Services.Validation.Orchestrator.Tests/ValidationMessageHandlerFacts.cs b/tests/NuGet.Services.Validation.Orchestrator.Tests/ValidationMessageHandlerFacts.cs
@@ -2,10 +2,14 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 using Moq;
+using NuGet.Services.ServiceBus;
+using NuGet.Services.Validation.Orchestrator.Telemetry;
 using NuGetGallery;
 using Xunit;
 
@@ -36,6 +40,44 @@ public async Task WaitsForPackageAvailabilityInGalleryDB()
             CorePackageServiceMock.Verify(ps => ps.FindPackageByIdAndVersionStrict(messageData.PackageId, messageData.PackageVersion), Times.Once());
         }
 
+        [Fact]
+        public async Task DropsMessageAfterMissingPackageRetryCountIsReached()
+        {
+            var validationTrackingId = Guid.NewGuid();
+            var messageData = new PackageValidationMessageData("packageId", "1.2.3", validationTrackingId);
+
+            CorePackageServiceMock
+                .Setup(ps => ps.FindPackageByIdAndVersionStrict("packageId", "1.2.3"))
+                .Returns<Package>(null)
+                .Verifiable();
+
+            TelemetryServiceMock
+                .Setup(t => t.TrackMissingPackageForValidationMessage("packageId", "1.2.3", validationTrackingId.ToString()))
+                .Verifiable();
+
+            var handler = CreateHandler();
+
+            Assert.False(await handler.HandleAsync(OverrideDeliveryCount(messageData, deliveryCount: 1)));
+            Assert.False(await handler.HandleAsync(OverrideDeliveryCount(messageData, deliveryCount: 2)));
+            Assert.True(await handler.HandleAsync(OverrideDeliveryCount(messageData, deliveryCount: 3)));
+
+            CorePackageServiceMock.Verify(ps => ps.FindPackageByIdAndVersionStrict("packageId", "1.2.3"), Times.Exactly(3));
+            TelemetryServiceMock.Verify(t => t.TrackMissingPackageForValidationMessage("packageId", "1.2.3", validationTrackingId.ToString()), Times.Once);
+        }
+
+        private PackageValidationMessageData OverrideDeliveryCount(
+            PackageValidationMessageData messageData,
+            int deliveryCount)
+        {
+            var serializer = new ServiceBusMessageSerializer();
+
+            var realBrokeredMessage = serializer.SerializePackageValidationMessageData(messageData);
+
+            var fakedBrokeredMessage = new MessageWithCustomDeliveryCount(realBrokeredMessage, deliveryCount);
+
+            return serializer.DeserializePackageValidationMessageData(fakedBrokeredMessage);
+        }
+
         [Fact]
         public async Task DropsMessageOnDuplicateValidationRequest()
         {
@@ -63,6 +105,31 @@ public async Task DropsMessageOnDuplicateValidationRequest()
             ValidationSetProviderMock
                 .Verify(vsp => vsp.TryGetOrCreateValidationSetAsync(messageData.ValidationTrackingId, package), Times.Once());
         }
+
+        private class MessageWithCustomDeliveryCount : IBrokeredMessage
+        {
+            private readonly IBrokeredMessage _inner;
+
+            public MessageWithCustomDeliveryCount(IBrokeredMessage inner, int deliveryCount)
+            {
+                _inner = inner;
+                DeliveryCount = deliveryCount;
+            }
+
+            public int DeliveryCount { get; private set; }
+
+            public string GetBody() => _inner.GetBody();
+            public IDictionary<string, object> Properties => _inner.Properties;
+
+            public DateTimeOffset ScheduledEnqueueTimeUtc { get => throw new NotImplementedException(); set => throw new NotImplementedException(); }
+            public DateTimeOffset ExpiresAtUtc => throw new NotImplementedException();
+            public DateTimeOffset EnqueuedTimeUtc => throw new NotImplementedException();
+
+            public Task AbandonAsync() => throw new NotImplementedException();
+            public IBrokeredMessage Clone() => throw new NotImplementedException();
+            public Task CompleteAsync() => throw new NotImplementedException();
+            public void Dispose() => throw new NotImplementedException();
+        }
     }
 
     public class ValidationMessageHandlerLooseFacts : ValidationMessageHandlerFactsBase
@@ -120,28 +187,43 @@ public async Task CallsProcessValidationOutcome()
 
     public class ValidationMessageHandlerFactsBase
     {
+        protected static readonly ValidationConfiguration Configuration = new ValidationConfiguration
+        {
+            MissingPackageRetryCount = 2,
+        };
+
+        protected Mock<IOptionsSnapshot<ValidationConfiguration>> ConfigurationAccessorMock { get; }
         protected Mock<ICorePackageService> CorePackageServiceMock { get; }
         protected Mock<IValidationSetProvider> ValidationSetProviderMock { get; }
         protected Mock<IValidationSetProcessor> ValidationSetProcessorMock { get; }
         protected Mock<IValidationOutcomeProcessor> ValidationOutcomeProcessorMock { get; }
+        protected Mock<ITelemetryService> TelemetryServiceMock { get; }
         protected Mock<ILogger<ValidationMessageHandler>> LoggerMock { get; }
 
         public ValidationMessageHandlerFactsBase(MockBehavior mockBehavior)
         {
+            ConfigurationAccessorMock = new Mock<IOptionsSnapshot<ValidationConfiguration>>();
             CorePackageServiceMock = new Mock<ICorePackageService>(mockBehavior);
             ValidationSetProviderMock = new Mock<IValidationSetProvider>(mockBehavior);
             ValidationSetProcessorMock = new Mock<IValidationSetProcessor>(mockBehavior);
             ValidationOutcomeProcessorMock = new Mock<IValidationOutcomeProcessor>(mockBehavior);
+            TelemetryServiceMock = new Mock<ITelemetryService>(mockBehavior);
             LoggerMock = new Mock<ILogger<ValidationMessageHandler>>(); // we generally don't care about how logger is called, so it's loose all the time
+
+            ConfigurationAccessorMock
+                .SetupGet(ca => ca.Value)
+                .Returns(Configuration);
         }
 
         public ValidationMessageHandler CreateHandler()
         {
             return new ValidationMessageHandler(
+                ConfigurationAccessorMock.Object,
                 CorePackageServiceMock.Object,
                 ValidationSetProviderMock.Object,
                 ValidationSetProcessorMock.Object,
                 ValidationOutcomeProcessorMock.Object,
+                TelemetryServiceMock.Object,
                 LoggerMock.Object);
         }
     }

Original file line number	Diff line number	Diff line change
`@@ -8,16 +8,14 @@ namespace NuGet.Services.Validation.Orchestrator`
`8`	`8`	`{`
`9`	`9`	`class Program`
`10`	`10`	`{`
`11`		`- private const string LoggingCategory = "Validation.Orchestrator";`
`12`		`-`
`13`	`11`	`static int Main(string[] args)`
`14`	`12`	`{`
`15`	`13`	`if (!args.Contains(JobArgumentNames.Once))`
`16`	`14`	`{`
`17`	`15`	`args = args.Concat(new[] { "-" + JobArgumentNames.Once }).ToArray();`
`18`	`16`	`}`
`19`	`17`	`var job = new Job();`
`20`		`- JobRunner.Run(job, args).Wait();`
	`18`	`+ JobRunner.Run(job, args).GetAwaiter().GetResult();`
`21`	`19`
`22`	`20`	`// if configuration validation failed, return non-zero status so we can detect failures in automation`
`23`	`21`	`return job.ConfigurationValidated ? 0 : 1;`