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