github.com/tonistiigi/docker@v0.10.1-0.20240229224939-974013b0dc6a/integration-cli/docker_cli_logs_test.go (about) 1 package main 2 3 import ( 4 "context" 5 "fmt" 6 "io" 7 "os/exec" 8 "regexp" 9 "strings" 10 "testing" 11 "time" 12 13 "github.com/containerd/log" 14 "github.com/docker/docker/integration-cli/cli" 15 "github.com/docker/docker/integration-cli/daemon" 16 "github.com/docker/docker/testutil" 17 testdaemon "github.com/docker/docker/testutil/daemon" 18 "gotest.tools/v3/assert" 19 "gotest.tools/v3/icmd" 20 ) 21 22 type DockerCLILogsSuite struct { 23 ds *DockerSuite 24 } 25 26 func (s *DockerCLILogsSuite) TearDownTest(ctx context.Context, c *testing.T) { 27 s.ds.TearDownTest(ctx, c) 28 } 29 30 func (s *DockerCLILogsSuite) OnTimeout(c *testing.T) { 31 s.ds.OnTimeout(c) 32 } 33 34 // This used to work, it test a log of PageSize-1 (gh#4851) 35 func (s *DockerCLILogsSuite) TestLogsContainerSmallerThanPage(c *testing.T) { 36 testLogsContainerPagination(c, 32767) 37 } 38 39 // Regression test: When going over the PageSize, it used to panic (gh#4851) 40 func (s *DockerCLILogsSuite) TestLogsContainerBiggerThanPage(c *testing.T) { 41 testLogsContainerPagination(c, 32768) 42 } 43 44 // Regression test: When going much over the PageSize, it used to block (gh#4851) 45 func (s *DockerCLILogsSuite) TestLogsContainerMuchBiggerThanPage(c *testing.T) { 46 testLogsContainerPagination(c, 33000) 47 } 48 49 func testLogsContainerPagination(c *testing.T, testLen int) { 50 id := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n = >> a.a; done; echo >> a.a; cat a.a", testLen)).Stdout() 51 id = strings.TrimSpace(id) 52 cli.DockerCmd(c, "wait", id) 53 out := cli.DockerCmd(c, "logs", id).Combined() 54 assert.Equal(c, len(out), testLen+1) 55 } 56 57 func (s *DockerCLILogsSuite) TestLogsTimestamps(c *testing.T) { 58 testLen := 100 59 id := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo = >> a.a; done; cat a.a", testLen)).Stdout() 60 id = strings.TrimSpace(id) 61 cli.DockerCmd(c, "wait", id) 62 63 out := cli.DockerCmd(c, "logs", "-t", id).Combined() 64 lines := strings.Split(out, "\n") 65 66 assert.Equal(c, len(lines), testLen+1) 67 68 ts := regexp.MustCompile(`^.* `) 69 70 for _, l := range lines { 71 if l != "" { 72 _, err := time.Parse(log.RFC3339NanoFixed+" ", ts.FindString(l)) 73 assert.NilError(c, err, "Failed to parse timestamp from %v", l) 74 // ensure we have padded 0's 75 assert.Equal(c, l[29], uint8('Z')) 76 } 77 } 78 } 79 80 func (s *DockerCLILogsSuite) TestLogsSeparateStderr(c *testing.T) { 81 msg := "stderr_log" 82 out := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)).Combined() 83 id := strings.TrimSpace(out) 84 cli.DockerCmd(c, "wait", id) 85 cli.DockerCmd(c, "logs", id).Assert(c, icmd.Expected{ 86 Out: "", 87 Err: msg, 88 }) 89 } 90 91 func (s *DockerCLILogsSuite) TestLogsStderrInStdout(c *testing.T) { 92 // TODO Windows: Needs investigation why this fails. Obtained string includes 93 // a bunch of ANSI escape sequences before the "stderr_log" message. 94 testRequires(c, DaemonIsLinux) 95 msg := "stderr_log" 96 out := cli.DockerCmd(c, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)).Combined() 97 id := strings.TrimSpace(out) 98 cli.DockerCmd(c, "wait", id) 99 100 cli.DockerCmd(c, "logs", id).Assert(c, icmd.Expected{ 101 Out: msg, 102 Err: "", 103 }) 104 } 105 106 func (s *DockerCLILogsSuite) TestLogsTail(c *testing.T) { 107 testLen := 100 108 out := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)).Combined() 109 110 id := strings.TrimSpace(out) 111 cli.DockerCmd(c, "wait", id) 112 113 out = cli.DockerCmd(c, "logs", "--tail", "0", id).Combined() 114 lines := strings.Split(out, "\n") 115 assert.Equal(c, len(lines), 1) 116 117 out = cli.DockerCmd(c, "logs", "--tail", "5", id).Combined() 118 lines = strings.Split(out, "\n") 119 assert.Equal(c, len(lines), 6) 120 121 out = cli.DockerCmd(c, "logs", "--tail", "99", id).Combined() 122 lines = strings.Split(out, "\n") 123 assert.Equal(c, len(lines), 100) 124 125 out = cli.DockerCmd(c, "logs", "--tail", "all", id).Combined() 126 lines = strings.Split(out, "\n") 127 assert.Equal(c, len(lines), testLen+1) 128 129 out = cli.DockerCmd(c, "logs", "--tail", "-1", id).Combined() 130 lines = strings.Split(out, "\n") 131 assert.Equal(c, len(lines), testLen+1) 132 133 out = cli.DockerCmd(c, "logs", "--tail", "random", id).Combined() 134 lines = strings.Split(out, "\n") 135 assert.Equal(c, len(lines), testLen+1) 136 } 137 138 func (s *DockerCLILogsSuite) TestLogsFollowStopped(c *testing.T) { 139 cli.DockerCmd(c, "run", "--name=test", "busybox", "echo", "hello") 140 id := getIDByName(c, "test") 141 142 logsCmd := exec.Command(dockerBinary, "logs", "-f", id) 143 assert.NilError(c, logsCmd.Start()) 144 145 errChan := make(chan error, 1) 146 go func() { 147 errChan <- logsCmd.Wait() 148 close(errChan) 149 }() 150 151 select { 152 case err := <-errChan: 153 assert.NilError(c, err) 154 case <-time.After(30 * time.Second): 155 c.Fatal("Following logs is hanged") 156 } 157 } 158 159 func (s *DockerCLILogsSuite) TestLogsSince(c *testing.T) { 160 name := "testlogssince" 161 cli.DockerCmd(c, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo log$i; done") 162 out := cli.DockerCmd(c, "logs", "-t", name).Combined() 163 164 log2Line := strings.Split(strings.Split(out, "\n")[1], " ") 165 t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // the timestamp log2 is written 166 assert.NilError(c, err) 167 since := t.Unix() + 1 // add 1s so log1 & log2 doesn't show up 168 out = cli.DockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name).Combined() 169 170 // Skip 2 seconds 171 unexpected := []string{"log1", "log2"} 172 for _, v := range unexpected { 173 assert.Check(c, !strings.Contains(out, v), "unexpected log message returned, since=%v", since) 174 } 175 176 // Test to make sure a bad since format is caught by the client 177 out, _, _ = dockerCmdWithError("logs", "-t", "--since=2006-01-02T15:04:0Z", name) 178 assert.Assert(c, strings.Contains(out, `cannot parse "0Z" as "05"`), "bad since format passed to server") 179 180 // Test with default value specified and parameter omitted 181 expected := []string{"log1", "log2", "log3"} 182 for _, cmd := range [][]string{ 183 {"logs", "-t", name}, 184 {"logs", "-t", "--since=0", name}, 185 } { 186 result := icmd.RunCommand(dockerBinary, cmd...) 187 result.Assert(c, icmd.Success) 188 for _, v := range expected { 189 assert.Check(c, strings.Contains(result.Combined(), v)) 190 } 191 } 192 } 193 194 func (s *DockerCLILogsSuite) TestLogsSinceFutureFollow(c *testing.T) { 195 // TODO Windows TP5 - Figure out why this test is so flakey. Disabled for now. 196 testRequires(c, DaemonIsLinux) 197 name := "testlogssincefuturefollow" 198 cli.DockerCmd(c, "run", "-d", "--name", name, "busybox", "/bin/sh", "-c", `for i in $(seq 1 5); do echo log$i; sleep 1; done`) 199 200 // Extract one timestamp from the log file to give us a starting point for 201 // our `--since` argument. Because the log producer runs in the background, 202 // we need to check repeatedly for some output to be produced. 203 var timestamp string 204 for i := 0; i != 100 && timestamp == ""; i++ { 205 if out := cli.DockerCmd(c, "logs", "-t", name).Combined(); out == "" { 206 time.Sleep(time.Millisecond * 100) // Retry 207 } else { 208 timestamp = strings.Split(strings.Split(out, "\n")[0], " ")[0] 209 } 210 } 211 212 assert.Assert(c, timestamp != "") 213 t, err := time.Parse(time.RFC3339Nano, timestamp) 214 assert.NilError(c, err) 215 216 since := t.Unix() + 2 217 out := cli.DockerCmd(c, "logs", "-t", "-f", fmt.Sprintf("--since=%v", since), name).Combined() 218 assert.Assert(c, len(out) != 0, "cannot read from empty log") 219 lines := strings.Split(strings.TrimSpace(out), "\n") 220 for _, v := range lines { 221 ts, err := time.Parse(time.RFC3339Nano, strings.Split(v, " ")[0]) 222 assert.NilError(c, err, "cannot parse timestamp output from log: '%v'", v) 223 assert.Assert(c, ts.Unix() >= since, "earlier log found. since=%v logdate=%v", since, ts) 224 } 225 } 226 227 // Regression test for #8832 228 func (s *DockerCLILogsSuite) TestLogsFollowSlowStdoutConsumer(c *testing.T) { 229 // TODO Windows: Fix this test for TP5. 230 testRequires(c, DaemonIsLinux) 231 expected := 150000 232 id := cli.DockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", fmt.Sprintf("usleep 600000; yes X | head -c %d", expected)).Stdout() 233 id = strings.TrimSpace(id) 234 235 stopSlowRead := make(chan bool) 236 237 go func() { 238 cli.DockerCmd(c, "wait", id) 239 stopSlowRead <- true 240 }() 241 242 logCmd := exec.Command(dockerBinary, "logs", "-f", id) 243 stdout, err := logCmd.StdoutPipe() 244 assert.NilError(c, err) 245 assert.NilError(c, logCmd.Start()) 246 defer func() { go logCmd.Wait() }() 247 248 // First read slowly 249 bytes1, err := ConsumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead) 250 assert.NilError(c, err) 251 252 // After the container has finished we can continue reading fast 253 bytes2, err := ConsumeWithSpeed(stdout, 32*1024, 0, nil) 254 assert.NilError(c, err) 255 256 assert.NilError(c, logCmd.Wait()) 257 258 actual := bytes1 + bytes2 259 assert.Equal(c, actual, expected) 260 } 261 262 // ConsumeWithSpeed reads chunkSize bytes from reader before sleeping 263 // for interval duration. Returns total read bytes. Send true to the 264 // stop channel to return before reading to EOF on the reader. 265 func ConsumeWithSpeed(reader io.Reader, chunkSize int, interval time.Duration, stop chan bool) (n int, err error) { 266 buffer := make([]byte, chunkSize) 267 for { 268 var readBytes int 269 readBytes, err = reader.Read(buffer) 270 n += readBytes 271 if err != nil { 272 if err == io.EOF { 273 err = nil 274 } 275 return 276 } 277 select { 278 case <-stop: 279 return 280 case <-time.After(interval): 281 } 282 } 283 } 284 285 func (s *DockerCLILogsSuite) TestLogsFollowGoroutinesWithStdout(c *testing.T) { 286 testRequires(c, DaemonIsLinux, testEnv.IsLocalDaemon) 287 c.Parallel() 288 289 ctx := testutil.GetContext(c) 290 d := daemon.New(c, dockerBinary, dockerdBinary, testdaemon.WithEnvVars("OTEL_SDK_DISABLED=1")) 291 defer func() { 292 d.Stop(c) 293 d.Cleanup(c) 294 }() 295 d.StartWithBusybox(ctx, c, "--iptables=false") 296 297 out, err := d.Cmd("run", "-d", "busybox", "/bin/sh", "-c", "while true; do echo hello; sleep 2; done") 298 assert.NilError(c, err) 299 300 id := strings.TrimSpace(out) 301 assert.NilError(c, d.WaitRun(id)) 302 303 client := d.NewClientT(c) 304 nroutines := waitForStableGourtineCount(ctx, c, client) 305 306 cmd := d.Command("logs", "-f", id) 307 r, w := io.Pipe() 308 defer r.Close() 309 defer w.Close() 310 311 cmd.Stdout = w 312 res := icmd.StartCmd(cmd) 313 assert.NilError(c, res.Error) 314 defer res.Cmd.Process.Kill() 315 316 finished := make(chan error) 317 go func() { 318 finished <- res.Cmd.Wait() 319 }() 320 321 // Make sure pipe is written to 322 chErr := make(chan error) 323 go func() { 324 b := make([]byte, 1) 325 _, err := r.Read(b) 326 chErr <- err 327 r.Close() 328 }() 329 330 // Check read from pipe succeeded 331 assert.NilError(c, <-chErr) 332 333 assert.NilError(c, res.Cmd.Process.Kill()) 334 <-finished 335 336 // NGoroutines is not updated right away, so we need to wait before failing 337 waitForGoroutines(ctx, c, client, nroutines) 338 } 339 340 func (s *DockerCLILogsSuite) TestLogsFollowGoroutinesNoOutput(c *testing.T) { 341 testRequires(c, DaemonIsLinux, testEnv.IsLocalDaemon) 342 c.Parallel() 343 344 d := daemon.New(c, dockerBinary, dockerdBinary, testdaemon.WithEnvVars("OTEL_SDK_DISABLED=1")) 345 defer func() { 346 d.Stop(c) 347 d.Cleanup(c) 348 }() 349 350 ctx := testutil.GetContext(c) 351 352 d.StartWithBusybox(ctx, c, "--iptables=false") 353 354 out, err := d.Cmd("run", "-d", "busybox", "/bin/sh", "-c", "while true; do sleep 2; done") 355 assert.NilError(c, err) 356 id := strings.TrimSpace(out) 357 assert.NilError(c, d.WaitRun(id)) 358 359 client := d.NewClientT(c) 360 nroutines := waitForStableGourtineCount(ctx, c, client) 361 assert.NilError(c, err) 362 363 cmd := d.Command("logs", "-f", id) 364 res := icmd.StartCmd(cmd) 365 assert.NilError(c, res.Error) 366 367 finished := make(chan error) 368 go func() { 369 finished <- res.Cmd.Wait() 370 }() 371 372 time.Sleep(200 * time.Millisecond) 373 assert.NilError(c, res.Cmd.Process.Kill()) 374 375 <-finished 376 377 // NGoroutines is not updated right away, so we need to wait before failing 378 waitForGoroutines(ctx, c, client, nroutines) 379 } 380 381 func (s *DockerCLILogsSuite) TestLogsCLIContainerNotFound(c *testing.T) { 382 name := "testlogsnocontainer" 383 out, _, _ := dockerCmdWithError("logs", name) 384 message := fmt.Sprintf("No such container: %s\n", name) 385 assert.Assert(c, strings.Contains(out, message)) 386 } 387 388 func (s *DockerCLILogsSuite) TestLogsWithDetails(c *testing.T) { 389 cli.DockerCmd(c, "run", "--name=test", "--label", "foo=bar", "-e", "baz=qux", "--log-opt", "labels=foo", "--log-opt", "env=baz", "busybox", "echo", "hello") 390 out := cli.DockerCmd(c, "logs", "--details", "--timestamps", "test").Combined() 391 392 logFields := strings.Fields(strings.TrimSpace(out)) 393 assert.Equal(c, len(logFields), 3, out) 394 395 details := strings.Split(logFields[1], ",") 396 assert.Equal(c, len(details), 2) 397 assert.Equal(c, details[0], "baz=qux") 398 assert.Equal(c, details[1], "foo=bar") 399 }