metrics: initial logic for command execution duration

Add a timer around command invocations to be reported with metrics.
This isn't actually sent anywhere currently, as it's meant for
evented data which is forthcoming. (We could report it with the
current events, but it's not clear that there's any value in doing
so.)

The signature for `Track()` has been changed to take an object with
all the fields. This is both for sanity to keep the method from
getting ridiculously long, and to make it easier to unify the usage
(heartbeat) and event code paths by ensuring we have all the data
for both.

Signed-off-by: Milas Bowman <milas.bowman@docker.com>

cli/main.go

@@ -253,10 +253,20 @@ func main() {
 
 	root.AddCommand(command)
 
-	if err = root.ExecuteContext(ctx); err != nil {
-		handleError(ctx, err, ctype, currentContext, cc, root)
+	start := time.Now().UTC()
+	err = root.ExecuteContext(ctx)
+	duration := time.Since(start)
+	if err != nil {
+		handleError(ctx, err, ctype, currentContext, cc, root, start, duration)
 	}
-	metricsClient.Track(ctype, os.Args[1:], metrics.SuccessStatus)
+	metricsClient.Track(
+		metrics.CmdMeta{
+			ContextType: ctype,
+			Args:        os.Args[1:],
+			Status:      metrics.SuccessStatus,
+			Start:       start,
+			Duration:    duration,
+		})
 }
 
 func customizeCliForACI(command *cobra.Command, proxy *api.ServiceProxy) {
@@ -275,33 +285,64 @@ func customizeCliForACI(command *cobra.Command, proxy *api.ServiceProxy) {
 	}
 }
 
-func handleError(ctx context.Context, err error, ctype string, currentContext string, cc *store.DockerContext, root *cobra.Command) {
+func handleError(
+	ctx context.Context,
+	err error,
+	ctype string,
+	currentContext string,
+	cc *store.DockerContext,
+	root *cobra.Command,
+	start time.Time,
+	duration time.Duration,
+) {
 	// if user canceled request, simply exit without any error message
 	if api.IsErrCanceled(err) || errors.Is(ctx.Err(), context.Canceled) {
-		metricsClient.Track(ctype, os.Args[1:], metrics.CanceledStatus)
+		metricsClient.Track(
+			metrics.CmdMeta{
+				ContextType: ctype,
+				Args:        os.Args[1:],
+				Status:      metrics.CanceledStatus,
+				Start:       start,
+				Duration:    duration,
+			},
+		)
 		os.Exit(130)
 	}
 	if ctype == store.AwsContextType {
-		exit(currentContext, errors.Errorf(`%q context type has been renamed. Recreate the context by running:
-$ docker context create %s <name>`, cc.Type(), store.EcsContextType), ctype)
+		exit(
+			currentContext,
+			errors.Errorf(`%q context type has been renamed. Recreate the context by running:
+$ docker context create %s <name>`, cc.Type(), store.EcsContextType),
+			ctype,
+			start,
+			duration,
+		)
 	}
 
 	// Context should always be handled by new CLI
 	requiredCmd, _, _ := root.Find(os.Args[1:])
 	if requiredCmd != nil && isContextAgnosticCommand(requiredCmd) {
-		exit(currentContext, err, ctype)
+		exit(currentContext, err, ctype, start, duration)
 	}
 	mobycli.ExecIfDefaultCtxType(ctx, root)
 
 	checkIfUnknownCommandExistInDefaultContext(err, currentContext, ctype)
 
-	exit(currentContext, err, ctype)
+	exit(currentContext, err, ctype, start, duration)
 }
 
-func exit(ctx string, err error, ctype string) {
+func exit(ctx string, err error, ctype string, start time.Time, duration time.Duration) {
 	if exit, ok := err.(cli.StatusError); ok {
 		// TODO(milas): shouldn't this use the exit code to determine status?
-		metricsClient.Track(ctype, os.Args[1:], metrics.SuccessStatus)
+		metricsClient.Track(
+			metrics.CmdMeta{
+				ContextType: ctype,
+				Args:        os.Args[1:],
+				Status:      metrics.SuccessStatus,
+				Start:       start,
+				Duration:    duration,
+			},
+		)
 		os.Exit(exit.StatusCode)
 	}
 
@@ -316,7 +357,15 @@ func exit(ctx string, err error, ctype string) {
 		metricsStatus = metrics.CommandSyntaxFailure.MetricsStatus
 		exitCode = metrics.CommandSyntaxFailure.ExitCode
 	}
-	metricsClient.Track(ctype, os.Args[1:], metricsStatus)
+	metricsClient.Track(
+		metrics.CmdMeta{
+			ContextType: ctype,
+			Args:        os.Args[1:],
+			Status:      metricsStatus,
+			Start:       start,
+			Duration:    duration,
+		},
+	)
 
 	if errors.Is(err, api.ErrLoginRequired) {
 		fmt.Fprintln(os.Stderr, err)
@@ -351,7 +400,11 @@ func checkIfUnknownCommandExistInDefaultContext(err error, currentContext string
 
 		if mobycli.IsDefaultContextCommand(dockerCommand) {
 			fmt.Fprintf(os.Stderr, "Command %q not available in current context (%s), you can use the \"default\" context to run this command\n", dockerCommand, currentContext)
-			metricsClient.Track(contextType, os.Args[1:], metrics.FailureStatus)
+			metricsClient.Track(metrics.CmdMeta{
+				ContextType: contextType,
+				Args:        os.Args[1:],
+				Status:      metrics.FailureStatus,
+			})
 			os.Exit(1)
 		}
 	}

cli/metrics/client.go

@@ -26,6 +26,15 @@ import (
 // specified file path.
 const EnvVarDebugMetricsPath = "DOCKER_METRICS_DEBUG_LOG"
 
+type CmdMeta struct {
+	ContextType string
+	Args        []string
+	Status      string
+	ExitCode    int
+	Start       time.Time
+	Duration    time.Duration
+}
+
 type client struct {
 	cliversion *cliversion
 	reporter   Reporter
@@ -62,7 +71,7 @@ type Client interface {
 	// Note that metric collection is best-effort, so any errors are ignored.
 	SendUsage(Command)
 	// Track creates an event for a command execution and reports it.
-	Track(context string, args []string, status string)
+	Track(cmd CmdMeta)
 }
 
 // NewClient returns a new metrics client that will send metrics using the

cli/metrics/metrics.go

@@ -25,17 +25,17 @@ import (
 	"github.com/docker/compose-cli/cli/metrics/metadata"
 )
 
-func (c *client) Track(context string, args []string, status string) {
+func (c *client) Track(cmd CmdMeta) {
 	if isInvokedAsCliBackend() {
 		return
 	}
-	command := GetCommand(args)
+	command := GetCommand(cmd.Args)
 	if command != "" {
 		c.SendUsage(Command{
 			Command: command,
-			Context: context,
-			Source:  c.getMetadata(CLISource, args),
-			Status:  status,
+			Context: cmd.ContextType,
+			Source:  c.getMetadata(CLISource, cmd.Args),
+			Status:  cmd.Status,
 		})
 	}
 }

cli/mobycli/exec.go

@@ -27,6 +27,7 @@ import (
 	"regexp"
 	"runtime"
 	"strings"
+	"time"
 
 	"github.com/google/shlex"
 	"github.com/spf13/cobra"
@@ -76,20 +77,35 @@ func Exec(_ *cobra.Command) {
 	metricsClient.WithCliVersionFunc(func() string {
 		return CliVersion()
 	})
+	start := time.Now().UTC()
 	childExit := make(chan bool)
 	err := RunDocker(childExit, os.Args[1:]...)
 	childExit <- true
+	duration := time.Since(start)
 	if err != nil {
 		if exiterr, ok := err.(*exec.ExitError); ok {
 			exitCode := exiterr.ExitCode()
 			metricsClient.Track(
-				store.DefaultContextType,
-				os.Args[1:],
-				metrics.FailureCategoryFromExitCode(exitCode).MetricsStatus,
+				metrics.CmdMeta{
+					ContextType: store.DefaultContextType,
+					Args:        os.Args[1:],
+					Status:      metrics.FailureCategoryFromExitCode(exitCode).MetricsStatus,
+					ExitCode:    exitCode,
+					Start:       start,
+					Duration:    duration,
+				},
 			)
 			os.Exit(exitCode)
 		}
-		metricsClient.Track(store.DefaultContextType, os.Args[1:], metrics.FailureStatus)
+		metricsClient.Track(
+			metrics.CmdMeta{
+				ContextType: store.DefaultContextType,
+				Args:        os.Args[1:],
+				Status:      metrics.FailureStatus,
+				Start:       start,
+				Duration:    duration,
+			},
+		)
 		fmt.Fprintln(os.Stderr, err)
 		os.Exit(1)
 	}
@@ -98,7 +114,16 @@ func Exec(_ *cobra.Command) {
 	if command == "login" && !metrics.HasQuietFlag(commandArgs) {
 		displayPATSuggestMsg(commandArgs)
 	}
-	metricsClient.Track(store.DefaultContextType, os.Args[1:], metrics.SuccessStatus)
+	metricsClient.Track(
+		metrics.CmdMeta{
+			ContextType: store.DefaultContextType,
+			Args:        os.Args[1:],
+			Status:      metrics.SuccessStatus,
+			ExitCode:    0,
+			Start:       start,
+			Duration:    duration,
+		},
+	)
 
 	os.Exit(0)
 }

cli/server/metrics_test.go

@@ -130,6 +130,6 @@ func (s *mockMetricsClient) SendUsage(command metrics.Command) {
 	s.Called(command)
 }
 
-func (s *mockMetricsClient) Track(context string, args []string, status string) {
-	s.Called(context, args, status)
+func (s *mockMetricsClient) Track(cmd metrics.CmdMeta) {
+	s.Called(cmd)
 }