integration-cli/docker_cli_service_logs_test.go

   1 // +build !windows
   2
   3 package main
   4
   5 import (
   6         "bufio"
   7         "fmt"
   8         "io"
   9         "os/exec"
  10         "strings"
  11         "time"
  12
  13         "github.com/docker/docker/integration-cli/checker"
  14         "github.com/docker/docker/integration-cli/daemon"
  15         icmd "github.com/docker/docker/pkg/testutil/cmd"
  16         "github.com/go-check/check"
  17 )
  18
  19 type logMessage struct {
  20         err  error
  21         data []byte
  22 }
  23
  24 func (s *DockerSwarmSuite) TestServiceLogs(c *check.C) {
  25         d := s.AddDaemon(c, true, true)
  26
  27         // we have multiple services here for detecting the goroutine issue #28915
  28         services := map[string]string{
  29                 "TestServiceLogs1": "hello1",
  30                 "TestServiceLogs2": "hello2",
  31         }
  32
  33         for name, message := range services {
  34                 out, err := d.Cmd("service", "create", "--no-resolve-image", "--name", name, "busybox",
  35                         "sh", "-c", fmt.Sprintf("echo %s; tail -f /dev/null", message))
  36                 c.Assert(err, checker.IsNil)
  37                 c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  38         }
  39
  40         // make sure task has been deployed.
  41         waitAndAssert(c, defaultReconciliationTimeout,
  42                 d.CheckRunningTaskImages, checker.DeepEquals,
  43                 map[string]int{"busybox": len(services)})
  44
  45         for name, message := range services {
  46                 out, err := d.Cmd("service", "logs", name)
  47                 c.Assert(err, checker.IsNil)
  48                 c.Logf("log for %q: %q", name, out)
  49                 c.Assert(out, checker.Contains, message)
  50         }
  51 }
  52
  53 // countLogLines returns a closure that can be used with waitAndAssert to
  54 // verify that a minimum number of expected container log messages have been
  55 // output.
  56 func countLogLines(d *daemon.Swarm, name string) func(*check.C) (interface{}, check.CommentInterface) {
  57         return func(c *check.C) (interface{}, check.CommentInterface) {
  58                 result := icmd.RunCmd(d.Command("service", "logs", "-t", "--raw", name))
  59                 result.Assert(c, icmd.Expected{})
  60                 // if this returns an emptystring, trying to split it later will return
  61                 // an array containing emptystring. a valid log line will NEVER be
  62                 // emptystring because we ask for the timestamp.
  63                 if result.Stdout() == "" {
  64                         return 0, check.Commentf("Empty stdout")
  65                 }
  66                 lines := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
  67                 return len(lines), check.Commentf("output, %q", string(result.Stdout()))
  68         }
  69 }
  70
  71 func (s *DockerSwarmSuite) TestServiceLogsCompleteness(c *check.C) {
  72         d := s.AddDaemon(c, true, true)
  73
  74         name := "TestServiceLogsCompleteness"
  75
  76         // make a service that prints 6 lines
  77         out, err := d.Cmd("service", "create", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "for line in $(seq 0 5); do echo log test $line; done; sleep 100000")
  78         c.Assert(err, checker.IsNil)
  79         c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
  80
  81         // make sure task has been deployed.
  82         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
  83         // and make sure we have all the log lines
  84         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6)
  85
  86         out, err = d.Cmd("service", "logs", name)
  87         c.Assert(err, checker.IsNil)
  88         lines := strings.Split(strings.TrimSpace(out), "\n")
  89
  90         // i have heard anecdotal reports that logs may come back from the engine
  91         // mis-ordered. if this tests fails, consider the possibility that that
  92         // might be occurring
  93         for i, line := range lines {
  94                 c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i))
  95         }
  96 }
  97
  98 func (s *DockerSwarmSuite) TestServiceLogsTail(c *check.C) {
  99         d := s.AddDaemon(c, true, true)
 100
 101         name := "TestServiceLogsTail"
 102
 103         // make a service that prints 6 lines
 104         out, err := d.Cmd("service", "create", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "for line in $(seq 1 6); do echo log test $line; done; sleep 100000")
 105         c.Assert(err, checker.IsNil)
 106         c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
 107
 108         // make sure task has been deployed.
 109         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
 110         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6)
 111
 112         out, err = d.Cmd("service", "logs", "--tail=2", name)
 113         c.Assert(err, checker.IsNil)
 114         lines := strings.Split(strings.TrimSpace(out), "\n")
 115
 116         for i, line := range lines {
 117                 // doing i+5 is hacky but not too fragile, it's good enough. if it flakes something else is wrong
 118                 c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i+5))
 119         }
 120 }
 121
 122 func (s *DockerSwarmSuite) TestServiceLogsSince(c *check.C) {
 123         // See DockerSuite.TestLogsSince, which is where this comes from
 124         d := s.AddDaemon(c, true, true)
 125
 126         name := "TestServiceLogsSince"
 127
 128         out, err := d.Cmd("service", "create", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "for i in $(seq 1 3); do sleep .1; echo log$i; done; sleep 10000000")
 129         c.Assert(err, checker.IsNil)
 130         c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
 131         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
 132         // wait a sec for the logs to come in
 133         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 3)
 134
 135         out, err = d.Cmd("service", "logs", "-t", name)
 136         c.Assert(err, checker.IsNil)
 137
 138         log2Line := strings.Split(strings.Split(out, "\n")[1], " ")
 139         t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // timestamp log2 is written
 140         c.Assert(err, checker.IsNil)
 141         u := t.Add(50 * time.Millisecond) // add .05s so log1 & log2 don't show up
 142         since := u.Format(time.RFC3339Nano)
 143
 144         out, err = d.Cmd("service", "logs", "-t", fmt.Sprintf("--since=%v", since), name)
 145         c.Assert(err, checker.IsNil)
 146
 147         unexpected := []string{"log1", "log2"}
 148         expected := []string{"log3"}
 149         for _, v := range unexpected {
 150                 c.Assert(out, checker.Not(checker.Contains), v, check.Commentf("unexpected log message returned, since=%v", u))
 151         }
 152         for _, v := range expected {
 153                 c.Assert(out, checker.Contains, v, check.Commentf("expected log message %v, was not present, since=%v", u))
 154         }
 155 }
 156
 157 func (s *DockerSwarmSuite) TestServiceLogsFollow(c *check.C) {
 158         d := s.AddDaemon(c, true, true)
 159
 160         name := "TestServiceLogsFollow"
 161
 162         out, err := d.Cmd("service", "create", "--no-resolve-image", "--name", name, "busybox", "sh", "-c", "while true; do echo log test; sleep 0.1; done")
 163         c.Assert(err, checker.IsNil)
 164         c.Assert(strings.TrimSpace(out), checker.Not(checker.Equals), "")
 165
 166         // make sure task has been deployed.
 167         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
 168
 169         args := []string{"service", "logs", "-f", name}
 170         cmd := exec.Command(dockerBinary, d.PrependHostArg(args)...)
 171         r, w := io.Pipe()
 172         cmd.Stdout = w
 173         cmd.Stderr = w
 174         c.Assert(cmd.Start(), checker.IsNil)
 175
 176         // Make sure pipe is written to
 177         ch := make(chan *logMessage)
 178         done := make(chan struct{})
 179         go func() {
 180                 reader := bufio.NewReader(r)
 181                 for {
 182                         msg := &logMessage{}
 183                         msg.data, _, msg.err = reader.ReadLine()
 184                         select {
 185                         case ch <- msg:
 186                         case <-done:
 187                                 return
 188                         }
 189                 }
 190         }()
 191
 192         for i := 0; i < 3; i++ {
 193                 msg := <-ch
 194                 c.Assert(msg.err, checker.IsNil)
 195                 c.Assert(string(msg.data), checker.Contains, "log test")
 196         }
 197         close(done)
 198
 199         c.Assert(cmd.Process.Kill(), checker.IsNil)
 200 }
 201
 202 func (s *DockerSwarmSuite) TestServiceLogsTaskLogs(c *check.C) {
 203         d := s.AddDaemon(c, true, true)
 204
 205         name := "TestServicelogsTaskLogs"
 206         replicas := 2
 207
 208         result := icmd.RunCmd(d.Command(
 209                 // create a service with the name
 210                 "service", "create", "--no-resolve-image", "--name", name,
 211                 // which has some number of replicas
 212                 fmt.Sprintf("--replicas=%v", replicas),
 213                 // which has this the task id as an environment variable templated in
 214                 "--env", "TASK={{.Task.ID}}",
 215                 // and runs this command to print exaclty 6 logs lines
 216                 "busybox", "sh", "-c", "for line in $(seq 0 5); do echo $TASK log test $line; done; sleep 100000",
 217         ))
 218         result.Assert(c, icmd.Expected{})
 219         // ^^ verify that we get no error
 220         // then verify that we have an id in stdout
 221         id := strings.TrimSpace(result.Stdout())
 222         c.Assert(id, checker.Not(checker.Equals), "")
 223         // so, right here, we're basically inspecting by id and returning only
 224         // the ID. if they don't match, the service doesn't exist.
 225         result = icmd.RunCmd(d.Command("service", "inspect", "--format=\"{{.ID}}\"", id))
 226         result.Assert(c, icmd.Expected{Out: id})
 227
 228         // make sure task has been deployed.
 229         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, replicas)
 230         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6*replicas)
 231
 232         // get the task ids
 233         result = icmd.RunCmd(d.Command("service", "ps", "-q", name))
 234         result.Assert(c, icmd.Expected{})
 235         // make sure we have two tasks
 236         taskIDs := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
 237         c.Assert(taskIDs, checker.HasLen, replicas)
 238
 239         for _, taskID := range taskIDs {
 240                 c.Logf("checking task %v", taskID)
 241                 result := icmd.RunCmd(d.Command("service", "logs", taskID))
 242                 result.Assert(c, icmd.Expected{})
 243                 lines := strings.Split(strings.TrimSpace(result.Stdout()), "\n")
 244
 245                 c.Logf("checking messages for %v", taskID)
 246                 for i, line := range lines {
 247                         // make sure the message is in order
 248                         c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i))
 249                         // make sure it contains the task id
 250                         c.Assert(line, checker.Contains, taskID)
 251                 }
 252         }
 253 }
 254
 255 func (s *DockerSwarmSuite) TestServiceLogsTTY(c *check.C) {
 256         d := s.AddDaemon(c, true, true)
 257
 258         name := "TestServiceLogsTTY"
 259
 260         result := icmd.RunCmd(d.Command(
 261                 // create a service
 262                 "service", "create", "--no-resolve-image",
 263                 // name it $name
 264                 "--name", name,
 265                 // use a TTY
 266                 "-t",
 267                 // busybox image, shell string
 268                 "busybox", "sh", "-c",
 269                 // echo to stdout and stderr
 270                 "echo out; (echo err 1>&2); sleep 10000",
 271         ))
 272
 273         result.Assert(c, icmd.Expected{})
 274         id := strings.TrimSpace(result.Stdout())
 275         c.Assert(id, checker.Not(checker.Equals), "")
 276         // so, right here, we're basically inspecting by id and returning only
 277         // the ID. if they don't match, the service doesn't exist.
 278         result = icmd.RunCmd(d.Command("service", "inspect", "--format=\"{{.ID}}\"", id))
 279         result.Assert(c, icmd.Expected{Out: id})
 280
 281         // make sure task has been deployed.
 282         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
 283         // and make sure we have all the log lines
 284         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2)
 285
 286         cmd := d.Command("service", "logs", "--raw", name)
 287         result = icmd.RunCmd(cmd)
 288         // for some reason there is carriage return in the output. i think this is
 289         // just expected.
 290         c.Assert(result, icmd.Matches, icmd.Expected{Out: "out\r\nerr\r\n"})
 291 }
 292
 293 func (s *DockerSwarmSuite) TestServiceLogsNoHangDeletedContainer(c *check.C) {
 294         d := s.AddDaemon(c, true, true)
 295
 296         name := "TestServiceLogsNoHangDeletedContainer"
 297
 298         result := icmd.RunCmd(d.Command(
 299                 // create a service
 300                 "service", "create", "--no-resolve-image",
 301                 // name it $name
 302                 "--name", name,
 303                 // busybox image, shell string
 304                 "busybox", "sh", "-c",
 305                 // echo to stdout and stderr
 306                 "while true; do echo line; sleep 2; done",
 307         ))
 308
 309         // confirm that the command succeeded
 310         c.Assert(result, icmd.Matches, icmd.Expected{})
 311         // get the service id
 312         id := strings.TrimSpace(result.Stdout())
 313         c.Assert(id, checker.Not(checker.Equals), "")
 314
 315         // make sure task has been deployed.
 316         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
 317         // and make sure we have all the log lines
 318         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2)
 319
 320         // now find and nuke the container
 321         result = icmd.RunCmd(d.Command("ps", "-q"))
 322         containerID := strings.TrimSpace(result.Stdout())
 323         c.Assert(containerID, checker.Not(checker.Equals), "")
 324         result = icmd.RunCmd(d.Command("stop", containerID))
 325         c.Assert(result, icmd.Matches, icmd.Expected{Out: containerID})
 326         result = icmd.RunCmd(d.Command("rm", containerID))
 327         c.Assert(result, icmd.Matches, icmd.Expected{Out: containerID})
 328
 329         // run logs. use tail 2 to make sure we don't try to get a bunch of logs
 330         // somehow and slow down execution time
 331         cmd := d.Command("service", "logs", "--tail", "2", id)
 332         // start the command and then wait for it to finish with a 3 second timeout
 333         result = icmd.StartCmd(cmd)
 334         result = icmd.WaitOnCmd(3*time.Second, result)
 335
 336         // then, assert that the result matches expected. if the command timed out,
 337         // if the command is timed out, result.Timeout will be true, but the
 338         // Expected defaults to false
 339         c.Assert(result, icmd.Matches, icmd.Expected{})
 340 }
 341
 342 func (s *DockerSwarmSuite) TestServiceLogsDetails(c *check.C) {
 343         d := s.AddDaemon(c, true, true)
 344
 345         name := "TestServiceLogsDetails"
 346
 347         result := icmd.RunCmd(d.Command(
 348                 // create a service
 349                 "service", "create", "--no-resolve-image",
 350                 // name it $name
 351                 "--name", name,
 352                 // add an environment variable
 353                 "--env", "asdf=test1",
 354                 // add a log driver (without explicitly setting a driver, log-opt doesn't work)
 355                 "--log-driver", "json-file",
 356                 // add a log option to print the environment variable
 357                 "--log-opt", "env=asdf",
 358                 // busybox image, shell string
 359                 "busybox", "sh", "-c",
 360                 // make a log line
 361                 "echo LogLine; while true; do sleep 1; done;",
 362         ))
 363
 364         result.Assert(c, icmd.Expected{})
 365         id := strings.TrimSpace(result.Stdout())
 366         c.Assert(id, checker.Not(checker.Equals), "")
 367
 368         // make sure task has been deployed
 369         waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
 370         // and make sure we have all the log lines
 371         waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 1)
 372
 373         // First, test without pretty printing
 374         // call service logs with details. set raw to skip pretty printing
 375         result = icmd.RunCmd(d.Command("service", "logs", "--raw", "--details", name))
 376         // in this case, we should get details and we should get log message, but
 377         // there will also be context as details (which will fall after the detail
 378         // we inserted in alphabetical order
 379         c.Assert(result, icmd.Matches, icmd.Expected{Out: "asdf=test1"})
 380         c.Assert(result, icmd.Matches, icmd.Expected{Out: "LogLine"})
 381
 382         // call service logs with details. this time, don't pass raw
 383         result = icmd.RunCmd(d.Command("service", "logs", "--details", id))
 384         // in this case, we should get details space logmessage as well. the context
 385         // is part of the pretty part of the logline
 386         c.Assert(result, icmd.Matches, icmd.Expected{Out: "asdf=test1 LogLine"})
 387 }