More appropriate handling of the optional validations in the Orchestrator (#450)

* work in progress

* more work in progress

* Builds and probably passes existing tests

* Fixes and tests

* `Enum.GetValues` instead of explicitly listing the values

* PR issues addressed

* Ignoring exceptions inside allwed to fail validations.

* catch modification

Author: agr

src/NuGet.Services.Validation.Orchestrator/IValidationOutcomeProcessor.cs

@@ -19,7 +19,9 @@ public interface IValidationOutcomeProcessor
         /// </summary>
         /// <param name="validationSet">Current state of validation set</param>
         /// <param name="package">Package information from Gallery DB</param>
+        /// <param name="currentCallStats">Contains information about what happened during current message processing in
+        /// the validation set processor.</param>
         /// <returns>A task that completes when the outcome has been processed</returns>
-        Task ProcessValidationOutcomeAsync(PackageValidationSet validationSet, Package package);
+        Task ProcessValidationOutcomeAsync(PackageValidationSet validationSet, Package package, ValidationSetProcessorResult currentCallStats);
     }
 }

src/NuGet.Services.Validation.Orchestrator/IValidationSetProcessor.cs

@@ -17,7 +17,7 @@ public interface IValidationSetProcessor
         /// </summary>
         /// <param name="validationSet">Validation set to work with. Any validation updates would be reflected in that object upon return.</param>
         /// <param name="package">Gallery DB package information</param>
-        /// <returns>Task object representing async operation</returns>
-        Task ProcessValidationsAsync(PackageValidationSet validationSet, Package package);
+        /// <returns>Information about what happened during processing of the message.</returns>
+        Task<ValidationSetProcessorResult> ProcessValidationsAsync(PackageValidationSet validationSet, Package package);
     }
 }

src/NuGet.Services.Validation.Orchestrator/NuGet.Services.Validation.Orchestrator.csproj

@@ -88,6 +88,7 @@
     <Compile Include="Configuration\ValidationConfigurationItem.cs" />
     <Compile Include="ValidationFailureBehavior.cs" />
     <Compile Include="ValidationPackageFileService.cs" />
+    <Compile Include="ValidationSetProcessorResult.cs" />
     <Compile Include="Vcs\IPackageCriteria.cs" />
     <Compile Include="Vcs\IPackageCriteriaEvaluator.cs" />
     <Compile Include="Vcs\PackageCriteriaEvaluator.cs" />

src/NuGet.Services.Validation.Orchestrator/ValidationMessageHandler.cs

@@ -123,8 +123,8 @@ public async Task<bool> HandleAsync(PackageValidationMessageData message)
                     return true;
                 }
 
-                await _validationSetProcessor.ProcessValidationsAsync(validationSet, package);
-                await _validationOutcomeProcessor.ProcessValidationOutcomeAsync(validationSet, package);
+                var processorStats = await _validationSetProcessor.ProcessValidationsAsync(validationSet, package);
+                await _validationOutcomeProcessor.ProcessValidationOutcomeAsync(validationSet, package, processorStats);
             }
             return true;
         }

src/NuGet.Services.Validation.Orchestrator/ValidationOutcomeProcessor.cs

@@ -52,7 +52,7 @@ public ValidationOutcomeProcessor(
             _validationConfigurationsByName = _validationConfiguration.Validations.ToDictionary(v => v.Name);
         }
 
-        public async Task ProcessValidationOutcomeAsync(PackageValidationSet validationSet, Package package)
+        public async Task ProcessValidationOutcomeAsync(PackageValidationSet validationSet, Package package, ValidationSetProcessorResult currentCallStats)
         {
             var failedValidations = GetFailedValidations(validationSet);
 
@@ -102,9 +102,10 @@ public async Task ProcessValidationOutcomeAsync(PackageValidationSet validationS
                         validationSet.ValidationTrackingId);
                 }
 
-                await CompleteValidationSetAsync(package, validationSet, isSuccess: false);
+                await CleanupValidationStorageAsync(validationSet);
+                TrackValidationSetCompletion(package, validationSet, isSuccess: false);
             }
