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