Added logging of the request body when scanning request was marked as…

… failed (#131)

* Added logging of the request body when scanning request was marked as failed.

* Removed "v."

* Added method to truncate string.
Made body completely logged in audit blob.

src/Validation.Common/TraceHelper.cs

@@ -23,7 +23,7 @@ public static void TrackValidatorResult(this ILogger logger, string validatorNam
                     $"{{{TraceConstant.ValidatorName}}} " +
                     $"ValidationId: {{{TraceConstant.ValidationId}}} " +
                     $"for package {{{TraceConstant.PackageId}}} " +
-                    $"v.{{{TraceConstant.PackageVersion}}} " +
+                    $"{{{TraceConstant.PackageVersion}}} " +
                     $"resulted in {{Result}}",
                 "ValidatorResult",
                 validatorName,
@@ -33,6 +33,34 @@ public static void TrackValidatorResult(this ILogger logger, string validatorNam
                 result);
         }
 
+        /// <summary>
+        /// Tracks the result of the validation with additional information
+        /// </summary>
+        /// <param name="logger">Logger object to use</param>
+        /// <param name="validatorName">The name of validator attempted</param>
+        /// <param name="validationId">Validation ID of the finished validator</param>
+        /// <param name="result">Validation result</param>
+        /// <param name="packageId">Package ID</param>
+        /// <param name="packageVersion">Package name</param>
+        /// <param name="additionalInformation">Additional information you'd want logged</param>
+        public static void TrackValidatorResult(this ILogger logger, string validatorName, Guid validationId, string result, string packageId, string packageVersion, string additionalInformation)
+        {
+            logger.LogInformation($"{{{TraceConstant.EventName}}}: " +
+                    $"{{{TraceConstant.ValidatorName}}} " +
+                    $"ValidationId: {{{TraceConstant.ValidationId}}} " +
+                    $"for package {{{TraceConstant.PackageId}}} " +
+                    $"{{{TraceConstant.PackageVersion}}} " +
+                    $"resulted in {{Result}}, " +
+                    $"additional info: {{AdditionalInformation}}",
+                "ValidatorResult",
+                validatorName,
+                validationId,
+                packageId,
+                packageVersion,
+                result,
+                additionalInformation);
+        }
+
         /// <summary>
         /// Tracks the exception occured during validation
         /// </summary>
@@ -48,7 +76,7 @@ public static void TrackValidatorException(this ILogger logger, string validator
                     $"{{{TraceConstant.EventName}}} " +
                     $"occurred while running {{{TraceConstant.ValidatorName}}} {{{TraceConstant.ValidationId}}}" +
                     $"on package {{{TraceConstant.PackageId}}}" +
-                    $"v. {{{TraceConstant.PackageVersion}}}", 
+                    $"{{{TraceConstant.PackageVersion}}}", 
                 "ValidatorException",
                 validationId,
                 validatorName,

src/Validation.Common/Validators/Vcs/VcsCallbackServer.cs

@@ -28,6 +28,17 @@ public class VcsCallbackServerStartup
         private readonly INotificationService _notificationService;
         private readonly ILogger<VcsCallbackServerStartup> _logger;
 
+        /// <summary>
+        /// Number of body characters to take for logging.
+        /// </summary>
+        /// <remarks>
+        /// Callback service is available to be queried from anywhere and hence the body may be of any size.
+        /// In situations when we want to log the body, we don't want to log potentially Multi-MB bodies, so, 
+        /// we'll only take a "reasonable" (that would fit most of the calls we really expect) amount from 
+        /// the beginning.
+        /// </remarks>
+        private const int ReasonableBodySize = 2048;
+
         private static class State
         {
             public const string Complete = "Complete";
@@ -230,13 +241,18 @@ await _packageValidationAuditor.WriteAuditEntryAsync(validationEntity.Validation
                             validationEntity.ValidatorCompleted(VcsValidator.ValidatorName, ValidationResult.Failed);
                             await _packageValidationTable.StoreAsync(validationEntity);
 
-                            _logger.TrackValidatorResult(VcsValidator.ValidatorName, validationId, ValidationResult.Failed.ToString(), validationEntity.PackageId, validationEntity.PackageVersion);
+                            _logger.TrackValidatorResult(VcsValidator.ValidatorName, 
+                                validationId, 
+                                ValidationResult.Failed.ToString(), 
+                                validationEntity.PackageId, 
+                                validationEntity.PackageVersion, 
+                                TruncateString(body, ReasonableBodySize));
                             var auditEntries = new List<PackageValidationAuditEntry>();
                             auditEntries.Add(new PackageValidationAuditEntry
                             {
                                 Timestamp = DateTimeOffset.UtcNow,
                                 ValidatorName = VcsValidator.ValidatorName,
-                                Message = "Package scan failed."
+                                Message = $"Package scan failed. Response: {body}"
                             });
 
                             if (result.ResultReasons?.ResultReason != null)
@@ -266,15 +282,30 @@ await _notificationService.SendNotificationAsync(
 
                 if (!processedRequest)
                 {
-                    // first 1024 bytes of the body are taken in order not to send potentially multi-MB long requests.
-                    // "Normal" callback calls are less than 1024 bytes, but since this service blindly accepts any
-                    // request, we may get some potentially long garbage and don't want it all logged.
                     _logger.LogWarning(
                         "Callback was not handled for State={State}, Result={Result}. " +
                         "Request body: {RequestBody}",
-                        result?.State, result?.Result, body.Substring(0, 1024));
+                        result?.State, result?.Result, TruncateString(body, ReasonableBodySize));
                 }
             }
         }
+
+        /// <summary>
+        /// Truncates the string leaving at most specified amount of characters and adds a "(truncated)" at the end
+        /// if it removes any portion of the string
+        /// </summary>
+        /// <param name="str">String to truncate</param>
+        /// <param name="length">Max amount of characters to keep if truncated</param>
+        /// <returns>Original string if it's length was less than specified length, otherwise, first 'length' characters of the string 
+        /// with "(truncated)" appended.</returns>
+        private static string TruncateString(string str, int length)
+        {
+            if (str.Length <= length)
+            {
+                return str;
+            }
+
+            return str.Substring(0, length) + "(truncated)";
+        }
     }
 }