-            else if (AllValidationsSucceeded(validationSet))
+            else if (AllRequiredValidationsSucceeded(validationSet))
             {
                 _logger.LogInformation("All validations are complete for the package {PackageId} {PackageVersion}, validation set {ValidationSetId}",
                     package.PackageRegistration.Id,
@@ -126,75 +127,28 @@ public async Task ProcessValidationOutcomeAsync(PackageValidationSet validationS
                     _messageService.SendPackagePublishedMessage(package);
                 }
 
-                await CompleteValidationSetAsync(package, validationSet, isSuccess: true);
-            }
-            else
-            {
-                // There are no failed validations and some validations are still in progress. Update
-                // the validation set's Updated field and send a notice if the validation set is taking
-                // too long to complete.
-                var previousUpdateTime = validationSet.Updated;
-
-                await _validationStorageService.UpdateValidationSetAsync(validationSet);
-
-                var validationSetDuration = validationSet.Updated - validationSet.Created;
-                var previousDuration = previousUpdateTime - validationSet.Created;
-
-                // Only send a "validating taking too long" notice once. This is ensured by verifying this is
-                // the package's first validation set and that this is the first time the validation set duration
-                // is greater than the configured threshold. Service Bus message duplication for a single validation
-                // set will not cause multiple notices to be sent due to the row version on PackageValidationSet.
-                if (validationSetDuration > _validationConfiguration.ValidationSetNotificationTimeout &&
-                    previousDuration <= _validationConfiguration.ValidationSetNotificationTimeout &&
-                    await _validationStorageService.GetValidationSetCountAsync(package.Key) == 1)
-                {
-                    _logger.LogWarning("Sending message that validation set {ValidationTrackingId} for package {PackageId} {PackageVersion} is taking too long",
-                        validationSet.ValidationTrackingId,
-                        validationSet.PackageId,
-                        validationSet.PackageNormalizedVersion);
-
-                    _messageService.SendPackageValidationTakingTooLongMessage(package);
-                    _telemetryService.TrackSentValidationTakingTooLongMessage(package.PackageRegistration.Id, package.NormalizedVersion, validationSet.ValidationTrackingId);
-                }
-
-                // Track any validations that are past their expected thresholds.
-                var timedOutValidations = GetIncompleteTimedOutValidations(validationSet);
-
-                if (timedOutValidations.Any())
+                if (currentCallStats.AnyRequiredValidationSucceeded)
                 {
-                    foreach (var validation in timedOutValidations)
-                    {
-                        var duration = DateTime.UtcNow - validation.Started;
-
-                        _logger.LogWarning("Validation {Validation} for package {PackageId} {PackageVersion} is past its expected duration after {Duration}",
-                            validation.Type,
-                            validationSet.PackageId,
-                            validationSet.PackageNormalizedVersion,
-                            duration);
-
-                        _telemetryService.TrackValidatorTimeout(validation.Type);
-                    }
+                    TrackValidationSetCompletion(package, validationSet, isSuccess: true);
                 }
 
-                // Schedule another check if we haven't reached the validation set timeout yet.
-                if (validationSetDuration <= _validationConfiguration.TimeoutValidationSetAfter)
+                if (AreOptionalValidationsRunning(validationSet))
                 {
-                    var messageData = new PackageValidationMessageData(package.PackageRegistration.Id, package.Version, validationSet.ValidationTrackingId);
-                    var postponeUntil = DateTimeOffset.UtcNow + _validationConfiguration.ValidationMessageRecheckPeriod;
-
-                    await _validationEnqueuer.StartValidationAsync(messageData, postponeUntil);
+                    await ScheduleCheckIfNotTimedOut(validationSet, package, tooLongNotificationAllowed: false);
                 }
                 else
                 {
-                    _telemetryService.TrackValidationSetTimeout(package.PackageRegistration.Id, package.NormalizedVersion, validationSet.ValidationTrackingId);
+                    await CleanupValidationStorageAsync(validationSet);
                 }
             }
+            else
+            {
+                await ScheduleCheckIfNotTimedOut(validationSet, package, tooLongNotificationAllowed: true);
+            }
         }
 
