5fb28eab |
package main
import (
"fmt" |
e3ba3dd5 |
"io" |
5fb28eab |
"os/exec" |
d1297fee |
"regexp"
"strings" |
59e55dcd |
"testing" |
d1297fee |
"time" |
cd7a5f5c |
|
eeaa6c96 |
"github.com/docker/docker/integration-cli/cli" |
27cfa68a |
"github.com/docker/docker/pkg/jsonmessage" |
9f0b3f56 |
"gotest.tools/v3/assert"
"gotest.tools/v3/icmd" |
5fb28eab |
)
// This used to work, it test a log of PageSize-1 (gh#4851) |
1d92789b |
func (s *DockerSuite) TestLogsContainerSmallerThanPage(c *testing.T) { |
9af5d7c3 |
testLogsContainerPagination(c, 32767) |
5fb28eab |
}
// Regression test: When going over the PageSize, it used to panic (gh#4851) |
1d92789b |
func (s *DockerSuite) TestLogsContainerBiggerThanPage(c *testing.T) { |
9af5d7c3 |
testLogsContainerPagination(c, 32768) |
5fb28eab |
}
// Regression test: When going much over the PageSize, it used to block (gh#4851) |
1d92789b |
func (s *DockerSuite) TestLogsContainerMuchBiggerThanPage(c *testing.T) { |
9af5d7c3 |
testLogsContainerPagination(c, 33000)
} |
5fb28eab |
|
1d92789b |
func testLogsContainerPagination(c *testing.T, testLen int) { |
9af5d7c3 |
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)) |
946e8cde |
id := strings.TrimSpace(out)
dockerCmd(c, "wait", id)
out, _ = dockerCmd(c, "logs", id) |
6345208b |
assert.Equal(c, len(out), testLen+1) |
5fb28eab |
} |
d1297fee |
|
1d92789b |
func (s *DockerSuite) TestLogsTimestamps(c *testing.T) { |
d1297fee |
testLen := 100 |
8ff88454 |
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)) |
d1297fee |
|
946e8cde |
id := strings.TrimSpace(out)
dockerCmd(c, "wait", id) |
d1297fee |
|
946e8cde |
out, _ = dockerCmd(c, "logs", "-t", id) |
d1297fee |
lines := strings.Split(out, "\n")
|
6345208b |
assert.Equal(c, len(lines), testLen+1) |
d1297fee |
|
aa0eca03 |
ts := regexp.MustCompile(`^.* `) |
d1297fee |
for _, l := range lines {
if l != "" { |
27cfa68a |
_, err := time.Parse(jsonmessage.RFC3339NanoFixed+" ", ts.FindString(l)) |
6345208b |
assert.NilError(c, err, "Failed to parse timestamp from %v", l) |
946e8cde |
// ensure we have padded 0's |
6345208b |
assert.Equal(c, l[29], uint8('Z')) |
d1297fee |
}
}
}
|
1d92789b |
func (s *DockerSuite) TestLogsSeparateStderr(c *testing.T) { |
d1297fee |
msg := "stderr_log" |
eeaa6c96 |
out := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)).Combined() |
946e8cde |
id := strings.TrimSpace(out) |
eeaa6c96 |
cli.DockerCmd(c, "wait", id)
cli.DockerCmd(c, "logs", id).Assert(c, icmd.Expected{
Out: "",
Err: msg,
}) |
d1297fee |
}
|
1d92789b |
func (s *DockerSuite) TestLogsStderrInStdout(c *testing.T) { |
10bd587d |
// TODO Windows: Needs investigation why this fails. Obtained string includes
// a bunch of ANSI escape sequences before the "stderr_log" message. |
f9a3558a |
testRequires(c, DaemonIsLinux) |
d1297fee |
msg := "stderr_log" |
eeaa6c96 |
out := cli.DockerCmd(c, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)).Combined() |
946e8cde |
id := strings.TrimSpace(out) |
eeaa6c96 |
cli.DockerCmd(c, "wait", id) |
d1297fee |
|
eeaa6c96 |
cli.DockerCmd(c, "logs", id).Assert(c, icmd.Expected{
Out: msg,
Err: "",
}) |
d1297fee |
} |
1dc0caf9 |
|
1d92789b |
func (s *DockerSuite) TestLogsTail(c *testing.T) { |
1dc0caf9 |
testLen := 100 |
eeaa6c96 |
out := cli.DockerCmd(c, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)).Combined() |
1dc0caf9 |
|
946e8cde |
id := strings.TrimSpace(out) |
eeaa6c96 |
cli.DockerCmd(c, "wait", id) |
1dc0caf9 |
|
eeaa6c96 |
out = cli.DockerCmd(c, "logs", "--tail", "0", id).Combined() |
1dc0caf9 |
lines := strings.Split(out, "\n") |
6345208b |
assert.Equal(c, len(lines), 1) |
1dc0caf9 |
|
eeaa6c96 |
out = cli.DockerCmd(c, "logs", "--tail", "5", id).Combined() |
63904eb6 |
lines = strings.Split(out, "\n") |
6345208b |
assert.Equal(c, len(lines), 6) |
946e8cde |
|
eeaa6c96 |
out = cli.DockerCmd(c, "logs", "--tail", "99", id).Combined() |
63904eb6 |
lines = strings.Split(out, "\n") |
6345208b |
assert.Equal(c, len(lines), 100) |
1dc0caf9 |
|
eeaa6c96 |
out = cli.DockerCmd(c, "logs", "--tail", "all", id).Combined() |
1dc0caf9 |
lines = strings.Split(out, "\n") |
6345208b |
assert.Equal(c, len(lines), testLen+1) |
1dc0caf9 |
|
eeaa6c96 |
out = cli.DockerCmd(c, "logs", "--tail", "-1", id).Combined() |
63904eb6 |
lines = strings.Split(out, "\n") |
6345208b |
assert.Equal(c, len(lines), testLen+1) |
946e8cde |
|
eeaa6c96 |
out = cli.DockerCmd(c, "logs", "--tail", "random", id).Combined() |
1dc0caf9 |
lines = strings.Split(out, "\n") |
6345208b |
assert.Equal(c, len(lines), testLen+1) |
1dc0caf9 |
} |
f04ef96e |
|
1d92789b |
func (s *DockerSuite) TestLogsFollowStopped(c *testing.T) { |
e4468913 |
dockerCmd(c, "run", "--name=test", "busybox", "echo", "hello") |
c10f6ef4 |
id := getIDByName(c, "test") |
f04ef96e |
|
946e8cde |
logsCmd := exec.Command(dockerBinary, "logs", "-f", id) |
6345208b |
assert.NilError(c, logsCmd.Start()) |
f04ef96e |
|
c322af80 |
errChan := make(chan error, 1) |
f04ef96e |
go func() { |
4203230c |
errChan <- logsCmd.Wait()
close(errChan) |
f04ef96e |
}()
select { |
4203230c |
case err := <-errChan: |
6345208b |
assert.NilError(c, err) |
10bd587d |
case <-time.After(30 * time.Second): |
dc944ea7 |
c.Fatal("Following logs is hanged") |
f04ef96e |
}
} |
c2cf97a0 |
|
1d92789b |
func (s *DockerSuite) TestLogsSince(c *testing.T) { |
cb9a6b9a |
name := "testlogssince" |
7ab0f9bf |
dockerCmd(c, "run", "--name="+name, "busybox", "/bin/sh", "-c", "for i in $(seq 1 3); do sleep 2; echo log$i; done")
out, _ := dockerCmd(c, "logs", "-t", name) |
cb9a6b9a |
|
2fe2f7a1 |
log2Line := strings.Split(strings.Split(out, "\n")[1], " ") |
7ab0f9bf |
t, err := time.Parse(time.RFC3339Nano, log2Line[0]) // the timestamp log2 is written |
6345208b |
assert.NilError(c, err) |
7ab0f9bf |
since := t.Unix() + 1 // add 1s so log1 & log2 doesn't show up |
eef6eda7 |
out, _ = dockerCmd(c, "logs", "-t", fmt.Sprintf("--since=%v", since), name) |
cb9a6b9a |
// Skip 2 seconds
unexpected := []string{"log1", "log2"}
for _, v := range unexpected { |
6345208b |
assert.Check(c, !strings.Contains(out, v), "unexpected log message returned, since=%v", since) |
cb9a6b9a |
} |
430d8ff6 |
// Test to make sure a bad since format is caught by the client
out, _, _ = dockerCmdWithError("logs", "-t", "--since=2006-01-02T15:04:0Z", name) |
6345208b |
assert.Assert(c, strings.Contains(out, `cannot parse "0Z" as "05"`), "bad since format passed to server") |
430d8ff6 |
|
cb9a6b9a |
// Test with default value specified and parameter omitted |
2fe2f7a1 |
expected := []string{"log1", "log2", "log3"} |
87e3fcfe |
for _, cmd := range [][]string{ |
303b1d20 |
{"logs", "-t", name},
{"logs", "-t", "--since=0", name}, |
cb9a6b9a |
} { |
303b1d20 |
result := icmd.RunCommand(dockerBinary, cmd...) |
87e3fcfe |
result.Assert(c, icmd.Success) |
cb9a6b9a |
for _, v := range expected { |
6345208b |
assert.Check(c, strings.Contains(result.Combined(), v)) |
cb9a6b9a |
}
}
}
|
1d92789b |
func (s *DockerSuite) TestLogsSinceFutureFollow(c *testing.T) { |
acaef7ca |
// TODO Windows TP5 - Figure out why this test is so flakey. Disabled for now.
testRequires(c, DaemonIsLinux) |
49281219 |
name := "testlogssincefuturefollow" |
ddd8a657 |
dockerCmd(c, "run", "-d", "--name", name, "busybox", "/bin/sh", "-c", `for i in $(seq 1 5); do echo log$i; sleep 1; done`) |
49281219 |
// Extract one timestamp from the log file to give us a starting point for
// our `--since` argument. Because the log producer runs in the background,
// we need to check repeatedly for some output to be produced.
var timestamp string |
10bd587d |
for i := 0; i != 100 && timestamp == ""; i++ { |
ddd8a657 |
if out, _ := dockerCmd(c, "logs", "-t", name); out == "" { |
49281219 |
time.Sleep(time.Millisecond * 100) // Retry
} else {
timestamp = strings.Split(strings.Split(out, "\n")[0], " ")[0]
}
} |
cb9a6b9a |
|
6345208b |
assert.Assert(c, timestamp != "") |
49281219 |
t, err := time.Parse(time.RFC3339Nano, timestamp) |
6345208b |
assert.NilError(c, err) |
49281219 |
since := t.Unix() + 2 |
ddd8a657 |
out, _ := dockerCmd(c, "logs", "-t", "-f", fmt.Sprintf("--since=%v", since), name) |
6345208b |
assert.Assert(c, len(out) != 0, "cannot read from empty log") |
cb9a6b9a |
lines := strings.Split(strings.TrimSpace(out), "\n")
for _, v := range lines { |
49281219 |
ts, err := time.Parse(time.RFC3339Nano, strings.Split(v, " ")[0]) |
6345208b |
assert.NilError(c, err, "cannot parse timestamp output from log: '%v'", v)
assert.Assert(c, ts.Unix() >= since, "earlier log found. since=%v logdate=%v", since, ts) |
cb9a6b9a |
}
}
|
c2cf97a0 |
// Regression test for #8832 |
1d92789b |
func (s *DockerSuite) TestLogsFollowSlowStdoutConsumer(c *testing.T) { |
b0e24c73 |
// TODO Windows: Fix this test for TP5. |
f9a3558a |
testRequires(c, DaemonIsLinux) |
1bc93bff |
expected := 150000
out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", fmt.Sprintf("usleep 600000; yes X | head -c %d", expected)) |
c2cf97a0 |
|
946e8cde |
id := strings.TrimSpace(out) |
c2cf97a0 |
stopSlowRead := make(chan bool)
go func() { |
1bc93bff |
dockerCmd(c, "wait", id) |
c2cf97a0 |
stopSlowRead <- true
}()
|
946e8cde |
logCmd := exec.Command(dockerBinary, "logs", "-f", id) |
c2cf97a0 |
stdout, err := logCmd.StdoutPipe() |
6345208b |
assert.NilError(c, err)
assert.NilError(c, logCmd.Start()) |
ddae20c0 |
defer func() { go logCmd.Wait() }() |
c2cf97a0 |
// First read slowly |
1455086c |
bytes1, err := ConsumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead) |
6345208b |
assert.NilError(c, err) |
c2cf97a0 |
// After the container has finished we can continue reading fast |
1455086c |
bytes2, err := ConsumeWithSpeed(stdout, 32*1024, 0, nil) |
6345208b |
assert.NilError(c, err) |
c2cf97a0 |
|
6345208b |
assert.NilError(c, logCmd.Wait()) |
14f0a188 |
|
c2cf97a0 |
actual := bytes1 + bytes2 |
6345208b |
assert.Equal(c, actual, expected) |
c2cf97a0 |
} |
e3ba3dd5 |
|
1455086c |
// ConsumeWithSpeed reads chunkSize bytes from reader before sleeping
// for interval duration. Returns total read bytes. Send true to the
// stop channel to return before reading to EOF on the reader.
func ConsumeWithSpeed(reader io.Reader, chunkSize int, interval time.Duration, stop chan bool) (n int, err error) {
buffer := make([]byte, chunkSize)
for {
var readBytes int
readBytes, err = reader.Read(buffer)
n += readBytes
if err != nil {
if err == io.EOF {
err = nil
}
return
}
select {
case <-stop:
return
case <-time.After(interval):
}
}
}
|
1d92789b |
func (s *DockerSuite) TestLogsFollowGoroutinesWithStdout(c *testing.T) { |
e3ba3dd5 |
out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do echo hello; sleep 2; done")
id := strings.TrimSpace(out) |
6345208b |
assert.NilError(c, waitRun(id)) |
e3ba3dd5 |
|
0c7c9df8 |
nroutines, err := getGoroutineNumber() |
6345208b |
assert.NilError(c, err) |
e3ba3dd5 |
cmd := exec.Command(dockerBinary, "logs", "-f", id)
r, w := io.Pipe()
cmd.Stdout = w |
6345208b |
assert.NilError(c, cmd.Start()) |
617f89b9 |
go cmd.Wait() |
e3ba3dd5 |
// Make sure pipe is written to
chErr := make(chan error)
go func() {
b := make([]byte, 1)
_, err := r.Read(b)
chErr <- err
}() |
6345208b |
assert.NilError(c, <-chErr)
assert.NilError(c, cmd.Process.Kill()) |
1e98fb5a |
r.Close() |
14f0a188 |
cmd.Wait() |
e3ba3dd5 |
// NGoroutines is not updated right away, so we need to wait before failing |
6345208b |
assert.NilError(c, waitForGoroutines(nroutines)) |
e3ba3dd5 |
} |
0c84604f |
|
1d92789b |
func (s *DockerSuite) TestLogsFollowGoroutinesNoOutput(c *testing.T) { |
0c84604f |
out, _ := dockerCmd(c, "run", "-d", "busybox", "/bin/sh", "-c", "while true; do sleep 2; done")
id := strings.TrimSpace(out) |
6345208b |
assert.NilError(c, waitRun(id)) |
0c84604f |
|
0c7c9df8 |
nroutines, err := getGoroutineNumber() |
6345208b |
assert.NilError(c, err) |
0c84604f |
cmd := exec.Command(dockerBinary, "logs", "-f", id) |
6345208b |
assert.NilError(c, cmd.Start()) |
617f89b9 |
go cmd.Wait() |
0c84604f |
time.Sleep(200 * time.Millisecond) |
6345208b |
assert.NilError(c, cmd.Process.Kill()) |
14f0a188 |
cmd.Wait() |
0c84604f |
// NGoroutines is not updated right away, so we need to wait before failing |
6345208b |
assert.NilError(c, waitForGoroutines(nroutines)) |
0c84604f |
} |
1eecc1e7 |
|
1d92789b |
func (s *DockerSuite) TestLogsCLIContainerNotFound(c *testing.T) { |
1eecc1e7 |
name := "testlogsnocontainer"
out, _, _ := dockerCmdWithError("logs", name) |
05dc9846 |
message := fmt.Sprintf("No such container: %s\n", name) |
6345208b |
assert.Assert(c, strings.Contains(out, message)) |
1eecc1e7 |
} |
bd9d14a0 |
|
1d92789b |
func (s *DockerSuite) TestLogsWithDetails(c *testing.T) { |
bd9d14a0 |
dockerCmd(c, "run", "--name=test", "--label", "foo=bar", "-e", "baz=qux", "--log-opt", "labels=foo", "--log-opt", "env=baz", "busybox", "echo", "hello")
out, _ := dockerCmd(c, "logs", "--details", "--timestamps", "test")
logFields := strings.Fields(strings.TrimSpace(out)) |
6345208b |
assert.Equal(c, len(logFields), 3, out) |
bd9d14a0 |
details := strings.Split(logFields[1], ",") |
6345208b |
assert.Equal(c, len(details), 2)
assert.Equal(c, details[0], "baz=qux")
assert.Equal(c, details[1], "foo=bar") |
bd9d14a0 |
} |