Add initial telemetry service with stub implementation (#317)

Use package key instead of ID/version and add unit tests for OtherRecentValidationSetForPackageExists
Progress on NuGet/NuGetGallery#4652

Author: joelverhagen

.gitignore

@@ -207,3 +207,5 @@ Results.*.xml
 AssemblyInfo.*.cs
 /tests/Validation.Helper.Tests/Validation.Helper.Tests.nuget.props
 /tests/Validation.Common.Tests/Validation.Common.Tests.nuget.props
+/tests/Validation.Common.Tests/Validation.Common.Tests.nuget.targets
+/tests/Validation.Helper.Tests/Validation.Helper.Tests.nuget.targets

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

@@ -25,6 +25,13 @@ public interface IValidationStorageService
         /// <returns>Validation set instance if found, null otherwise.</returns>
         Task<PackageValidationSet> GetValidationSetAsync(Guid validationTrackingId);
 
+        /// <summary>
+        /// Gets the number of validation sets that the provided package key has.
+        /// </summary>
+        /// <param name="packageKey">The package key.</param>
+        /// <returns>The count.</returns>
+        Task<int> GetValidationSetCountAsync(int packageKey);
+
         /// <summary>
         /// Updates the passed <see cref="PackageValidation"/> with the validation result's status,
         /// updates the <see cref="PackageValidation.ValidationStatusTimestamp"/> to current timestamp,
@@ -62,8 +69,7 @@ public interface IValidationStorageService
         /// <param name="currentValidationSetTrackingId">Validation set tracking for the currently processed request.</param>
         /// <returns>True if validation set exists, false otherwise.</returns>
         Task<bool> OtherRecentValidationSetForPackageExists(
-            string packageId,
-            string normalizedVersion,
+            int packageKey,
             TimeSpan recentDuration,
             Guid currentValidationSetTrackingId);
     }

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

@@ -23,6 +23,7 @@
 using NuGet.Services.Configuration;
 using NuGet.Services.KeyVault;
 using NuGet.Services.ServiceBus;
+using NuGet.Services.Validation.Orchestrator.Telemetry;
 using NuGet.Services.Validation.PackageCertificates;
 using NuGet.Services.Validation.PackageSigning;
 using NuGet.Services.Validation.Vcs;
@@ -207,6 +208,7 @@ private void ConfigureJobServices(IServiceCollection services, IConfigurationRoo
             services.AddTransient<ICoreMessageServiceConfiguration, CoreMessageServiceConfiguration>();
             services.AddTransient<ICoreMessageService, CoreMessageService>();
             services.AddTransient<IMessageService, MessageService>();
+            services.AddTransient<ITelemetryService, TelemetryService>();
         }
 
         private static IServiceProvider CreateProvider(IServiceCollection services)

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

@@ -72,6 +72,8 @@
     <Compile Include="Properties\AssemblyInfo.cs" />
     <Compile Include="Properties\AssemblyInfo.*.cs" />
     <Compile Include="SmtpConfiguration.cs" />
+    <Compile Include="Telemetry\ITelemetryService.cs" />
+    <Compile Include="Telemetry\TelemetryService.cs" />
     <Compile Include="ValidationConfiguration.cs" />
     <Compile Include="ValidationConfigurationItem.cs" />
     <Compile Include="ValidationFailureBehavior.cs" />

src/NuGet.Services.Validation.Orchestrator/Telemetry/ITelemetryService.cs

