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