github.com/codemac/docker@v1.2.1-0.20150518222241-6a18412d5b9c/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/timeutils" 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 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 21 out, _, _, err := runCommandWithStdoutStderr(runCmd) 22 if err != nil { 23 c.Fatalf("run failed with errors: %s, %v", out, err) 24 } 25 26 cleanedContainerID := strings.TrimSpace(out) 27 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 28 29 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 30 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 31 if err != nil { 32 c.Fatalf("failed to log container: %s, %v", out, err) 33 } 34 35 if len(out) != testLen+1 { 36 c.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out)) 37 } 38 39 deleteContainer(cleanedContainerID) 40 41 } 42 43 // Regression test: When going over the PageSize, it used to panic (gh#4851) 44 func (s *DockerSuite) TestLogsContainerBiggerThanPage(c *check.C) { 45 testLen := 32768 46 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 47 out, _, _, err := runCommandWithStdoutStderr(runCmd) 48 if err != nil { 49 c.Fatalf("run failed with errors: %s, %v", out, err) 50 } 51 52 cleanedContainerID := strings.TrimSpace(out) 53 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 54 55 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 56 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 57 if err != nil { 58 c.Fatalf("failed to log container: %s, %v", out, err) 59 } 60 61 if len(out) != testLen+1 { 62 c.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out)) 63 } 64 65 deleteContainer(cleanedContainerID) 66 67 } 68 69 // Regression test: When going much over the PageSize, it used to block (gh#4851) 70 func (s *DockerSuite) TestLogsContainerMuchBiggerThanPage(c *check.C) { 71 testLen := 33000 72 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 73 out, _, _, err := runCommandWithStdoutStderr(runCmd) 74 if err != nil { 75 c.Fatalf("run failed with errors: %s, %v", out, err) 76 } 77 78 cleanedContainerID := strings.TrimSpace(out) 79 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 80 81 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 82 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 83 if err != nil { 84 c.Fatalf("failed to log container: %s, %v", out, err) 85 } 86 87 if len(out) != testLen+1 { 88 c.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out)) 89 } 90 91 deleteContainer(cleanedContainerID) 92 93 } 94 95 func (s *DockerSuite) TestLogsTimestamps(c *check.C) { 96 testLen := 100 97 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)) 98 99 out, _, _, err := runCommandWithStdoutStderr(runCmd) 100 if err != nil { 101 c.Fatalf("run failed with errors: %s, %v", out, err) 102 } 103 104 cleanedContainerID := strings.TrimSpace(out) 105 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 106 107 logsCmd := exec.Command(dockerBinary, "logs", "-t", cleanedContainerID) 108 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 109 if err != nil { 110 c.Fatalf("failed to log container: %s, %v", out, err) 111 } 112 113 lines := strings.Split(out, "\n") 114 115 if len(lines) != testLen+1 { 116 c.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines)) 117 } 118 119 ts := regexp.MustCompile(`^.* `) 120 121 for _, l := range lines { 122 if l != "" { 123 _, err := time.Parse(timeutils.RFC3339NanoFixed+" ", ts.FindString(l)) 124 if err != nil { 125 c.Fatalf("Failed to parse timestamp from %v: %v", l, err) 126 } 127 if l[29] != 'Z' { // ensure we have padded 0's 128 c.Fatalf("Timestamp isn't padded properly: %s", l) 129 } 130 } 131 } 132 133 deleteContainer(cleanedContainerID) 134 135 } 136 137 func (s *DockerSuite) TestLogsSeparateStderr(c *check.C) { 138 msg := "stderr_log" 139 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)) 140 141 out, _, _, err := runCommandWithStdoutStderr(runCmd) 142 if err != nil { 143 c.Fatalf("run failed with errors: %s, %v", out, err) 144 } 145 146 cleanedContainerID := strings.TrimSpace(out) 147 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 148 149 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 150 stdout, stderr, _, err := runCommandWithStdoutStderr(logsCmd) 151 if err != nil { 152 c.Fatalf("failed to log container: %s, %v", out, err) 153 } 154 155 if stdout != "" { 156 c.Fatalf("Expected empty stdout stream, got %v", stdout) 157 } 158 159 stderr = strings.TrimSpace(stderr) 160 if stderr != msg { 161 c.Fatalf("Expected %v in stderr stream, got %v", msg, stderr) 162 } 163 164 deleteContainer(cleanedContainerID) 165 166 } 167 168 func (s *DockerSuite) TestLogsStderrInStdout(c *check.C) { 169 msg := "stderr_log" 170 runCmd := exec.Command(dockerBinary, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)) 171 172 out, _, _, err := runCommandWithStdoutStderr(runCmd) 173 if err != nil { 174 c.Fatalf("run failed with errors: %s, %v", out, err) 175 } 176 177 cleanedContainerID := strings.TrimSpace(out) 178 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 179 180 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 181 stdout, stderr, _, err := runCommandWithStdoutStderr(logsCmd) 182 if err != nil { 183 c.Fatalf("failed to log container: %s, %v", out, err) 184 } 185 186 if stderr != "" { 187 c.Fatalf("Expected empty stderr stream, got %v", stdout) 188 } 189 190 stdout = strings.TrimSpace(stdout) 191 if stdout != msg { 192 c.Fatalf("Expected %v in stdout stream, got %v", msg, stdout) 193 } 194 195 deleteContainer(cleanedContainerID) 196 197 } 198 199 func (s *DockerSuite) TestLogsTail(c *check.C) { 200 testLen := 100 201 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)) 202 203 out, _, _, err := runCommandWithStdoutStderr(runCmd) 204 if err != nil { 205 c.Fatalf("run failed with errors: %s, %v", out, err) 206 } 207 208 cleanedContainerID := strings.TrimSpace(out) 209 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 210 211 logsCmd := exec.Command(dockerBinary, "logs", "--tail", "5", cleanedContainerID) 212 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 213 if err != nil { 214 c.Fatalf("failed to log container: %s, %v", out, err) 215 } 216 217 lines := strings.Split(out, "\n") 218 219 if len(lines) != 6 { 220 c.Fatalf("Expected log %d lines, received %d\n", 6, len(lines)) 221 } 222 223 logsCmd = exec.Command(dockerBinary, "logs", "--tail", "all", cleanedContainerID) 224 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 225 if err != nil { 226 c.Fatalf("failed to log container: %s, %v", out, err) 227 } 228 229 lines = strings.Split(out, "\n") 230 231 if len(lines) != testLen+1 { 232 c.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines)) 233 } 234 235 logsCmd = exec.Command(dockerBinary, "logs", "--tail", "random", cleanedContainerID) 236 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 237 if err != nil { 238 c.Fatalf("failed to log container: %s, %v", out, err) 239 } 240 241 lines = strings.Split(out, "\n") 242 243 if len(lines) != testLen+1 { 244 c.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines)) 245 } 246 247 deleteContainer(cleanedContainerID) 248 } 249 250 func (s *DockerSuite) TestLogsFollowStopped(c *check.C) { 251 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "echo", "hello") 252 253 out, _, _, err := runCommandWithStdoutStderr(runCmd) 254 if err != nil { 255 c.Fatalf("run failed with errors: %s, %v", out, err) 256 } 257 258 cleanedContainerID := strings.TrimSpace(out) 259 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 260 261 logsCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID) 262 if err := logsCmd.Start(); err != nil { 263 c.Fatal(err) 264 } 265 266 errChan := make(chan error) 267 go func() { 268 errChan <- logsCmd.Wait() 269 close(errChan) 270 }() 271 272 select { 273 case err := <-errChan: 274 c.Assert(err, check.IsNil) 275 case <-time.After(1 * time.Second): 276 c.Fatal("Following logs is hanged") 277 } 278 279 deleteContainer(cleanedContainerID) 280 } 281 282 func (s *DockerSuite) TestLogsSince(c *check.C) { 283 name := "testlogssince" 284 runCmd := exec.Command(dockerBinary, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo `date +%s` log$i; done") 285 out, _, err := runCommandWithOutput(runCmd) 286 if err != nil { 287 c.Fatalf("run failed with errors: %s, %v", out, err) 288 } 289 290 log2Line := strings.Split(strings.Split(out, "\n")[1], " ") 291 t, err := strconv.ParseInt(log2Line[0], 10, 64) // the timestamp log2 is writen 292 c.Assert(err, check.IsNil) 293 since := t + 1 // add 1s so log1 & log2 doesn't show up 294 logsCmd := exec.Command(dockerBinary, "logs", "-t", fmt.Sprintf("--since=%v", since), name) 295 296 out, _, err = runCommandWithOutput(logsCmd) 297 if err != nil { 298 c.Fatalf("failed to log container: %s, %v", out, err) 299 } 300 301 // Skip 2 seconds 302 unexpected := []string{"log1", "log2"} 303 for _, v := range unexpected { 304 if strings.Contains(out, v) { 305 c.Fatalf("unexpected log message returned=%v, since=%v\nout=%v", v, since, out) 306 } 307 } 308 309 // Test with default value specified and parameter omitted 310 expected := []string{"log1", "log2", "log3"} 311 for _, cmd := range []*exec.Cmd{ 312 exec.Command(dockerBinary, "logs", "-t", name), 313 exec.Command(dockerBinary, "logs", "-t", "--since=0", name), 314 } { 315 out, _, err = runCommandWithOutput(cmd) 316 if err != nil { 317 c.Fatalf("failed to log container: %s, %v", out, err) 318 } 319 for _, v := range expected { 320 if !strings.Contains(out, v) { 321 c.Fatalf("'%v' does not contain=%v\nout=%s", cmd.Args, v, out) 322 } 323 } 324 } 325 } 326 327 func (s *DockerSuite) TestLogsSinceFutureFollow(c *check.C) { 328 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "/bin/sh", "-c", `for i in $(seq 1 5); do date +%s; sleep 1; done`) 329 out, _, err := runCommandWithOutput(runCmd) 330 if err != nil { 331 c.Fatalf("run failed with errors: %s, %v", out, err) 332 } 333 cleanedContainerID := strings.TrimSpace(out) 334 335 now := daemonTime(c).Unix() 336 since := now + 2 337 logCmd := exec.Command(dockerBinary, "logs", "-f", fmt.Sprintf("--since=%v", since), cleanedContainerID) 338 out, _, err = runCommandWithOutput(logCmd) 339 if err != nil { 340 c.Fatalf("failed to log container: %s, %v", out, err) 341 } 342 lines := strings.Split(strings.TrimSpace(out), "\n") 343 if len(lines) == 0 { 344 c.Fatal("got no log lines") 345 } 346 for _, v := range lines { 347 ts, err := strconv.ParseInt(v, 10, 64) 348 if err != nil { 349 c.Fatalf("cannot parse timestamp output from log: '%v'\nout=%s", v, out) 350 } 351 if ts < since { 352 c.Fatalf("earlier log found. since=%v logdate=%v", since, ts) 353 } 354 } 355 } 356 357 // Regression test for #8832 358 func (s *DockerSuite) TestLogsFollowSlowStdoutConsumer(c *check.C) { 359 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "/bin/sh", "-c", `usleep 200000;yes X | head -c 200000`) 360 361 out, _, _, err := runCommandWithStdoutStderr(runCmd) 362 if err != nil { 363 c.Fatalf("run failed with errors: %s, %v", out, err) 364 } 365 366 cleanedContainerID := strings.TrimSpace(out) 367 368 stopSlowRead := make(chan bool) 369 370 go func() { 371 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 372 stopSlowRead <- true 373 }() 374 375 logCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID) 376 377 stdout, err := logCmd.StdoutPipe() 378 c.Assert(err, check.IsNil) 379 380 if err := logCmd.Start(); err != nil { 381 c.Fatal(err) 382 } 383 384 // First read slowly 385 bytes1, err := consumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead) 386 c.Assert(err, check.IsNil) 387 388 // After the container has finished we can continue reading fast 389 bytes2, err := consumeWithSpeed(stdout, 32*1024, 0, nil) 390 c.Assert(err, check.IsNil) 391 392 actual := bytes1 + bytes2 393 expected := 200000 394 if actual != expected { 395 c.Fatalf("Invalid bytes read: %d, expected %d", actual, expected) 396 } 397 398 } 399 400 func (s *DockerSuite) TestLogsFollowGoroutinesWithStdout(c *check.C) { 401 out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do echo hello; sleep 2; done") 402 id := strings.TrimSpace(out) 403 c.Assert(waitRun(id), check.IsNil) 404 405 type info struct { 406 NGoroutines int 407 } 408 getNGoroutines := func() int { 409 var i info 410 status, b, err := sockRequest("GET", "/info", nil) 411 c.Assert(err, check.IsNil) 412 c.Assert(status, check.Equals, 200) 413 c.Assert(json.Unmarshal(b, &i), check.IsNil) 414 return i.NGoroutines 415 } 416 417 nroutines := getNGoroutines() 418 419 cmd := exec.Command(dockerBinary, "logs", "-f", id) 420 r, w := io.Pipe() 421 cmd.Stdout = w 422 c.Assert(cmd.Start(), check.IsNil) 423 424 // Make sure pipe is written to 425 chErr := make(chan error) 426 go func() { 427 b := make([]byte, 1) 428 _, err := r.Read(b) 429 chErr <- err 430 }() 431 c.Assert(<-chErr, check.IsNil) 432 c.Assert(cmd.Process.Kill(), check.IsNil) 433 434 // NGoroutines is not updated right away, so we need to wait before failing 435 t := time.After(30 * time.Second) 436 for { 437 select { 438 case <-t: 439 c.Assert(nroutines, check.Equals, getNGoroutines()) 440 default: 441 if nroutines == getNGoroutines() { 442 return 443 } 444 time.Sleep(200 * time.Millisecond) 445 } 446 } 447 }