fix: added debug log

Signed-off-by: Junjie Gao <junjiegao@microsoft.com>
notaryproject · Dec 1, 2022 · 5d49b42 · 5d49b42
1 parent b70f058
commit 5d49b42
Show file tree

Hide file tree

Showing 4 changed files with 50 additions and 11 deletions.
diff --git a/notation.go b/notation.go
@@ -53,6 +53,8 @@ type Signer interface {
 // remote.
 // The descriptor of the sign content is returned upon sucessful signing.
 func Sign(ctx context.Context, signer Signer, repo registry.Repository, opts SignOptions) (ocispec.Descriptor, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("fetch artifact digest for %v", opts.ArtifactReference)
 	targetDesc, err := repo.Resolve(ctx, opts.ArtifactReference)
 	if err != nil {
 		return ocispec.Descriptor{}, err
@@ -61,10 +63,12 @@ func Sign(ctx context.Context, signer Signer, repo registry.Repository, opts Sig
 	if err != nil {
 		return ocispec.Descriptor{}, err
 	}
+	logger.Debugf("generate annotation")
 	annotations, err := generateAnnotations(signerInfo)
 	if err != nil {
 		return ocispec.Descriptor{}, err
 	}
+	logger.Debugf("push signature: %s, artifact descriptor: %+v, annotations: %+v", string(sig), targetDesc, annotations)
 	_, _, err = repo.PushSignature(ctx, opts.SignatureMediaType, sig, targetDesc, annotations)
 	if err != nil {
 		return ocispec.Descriptor{}, err
@@ -170,6 +174,7 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 			return ocispec.Descriptor{}, nil, err
 		}
 	} else if reflect.DeepEqual(outcome.VerificationLevel, trustpolicy.LevelSkip) {
+		logger.Debug("verification finished for %v because verification level is skip", remoteOpts.ArtifactReference)
 		return ocispec.Descriptor{}, []*VerificationOutcome{outcome}, nil
 	}
 
@@ -178,8 +183,9 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 		return ocispec.Descriptor{}, nil, ErrorSignatureRetrievalFailed{Msg: fmt.Sprintf("verifyOptions.MaxSignatureAttempts expects a positive number, got %d", remoteOpts.MaxSignatureAttempts)}
 	}
 
-	// get signature manifests
+	// get artifact descriptor
 	artifactRef := remoteOpts.ArtifactReference
+	logger.Debugf("fetch artifact digest for %v", artifactRef)
 	artifactDescriptor, err := repo.Resolve(ctx, artifactRef)
 	if err != nil {
 		return ocispec.Descriptor{}, nil, ErrorSignatureRetrievalFailed{Msg: err.Error()}
@@ -189,15 +195,17 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 	errExceededMaxVerificationLimit := ErrorVerificationFailed{Msg: fmt.Sprintf("total number of signatures associated with an artifact should be less than: %d", remoteOpts.MaxSignatureAttempts)}
 	numOfSignatureProcessed := 0
 
+	logger.Debugf("fetch signature manifest")
 	err = repo.ListSignatures(ctx, artifactDescriptor, func(signatureManifests []ocispec.Descriptor) error {
 		// process signatures
 		for _, sigManifestDesc := range signatureManifests {
 			if numOfSignatureProcessed >= remoteOpts.MaxSignatureAttempts {
 				break
 			}
 			numOfSignatureProcessed++
-			logger.Infof("Processing signature with digest: %v", sigManifestDesc.Digest)
+			logger.Infof("processing signature with digest: %v", sigManifestDesc.Digest)
 			// get signature envelope
+			logger.Debugf("fetch signature blob for signature manifest %v", sigManifestDesc.Digest)
 			sigBlob, sigDesc, err := repo.FetchSignatureBlob(ctx, sigManifestDesc)
 			if err != nil {
 				return ErrorSignatureRetrievalFailed{Msg: fmt.Sprintf("unable to retrieve digital signature with digest %q associated with %q from the registry, error : %v", sigManifestDesc.Digest, artifactRef, err.Error())}
@@ -217,7 +225,7 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 			// at this point, the signature is verified successfully. Add
 			// it to the verificationOutcomes.
 			verificationOutcomes = append(verificationOutcomes, outcome)
-			logger.Debugf("Successfully verified signature with digest %v", sigManifestDesc.Digest)
+			logger.Debugf("successfully verified signature with digest %v", sigManifestDesc.Digest)
 
 			// early break on success
 			return errDoneVerification
@@ -244,7 +252,9 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 
 	// Verification Failed
 	if len(verificationOutcomes) == 0 {
-		return ocispec.Descriptor{}, verificationOutcomes, ErrorVerificationFailed{}
+		return ocispec.Descriptor{}, verificationOutcomes, ErrorVerificationFailed{
+			Msg: fmt.Sprintf("Signature verification failed for all the signatures associated with digest %v", artifactDescriptor.Digest),
+		}
 	}
 
 	// Verification Succeeded

diff --git a/signer/plugin.go b/signer/plugin.go
@@ -10,6 +10,7 @@ import (
 	"github.com/notaryproject/notation-core-go/signature"
 	"github.com/notaryproject/notation-go"
 	"github.com/notaryproject/notation-go/internal/envelope"
+	"github.com/notaryproject/notation-go/log"
 	"github.com/notaryproject/notation-go/plugin"
 	"github.com/notaryproject/notation-go/plugin/proto"
 	ocispec "github.com/opencontainers/image-spec/specs-go/v1"
@@ -45,13 +46,18 @@ func NewFromPlugin(plugin plugin.Plugin, keyID string, pluginConfig map[string]s
 // Sign signs the artifact described by its descriptor and returns the
 // marshalled envelope.
 func (s *pluginSigner) Sign(ctx context.Context, desc ocispec.Descriptor, opts notation.SignOptions) ([]byte, *signature.SignerInfo, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("plugin signing for %v", desc.Digest)
+
 	req := &proto.GetMetadataRequest{
 		PluginConfig: s.mergeConfig(opts.PluginConfig),
 	}
 	metadata, err := s.plugin.GetMetadata(ctx, req)
 	if err != nil {
 		return nil, nil, err
 	}
+
+	logger.Debugf("plugin capabilities %v", metadata.Capabilities)
 	if metadata.HasCapability(proto.CapabilitySignatureGenerator) {
 		return s.generateSignature(ctx, desc, opts)
 	} else if metadata.HasCapability(proto.CapabilityEnvelopeGenerator) {
@@ -61,6 +67,8 @@ func (s *pluginSigner) Sign(ctx context.Context, desc ocispec.Descriptor, opts n
 }
 
 func (s *pluginSigner) generateSignature(ctx context.Context, desc ocispec.Descriptor, opts notation.SignOptions) ([]byte, *signature.SignerInfo, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debug("generating signature by plugin")
 	config := s.mergeConfig(opts.PluginConfig)
 	// Get key info.
 	key, err := s.describeKey(ctx, config)
@@ -86,11 +94,13 @@ func (s *pluginSigner) generateSignature(ctx context.Context, desc ocispec.Descr
 			keySpec:      ks,
 		},
 	}
-
+	logger.Debugf("generated genericSigner %+v", genericSigner)
 	return genericSigner.Sign(ctx, desc, opts)
 }
 
 func (s *pluginSigner) generateSignatureEnvelope(ctx context.Context, desc ocispec.Descriptor, opts notation.SignOptions) ([]byte, *signature.SignerInfo, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debug("generating signature envelope by plugin")
 	payload := envelope.Payload{TargetArtifact: envelope.SanitizeTargetArtifact(desc)}
 	payloadBytes, err := json.Marshal(payload)
 	if err != nil {
@@ -104,10 +114,12 @@ func (s *pluginSigner) generateSignatureEnvelope(ctx context.Context, desc ocisp
 		PayloadType:           envelope.MediaTypePayloadV1,
 		PluginConfig:          s.mergeConfig(opts.PluginConfig),
 	}
+	logger.Debugf("plugin GenerateEnvelopeRequest %+v", req)
 	resp, err := s.plugin.GenerateEnvelope(ctx, req)
 	if err != nil {
 		return nil, nil, fmt.Errorf("plugin failed to sign with following error: %w", err)
 	}
+	logger.Debugf("plugin GenerateEnvelopeResponse %+v", resp)
 
 	// Check signatureEnvelopeType is honored.
 	if resp.SignatureEnvelopeType != req.SignatureEnvelopeType {
@@ -117,6 +129,7 @@ func (s *pluginSigner) generateSignatureEnvelope(ctx context.Context, desc ocisp
 		)
 	}
 
+	logger.Debug("verify plugin generated signature envelope")
 	sigEnv, err := signature.ParseEnvelope(opts.SignatureMediaType, resp.SignatureEnvelope)
 	if err != nil {
 		return nil, nil, err

diff --git a/signer/signer.go b/signer/signer.go
@@ -16,6 +16,7 @@ import (
 	"github.com/notaryproject/notation-core-go/signature"
 	"github.com/notaryproject/notation-go"
 	"github.com/notaryproject/notation-go/internal/envelope"
+	"github.com/notaryproject/notation-go/log"
 	ocispec "github.com/opencontainers/image-spec/specs-go/v1"
 )
 
@@ -72,6 +73,8 @@ func NewFromFiles(keyPath, certChainPath string) (notation.Signer, error) {
 // Sign signs the artifact described by its descriptor and returns the
 // marshalled envelope.
 func (s *genericSigner) Sign(ctx context.Context, desc ocispec.Descriptor, opts notation.SignOptions) ([]byte, *signature.SignerInfo, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("local signing for %v", desc.Digest)
 	// Generate payload to be signed.
 	payload := envelope.Payload{TargetArtifact: envelope.SanitizeTargetArtifact(desc)}
 	payloadBytes, err := json.Marshal(payload)
@@ -93,6 +96,12 @@ func (s *genericSigner) Sign(ctx context.Context, desc ocispec.Descriptor, opts
 	if !opts.Expiry.IsZero() {
 		signReq.Expiry = opts.Expiry
 	}
+	logger.Debugf("sign request:")
+	logger.Debugf("  ContentType: %v", signReq.Payload.ContentType)
+	logger.Debugf("  Content: %s", string(signReq.Payload.Content))
+	logger.Debugf("  SigningTime: %v", signReq.SigningTime)
+	logger.Debugf("  SigningScheme: %v", signReq.SigningScheme)
+	logger.Debugf("  SigningAgent: %v", signReq.SigningAgent)
 
 	// perform signing
 	sigEnv, err := signature.NewEnvelope(opts.SignatureMediaType)

diff --git a/verifier/verifier.go b/verifier/verifier.go
@@ -109,6 +109,9 @@ func (v *verifier) Verify(ctx context.Context, desc ocispec.Descriptor, signatur
 }
 
 func (v *verifier) processSignature(ctx context.Context, sigBlob []byte, envelopeMediaType string, trustPolicy *trustpolicy.TrustPolicy, pluginConfig map[string]string, outcome *notation.VerificationOutcome) error {
+	if sigBlob == nil || len(sigBlob) == 0 {
+		return errors.New("sigBlob is nil or empty")
+	}
 	logger := log.GetLogger(ctx)
 
 	// verify integrity first. notation will always verify integrity no matter what the signing scheme is
@@ -165,8 +168,8 @@ func (v *verifier) processSignature(ctx context.Context, sigBlob []byte, envelop
 	// verify x509 trust store based authenticity
 	logger.Debug("verify cert chain")
 	authenticityResult := verifyAuthenticity(ctx, trustPolicy, v.trustStore, outcome)
-	logVerificationResult(logger, authenticityResult)
 	outcome.VerificationResults = append(outcome.VerificationResults, authenticityResult)
+	logVerificationResult(logger, authenticityResult)
 	if isCriticalFailure(authenticityResult) {
 		return authenticityResult.Error
 	}
@@ -187,17 +190,17 @@ func (v *verifier) processSignature(ctx context.Context, sigBlob []byte, envelop
 	// verify expiry
 	logger.Debug("verify expiry")
 	expiryResult := verifyExpiry(outcome)
-	logVerificationResult(logger, expiryResult)
 	outcome.VerificationResults = append(outcome.VerificationResults, expiryResult)
+	logVerificationResult(logger, expiryResult)
 	if isCriticalFailure(expiryResult) {
 		return expiryResult.Error
 	}
 
 	// verify authentic timestamp
 	logger.Debug("verify authentic timestamp")
 	authenticTimestampResult := verifyAuthenticTimestamp(outcome)
-	logVerificationResult(logger, authenticTimestampResult)
 	outcome.VerificationResults = append(outcome.VerificationResults, authenticTimestampResult)
+	logVerificationResult(logger, authenticTimestampResult)
 	if isCriticalFailure(authenticTimestampResult) {
 		return authenticTimestampResult.Error
 	}
@@ -217,6 +220,7 @@ func (v *verifier) processSignature(ctx context.Context, sigBlob []byte, envelop
 		for _, pc := range pluginCapabilities {
 			// skip the revocation capability if the trust policy is configured to skip it
 			if outcome.VerificationLevel.Enforcement[trustpolicy.TypeRevocation] == trustpolicy.ActionSkip && pc == proto.CapabilityRevocationCheckVerifier {
+				logger.Debugf("skip the verification capability %v because of verification action setting as skipped", pc)
 				continue
 			}
 			capabilitiesToVerify = append(capabilitiesToVerify, pc)
@@ -450,6 +454,7 @@ func verifyAuthenticTimestamp(outcome *notation.VerificationOutcome) *notation.V
 }
 
 func executePlugin(ctx context.Context, installedPlugin plugin.Plugin, trustPolicy *trustpolicy.TrustPolicy, capabilitiesToVerify []proto.Capability, envelopeContent *signature.EnvelopeContent, pluginConfig map[string]string) (*proto.VerifySignatureResponse, error) {
+	logger := log.GetLogger(ctx)
 	// sanity check
 	if installedPlugin == nil {
 		return nil, errors.New("installedPlugin cannot be nil")
@@ -463,6 +468,7 @@ func executePlugin(ctx context.Context, installedPlugin plugin.Plugin, trustPoli
 		extendedAttributes[attr.Key.(string)] = attr.Value
 		attributesToProcess = append(attributesToProcess, attr.Key.(string))
 	}
+	logger.Debugf("added plugin attributes to be processed %v", attributesToProcess)
 
 	var certChain [][]byte
 	for _, cert := range signerInfo.CertificateChain {
@@ -497,8 +503,10 @@ func executePlugin(ctx context.Context, installedPlugin plugin.Plugin, trustPoli
 		TrustPolicy:  policy,
 		PluginConfig: pluginConfig,
 	}
-
-	return installedPlugin.VerifySignature(ctx, req)
+	logger.Debugf("plugin VerifySignatureRequest: %+v", req)
+	resp, err := installedPlugin.VerifySignature(ctx, req)
+	logger.Debugf("plugin VerifySignatureResponse: %+v", resp)
+	return resp, err
 }
 
 func verifyX509TrustedIdentities(certs []*x509.Certificate, trustPolicy *trustpolicy.TrustPolicy) error {
@@ -547,7 +555,6 @@ func verifyX509TrustedIdentities(certs []*x509.Certificate, trustPolicy *trustpo
 }
 
 func logVerificationResult(logger log.Logger, result *notation.ValidationResult) {
-	// log verification result
 	if result.Error == nil {
 		return
 	}