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