-        private async Task CompleteValidationSetAsync(Package package, PackageValidationSet validationSet, bool isSuccess)
+        private void TrackValidationSetCompletion(Package package, PackageValidationSet validationSet, bool isSuccess)
         {
-            await _packageFileService.DeletePackageForValidationSetAsync(validationSet);
-
             _logger.LogInformation("Done processing {PackageId} {PackageVersion} {ValidationSetId} with IsSuccess = {IsSuccess}.",
                 package.PackageRegistration.Id,
                 package.NormalizedVersion,
@@ -204,6 +158,11 @@ private async Task CompleteValidationSetAsync(Package package, PackageValidation
             TrackTotalValidationDuration(validationSet, isSuccess);
         }
 
+        private async Task CleanupValidationStorageAsync(PackageValidationSet validationSet)
+        {
+            await _packageFileService.DeletePackageForValidationSetAsync(validationSet);
+        }
+
         private ValidationConfigurationItem GetValidationConfigurationItemByName(string name)
         {
             _validationConfigurationsByName.TryGetValue(name, out var item);
@@ -218,14 +177,22 @@ private void TrackTotalValidationDuration(PackageValidationSet validationSet, bo
                 isSuccess);
         }
 
-        private bool AllValidationsSucceeded(PackageValidationSet packageValidationSet)
+        private bool AllRequiredValidationsSucceeded(PackageValidationSet packageValidationSet)
         {
             return packageValidationSet
                 .PackageValidations
                 .All(pv => pv.ValidationStatus == ValidationStatus.Succeeded
                     || GetValidationConfigurationItemByName(pv.Type)?.FailureBehavior == ValidationFailureBehavior.AllowedToFail);
         }
 
+        private bool AreOptionalValidationsRunning(PackageValidationSet packageValidationSet)
+        {
+            return packageValidationSet
+                .PackageValidations
+                .Any(pv => pv.ValidationStatus == ValidationStatus.Incomplete
+                    && GetValidationConfigurationItemByName(pv.Type)?.FailureBehavior == ValidationFailureBehavior.AllowedToFail);
+        }
+
         private List<PackageValidation> GetFailedValidations(PackageValidationSet packageValidationSet)
         {
             return packageValidationSet
@@ -251,5 +218,82 @@ bool IsPackageValidationTimedOut(PackageValidation validation)
                 .Where(IsPackageValidationTimedOut)
                 .ToList();
         }
+
+        private async Task<TimeSpan> UpdateValidationDurationAsync(PackageValidationSet validationSet, Package package, bool tooLongNotificationAllowed)
+        {
+            // There are no failed validations and some validations are still in progress. Update
+            // the validation set's Updated field and send a notice if the validation set is taking
+            // too long to complete.
+            var previousUpdateTime = validationSet.Updated;
+
+            await _validationStorageService.UpdateValidationSetAsync(validationSet);
+
+            var validationSetDuration = validationSet.Updated - validationSet.Created;
+            var previousDuration = previousUpdateTime - validationSet.Created;
+
+            // Only send a "validating taking too long" notice once. This is ensured by verifying this is
+            // the package's first validation set and that this is the first time the validation set duration
+            // is greater than the configured threshold. Service Bus message duplication for a single validation
+            // set will not cause multiple notices to be sent due to the row version on PackageValidationSet.
+            if (tooLongNotificationAllowed &&
+                validationSetDuration > _validationConfiguration.ValidationSetNotificationTimeout &&
+                previousDuration <= _validationConfiguration.ValidationSetNotificationTimeout &&
+                await _validationStorageService.GetValidationSetCountAsync(package.Key) == 1)
+            {
+                _logger.LogWarning("Sending message that validation set {ValidationTrackingId} for package {PackageId} {PackageVersion} is taking too long",
+                    validationSet.ValidationTrackingId,
+                    validationSet.PackageId,
+                    validationSet.PackageNormalizedVersion);
+
+                _messageService.SendPackageValidationTakingTooLongMessage(package);
+                _telemetryService.TrackSentValidationTakingTooLongMessage(package.PackageRegistration.Id, package.NormalizedVersion, validationSet.ValidationTrackingId);
+            }
+
+            // Track any validations that are past their expected thresholds.
+            var timedOutValidations = GetIncompleteTimedOutValidations(validationSet);
+
+            if (timedOutValidations.Any())
+            {
+                foreach (var validation in timedOutValidations)
+                {
+                    var duration = DateTime.UtcNow - validation.Started;
+
+                    _logger.LogWarning("Validation {Validation} for package {PackageId} {PackageVersion} is past its expected duration after {Duration}",
+                        validation.Type,
+                        validationSet.PackageId,
+                        validationSet.PackageNormalizedVersion,
+                        duration);
+
+                    _telemetryService.TrackValidatorTimeout(validation.Type);
+                }
+            }
+
+            return validationSetDuration;
+        }
+
+        private async Task ScheduleCheckIfNotTimedOut(PackageValidationSet validationSet, Package package, bool tooLongNotificationAllowed)
+        {
+            var validationSetDuration = await UpdateValidationDurationAsync(validationSet, package, tooLongNotificationAllowed);
+
+            // Schedule another check if we haven't reached the validation set timeout yet.
+            if (validationSetDuration <= _validationConfiguration.TimeoutValidationSetAfter)
+            {
+                var messageData = new PackageValidationMessageData(package.PackageRegistration.Id, package.Version, validationSet.ValidationTrackingId);
+                var postponeUntil = DateTimeOffset.UtcNow + _validationConfiguration.ValidationMessageRecheckPeriod;
+
+                await _validationEnqueuer.StartValidationAsync(messageData, postponeUntil);
+            }
+            else
+            {
+                _logger.LogWarning("Abandoning checking status of validation set {ValidationTrackingId} for " +
+                    "package {PackageId} {PackageVersion} because it took too long (Duration: {Duration}, CutOffDuration: {CutOffDuration})",
+                    validationSet.ValidationTrackingId,
+                    validationSet.PackageId,
+                    validationSet.PackageNormalizedVersion,
+                    validationSetDuration,
+                    _validationConfiguration.TimeoutValidationSetAfter);
+                _telemetryService.TrackValidationSetTimeout(package.PackageRegistration.Id, package.NormalizedVersion, validationSet.ValidationTrackingId);
+            }
+        }
     }
 }