Change log details encoding format and support details on service logs

URL query encode log details, so that characters like spaces don't make
log parsing ambiguous. Add a helper function to parse these details to a
map, if needed

Add support for details on service logs

Signed-off-by: Drew Erny <drew.erny@docker.com>

api/server/httputils/write_log_stream.go

@@ -3,6 +3,7 @@ package httputils
 import (
 	"fmt"
 	"io"
+	"net/url"
 	"sort"
 	"strings"
 
@@ -85,6 +86,7 @@ func (s byKey) Swap(i, j int) {
 func stringAttrs(a backend.LogAttributes) string {
 	var ss byKey
 	for k, v := range a {
+		k, v := url.QueryEscape(k), url.QueryEscape(v)
 		ss = append(ss, k+"="+v)
 	}
 	sort.Sort(ss)

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
+}

client/parse_logs_test.go

@@ -0,0 +1,36 @@
+package client
+
+import (
+	"reflect"
+	"testing"
+
+	"github.com/pkg/errors"
+)
+
+func TestParseLogDetails(t *testing.T) {
+	testCases := []struct {
+		line     string
+		expected map[string]string
+		err      error
+	}{
+		{"key=value", map[string]string{"key": "value"}, nil},
+		{"key1=value1,key2=value2", map[string]string{"key1": "value1", "key2": "value2"}, nil},
+		{"key+with+spaces=value%3Dequals,asdf%2C=", map[string]string{"key with spaces": "value=equals", "asdf,": ""}, nil},
+		{"key=,=nothing", map[string]string{"key": "", "": "nothing"}, nil},
+		{"=", map[string]string{"": ""}, nil},
+		{"errors", nil, errors.New("invalid details format")},
+	}
+	for _, tc := range testCases {
+		tc := tc // capture range variable
+		t.Run(tc.line, func(t *testing.T) {
+			t.Parallel()
+			res, err := ParseLogDetails(tc.line)
+			if err != nil && (err.Error() != tc.err.Error()) {
+				t.Fatalf("unexpected error parsing logs:\nExpected:\n\t%v\nActual:\n\t%v", tc.err, err)
+			}
+			if !reflect.DeepEqual(tc.expected, res) {
+				t.Errorf("result does not match expected:\nExpected:\n\t%#v\nActual:\n\t%#v", tc.expected, res)
+			}
+		})
+	}
+}

daemon/cluster/executor/container/adapter.go

@@ -405,11 +405,11 @@ func (c *containerAdapter) logs(ctx context.Context, options api.LogSubscription
 	apiOptions := &types.ContainerLogsOptions{
 		Follow: options.Follow,
 
-		// TODO(stevvooe): Parse timestamp out of message. This
+		// Always say yes to Timestamps and Details. we make the decision
-		// absolutely needs to be done before going to production with
+		// of whether to return these to the user or not way higher up the
-		// this, at it is completely redundant.
+		// stack.
 		Timestamps: true,
-		Details:    false, // no clue what to do with this, let's just deprecate it.
+		Details:    true,
 	}
 
 	if options.Since != nil {

daemon/cluster/executor/container/controller.go

@@ -523,10 +523,18 @@ func (r *controller) Logs(ctx context.Context, publisher exec.LogPublisher, opti
 			stream = api.LogStreamStderr
 		}
 
+		// parse the details out of the Attrs map
+		attrs := []api.LogAttr{}
+		for k, v := range msg.Attrs {
+			attr := api.LogAttr{Key: k, Value: v}
+			attrs = append(attrs, attr)
+		}
+
 		if err := publisher.Publish(ctx, api.LogMessage{
 			Context:   msgctx,
 			Timestamp: tsp,
 			Stream:    stream,
+			Attrs:     attrs,
 			Data:      msg.Line,
 		}); err != nil {
 			return errors.Wrap(err, "failed to publish log message")

daemon/cluster/services.go

@@ -430,9 +430,17 @@ func (c *Cluster) ServiceLogs(ctx context.Context, selector *backend.LogSelector
 				if err != nil {
 					m.Err = err
 				}
+				// copy over all of the details
+				for _, d := range msg.Attrs {
+					m.Attrs[d.Key] = d.Value
+				}
+				// we have the final say over context details (in case there
+				// is a conflict (if the user added a detail with a context's
+				// key for some reason))
 				m.Attrs[contextPrefix+".node.id"] = msg.Context.NodeID
 				m.Attrs[contextPrefix+".service.id"] = msg.Context.ServiceID
 				m.Attrs[contextPrefix+".task.id"] = msg.Context.TaskID
+
 				switch msg.Stream {
 				case swarmapi.LogStreamStdout:
 					m.Source = "stdout"

hack/dockerfile/binaries-commits

@@ -11,5 +11,5 @@ VNDR_COMMIT=c56e082291115e369f77601f9c071dd0b87c7120
 BINDATA_COMMIT=a0ff2567cfb70903282db057e799fd826784d41d
 
 # CLI
-DOCKERCLI_REPO=https://github.com/aaronlehmann/cli
+DOCKERCLI_REPO=https://github.com/dperny/cli
-DOCKERCLI_COMMIT=0e2b9d30814eaecd6518bfb112bb4adef0265d4b
+DOCKERCLI_COMMIT=7230906e0e297999eb33da74e0279c5cf41a119e

integration-cli/docker_cli_service_logs_test.go

@@ -55,8 +55,14 @@ func (s *DockerSwarmSuite) TestServiceLogs(c *check.C) {
 // output.
 func countLogLines(d *daemon.Swarm, name string) func(*check.C) (interface{}, check.CommentInterface) {
 	return func(c *check.C) (interface{}, check.CommentInterface) {
-		result := icmd.RunCmd(d.Command("service", "logs", "-t", name))
+		result := icmd.RunCmd(d.Command("service", "logs", "-t", "--raw", name))
 		result.Assert(c, icmd.Expected{})
+		// if this returns an emptystring, trying to split it later will return
+		// an array containing emptystring. a valid log line will NEVER be
+		// emptystring because we ask for the timestamp.
+		if result.Stdout() == "" {
+			return 0, check.Commentf("Empty stdout")
+		}
 		lines := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
 		return len(lines), check.Commentf("output, %q", string(result.Stdout()))
 	}
@@ -277,7 +283,7 @@ func (s *DockerSwarmSuite) TestServiceLogsTTY(c *check.C) {
 	// and make sure we have all the log lines
 	waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2)
 
-	cmd := d.Command("service", "logs", name)
+	cmd := d.Command("service", "logs", "--raw", name)
 	result = icmd.RunCmd(cmd)
 	// for some reason there is carriage return in the output. i think this is
 	// just expected.
@@ -332,3 +338,50 @@ func (s *DockerSwarmSuite) TestServiceLogsNoHangDeletedContainer(c *check.C) {
 	// Expected defaults to false
 	c.Assert(result, icmd.Matches, icmd.Expected{})
 }
+
+func (s *DockerSwarmSuite) TestServiceLogsDetails(c *check.C) {
+	d := s.AddDaemon(c, true, true)
+
+	name := "TestServiceLogsDetails"
+
+	result := icmd.RunCmd(d.Command(
+		// create a service
+		"service", "create",
+		// name it $name
+		"--name", name,
+		// add an environment variable
+		"--env", "asdf=test1",
+		// add a log driver (without explicitly setting a driver, log-opt doesn't work)
+		"--log-driver", "json-file",
+		// add a log option to print the environment variable
+		"--log-opt", "env=asdf",
+		// busybox image, shell string
+		"busybox", "sh", "-c",
+		// make a log line
+		"echo LogLine; while true; do sleep 1; done;",
+	))
+
+	result.Assert(c, icmd.Expected{})
+	id := strings.TrimSpace(result.Stdout())
+	c.Assert(id, checker.Not(checker.Equals), "")
+
+	// make sure task has been deployed
+	waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
+	// and make sure we have all the log lines
+	waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 1)
+
+	// First, test without pretty printing
+	// call service logs with details. set raw to skip pretty printing
+	result = icmd.RunCmd(d.Command("service", "logs", "--raw", "--details", name))
+	// in this case, we should get details and we should get log message, but
+	// there will also be context as details (which will fall after the detail
+	// we inserted in alphabetical order
+	c.Assert(result, icmd.Matches, icmd.Expected{Out: "asdf=test1"})
+	c.Assert(result, icmd.Matches, icmd.Expected{Out: "LogLine"})
+
+	// call service logs with details. this time, don't pass raw
+	result = icmd.RunCmd(d.Command("service", "logs", "--details", id))
+	// in this case, we should get details space logmessage as well. the context
+	// is part of the pretty part of the logline
+	c.Assert(result, icmd.Matches, icmd.Expected{Out: "asdf=test1 LogLine"})
+}