From 784377898f2ec6b7936dcacde036eab921dccd02 Mon Sep 17 00:00:00 2001 From: Milas Bowman Date: Mon, 6 Feb 2023 16:16:50 -0500 Subject: [PATCH] metrics: track and report non-aggregated events Currently, "usage" reports are sent, which are aggregated. Add "event" variant, which won't be aggregated. For compatibility, the "usage" events remain and nothing has changed in terms of how they parse the command args, for example. This will ensure continued functioning of anything that relies on these metrics. For the "event" variants, the CLI parsing is slightly different in an attempt to improve data analysis capabilities while still being respectful of user privacy (i.e. only known values of Docker CLI commands/flags are ever recorded). Additionally, execution duration information is now reported with these events. Signed-off-by: Milas Bowman --- cli/main.go | 10 +- cli/metrics/client.go | 37 ++++-- cli/metrics/docker_command.go | 193 +++++++++++++++++++++++++++++ cli/metrics/docker_command_test.go | 92 ++++++++++++++ cli/metrics/metrics.go | 55 ++++++-- cli/metrics/reporter.go | 67 ++++++++-- cli/mobycli/exec.go | 6 +- cli/server/metrics.go | 2 +- cli/server/metrics_test.go | 6 +- go.mod | 2 +- 10 files changed, 423 insertions(+), 47 deletions(-) create mode 100644 cli/metrics/docker_command.go create mode 100644 cli/metrics/docker_command_test.go diff --git a/cli/main.go b/cli/main.go index 81729ebfc..9693d5718 100644 --- a/cli/main.go +++ b/cli/main.go @@ -260,7 +260,7 @@ func main() { handleError(ctx, err, ctype, currentContext, cc, root, start, duration) } metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: ctype, Args: os.Args[1:], Status: metrics.SuccessStatus, @@ -298,7 +298,7 @@ func handleError( // if user canceled request, simply exit without any error message if api.IsErrCanceled(err) || errors.Is(ctx.Err(), context.Canceled) { metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: ctype, Args: os.Args[1:], Status: metrics.CanceledStatus, @@ -335,7 +335,7 @@ func exit(ctx string, err error, ctype string, start time.Time, duration time.Du if exit, ok := err.(cli.StatusError); ok { // TODO(milas): shouldn't this use the exit code to determine status? metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: ctype, Args: os.Args[1:], Status: metrics.SuccessStatus, @@ -358,7 +358,7 @@ func exit(ctx string, err error, ctype string, start time.Time, duration time.Du exitCode = metrics.CommandSyntaxFailure.ExitCode } metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: ctype, Args: os.Args[1:], Status: metricsStatus, @@ -400,7 +400,7 @@ 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(metrics.CmdMeta{ + metricsClient.Track(metrics.CmdResult{ ContextType: contextType, Args: os.Args[1:], Status: metrics.FailureStatus, diff --git a/cli/metrics/client.go b/cli/metrics/client.go index 896bf3cdb..145e83afa 100644 --- a/cli/metrics/client.go +++ b/cli/metrics/client.go @@ -26,13 +26,26 @@ import ( // specified file path. const EnvVarDebugMetricsPath = "DOCKER_METRICS_DEBUG_LOG" -type CmdMeta struct { +// Timeout is the maximum amount of time we'll wait for metrics sending to be +// acknowledged before giving up. +const Timeout = 50 * time.Millisecond + +// CmdResult provides details about process execution. +type CmdResult struct { + // ContextType is `moby` for Docker or the name of a cloud provider. ContextType string - Args []string - Status string - ExitCode int - Start time.Time - Duration time.Duration + // Args minus the process name (argv[0] aka `docker`). + Args []string + // Status based on exit code as a descriptive value. + // + // Deprecated: used for usage, events rely exclusively on exit code. + Status string + // ExitCode is 0 on success; otherwise, failure. + ExitCode int + // Start time of the process (UTC). + Start time.Time + // Duration of process execution. + Duration time.Duration } type client struct { @@ -44,8 +57,8 @@ type cliversion struct { f func() string } -// Command is a command -type Command struct { +// CommandUsage reports a CLI invocation for aggregation. +type CommandUsage struct { Command string `json:"command"` Context string `json:"context"` Source string `json:"source"` @@ -69,9 +82,9 @@ type Client interface { // SendUsage sends the command to Docker Desktop. // // Note that metric collection is best-effort, so any errors are ignored. - SendUsage(Command) + SendUsage(CommandUsage) // Track creates an event for a command execution and reports it. - Track(cmd CmdMeta) + Track(CmdResult) } // NewClient returns a new metrics client that will send metrics using the @@ -107,7 +120,7 @@ func (c *client) WithCliVersionFunc(f func() string) { c.cliversion.f = f } -func (c *client) SendUsage(command Command) { +func (c *client) SendUsage(command CommandUsage) { result := make(chan bool, 1) go func() { c.reporter.Heartbeat(command) @@ -118,6 +131,6 @@ func (c *client) SendUsage(command Command) { // Posting metrics without Desktop listening returns in less than a ms, and a handful of ms (often <2ms) when Desktop is listening select { case <-result: - case <-time.After(50 * time.Millisecond): + case <-time.After(Timeout): } } diff --git a/cli/metrics/docker_command.go b/cli/metrics/docker_command.go new file mode 100644 index 000000000..f756ffc1c --- /dev/null +++ b/cli/metrics/docker_command.go @@ -0,0 +1,193 @@ +/* + Copyright 2022 Docker Compose CLI authors + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package metrics + +import ( + "strings" + "time" +) + +// DockerCLIEvent represents an invocation of `docker` from the the CLI. +type DockerCLIEvent struct { + Command string `json:"command,omitempty"` + Subcommand string `json:"subcommand,omitempty"` + Usage bool `json:"usage,omitempty"` + ExitCode int32 `json:"exit_code"` + StartTime time.Time `json:"start_time"` + DurationSecs float64 `json:"duration_secs,omitempty"` +} + +// NewDockerCLIEvent inspects the command line string and returns a stripped down +// version suitable for reporting. +// +// The parser will only use known values for command/subcommand from a hardcoded +// built-in set for safety. It also does not attempt to perfectly accurately +// reflect how arg parsing works in a real program, instead favoring a fairly +// simple approach that's still reasonably robust. +// +// If the command does not map to a known Docker (or first-party plugin) +// command, `nil` will be returned. Similarly, if no subcommand for the +// built-in/plugin can be determined, it will be empty. +func NewDockerCLIEvent(cmd CmdResult) *DockerCLIEvent { + if len(cmd.Args) == 0 { + return nil + } + + cmdPath := findCommand(append([]string{"docker"}, cmd.Args...)) + if cmdPath == nil { + return nil + } + + if len(cmdPath) < 2 { + // ignore unknown commands; we can't infer anything from them safely + // N.B. ONLY compose commands are supported by `cmdHierarchy` currently! + return nil + } + + // look for a subcommand + var subcommand string + if len(cmdPath) >= 3 { + var subcommandParts []string + for _, c := range cmdPath[2:] { + subcommandParts = append(subcommandParts, c.name) + } + subcommand = strings.Join(subcommandParts, "-") + } + + var usage bool + for _, arg := range cmd.Args { + // TODO(milas): also support `docker help build` syntax + if arg == "help" { + return nil + } + + if arg == "--help" || arg == "-h" { + usage = true + } + } + + event := &DockerCLIEvent{ + Command: cmdPath[1].name, + Subcommand: subcommand, + ExitCode: int32(cmd.ExitCode), + Usage: usage, + StartTime: cmd.Start, + DurationSecs: cmd.Duration.Seconds(), + } + + return event +} + +func findCommand(args []string) []*cmdNode { + if len(args) == 0 { + return nil + } + + cmdPath := []*cmdNode{cmdHierarchy} + if len(args) == 1 { + return cmdPath + } + + nodePath := []string{args[0]} + for _, v := range args[1:] { + v = strings.TrimSpace(v) + if v == "" || strings.HasPrefix(v, "-") { + continue + } + candidate := append(nodePath, v) + if c := cmdHierarchy.find(candidate); c != nil { + cmdPath = append(cmdPath, c) + nodePath = candidate + } + } + + return cmdPath +} + +type cmdNode struct { + name string + plugin bool + children []*cmdNode +} + +func (c *cmdNode) find(path []string) *cmdNode { + if len(path) == 0 { + return nil + } + + if c.name != path[0] { + return nil + } + + if len(path) == 1 { + return c + } + + remainder := path[1:] + for _, child := range c.children { + if res := child.find(remainder); res != nil { + return res + } + } + + return nil +} + +var cmdHierarchy = &cmdNode{ + name: "docker", + children: []*cmdNode{ + { + name: "compose", + plugin: true, + children: []*cmdNode{ + { + name: "alpha", + children: []*cmdNode{ + {name: "watch"}, + {name: "dryrun"}, + }, + }, + {name: "build"}, + {name: "config"}, + {name: "convert"}, + {name: "cp"}, + {name: "create"}, + {name: "down"}, + {name: "events"}, + {name: "exec"}, + {name: "images"}, + {name: "kill"}, + {name: "logs"}, + {name: "ls"}, + {name: "pause"}, + {name: "port"}, + {name: "ps"}, + {name: "pull"}, + {name: "push"}, + {name: "restart"}, + {name: "rm"}, + {name: "run"}, + {name: "start"}, + {name: "stop"}, + {name: "top"}, + {name: "unpause"}, + {name: "up"}, + {name: "version"}, + }, + }, + }, +} diff --git a/cli/metrics/docker_command_test.go b/cli/metrics/docker_command_test.go new file mode 100644 index 000000000..233ef2aac --- /dev/null +++ b/cli/metrics/docker_command_test.go @@ -0,0 +1,92 @@ +/* + Copyright 2022 Docker Compose CLI authors + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package metrics + +import ( + "testing" + + "github.com/mattn/go-shellwords" + "github.com/stretchr/testify/require" +) + +func TestCmdCompose(t *testing.T) { + tcs := []struct { + name string + input string + expected *DockerCLIEvent + }{ + { + name: "Docker - Root", + input: "docker", + expected: nil, + }, + { + name: "Docker - Build", + input: "docker build .", + // N.B. built-in commands are not reported currently, ONLY Compose + expected: nil, + }, + { + name: "Compose - Base", + input: "docker compose", + expected: &DockerCLIEvent{Command: "compose"}, + }, + { + name: "Compose - Root Args", + input: "docker --host 127.0.0.1 --debug=true compose ls", + expected: &DockerCLIEvent{ + Command: "compose", + Subcommand: "ls", + }, + }, + { + name: "Compose - Base Args", + input: "docker compose -p myproject build myservice", + expected: &DockerCLIEvent{ + Command: "compose", + Subcommand: "build", + }, + }, + { + name: "Compose - Usage", + input: "docker compose --file=mycompose.yaml up --help myservice", + expected: &DockerCLIEvent{ + Command: "compose", + Subcommand: "up", + Usage: true, + }, + }, + { + name: "Compose - Multilevel", + input: "docker -D compose alpha --arg watch", + expected: &DockerCLIEvent{ + Command: "compose", + Subcommand: "alpha-watch", + }, + }, + } + + for _, tc := range tcs { + t.Run(tc.name, func(t *testing.T) { + args, err := shellwords.Parse(tc.input) + require.NoError(t, err, "Invalid command: %s", tc.input) + + c := NewDockerCLIEvent(CmdResult{Args: args}) + require.Equal(t, tc.expected, c) + }) + } +} diff --git a/cli/metrics/metrics.go b/cli/metrics/metrics.go index 715727326..ae1bacadb 100644 --- a/cli/metrics/metrics.go +++ b/cli/metrics/metrics.go @@ -19,24 +19,48 @@ package metrics import ( "os" "strings" + "sync" + "time" "github.com/docker/compose/v2/pkg/utils" "github.com/docker/compose-cli/cli/metrics/metadata" ) -func (c *client) Track(cmd CmdMeta) { +func (c *client) Track(cmd CmdResult) { if isInvokedAsCliBackend() { return } - command := GetCommand(cmd.Args) - if command != "" { - c.SendUsage(Command{ - Command: command, - Context: cmd.ContextType, - Source: c.getMetadata(CLISource, cmd.Args), - Status: cmd.Status, - }) + + var wg sync.WaitGroup + usageCmd := NewCommandUsage(cmd) + if usageCmd != nil { + usageCmd.Source = c.getMetadata(CLISource, cmd.Args) + wg.Add(1) + go func() { + c.reporter.Heartbeat(*usageCmd) + wg.Done() + }() + } + + eventCmd := NewDockerCLIEvent(cmd) + if eventCmd != nil { + wg.Add(1) + go func() { + c.reporter.Event(*eventCmd) + wg.Done() + }() + } + + done := make(chan struct{}) + go func() { + defer close(done) + wg.Wait() + }() + + select { + case <-done: + case <-time.After(Timeout): } } @@ -100,3 +124,16 @@ func GetCommand(args []string) string { } return result } + +func NewCommandUsage(cmd CmdResult) *CommandUsage { + command := GetCommand(cmd.Args) + if command == "" { + return nil + } + + return &CommandUsage{ + Command: command, + Context: cmd.ContextType, + Status: cmd.Status, + } +} diff --git a/cli/metrics/reporter.go b/cli/metrics/reporter.go index e145f525d..255329bde 100644 --- a/cli/metrics/reporter.go +++ b/cli/metrics/reporter.go @@ -21,11 +21,21 @@ import ( "encoding/json" "io" "net/http" + "net/url" ) +type AnalyticsRequest struct { + Event string `json:"event"` + Body interface{} `json:"body"` +} + // Reporter reports metric events generated by the client. type Reporter interface { - Heartbeat(cmd Command) + // Heartbeat reports a metric for aggregation. + Heartbeat(cmd CommandUsage) + + // Event reports an analytics action. + Event(cmd DockerCLIEvent) } // HTTPReporter reports metric events to an HTTP endpoint. @@ -40,18 +50,33 @@ func NewHTTPReporter(client *http.Client) HTTPReporter { } // Heartbeat reports a metric for aggregation. -func (l HTTPReporter) Heartbeat(cmd Command) { - entry, err := json.Marshal(cmd) +func (l HTTPReporter) Heartbeat(cmd CommandUsage) { + l.post("/usage", cmd) +} + +// Event reports an analytics action. +func (l HTTPReporter) Event(cmd DockerCLIEvent) { + event := AnalyticsRequest{ + Event: "eventCliCommand", + Body: cmd, + } + l.post("/analytics/track", event) +} + +func (l HTTPReporter) post(path string, body interface{}) { + entry, err := json.Marshal(body) + if err != nil { + // we only pass known types that will marshal without error (no cycles) + return + } + + u, err := url.JoinPath("http://ipc", path) if err != nil { - // impossible: cannot fail on controlled input (i.e. no cycles) + // we only pass known values here, so this isn't possible in practice return } - resp, _ := l.client.Post( - "http://localhost/usage", - "application/json", - bytes.NewReader(entry), - ) + resp, _ := l.client.Post(u, "application/json", bytes.NewReader(entry)) if resp != nil && resp.Body != nil { _ = resp.Body.Close() } @@ -69,10 +94,19 @@ func NewWriterReporter(w io.Writer) WriterReporter { } // Heartbeat reports a metric for aggregation. -func (w WriterReporter) Heartbeat(cmd Command) { - entry, err := json.Marshal(cmd) +func (w WriterReporter) Heartbeat(cmd CommandUsage) { + w.write(cmd) +} + +// Event reports an analytics action. +func (w WriterReporter) Event(cmd DockerCLIEvent) { + w.write(cmd) +} + +func (w WriterReporter) write(v interface{}) { + entry, err := json.Marshal(v) if err != nil { - // impossible: cannot fail on controlled input (i.e. no cycles) + // we only pass known types that will marshal without error (no cycles) return } entry = append(entry, '\n') @@ -92,8 +126,15 @@ func NewMuxReporter(reporters ...Reporter) MuxReporter { } // Heartbeat reports a metric for aggregation. -func (m MuxReporter) Heartbeat(cmd Command) { +func (m MuxReporter) Heartbeat(cmd CommandUsage) { for i := range m.reporters { m.reporters[i].Heartbeat(cmd) } } + +// Event reports an analytics action. +func (m MuxReporter) Event(cmd DockerCLIEvent) { + for i := range m.reporters { + m.reporters[i].Event(cmd) + } +} diff --git a/cli/mobycli/exec.go b/cli/mobycli/exec.go index 9d1d20461..94396f493 100644 --- a/cli/mobycli/exec.go +++ b/cli/mobycli/exec.go @@ -86,7 +86,7 @@ func Exec(_ *cobra.Command) { if exiterr, ok := err.(*exec.ExitError); ok { exitCode := exiterr.ExitCode() metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: store.DefaultContextType, Args: os.Args[1:], Status: metrics.FailureCategoryFromExitCode(exitCode).MetricsStatus, @@ -98,7 +98,7 @@ func Exec(_ *cobra.Command) { os.Exit(exitCode) } metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: store.DefaultContextType, Args: os.Args[1:], Status: metrics.FailureStatus, @@ -115,7 +115,7 @@ func Exec(_ *cobra.Command) { displayPATSuggestMsg(commandArgs) } metricsClient.Track( - metrics.CmdMeta{ + metrics.CmdResult{ ContextType: store.DefaultContextType, Args: os.Args[1:], Status: metrics.SuccessStatus, diff --git a/cli/server/metrics.go b/cli/server/metrics.go index 683cfd361..55cf51d11 100644 --- a/cli/server/metrics.go +++ b/cli/server/metrics.go @@ -66,7 +66,7 @@ func metricsServerInterceptor(client metrics.Client) grpc.UnaryServerInterceptor } command := methodMapping[info.FullMethod] if command != "" { - client.SendUsage(metrics.Command{ + client.SendUsage(metrics.CommandUsage{ Command: command, Context: contextType, Source: metrics.APISource, diff --git a/cli/server/metrics_test.go b/cli/server/metrics_test.go index 4c99e6b06..06d88a92d 100644 --- a/cli/server/metrics_test.go +++ b/cli/server/metrics_test.go @@ -60,7 +60,7 @@ func TestAllMethodsHaveCorrespondingCliCommand(t *testing.T) { func TestTrackSuccess(t *testing.T) { var mockMetrics = &mockMetricsClient{} - mockMetrics.On("SendUsage", metrics.Command{Command: "ps", Context: "aci", Status: "success", Source: "api"}).Return() + mockMetrics.On("SendUsage", metrics.CommandUsage{Command: "ps", Context: "aci", Status: "success", Source: "api"}).Return() newClient := client.NewClient("aci", noopService{}) interceptor := metricsServerInterceptor(mockMetrics) @@ -126,10 +126,10 @@ func (s *mockMetricsClient) WithCliVersionFunc(f func() string) { s.Called(f) } -func (s *mockMetricsClient) SendUsage(command metrics.Command) { +func (s *mockMetricsClient) SendUsage(command metrics.CommandUsage) { s.Called(command) } -func (s *mockMetricsClient) Track(cmd metrics.CmdMeta) { +func (s *mockMetricsClient) Track(cmd metrics.CmdResult) { s.Called(cmd) } diff --git a/go.mod b/go.mod index c80b9afb9..69db23c9a 100644 --- a/go.mod +++ b/go.mod @@ -37,6 +37,7 @@ require ( github.com/iancoleman/strcase v0.2.0 github.com/joho/godotenv v1.3.0 github.com/labstack/echo v3.3.10+incompatible + github.com/mattn/go-shellwords v1.0.12 github.com/morikuni/aec v1.0.0 github.com/opencontainers/go-digest v1.0.0 github.com/opencontainers/image-spec v1.0.2 @@ -145,7 +146,6 @@ require ( github.com/mattn/go-ieproxy v0.0.0-20190610004146-91bb50d98149 // indirect github.com/mattn/go-isatty v0.0.14 // indirect github.com/mattn/go-runewidth v0.0.7 // indirect - github.com/mattn/go-shellwords v1.0.12 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b // indirect github.com/miekg/pkcs11 v1.0.3 // indirect