Instrument plugin command executions

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

Author: krissetto

cli-plugins/manager/cobra.go

@@ -90,11 +90,12 @@ 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()
+					runCommand := dockerCli.(*command.DockerCli).InstrumentPluginCommand(pluginRunCommand)
+					runErr = runCommand.TimedRun(cmd.Context())
 					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,20 +15,18 @@ 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)...)
 }
 
 // InstrumentCobraCommands wraps all cobra commands' RunE funcs to set a command duration metric using otel.
 //
-// Note: this should be the last func to wrap/modify the PersistentRunE/RunE funcs before command execution.
-//
-// can also be used for spans!
-func (cli *DockerCli) InstrumentCobraCommands(cmd *cobra.Command, mp metric.MeterProvider) {
-	meter := getDefaultMeter(mp)
+// Note: this should be the last func to wrap/modify the PersistentRunE/RunE funcs
+// before command execution for more accurate measurements.
+func (cli *DockerCli) InstrumentCobraCommands(cmd *cobra.Command) {
 	// If PersistentPreRunE is nil, make it execute PersistentPreRun and return nil by default
 	ogPersistentPreRunE := cmd.PersistentPreRunE
 	if ogPersistentPreRunE == nil {
@@ -55,8 +54,8 @@ func (cli *DockerCli) InstrumentCobraCommands(cmd *cobra.Command, mp metric.Mete
 		}
 		cmd.RunE = func(cmd *cobra.Command, args []string) error {
 			// start the timer as the first step of every cobra command
-			baseAttrs := BaseCommandAttributes(cmd, cli)
-			stopCobraCmdTimer := startCobraCommandTimer(cmd, meter, baseAttrs)
+			baseAttrs := baseCommandAttributes(cmd, cli)
+			stopCobraCmdTimer := cli.startCobraCommandTimer(cmd, baseAttrs)
 			cmdErr := ogRunE(cmd, args)
 			stopCobraCmdTimer(cmdErr)
 			return cmdErr
@@ -66,9 +65,9 @@ func (cli *DockerCli) InstrumentCobraCommands(cmd *cobra.Command, mp metric.Mete
 	}
 }
 
-func startCobraCommandTimer(cmd *cobra.Command, meter metric.Meter, attrs []attribute.KeyValue) func(err error) {
+func (cli *DockerCli) startCobraCommandTimer(cmd *cobra.Command, attrs []attribute.KeyValue) func(err error) {
 	ctx := cmd.Context()
-	durationCounter, _ := meter.Float64Counter(
+	durationCounter, _ := cli.getDefaultMeter().Float64Counter(
 		"command.time",
 		metric.WithDescription("Measures the duration of the cobra command"),
 		metric.WithUnit("ms"),
@@ -77,14 +76,66 @@ func startCobraCommandTimer(cmd *cobra.Command, meter metric.Meter, attrs []attr
 
 	return func(err error) {
 		duration := float64(time.Since(start)) / float64(time.Millisecond)
-		cmdStatusAttrs := attributesFromError(err)
+		cmdStatusAttrs := attributesFromCommandError(err)
 		durationCounter.Add(ctx, duration,
 			metric.WithAttributes(attrs...),
 			metric.WithAttributes(cmdStatusAttrs...),
 		)
 	}
 }
 
+// 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(ctx, 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(ctx context.Context, attrs []attribute.KeyValue) func(err error) {
+	durationCounter, _ := cli.getDefaultMeter().Float64Counter(
+		"plugin.command.time",
+		metric.WithDescription("Measures the duration of the plugin execution"),
+		metric.WithUnit("ms"),
+	)
+	start := time.Now()
+
+	return func(err error) {
+		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())
@@ -95,7 +146,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 {
@@ -114,6 +167,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"
@@ -158,9 +232,9 @@ func getFullCommandName(cmd *cobra.Command) string {
 }
 
 // getDefaultMeter gets the default metric.Meter for the application
-// using the given metric.MeterProvider
-func getDefaultMeter(mp metric.MeterProvider) metric.Meter {
-	return mp.Meter(
+// using the global metric.MeterProvider
+func (cli *DockerCli) getDefaultMeter() metric.Meter {
+	return cli.MeterProvider().Meter(
 		"github.com/docker/cli",
 		metric.WithInstrumentationVersion(version.Version),
 	)

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,10 @@ 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()
+				helpcmd := dockerCli.(*command.DockerCli).InstrumentPluginCommand(helpRunCmd)
+				return helpcmd.TimedRun(c.Context())
 			}
 			if !pluginmanager.IsNotFound(err) {
 				return errors.Errorf("unknown help topic: %v", strings.Join(args, " "))
@@ -159,11 +160,12 @@ 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()
+	helpcmd := dockerCli.(*command.DockerCli).InstrumentPluginCommand(helpRunCmd)
+	return helpcmd.TimedRun(ccmd.Context())
 }
 
 func setHelpFunc(dockerCli command.Cli, cmd *cobra.Command) {
@@ -225,10 +227,11 @@ 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)
+	pluginRunCmd, err := pluginmanager.PluginRunCommand(dockerCli, subcommand, cmd)
 	if err != nil {
 		return err
 	}
+	plugincmd := dockerCli.(*command.DockerCli).InstrumentPluginCommand(pluginRunCmd)
 
 	// Establish the plugin socket, adding it to the environment under a
 	// well-known key if successful.
@@ -279,7 +282,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 {
@@ -308,9 +311,11 @@ func runDocker(ctx context.Context, dockerCli *command.DockerCli) error {
 		return err
 	}
 
-	mp := dockerCli.MeterProvider(ctx)
+	mp := dockerCli.MeterProvider()
 	defer mp.(command.MeterProvider).Shutdown(ctx)
-	dockerCli.InstrumentCobraCommands(cmd, mp)
+	dockerCli.InstrumentCobraCommands(cmd)
+
+	cmd.SetContext(ctx)
 
 	var envs []string
 	args, os.Args, envs, err = processAliases(dockerCli, cmd, args, os.Args)
@@ -352,7 +357,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.