feat: add required log

notation.go

@@ -87,10 +87,13 @@ func Sign(ctx context.Context, signer Signer, repo registry.Repository, opts Sig
 	if err != nil {
 		return ocispec.Descriptor{}, err
 	}
+	logger.Debug("Generating annotation")
 	annotations, err := generateAnnotations(signerInfo)
 	if err != nil {
 		return ocispec.Descriptor{}, err
 	}
+	logger.Debugf("Generated annotations: %+v", annotations)
+	logger.Debugf("Pushing signature of artifact descriptor: %+v, signature media type: %v", targetDesc, opts.SignatureMediaType)
 	_, _, err = repo.PushSignature(ctx, opts.SignatureMediaType, sig, targetDesc, annotations)
 	if err != nil {
 		return ocispec.Descriptor{}, err
@@ -191,14 +194,17 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 	}
 
 	// passing nil signature to check 'skip'
+	logger.Info("Checking whether signature verification should be skipped or not")
 	outcome, err := verifier.Verify(ctx, ocispec.Descriptor{}, nil, opts)
 	if err != nil {
 		if outcome == nil {
 			return ocispec.Descriptor{}, nil, err
 		}
 	} else if reflect.DeepEqual(outcome.VerificationLevel, trustpolicy.LevelSkip) {
+		logger.Infoln("Verification skipped for", remoteOpts.ArtifactReference)
 		return ocispec.Descriptor{}, []*VerificationOutcome{outcome}, nil
 	}
+	logger.Info("Check over. Trust policy is not configured to skip signature verification")
 
 	// check MaxSignatureAttempts
 	if remoteOpts.MaxSignatureAttempts <= 0 {
@@ -229,18 +235,22 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 	numOfSignatureProcessed := 0
 
 	// get signature manifests
+	logger.Debug("Fetching signature manifests using referrers API")
 	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)
 			// get signature envelope
 			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())}
 			}
+			logger.Debugf("signature media type: %v", sigDesc.MediaType)
+
 			// using signature media type fetched from registry
 			opts.SignatureMediaType = sigDesc.MediaType
 
@@ -253,10 +263,10 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 				}
 				continue
 			}
-
 			// at this point, the signature is verified successfully. Add
 			// it to the verificationOutcomes.
 			verificationOutcomes = append(verificationOutcomes, outcome)
+			logger.Debugf("Signature verification succeeded for artifact %v with signature digest %v", artifactDescriptor.Digest, sigManifestDesc.Digest)
 
 			// early break on success
 			return errDoneVerification
