Improve logging of long log lines #22982

nalind · 2016-05-25T16:05:26Z

- What I did
Worked up a proposal for addressing the memory usage in #18057.

- How I did it
Switch from using a reader from the bufio package to doing the buffering ourselves, and tracking whether or not we read the end of a line. That information is now passed to log drivers so that they can do the right thing when they're sending entries to clients that call a container's logs handler.

- How to verify it
Run docker run -d busybox /bin/sh -c 'while true ; do echo -n "aaasd"; done' and observe usage either with top using memory sorting, or with DEBUG set, dockerd listening on a TCP port, and watch go tool pprof --text /usr/bin/docker-current http://$hostname:$port/debug/pprof/heap

- Description for the changelog
Improve logging of long log lines

thaJeztah · 2016-05-25T19:00:57Z

ping @unclejack perhaps you can have a look as well?

nalind · 2016-05-25T20:20:42Z

Revised to subject each call to the log driver's Log() method to a check if the copier's been Close()d, to make TestCopierSlow() pass.

nalind · 2016-05-31T20:36:12Z

The journald reader was keying off of the "partial" flag incorrectly, fixed.

unclejack · 2016-06-04T21:49:37Z

@thaJeztah Thanks!

@nalind Can you add a benchmark to benchmark the numbers before and after, please?

nalind · 2016-06-06T18:17:22Z

Sure. The larger message sizes are unlikely, so I tweaked the maximum size down to 16k to get better results for smaller sizes. Before:

Size	Ops	Speed	Memory	Allocs
1K	10000	141169 ns/op	16351 B/op	39 allocs/op
2K	20000	98573 ns/op	26577 B/op	39 allocs/op
4K	10000	105285 ns/op	47058 B/op	39 allocs/op
8K	10000	138987 ns/op	129302 B/op	59 allocs/op
16K	10000	171856 ns/op	294591 B/op	100 allocs/op
32K	5000	307481 ns/op	624206 B/op	152 allocs/op
64K	2000	582192 ns/op	1283438 B/op	245 allocs/op
128K	1000	1212861 ns/op	2601906 B/op	422 allocs/op
256K	1000	2267578 ns/op	5238848 B/op	766 allocs/op

After:

Size	Ops	Speed	Change	Memory	Change	Allocs	Change
1K	10000	101876 ns/op	-28%	17664 B/op	+8%	20 allocs/op	-49%
2K	10000	100582 ns/op	+2%	17664 B/op	-34%	20 allocs/op	-49%
4K	10000	103867 ns/op	-2%	17664 B/op	-63%	20 allocs/op	-49%
8K	10000	117245 ns/op	-16%	17664 B/op	-87%	20 allocs/op	-67%
16K	10000	120569 ns/op	-30%	17664 B/op	-95%	20 allocs/op	-80%
32K	5000	236115 ns/op	-24%	17664 B/op	-98%	20 allocs/op	-87%
64K	3000	434702 ns/op	-26%	17664 B/op	-99%	20 allocs/op	-92%
128K	2000	839920 ns/op	-31%	17664 B/op	-99%	20 allocs/op	-96%
256K	1000	1611549 ns/op	-29%	17664 B/op	-99%	20 allocs/op	-98%

LK4D4 · 2016-06-07T16:18:00Z

daemon/logger/copier.go

