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