Misleading and inconsistent logs

[yizha1]

What is not working as expected?

The type of trust store is ca. When signature verification failed, the following logs were shown:

DEBU[xxx] Validating cert chain
DEBU[xxx] Validating trust identity
DEBU[xxx] Validating expiry
DEBU[xxx] Validating authentic timestamp
DEBU[xxx] Validating revocation
DEBU[xxx] not using authentic signing time due to error retrieving AuthenticSigningTime, err: authenticSigningTime not found
DEBU[xxx] no verification impacting errors encountered while checking revocation, status is OK
INFO[xxx] payload.TargetArtifact in signature: {MediaType:application/vnd.docker.distribution.manifest.v2+json Digest:sha256:xxx Size:xxx URLs:[] Annotations:map[] Data:[] Platform: ArtifactType:}
INFO[xxx] Target artifact that want to be verified: {MediaType:application/vnd.docker.distribution.manifest.v2+json Digest:sha256:xxx Size:xxx URLs:[] Annotations:map[] Data:[] Platform: ArtifactType:}
WARN[xxx] Signature sha256:xxx failed verification with error: content descriptor mismatch

There are several problems:

• Log Severity and Reasoning: The log that helped identify the root cause is: WARN[***] Signature sha256:*** failed verification with error: content descriptor mismatch.
  However, it is both a “WARN” and an “ERROR” (from the details). Why use “WARN” instead of “ERROR”?
• Misleading Log: The following log is misleading:
  DEBU[***] not using authentic signing time due to error retrieving AuthenticSigningTime, err: authenticSigningTime not found
  Although it starts with “DEBU,” it discusses an issue related to “AuthenticSigningTime,” which is not actually the problem for the failure. And this log appears for any successful verification as well.
• Capitalization Consistency: Most logs start with a capital letter after the log level, but the following logs begin with lowercase letters, which lacks consistency:
  DEBU[xxx] not using authentic signing time due to error retrieving AuthenticSigningTime, err: authenticSigningTime not found
DEBU[xxx] no verification impacting errors encountered while checking revocation, status is OK
INFO[xxx] payload.TargetArtifact in signature: {MediaType:application/vnd.docker.distribution.manifest.v2+json Digest:sha256:xxx Size:xxx URLs:[] Annotations:map[] Data:[] Platform:<nil> ArtifactType:}

What did you expect to happen?

Here are my suggestions for the three problems

• Log Severity and Reasoning:
  • Suggestion: Update the log level to ERRO. The error message content descriptor mismatch can be improved as well, but it is not the main purpose of this issue, it can be done with error message improvements.
• Misleading Log
  • Suggestion: Rephase the log description as it is not an error
• Capitalization Consistency:
  • Suggestion: Align the capitalization with all logs.

How can we reproduce it?

For the 1st problem, use oras fetch command to fetch a signature blob from one signed image, and then use oras attach to attach it to a different unsigned image.

For the 2nd and 3rd problems, use notation verify to verify any signed images, no matter if it is successful or failure.

Describe your environment

Linux OS

What is the version of your Notation CLI or Notation Library?

notation v1.1.1

[Two-Hearts]

@yizha1 can you move the issue to notation-go as the confusing log is generated by notation-go library.

[Two-Hearts]

Should be a quick fix, on my list.

[Two-Hearts]

@yizha1

Log Severity and Reasoning: The log that helped identify the root cause is: WARN[] Signature sha256: failed verification with error: content descriptor mismatch.
However, it is both a “WARN” and an “ERROR” (from the details). Why use “WARN” instead of “ERROR”?

It's WARN instead of ERROR because there could be multiple signatures for an image. For a certain signature, if its verification fails, the overall verification doesn't have to fail (other signatures may pass the verification). Therefore, using ERROR here maybe not very accurate, because the desired behavior is an overall succeeded verification shouldn't have any 'ERROR' in its log.

[Two-Hearts]

@yizha1

Misleading Log: The following log is misleading:
DEBU[***] not using authentic signing time due to error retrieving AuthenticSigningTime, err: authenticSigningTime not found
Although it starts with “DEBU,” it discusses an issue related to “AuthenticSigningTime,” which is not actually the problem for the failure. And this log appears for any successful verification as well.

This is a tricky one, firstly, this log only appears under signing scheme notary.x509. Secondly, it is not an error now because we haven't supported the RFC 3161 timestamp. Once we support it, this error log would then become valid. Therefore, my suggestion is to keep it as is and revisit it before next release, i.e. v1.2.0-beta.1.