moby: Container hangs when using fluentd logger

+1 on this issue

I have the same problem too

Anything new on this? Thanks

+1 When will this be resolved? It looks like PR has not been merged yet

Is there a plan to bump fluent-logger-golang version to 1.5.0 so that this issue is resolved in Docker version 19.03? Or is there any workaround to make this work in Docker version 19.0.3?

I was going to open a new issue to post my full bug report on this issue but I think we experience the same issue so I’m going to post it here.

Some weeks ago, a teammate experienced docker freezes when using fluentd logger whereas fluentd was down when containers were created and despite the mode=non-blocking and fluentd-async-connect=true options, with docker v19.03. To reproduce the bug you have to:

# Don't start any fluentd server
$ docker run --name repro -d -p 80:80 --log-driver fluentd --log-opt=fluentd-async-connect=true nginx

$ curl http://locahost
# This will generate some logs

$ docker stop repro
# Will hang out infinitely

After generating and analysing the goroutine stacktraces, it appears that there’re some goroutine blocked in semacquire state, in the fluent-logger-golang package:

goroutine 1908 [semacquire, 23 minutes]:
sync.runtime_Semacquire(0xc005964560)
	/usr/lib/go/src/runtime/sema.go:56 +0x44
sync.(*WaitGroup).Wait(0xc005964558)
	/usr/lib/go/src/sync/waitgroup.go:130 +0x66
github.com/docker/docker/vendor/github.com/fluent/fluent-logger-golang/fluent.(*Fluent).Close(0xc0059644d0, 0xc006326140, 0x55618f040db0)
	/build/docker/src/src/github.com/docker/docker/vendor/github.com/fluent/fluent-logger-golang/fluent/fluent.go:297 +0x6a
github.com/docker/docker/daemon/logger/fluentd.(*fluentd).Close(0xc0063260c0, 0x55618f040db0, 0x0)
	/build/docker/src/src/github.com/docker/docker/daemon/logger/fluentd/fluentd.go:181 +0x31
github.com/docker/docker/daemon/logger.(*RingLogger).Close(0xc000e57a40, 0xc005880e70, 0x2)
	/build/docker/src/src/github.com/docker/docker/daemon/logger/ring.go:103 +0x3fc
github.com/docker/docker/container.(*Container).Reset(0xc0053cdd40, 0x55618deb6d00)
	/build/docker/src/src/github.com/docker/docker/container/monitor.go:42 +0x109
github.com/docker/docker/daemon.(*Daemon).ProcessEvent(0xc0008a01e0, 0xc000d69380, 0x40, 0x55618cfd1515, 0x4, 0xc000d69380, 0x40, 0xc000d693c0, 0x40, 0x1000318eb, ...)
	/build/docker/src/src/github.com/docker/docker/daemon/monitor.go:61 +0x4d1
github.com/docker/docker/libcontainerd/remote.(*client).processEvent.func1()
	/build/docker/src/src/github.com/docker/docker/libcontainerd/remote/client.go:634 +0x109
github.com/docker/docker/libcontainerd/queue.(*Queue).Append.func1(0xc000d69300, 0x0, 0xc0007da090, 0xc000cb8ea0, 0xc000765d80, 0xc000d69380, 0x40)
	/build/docker/src/src/github.com/docker/docker/libcontainerd/queue/queue.go:28 +0x3a
created by github.com/docker/docker/libcontainerd/queue.(*Queue).Append
	/build/docker/src/src/github.com/docker/docker/libcontainerd/queue/queue.go:24 +0x1cf

After a more thorough analysis, I found out that:

