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