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