Fix logging statements with incorrect number of parameters (#609)

Address NuGet/NuGetGallery#6618

Author: joelverhagen

src/Validation.Common.Job/Storage/ValidatorStateService.cs

@@ -142,6 +142,7 @@ public async Task<ValidatorStatus> TryAddValidatorStatusAsync(IValidationRequest
                 _logger.LogWarning(
                     Error.ValidatorStateServiceFailedToAddStatus,
                     "Failed to add validation status for {ValidationId} ({PackageId} {PackageVersion}) as a record already exists",
+                    request.ValidationId,
                     request.PackageId,
                     request.PackageVersion);
 
@@ -169,6 +170,7 @@ public async Task<ValidatorStatus> TryUpdateValidationStatusAsync(IValidationReq
                 _logger.LogWarning(
                     Error.ValidatorStateServiceFailedToUpdateStatus,
                     "Failed to save validation status for {ValidationId} ({PackageId} {PackageVersion}) as the current status is stale",
+                    request.ValidationId,
                     request.PackageId,
                     request.PackageVersion);
 

tests/NuGet.Services.Validation.Orchestrator.Tests/ValidatorStateServiceFacts.cs

@@ -3,15 +3,20 @@
 
 using System;
 using System.Collections.Generic;
+using System.Data;
 using System.Data.Entity;
+using System.Data.Entity.Infrastructure;
+using System.Data.SqlClient;
 using System.Linq;
+using System.Reflection;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
 using Moq;
 using NuGet.Jobs.Validation;
 using NuGet.Jobs.Validation.Storage;
 using Tests.ContextHelpers;
 using Xunit;
+using Xunit.Abstractions;
 
 namespace NuGet.Services.Validation
 {
@@ -50,6 +55,10 @@ class BValidator : IValidator
 
         public class TheGetStatusMethod : FactsBase
         {
+            public TheGetStatusMethod(ITestOutputHelper output) : base(output)
+            {
+            }
+
             [Fact]
             public async Task GetStatusReturnsNotStartedIfNoPersistedStatus()
             {
@@ -170,6 +179,10 @@ public async Task GetStatusThrowsOnInvalidValidatorName()
 
         public class TheIsRevalidationRequestMethod : FactsBase
         {
+            public TheIsRevalidationRequestMethod(ITestOutputHelper output) : base(output)
+            {
+            }
+
             [Fact]
             public async Task ReturnsFalseIfPackageHasNeverBeenValidated()
             {
@@ -318,6 +331,10 @@ public async Task ReturnsTrueIfPackageHasBeenValidatedByMultipleValidatorsAndCur
 
         public class TheAddStatusAsyncMethod : FactsBase
         {
+            public TheAddStatusAsyncMethod(ITestOutputHelper output) : base(output)
+            {
+            }
+
             [Fact]
             public async Task AddStatusAsyncThrowsIfValidatorNameIsWrong()
             {
@@ -372,6 +389,10 @@ public async Task AddStatusAsyncMethodPersistsStatus(ValidationStatus status)
 
         public class TheSaveStatusAsyncMethod : FactsBase
         {
+            public TheSaveStatusAsyncMethod(ITestOutputHelper output) : base(output)
+            {
+            }
+
             [Fact]
             public async Task SaveStatusAsyncThrowsIfValidatorNameIsWrong()
             {
@@ -414,13 +435,42 @@ public async Task SaveStatusAsyncMethodPersistsStatus(ValidationStatus status)
 
         public class TheTryAddValidatorStatusAsyncMethod : FactsBase
         {
+            public TheTryAddValidatorStatusAsyncMethod(ITestOutputHelper output) : base(output)
+            {
+            }
+
             private ValidatorStatus NewStatus => new ValidatorStatus
             {
                 ValidationId = ValidationId,
                 PackageKey = PackageKey,
                 ValidatorName = nameof(AValidator),
             };
 
+            [Fact]
+            public async Task HandlesUniqueConstraintViolationGracefully()
+            {
+                // Arrange
+                var exception = new DbUpdateException(
+                    message: "Fail!",
+                    innerException: CreateSqlException(2627, "No can do, friend."));
+                _validationContext
+                    .Setup(x => x.SaveChangesAsync())
+                    .ThrowsAsync(exception);
+
+                _validationContext.Mock(validatorStatusesMock: new Mock<IDbSet<ValidatorStatus>>());
+                var status = NewStatus;
+
+                // Act
+                var result = await _target.TryAddValidatorStatusAsync(
+                    _validationRequest.Object,
+                    status,
+                    ValidationStatus.Succeeded);
+
+                // Assert
+                Assert.Same(status, result);
+                _validationContext.Verify(x => x.ValidatorStatuses, Times.Exactly(2));
+            }
+
             [Fact]
             public async Task PersistsStatus()
             {
@@ -453,6 +503,10 @@ public async Task PersistsStatus()
 
         public class TheTryUpdateValidationStatusAsyncMethod : FactsBase
         {
+            public TheTryUpdateValidationStatusAsyncMethod(ITestOutputHelper output) : base(output)
+            {
+            }
+
             private ValidatorStatus ExistingStatus => new ValidatorStatus
             {
                 ValidationId = ValidationId,
@@ -461,6 +515,30 @@ public class TheTryUpdateValidationStatusAsyncMethod : FactsBase
                 State = ValidationStatus.NotStarted,
             };
 
+            [Fact]
+            public async Task HandlesUniqueConstraintViolationGracefully()
+            {
+                // Arrange
+                var exception = new DbUpdateConcurrencyException("Fail!");
+                _validationContext
+                    .Setup(x => x.SaveChangesAsync())
+                    .ThrowsAsync(exception);
+
+                _validationContext.Mock(validatorStatusesMock: new Mock<IDbSet<ValidatorStatus>>());
+                var status = ExistingStatus;
+                _validationContext.Object.ValidatorStatuses.Add(status);
+
+                // Act
+                var result = await _target.TryUpdateValidationStatusAsync(
+                    _validationRequest.Object,
+                    status,
+                    ValidationStatus.Succeeded);
+
+                // Assert
+                Assert.Same(status, result);
+                _validationContext.Verify(x => x.ValidatorStatuses, Times.Exactly(2));
+            }
+
             [Fact]
             public async Task PersistsStatus()
             {
@@ -484,15 +562,17 @@ public async Task PersistsStatus()
 
         public abstract class FactsBase
         {
+            protected readonly ITestOutputHelper _output;
             protected readonly Mock<IValidationEntitiesContext> _validationContext;
-            protected readonly Mock<ILogger<ValidatorStateService>> _logger;
+            protected readonly ILogger<ValidatorStateService> _logger;
             protected readonly Mock<IValidationRequest> _validationRequest;
             protected readonly ValidatorStateService _target;
 
-            public FactsBase()
+            public FactsBase(ITestOutputHelper output)
             {
+                _output = output ?? throw new ArgumentNullException(nameof(output));
                 _validationContext = new Mock<IValidationEntitiesContext>();
-                _logger = new Mock<ILogger<ValidatorStateService>>();
+                _logger = new LoggerFactory().AddXunit(_output).CreateLogger<ValidatorStateService>();
 
                 _validationRequest = new Mock<IValidationRequest>();
                 _validationRequest.Setup(x => x.NupkgUrl).Returns(NupkgUrl);
@@ -508,7 +588,52 @@ protected ValidatorStateService CreateValidatorStateService(string validatorName
                 => new ValidatorStateService(
                     _validationContext.Object,
                     validatorName,
-                    _logger.Object);
+                    _logger);
+
+            /// <summary>
+            /// Source: http://blog.gauffin.org/2014/08/how-to-create-a-sqlexception/
+            /// </summary>
+            protected SqlException CreateSqlException(int number, string message)
+            {
+                var collectionConstructor = typeof(SqlErrorCollection)
+                    .GetConstructor(
+                        bindingAttr: BindingFlags.NonPublic | BindingFlags.Instance,
+                        binder: null,
+                        types: new Type[0],
+                        modifiers: null);
+                var addMethod = typeof(SqlErrorCollection).GetMethod("Add", BindingFlags.NonPublic | BindingFlags.Instance);
+                var errorCollection = (SqlErrorCollection)collectionConstructor.Invoke(null);
+
+                var errorConstructor = typeof(SqlError).GetConstructor(
+                    bindingAttr: BindingFlags.NonPublic | BindingFlags.Instance,
+                    binder: null,
+                    types: new[]
+                    {
+                        typeof (int), typeof (byte), typeof (byte), typeof (string), typeof(string), typeof (string),
+                        typeof (int), typeof (uint)
+                    },
+                    modifiers: null);
+                var error = errorConstructor.Invoke(new object[]
+                {
+                    number,
+                    (byte)0,
+                    (byte)0,
+                    "server",
+                    "errMsg",
+                    "procedure",
+                    100,
+                    (uint)0
+                });
+
+                addMethod.Invoke(errorCollection, new[] { error });
+
+                var constructor = typeof(SqlException).GetConstructor(
+                    bindingAttr: BindingFlags.NonPublic | BindingFlags.Instance,
+                    binder: null,
+                    types: new[] { typeof(string), typeof(SqlErrorCollection), typeof(Exception), typeof(Guid) },
+                    modifiers: null);
+                return (SqlException)constructor.Invoke(new object[] { message, errorCollection, null, Guid.NewGuid() });
+            }
         }
     }
 }