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