Instrument plugin command executions

Signed-off-by: Christopher Petito <[email protected]>

Author: krissetto

cli-plugins/manager/cobra.go

@@ -90,11 +90,18 @@ func AddPluginCommandStubs(dockerCli command.Cli, rootCmd *cobra.Command) (err e
 					cargs = append(cargs, args...)
 					cargs = append(cargs, toComplete)
 					os.Args = cargs
-					runCommand, runErr := PluginRunCommand(dockerCli, p.Name, cmd)
+					pluginRunCommand, runErr := PluginRunCommand(dockerCli, p.Name, cmd)
 					if runErr != nil {
 						return nil, cobra.ShellCompDirectiveError
 					}
-					runErr = runCommand.Run()
+					if dockerCli, ok := dockerCli.(*command.DockerCli); !ok {
+						runCommand := dockerCli.InstrumentPluginCommand(pluginRunCommand)
+						runErr = runCommand.TimedRun(cmd.Context())
+					} else {
+						// This should not happen. continue without instrumenting the cmd if it does
+						fmt.Fprint(dockerCli.Err(), "Warning: Unexpected error, the plugin command will not have OTEL metrics")
+						runErr = pluginRunCommand.Run()
+					}
 					if runErr == nil {
 						os.Exit(0) // plugin already rendered complete data
 					}

cli/command/telemetry_utils.go

@@ -3,6 +3,7 @@ package command
 import (
 	"context"
 	"fmt"
+	"os/exec"
 	"strings"
 	"time"
 
@@ -14,8 +15,8 @@ import (
 	"go.opentelemetry.io/otel/metric"
 )
 
-// BaseCommandAttributes returns an attribute.Set containing attributes to attach to metrics/traces
-func BaseCommandAttributes(cmd *cobra.Command, streams Streams) []attribute.KeyValue {
+// baseCommandAttributes returns an attribute.Set containing attributes to attach to metrics/traces
+func baseCommandAttributes(cmd *cobra.Command, streams Streams) []attribute.KeyValue {
 	return append([]attribute.KeyValue{
 		attribute.String("command.name", getCommandName(cmd)),
 	}, stdioAttributes(streams)...)
@@ -69,7 +70,7 @@ func (cli *DockerCli) InstrumentCobraCommands(ctx context.Context, cmd *cobra.Co
 // It should be called immediately before command execution, and returns a stopInstrumentation function
 // that must be called with the error resulting from the command execution.
 func (cli *DockerCli) StartInstrumentation(cmd *cobra.Command) (stopInstrumentation func(error)) {
-	baseAttrs := BaseCommandAttributes(cmd, cli)
+	baseAttrs := baseCommandAttributes(cmd, cli)
 	return startCobraCommandTimer(cli.MeterProvider(), baseAttrs)
 }
 
@@ -89,7 +90,7 @@ func startCobraCommandTimer(mp metric.MeterProvider, attrs []attribute.KeyValue)
 		defer cancel()
 
 		duration := float64(time.Since(start)) / float64(time.Millisecond)
-		cmdStatusAttrs := attributesFromError(err)
+		cmdStatusAttrs := attributesFromCommandError(err)
 		durationCounter.Add(ctx, duration,
 			metric.WithAttributes(attrs...),
 			metric.WithAttributes(cmdStatusAttrs...),
@@ -100,6 +101,63 @@ func startCobraCommandTimer(mp metric.MeterProvider, attrs []attribute.KeyValue)
 	}
 }
 
+// basePluginCommandAttributes returns a slice of attribute.KeyValue to attach to metrics/traces
+func basePluginCommandAttributes(plugincmd *exec.Cmd, streams Streams) []attribute.KeyValue {
+	pluginPath := strings.Split(plugincmd.Path, "-")
+	pluginName := pluginPath[len(pluginPath)-1]
+	return append([]attribute.KeyValue{
+		attribute.String("plugin.name", pluginName),
+	}, stdioAttributes(streams)...)
+}
+
+// wrappedCmd is used to wrap an exec.Cmd in order to instrument the
+// command with otel by using the TimedRun() func
+type wrappedCmd struct {
+	*exec.Cmd
+
+	baseAttrs []attribute.KeyValue
+	cli       *DockerCli
+}
+
+// TimedRun measures the duration of the command execution using and otel meter
+func (c *wrappedCmd) TimedRun(ctx context.Context) error {
+	stopPluginCommandTimer := c.cli.startPluginCommandTimer(c.cli.MeterProvider(), c.baseAttrs)
+	err := c.Cmd.Run()
+	stopPluginCommandTimer(err)
+	return err
+}
+
+// InstrumentPluginCommand instruments the plugin's exec.Cmd to measure it's execution time
+// Execute the returned command with TimedRun() to record the execution time.
+func (cli *DockerCli) InstrumentPluginCommand(plugincmd *exec.Cmd) *wrappedCmd {
+	baseAttrs := basePluginCommandAttributes(plugincmd, cli)
+	newCmd := &wrappedCmd{Cmd: plugincmd, baseAttrs: baseAttrs, cli: cli}
+	return newCmd
+}
+
+func (cli *DockerCli) startPluginCommandTimer(mp metric.MeterProvider, attrs []attribute.KeyValue) func(err error) {
+	durationCounter, _ := getDefaultMeter(mp).Float64Counter(
+		"plugin.command.time",
+		metric.WithDescription("Measures the duration of the plugin execution"),
+		metric.WithUnit("ms"),
+	)
+	start := time.Now()
+
+	return func(err error) {
+		// Use a new context for the export so that the command being cancelled
+		// doesn't affect the metrics, and we get metrics for cancelled commands.
+		ctx, cancel := context.WithTimeout(context.Background(), exportTimeout)
+		defer cancel()
+
+		duration := float64(time.Since(start)) / float64(time.Millisecond)
+		pluginStatusAttrs := attributesFromPluginError(err)
+		durationCounter.Add(ctx, duration,
+			metric.WithAttributes(attrs...),
+			metric.WithAttributes(pluginStatusAttrs...),
+		)
+	}
+}
+
 func stdioAttributes(streams Streams) []attribute.KeyValue {
 	// we don't wrap stderr, but we do wrap in/out
 	_, stderrTty := term.GetFdInfo(streams.Err())
@@ -110,7 +168,9 @@ func stdioAttributes(streams Streams) []attribute.KeyValue {
 	}
 }
 
-func attributesFromError(err error) []attribute.KeyValue {
+// Used to create attributes from an error.
+// The error is expected to be returned from the execution of a cobra command
+func attributesFromCommandError(err error) []attribute.KeyValue {
 	attrs := []attribute.KeyValue{}
 	exitCode := 0
 	if err != nil {
@@ -129,6 +189,27 @@ func attributesFromError(err error) []attribute.KeyValue {
 	return attrs
 }
 
+// Used to create attributes from an error.
+// The error is expected to be returned from the execution of a plugin
+func attributesFromPluginError(err error) []attribute.KeyValue {
+	attrs := []attribute.KeyValue{}
+	exitCode := 0
+	if err != nil {
+		exitCode = 1
+		if stderr, ok := err.(statusError); ok {
+			// StatusError should only be used for errors, and all errors should
+			// have a non-zero exit status, so only set this here if this value isn't 0
+			if stderr.StatusCode != 0 {
+				exitCode = stderr.StatusCode
+			}
+		}
+		attrs = append(attrs, attribute.String("plugin.error.type", otelErrorType(err)))
+	}
+	attrs = append(attrs, attribute.Int("plugin.status.code", exitCode))
+
+	return attrs
+}
+
 // otelErrorType returns an attribute for the error type based on the error category.
 func otelErrorType(err error) string {
 	name := "generic"

cli/command/telemetry_utils_test.go

@@ -182,7 +182,7 @@ func TestAttributesFromError(t *testing.T) {
 		tc := tc
 		t.Run(tc.testName, func(t *testing.T) {
 			t.Parallel()
-			actual := attributesFromError(tc.err)
+			actual := attributesFromCommandError(tc.err)
 			assert.Check(t, reflect.DeepEqual(actual, tc.expected))
 		})
 	}

cmd/docker/docker.go

@@ -136,9 +136,16 @@ func setupHelpCommand(dockerCli command.Cli, rootCmd, helpCmd *cobra.Command) {
 	helpCmd.Run = nil
 	helpCmd.RunE = func(c *cobra.Command, args []string) error {
 		if len(args) > 0 {
-			helpcmd, err := pluginmanager.PluginRunCommand(dockerCli, args[0], rootCmd)
+			helpRunCmd, err := pluginmanager.PluginRunCommand(dockerCli, args[0], rootCmd)
 			if err == nil {
-				return helpcmd.Run()
+				if dockerCli, ok := dockerCli.(*command.DockerCli); !ok {
+					helpcmd := dockerCli.InstrumentPluginCommand(helpRunCmd)
+					return helpcmd.TimedRun(c.Context())
+				} else {
+					// This should not happen. continue without instrumenting the cmd if it does
+					fmt.Fprint(dockerCli.Err(), "Warning: Unexpected error, the help command will not have OTEL metrics")
+					return helpRunCmd.Run()
+				}
 			}
 			if !pluginmanager.IsNotFound(err) {
 				return errors.Errorf("unknown help topic: %v", strings.Join(args, " "))
@@ -159,11 +166,18 @@ func tryRunPluginHelp(dockerCli command.Cli, ccmd *cobra.Command, cargs []string
 	if err != nil {
 		return err
 	}
-	helpcmd, err := pluginmanager.PluginRunCommand(dockerCli, cmd.Name(), root)
+	helpRunCmd, err := pluginmanager.PluginRunCommand(dockerCli, cmd.Name(), root)
 	if err != nil {
 		return err
 	}
-	return helpcmd.Run()
+	if dockerCli, ok := dockerCli.(*command.DockerCli); !ok {
+		helpcmd := dockerCli.InstrumentPluginCommand(helpRunCmd)
+		return helpcmd.TimedRun(ccmd.Context())
+	} else {
+		// This should not happen. continue without instrumenting the cmd if it does
+		fmt.Fprint(dockerCli.Err(), "Warning: Unexpected error, the plugin help command will not have OTEL metrics")
+		return helpRunCmd.Run()
+	}
 }
 
 func setHelpFunc(dockerCli command.Cli, cmd *cobra.Command) {
@@ -224,12 +238,14 @@ func setValidateArgs(dockerCli command.Cli, cmd *cobra.Command) {
 	})
 }
 
-func tryPluginRun(dockerCli command.Cli, cmd *cobra.Command, subcommand string, envs []string) error {
-	plugincmd, err := pluginmanager.PluginRunCommand(dockerCli, subcommand, cmd)
+func tryPluginRun(dockerCli *command.DockerCli, cmd *cobra.Command, subcommand string, envs []string) error {
+	pluginRunCmd, err := pluginmanager.PluginRunCommand(dockerCli, subcommand, cmd)
 	if err != nil {
 		return err
 	}
 
+	plugincmd := dockerCli.InstrumentPluginCommand(pluginRunCmd)
+
 	// Establish the plugin socket, adding it to the environment under a
 	// well-known key if successful.
 	srv, err := socket.NewPluginServer(nil)
@@ -279,7 +295,7 @@ func tryPluginRun(dockerCli command.Cli, cmd *cobra.Command, subcommand string,
 		}
 	}()
 
-	if err := plugincmd.Run(); err != nil {
+	if err := plugincmd.TimedRun(cmd.Context()); err != nil {
 		statusCode := 1
 		exitErr, ok := err.(*exec.ExitError)
 		if !ok {
@@ -304,6 +320,8 @@ func runDocker(ctx context.Context, dockerCli *command.DockerCli) error {
 		return err
 	}
 
+	cmd.SetContext(ctx)
+
 	if err := tcmd.Initialize(); err != nil {
 		return err
 	}
@@ -357,7 +375,7 @@ func runDocker(ctx context.Context, dockerCli *command.DockerCli) error {
 	// We've parsed global args already, so reset args to those
 	// which remain.
 	cmd.SetArgs(args)
-	err = cmd.ExecuteContext(ctx)
+	err = cmd.Execute()
 
 	// If the command is being executed in an interactive terminal
 	// and hook are enabled, run the plugin hooks.

e2e/cli-plugins/run_test.go

@@ -138,7 +138,7 @@ func TestHelpGood(t *testing.T) {
 	res := icmd.RunCmd(run("-l", "info", "help", "helloworld"))
 	res.Assert(t, icmd.Expected{
 		ExitCode: 0,
-		Err:      icmd.None,
+		Err:      "Warning: Unexpected error, the help command will not have OTEL metrics",
 	})
 	golden.Assert(t, res.Stdout(), "docker-help-helloworld.golden")
 }
@@ -191,7 +191,7 @@ func TestHelpGoodSubcommand(t *testing.T) {
 	res := icmd.RunCmd(run("-l", "info", "help", "helloworld", "goodbye"))
 	res.Assert(t, icmd.Expected{
 		ExitCode: 0,
-		Err:      icmd.None,
+		Err:      "Warning: Unexpected error, the help command will not have OTEL metrics",
 	})
 	golden.Assert(t, res.Stdout(), "docker-help-helloworld-goodbye.golden")
 }