Skip to content

Commit 2ec3e14

Browse files
vvolandcorhere
vvoland
and
corhere
committed
test: Add tests for logging
1. Add integration tests for the ContainerLogs API call Each test handle a distinct case of ContainerLogs output. - Muxed stream, when container is started without tty - Single stream, when container is started with tty 2. Add unit test for LogReader suite that tests concurrent logging It checks that there are no race conditions when logging concurrently from multiple goroutines. Co-authored-by: Cory Snider <[email protected]> Signed-off-by: Cory Snider <[email protected]> Signed-off-by: Paweł Gronowski <[email protected]>
1 parent 20d6b5c commit 2ec3e14

4 files changed

Lines changed: 380 additions & 8 deletions

File tree

‎daemon/logger/loggertest/logreader.go‎

Lines changed: 90 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ package loggertest // import "github.com/docker/docker/daemon/logger/loggertest"
33
import (
44
"runtime"
55
"strings"
6+
"sync"
67
"testing"
78
"time"
89

@@ -381,6 +382,81 @@ func (tr Reader) TestFollow(t *testing.T) {
381382
<-doneReading
382383
assert.DeepEqual(t, logs, expected, compareLog)
383384
})
385+
386+
t.Run("Concurrent", tr.TestConcurrent)
387+
}
388+
389+
// TestConcurrent tests the Logger and its LogReader implementation for
390+
// race conditions when logging from multiple goroutines concurrently.
391+
func (tr Reader) TestConcurrent(t *testing.T) {
392+
t.Parallel()
393+
l := tr.Factory(t, logger.Info{
394+
ContainerID: "logconcurrent0",
395+
ContainerName: "logconcurrent123",
396+
})(t)
397+
398+
// Split test messages
399+
stderrMessages := []*logger.Message{}
400+
stdoutMessages := []*logger.Message{}
401+
for _, m := range makeTestMessages() {
402+
if m.Source == "stdout" {
403+
stdoutMessages = append(stdoutMessages, m)
404+
} else if m.Source == "stderr" {
405+
stderrMessages = append(stderrMessages, m)
406+
}
407+
}
408+
409+
// Follow all logs
410+
lw := l.(logger.LogReader).ReadLogs(logger.ReadConfig{Follow: true, Tail: -1})
411+
defer lw.ConsumerGone()
412+
413+
// Log concurrently from two sources and close log
414+
wg := &sync.WaitGroup{}
415+
logAll := func(msgs []*logger.Message) {
416+
defer wg.Done()
417+
for _, m := range msgs {
418+
l.Log(copyLogMessage(m))
419+
}
420+
}
421+
422+
closed := make(chan struct{})
423+
wg.Add(2)
424+
go logAll(stdoutMessages)
425+
go logAll(stderrMessages)
426+
go func() {
427+
defer close(closed)
428+
defer l.Close()
429+
wg.Wait()
430+
}()
431+
432+
// Check if the message count, order and content is equal to what was logged
433+
for {
434+
l := readMessage(t, lw)
435+
if l == nil {
436+
break
437+
}
438+
439+
var messages *[]*logger.Message
440+
if l.Source == "stdout" {
441+
messages = &stdoutMessages
442+
} else if l.Source == "stderr" {
443+
messages = &stderrMessages
444+
} else {
445+
t.Fatalf("Corrupted message.Source = %q", l.Source)
446+
}
447+
448+
expectedMsg := transformToExpected((*messages)[0])
449+
450+
assert.DeepEqual(t, *expectedMsg, *l, compareLog)
451+
*messages = (*messages)[1:]
452+
}
453+
454+
assert.Equal(t, len(stdoutMessages), 0)
455+
assert.Equal(t, len(stderrMessages), 0)
456+
457+
// Make sure log gets closed before we return
458+
// so the temporary dir can be deleted
459+
<-closed
384460
}
385461