• The stacktrace above starts with libcontainerd client.processEvent() -> (beginning of the goroutine) eventQ.Append()
• Cf. https://sourcegraph.com/github.com/moby/moby@10866714412aea1bb587d1ad14b2ce1ba4cf4308/-/blob/libcontainerd/remote/client.go#L636:11
• Cf. https://sourcegraph.com/github.com/moby/moby@10866714412aea1bb587d1ad14b2ce1ba4cf4308/-/blob/libcontainerd/queue/queue.go#L12
• Event is forwarded to Docker (*Daemon.ProcessEvent())
• Event type: libcontainerdtypes.EventExit()
• Container is locked
• Docker calls container.Reset(false) (cf. https://github.com/docker/docker-ce/blob/v19.03.4/components/engine/daemon/monitor.go#L61)
• container.Reset(lock bool): Reset puts a container into a state where it can be restarted again.
• https://github.com/docker/docker-ce/blob/v19.03.5/components/engine/container/monitor.go#L42
• Reset calls LogDriver.Close() -> (*Fluent).Close()

In 688e67e1d3, @thaJeztah bumped fluent/fluent-logger-golang from v1.3.0 to v1.4.0. By looking at the diff between v1.3.0 and v1.4.0, it appears that (*Fluent).Close() method changed: there were no call to wg.Wait() in previous versions.

Since we run with async option, the wait group is incremented at this line. The HTTP call shown above triggers that select, and even if the channel f.pending is closed there, since the first log triggered the select, it’s still blocked on that call to f.write() and then it retries to connect to the fluentd server which is down for a long period of time (actually using an exponential back-off retry strategy). And this is the reason of the freezes we experience.

Finally, we had to downgrade to v18.09 to get a working version of Docker and fluentd logger.

EDIT: Actually it looks like this PR on fluent-logger-golang (and PR #40293 on this repo) are trying to solve this exact issue.

When can we expect this issue to be fixed. It is a blocker for me

Yes, it will require a new docker release. I still feel like the solution provided in fluentd is not great. I’m not sure how we can expose the new functionality w/o requiring the user to explicitly set the option… which also means no backport to 19.03.

Alternatively someone could make a plugin that uses the latest fluentd release.

Also note that the version of fluentd has not been updated here, and this option is not exposed in anyway yet.

Agree that it will not be backward compatible. However, currently there is no solution/workaround in sight. Even simple commands like stop containers lead to a hung state. Request for prioritising this for the major release.

How do you create a plugin with the latest fluentd for 19.03 docker? Will this mean that we don’t need a new docker release?

The only solution that works for me on this case is:

systemctl stop docker
mount | grep /containers/ | cut -d' ' -f3 | xargs umount
rm -rf /var/lib/docker/containers
systemctl start docker

Then start the containers as usual.

any updates or workaround guys, I think that I couldn’t wait until 19.04, and so could my penguin 🐧

Thanks for the update @akerouanton, I can see that tests are now passing thanks to the changes you made to CI

PR under review: https://github.com/fluent/fluent-logger-golang/pull/82

@NiR How do I swap the broken fluentd logging driver currently packaged in Docker with your v0.1 of akerouanton/fluentd-async-logger? I’m hoping Docker will fix this soon but until then happy to use your fix.

I added some test cases (TestCloseOnFailingAsyncConnect && TestCloseOnFailingAsyncReconnect) to fluent-logger-golang. My two PRs are still in review, but I published a v0.1 of akerouanton/fluentd-async-logger based on my fixes. Feel free to use it if you face the issue described here.

I’m currently working on a logging driver based on the fixed version of fluent-logger-golang and I’m wondering if ForceStopAsyncSend should be set to true whenever RequestAck is false (as this is already somehow encoding delivery expectations).

I think the issue described here is quite expectable in the case of RequestAck=true + Async=true whenever the fluentd server is down. In the other hand, with RequestAck=false (the default) and Async=true, people are actually expecting the logger to stop as soon as possible.

Moreover, it means no additional option have to be exposed to Docker users thus, I guess, this could be backported to v19.03. If these assumptions seem reasonable to Docker maintainers, I’m willing to send a patch.

EDIT: Actually ForceStopAsyncSend does not work as it’s used by a select run after the select that try to write the log (and the write method is actually the one using exponential back-off retry to lazily and asynchronously connect to fluentd). But I’m gonna send a patch to fluent-logger-golang to get it working properly.

I’ve commented on that issue. Sorry for missing it.