+			// Break up the data that we've buffered up into lines, and log each in turn.
+			p := 0
+			for q := bytes.Index(buf[p:n], []byte{'\n'}); q >= 0; q = bytes.Index(buf[p:n], []byte{'\n'}) {
+				msg.Line = buf[p : p+q]


I'm a little not comfortable with passing part of a slice to Log. I'm not sure about current loggers if they can stash messages and send them later, but that would lead to messages corruption.

We could allocate msg.Line and copy the slice into it every time, at the cost of a hit to speed and memory usage. Some of the log driver internals are complicated enough that I can't say for sure that we don't need to worry about that.

Okay, dug into it.

awslogs buffers Message structures on a channel and processes multiple Messages in batches in a separate goroutine. It could be tripped up by using slices.

etwlogs uses the slice to build a string using fmt.Sprintf, so it'd be fine.

fluentd copies the byte slice into a string immediately, so it'd be fine.

gcplogs copies the byte slice into a string immediately, so it'd be fine.

gelf copies the byte slice into a string immediately, so it'd be fine.

journald copies the byte slice into a string immediately, so it'd be fine.

jsonfilelog marshals the byte slice into a JSON blob immediately, so it'd be fine.

splunk copies the byte slice into a string immediately, so it'd be fine.

syslog copies the byte slice into a string immediately, so it'd be fine.

I'm tempted to make awslogs copy the data, and let the rest use slices, because otherwise we're copying the log data twice for most log drivers (once in Copier, and again in the log driver).

I'm ok with this, let's document this also.

I've added notes around the definition of Message and the new CopyMessage function, and a very short note in the awslog driver where it calls CopyMessage(). @LK4D4 is this what you were thinking, or are there other places this should be called out?

LK4D4 · 2016-06-07T16:25:13Z

I like it very much. thanks @nalind
Design is good for me. @unclejack feel free to move to code-review if ok for you as well.

Add a benchmark for measuring how the logger.Copier implementation handles logged lines of sizes ranging up from 64 bytes to 256KB. Signed-off-by: Nalin Dahyabhai <nalin@redhat.com>

AkihiroSuda · 2016-06-14T09:21:51Z

daemon/logger/journald/read.go

 //{
 //	int rc;
 //	*msg = NULL;
 //	*length = 0;
+//	rc = sd_journal_get_data(j, "CONTAINER_PARTIAL_MESSAGE", (const void **) msg, length);
+//	*partial = ((rc == 0) && (*length == 30) && (memcmp(*msg, "CONTAINER_PARTIAL_MESSAGE=true", 30) == 0));


I feel strlen("CONTAINER_PARTIAL_MESSAGE=true") is better than the magic number 30

Okay, changing that.

This change updates how we handle long lines of output from the container. The previous logic used a bufio reader to read entire lines of output from the container through an intermediate BytesPipe, and that allowed the container to cause dockerd to consume an unconstrained amount of memory as it attempted to collect a whole line of output, by outputting data without newlines. To avoid that, we replace the bufio reader with our own buffering scheme that handles log lines up to 16k in length, breaking up anything longer than that into multiple chunks. If we can dispense with noting this detail properly at the end of output, we can switch from using ReadBytes() to using ReadLine() instead. We add a field ("Partial") to the log message structure to flag when we pass data to the log driver that did not end with a newline. The Line member of Message structures that we pass to log drivers is now a slice into data which can be overwritten between calls to the log driver's Log() method, so drivers which batch up Messages before processing them need to take additional care: we add a function (logger.CopyMessage()) that can be used to create a deep copy of a Message structure, and modify the awslogs driver to use it. We update the jsonfile log driver to append a "\n" to the data that it logs to disk only when the Partial flag is false (it previously did so unconditionally), to make its "logs" output correctly reproduce the data as we received it. Likewise, we modify the journald log driver to add a data field with value CONTAINER_PARTIAL_MESSAGE=true to entries when the Partial flag is true, and update its "logs" reader to refrain from appending a "\n" to the data that it retrieves if it does not see this field/value pair (it also previously did this unconditionally). Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)

runcom · 2016-06-22T15:00:19Z

LGTM ping @LK4D4 @cpuguy83 @unclejack

runcom · 2016-07-01T22:24:56Z

ping anyone :)

LK4D4 · 2016-07-01T22:40:32Z

LGTM

LK4D4 · 2016-07-01T22:41:21Z

Let's merge it after 1.12 to not occasionally bring additional work with cherry-picks merging in release branch.

