Skip to content
This repository was archived by the owner on Jul 30, 2024. It is now read-only.

Commit e8b05bd

Browse files
loic-sharmaloic-sharma
authored
[Package Signing] Improve logging (#376)
Add logging scopes to package signing validation jobs to ease log correlation. Example scenario: find all logs for the Extract and Validate job that are for package X.
1 parent 6050fc6 commit e8b05bd

3 files changed

Lines changed: 154 additions & 143 deletions

File tree

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -166,7 +166,7 @@ await _validationStorageService.GetValidationSetCountAsync(package.Key) == 1)
166166
{
167167
var duration = DateTime.UtcNow - validation.Started;
168168

169-
_logger.LogWarning("Validation {Validation} for package {PackageId} {PackageVersion} has reached the configured failure timeout after duration {Duration}",
169+
_logger.LogWarning("Validation {Validation} for package {PackageId} {PackageVersion} is past its expected duration after {Duration}",
170170
validation.Type,
171171
validationSet.PackageId,
172172
validationSet.PackageNormalizedVersion,

‎src/Validation.PackageSigning.ExtractAndValidateSignature/SignatureValidationMessageHandler.cs‎

Lines changed: 77 additions & 71 deletions
Original file line numberDiff line numberDiff line change
@@ -64,91 +64,97 @@ public async Task<bool> HandleAsync(SignatureValidationMessage message)
6464

6565
private async Task<bool> HandleAsync(SignatureValidationMessage message, CancellationToken cancellationToken)
6666
{
67-
// Find the signature validation entity that matches this message.
68-
var validation = await _validatorStateService.GetStatusAsync(message.ValidationId);
69-
70-
// A signature validation should be queued with ValidatorState == Incomplete.
71-
if (validation == null)
67+
using (_logger.BeginScope("Handling signature validation message for package {PackageId} {PackageVersion}, validation set {ValidationSetId}",
68+
message.PackageId,
69+
message.PackageVersion,
70+
message.ValidationId))
7271
{
73-
_logger.LogInformation(
74-
"Could not find validation entity, requeueing (package: {PackageId} {PackageVersion}, validationId: {ValidationId})",
75-
message.PackageId,
76-
message.PackageVersion,
77-
message.ValidationId);
72+
// Find the signature validation entity that matches this message.
73+
var validation = await _validatorStateService.GetStatusAsync(message.ValidationId);
7874

79-
// Message may be retried.
80-
return false;
81-
}
82-
else if (validation.State == ValidationStatus.NotStarted)
83-
{
84-
_logger.LogWarning(
85-
"Unexpected signature verification status '{ValidatorState}' when 'Incomplete' was expected, requeueing (package id: {PackageId} package version: {PackageVersion} validation id: {ValidationId})",
86-
validation.State,
87-
message.PackageId,
88-
message.PackageVersion,
89-
message.ValidationId);
90-
91-
// Message may be retried.
92-
return false;
93-
}
94-
else if (validation.State != ValidationStatus.Incomplete)
95-
{
96-
_logger.LogWarning(
97-
"Terminal signature verification status '{ValidatorState}' when 'Incomplete' was expected, dropping message (package id: {PackageId} package version: {PackageVersion} validation id: {ValidationId})",
98-
validation.State,
99-
message.PackageId,
100-
message.PackageVersion,
101-
message.ValidationId);
75+
// A signature validation should be queued with ValidatorState == Incomplete.
76+
if (validation == null)
77+
{
78+
_logger.LogInformation(
79+
"Could not find validation entity, requeueing (package: {PackageId} {PackageVersion}, validationId: {ValidationId})",
80+
message.PackageId,
81+
message.PackageVersion,
82+
message.ValidationId);
10283

103-
// Consume the message.
104-
return true;
105-
}
84+
// Message may be retried.
85+
return false;
86+
}
87+
else if (validation.State == ValidationStatus.NotStarted)
88+
{
89+
_logger.LogWarning(
90+
"Unexpected signature verification status '{ValidatorState}' when 'Incomplete' was expected, requeueing (package id: {PackageId} package version: {PackageVersion} validation id: {ValidationId})",
91+
validation.State,
92+
message.PackageId,
93+
message.PackageVersion,
94+
message.ValidationId);
10695

107-
// Validate package
108-
using (var packageStream = await _packageDownloader.DownloadAsync(message.NupkgUri, cancellationToken))
109-
using (var packageWriteStream = new MemoryStream()) // Unused, but to be careful we don't pass the original stream.
110-
using (var package = new SignedPackageArchive(packageStream, packageWriteStream))
111-
{
112-
var result = await _signatureValidator.ValidateAsync(
113-
validation.PackageKey,
114-
package,
115-
message,
116-
cancellationToken);
96+
// Message may be retried.
97+
return false;
98+
}
99+
else if (validation.State != ValidationStatus.Incomplete)
100+
{
101+
_logger.LogWarning(
102+
"Terminal signature verification status '{ValidatorState}' when 'Incomplete' was expected, dropping message (package id: {PackageId} package version: {PackageVersion} validation id: {ValidationId})",
103+
validation.State,
104+
message.PackageId,
105+
message.PackageVersion,
106+
message.ValidationId);
117107

118-
validation.State = result.State;
108+
// Consume the message.
109+
return true;
110+
}
119111

120-
// Save any issues if the resulting state is terminal.
121-
if (validation.State == ValidationStatus.Failed
122-
|| validation.State == ValidationStatus.Succeeded)
112+
// Validate package
113+
using (var packageStream = await _packageDownloader.DownloadAsync(message.NupkgUri, cancellationToken))
114+
using (var packageWriteStream = new MemoryStream()) // Unused, but to be careful we don't pass the original stream.
115+
using (var package = new SignedPackageArchive(packageStream, packageWriteStream))
123116
{
124-
validation.ValidatorIssues = validation.ValidatorIssues ?? new List<ValidatorIssue>();
125-
foreach (var issue in result.Issues)
117+
var result = await _signatureValidator.ValidateAsync(
118+
validation.PackageKey,
119+
package,
120+
message,
121+
cancellationToken);
122+
123+
validation.State = result.State;
124+
125+
// Save any issues if the resulting state is terminal.
126+
if (validation.State == ValidationStatus.Failed
127+
|| validation.State == ValidationStatus.Succeeded)
126128
{
127-
validation.ValidatorIssues.Add(new ValidatorIssue
129+
validation.ValidatorIssues = validation.ValidatorIssues ?? new List<ValidatorIssue>();
130+
foreach (var issue in result.Issues)
128131
{
129-
IssueCode = issue.IssueCode,
130-
Data = issue.Serialize(),
131-
});
132+
validation.ValidatorIssues.Add(new ValidatorIssue
133+
{
134+
IssueCode = issue.IssueCode,
135+
Data = issue.Serialize(),
136+
});
137+
}
132138
}
133139
}
134-
}
135140

136-
// The signature validator should do all of the work to bring this validation to its completion.
137-
if (validation.State != ValidationStatus.Succeeded
138-
&& validation.State != ValidationStatus.Failed)
139-
{
140-
_logger.LogError("The signature validator should have set the status 'Succeeded' or 'Failed', not " +
141-
"'{ValidatorState}' (package id: {PackageId} package version: {PackageVersion} validation id: {ValidationId})",
142-
validation.State,
143-
message.PackageId,
144-
message.PackageVersion,
145-
message.ValidationId);
141+
// The signature validator should do all of the work to bring this validation to its completion.
142+
if (validation.State != ValidationStatus.Succeeded
143+
&& validation.State != ValidationStatus.Failed)
144+
{
145+
_logger.LogError("The signature validator should have set the status 'Succeeded' or 'Failed', not " +
146+
"'{ValidatorState}' (package id: {PackageId} package version: {PackageVersion} validation id: {ValidationId})",
147+
validation.State,
148+
message.PackageId,
149+
message.PackageVersion,
150+
message.ValidationId);
146151

147-
return false;
148-
}
152+
return false;
153+
}
149154

150-
// Save the resulting validation status.
151-
return await SaveStatusAsync(validation, message);
155+
// Save the resulting validation status.
156+
return await SaveStatusAsync(validation, message);
157+
}
152158
}
153159

154160
private async Task<bool> SaveStatusAsync(ValidatorStatus validation, SignatureValidationMessage message)

‎src/Validation.PackageSigning.ValidateCertificate/CertificateValidationMessageHandler.cs‎

Lines changed: 76 additions & 71 deletions
Original file line numberDiff line numberDiff line change
@@ -50,94 +50,99 @@ public CertificateValidationMessageHandler(
5050
/// <returns>Whether the validation completed. If false, the validation should be retried later.</returns>
5151
public async Task<bool> HandleAsync(CertificateValidationMessage message)
5252
{
53-
var validation = await _certificateValidationService.FindCertificateValidationAsync(message);
54-
55-
if (validation == null)
53+
using (_logger.BeginScope("Handling validate certificate message {CertificateKey} {ValidationId}",
54+
message.CertificateKey,
55+
message.ValidationId))
5656
{
57-
_logger.LogInformation(
58-
"Could not find a certificate validation entity, failing (certificate: {CertificateKey} validation: {ValidationId})",
59-
message.CertificateKey,
60-
message.ValidationId);
61-
62-
return false;
63-
}
57+
var validation = await _certificateValidationService.FindCertificateValidationAsync(message);
6458

65-
if (validation.Status != null)
66-
{
67-
// A certificate validation should be queued with a Status of null, and once the certificate validation
68-
// completes, the Status should be updated to a non-null value. Hence, the Status here SHOULD be null.
69-
// A non-null Status may indicate message duplication.
70-
_logger.LogWarning(
71-
"Invalid certificate validation entity's status, dropping message (certificate: {CertificateThumbprint} validation: {ValidationId})",
72-
validation.EndCertificate.Thumbprint,
73-
validation.ValidationId);
59+
if (validation == null)
60+
{
61+
_logger.LogInformation(
62+
"Could not find a certificate validation entity, failing (certificate: {CertificateKey} validation: {ValidationId})",
63+
message.CertificateKey,
64+
message.ValidationId);
7465

75-
return true;
76-
}
66+
return false;
67+
}
7768

78-
if (validation.EndCertificate.Status == EndCertificateStatus.Revoked)
79-
{
80-
if (message.RevalidateRevokedCertificate)
69+
if (validation.Status != null)
8170
{
71+
// A certificate validation should be queued with a Status of null, and once the certificate validation
72+
// completes, the Status should be updated to a non-null value. Hence, the Status here SHOULD be null.
73+
// A non-null Status may indicate message duplication.
8274
_logger.LogWarning(
83-
"Revalidating certificate that is known to be revoked " +
84-
"(certificate: {CertificateThumbprint} validation: {ValidationId})",
85-
validation.EndCertificate.Thumbprint,
86-
validation.ValidationId);
87-
}
88-
else
89-
{
90-
// Do NOT revalidate a certificate that is known to be revoked unless explicitly told to!
91-
// Certificate Authorities are not required to keep a certificate's revocation information
92-
// forever, therefore, revoked certificates should only be revalidated in special cases.
93-
_logger.LogError(
94-
"Certificate known to be revoked MUST be validated with the " +
95-
$"{nameof(CertificateValidationMessage.RevalidateRevokedCertificate)} flag enabled " +
96-
"(certificate: {CertificateThumbprint} validation: {ValidationId})",
75+
"Invalid certificate validation entity's status, dropping message (certificate: {CertificateThumbprint} validation: {ValidationId})",
9776
validation.EndCertificate.Thumbprint,
9877
validation.ValidationId);
9978

10079
return true;
10180
}
102-
}
10381

104-
CertificateVerificationResult result;
82+
if (validation.EndCertificate.Status == EndCertificateStatus.Revoked)
83+
{
84+
if (message.RevalidateRevokedCertificate)
85+
{
86+
_logger.LogWarning(
87+
"Revalidating certificate that is known to be revoked " +
88+
"(certificate: {CertificateThumbprint} validation: {ValidationId})",
89+
validation.EndCertificate.Thumbprint,
90+
validation.ValidationId);
91+
}
92+
else
93+
{
94+
// Do NOT revalidate a certificate that is known to be revoked unless explicitly told to!
95+
// Certificate Authorities are not required to keep a certificate's revocation information
96+
// forever, therefore, revoked certificates should only be revalidated in special cases.
97+
_logger.LogError(
98+
"Certificate known to be revoked MUST be validated with the " +
99+
$"{nameof(CertificateValidationMessage.RevalidateRevokedCertificate)} flag enabled " +
100+
"(certificate: {CertificateThumbprint} validation: {ValidationId})",
101+
validation.EndCertificate.Thumbprint,
102+
validation.ValidationId);
103+
104+
return true;
105+
}
106+
}
105107

106-
using (var certificates = await LoadCertificatesAsync(validation))
107-
{
108-
switch (validation.EndCertificate.Use)
108+
CertificateVerificationResult result;
109+
110+
using (var certificates = await LoadCertificatesAsync(validation))
109111
{
110-
case EndCertificateUse.CodeSigning:
111-
result = _certificateVerifier.VerifyCodeSigningCertificate(
112-
certificates.EndCertificate,
113-
certificates.AncestorCertificates);
114-
break;
115-
116-
case EndCertificateUse.Timestamping:
117-
result = _certificateVerifier.VerifyTimestampingCertificate(
118-
certificates.EndCertificate,
119-
certificates.AncestorCertificates);
120-
break;
121-
122-
default:
123-
throw new InvalidOperationException($"Unknown {nameof(EndCertificateUse)}: {validation.EndCertificate.Use}");
112+
switch (validation.EndCertificate.Use)
113+
{
114+
case EndCertificateUse.CodeSigning:
115+
result = _certificateVerifier.VerifyCodeSigningCertificate(
116+
certificates.EndCertificate,
117+
certificates.AncestorCertificates);
118+
break;
119+
120+
case EndCertificateUse.Timestamping:
121+
result = _certificateVerifier.VerifyTimestampingCertificate(
122+
certificates.EndCertificate,
123+
certificates.AncestorCertificates);
124+
break;
125+
126+
default:
127+
throw new InvalidOperationException($"Unknown {nameof(EndCertificateUse)}: {validation.EndCertificate.Use}");
128+
}
124129
}
125-
}
126130

127-
// Save the result. This may alert if packages are invalidated.
128-
if (!await _certificateValidationService.TrySaveResultAsync(validation, result))
129-
{
130-
_logger.LogWarning(
131-
"Failed to save certificate validation result " +
132-
"(certificate: {CertificateThumbprint} validation: {ValidationId}), " +
133-
"failing validation",
134-
validation.EndCertificate.Thumbprint,
135-
validation.ValidationId);
136-
137-
return false;
138-
}
131+
// Save the result. This may alert if packages are invalidated.
132+
if (!await _certificateValidationService.TrySaveResultAsync(validation, result))
133+
{
134+
_logger.LogWarning(
135+
"Failed to save certificate validation result " +
136+
"(certificate: {CertificateThumbprint} validation: {ValidationId}), " +
137+
"failing validation",
138+
validation.EndCertificate.Thumbprint,
139+
validation.ValidationId);
139140

140-
return HasValidationCompleted(validation, result);
141+
return false;
142+
}
143+
144+
return HasValidationCompleted(validation, result);
145+
}
141146
}
142147

143148
private bool HasValidationCompleted(EndCertificateValidation validation, CertificateVerificationResult result)

0 commit comments

Comments
 (0)