@@ -283,6 +293,7 @@ func Verify(ctx context.Context, verifier Verifier, repo registry.Repository, re
 
 	// Verification Failed
 	if len(verificationOutcomes) == 0 {
+		logger.Debugf("Signature verification failed for all the signatures associated with artifact %v", artifactDescriptor.Digest)
 		return ocispec.Descriptor{}, verificationOutcomes, ErrorVerificationFailed{}
 	}
 

plugin/plugin.go

@@ -14,6 +14,7 @@ import (
 	"path/filepath"
 
 	"github.com/notaryproject/notation-go/internal/slices"
+	"github.com/notaryproject/notation-go/log"
 	"github.com/notaryproject/notation-go/plugin/proto"
 )
 
@@ -83,6 +84,8 @@ func NewCLIPlugin(ctx context.Context, name, path string) (*CLIPlugin, error) {
 
 // GetMetadata returns the metadata information of the plugin.
 func (p *CLIPlugin) GetMetadata(ctx context.Context, req *proto.GetMetadataRequest) (*proto.GetMetadataResponse, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("Plugin get-plugin-metadata request: %+v", req)
 	var metadata proto.GetMetadataResponse
 	err := run(ctx, p.name, p.path, req, &metadata)
 	if err != nil {
@@ -95,54 +98,67 @@ func (p *CLIPlugin) GetMetadata(ctx context.Context, req *proto.GetMetadataReque
 	if metadata.Name != p.name {
 		return nil, fmt.Errorf("executable name must be %q instead of %q", binName(metadata.Name), filepath.Base(p.path))
 	}
+	logger.Debugf("Plugin get-plugin-metadata response: %+v", metadata)
 	return &metadata, nil
 }
 
 // DescribeKey returns the KeySpec of a key.
 //
 // if ContractVersion is not set, it will be set by the function.
 func (p *CLIPlugin) DescribeKey(ctx context.Context, req *proto.DescribeKeyRequest) (*proto.DescribeKeyResponse, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("Plugin describe-key request: %+v", req)
 	var resp proto.DescribeKeyResponse
 	if req.ContractVersion == "" {
 		req.ContractVersion = proto.ContractVersion
 	}
 	err := run(ctx, p.name, p.path, req, &resp)
+	logger.Debugf("Plugin describe-key response: %+v", resp)
 	return &resp, err
 }
 
 // GenerateSignature generates the raw signature based on the request.
 //
 // if ContractVersion is not set, it will be set by the function.
 func (p *CLIPlugin) GenerateSignature(ctx context.Context, req *proto.GenerateSignatureRequest) (*proto.GenerateSignatureResponse, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("Plugin generate-signature request: {ContractVersion: %v, KeyID: %v, KeySpec: %v, Hash: %v, PluginConfig: %v}", req.ContractVersion, req.KeyID, req.KeySpec, req.Hash, req.PluginConfig)
 	var resp proto.GenerateSignatureResponse
 	if req.ContractVersion == "" {
 		req.ContractVersion = proto.ContractVersion
 	}
 	err := run(ctx, p.name, p.path, req, &resp)
+	logger.Debugf("Plugin generate-signature response: {keyId: %v, SigningAlgorithm: %v}", resp.KeyID, resp.SigningAlgorithm)
 	return &resp, err
 }
 
 // GenerateEnvelope generates the Envelope with signature based on the request.
 //
 // if ContractVersion is not set, it will be set by the function.
 func (p *CLIPlugin) GenerateEnvelope(ctx context.Context, req *proto.GenerateEnvelopeRequest) (*proto.GenerateEnvelopeResponse, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("Plugin generate-envelope request: {ContractVersion: %v, KeyID: %v, PayloadType: %v, SignatureEnvelope: %v, ExpiryDurationInSeconds: %v, PluginConfig: %v}", req.ContractVersion, req.KeyID, req.PayloadType, req.SignatureEnvelopeType, req.ExpiryDurationInSeconds, req.PluginConfig)
 	var resp proto.GenerateEnvelopeResponse
 	if req.ContractVersion == "" {
 		req.ContractVersion = proto.ContractVersion
 	}
 	err := run(ctx, p.name, p.path, req, &resp)
+	logger.Debugf("Plugin generate-envelope response: {SignatureEnvelopeType: %v, Annotations:%v}", resp.SignatureEnvelopeType, resp.Annotations)
 	return &resp, err
 }
 
 // VerifySignature validates the signature based on the request.
 //
 // if ContractVersion is not set, it will be set by the function.
 func (p *CLIPlugin) VerifySignature(ctx context.Context, req *proto.VerifySignatureRequest) (*proto.VerifySignatureResponse, error) {
+	logger := log.GetLogger(ctx)
+	logger.Debugf("Plugin verify-signature request: {ContractVersion: %v, TrustPolicy: %v, PluginConfig: %v, Signature: {CriticalAttributes: %v, UnprocessedAttributes: %v}}", req.ContractVersion, req.TrustPolicy, req.PluginConfig, req.Signature.CriticalAttributes, req.Signature.UnprocessedAttributes)
 	var resp proto.VerifySignatureResponse
 	if req.ContractVersion == "" {
 		req.ContractVersion = proto.ContractVersion
 	}
 	err := run(ctx, p.name, p.path, req, &resp)
+	logger.Debugf("Plugin verify-signature response: %+v", resp)
 	return &resp, err
 }
 

signer/plugin.go

@@ -11,6 +11,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"
@@ -46,13 +47,17 @@ 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.Debug("Invoking plugin's get-plugin-metadata command")
 	req := &proto.GetMetadataRequest{
 		PluginConfig: s.mergeConfig(opts.PluginConfig),
 	}
 	metadata, err := s.plugin.GetMetadata(ctx, req)
 	if err != nil {
 		return nil, nil, err
 	}
+
+	logger.Debugf("Using plugin %v with capabilities %v to sign artifact %v", metadata.Name, metadata.Capabilities, desc.Digest)
 	if metadata.HasCapability(proto.CapabilitySignatureGenerator) {
 		return s.generateSignature(ctx, desc, opts)
 	} else if metadata.HasCapability(proto.CapabilityEnvelopeGenerator) {
@@ -62,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)
@@ -87,11 +94,12 @@ func (s *pluginSigner) generateSignature(ctx context.Context, desc ocispec.Descr
 			keySpec:      ks,
 		},
 	}
-
 	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 {
@@ -119,6 +127,7 @@ func (s *pluginSigner) generateSignatureEnvelope(ctx context.Context, desc ocisp
 		)
 	}
 
+	logger.Debug("Verifying signature envelope generated by the plugin")
 	sigEnv, err := signature.ParseEnvelope(opts.SignatureMediaType, resp.SignatureEnvelope)
 	if err != nil {
 		return nil, nil, err

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("Generic signing for %v", desc.Digest)
 	// Generate payload to be signed.
 	payload := envelope.Payload{TargetArtifact: envelope.SanitizeTargetArtifact(desc)}
 	payloadBytes, err := json.Marshal(payload)
@@ -94,6 +97,13 @@ func (s *genericSigner) Sign(ctx context.Context, desc ocispec.Descriptor, opts
 	if opts.ExpiryDuration != 0 {
 		signReq.Expiry = signReq.SigningTime.Add(opts.ExpiryDuration)
 	}
+	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("  Expiry:        %v", signReq.Expiry)
+	logger.Debugf("  SigningScheme: %v", signReq.SigningScheme)
+	logger.Debugf("  SigningAgent:  %v", signReq.SigningAgent)
 
 	// perform signing
 	sigEnv, err := signature.NewEnvelope(opts.SignatureMediaType)