Upstream reference: moby#22982 This change updates how we handle long lines of output from the container. The previous logic used a bufio reader to read entire lines of output from the container through an intermediate BytesPipe, and that allowed the container to cause dockerd to consume an unconstrained amount of memory as it attempted to collect a whole line of output, by outputting data without newlines. To avoid that, we replace the bufio reader with our own buffering scheme that handles log lines up to 16k in length, breaking up anything longer than that into multiple chunks. If we can dispense with noting this detail properly at the end of output, we can switch from using ReadBytes() to using ReadLine() instead. We add a field ("Partial") to the log message structure to flag when we pass data to the log driver that did not end with a newline. The Line member of Message structures that we pass to log drivers is now a slice into data which can be overwritten between calls to the log driver's Log() method, so drivers which batch up Messages before processing them need to take additional care: we add a function (logger.CopyMessage()) that can be used to create a deep copy of a Message structure, and modify the awslogs driver to use it. We update the jsonfile log driver to append a "\n" to the data that it logs to disk only when the Partial flag is false (it previously did so unconditionally), to make its "logs" output correctly reproduce the data as we received it. Likewise, we modify the journald log driver to add a data field with value CONTAINER_PARTIAL_MESSAGE=true to entries when the Partial flag is true, and update its "logs" reader to refrain from appending a "\n" to the data that it retrieves if it does not see this field/value pair (it also previously did this unconditionally). Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind) Signed-off-by: Antonio Murdaca <runcom@redhat.com>

pmoust · 2016-10-25T15:03:16Z

@thaJeztah I take it this did not land in 1.12.x ? :(

Upstream reference: moby#22982 This change updates how we handle long lines of output from the container. The previous logic used a bufio reader to read entire lines of output from the container through an intermediate BytesPipe, and that allowed the container to cause dockerd to consume an unconstrained amount of memory as it attempted to collect a whole line of output, by outputting data without newlines. To avoid that, we replace the bufio reader with our own buffering scheme that handles log lines up to 16k in length, breaking up anything longer than that into multiple chunks. If we can dispense with noting this detail properly at the end of output, we can switch from using ReadBytes() to using ReadLine() instead. We add a field ("Partial") to the log message structure to flag when we pass data to the log driver that did not end with a newline. The Line member of Message structures that we pass to log drivers is now a slice into data which can be overwritten between calls to the log driver's Log() method, so drivers which batch up Messages before processing them need to take additional care: we add a function (logger.CopyMessage()) that can be used to create a deep copy of a Message structure, and modify the awslogs driver to use it. We update the jsonfile log driver to append a "\n" to the data that it logs to disk only when the Partial flag is false (it previously did so unconditionally), to make its "logs" output correctly reproduce the data as we received it. Likewise, we modify the journald log driver to add a data field with value CONTAINER_PARTIAL_MESSAGE=true to entries when the Partial flag is true, and update its "logs" reader to refrain from appending a "\n" to the data that it retrieves if it does not see this field/value pair (it also previously did this unconditionally). Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind) Signed-off-by: Antonio Murdaca <runcom@redhat.com>

jpetazzo · 2016-10-31T23:50:25Z

An easy way to reproduce the issue really fast: docker run -d alpine cat /dev/zero

zoobab · 2016-11-02T09:19:11Z

Please consider backporting to all your releases (1.9.x, 1.10.x, 1.11.x, 1.12.x) that are seriously affected by this bug.

Upstream reference: moby#22982 This change updates how we handle long lines of output from the container. The previous logic used a bufio reader to read entire lines of output from the container through an intermediate BytesPipe, and that allowed the container to cause dockerd to consume an unconstrained amount of memory as it attempted to collect a whole line of output, by outputting data without newlines. To avoid that, we replace the bufio reader with our own buffering scheme that handles log lines up to 16k in length, breaking up anything longer than that into multiple chunks. If we can dispense with noting this detail properly at the end of output, we can switch from using ReadBytes() to using ReadLine() instead. We add a field ("Partial") to the log message structure to flag when we pass data to the log driver that did not end with a newline. The Line member of Message structures that we pass to log drivers is now a slice into data which can be overwritten between calls to the log driver's Log() method, so drivers which batch up Messages before processing them need to take additional care: we add a function (logger.CopyMessage()) that can be used to create a deep copy of a Message structure, and modify the awslogs driver to use it. We update the jsonfile log driver to append a "\n" to the data that it logs to disk only when the Partial flag is false (it previously did so unconditionally), to make its "logs" output correctly reproduce the data as we received it. Likewise, we modify the journald log driver to add a data field with value CONTAINER_PARTIAL_MESSAGE=true to entries when the Partial flag is true, and update its "logs" reader to refrain from appending a "\n" to the data that it retrieves if it does not see this field/value pair (it also previously did this unconditionally). Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind) Signed-off-by: Antonio Murdaca <runcom@redhat.com>

This change updates how we handle long lines of output from the container. The previous logic used a bufio reader to read entire lines of output from the container through an intermediate BytesPipe, and that allowed the container to cause dockerd to consume an unconstrained amount of memory as it attempted to collect a whole line of output, by outputting data without newlines. To avoid that, we replace the bufio reader with our own buffering scheme that handles log lines up to 16k in length, breaking up anything longer than that into multiple chunks. If we can dispense with noting this detail properly at the end of output, we can switch from using ReadBytes() to using ReadLine() instead. We add a field ("Partial") to the log message structure to flag when we pass data to the log driver that did not end with a newline. The Line member of Message structures that we pass to log drivers is now a slice into data which can be overwritten between calls to the log driver's Log() method, so drivers which batch up Messages before processing them need to take additional care: we add a function (logger.CopyMessage()) that can be used to create a deep copy of a Message structure, and modify the awslogs driver to use it. We update the jsonfile log driver to append a "\n" to the data that it logs to disk only when the Partial flag is false (it previously did so unconditionally), to make its "logs" output correctly reproduce the data as we received it. Likewise, we modify the journald log driver to add a data field with value CONTAINER_PARTIAL_MESSAGE=true to entries when the Partial flag is true, and update its "logs" reader to refrain from appending a "\n" to the data that it retrieves if it does not see this field/value pair (it also previously did this unconditionally). fix http://code.huawei.com/docker/docker/issues/324 upsteam issue: moby#18057 fix DTS2017062307255 cherry-pick from: moby#22982 conflicts: daemon/logger/copier.go daemon/logger/journald/read.go daemon/logger/logger.go Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind) Signed-off-by: Lei Jitang <leijitang@huawei.com>

Add a benchmark for measuring how the logger.Copier implementation handles logged lines of sizes ranging up from 64 bytes to 256KB. cherry-pick from: moby#22982 conflicts: daemon/logger/copier_test.go Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> Signed-off-by: Lei Jitang <leijitang@huawei.com>

GordonTheTurtle added the status/0-triage label May 25, 2016

cpuguy83 added status/1-design-review and removed status/0-triage labels May 25, 2016

nalind force-pushed the log-newlines branch 2 times, most recently from 418dbb3 to 3954c88 Compare May 25, 2016 18:25

nalind force-pushed the log-newlines branch from 3954c88 to fa22281 Compare May 25, 2016 20:20

nalind force-pushed the log-newlines branch from fa22281 to 20e8f2e Compare May 31, 2016 20:35

nalind force-pushed the log-newlines branch 2 times, most recently from 7d17215 to 4f506c1 Compare June 2, 2016 14:41

nalind force-pushed the log-newlines branch 2 times, most recently from fd9c303 to d166069 Compare June 6, 2016 18:17

LK4D4 reviewed Jun 7, 2016
View reviewed changes

unclejack added status/2-code-review and removed status/1-design-review labels Jun 9, 2016

Add a benchmark for logger.Copier

af439c7

Add a benchmark for measuring how the logger.Copier implementation handles logged lines of sizes ranging up from 64 bytes to 256KB. Signed-off-by: Nalin Dahyabhai <nalin@redhat.com>

AkihiroSuda reviewed Jun 14, 2016
View reviewed changes

nalind force-pushed the log-newlines branch from d166069 to 513ec73 Compare June 14, 2016 18:12

LK4D4 added the status/4-merge label Jul 1, 2016

cpuguy83 mentioned this pull request Aug 22, 2016

--log-opt max-size does not limit non-breaking log output #25930

Closed

jonathanperret mentioned this pull request Sep 2, 2016

Error response from daemon: Cannot start container (fork/exec /usr/sbin/iptables: cannot allocate memory) #8539

Closed

tonistiigi modified the milestones: 1.12.2, 1.13.0 Sep 2, 2016

thaJeztah modified the milestones: 1.13.0, 1.12.2 Oct 24, 2016

cpuguy83 mentioned this pull request Dec 9, 2016

Implement optional ring buffer for container logs #28762

Merged

nickperry mentioned this pull request Sep 13, 2017

[e2e failure] Cluster level logging implemented by Stackdriver should ingest logs kubernetes/kubernetes#52433

Closed

This was referenced Sep 13, 2017

Supporting docker log splitting in Kubernetes logging integrations kubernetes/kubernetes#52444

Closed

Make the log lines splitting configurable #34855

Open

thaJeztah added the area/logging label Nov 22, 2019

charliefoxtwo mentioned this pull request Dec 5, 2019

Log lines longer than 16384 characters are improperly joined portainer/portainer#3445

Closed

slim-bean mentioned this pull request Jul 1, 2020

Reconstruct split docker log lines in Promtail grafana/loki#2281

Closed

smullenrga mentioned this pull request Nov 15, 2021

AWX RuntimeError resulting in loss of worker task logs and true outcome ansible/awx#9961

Closed

andoks mentioned this pull request Mar 19, 2024

loki-docker-driver does not support reconstructing docker logs split by docker in 16kB chunks grafana/loki#12262

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve logging of long log lines #22982

Improve logging of long log lines #22982

nalind commented May 25, 2016

thaJeztah commented May 25, 2016

nalind commented May 25, 2016

nalind commented May 31, 2016

unclejack commented Jun 4, 2016

nalind commented Jun 6, 2016

LK4D4 Jun 7, 2016

nalind Jun 7, 2016

nalind Jun 9, 2016

LK4D4 Jun 13, 2016

nalind Jun 14, 2016

LK4D4 commented Jun 7, 2016 •

edited

AkihiroSuda Jun 14, 2016

nalind Jun 14, 2016

runcom commented Jun 22, 2016

runcom commented Jul 1, 2016

LK4D4 commented Jul 1, 2016

LK4D4 commented Jul 1, 2016

pmoust commented Oct 25, 2016

jpetazzo commented Oct 31, 2016

zoobab commented Nov 2, 2016

Improve logging of long log lines #22982

Improve logging of long log lines #22982

Conversation

nalind commented May 25, 2016

thaJeztah commented May 25, 2016

nalind commented May 25, 2016

nalind commented May 31, 2016

unclejack commented Jun 4, 2016

nalind commented Jun 6, 2016

LK4D4 Jun 7, 2016

Choose a reason for hiding this comment

nalind Jun 7, 2016

Choose a reason for hiding this comment

nalind Jun 9, 2016

Choose a reason for hiding this comment

LK4D4 Jun 13, 2016

Choose a reason for hiding this comment

nalind Jun 14, 2016

Choose a reason for hiding this comment

LK4D4 commented Jun 7, 2016 • edited

AkihiroSuda Jun 14, 2016

Choose a reason for hiding this comment

nalind Jun 14, 2016

Choose a reason for hiding this comment

runcom commented Jun 22, 2016

runcom commented Jul 1, 2016

LK4D4 commented Jul 1, 2016

LK4D4 commented Jul 1, 2016

pmoust commented Oct 25, 2016

jpetazzo commented Oct 31, 2016

zoobab commented Nov 2, 2016

LK4D4 commented Jun 7, 2016 •

edited