github.com/ruphin/docker@v1.10.1/integration-cli/docker_cli_logs_test.go (about) 1 package main 2 3 import ( 4 "encoding/json" 5 "fmt" 6 "io" 7 "os/exec" 8 "regexp" 9 "strconv" 10 "strings" 11 "time" 12 13 "github.com/docker/docker/pkg/integration/checker" 14 "github.com/docker/docker/pkg/jsonlog" 15 "github.com/go-check/check" 16 ) 17 18 // This used to work, it test a log of PageSize-1 (gh#4851) 19 func (s *DockerSuite) TestLogsContainerSmallerThanPage(c *check.C) { 20 testRequires(c, DaemonIsLinux) 21 testLen := 32767 22 out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 23 24 id := strings.TrimSpace(out) 25 dockerCmd(c, "wait", id) 26 27 out, _ = dockerCmd(c, "logs", id) 28 29 c.Assert(out, checker.HasLen, testLen+1) 30 } 31 32 // Regression test: When going over the PageSize, it used to panic (gh#4851) 33 func (s *DockerSuite) TestLogsContainerBiggerThanPage(c *check.C) { 34 testRequires(c, DaemonIsLinux) 35 testLen := 32768 36 out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 37 38 id := strings.TrimSpace(out) 39 dockerCmd(c, "wait", id) 40 41 out, _ = dockerCmd(c, "logs", id) 42 43 c.Assert(out, checker.HasLen, testLen+1) 44 } 45 46 // Regression test: When going much over the PageSize, it used to block (gh#4851) 47 func (s *DockerSuite) TestLogsContainerMuchBiggerThanPage(c *check.C) { 48 testRequires(c, DaemonIsLinux) 49 testLen := 33000 50 out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 51 52 id := strings.TrimSpace(out) 53 dockerCmd(c, "wait", id) 54 55 out, _ = dockerCmd(c, "logs", id) 56 57 c.Assert(out, checker.HasLen, testLen+1) 58 } 59 60 func (s *DockerSuite) TestLogsTimestamps(c *check.C) { 61 testRequires(c, DaemonIsLinux) 62 testLen := 100 63 out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)) 64 65 id := strings.TrimSpace(out) 66 dockerCmd(c, "wait", id) 67 68 out, _ = dockerCmd(c, "logs", "-t", id) 69 70 lines := strings.Split(out, "\n") 71 72 c.Assert(lines, checker.HasLen, testLen+1) 73 74 ts := regexp.MustCompile(`^.* `) 75 76 for _, l := range lines { 77 if l != "" { 78 _, err := time.Parse(jsonlog.RFC3339NanoFixed+" ", ts.FindString(l)) 79 c.Assert(err, checker.IsNil, check.Commentf("Failed to parse timestamp from %v", l)) 80 // ensure we have padded 0's 81 c.Assert(l[29], checker.Equals, uint8('Z')) 82 } 83 } 84 } 85 86 func (s *DockerSuite) TestLogsSeparateStderr(c *check.C) { 87 testRequires(c, DaemonIsLinux) 88 msg := "stderr_log" 89 out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)) 90 91 id := strings.TrimSpace(out) 92 dockerCmd(c, "wait", id) 93 94 stdout, stderr, _ := dockerCmdWithStdoutStderr(c, "logs", id) 95 96 c.Assert(stdout, checker.Equals, "") 97 98 stderr = strings.TrimSpace(stderr) 99 100 c.Assert(stderr, checker.Equals, msg) 101 } 102 103 func (s *DockerSuite) TestLogsStderrInStdout(c *check.C) { 104 testRequires(c, DaemonIsLinux) 105 msg := "stderr_log" 106 out, _ := dockerCmd(c, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)) 107 108 id := strings.TrimSpace(out) 109 dockerCmd(c, "wait", id) 110 111 stdout, stderr, _ := dockerCmdWithStdoutStderr(c, "logs", id) 112 c.Assert(stderr, checker.Equals, "") 113 114 stdout = strings.TrimSpace(stdout) 115 c.Assert(stdout, checker.Equals, msg) 116 } 117 118 func (s *DockerSuite) TestLogsTail(c *check.C) { 119 testRequires(c, DaemonIsLinux) 120 testLen := 100 121 out, _ := dockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)) 122 123 id := strings.TrimSpace(out) 124 dockerCmd(c, "wait", id) 125 126 out, _ = dockerCmd(c, "logs", "--tail", "5", id) 127 128 lines := strings.Split(out, "\n") 129 130 c.Assert(lines, checker.HasLen, 6) 131 132 out, _ = dockerCmd(c, "logs", "--tail", "all", id) 133 134 lines = strings.Split(out, "\n") 135 136 c.Assert(lines, checker.HasLen, testLen+1) 137 138 out, _, _ = dockerCmdWithStdoutStderr(c, "logs", "--tail", "random", id) 139 140 lines = strings.Split(out, "\n") 141 142 c.Assert(lines, checker.HasLen, testLen+1) 143 } 144 145 func (s *DockerSuite) TestLogsFollowStopped(c *check.C) { 146 testRequires(c, DaemonIsLinux) 147 out, _ := dockerCmd(c, "run", "-d", "busybox", "echo", "hello") 148 149 id := strings.TrimSpace(out) 150 dockerCmd(c, "wait", id) 151 152 logsCmd := exec.Command(dockerBinary, "logs", "-f", id) 153 c.Assert(logsCmd.Start(), checker.IsNil) 154 155 errChan := make(chan error) 156 go func() { 157 errChan <- logsCmd.Wait() 158 close(errChan) 159 }() 160 161 select { 162 case err := <-errChan: 163 c.Assert(err, checker.IsNil) 164 case <-time.After(1 * time.Second): 165 c.Fatal("Following logs is hanged") 166 } 167 } 168 169 func (s *DockerSuite) TestLogsSince(c *check.C) { 170 testRequires(c, DaemonIsLinux) 171 name := "testlogssince" 172 dockerCmd(c, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo log$i; done") 173 out, _ := dockerCmd(c, "logs", "-t", name) 174 175 log2Line := strings.Split(strings.Split(out, "\n")[1], " ") 176 t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // the timestamp log2 is written 177 c.Assert(err, checker.IsNil) 178 since := t.Unix() + 1 // add 1s so log1 & log2 doesn't show up 179 out, _ = dockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name) 180 181 // Skip 2 seconds 182 unexpected := []string{"log1", "log2"} 183 for _, v := range unexpected { 184 c.Assert(out, checker.Not(checker.Contains), v, check.Commentf("unexpected log message returned, since=%v", since)) 185 } 186 187 // Test to make sure a bad since format is caught by the client 188 out, _, _ = dockerCmdWithError("logs", "-t", "--since=2006-01-02T15:04:0Z", name) 189 c.Assert(out, checker.Contains, "cannot parse \"0Z\" as \"05\"", check.Commentf("bad since format passed to server")) 190 191 // Test with default value specified and parameter omitted 192 expected := []string{"log1", "log2", "log3"} 193 for _, cmd := range []*exec.Cmd{ 194 exec.Command(dockerBinary, "logs", "-t", name), 195 exec.Command(dockerBinary, "logs", "-t", "--since=0", name), 196 } { 197 out, _, err = runCommandWithOutput(cmd) 198 c.Assert(err, checker.IsNil, check.Commentf("failed to log container: %s", out)) 199 for _, v := range expected { 200 c.Assert(out, checker.Contains, v) 201 } 202 } 203 } 204 205 func (s *DockerSuite) TestLogsSinceFutureFollow(c *check.C) { 206 testRequires(c, DaemonIsLinux) 207 out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", `for i in $(seq 1 5); do date +%s; sleep 1; done`) 208 id := strings.TrimSpace(out) 209 210 now := daemonTime(c).Unix() 211 since := now + 2 212 out, _ = dockerCmd(c, "logs", "-f", fmt.Sprintf("--since=%v", since), id) 213 lines := strings.Split(strings.TrimSpace(out), "\n") 214 c.Assert(lines, checker.Not(checker.HasLen), 0) 215 for _, v := range lines { 216 ts, err := strconv.ParseInt(v, 10, 64) 217 c.Assert(err, checker.IsNil, check.Commentf("cannot parse timestamp output from log: '%v'\nout=%s", v, out)) 218 c.Assert(ts >= since, checker.Equals, true, check.Commentf("earlier log found. since=%v logdate=%v", since, ts)) 219 } 220 } 221 222 // Regression test for #8832 223 func (s *DockerSuite) TestLogsFollowSlowStdoutConsumer(c *check.C) { 224 testRequires(c, DaemonIsLinux) 225 out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", `usleep 600000;yes X | head -c 200000`) 226 227 id := strings.TrimSpace(out) 228 229 stopSlowRead := make(chan bool) 230 231 go func() { 232 exec.Command(dockerBinary, "wait", id).Run() 233 stopSlowRead <- true 234 }() 235 236 logCmd := exec.Command(dockerBinary, "logs", "-f", id) 237 stdout, err := logCmd.StdoutPipe() 238 c.Assert(err, checker.IsNil) 239 c.Assert(logCmd.Start(), checker.IsNil) 240 241 // First read slowly 242 bytes1, err := consumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead) 243 c.Assert(err, checker.IsNil) 244 245 // After the container has finished we can continue reading fast 246 bytes2, err := consumeWithSpeed(stdout, 32*1024, 0, nil) 247 c.Assert(err, checker.IsNil) 248 249 actual := bytes1 + bytes2 250 expected := 200000 251 c.Assert(actual, checker.Equals, expected) 252 253 } 254 255 func (s *DockerSuite) TestLogsFollowGoroutinesWithStdout(c *check.C) { 256 testRequires(c, DaemonIsLinux) 257 out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do echo hello; sleep 2; done") 258 id := strings.TrimSpace(out) 259 c.Assert(waitRun(id), checker.IsNil) 260 261 type info struct { 262 NGoroutines int 263 } 264 getNGoroutines := func() int { 265 var i info 266 status, b, err := sockRequest("GET", "/info", nil) 267 c.Assert(err, checker.IsNil) 268 c.Assert(status, checker.Equals, 200) 269 c.Assert(json.Unmarshal(b, &i), checker.IsNil) 270 return i.NGoroutines 271 } 272 273 nroutines := getNGoroutines() 274 275 cmd := exec.Command(dockerBinary, "logs", "-f", id) 276 r, w := io.Pipe() 277 cmd.Stdout = w 278 c.Assert(cmd.Start(), checker.IsNil) 279 280 // Make sure pipe is written to 281 chErr := make(chan error) 282 go func() { 283 b := make([]byte, 1) 284 _, err := r.Read(b) 285 chErr <- err 286 }() 287 c.Assert(<-chErr, checker.IsNil) 288 c.Assert(cmd.Process.Kill(), checker.IsNil) 289 290 // NGoroutines is not updated right away, so we need to wait before failing 291 t := time.After(30 * time.Second) 292 for { 293 select { 294 case <-t: 295 n := getNGoroutines() 296 c.Assert(n <= nroutines, checker.Equals, true, check.Commentf("leaked goroutines: expected less than or equal to %d, got: %d", nroutines, n)) 297 298 default: 299 if n := getNGoroutines(); n <= nroutines { 300 return 301 } 302 time.Sleep(200 * time.Millisecond) 303 } 304 } 305 } 306 307 func (s *DockerSuite) TestLogsFollowGoroutinesNoOutput(c *check.C) { 308 testRequires(c, DaemonIsLinux) 309 out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do sleep 2; done") 310 id := strings.TrimSpace(out) 311 c.Assert(waitRun(id), checker.IsNil) 312 313 type info struct { 314 NGoroutines int 315 } 316 getNGoroutines := func() int { 317 var i info 318 status, b, err := sockRequest("GET", "/info", nil) 319 c.Assert(err, checker.IsNil) 320 c.Assert(status, checker.Equals, 200) 321 c.Assert(json.Unmarshal(b, &i), checker.IsNil) 322 return i.NGoroutines 323 } 324 325 nroutines := getNGoroutines() 326 327 cmd := exec.Command(dockerBinary, "logs", "-f", id) 328 c.Assert(cmd.Start(), checker.IsNil) 329 time.Sleep(200 * time.Millisecond) 330 c.Assert(cmd.Process.Kill(), checker.IsNil) 331 332 // NGoroutines is not updated right away, so we need to wait before failing 333 t := time.After(30 * time.Second) 334 for { 335 select { 336 case <-t: 337 n := getNGoroutines() 338 c.Assert(n <= nroutines, checker.Equals, true, check.Commentf("leaked goroutines: expected less than or equal to %d, got: %d", nroutines, n)) 339 340 default: 341 if n := getNGoroutines(); n <= nroutines { 342 return 343 } 344 time.Sleep(200 * time.Millisecond) 345 } 346 } 347 } 348 349 func (s *DockerSuite) TestLogsCLIContainerNotFound(c *check.C) { 350 name := "testlogsnocontainer" 351 out, _, _ := dockerCmdWithError("logs", name) 352 message := fmt.Sprintf("Error: No such container: %s\n", name) 353 c.Assert(out, checker.Equals, message) 354 }