Browse code

Merge pull request #31500 from dperny/fix-service-logs-cli

Add tail and since to service logs

Vincent Demeester authored on 2017/03/14 22:19:29
Showing 4 changed files
... ...
@@ -51,7 +51,7 @@ func newLogsCommand(dockerCli *command.DockerCli) *cobra.Command {
51 51
 	flags.BoolVar(&opts.noTrunc, "no-trunc", false, "Do not truncate output")
52 52
 	flags.BoolVar(&opts.noTaskIDs, "no-task-ids", false, "Do not include task IDs")
53 53
 	flags.BoolVarP(&opts.follow, "follow", "f", false, "Follow log output")
54
-	flags.StringVar(&opts.since, "since", "", "Show logs since timestamp")
54
+	flags.StringVar(&opts.since, "since", "", "Show logs since timestamp (e.g. 2013-01-02T13:23:37) or relative (e.g. 42m for 42 minutes)")
55 55
 	flags.BoolVarP(&opts.timestamps, "timestamps", "t", false, "Show timestamps")
56 56
 	flags.StringVar(&opts.tail, "tail", "all", "Number of lines to show from the end of the logs")
57 57
 	return cmd
... ...
@@ -423,7 +423,10 @@ func (c *containerAdapter) logs(ctx context.Context, options api.LogSubscription
423 423
 		if err != nil {
424 424
 			return nil, err
425 425
 		}
426
-		apiOptions.Since = since.Format(time.RFC3339Nano)
426
+		// print since as this formatted string because the docker container
427
+		// logs interface expects it like this.
428
+		// see github.com/docker/docker/api/types/time.ParseTimestamps
429
+		apiOptions.Since = fmt.Sprintf("%d.%09d", since.Unix(), int64(since.Nanosecond()))
427 430
 	}
428 431
 
429 432
 	if options.Tail < 0 {
... ...
@@ -6,7 +6,9 @@ import (
6 6
 	"fmt"
7 7
 	"io"
8 8
 	"os"
9
+	"strconv"
9 10
 	"strings"
11
+	"time"
10 12
 
11 13
 	"github.com/Sirupsen/logrus"
12 14
 	"github.com/docker/distribution/reference"
... ...
@@ -14,6 +16,7 @@ import (
14 14
 	apitypes "github.com/docker/docker/api/types"
15 15
 	"github.com/docker/docker/api/types/backend"
16 16
 	types "github.com/docker/docker/api/types/swarm"
17
+	timetypes "github.com/docker/docker/api/types/time"
17 18
 	"github.com/docker/docker/daemon/cluster/convert"
18 19
 	"github.com/docker/docker/daemon/logger"
19 20
 	"github.com/docker/docker/pkg/ioutils"
... ...
@@ -281,6 +284,44 @@ func (c *Cluster) ServiceLogs(ctx context.Context, input string, config *backend
281 281
 		stdStreams = append(stdStreams, swarmapi.LogStreamStderr)
282 282
 	}
283 283
 
284
+	// Get tail value squared away - the number of previous log lines we look at
285
+	var tail int64
286
+	if config.Tail == "all" {
287
+		// tail of 0 means send all logs on the swarmkit side
288
+		tail = 0
289
+	} else {
290
+		t, err := strconv.Atoi(config.Tail)
291
+		if err != nil {
292
+			return errors.New("tail value must be a positive integer or \"all\"")
293
+		}
294
+		if t < 0 {
295
+			return errors.New("negative tail values not supported")
296
+		}
297
+		// we actually use negative tail in swarmkit to represent messages
298
+		// backwards starting from the beginning. also, -1 means no logs. so,
299
+		// basically, for api compat with docker container logs, add one and
300
+		// flip the sign. we error above if you try to negative tail, which
301
+		// isn't supported by docker (and would error deeper in the stack
302
+		// anyway)
303
+		//
304
+		// See the logs protobuf for more information
305
+		tail = int64(-(t + 1))
306
+	}
307
+
308
+	// get the since value - the time in the past we're looking at logs starting from
309
+	var sinceProto *gogotypes.Timestamp
310
+	if config.Since != "" {
311
+		s, n, err := timetypes.ParseTimestamps(config.Since, 0)
312
+		if err != nil {
313
+			return errors.Wrap(err, "could not parse since timestamp")
314
+		}
315
+		since := time.Unix(s, n)
316
+		sinceProto, err = gogotypes.TimestampProto(since)
317
+		if err != nil {
318
+			return errors.Wrap(err, "could not parse timestamp to proto")
319
+		}
320
+	}
321
+
284 322
 	stream, err := state.logsClient.SubscribeLogs(ctx, &swarmapi.SubscribeLogsRequest{
285 323
 		Selector: &swarmapi.LogSelector{
286 324
 			ServiceIDs: []string{service.ID},
... ...
@@ -288,6 +329,8 @@ func (c *Cluster) ServiceLogs(ctx context.Context, input string, config *backend
288 288
 		Options: &swarmapi.LogSubscriptionOptions{
289 289
 			Follow:  config.Follow,
290 290
 			Streams: stdStreams,
291
+			Tail:    tail,
292
+			Since:   sinceProto,
291 293
 		},
292 294
 	})
293 295
 	if err != nil {
... ...
@@ -8,8 +8,10 @@ import (
8 8
 	"io"
9 9
 	"os/exec"
10 10
 	"strings"
11
+	"time"
11 12
 
12 13
 	"github.com/docker/docker/integration-cli/checker"
14
+	"github.com/docker/docker/integration-cli/daemon"
13 15
 	"github.com/go-check/check"
14 16
 )
15 17
 
... ...
@@ -49,6 +51,122 @@ func (s *DockerSwarmSuite) TestServiceLogs(c *check.C) {
49 49
 	}
50 50
 }
51 51
 
52
+// countLogLines returns a closure that can be used with waitAndAssert to
53
+// verify that a minimum number of expected container log messages have been
54
+// output.
55
+func countLogLines(d *daemon.Swarm, name string) func(*check.C) (interface{}, check.CommentInterface) {
56
+	return func(c *check.C) (interface{}, check.CommentInterface) {
57
+		out, err := d.Cmd("service", "logs", "-t", name)
58
+		c.Assert(err, checker.IsNil)
59
+		lines := strings.Split(strings.TrimSpace(out), "\n")
60
+		return len(lines), check.Commentf("output, %q", string(out))
61
+	}
62
+}
63
+
64
+func (s *DockerSwarmSuite) TestServiceLogsCompleteness(c *check.C) {
65
+	testRequires(c, ExperimentalDaemon)
66
+	d := s.AddDaemon(c, true, true)
67
+
68
+	name := "TestServiceLogsCompleteness"
69
+
70
+	// make a service that prints 6 lines
71
+	out, err := d.Cmd("service", "create", "--name", name, "busybox", "sh", "-c", "for line in $(seq 1 6); do echo log test $line; done; sleep 100000")
72
+	c.Assert(err, checker.IsNil)
73
+	c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
74
+
75
+	// make sure task has been deployed.
76
+	waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
77
+	// and make sure we have all the log lines
78
+	waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6)
79
+
80
+	args := []string{"service", "logs", name}
81
+	cmd := exec.Command(dockerBinary, d.PrependHostArg(args)...)
82
+	r, w := io.Pipe()
83
+	cmd.Stdout = w
84
+	cmd.Stderr = w
85
+	c.Assert(cmd.Start(), checker.IsNil)
86
+
87
+	reader := bufio.NewReader(r)
88
+	// i have heard anecdotal reports that logs may come back from the engine
89
+	// mis-ordered. if this tests fails, consider the possibility that that
90
+	// might be occurring
91
+	for i := 1; i <= 6; i++ {
92
+		msg := &logMessage{}
93
+		msg.data, _, msg.err = reader.ReadLine()
94
+		c.Assert(msg.err, checker.IsNil)
95
+		c.Assert(string(msg.data), checker.Contains, fmt.Sprintf("log test %v", i))
96
+	}
97
+}
98
+
99
+func (s *DockerSwarmSuite) TestServiceLogsTail(c *check.C) {
100
+	testRequires(c, ExperimentalDaemon)
101
+	d := s.AddDaemon(c, true, true)
102
+
103
+	name := "TestServiceLogsTail"
104
+
105
+	// make a service that prints 6 lines
106
+	out, err := d.Cmd("service", "create", "--name", name, "busybox", "sh", "-c", "for line in $(seq 1 6); do echo log test $line; done; sleep 100000")
107
+	c.Assert(err, checker.IsNil)
108
+	c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
109
+
110
+	// make sure task has been deployed.
111
+	waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
112
+	waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6)
113
+
114
+	args := []string{"service", "logs", "--tail=2", name}
115
+	cmd := exec.Command(dockerBinary, d.PrependHostArg(args)...)
116
+	r, w := io.Pipe()
117
+	cmd.Stdout = w
118
+	cmd.Stderr = w
119
+	c.Assert(cmd.Start(), checker.IsNil)
120
+
121
+	reader := bufio.NewReader(r)
122
+	// see TestServiceLogsCompleteness for comments about logs being well-
123
+	// ordered, if this flakes
124
+	for i := 5; i <= 6; i++ {
125
+		msg := &logMessage{}
126
+		msg.data, _, msg.err = reader.ReadLine()
127
+		c.Assert(msg.err, checker.IsNil)
128
+		c.Assert(string(msg.data), checker.Contains, fmt.Sprintf("log test %v", i))
129
+	}
130
+}
131
+
132
+func (s *DockerSwarmSuite) TestServiceLogsSince(c *check.C) {
133
+	// See DockerSuite.TestLogsSince, which is where this comes from
134
+	testRequires(c, ExperimentalDaemon)
135
+	d := s.AddDaemon(c, true, true)
136
+
137
+	name := "TestServiceLogsSince"
138
+
139
+	out, err := d.Cmd("service", "create", "--name", name, "busybox", "sh", "-c", "for i in $(seq 1 3); do sleep .1; echo log$i; done; sleep 10000000")
140
+	c.Assert(err, checker.IsNil)
141
+	c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
142
+	waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
143
+	// wait a sec for the logs to come in
144
+	waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 3)
145
+
146
+	out, err = d.Cmd("service", "logs", "-t", name)
147
+	c.Assert(err, checker.IsNil)
148
+
149
+	log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
150
+	t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // timestamp log2 is written
151
+	c.Assert(err, checker.IsNil)
152
+	u := t.Add(50 * time.Millisecond) // add .05s so log1 & log2 don't show up
153
+	since := u.Format(time.RFC3339Nano)
154
+
155
+	out, err = d.Cmd("service", "logs", "-t", fmt.Sprintf("--since=%v", since), name)
156
+	c.Assert(err, checker.IsNil)
157
+
158
+	unexpected := []string{"log1", "log2"}
159
+	expected := []string{"log3"}
160
+	for _, v := range unexpected {
161
+		c.Assert(out, checker.Not(checker.Contains), v, check.Commentf("unexpected log message returned, since=%v", u))
162
+	}
163
+	for _, v := range expected {
164
+		c.Assert(out, checker.Contains, v, check.Commentf("expected log message %v, was not present, since=%v", u))
165
+	}
166
+}
167
+
52 168
 func (s *DockerSwarmSuite) TestServiceLogsFollow(c *check.C) {
53 169
 	testRequires(c, ExperimentalDaemon)
54 170