Skip to content

integration: Add logs tests#43642

Closed
vvoland wants to merge 2 commits intomoby:masterfrom
vvoland:test-container-logs
Closed

integration: Add logs tests#43642
vvoland wants to merge 2 commits intomoby:masterfrom
vvoland:test-container-logs

Conversation

@vvoland
Copy link
Copy Markdown
Contributor

@vvoland vvoland commented May 25, 2022

Added integration tests for ContainerLogs.

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

- How to verify it
make BIND_DIR=. TEST_FILTER='TestLogs' test-integration

- A picture of a cute animal (not mandatory but encouraged)

@vvoland
Copy link
Copy Markdown
Contributor Author

vvoland commented May 25, 2022

The tests randomly fail. Sometimes they all pass successfully, but sometimes they fail. See below for example errors.
This doesn’t seem to me like a flakiness in the tests themselves, but maybe someone smarter can take a look? :)

Example errors 
=== RUN   TestLogsMuxed
=== RUN   TestLogsMuxed/stdout_and_stderr
=== RUN   TestLogsMuxed/only_stdout
=== RUN   TestLogsMuxed/only_stderr
    logs_test.go:100: assertion failed: error is not nil: error from daemon in stream: Error grabbing logs: invalid character 's' after object key
        
--- FAIL: TestLogsMuxed (0.75s)
    --- PASS: TestLogsMuxed/stdout_and_stderr (0.25s)
    --- PASS: TestLogsMuxed/only_stdout (0.25s)
    --- FAIL: TestLogsMuxed/only_stderr (0.24s)
=== RUN   TestLogsNotMuxed
=== RUN   TestLogsNotMuxed/stdout_and_stderr
=== RUN   TestLogsNotMuxed/only_stdout
=== RUN   TestLogsNotMuxed/only_stderr
--- PASS: TestLogsNotMuxed (0.79s)
    --- PASS: TestLogsNotMuxed/stdout_and_stderr (0.27s)
    --- PASS: TestLogsNotMuxed/only_stdout (0.24s)
    --- PASS: TestLogsNotMuxed/only_stderr (0.26s)
FAIL

=== Failed
=== FAIL: arm64.integration.container TestLogsMuxed/only_stderr (0.24s)
    logs_test.go:100: assertion failed: error is not nil: error from daemon in stream: Error grabbing logs: invalid character 's' after object key
        
    --- FAIL: TestLogsMuxed/only_stderr (0.24s)

=== FAIL: arm64.integration.container TestLogsMuxed (0.75s)

=== RUN   TestLogsMuxed
=== RUN   TestLogsMuxed/stdout_and_stderr
    logs_test.go:101: assertion failed:  (string) != this is fine (tC.expectedOut string)
=== RUN   TestLogsMuxed/only_stdout
=== RUN   TestLogsMuxed/only_stderr
    logs_test.go:100: assertion failed: error is not nil: error from daemon in stream: Error grabbing logs: invalid character '{' looking for beginning of object key string
        
--- FAIL: TestLogsMuxed (0.77s)
    --- FAIL: TestLogsMuxed/stdout_and_stderr (0.24s)
    --- PASS: TestLogsMuxed/only_stdout (0.26s)
    --- FAIL: TestLogsMuxed/only_stderr (0.25s)
=== RUN   TestLogsNotMuxed
=== RUN   TestLogsNotMuxed/stdout_and_stderr
=== RUN   TestLogsNotMuxed/only_stdout
=== RUN   TestLogsNotMuxed/only_stderr
--- PASS: TestLogsNotMuxed (0.72s)
    --- PASS: TestLogsNotMuxed/stdout_and_stderr (0.23s)
    --- PASS: TestLogsNotMuxed/only_stdout (0.24s)
    --- PASS: TestLogsNotMuxed/only_stderr (0.24s)
FAIL

=== Failed
=== FAIL: arm64.integration.container TestLogsMuxed/stdout_and_stderr (0.24s)
    logs_test.go:101: assertion failed:  (string) != this is fine (tC.expectedOut string)
    --- FAIL: TestLogsMuxed/stdout_and_stderr (0.24s)

=== FAIL: arm64.integration.container TestLogsMuxed/only_stderr (0.25s)
    logs_test.go:100: assertion failed: error is not nil: error from daemon in stream: Error grabbing logs: invalid character '{' looking for beginning of object key string
        
    --- FAIL: TestLogsMuxed/only_stderr (0.25s)

=== FAIL: arm64.integration.container TestLogsMuxed (0.77s)

