feat: add trace for executables

cmd/notation/cert/list.go

@@ -52,7 +52,7 @@ Example - List all certificate files from trust store "wabbit-networks" of type
 
 func listCerts(ctx context.Context, opts *certListOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 	logger := log.GetLogger(ctx)
 
 	namedStore := opts.namedStore

cmd/notation/cert/show.go

@@ -59,7 +59,7 @@ Example - Show details of certificate "cert2.pem" with type "signingAuthority" f
 
 func showCerts(ctx context.Context, opts *certShowOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 	logger := log.GetLogger(ctx)
 
 	storeType := opts.storeType

cmd/notation/inspect.go

@@ -108,7 +108,7 @@ Example - [Experimental] Inspect signatures on an OCI artifact identified by a d
 
 func runInspect(command *cobra.Command, opts *inspectOpts) error {
 	// set log level
-	ctx := opts.LoggingFlagOpts.SetLoggerLevel(command.Context())
+	ctx := opts.LoggingFlagOpts.InitializeLogger(command.Context())
 
 	if opts.outputFormat != cmd.OutputJSON && opts.outputFormat != cmd.OutputPlaintext {
 		return fmt.Errorf("unrecognized output format %s", opts.outputFormat)

cmd/notation/key.go

@@ -162,7 +162,7 @@ func keyDeleteCommand(opts *keyDeleteOpts) *cobra.Command {
 
 func addKey(ctx context.Context, opts *keyAddOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 
 	pluginConfig, err := cmd.ParseFlagMap(opts.pluginConfig, cmd.PflagPluginConfig.Name)
 	if err != nil {
@@ -188,7 +188,7 @@ func addKey(ctx context.Context, opts *keyAddOpts) error {
 
 func updateKey(ctx context.Context, opts *keyUpdateOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 	logger := log.GetLogger(ctx)
 
 	if !opts.isDefault {
@@ -222,7 +222,7 @@ func listKeys() error {
 
 func deleteKeys(ctx context.Context, opts *keyDeleteOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 	logger := log.GetLogger(ctx)
 
 	// core process

cmd/notation/list.go

@@ -66,7 +66,7 @@ func listCommand(opts *listOpts) *cobra.Command {
 
 func runList(ctx context.Context, opts *listOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 
 	// initialize
 	reference := opts.reference

cmd/notation/login.go

@@ -65,7 +65,7 @@ Example - Login using $NOTATION_USERNAME $NOTATION_PASSWORD variables:
 
 func runLogin(ctx context.Context, opts *loginOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 
 	// initialize
 	serverAddress := opts.server

cmd/notation/logout.go

@@ -40,7 +40,7 @@ func logoutCommand(opts *logoutOpts) *cobra.Command {
 
 func runLogout(ctx context.Context, opts *logoutOpts) error {
 	// set log level
-	ctx = opts.LoggingFlagOpts.SetLoggerLevel(ctx)
+	ctx = opts.LoggingFlagOpts.InitializeLogger(ctx)
 	credsStore, err := auth.NewCredentialsStore()
 	if err != nil {
 		return fmt.Errorf("failed to get credentials store: %v", err)

cmd/notation/sign.go

@@ -107,7 +107,7 @@ Example - [Experimental] Sign an OCI artifact identified by a tag and referenced
 
 func runSign(command *cobra.Command, cmdOpts *signOpts) error {
 	// set log level
-	ctx := cmdOpts.LoggingFlagOpts.SetLoggerLevel(command.Context())
+	ctx := cmdOpts.LoggingFlagOpts.InitializeLogger(command.Context())
 
 	// initialize
 	signer, err := cmd.GetSigner(ctx, &cmdOpts.SignerFlagOpts)

cmd/notation/verify.go

@@ -93,7 +93,7 @@ Example - [Experimental] Verify a signature on an OCI artifact identified by a t
 
 func runVerify(command *cobra.Command, opts *verifyOpts) error {
 	// set log level
-	ctx := opts.LoggingFlagOpts.SetLoggerLevel(command.Context())
+	ctx := opts.LoggingFlagOpts.InitializeLogger(command.Context())
 
 	// initialize
 	sigVerifier, err := verifier.NewFromConfig()

go.mod

@@ -7,7 +7,7 @@ require (
 	github.com/notaryproject/notation-go v1.0.0-rc.6
 	github.com/opencontainers/go-digest v1.0.0
 	github.com/opencontainers/image-spec v1.1.0-rc4
-	github.com/oras-project/oras-credentials-go v0.2.0
+	github.com/oras-project/oras-credentials-go v0.3.0
 	github.com/sirupsen/logrus v1.9.3
 	github.com/spf13/cobra v1.7.0
 	github.com/spf13/pflag v1.0.5

go.sum

@@ -23,8 +23,8 @@ github.com/opencontainers/go-digest v1.0.0 h1:apOUWs51W5PlhuyGyz9FCeeBIOUDA/6nW8
 github.com/opencontainers/go-digest v1.0.0/go.mod h1:0JzlMkj0TRzQZfJkVvzbP0HBR3IKzErnv2BNG4W4MAM=
 github.com/opencontainers/image-spec v1.1.0-rc4 h1:oOxKUJWnFC4YGHCCMNql1x4YaDfYBTS5Y4x/Cgeo1E0=
 github.com/opencontainers/image-spec v1.1.0-rc4/go.mod h1:X4pATf0uXsnn3g5aiGIsVnJBR4mxhKzfwmvK/B2NTm8=
-github.com/oras-project/oras-credentials-go v0.2.0 h1:BvWAXo0e5unWR6Hfxyb0K04mHNHreQz/Zclw6IzCYJo=
-github.com/oras-project/oras-credentials-go v0.2.0/go.mod h1:JVdg7a5k7hzTrEeeouwag0aCv7OLrS77r7/6w3gVirU=
+github.com/oras-project/oras-credentials-go v0.3.0 h1:Bg1d9iAmgo50RlaIy2XI5MQs7qL00DB3R9Q4JRP1VWs=
+github.com/oras-project/oras-credentials-go v0.3.0/go.mod h1:fFCebDQo0Do+gnM96uV9YUnRay0pwuRQupypvofsp4s=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=

internal/cmd/options.go

@@ -3,7 +3,9 @@ package cmd
 import (
 	"context"
 
+	"github.com/notaryproject/notation-go/log"
 	"github.com/notaryproject/notation/internal/trace"
+	credentialstrace "github.com/oras-project/oras-credentials-go/trace"
 	"github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/spf13/pflag"
@@ -41,12 +43,32 @@ func (opts *LoggingFlagOpts) ApplyFlags(fs *pflag.FlagSet) {
 	fs.BoolVarP(&opts.Verbose, "verbose", "v", false, "verbose mode")
 }
 
-// SetLoggerLevel sets up the logger based on common options.
-func (opts *LoggingFlagOpts) SetLoggerLevel(ctx context.Context) context.Context {
+// InitializeLogger sets up the logger based on common options.
+func (opts *LoggingFlagOpts) InitializeLogger(ctx context.Context) context.Context {
 	if opts.Debug {
-		return trace.WithLoggerLevel(ctx, logrus.DebugLevel)
+		ctx = trace.WithLoggerLevel(ctx, logrus.DebugLevel)
 	} else if opts.Verbose {
-		return trace.WithLoggerLevel(ctx, logrus.InfoLevel)
+		ctx = trace.WithLoggerLevel(ctx, logrus.InfoLevel)
+	} else {
+		return ctx
 	}
+	return withExecutableTrace(ctx)
+}
+
+// withExecutableTrace adds tracing for credential helper executables.
+func withExecutableTrace(ctx context.Context) context.Context {
+	logger := log.GetLogger(ctx)
+	ctx = credentialstrace.WithExecutableTrace(ctx, &credentialstrace.ExecutableTrace{
+		ExecuteStart: func(executableName, action string) {
+			logger.Debugf("started executing credential helper program %s with action %s", executableName, action)
+		},
+		ExecuteDone: func(executableName, action string, err error) {
+			if err != nil {
+				logger.Errorf("finished executing credential helper program %s with action %s and got error %w", executableName, action, err)
+			} else {
+				logger.Debugf("finished executing credential helper program %s with action %s", executableName, action)
+			}
+		},
+	})
 	return ctx
 }