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