From a5644cd608ef704bea53378ca04008520453ccbd Mon Sep 17 00:00:00 2001 From: Christopher Petito Date: Fri, 17 May 2024 12:22:18 +0000 Subject: [PATCH] Instrument plugin command executions Signed-off-by: Christopher Petito --- cli-plugins/manager/cobra.go | 11 +++- cli/command/telemetry_utils.go | 98 ++++++++++++++++++++++++++--- cli/command/telemetry_utils_test.go | 2 +- cmd/docker/docker.go | 32 +++++++--- 4 files changed, 125 insertions(+), 18 deletions(-) diff --git a/cli-plugins/manager/cobra.go b/cli-plugins/manager/cobra.go index feff8a8fd6f3..e46c909e1713 100644 --- a/cli-plugins/manager/cobra.go +++ b/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 verifiedDockerCli, ok := dockerCli.(*command.DockerCli); ok { + runCommand := verifiedDockerCli.InstrumentPluginCommand(pluginRunCommand) + runErr = runCommand.TimedRun() + } 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 } diff --git a/cli/command/telemetry_utils.go b/cli/command/telemetry_utils.go index 87b976ce69a7..2f457f5fbbad 100644 --- a/cli/command/telemetry_utils.go +++ b/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,66 @@ 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 an otel meter +func (c *wrappedCmd) TimedRun() 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 its 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...), + ) + if mp, ok := mp.(MeterProvider); ok { + mp.ForceFlush(ctx) + } + } +} + func stdioAttributes(streams Streams) []attribute.KeyValue { // we don't wrap stderr, but we do wrap in/out _, stderrTty := term.GetFdInfo(streams.Err()) @@ -110,7 +171,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 +192,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" @@ -149,7 +233,7 @@ func (e statusError) Error() string { } // getCommandName gets the cobra command name in the format -// `... parentCommandName commandName` by traversing it's parent commands recursively. +// `... parentCommandName commandName` by traversing its parent commands recursively. // until the root command is reached. // // Note: The root command's name is excluded. If cmd is the root cmd, return "" @@ -163,7 +247,7 @@ func getCommandName(cmd *cobra.Command) string { } // getFullCommandName gets the full cobra command name in the format -// `... parentCommandName commandName` by traversing it's parent commands recursively +// `... parentCommandName commandName` by traversing its parent commands recursively // until the root command is reached. func getFullCommandName(cmd *cobra.Command) string { if cmd.HasParent() { diff --git a/cli/command/telemetry_utils_test.go b/cli/command/telemetry_utils_test.go index a8520816aa02..73c4160edc67 100644 --- a/cli/command/telemetry_utils_test.go +++ b/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)) }) } diff --git a/cmd/docker/docker.go b/cmd/docker/docker.go index 27eb0263bd61..7abe1f26c384 100644 --- a/cmd/docker/docker.go +++ b/cmd/docker/docker.go @@ -136,9 +136,15 @@ 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() + } + // 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 +165,17 @@ 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() + } + // 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 +236,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 +293,7 @@ func tryPluginRun(dockerCli command.Cli, cmd *cobra.Command, subcommand string, } }() - if err := plugincmd.Run(); err != nil { + if err := plugincmd.TimedRun(); err != nil { statusCode := 1 exitErr, ok := err.(*exec.ExitError) if !ok { @@ -304,6 +318,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 +373,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.