integration-cli/docker_cli_logs_test.go
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
 }