386462
// logMessages logs messages to l and returns a slice of messages as would be
@@ -395,19 +471,25 @@ func logMessages(t *testing.T, l logger.Logger, messages []*logger.Message) []*l
395471
assert.NilError(t, l.Log(copyLogMessage(m)))
396472
runtime.Gosched()
397473

398-
// Copy the log message again so as not to mutate the input.
399-
expect := copyLogMessage(m)
400-
// Existing API consumers expect a newline to be appended to
401-
// messages other than nonterminal partials as that matches the
402-
// existing behavior of the json-file log driver.
403-
if m.PLogMetaData == nil || m.PLogMetaData.Last {
404-
expect.Line = append(expect.Line, '\n')
405-
}
474+
expect := transformToExpected(m)
406475
expected = append(expected, expect)
407476
}
408477
return expected
409478
}
410479

480+
// Existing API consumers expect a newline to be appended to
481+
// messages other than nonterminal partials as that matches the
482+
// existing behavior of the json-file log driver.
483+
func transformToExpected(m *logger.Message) *logger.Message {
484+
// Copy the log message again so as not to mutate the input.
485+
copy := copyLogMessage(m)
486+
if m.PLogMetaData == nil || m.PLogMetaData.Last {
487+
copy.Line = append(copy.Line, '\n')
488+
}
489+
490+
return copy
491+
}
492+
411493
func copyLogMessage(src *logger.Message) *logger.Message {
412494
dst := logger.NewMessage()
413495
dst.Source = src.Source

‎integration/container/logs_test.go‎

Lines changed: 156 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,22 @@
11
package container // import "github.com/docker/docker/integration/container"
22

33
import (
4+
"bytes"
45
"context"
56
"io"
7+
"strings"
68
"testing"
9+
"time"
710

811
"github.com/docker/docker/api/types"
12+
"github.com/docker/docker/daemon/logger/jsonfilelog"
13+
"github.com/docker/docker/daemon/logger/local"
914
"github.com/docker/docker/integration/internal/container"
15+
"github.com/docker/docker/integration/internal/termtest"
1016
"github.com/docker/docker/pkg/stdcopy"
1117
"gotest.tools/v3/assert"
18+
"gotest.tools/v3/assert/cmp"
19+
"gotest.tools/v3/poll"
1220
"gotest.tools/v3/skip"
1321
)
1422

@@ -32,3 +40,151 @@ func TestLogsFollowTailEmpty(t *testing.T) {
3240
_, err = stdcopy.StdCopy(io.Discard, io.Discard, logs)
3341
assert.Check(t, err)
3442
}
43+
44+
func TestLogs(t *testing.T) {
45+
drivers := []string{local.Name, jsonfilelog.Name}
46+
47+
for _, logDriver := range drivers {
48+
t.Run("driver "+logDriver, func(t *testing.T) {
49+
testLogs(t, logDriver)
50+
})
51+
}
52+
}
53+
54+
func testLogs(t *testing.T, logDriver string) {
55+
defer setupTest(t)()
56+
client := testEnv.APIClient()
57+
ctx := context.Background()
58+
59+
testCases := []struct {
60+
desc string
61+
logOps types.ContainerLogsOptions
62+
expectedOut string
63+
expectedErr string
64+
tty bool
65+
}{
66+
// TTY, only one output stream
67+
{
68+
desc: "tty/stdout and stderr",
69+
tty: true,
70+
logOps: types.ContainerLogsOptions{
71+
ShowStdout: true,
72+
ShowStderr: true,
73+
},
74+
expectedOut: "this is fineaccidents happen",
75+
},
76+
{
77+
desc: "tty/only stdout",
78+
tty: true,
79+
logOps: types.ContainerLogsOptions{
80+
ShowStdout: true,
81+
ShowStderr: false,
82+
},
83+
expectedOut: "this is fineaccidents happen",
84+
},
85+
{
86+
desc: "tty/only stderr",
87+
tty: true,
88+
logOps: types.ContainerLogsOptions{
89+
ShowStdout: false,
90+
ShowStderr: true,
91+
},
92+
expectedOut: "",
93+
},
94+
// Without TTY, both stdout and stderr
95+
{
96+
desc: "without tty/stdout and stderr",
97+
tty: false,
98+
logOps: types.ContainerLogsOptions{
99+
ShowStdout: true,
100+
ShowStderr: true,
101+
},
102+
expectedOut: "this is fine",
103+
expectedErr: "accidents happen",
104+
},
105+
{
106+
desc: "without tty/only stdout",
107+
tty: false,
108+
logOps: types.ContainerLogsOptions{
109+
ShowStdout: true,
110+
ShowStderr: false,
111+
},
112+
expectedOut: "this is fine",
113+
expectedErr: "",
114+
},
115+
{
116+
desc: "without tty/only stderr",
117+
tty: false,
118+
logOps: types.ContainerLogsOptions{
119+
ShowStdout: false,
120+
ShowStderr: true,
121+
},
122+
expectedOut: "",
123+
expectedErr: "accidents happen",
124+
},
125+
}
126+
127+
for _, tC := range testCases {
128+
tC := tC
129+
t.Run(tC.desc, func(t *testing.T) {
130+
t.Parallel()
131+
tty := tC.tty
132+
id := container.Run(ctx, t, client,
133+
container.WithCmd("sh", "-c", "echo -n this is fine; echo -n accidents happen >&2"),
134+
container.WithTty(tty),
135+
container.WithLogDriver(logDriver),
136+
)
137+
defer client.ContainerRemove(ctx, id, types.ContainerRemoveOptions{Force: true})
138+
139+
poll.WaitOn(t, container.IsStopped(ctx, client, id), poll.WithDelay(time.Millisecond*100))
140+
141+
logs, err := client.ContainerLogs(ctx, id, tC.logOps)
142+
assert.NilError(t, err)
143+
defer logs.Close()
144+
145+
var stdout, stderr bytes.Buffer
146+
if tty {
147+
// TTY, only one output stream
148+
_, err = io.Copy(&stdout, logs)
149+
} else {
150+
_, err = stdcopy.StdCopy(&stdout, &stderr, logs)
151+
}
152+
assert.NilError(t, err)
153+
154+
stdoutStr := stdout.String()
155+
156+
if tty && testEnv.OSType == "windows" {
157+
stdoutStr = stripEscapeCodes(t, stdoutStr)
158+
159+
// Special case for Windows Server 2019
160+
// Check only that the raw output stream contains strings
161+
// that were printed to container's stdout and stderr.
162+
// This is a workaround for the backspace being outputted in an unexpected place
163+
// which breaks the parsed output: https://github.com/moby/moby/issues/43710
164+
if strings.Contains(testEnv.DaemonInfo.OperatingSystem, "Windows Server Version 1809") {
165+
if tC.logOps.ShowStdout {
166+
assert.Check(t, cmp.Contains(stdout.String(), "this is fine"))
167+
assert.Check(t, cmp.Contains(stdout.String(), "accidents happen"))
168+
} else {
169+
assert.DeepEqual(t, stdoutStr, "")
170+
}
171+
return
172+
}
173+
174+
}
175+
176+
assert.DeepEqual(t, stdoutStr, tC.expectedOut)
177+
assert.DeepEqual(t, stderr.String(), tC.expectedErr)
178+
})
179+
}
180+
}
181+
182+
// This hack strips the escape codes that appear in the Windows TTY output and don't have
183+
// any effect on the text content.
184+
// This doesn't handle all escape sequences, only ones that were encountered during testing.
185+
func stripEscapeCodes(t *testing.T, input string) string {
186+
t.Logf("Stripping: %q\n", input)
187+
output, err := termtest.StripANSICommands(input)
188+
assert.NilError(t, err)
189+
return output
190+
}

0 commit comments

Comments
 (0)