1// +build !windows 2 3package main 4 5import ( 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 "github.com/go-check/check" 16 "github.com/gotestyourself/gotestyourself/icmd" 17) 18 19type logMessage struct { 20 err error 21 data []byte 22} 23 24func (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", "--detach", "--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:latest": 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. 56func 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 71func (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", "--detach", "--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 98func (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", "--detach", "--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 122func (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", "--detach", "--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 157func (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", "--detach", "--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 go cmd.Wait() 176 177 // Make sure pipe is written to 178 ch := make(chan *logMessage) 179 done := make(chan struct{}) 180 go func() { 181 reader := bufio.NewReader(r) 182 for { 183 msg := &logMessage{} 184 msg.data, _, msg.err = reader.ReadLine() 185 select { 186 case ch <- msg: 187 case <-done: 188 return 189 } 190 } 191 }() 192 193 for i := 0; i < 3; i++ { 194 msg := <-ch 195 c.Assert(msg.err, checker.IsNil) 196 c.Assert(string(msg.data), checker.Contains, "log test") 197 } 198 close(done) 199 200 c.Assert(cmd.Process.Kill(), checker.IsNil) 201} 202 203func (s *DockerSwarmSuite) TestServiceLogsTaskLogs(c *check.C) { 204 d := s.AddDaemon(c, true, true) 205 206 name := "TestServicelogsTaskLogs" 207 replicas := 2 208 209 result := icmd.RunCmd(d.Command( 210 // create a service with the name 211 "service", "create", "--detach", "--no-resolve-image", "--name", name, 212 // which has some number of replicas 213 fmt.Sprintf("--replicas=%v", replicas), 214 // which has this the task id as an environment variable templated in 215 "--env", "TASK={{.Task.ID}}", 216 // and runs this command to print exactly 6 logs lines 217 "busybox", "sh", "-c", "for line in $(seq 0 5); do echo $TASK log test $line; done; sleep 100000", 218 )) 219 result.Assert(c, icmd.Expected{}) 220 // ^^ verify that we get no error 221 // then verify that we have an id in stdout 222 id := strings.TrimSpace(result.Stdout()) 223 c.Assert(id, checker.Not(checker.Equals), "") 224 // so, right here, we're basically inspecting by id and returning only 225 // the ID. if they don't match, the service doesn't exist. 226 result = icmd.RunCmd(d.Command("service", "inspect", "--format=\"{{.ID}}\"", id)) 227 result.Assert(c, icmd.Expected{Out: id}) 228 229 // make sure task has been deployed. 230 waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, replicas) 231 waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 6*replicas) 232 233 // get the task ids 234 result = icmd.RunCmd(d.Command("service", "ps", "-q", name)) 235 result.Assert(c, icmd.Expected{}) 236 // make sure we have two tasks 237 taskIDs := strings.Split(strings.TrimSpace(result.Stdout()), "\n") 238 c.Assert(taskIDs, checker.HasLen, replicas) 239 240 for _, taskID := range taskIDs { 241 c.Logf("checking task %v", taskID) 242 result := icmd.RunCmd(d.Command("service", "logs", taskID)) 243 result.Assert(c, icmd.Expected{}) 244 lines := strings.Split(strings.TrimSpace(result.Stdout()), "\n") 245 246 c.Logf("checking messages for %v", taskID) 247 for i, line := range lines { 248 // make sure the message is in order 249 c.Assert(line, checker.Contains, fmt.Sprintf("log test %v", i)) 250 // make sure it contains the task id 251 c.Assert(line, checker.Contains, taskID) 252 } 253 } 254} 255 256func (s *DockerSwarmSuite) TestServiceLogsTTY(c *check.C) { 257 d := s.AddDaemon(c, true, true) 258 259 name := "TestServiceLogsTTY" 260 261 result := icmd.RunCmd(d.Command( 262 // create a service 263 "service", "create", "--detach", "--no-resolve-image", 264 // name it $name 265 "--name", name, 266 // use a TTY 267 "-t", 268 // busybox image, shell string 269 "busybox", "sh", "-c", 270 // echo to stdout and stderr 271 "echo out; (echo err 1>&2); sleep 10000", 272 )) 273 274 result.Assert(c, icmd.Expected{}) 275 id := strings.TrimSpace(result.Stdout()) 276 c.Assert(id, checker.Not(checker.Equals), "") 277 // so, right here, we're basically inspecting by id and returning only 278 // the ID. if they don't match, the service doesn't exist. 279 result = icmd.RunCmd(d.Command("service", "inspect", "--format=\"{{.ID}}\"", id)) 280 result.Assert(c, icmd.Expected{Out: id}) 281 282 // make sure task has been deployed. 283 waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1) 284 // and make sure we have all the log lines 285 waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2) 286 287 cmd := d.Command("service", "logs", "--raw", name) 288 result = icmd.RunCmd(cmd) 289 // for some reason there is carriage return in the output. i think this is 290 // just expected. 291 result.Assert(c, icmd.Expected{Out: "out\r\nerr\r\n"}) 292} 293 294func (s *DockerSwarmSuite) TestServiceLogsNoHangDeletedContainer(c *check.C) { 295 d := s.AddDaemon(c, true, true) 296 297 name := "TestServiceLogsNoHangDeletedContainer" 298 299 result := icmd.RunCmd(d.Command( 300 // create a service 301 "service", "create", "--detach", "--no-resolve-image", 302 // name it $name 303 "--name", name, 304 // busybox image, shell string 305 "busybox", "sh", "-c", 306 // echo to stdout and stderr 307 "while true; do echo line; sleep 2; done", 308 )) 309 310 // confirm that the command succeeded 311 result.Assert(c, icmd.Expected{}) 312 // get the service id 313 id := strings.TrimSpace(result.Stdout()) 314 c.Assert(id, checker.Not(checker.Equals), "") 315 316 // make sure task has been deployed. 317 waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1) 318 // and make sure we have all the log lines 319 waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 2) 320 321 // now find and nuke the container 322 result = icmd.RunCmd(d.Command("ps", "-q")) 323 containerID := strings.TrimSpace(result.Stdout()) 324 c.Assert(containerID, checker.Not(checker.Equals), "") 325 result = icmd.RunCmd(d.Command("stop", containerID)) 326 result.Assert(c, icmd.Expected{Out: containerID}) 327 result = icmd.RunCmd(d.Command("rm", containerID)) 328 result.Assert(c, icmd.Expected{Out: containerID}) 329 330 // run logs. use tail 2 to make sure we don't try to get a bunch of logs 331 // somehow and slow down execution time 332 cmd := d.Command("service", "logs", "--tail", "2", id) 333 // start the command and then wait for it to finish with a 3 second timeout 334 result = icmd.StartCmd(cmd) 335 result = icmd.WaitOnCmd(3*time.Second, result) 336 337 // then, assert that the result matches expected. if the command timed out, 338 // if the command is timed out, result.Timeout will be true, but the 339 // Expected defaults to false 340 result.Assert(c, icmd.Expected{}) 341} 342 343func (s *DockerSwarmSuite) TestServiceLogsDetails(c *check.C) { 344 d := s.AddDaemon(c, true, true) 345 346 name := "TestServiceLogsDetails" 347 348 result := icmd.RunCmd(d.Command( 349 // create a service 350 "service", "create", "--detach", "--no-resolve-image", 351 // name it $name 352 "--name", name, 353 // add an environment variable 354 "--env", "asdf=test1", 355 // add a log driver (without explicitly setting a driver, log-opt doesn't work) 356 "--log-driver", "json-file", 357 // add a log option to print the environment variable 358 "--log-opt", "env=asdf", 359 // busybox image, shell string 360 "busybox", "sh", "-c", 361 // make a log line 362 "echo LogLine; while true; do sleep 1; done;", 363 )) 364 365 result.Assert(c, icmd.Expected{}) 366 id := strings.TrimSpace(result.Stdout()) 367 c.Assert(id, checker.Not(checker.Equals), "") 368 369 // make sure task has been deployed 370 waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1) 371 // and make sure we have all the log lines 372 waitAndAssert(c, defaultReconciliationTimeout, countLogLines(d, name), checker.Equals, 1) 373 374 // First, test without pretty printing 375 // call service logs with details. set raw to skip pretty printing 376 result = icmd.RunCmd(d.Command("service", "logs", "--raw", "--details", name)) 377 // in this case, we should get details and we should get log message, but 378 // there will also be context as details (which will fall after the detail 379 // we inserted in alphabetical order 380 result.Assert(c, icmd.Expected{Out: "asdf=test1"}) 381 result.Assert(c, icmd.Expected{Out: "LogLine"}) 382 383 // call service logs with details. this time, don't pass raw 384 result = icmd.RunCmd(d.Command("service", "logs", "--details", id)) 385 // in this case, we should get details space logmessage as well. the context 386 // is part of the pretty part of the logline 387 result.Assert(c, icmd.Expected{Out: "asdf=test1 LogLine"}) 388} 389