=== RUN   TestLogsMuxed
=== RUN   TestLogsMuxed/stdout_and_stderr
=== RUN   TestLogsMuxed/only_stdout
=== RUN   TestLogsMuxed/only_stderr
    logs_test.go:100: assertion failed: error is not nil: error from daemon in stream: Error grabbing logs: invalid character 'l' after object key:value pair
        
--- FAIL: TestLogsMuxed (0.78s)
    --- PASS: TestLogsMuxed/stdout_and_stderr (0.26s)
    --- PASS: TestLogsMuxed/only_stdout (0.24s)
    --- FAIL: TestLogsMuxed/only_stderr (0.25s)
=== RUN   TestLogsNotMuxed
=== RUN   TestLogsNotMuxed/stdout_and_stderr
=== RUN   TestLogsNotMuxed/only_stdout
=== RUN   TestLogsNotMuxed/only_stderr
--- PASS: TestLogsNotMuxed (0.78s)
    --- PASS: TestLogsNotMuxed/stdout_and_stderr (0.26s)
    --- PASS: TestLogsNotMuxed/only_stdout (0.25s)
    --- PASS: TestLogsNotMuxed/only_stderr (0.25s)
FAIL

=== Failed
=== FAIL: arm64.integration.container TestLogsMuxed/only_stderr (0.25s)
    logs_test.go:100: assertion failed: error is not nil: error from daemon in stream: Error grabbing logs: invalid character 'l' after object key:value pair
        
    --- FAIL: TestLogsMuxed/only_stderr (0.25s)

=== FAIL: arm64.integration.container TestLogsMuxed (0.78s)

@vvoland
Copy link
Copy Markdown
Contributor Author

vvoland commented May 26, 2022 •
edited
Loading

Quick update: I looked at the json log file of the container created in a failed test and it seems that the file itself is corrupted:

# cat /var/lib/docker/containers/babb35c51972046a575a42c414cf2ad7d58d270b9594a251fb6d59234ccc021a/babb35c51972046a575a42c414cf2ad7d58d270b9594a251fb6d59234ccc021a-json.log
{"log":"accidents happ"st,"stre"std"std,rr","time":"2022-05-26T07:43:19.448576002Z"}
{"log":"accidents happ"st,"stre"std"std,rr","time":"2022-05-26T07:43:19.44857621Z"}

I also checked the tests on the v20.10.16 tag and they don't fail there. So it's probably some recent regression.
I'm doing a bisect to find what caused it.

@vvoland
Copy link
Copy Markdown
Contributor Author

vvoland commented May 26, 2022

First commit with the regression is ae5f664 (#43294)

The issue is that marshalFunc used in LogFile use a shared buffer. See:

With the mutex lock around WriteLogEntry got removed in the linked commit, the marshaller can be called for both stdout and stderr at the same time, which makes them write to the same buffer.

Allocating a buffer inside the marshaller call fixes the problem. But this is probably not a good idea because it would cause too many memory allocation? Maybe we should restore the critical section for the WriteLogEntry?

@corhere Could you please take a look?

@thaJeztah thaJeztah added this to the 22.06.0 milestone May 26, 2022
This was referenced May 26, 2022
Closed
Merged
@vvoland vvoland force-pushed the test-container-logs branch from 9d6f0b3 to 95efc0e Compare May 27, 2022 14:20
vvoland added 2 commits May 27, 2022 16:23
@vvoland
daemon/logger: Share buffers by sync.Pool
6f57be6 
Marshalling log messages by json-file and local drivers involved
serializing the message into a shared buffer. This caused a regression
resulting in log corruption with recent changes where Log may be called
from multiple goroutines at the same time.

Solution is to use a sync.Pool to manage the buffers used for the
serialization. Also removed the MarshalFunc, which the driver had to
expose to the LogFile so that it can marshal the message. This is now
moved entirely to the driver.

Signed-off-by: Paweł Gronowski <[email protected]>
@vvoland
integration: Add logs tests
cd41010 
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

Signed-off-by: Paweł Gronowski <[email protected]>
@vvoland vvoland force-pushed the test-container-logs branch from 95efc0e to cd41010 Compare May 27, 2022 14:23
@vvoland vvoland closed this May 31, 2022
@vvoland vvoland mentioned this pull request May 31, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

area/logging area/testing status/2-code-review

Projects

None yet

Milestone

23.0.0

Development

Successfully merging this pull request may close these issues.

2 participants

@vvoland @thaJeztah