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