@@ -0,0 +1,82 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using NuGetGallery;
+
+namespace NuGet.Services.Validation.Orchestrator.Telemetry
+{
+    /// <summary>
+    /// The interface used for emitting telemetry from the validation orchestrator.
+    /// </summary>
+    public interface ITelemetryService
+    {
+        /// <summary>
+        /// The duration from when the package was created to when the first validation set was created. This metric
+        /// is not emitted for revalidation requests.
+        /// </summary>
+        void TrackDurationToValidationSetCreation(TimeSpan duration);
+
+        /// <summary>
+        /// A counter metric emitted when a package changes package status. This metric is not emitted if package status
+        /// does not change. This metric is emitted for revalidation if the terminal state changes.
+        /// </summary>
+        /// <param name="fromStatus">The status that the package moved from.</param>
+        /// <param name="toStatus">The status that the package moved tp.</param>
+        void TrackPackageStatusChange(PackageStatus fromStatus, PackageStatus toStatus);
+
+        /// <summary>
+        /// The total duration of all validators. This is the time that the validation set is first created until all of
+        /// the validators have completed. This metric is also emitted for revalidations.
+        /// </summary>
+        /// <param name="duration">The duration.</param>
+        /// <param name="isSuccess">Whether or not all of the validations succeeded.</param>
+        void TrackTotalValidationDuration(TimeSpan duration, bool isSuccess);
+
+        /// <summary>
+        /// A counter metric emitted when a validator fails due to the <see cref="ValidationConfigurationItem.FailAfter"/>
+        /// configuration.
+        /// </summary>
+        /// <param name="validatorType">The validator type (name).</param>
+        void TrackValidatorTimeout(string validatorType);
+
+        /// <summary>
+        /// The total duration of a single validator. This is the time from when the validation is first started until
+        /// when the validation either completes or times out.
+        /// </summary>
+        /// <param name="duration">The duration.</param>
+        /// <param name="validatorType">The validator type (name).</param>
+        /// <param name="isSuccess">Whether or not the validation succeeded.</param>
+        void TrackValidatorDuration(TimeSpan duration, string validatorType, bool isSuccess);
+
+        /// <summary>
+        /// A counter metric emitted when a validator is started.
+        /// </summary>
+        /// <param name="validatorType">The validator type (name).</param>
+        void TrackValidatorStarted(string validatorType);
+
+        /// <summary>
+        /// A counter metric emmitted when a validator reaches a terminal state and potentially persists validation
+        /// issues. A count of zero is emitted if the validator does not produce any issues. This metric is not emitted
+        /// if the validation is still at a non-terminal state.
+        /// </summary>
+        /// <param name="count">The number of issues.</param>
+        /// <param name="validatorType">The validator type (name) that returned the issue list.</param>
+        /// <param name="isSuccess">Whether or not the validation succeeded.</param>
+        void TrackValidationIssueCount(int count, string validatorType, bool isSuccess);
+
+        /// <summary>
+        /// A counter metric emitted when a validation issue is created.
+        /// </summary>
+        /// <param name="validatorType">The validator type (name) the produced the issue.</param>
+        /// <param name="code">The issue code.</param>
+        void TrackValidationIssue(string validatorType, ValidationIssueCode code);
+
+        /// <summary>
+        /// A counter metric emitted when a client-mastered validation issue is emitted.
+        /// </summary>
+        /// <param name="validatorType">The validator type (name) the produced the issue.</param>
+        /// <param name="clientCode">The client code.</param>
+        void TrackClientValidationIssue(string validatorType, string clientCode);
+    }
+}

src/NuGet.Services.Validation.Orchestrator/Telemetry/TelemetryService.cs

@@ -0,0 +1,47 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using NuGetGallery;
+
+namespace NuGet.Services.Validation.Orchestrator.Telemetry
+{
+    public class TelemetryService : ITelemetryService
+    {
+        public void TrackDurationToValidationSetCreation(TimeSpan duration)
+        {
+        }
+
+        public void TrackPackageStatusChange(PackageStatus fromStatus, PackageStatus toStatus)
+        {
+        }
+
+        public void TrackTotalValidationDuration(TimeSpan duration, bool isSuccess)
+        {
+        }
+
+        public void TrackValidationIssue(string validatorType, ValidationIssueCode code)
+        {
+        }
+
+        public void TrackValidationIssueCount(int count, string validatorType, bool isSuccess)
+        {
+        }
+
+        public void TrackValidatorTimeout(string validatorType)
+        {
+        }
+
+        public void TrackValidatorDuration(TimeSpan duration, string validatorType, bool isSuccess)
+        {
+        }
+
+        public void TrackValidatorStarted(string validatorType)
+        {
+        }
+
+        public void TrackClientValidationIssue(string validatorType, string clientCode)
+        {
+        }
+    }
+}

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

@@ -7,8 +7,8 @@
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
+using NuGet.Services.Validation.Orchestrator.Telemetry;
 using NuGetGallery;
