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