use pubsub instead of filenotify to follow json logs by mountkin · Pull Request #19498 · moby/moby

mountkin · 2016-01-20T16:51:21Z

inotify event is trigged immediately there's data written to disk.
But at the time that the inotify event is received, the json line might
not fully saved to disk. If the json decoder tries to decode in such
case, an io.UnexpectedEOF will be trigged.
We used to retry for several times to mitigate the io.UnexpectedEOF error.
But there are still flaky tests caused by the partial log entries.

The daemon knows exactly when there are new log entries emitted. We can
use the pubsub package to notify all the log readers instead of inotify.

BTW: I can't run the test locally because the testing infrastructure seems to be broken on my laptop.

---> Making bundle: test-integration-cli (in bundles/1.10.0-dev/test-integration-cli)
---> Making bundle: .integration-daemon-start (in bundles/1.10.0-dev/test-integration-cli)
+++ /etc/init.d/apparmor start
 * Starting AppArmor profiles
Skipping profile in /etc/apparmor.d/disable: usr.sbin.rsyslogd
   ...done.
INFO: Waiting for daemon to start...
+++ exec docker daemon --debug --host unix:///go/src/github.com/docker/docker/bundles/1.10.0-dev/test-integration-cli/docker.sock --storage-driver vfs --pidfile bundles/1.10.0-dev/test-integration-cli/docker.pid --userland-proxy=true
.
---> Making bundle: .integration-daemon-setup (in bundles/1.10.0-dev/test-integration-cli)
---> Making bundle: .detect-daemon-osarch (in bundles/1.10.0-dev/test-integration-cli)
---> Making bundle: .ensure-emptyfs (in bundles/1.10.0-dev/test-integration-cli)
++++ tar -cC bundles/1.10.0-dev/test-integration-cli/emptyfs .
++++ docker load
---> Making bundle: .ensure-frozen-images (in bundles/1.10.0-dev/test-integration-cli)
++++ tar -cC /docker-frozen-images .
++++ docker load
Error response from daemon: ApplyLayer exit status 1 stdout:  stderr: unexpected EOF
+++ bundle .integration-daemon-stop
+++ local bundle=.integration-daemon-stop
/go/src/github.com/docker/docker/hack/make.sh: line 257: local: can only be used in a function

Signed-off-by: Shijiang Wei [email protected]

LK4D4 · 2016-01-20T17:57:05Z

@mountkin One logs test failed

mountkin · 2016-01-22T15:08:50Z

@LK4D4 test passed (I rebased and force pushed so the jenkins jobs started again 🏊 Let's see the final result)

cpuguy83 · 2016-01-22T18:17:58Z

I like the general simplification, but the issue is now for every write we have to notify as well.
I think the flakey tests are generally from a race between stopping the log writer (on container stop) and getting all that out of the buffer in time.

mountkin · 2016-01-22T21:48:40Z

@cpuguy83 I think the publish is much cheaper than inotify because if no one is running 'docker logs -f' the 'Publish' function does nothing more than locking and unlocking a mutex. And the 'Publish' is only called when a line is fully written to the disk (while inotify might be triggered many times when writing a line, see my debug log in another PR #17606).
If someone is running, the subscriber is also very lightweight and it never blocks (merely a atomic.AddUint64).

LK4D4 · 2016-01-27T17:38:01Z

daemon/logger/jsonfilelog/jsonfilelog.go

I would suggest avoiding timeout. Timers is very heavy.

@LK4D4 addressed. Thanks for pointing out this.

LK4D4 · 2016-01-28T16:27:58Z

@cpuguy83 What's your thoughts?

cpuguy83 · 2016-01-28T16:32:15Z

The extra call for every write even when there may not be a reader is a little iffy.
The thing with inotify is, it's only consuming resources when there is a reader.

BenchmarkPubSub-8   10000000           175 ns/op         260 B/op          1 allocs/op
BenchmarkNoPubSub-8 30000000            82.1 ns/op       163 B/op          0 allocs/op

This is comparing just writing with the pubsub call and writing without.

mountkin · 2016-01-28T16:58:31Z

@cpuguy83 the current version of 'Publish' function can be optimized a little. If no subscribers the waitgroup allocation can be omitted.

mountkin · 2016-01-29T05:32:10Z

@cpuguy83 Here is the result of my benchmark:
go test -v -benchtime 10s -test.bench BenchmarkJSONFileLogger -test.benchmem -test.run=BenchmarkJSONFileLogger

filenotify:
BenchmarkJSONFileLogger-8 200000 60936 ns/op 59.57 MB/s 960 B/op 30 allocs/op

before mountkin@1106c13:
BenchmarkJSONFileLogger-8 200000 68881 ns/op 52.70 MB/s 1440 B/op 60 allocs/op

after mountkin@1106c13:
BenchmarkJSONFileLogger-8 200000 64656 ns/op 56.14 MB/s 960 B/op 30 allocs/op

Is the overhead after pubsub optimization acceptable?

thaJeztah · 2016-02-04T14:19:19Z

ping @cpuguy83 @LK4D4 PTAL

LK4D4 · 2016-02-04T16:48:41Z

looks decent
@cpuguy83 WDYT?

cpuguy83 · 2016-02-06T03:33:40Z

Thanks @mountkin!

Yep, I'm good with those results, but I think we need some simplifications in the code.

cpuguy83 · 2016-02-06T04:04:36Z

daemon/logger/jsonfilelog/read.go

Can we change this name to writeNotify

cpuguy83 · 2016-02-09T21:52:06Z

daemon/logger/jsonfilelog/read.go

Seems like we should read to the end of the current file on rotate.

@cpuguy83 when this channel is readable the file has already been moved away. So reading the current file leads to a "bad file descriptor" error.
I've no idea how to handle this case correctly.
Moreover, it seems that following rotated log never worked correctly before.

thaJeztah · 2016-02-11T16:23:10Z

ping @mountkin can you have a look at @cpuguy83's comment?

mountkin · 2016-02-13T15:43:16Z

@thaJeztah sorry for the late response. I'm on holiday these days. I'll look into the failed tests tomorrow.

thaJeztah · 2016-02-13T17:04:16Z

Oh no worries, enjoy your Holiday!

inotify event is trigged immediately there's data written to disk. But at the time that the inotify event is received, the json line might not fully saved to disk. If the json decoder tries to decode in such case, an io.UnexpectedEOF will be trigged. We used to retry for several times to mitigate the io.UnexpectedEOF error. But there are still flaky tests caused by the partial log entries. The daemon knows exactly when there are new log entries emitted. We can use the pubsub package to notify all the log readers instead of inotify. Signed-off-by: Shijiang Wei <[email protected]> try to fix broken test. will squash once tests pass Signed-off-by: Shijiang Wei <[email protected]>

Signed-off-by: Shijiang Wei <[email protected]>

mountkin · 2016-02-15T11:39:40Z

Updated.
@cpuguy83 PTAL this PR and #20327

mountkin · 2016-02-15T11:40:38Z

BTW, it seems that the filenotify package is no longer needed when this PR is merged. Can I remove the package in another commit?

cpuguy83 · 2016-02-16T16:16:18Z

@mountkin Let's save it for another PR I think, b/c it's going to make this PR difficult to look at, even if in different commits.

cpuguy83 · 2016-02-16T21:25:12Z

daemon/logger/jsonfilelog/jsonfilelog.go

+		writer:        writer,
+		readers:       make(map[*logger.LogWatcher]struct{}),
+		extra:         extra,
+		writeNotifier: pubsub.NewPublisher(0, 10),


Probably only need 1 here instead of 10, but this should be fine. We'll just end up reading an EOF if there are extra notifications.

cpuguy83 · 2016-02-16T21:25:38Z

1 small nit, but I'm fine with it.

LGTM

LK4D4 · 2016-02-16T21:55:46Z

LGTM

use pubsub instead of filenotify to follow json logs

thaJeztah · 2016-02-17T10:33:25Z

Based on #20327 (comment), this is a regression in 1.10.x, so I'm adding this to the 1.10.2 milestone

anusha-ragunathan · 2016-02-17T19:14:10Z

ARM tests are failing in TestLogsFollowSlowStdoutConsumer due to this change.
https://jenkins.dockerproject.org/job/Docker%20Master%20%28arm%29/694/console

tiborvass · 2016-02-19T17:07:52Z

I'm removing this from 1.10.2 as this changes a lot and we'd rather not add more risk than necessary to 1.10.2

cpuguy83 · 2016-02-24T01:36:54Z

Yeah, this change is definitely slower :(
The existing benchmark is only really testing the marshalling and not really the full write->read flow

benchmark                 old ns/op     new ns/op     delta
BenchmarkJSONLogger-8     2162          2938          +35.89%

benchmark                 old allocs     new allocs     delta
BenchmarkJSONLogger-8     7              9              +28.57%

benchmark                 old bytes     new bytes     delta
BenchmarkJSONLogger-8     245           336           +37.14%

cpuguy83 · 2016-02-24T01:37:10Z

And that's with the file poller too, not inotify.

GordonTheTurtle added the status/0-triage label Jan 20, 2016

mountkin force-pushed the refactor-jsonfilelog-reader branch from c863500 to 16c3c51 Compare January 20, 2016 17:03

LK4D4 added status/2-code-review and removed status/0-triage labels Jan 20, 2016

mountkin force-pushed the refactor-jsonfilelog-reader branch from 16c3c51 to 2ac8db4 Compare January 21, 2016 17:02

GordonTheTurtle added the dco/no Automatically set by a bot when one of the commits lacks proper signature label Jan 21, 2016

mountkin force-pushed the refactor-jsonfilelog-reader branch from 2ac8db4 to 37cb26a Compare January 21, 2016 17:03

GordonTheTurtle removed the dco/no Automatically set by a bot when one of the commits lacks proper signature label Jan 21, 2016

mountkin force-pushed the refactor-jsonfilelog-reader branch 2 times, most recently from d0b5a3f to 7835599 Compare January 22, 2016 15:06

LK4D4 reviewed Jan 27, 2016
View reviewed changes

mountkin force-pushed the refactor-jsonfilelog-reader branch 2 times, most recently from 6635882 to 3f1cb58 Compare January 28, 2016 15:04

mountkin force-pushed the refactor-jsonfilelog-reader branch from 319b782 to 1106c13 Compare January 29, 2016 05:29

cpuguy83 reviewed Feb 6, 2016
View reviewed changes

daemon/logger/jsonfilelog/read.go Outdated

Copy link

Member

cpuguy83 Feb 6, 2016

Choose a reason for hiding this comment

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

Can we change this name to writeNotify

mountkin force-pushed the refactor-jsonfilelog-reader branch from 1106c13 to 988de9c Compare February 6, 2016 16:42

mountkin force-pushed the refactor-jsonfilelog-reader branch from 988de9c to ffe1174 Compare February 6, 2016 16:44

cpuguy83 reviewed Feb 9, 2016
View reviewed changes

mountkin force-pushed the refactor-jsonfilelog-reader branch from ffe1174 to 445d7e5 Compare February 15, 2016 09:23

mountkin added 2 commits February 15, 2016 19:25

optimize pubsub.Publish function

1e0f1ec

Signed-off-by: Shijiang Wei <[email protected]>

mountkin force-pushed the refactor-jsonfilelog-reader branch from 445d7e5 to 1e0f1ec Compare February 15, 2016 11:26

mountkin mentioned this pull request Feb 15, 2016

Panic on log rotation when running docker logs -f xxxx #20327

Closed

cpuguy83 reviewed Feb 16, 2016
View reviewed changes

LK4D4 added a commit that referenced this pull request Feb 16, 2016

Merge pull request #19498 from mountkin/refactor-jsonfilelog-reader

8545fdc

use pubsub instead of filenotify to follow json logs

LK4D4 merged commit 8545fdc into moby:master Feb 16, 2016

thaJeztah added this to the 1.10.2 milestone Feb 17, 2016

tiborvass removed this from the 1.10.2 milestone Feb 19, 2016

mountkin mentioned this pull request Feb 24, 2016

Revert fsnotify changes #20641

Merged

tiborvass mentioned this pull request Mar 1, 2016

Update changelog with changes from 1.10.1 and .2 #20813

Merged

corhere mentioned this pull request Feb 26, 2022

LogFile follow without filenotify #43294

Merged

Comments

Conversation

mountkin commented Jan 20, 2016

Uh oh!

LK4D4 commented Jan 20, 2016

Uh oh!

mountkin commented Jan 22, 2016

Uh oh!

cpuguy83 commented Jan 22, 2016

Uh oh!

mountkin commented Jan 22, 2016

Uh oh!

LK4D4 Jan 27, 2016

Choose a reason for hiding this comment

Uh oh!

mountkin Jan 28, 2016

Choose a reason for hiding this comment

Uh oh!

LK4D4 commented Jan 28, 2016

Uh oh!

cpuguy83 commented Jan 28, 2016

Uh oh!

mountkin commented Jan 28, 2016

Uh oh!

mountkin commented Jan 29, 2016

Uh oh!

thaJeztah commented Feb 4, 2016

Uh oh!

LK4D4 commented Feb 4, 2016

Uh oh!

cpuguy83 commented Feb 6, 2016

Uh oh!

cpuguy83 Feb 6, 2016

Choose a reason for hiding this comment

Uh oh!

cpuguy83 Feb 9, 2016

Choose a reason for hiding this comment

Uh oh!

mountkin Feb 15, 2016

Choose a reason for hiding this comment

Uh oh!

thaJeztah commented Feb 11, 2016

Uh oh!

mountkin commented Feb 13, 2016

Uh oh!

thaJeztah commented Feb 13, 2016

Uh oh!

mountkin commented Feb 15, 2016

Uh oh!

mountkin commented Feb 15, 2016

Uh oh!

cpuguy83 commented Feb 16, 2016

Uh oh!

cpuguy83 Feb 16, 2016

Choose a reason for hiding this comment

Uh oh!

cpuguy83 commented Feb 16, 2016

Uh oh!

LK4D4 commented Feb 16, 2016

Uh oh!

thaJeztah commented Feb 17, 2016

Uh oh!

anusha-ragunathan commented Feb 17, 2016

Uh oh!

tiborvass commented Feb 19, 2016

Uh oh!

cpuguy83 commented Feb 24, 2016

Uh oh!

cpuguy83 commented Feb 24, 2016

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants