Add log max size #761

Random-Liu · 2018-05-05T06:13:22Z

Fixes #283.

This PR added a configuration max_container_log_size for configuring max container log line size. Log line longer than the size limit will be split into multiple lines.

@yujuhong

thaJeztah · 2018-05-05T07:05:22Z

I know user configurable buffer size has been a hot topic on dockerd; configuring a huge size can easily lead to memory issues if there's congestion; is that an issue here as well?

/cc @cpuguy83

k8s-ci-robot · 2018-05-05T07:05:23Z

@thaJeztah: GitHub didn't allow me to request PR reviews from the following users: cpuguy83.

Note that only containerd members and repo collaborators can review this PR, and authors cannot review their own PRs.

Details

In response to this:

I know user configurable buffer size has been a hot topic on dockerd; configuring a huge size can easily lead to memory issues if there's congestion; is that an issue here as well?

/cc @cpuguy83

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

Random-Liu · 2018-05-07T01:35:19Z

@thaJeztah The read buffer size is 4096 fixed for now. If there is no long line, the memory usage will be 4096 (fixed read buffer size); if there is, the memory usage grows once for the log line.

Since docker is a user facing tool, I agree that we may not want user to care about and configure this directly.

However, to Kubernetes, containerd and cri are just building block. And the configuration is just for system admin. They should be able to configure the behavior according to their system environment. For example, in GCP, stackdriver has a 100kb log length limit, we want the log generated by container runtime to match that limit.

Another solution of this is to do this in fluentd. We've thought about it, and https://github.com/fluent-plugins-nursery/fluent-plugin-concat can probably be used. However, since not everyone is using fluentd, we think that it is still better to make this configurable in container runtime instead.

mikebrow

See comments.

mikebrow · 2018-05-07T19:33:55Z

docs/config.md


+  # max_container_log_size is the maximum log line size in bytes for a container.
+  # Log line longer than the limit will be split into multiple lines. Negative
+  # value means no limit.


Wrt. negative value .. we might want to be more explicit about which negative value has no limit.. say -1

mikebrow · 2018-05-07T19:40:01Z

integration/container_log_test.go

+	t.Log("Create a container with log path")
+	defaultMaxSize := config.DefaultConfig().MaxContainerLogSize
+	shortLineCmd := fmt.Sprintf("i=0; while [ $i -lt %d ]; do printf %s; i=$((i+1)); done", defaultMaxSize-1, "a")
+	longLineCmd := fmt.Sprintf("i=0; while [ $i -lt %d ]; do printf %s; i=$((i+1)); done", defaultMaxSize+1, "b")


one short one long and one == to max?

I think if max is negative this test won't work right?

Maybe run the bucket through with a few different sizes?

Will get this from Status function in CRI.

mikebrow · 2018-05-07T19:42:58Z

pkg/config/config.go

 	EnableTLSStreaming bool `toml:"enable_tls_streaming" json:"enableTLSStreaming"`
+	// MaxContainerLogSize is the maximum log line size in bytes for a container.
+	// Log line longer than the limit will be split into multiple lines. Negative
+	// value means no limit.


see above comment on negative value..

Let's make the description in the comment more accurate. This is not user facing anyway.

mikebrow · 2018-05-07T19:47:51Z

pkg/server/container_start.go

-			return nil, nil, errors.Wrap(err, "failed to start container stdout logger")
+		f, err := os.OpenFile(logPath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0640)
+		if err != nil {
+			return nil, nil, errors.Wrap(err, "failed to open log file")


failed to create / open log file

mikebrow · 2018-05-07T19:58:08Z

pkg/server/container_start.go

+			if stderrCh != nil {
+				<-stderrCh
+			}
+			logrus.Debugf("Finish redirecting log file %q, close it", logPath)


closing log file %q

if we're going to have a "closing" comment in debug probably should have an opening comment above on success from line 141..

though it might be better to just remove as this may just clutter up the debug log .. no?

The log here is to indicate the goroutine stops.

mikebrow · 2018-05-07T20:03:01Z

pkg/server/container_start.go

 		defer func() {
 			if err != nil {
-				stdout.Close()
+				f.Close()


in the error case I don't think we need to close "f" ...

maybe I'm reading wrong but it looks like f didn't open if err != nil..

That error is checked before this defer.

exactly and the only way the function can return error (atm) is if it failed to open.. see "return" statements :-)

Yeah, I thought about this for a while. We have this defer because we do return an error before in the code below, but the error is removed in this PR.

However, i decide to keep this defer to make sure we don't miss the close when we introduce an error in the code below in the future.

ok.. yeah that's true that it could become useful in the future..

mikebrow · 2018-05-07T20:07:20Z

pkg/ioutil/write_closer_test.go

 	}
 }
+
+func TestSerialWriteCloesr(t *testing.T) {


/s/Cloesr/Closer/

Random-Liu · 2018-05-07T22:02:39Z

@mikebrow Thanks for reviewing! Will address comments today.

Random-Liu · 2018-05-15T07:47:36Z

pkg/ioutil/write_closer_test.go

+
+func TestSerialWriteCloser(t *testing.T) {
+	const (
+		// Test 100 times to make sure it always pass.


Random-Liu · 2018-05-15T07:49:43Z

pkg/server/container_start.go

 		defer func() {
 			if err != nil {
-				stdout.Close()
+				f.Close()


That error is checked before this defer.

yujuhong · 2018-05-14T18:32:17Z

docs/config.md

+  # max_container_log_size is the maximum log line size in bytes for a container.
+  # Log line longer than the limit will be split into multiple lines. -1 means no
+  # limit.
+  max_container_log_size = 16384


Use max_container_log_line_size instead? It's longer but more accurate.

yujuhong · 2018-05-15T21:29:45Z

pkg/server/io/logger.go

-	pipeBufSize = 4096
 	// bufSize is the size of the read buffer.
-	bufSize = pipeBufSize - len(timestampFormat) - len(Stdout) - len(runtime.LogTagPartial) - 3 /*3 delimiter*/ - 1 /*eol*/
+	bufSize = 4096


nit: make it clear in the comment that these are bytes.

Rename this to defaultBufferSize to avoid confusion?

yujuhong · 2018-05-15T21:39:55Z

pkg/server/io/logger.go

+			logrus.WithError(err).Errorf("Fail to write %q log to log file %q", s, path)
 		}
 		// Continue on write error to drain the input.
+		if stop {


If there was an error draining the input, should you still break?

We've already drain the input. I just mean we should not return error if we fail to write one line, because we should continue draining the container output.

I put the comment in a wrong place. Updated.

yujuhong · 2018-05-15T21:55:04Z

pkg/server/io/logger.go

+		switch {
+		case maxLen < 0:
+			// Always try reading the full line, if no max length limit.
+			fallthrough


Why fallthrough? Should this be break instead?

Simplified and fixed the logic here.

Random-Liu · 2018-05-15T23:37:26Z

@mikebrow @yujuhong Thanks for reviewing! Will try to address comments today.

Random-Liu · 2018-06-11T18:16:07Z

Distracted by other things. Will address comments today.

Random-Liu · 2018-06-13T01:28:27Z

@yujuhong @mikebrow Addressed comments.

mikebrow

/LGTM

yujuhong · 2018-06-13T22:06:19Z

pkg/ioutil/write_closer_test.go

+		require.Len(t, resultData, goroutine)
+		sort.Strings(resultData)
+		for i := 0; i < goroutine; i++ {
+			expected := strings.Repeat(strconv.Itoa(i), dataLen)


nit: make strings.Repeat(strconv.Itoa(i), dataLen) a function to reuse.

yujuhong · 2018-06-13T22:07:14Z

pkg/ioutil/write_closer_test.go

+		testCount = 10
+
+		goroutine = 10
+		dataLen   = 100000 // larger than PIPE_BUF=4096


Does the same test fail if non-serial writer is used?

https://stackoverflow.com/questions/29981050/concurrent-writing-to-a-file

It only has problem with old kernel. I can't reproduce this in my desktop. :)

Updated the comment to explain the use case.

Signed-off-by: Lantao Liu <[email protected]>

yujuhong · 2018-06-15T22:55:18Z

/lgtm

Backport #761 to release/1.0

Random-Liu added this to the v1.11 milestone May 5, 2018

k8s-ci-robot added the size/XL label May 5, 2018

Random-Liu assigned mikebrow and yujuhong May 5, 2018

Random-Liu force-pushed the add-log-max-size branch from e7dd626 to 6311d9b Compare May 5, 2018 06:24

mikebrow reviewed May 7, 2018

View reviewed changes

Random-Liu force-pushed the add-log-max-size branch from 6311d9b to 35802eb Compare May 11, 2018 18:39

Random-Liu commented May 15, 2018

View reviewed changes

yujuhong reviewed May 15, 2018

View reviewed changes

Random-Liu force-pushed the add-log-max-size branch 4 times, most recently from adb5824 to 37d7369 Compare June 13, 2018 01:25

k8s-ci-robot added the lgtm label Jun 13, 2018

mikebrow approved these changes Jun 13, 2018

View reviewed changes

yujuhong reviewed Jun 13, 2018

View reviewed changes

Random-Liu added 2 commits June 14, 2018 14:24

Add max_container_log_size

405f57f

Signed-off-by: Lantao Liu <[email protected]>

Add integration test.

bf551b9

Signed-off-by: Lantao Liu <[email protected]>

Random-Liu force-pushed the add-log-max-size branch from 37d7369 to bf551b9 Compare June 14, 2018 21:24

k8s-ci-robot removed the lgtm label Jun 14, 2018

k8s-ci-robot added the lgtm label Jun 15, 2018

Random-Liu merged commit e3d57d2 into containerd:master Jun 15, 2018

Random-Liu deleted the add-log-max-size branch June 15, 2018 22:56

Random-Liu mentioned this pull request Jul 10, 2018

Backport #761 to release/1.0 #839

Merged

Random-Liu added a commit that referenced this pull request Jul 11, 2018

Merge pull request #839 from Random-Liu/cherrypick-#761

1895a01

Backport #761 to release/1.0

Add log max size #761

Add log max size #761

Uh oh!

Conversation

Random-Liu commented May 5, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

thaJeztah commented May 5, 2018

Uh oh!

k8s-ci-robot commented May 5, 2018

Uh oh!

Random-Liu commented May 7, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mikebrow left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Random-Liu commented May 7, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Random-Liu commented May 5, 2018 •

edited

Loading

Random-Liu commented May 7, 2018 •

edited

Loading