Skip to content

daemon/logger: Share buffers by sync.Pool#43650

Merged
thaJeztah merged 1 commit intomoby:masterfrom
vvoland:fix-logs-regression
May 28, 2022
Merged

daemon/logger: Share buffers by sync.Pool#43650
thaJeztah merged 1 commit intomoby:masterfrom
vvoland:fix-logs-regression

Conversation

@vvoland
Copy link
Copy Markdown
Contributor

@vvoland vvoland commented May 27, 2022

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.

- What I did
FIx the log regression described in #43647

- How I did it
Use sync.Pool for sharing the buffers between multiple goroutines.
Move execution of marshal code up to the driver

- How to verify it
docker logs -f $(docker run -d busybox sh -c 'echo stdout; echo stderr >&2')
Run tests from #43642

- Description for the changelog
Fix log corruption

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

obraz

writer: writer,
tag: tag,
extra: extra,
buffersPool: makePool(),
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wondering if it would make sense to make the pool global for the whole driver instead of per the logger instance?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

writeLen := protoSize + (2 * encodeBinaryLen) // + len(messageDelimiter)

buf := *buffer
if writeLen > cap(buf) {
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed the len(buf) to cap(buf) to stop considering buffers with smaller len, but enough capacity, as too small for the message.
I think the whole logic tries to reimplement what the bytes.Buffer does... I wonder if this should be rewritten to use bytes.Buffer instead. However it would be a bit hacky, because it would require to write directly to the byte slice returned by buffer.Bytes() and then return the buffer.Bytes()[:writeLen] to the caller.
Also I don't really like *[]byte in sync.Pool, but maybe it's fine?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed the len(buf) to cap(buf) to stop considering buffers with smaller len, but enough capacity, as too small for the message.

👍 Good catch!

I think the whole logic tries to reimplement what the bytes.Buffer does... I wonder if this should be rewritten to use bytes.Buffer instead. However it would be a bit hacky, because it would require to write directly to the byte slice returned by buffer.Bytes() and then return the buffer.Bytes()[:writeLen] to the caller.

I came to the same conclusion as well; trying to use a bytes.Buffer would be too hacky to be worth it.

Also I don't really like *[]byte in sync.Pool, but maybe it's fine?

I don't like it either, but it is the most performant way to use a Pool. As mentioned in the example in the godoc:

		// The Pool's New function should generally only return pointer
		// types, since a pointer can be put into the return interface
		// value without an allocation

A slice value is wider than a pointer so putting it directly into the pool would cost the very heap allocation we wanted to avoid. Getting and putting *[]byte values ensures that the heap allocation is only paid once, when the slice is first allocated, no matter how many times it is reused.

Comment thread daemon/logger/local/local.go Outdated
}
return &driver{
logfile: lf,
buffersPool: sync.Pool{New: func() any {
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same as in the jsonfilelog. Maybe the pool could be global?

// Log converts logger.Message to jsonlog.JSONLog and serializes it to file.
func (l *JSONFileLogger) Log(msg *logger.Message) error {
return l.writer.WriteLogEntry(msg)
defer logger.PutMessage(msg)
Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wanted to move the PutMessage up to be the responsibility of the caller. But a lot of tests rely on this being done inside Log, so left it to keep the changes small. Maybe could be done in a follow up?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤔 I'm of two minds on this. One one hand, there are more logging drivers than consumers of the logger.Logger interface so pushing responsibility of putting the message back into the pool over to the consumer would be DRYer. On the other hand, the existing architecture has "move" semantics, which gives the log drivers great flexibility in handling incoming log messages as the message's lifetime does not need to be bounded by the Log call. Given that forgetting to put the message back into the pool would only result in a performance regression, not a memory leak (the struct will be GC'ed like normal) I think the flexibility afforded to the drivers by the move semantics is worth the cost of keeping the drivers responsible for returning the messages back to the pool when they're done.

@vvoland vvoland force-pushed the fix-logs-regression branch from 506ba72 to cb72814 Compare May 27, 2022 14:26
Comment thread daemon/logger/jsonfilelog/jsonfilelog.go Outdated
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
Copy link
Copy Markdown
Contributor Author

vvoland commented May 27, 2022

I rebased the PR which adds the tests for ContainerLogs on this branch: #43642
The tests still seem to fail, but only on Windows. It's also interesting that they seem to fail predictably (only in cases where stdout is mixed with stderr) and the output they produce is broken in a different way:

=== Failed
=== FAIL: github.com/docker/docker/integration/container TestLogsNotMuxed/stdout_and_stderr (2.35s)
    logs_test.go:166: assertion failed: 25lthis is fine�25h25laccidents happen �25h (string) != this is fineaccidents happen (tC.expectedOutput string)
    --- FAIL: TestLogsNotMuxed/stdout_and_stderr (2.35s)

=== FAIL: github.com/docker/docker/integration/container TestLogsNotMuxed/only_stdout (2.40s)
    logs_test.go:166: assertion failed: 25lthis is fine�25h25laccidents happen �25h (string) != this is fineaccidents happen (tC.expectedOutput string)
    --- FAIL: TestLogsNotMuxed/only_stdout (2.40s)
=== Failed
=== FAIL: github.com/docker/docker/integration/container TestLogsNotMuxed/stdout_and_stderr (2.18s)
    logs_test.go:166: assertion failed: this is fine25haccidents happen (string) != this is fineaccidents happen (tC.expectedOutput string)
    --- FAIL: TestLogsNotMuxed/stdout_and_stderr (2.18s)

=== FAIL: github.com/docker/docker/integration/container TestLogsNotMuxed/only_stdout (1.60s)
    logs_test.go:166: assertion failed: this is fine25haccidents happen (string) != this is fineaccidents happen (tC.expectedOutput string)
    --- FAIL: TestLogsNotMuxed/only_stdout (1.60s)

The output doesn't match, because there are some garbage strings between the lines (25h and 25l).
This seems like some control characters being captured. Possibly "Text Cursor Enable Mode Show" and "Text Cursor Enable Mode Hide" - https://docs.microsoft.com/en-us/windows/console/console-virtual-terminal-sequences#cursor-visibility.
So probably the test failure is not really due to the logs corruption still happening.

@vvoland vvoland force-pushed the fix-logs-regression branch from cb72814 to 7493342 Compare May 27, 2022 15:29
Copy link
Copy Markdown
Contributor

@corhere corhere left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM! :shipit: I see nothing that couldn't be addressed in a follow-up PR, my review comments included.

writer: writer,
tag: tag,
extra: extra,
buffersPool: makePool(),
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

// Log converts logger.Message to jsonlog.JSONLog and serializes it to file.
func (l *JSONFileLogger) Log(msg *logger.Message) error {
return l.writer.WriteLogEntry(msg)
defer logger.PutMessage(msg)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤔 I'm of two minds on this. One one hand, there are more logging drivers than consumers of the logger.Logger interface so pushing responsibility of putting the message back into the pool over to the consumer would be DRYer. On the other hand, the existing architecture has "move" semantics, which gives the log drivers great flexibility in handling incoming log messages as the message's lifetime does not need to be bounded by the Log call. Given that forgetting to put the message back into the pool would only result in a performance regression, not a memory leak (the struct will be GC'ed like normal) I think the flexibility afforded to the drivers by the move semantics is worth the cost of keeping the drivers responsible for returning the messages back to the pool when they're done.

writeLen := protoSize + (2 * encodeBinaryLen) // + len(messageDelimiter)

buf := *buffer
if writeLen > cap(buf) {
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed the len(buf) to cap(buf) to stop considering buffers with smaller len, but enough capacity, as too small for the message.

👍 Good catch!

I think the whole logic tries to reimplement what the bytes.Buffer does... I wonder if this should be rewritten to use bytes.Buffer instead. However it would be a bit hacky, because it would require to write directly to the byte slice returned by buffer.Bytes() and then return the buffer.Bytes()[:writeLen] to the caller.

I came to the same conclusion as well; trying to use a bytes.Buffer would be too hacky to be worth it.

Also I don't really like *[]byte in sync.Pool, but maybe it's fine?

I don't like it either, but it is the most performant way to use a Pool. As mentioned in the example in the godoc:

		// The Pool's New function should generally only return pointer
		// types, since a pointer can be put into the return interface
		// value without an allocation

A slice value is wider than a pointer so putting it directly into the pool would cost the very heap allocation we wanted to avoid. Getting and putting *[]byte values ensures that the heap allocation is only paid once, when the slice is first allocated, no matter how many times it is reused.


buf := *buffer
if writeLen > cap(buf) {
buf = make([]byte, writeLen)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
buf = make([]byte, writeLen)
buf = make([]byte, 1 << (bits.Len(writeLen) + 1))

If we need to pay the cost to reallocate the buffer, we should try to make it big enough to be reusable. Round up to the next power of two?
(Reusing slices with good performance is tricky to get right.)


func (d *driver) Log(msg *logger.Message) error {
return d.logfile.WriteLogEntry(msg)
defer logger.PutMessage(msg)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Optimization opportunity: msg can be returned to the pool as soon as marshal returns, rather than deferring until after WriteLogEntry. Be mindful of that timestamp, though!

// Every buffer will have to store the same constant json structure and the message
// len(`{"log":"","stream:"stdout","time":"2000-01-01T00:00:00.000000000Z"}\n`) = 68
// So let's start with a buffer bigger than this
const initialBufSize = 128
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
const initialBufSize = 128
const initialBufSize = 256

60 chars for the log message after overhead seems a touch small to me. It wouldn't fit a full 80-column line of text without resizing. How about sizing it enough for an SMS?

@thaJeztah
Copy link
Copy Markdown
Member

FWIW; running a build of this PR on the internal test-pipeline of Docker Desktop; just kicked of a new run, but one test was failing with this: the Unrecognized input header: 54\n stood out to me (wondering if similar to the Windows failures mentioned above). Anyway, thought I'd post it here as well, in case it's indeed related (I'm not familiar with all tests in that pipeline, so I could be completely on the wrong foot 😅)

Details
STEP: Execute '/usr/local/bin/docker rm -f ipv6-intra-container' 05/27/22 17:11:39.534
------------------------------
• [FAILED] [24.000 seconds]
[network] IPv6
/home/user/go/src/github.com/docker/pinata/tests/POS_network_test.go:31
  [It] [!linux] intra-container (docker/for-win#6206)
  /home/user/go/src/github.com/docker/pinata/tests/POS_network_test.go:32

  Begin Captured GinkgoWriter Output >>
    STEP: Execute '/usr/local/bin/docker pull nginx:1.19.6-alpine' 05/27/22 17:11:16.631
    STEP: Execute '/usr/local/bin/docker run -d --name ipv6-intra-container --net host -v /home/docker/jenkins/workspace/desktop/desktop-test-single-pr-linux/tests/tmp/ipv6-intra-container-2532572292/default.conf:/etc/nginx/conf.d/default.conf -v /home/docker/jenkins/workspace/desktop/desktop-test-single-pr-linux/tests/tmp/ipv6-intra-container-2532572292:/usr/share/nginx/html nginx:1.19.6-alpine' 05/27/22 17:11:26.592
    STEP: Execute '/usr/local/bin/docker pull nginx:1.19.6-alpine' 05/27/22 17:11:29.534
    STEP: Execute '/usr/local/bin/docker run --rm --pid=host --privileged justincormack/nsenter1 /bin/sh -c wget -O /tmp/test.html http://[::1]:8080/test.html && cat /tmp/test.html' 05/27/22 17:11:31.264
    STEP: Execute '/usr/local/bin/docker logs ipv6-intra-container' 05/27/22 17:11:39.428
    STEP: e2e tests failed, running FailHandler: Unexpected error:
        <*multierror.Error | 0xc0004d8a60>: {
            Errors: [
                <exec.CodeExitError>{
                    Err: <*errors.errorString | 0xc000c30170>{
                        s: "error running [docker logs ipv6-intra-container]:\nCommand stdout:\n\nstderr:\nUnrecognized input header: 54\n\nerror:\nexit status 1",
                    },
                    Code: 1,
                },
            ],
            ErrorFormat: nil,
        }
        1 error occurred:
        	* error running [docker logs ipv6-intra-container]:
        Command stdout:
        
        stderr:
        Unrecognized input header: 54
        
        error:
        exit status 1
        
        
    occurred 05/27/22 17:11:39.524
    STEP: Execute '/usr/local/bin/docker rm -f ipv6-intra-container' 05/27/22 17:11:39.534

@corhere
Copy link
Copy Markdown
Contributor

corhere commented May 27, 2022

@thaJeztah the error message Unrecognized input header: 54 probably originates from pkg/stdcopy:

moby/pkg/stdcopy/stdcopy.go

Lines 137 to 138 in 69adaa8

default:
return 0, fmt.Errorf("Unrecognized input header: %d", buf[stdWriterFdIndex])

The stdcopy encoder's constructor, stdcopy.NewStdWriter, takes the input header value as an argument. And that argument is specified as a constant in all call sites. Outside of memory corruption, I don't see a way for a log driver to corrupt the stdcopy log stream like that.

@thaJeztah
Copy link
Copy Markdown
Member

@thaJeztah the error message Unrecognized input header: 54 probably originates from pkg/stdcopy:

Yes, it's odd. Got another one of those Unrecognized input header failures; so "something" may still be happening (no clue what)

error running [docker service logs service_logs]:\nCommand stdout:\n\nstderr:\nUnrecognized input header: 97\n\nerror:\nexit status 1

I'm not very familiar with the tests in that repository, so I'll do some more digging as well ; this is roughly what the logs of that specific tests shows it's doing

docker service create --detach=false --name service_logs alpine:3.14 /bin/sh -c echo Hello && sleep 100
docker service logs service_logs

I do notice that

  • this failure is with docker service logs (not docker logs)
  • the /bin/sh -c echo Hello && sleep 100 looks potentially fishy (there's no quotes around echo Hello && sleep 100, but this could be how it's printed)
  • If the 97 comes from something else, 97 could be lowercase a (ASCII)

trying to run it manually;

docker service create --detach=false --name service_logs alpine:3.14 /bin/sh -c 'echo Hello && sleep 100'
oymfv2ajy6mj9lkyidtatihyh
overall progress: 1 out of 1 tasks
1/1: running   [==================================================>]
verify: Service converged

docker service logs service_logs
service_logs.1.zegk07hwjj5a@docker-desktop    | Hello

Copy link
Copy Markdown
Member

@thaJeztah thaJeztah left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

let's get this one in, and do further changes as a follow-up 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants