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