From ebc0eff4780c5a9b0bdd84807bfbd3aa1c9cefd9 Mon Sep 17 00:00:00 2001 From: Drew Erny Date: Mon, 8 May 2017 10:58:37 -0700 Subject: [PATCH] Add support for details on service logs Adds CLI and client support for details on service logs. CLI component of moby/moby#32996. Signed-off-by: Drew Erny --- cli/command/service/logs.go | 190 +++++++++++------- vendor.conf | 2 +- .../docker/docker/client/config_update.go | 2 +- .../docker/docker/client/parse_logs.go | 41 ++++ .../docker/docker/client/secret_update.go | 2 +- 5 files changed, 161 insertions(+), 76 deletions(-) create mode 100644 vendor/github.com/docker/docker/client/parse_logs.go diff --git a/cli/command/service/logs.go b/cli/command/service/logs.go index e4ccd34f..42e00e6c 100644 --- a/cli/command/service/logs.go +++ b/cli/command/service/logs.go @@ -4,6 +4,7 @@ import ( "bytes" "fmt" "io" + "sort" "strconv" "strings" @@ -29,15 +30,12 @@ type logsOptions struct { since string timestamps bool tail string + details bool + raw bool target string } -// TODO(dperny) the whole CLI for this is kind of a mess IMHOIRL and it needs -// to be refactored agressively. There may be changes to the implementation of -// details, which will be need to be reflected in this code. The refactoring -// should be put off until we make those changes, tho, because I think the -// decisions made WRT details will impact the design of the CLI. func newLogsCommand(dockerCli *command.DockerCli) *cobra.Command { var opts logsOptions @@ -56,11 +54,15 @@ func newLogsCommand(dockerCli *command.DockerCli) *cobra.Command { // options specific to service logs flags.BoolVar(&opts.noResolve, "no-resolve", false, "Do not map IDs to Names in output") flags.BoolVar(&opts.noTrunc, "no-trunc", false, "Do not truncate output") + flags.BoolVar(&opts.raw, "raw", false, "Do not neatly format logs") + flags.SetAnnotation("raw", "version", []string{"1.30"}) flags.BoolVar(&opts.noTaskIDs, "no-task-ids", false, "Do not include task IDs in output") // options identical to container logs flags.BoolVarP(&opts.follow, "follow", "f", false, "Follow log output") flags.StringVar(&opts.since, "since", "", "Show logs since timestamp (e.g. 2013-01-02T13:23:37) or relative (e.g. 42m for 42 minutes)") flags.BoolVarP(&opts.timestamps, "timestamps", "t", false, "Show timestamps") + flags.BoolVar(&opts.details, "details", false, "Show extra details provided to logs") + flags.SetAnnotation("details", "version", []string{"1.30"}) flags.StringVar(&opts.tail, "tail", "all", "Number of lines to show from the end of the logs") return cmd } @@ -75,7 +77,9 @@ func runLogs(dockerCli *command.DockerCli, opts *logsOptions) error { Timestamps: opts.timestamps, Follow: opts.follow, Tail: opts.tail, - Details: true, + // get the details if we request it OR if we're not doing raw mode + // (we need them for the context to pretty print) + Details: opts.details || !opts.raw, } cli := dockerCli.Client() @@ -84,6 +88,9 @@ func runLogs(dockerCli *command.DockerCli, opts *logsOptions) error { maxLength = 1 responseBody io.ReadCloser tty bool + // logfunc is used to delay the call to logs so that we can do some + // processing before we actually get the logs + logfunc func(context.Context, string, types.ContainerLogsOptions) (io.ReadCloser, error) ) service, _, err := cli.ServiceInspectWithRaw(ctx, opts.target, types.ServiceInspectOptions{}) @@ -97,56 +104,60 @@ func runLogs(dockerCli *command.DockerCli, opts *logsOptions) error { if client.IsErrTaskNotFound(err) { // if the task isn't found, rewrite the error to be clear // that we looked for services AND tasks and found none - err = fmt.Errorf("no such task or service") + err = fmt.Errorf("no such task or service: %v", opts.target) } return err } + tty = task.Spec.ContainerSpec.TTY - // TODO(dperny) hot fix until we get a nice details system squared away, - // ignores details (including task context) if we have a TTY log - // if we don't do this, we'll vomit the huge context verbatim into the - // TTY log lines and that's Undesirable. - if tty { - options.Details = false - } - - responseBody, err = cli.TaskLogs(ctx, opts.target, options) - if err != nil { - return err - } - maxLength = getMaxLength(task.Slot) - } else { - tty = service.Spec.TaskTemplate.ContainerSpec.TTY - // TODO(dperny) hot fix until we get a nice details system squared away, - // ignores details (including task context) if we have a TTY log - if tty { - options.Details = false - } - responseBody, err = cli.ServiceLogs(ctx, opts.target, options) - if err != nil { - return err - } + // use the TaskLogs api function + logfunc = cli.TaskLogs + } else { + // use ServiceLogs api function + logfunc = cli.ServiceLogs + tty = service.Spec.TaskTemplate.ContainerSpec.TTY if service.Spec.Mode.Replicated != nil && service.Spec.Mode.Replicated.Replicas != nil { // if replicas are initialized, figure out if we need to pad them replicas := *service.Spec.Mode.Replicated.Replicas maxLength = getMaxLength(int(replicas)) } } + + // we can't prettify tty logs. tell the user that this is the case. + // this is why we assign the logs function to a variable and delay calling + // it. we want to check this before we make the call and checking twice in + // each branch is even sloppier than this CLI disaster already is + if tty && !opts.raw { + return errors.New("tty service logs only supported with --raw") + } + + // now get the logs + responseBody, err = logfunc(ctx, opts.target, options) + if err != nil { + return err + } defer responseBody.Close() + // tty logs get straight copied. they're not muxed with stdcopy if tty { _, err = io.Copy(dockerCli.Out(), responseBody) return err } - taskFormatter := newTaskFormatter(cli, opts, maxLength) + // otherwise, logs are multiplexed. if we're doing pretty printing, also + // create a task formatter. + var stdout, stderr io.Writer + stdout = dockerCli.Out() + stderr = dockerCli.Err() + if !opts.raw { + taskFormatter := newTaskFormatter(cli, opts, maxLength) - stdout := &logWriter{ctx: ctx, opts: opts, f: taskFormatter, w: dockerCli.Out()} - stderr := &logWriter{ctx: ctx, opts: opts, f: taskFormatter, w: dockerCli.Err()} + stdout = &logWriter{ctx: ctx, opts: opts, f: taskFormatter, w: stdout} + stderr = &logWriter{ctx: ctx, opts: opts, f: taskFormatter, w: stderr} + } - // TODO(aluzzardi): Do an io.Copy for services with TTY enabled. _, err = stdcopy.StdCopy(stdout, stderr, responseBody) return err } @@ -161,7 +172,9 @@ type taskFormatter struct { opts *logsOptions padding int - r *idresolver.IDResolver + r *idresolver.IDResolver + // cache saves a pre-cooked logContext formatted string based on a + // logcontext object, so we don't have to resolve names every time cache map[logContext]string } @@ -222,40 +235,78 @@ type logWriter struct { } func (lw *logWriter) Write(buf []byte) (int, error) { - contextIndex := 0 + // this works but ONLY because stdcopy calls write a whole line at a time. + // if this ends up horribly broken or panics, check to see if stdcopy has + // reneged on that asssumption. (@god forgive me) + // also this only works because the logs format is, like, barely parsable. + // if something changes in the logs format, this is gonna break + + // there should always be at least 2 parts: details and message. if there + // is no timestamp, details will be first (index 0) when we split on + // spaces. if there is a timestamp, details will be 2nd (`index 1) + detailsIndex := 0 numParts := 2 if lw.opts.timestamps { - contextIndex++ + detailsIndex++ numParts++ } + // break up the log line into parts. parts := bytes.SplitN(buf, []byte(" "), numParts) if len(parts) != numParts { return 0, errors.Errorf("invalid context in log message: %v", string(buf)) } - - logCtx, err := lw.parseContext(string(parts[contextIndex])) + // parse the details out + details, err := client.ParseLogDetails(string(parts[detailsIndex])) + if err != nil { + return 0, err + } + // and then create a context from the details + // this removes the context-specific details from the details map, so we + // can more easily print the details later + logCtx, err := lw.parseContext(details) if err != nil { return 0, err } output := []byte{} - for i, part := range parts { - // First part doesn't get space separation. - if i > 0 { - output = append(output, []byte(" ")...) - } - - if i == contextIndex { - formatted, err := lw.f.format(lw.ctx, logCtx) - if err != nil { - return 0, err - } - output = append(output, []byte(fmt.Sprintf("%s |", formatted))...) - } else { - output = append(output, part...) - } + // if we included timestamps, add them to the front + if lw.opts.timestamps { + output = append(output, parts[0]...) + output = append(output, ' ') } + // add the context, nice and formatted + formatted, err := lw.f.format(lw.ctx, logCtx) + if err != nil { + return 0, err + } + output = append(output, []byte(formatted+" | ")...) + // if the user asked for details, add them to be log message + if lw.opts.details { + // ugh i hate this it's basically a dupe of api/server/httputils/write_log_stream.go:stringAttrs() + // ok but we're gonna do it a bit different + + // there are optimizations that can be made here. for starters, i'd + // suggest caching the details keys. then, we can maybe draw maps and + // slices from a pool to avoid alloc overhead on them. idk if it's + // worth the time yet. + + // first we need a slice + d := make([]string, 0, len(details)) + // then let's add all the pairs + for k := range details { + d = append(d, k+"="+details[k]) + } + // then sort em + sort.Strings(d) + // then join and append + output = append(output, []byte(strings.Join(d, ","))...) + output = append(output, ' ') + } + + // add the log message itself, finally + output = append(output, parts[detailsIndex+1]...) + _, err = lw.w.Write(output) if err != nil { return 0, err @@ -264,32 +315,25 @@ func (lw *logWriter) Write(buf []byte) (int, error) { return len(buf), nil } -func (lw *logWriter) parseContext(input string) (logContext, error) { - context := make(map[string]string) - - components := strings.Split(input, ",") - for _, component := range components { - parts := strings.SplitN(component, "=", 2) - if len(parts) != 2 { - return logContext{}, errors.Errorf("invalid context: %s", input) - } - context[parts[0]] = parts[1] - } - - nodeID, ok := context["com.docker.swarm.node.id"] +// parseContext returns a log context and REMOVES the context from the details map +func (lw *logWriter) parseContext(details map[string]string) (logContext, error) { + nodeID, ok := details["com.docker.swarm.node.id"] if !ok { - return logContext{}, errors.Errorf("missing node id in context: %s", input) + return logContext{}, errors.Errorf("missing node id in details: %v", details) } + delete(details, "com.docker.swarm.node.id") - serviceID, ok := context["com.docker.swarm.service.id"] + serviceID, ok := details["com.docker.swarm.service.id"] if !ok { - return logContext{}, errors.Errorf("missing service id in context: %s", input) + return logContext{}, errors.Errorf("missing service id in details: %v", details) } + delete(details, "com.docker.swarm.service.id") - taskID, ok := context["com.docker.swarm.task.id"] + taskID, ok := details["com.docker.swarm.task.id"] if !ok { - return logContext{}, errors.Errorf("missing task id in context: %s", input) + return logContext{}, errors.Errorf("missing task id in details: %s", details) } + delete(details, "com.docker.swarm.task.id") return logContext{ nodeID: nodeID, diff --git a/vendor.conf b/vendor.conf index 93924ece..c0a72b49 100644 --- a/vendor.conf +++ b/vendor.conf @@ -6,7 +6,7 @@ github.com/agl/ed25519 d2b94fd789ea21d12fac1a4443dd3a3f79cda72c github.com/coreos/etcd 824277cb3a577a0e8c829ca9ec557b973fe06d20 github.com/davecgh/go-spew 346938d642f2ec3594ed81d874461961cd0faa76 github.com/docker/distribution b38e5838b7b2f2ad48e06ec4b500011976080621 -github.com/docker/docker eb8abc95985bf3882a4a177c409a96e36e25f5b7 +github.com/docker/docker 7fd8a9382c0fd3f23002288e357b5612b869a974 github.com/docker/docker-credential-helpers v0.5.0 github.com/docker/go d30aec9fd63c35133f8f79c3412ad91a3b08be06 github.com/docker/go-connections e15c02316c12de00874640cd76311849de2aeed5 diff --git a/vendor/github.com/docker/docker/client/config_update.go b/vendor/github.com/docker/docker/client/config_update.go index 06f71151..da171cb4 100644 --- a/vendor/github.com/docker/docker/client/config_update.go +++ b/vendor/github.com/docker/docker/client/config_update.go @@ -8,7 +8,7 @@ import ( "golang.org/x/net/context" ) -// ConfigUpdate attempts to updates a Config +// ConfigUpdate attempts to update a Config func (cli *Client) ConfigUpdate(ctx context.Context, id string, version swarm.Version, config swarm.ConfigSpec) error { query := url.Values{} query.Set("version", strconv.FormatUint(version.Index, 10)) diff --git a/vendor/github.com/docker/docker/client/parse_logs.go b/vendor/github.com/docker/docker/client/parse_logs.go new file mode 100644 index 00000000..e427f80a --- /dev/null +++ b/vendor/github.com/docker/docker/client/parse_logs.go @@ -0,0 +1,41 @@ +package client + +// parse_logs.go contains utility helpers for getting information out of docker +// log lines. really, it only contains ParseDetails right now. maybe in the +// future there will be some desire to parse log messages back into a struct? +// that would go here if we did + +import ( + "net/url" + "strings" + + "github.com/pkg/errors" +) + +// ParseLogDetails takes a details string of key value pairs in the form +// "k=v,l=w", where the keys and values are url query escaped, and each pair +// is separated by a comma, returns a map. returns an error if the details +// string is not in a valid format +// the exact form of details encoding is implemented in +// api/server/httputils/write_log_stream.go +func ParseLogDetails(details string) (map[string]string, error) { + pairs := strings.Split(details, ",") + detailsMap := make(map[string]string, len(pairs)) + for _, pair := range pairs { + p := strings.SplitN(pair, "=", 2) + // if there is no equals sign, we will only get 1 part back + if len(p) != 2 { + return nil, errors.New("invalid details format") + } + k, err := url.QueryUnescape(p[0]) + if err != nil { + return nil, err + } + v, err := url.QueryUnescape(p[1]) + if err != nil { + return nil, err + } + detailsMap[k] = v + } + return detailsMap, nil +} diff --git a/vendor/github.com/docker/docker/client/secret_update.go b/vendor/github.com/docker/docker/client/secret_update.go index 42cdbbe1..3af52870 100644 --- a/vendor/github.com/docker/docker/client/secret_update.go +++ b/vendor/github.com/docker/docker/client/secret_update.go @@ -8,7 +8,7 @@ import ( "golang.org/x/net/context" ) -// SecretUpdate attempts to updates a Secret +// SecretUpdate attempts to update a Secret func (cli *Client) SecretUpdate(ctx context.Context, id string, version swarm.Version, secret swarm.SecretSpec) error { query := url.Values{} query.Set("version", strconv.FormatUint(version.Index, 10))