-using NuGetGallery.Services;
 
 namespace NuGet.Services.Validation.Orchestrator
 {
@@ -19,6 +19,7 @@ public class ValidationOutcomeProcessor : IValidationOutcomeProcessor
         private readonly IPackageValidationEnqueuer _validationEnqueuer;
         private readonly ValidationConfiguration _validationConfiguration;
         private readonly IMessageService _messageService;
+        private readonly ITelemetryService _telemetryService;
         private readonly ILogger<ValidationOutcomeProcessor> _logger;
 
         public ValidationOutcomeProcessor(
@@ -27,6 +28,7 @@ public ValidationOutcomeProcessor(
             IPackageValidationEnqueuer validationEnqueuer,
             IOptionsSnapshot<ValidationConfiguration> validationConfigurationAccessor,
             IMessageService messageService,
+            ITelemetryService telemetryService,
             ILogger<ValidationOutcomeProcessor> logger)
         {
             _galleryPackageService = galleryPackageService ?? throw new ArgumentNullException(nameof(galleryPackageService));
@@ -40,6 +42,7 @@ public ValidationOutcomeProcessor(
                 ?? throw new ArgumentException($"The {nameof(validationConfigurationAccessor)}.Value property cannot be null",
                     nameof(validationConfigurationAccessor));
             _messageService = messageService ?? throw new ArgumentNullException(nameof(messageService));
+            _telemetryService = telemetryService ?? throw new ArgumentNullException(nameof(telemetryService));
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
         }
 
@@ -63,9 +66,14 @@ ValidationConfigurationItem GetValidationConfigurationItem(string validationName
                     validationSet.ValidationTrackingId,
                     GetFailedValidations(validationSet, GetValidationConfigurationItem));
 
-                if (package.PackageStatusKey != PackageStatus.Available)
+                // The only way we can move to the failed validation state is if the package is currently in the
+                // validating state. This has a beneficial side effect of only sending a failed validation email to the
+                // customer when the package first moves to the failed validation state. If an admin comes along and
+                // revalidates the package and the package fails validation again, we don't want another email going
+                // out since that would be noisy for the customer.                
+                if (package.PackageStatusKey == PackageStatus.Validating)
                 {
-                    await _galleryPackageService.UpdatePackageStatusAsync(package, PackageStatus.FailedValidation);
+                    await UpdatePackageStatusAsync(package, PackageStatus.FailedValidation);
 
                     var issuesExistAndAllPackageSigned = validationSet
                         .PackageValidations
@@ -85,15 +93,18 @@ ValidationConfigurationItem GetValidationConfigurationItem(string validationName
                 }
                 else
                 {
-                    // The case when validation fails while PackageStatus is Available is the case of 
+                    // The case when validation fails while PackageStatus not validating is the case of 
                     // manual revalidation. In this case we don't want to take package down automatically
-                    // and let the person who requested revalidation to decide how to proceed. User will be
+                    // and let the person who requested revalidation to decide how to proceed. Ops will be
                     // alerted by failed validation monitoring.
-                    _logger.LogInformation("Package {PackageId} {PackageVersion} was available when validation set {ValidationSetId} failed. Will not mark it as failed",
+                    _logger.LogInformation("Package {PackageId} {PackageVersion} was {PackageStatus} when validation set {ValidationSetId} failed. Will not mark it as failed.",
                         package.PackageRegistration.Id,
                         package.NormalizedVersion,
+                        package.PackageStatusKey,
                         validationSet.ValidationTrackingId);
                 }
+
+                TrackTotalValidationDuration(validationSet, isSuccess: false);
             }
             else if (AllValidationsSucceeded(validationSet, GetValidationConfigurationItem))
             {
@@ -116,6 +127,8 @@ ValidationConfigurationItem GetValidationConfigurationItem(string validationName
                     package.PackageRegistration.Id,
                     package.NormalizedVersion,
                     validationSet.ValidationTrackingId);
+
+                TrackTotalValidationDuration(validationSet, isSuccess: true);
             }
             else
             {
@@ -126,6 +139,13 @@ ValidationConfigurationItem GetValidationConfigurationItem(string validationName
             }
         }
 
+        private void TrackTotalValidationDuration(PackageValidationSet validationSet, bool isSuccess)
+        {
+            _telemetryService.TrackTotalValidationDuration(
+                DateTime.UtcNow - validationSet.Created,
+                isSuccess);
+        }
+
         private async Task MoveFileToPublicStorageAndMarkPackageAsAvailable(PackageValidationSet validationSet, Package package)
         {
             _logger.LogInformation("Copying .nupkg to public storage for package {PackageId} {PackageVersion}, validation set {ValidationSetId}",
@@ -142,7 +162,9 @@ private async Task MoveFileToPublicStorageAndMarkPackageAsAvailable(PackageValid
                     package.NormalizedVersion,
                     validationSet.ValidationTrackingId,
                     PackageStatus.Available);
-                await _galleryPackageService.UpdatePackageStatusAsync(package, PackageStatus.Available, commitChanges: true);
+
+                await UpdatePackageStatusAsync(package, PackageStatus.Available);
+
                 _messageService.SendPackagePublishedMessage(package);
             }
             catch (Exception e)
@@ -193,5 +215,17 @@ private bool AnyValidationFailed(
         {
             return GetFailedValidations(packageValidationSet, getValidationConfigurationItem).Any();
         }
+
+        private async Task UpdatePackageStatusAsync(Package package, PackageStatus toStatus)
+        {
+            var fromStatus = package.PackageStatusKey;
+
+            await _galleryPackageService.UpdatePackageStatusAsync(package, toStatus, commitChanges: true);
+
+            if (fromStatus != toStatus)
+            {
+                _telemetryService.TrackPackageStatusChange(fromStatus, toStatus);
+            }
+        }
     }
 }

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

@@ -7,6 +7,7 @@
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
+using NuGet.Services.Validation.Orchestrator.Telemetry;
 using NuGetGallery;
 
 namespace NuGet.Services.Validation.Orchestrator
@@ -18,13 +19,15 @@ public class ValidationSetProcessor : IValidationSetProcessor
         private readonly IValidationStorageService _validationStorageService;
         private readonly ValidationConfiguration _validationConfiguration;
         private readonly ICorePackageFileService _packageFileService;
+        private readonly ITelemetryService _telemetryService;
         private readonly ILogger<ValidationSetProcessor> _logger;
 
         public ValidationSetProcessor(
             IValidatorProvider validatorProvider,
             IValidationStorageService validationStorageService,
             IOptionsSnapshot<ValidationConfiguration> validationConfigurationAccessor,
             ICorePackageFileService packageFileService,
+            ITelemetryService telemetryService,
             ILogger<ValidationSetProcessor> logger)
         {
             _validatorProvider = validatorProvider ?? throw new ArgumentNullException(nameof(validatorProvider));
@@ -35,6 +38,7 @@ public ValidationSetProcessor(
             }
             _validationConfiguration = validationConfigurationAccessor.Value ?? throw new ArgumentException($"The Value property cannot be null", nameof(validationConfigurationAccessor));
             _packageFileService = packageFileService ?? throw new ArgumentNullException(nameof(packageFileService));
+            _telemetryService = telemetryService ?? throw new ArgumentNullException(nameof(telemetryService));
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
         }
 
@@ -195,6 +199,8 @@ private async Task<bool> ProcessNotStartedValidations(PackageValidationSet valid
                     else
                     {
                         await _validationStorageService.MarkValidationStartedAsync(packageValidation, validationResult);
+
+                        _telemetryService.TrackValidatorStarted(packageValidation.Type);
                     }
 
                     tryMoreValidations = tryMoreValidations || validationResult.Status == ValidationStatus.Succeeded;
@@ -232,6 +238,9 @@ private async Task ProcessIncompleteValidation(PackageValidation packageValidati
                     packageValidation.PackageValidationSet.PackageNormalizedVersion,
                     validationConfiguration.FailAfter);
                 await _validationStorageService.UpdateValidationStatusAsync(packageValidation, ValidationResult.Failed);
+
+                _telemetryService.TrackValidatorTimeout(packageValidation.Type);
+
                 return;
             }
         }