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