public async Task <bool> Run()
{
_logger.LogInformation($"Starting creating successful scan entry for the {{{TraceConstant.PackageId}}} " +
$"{{{TraceConstant.PackageVersion}}}",
PackageId,
PackageVersion);
var package = await Util.GetPackage(
_galleryBaseAddress,
_feed,
PackageId,
PackageVersion,
includeDownloadUrl : false);
if (package == null)
{
_logger.LogError($"Unable to find {{{TraceConstant.PackageId}}} " +
$"{{{TraceConstant.PackageVersion}}}. Terminating.",
PackageId,
PackageVersion);
return(false);
}
_logger.LogInformation($"Found package {{{TraceConstant.PackageId}}} " +
$"{{{TraceConstant.PackageVersion}}}",
package.Id,
package.Version);
string packageVersion = package.GetVersion();
PackageValidationAuditEntry[] entries = new[] { new PackageValidationAuditEntry {
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = VcsValidator.ValidatorName,
Message = $"{_alias} marked the package as scanned clean, comment: {_comment}",
EventId = ValidationEvent.PackageClean,
} };
_logger.LogInformation($"Marking the {{{TraceConstant.PackageId}}} " +
$"{{{TraceConstant.PackageVersion}}} " +
$"as clean with comment: {{{TraceConstant.Comment}}}. " +
$"Requested by {{{TraceConstant.Alias}}}",
package.Id,
packageVersion,
_comment,
_alias);
await _packageValidationAuditor.WriteAuditEntriesAsync(_validationId, package.Id, packageVersion, entries);
return(true);
}
private async Task ProcessRequest(Stream requestBody)
{
using (var bodyStreamReader = new StreamReader(requestBody))
{
bool processedRequest = false;
var body = await bodyStreamReader.ReadToEndAsync();
var result = _callbackParser.ParseSoapMessage(body);
// Find our validation
Guid validationId;
PackageValidationEntity validationEntity = null;
if (Guid.TryParse(result.SrcId, out validationId))
{
validationEntity = await _packageValidationTable.GetValidationAsync(validationId);
if (validationEntity == null)
{
processedRequest = true;
_logger.TrackValidatorResult(VcsValidator.ValidatorName, validationId, TraceConstant.RequestNotFound, validationEntity.PackageId, validationEntity.PackageVersion);
// Notify us about the fact that no valiation was found
await _notificationService.SendNotificationAsync(
"vcscallback-notfound",
"Validation " + validationId + " was not found.",
body);
}
else
{
if (validationEntity.GetCompletedValidatorsList().Contains(VcsValidator.ValidatorName))
{
_logger.LogInformation($"Package already processed for validation {{{TraceConstant.ValidationId}}} " +
"with state={State}, result={Result} " +
$"for package {{{TraceConstant.PackageId}}} " +
$"v. {{{TraceConstant.PackageVersion}}}",
validationId,
result.State,
result.Result,
validationEntity.PackageId,
validationEntity.PackageVersion);
return;
}
}
}
// Determine state of the VCS callback
if (validationEntity != null)
{
_logger.LogInformation($"Got VCS callback for validation {{{TraceConstant.ValidationId}}} " +
"with state={State}, result={Result} " +
$"for package {{{TraceConstant.PackageId}}} " +
$"v. {{{TraceConstant.PackageVersion}}}",
validationId,
result.State,
result.Result,
validationEntity.PackageId,
validationEntity.PackageVersion);
// "The Request is in Manual State and the Request is cancelled."
// This denotes a manual verification is being carried out or has been carried out.
if ((result.State == State.Complete || result.State == State.Released) &&
(result.Result == "Canceled" || result.Result == "Cancelled"))
{
processedRequest = true;
var services = result.Services?.Service;
if (services != null && services.Any(s => s.Name == "Scan" && s.State == "Complete" && s.Result == "Canceled"))
{
// Package scanned unclean
validationEntity.ValidatorCompleted(VcsValidator.ValidatorName, ValidationResult.Failed);
await _packageValidationTable.StoreAsync(validationEntity);
_logger.TrackValidatorResult(VcsValidator.ValidatorName, validationId, TraceConstant.PackageUnclean, validationEntity.PackageId, validationEntity.PackageVersion);
var auditEntries = new List <PackageValidationAuditEntry>();
auditEntries.Add(new PackageValidationAuditEntry
{
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = VcsValidator.ValidatorName,
Message = "Package did not scan clean.",
EventId = ValidationEvent.PackageNotClean,
});
if (result.ResultReasons?.ResultReason != null)
{
foreach (var resultReason in result.ResultReasons.ResultReason)
{
auditEntries.Add(new PackageValidationAuditEntry
{
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = VcsValidator.ValidatorName,
Message = resultReason.RefId + " " + resultReason.Result + " " + resultReason.Determination,
EventId = ValidationEvent.NotCleanReason,
});
}
}
await _packageValidationAuditor.WriteAuditEntriesAsync(
validationEntity.ValidationId, validationEntity.PackageId, validationEntity.PackageVersion, auditEntries);
// Notify
await _notificationService.SendNotificationAsync(
$"vcscallback-notclean/{validationEntity.Created.ToString("yyyy-MM-dd")}",
$"Validation {validationId} ({validationEntity.PackageId} {validationEntity.PackageVersion}) returned {result.State} {result.Result}.",
body);
}
else
{
_logger.TrackValidatorResult(VcsValidator.ValidatorName, validationId, TraceConstant.InvestigationNeeded, validationEntity.PackageId, validationEntity.PackageVersion);
// To investigate
await _notificationService.SendNotificationAsync(
$"vcscallback-investigate/{validationEntity.Created.ToString("yyyy-MM-dd")}",
$"Validation {validationId} ({validationEntity.PackageId} {validationEntity.PackageVersion}) returned {result.State} {result.Result}.",
body);
}
}
// "The Request is completed, with either of these four states: Results, Pass, PassWithInfo, PassManual"
// This denotes scan has completed and we have a pass (or results)
if (result.State == State.Complete || result.State == State.Released)
{
if (SuccessResults.Contains(result.Result))
{
// The result is clean.
processedRequest = true;
validationEntity.ValidatorCompleted(VcsValidator.ValidatorName, ValidationResult.Succeeded);
await _packageValidationTable.StoreAsync(validationEntity);
_logger.TrackValidatorResult(VcsValidator.ValidatorName, validationId, ValidationResult.Succeeded.ToString(), validationEntity.PackageId, validationEntity.PackageVersion);
await _packageValidationAuditor.WriteAuditEntryAsync(validationEntity.ValidationId, validationEntity.PackageId, validationEntity.PackageVersion,
new PackageValidationAuditEntry
{
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = VcsValidator.ValidatorName,
Message = "Package scanned clean.",
EventId = ValidationEvent.PackageClean,
});
}
else if (result.Result == "Results" || result.Result == "Fail")
{
// Potential issue, report back
processedRequest = true;
validationEntity.ValidatorCompleted(VcsValidator.ValidatorName, ValidationResult.Failed);
await _packageValidationTable.StoreAsync(validationEntity);
_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. Response: {body}",
EventId = ValidationEvent.ScanFailed,
});
if (result.ResultReasons?.ResultReason != null)
{
foreach (var resultReason in result.ResultReasons.ResultReason)
{
auditEntries.Add(new PackageValidationAuditEntry
{
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = VcsValidator.ValidatorName,
Message = resultReason.RefId + " " + resultReason.Result + " " + resultReason.Determination,
EventId = ValidationEvent.ScanFailureReason,
});
}
}
await _packageValidationAuditor.WriteAuditEntriesAsync(
validationEntity.ValidationId, validationEntity.PackageId, validationEntity.PackageVersion, auditEntries);
// Notify
await _notificationService.SendNotificationAsync(
$"vcscallback-failed/{validationEntity.Created.ToString("yyyy-MM-dd")}",
$"Validation {validationId} ({validationEntity.PackageId} {validationEntity.PackageVersion}) did not scan clean.",
body);
}
}
}
if (!processedRequest)
{
if (validationEntity == null)
{
_logger.LogWarning(
"Callback was not handled for State={State}, Result={Result}. " +
"Request body: {RequestBody}",
result?.State, result?.Result, TruncateString(body, ReasonableBodySize));
}
else
{
_logger.LogWarning(
"Callback was not handled for State={State}, Result={Result}," +
$"{{{TraceConstant.ValidationId}}}, " +
$"Package: {{{TraceConstant.PackageId}}} {{{TraceConstant.PackageVersion}}}. " +
"Request body: {RequestBody}",
result?.State,
result?.Result,
validationEntity.ValidationId,
validationEntity.PackageId,
validationEntity.PackageVersion,
TruncateString(body, ReasonableBodySize));
}
}
}
}
private async Task RunValidationsAsync(IValidator validator)
{
Logger.LogInformation($"{{{TraceConstant.EventName}}}: " +
$"Checking the queue of {{{TraceConstant.ValidatorName}}}",
"ValidatorQueueCheck",
validator.Name);
// Services
var packageValidationTable = new PackageValidationTable(_cloudStorageAccount, _containerName);
var packageValidationAuditor = new PackageValidationAuditor(_cloudStorageAccount, _containerName, LoggerFactory);
var packageValidationQueue = new PackageValidationQueue(_cloudStorageAccount, _containerName, LoggerFactory);
var notificationService = new NotificationService(_cloudStorageAccount, _containerName);
// Get messages to process
var messages = await packageValidationQueue.DequeueAsync(validator.Name, _batchSize, validator.VisibilityTimeout);
foreach (var message in messages)
{
// Audit entry collection to which our validator can write
var auditEntries = new List <PackageValidationAuditEntry>();
var validationResult = ValidationResult.Unknown;
// Deadlettering
if (message.DequeueCount > 10)
{
validationResult = ValidationResult.Deadlettered;
auditEntries.Add(new PackageValidationAuditEntry
{
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = validator.Name,
Message = $"Message has been attempted too many times and is being deadlettered. Aborting validator.",
EventId = ValidationEvent.Deadlettered,
});
}
if (validationResult != ValidationResult.Deadlettered)
{
try
{
// Perform the validation
Logger.LogInformation($"Starting validator {{{TraceConstant.ValidatorName}}} " +
$"for validation {{{TraceConstant.ValidationId}}} " +
$"- package {{{TraceConstant.PackageId}}} " +
$"v. {{{TraceConstant.PackageVersion}}}...",
validator.Name,
message.ValidationId,
message.PackageId,
message.PackageVersion);
validationResult = await validator.ValidateAsync(message, auditEntries);
Logger.LogInformation($"Finished running validator {{{TraceConstant.ValidatorName}}} " +
$"for validation {{{TraceConstant.ValidationId}}} " +
$"- package {{{TraceConstant.PackageId}}} " +
$"v. {{{TraceConstant.PackageVersion}}}. " +
$"Result: {{{TraceConstant.ValidationResult}}}",
validator.Name,
message.ValidationId,
message.PackageId,
message.PackageVersion,
validationResult);
}
catch (Exception ex)
{
// Audit the exception, but do not remove the message yet.
// We want to retry validation on next run.
auditEntries.Add(new PackageValidationAuditEntry
{
Timestamp = DateTimeOffset.UtcNow,
ValidatorName = validator.Name,
Message = $"Exception thrown during validation - {ex.Message}\r\n{ex.StackTrace}",
EventId = ValidationEvent.ValidatorException,
});
Logger.LogError(TraceEvent.ValidatorException, ex,
$"Exception while running validator {{{TraceConstant.ValidatorName}}} " +
$"for validation {{{TraceConstant.ValidationId}}} " +
$"- package {{{TraceConstant.PackageId}}} " +
$"v. {{{TraceConstant.PackageVersion}}}",
validator.Name,
message.ValidationId,
message.PackageId,
message.PackageVersion);
}
}
// Process message
if (validationResult != ValidationResult.Unknown)
{
TrackValidatorResult(validator.Name, message.ValidationId, validationResult.ToString(), message.PackageId, message.PackageVersion);
// Update our tracking entity
var packageValidationEntity = await packageValidationTable.GetValidationAsync(message.ValidationId);
if (packageValidationEntity != null && validationResult != ValidationResult.Asynchronous)
{
packageValidationEntity.ValidatorCompleted(validator.Name, validationResult);
await packageValidationTable.StoreAsync(packageValidationEntity);
}
// Remove the message
await packageValidationQueue.DeleteAsync(validator.Name, message);
}
// Write audit entries
await packageValidationAuditor.WriteAuditEntriesAsync(message.ValidationId, message.PackageId, message.PackageVersion, auditEntries);
// Process failure
if (validationResult == ValidationResult.Failed || validationResult == ValidationResult.Deadlettered)
{
var audit = await packageValidationAuditor.ReadAuditAsync(message.ValidationId, message.PackageId, message.PackageVersion);
await notificationService.SendNotificationAsync(
"validation",
$"Validation {message.ValidationId} ({message.PackageId} {message.PackageVersion}) returned '{validationResult}'",
audit.Humanize());
}
}
Logger.LogInformation($"Done checking the queue of {{{TraceConstant.ValidatorName}}}", validator.Name);
}