moby: Docker logging blocks and never recovers

correctness > speed indeed, a production application thats blocked and unusuable because a peripheral system is having a bad time is not correct - it’s completely dead and unusable in a way that might impact customers.

logging is peripheral to the primary function of the application.

This behaviour leads to a system that as soon as you flag an app in docker to enable debug level logging for a while then in the case where the debugging is volumous the system under debug becomes unusable - and impossible to debug. Operationally you’d much rather sacrifice logging integrity.

Systems where logging is so important as to be a critical function of the app will/should not be doing that logging to STD{OUT,ERR}, so sacrificing integrity of STD{OUT,ERR} logs seems reasonable to me over sacrificing the entire app.

Something consuming the data and getting the bogus input is potentially far more dangerous than the decrease in speed.

Someone able to cause a denial of service by using a slow log reader is even more dangerous, as “blocked” in this case is just another way to say DoS. In the field, one simply never assumes that syslogs are 100% complete because syslog, like ICMP, is one of the first things that is dropped to ensure the responsiveness of the service.

Some systems note “## syslog events were dropped” so that purposeful gaps can be differentiated from gaps caused by communication interruption. That may be helpful here to some extent.

+1 @ripienaar @relistan

I understand there are applications where it is absolutely critical that no log is lost. I would argue that is by far outweighed by applications that are more than happy to shed a few logs to survive a heavy load event.

If it were configurable you could give people the option of 100% log capture but I would say the default should be to throw logs on the floor for a consumer with a full buffer.

The fundamental misunderstanding here is that it was not clear to me (and I think also at least the authors of Logspout, and Heka until recently) that /attach and /logs do not hit the same buffers inside the daemon. It doesn’t help when, even with code to look at @aaronlehmann continued to refer to “logs” when he can see that we’re using /attach:

I don’t think dropping data from the log stream would necessarily be the correct behavior. This could break the formatting of the logs and lead to unexpected gaps in the log data.

I was not aware of that and I guess no one at Docker (at least none of you guys) knew that at least two of the major third party logging systems were until not very long ago using the /attach endpoint to consume logs. I can assure you because at New Relic we ran Heka in production for quite some time, and at Nitro for a few months on v1.9, that this did not block containers until v1.10. It did leak memory like crazy when the reader got slow. At New Relic we ran a custom patched build that resolved the memory leak issue that @didip and I patched here.

I am a major contributor on the Heka Docker plugin and we’ve been running it at Nitro just fine until we upgraded to Docker v1.10 in production and the change took out our site not long after. We’ll pull in Rob’s recent changes to the Heka Docker plugin that switches it to the /logs endpoint and expect that it resolves this issue at least.

Nonetheless, this functional change to the behavior of the /attach endpoint really needs to go into the release notes for v1.10. It certainly would have raised a red flag for me. And I suggest adding some clarity to the Remote API documentation for the /attach endpoint which in various places refers to pulling in logs.

I would suggest that a 1MB buffer (not quite, it’s 1e6) is also not anywhere near big enough. With log line average length around 100-150 bytes , this is 6666 to 10k lines of buffer. A high throughput production app can blow that buffer very quickly, especially in debug logging mode.

Finally, an explicit warning that docker attach can block a container is a critical addition. It’s not mentioned in the docs. And anyone with experience prior to v1.10 will be reasonably certain that it doesn’t.

@tonistiigi we’re talking about logs here, right? Having worked on production systems for over 20 years I can’t remember a time when I would have preferred to have complete logs over having the application up and running. The only exception being audit logging, something generally not entrusted to generalized logging anyway. This is the reason many people don’t log to disk, and why traditional stream logging was done over UDP, for example.

I know you said you don’t think it’s about logging speed, but it is. The tool I provided above is the fastest way to make it happen so it doesn’t read anything. In the production environment where this hit us, Heka was consuming the stream, but it had gotten backed up and was slow. I know this because we replaced our log appender with an asynchronous one. We then attached metrics to the remaining buffer size for our asynchronous appender. You can see it go up and down as Heka consumes messages. Of course since we’re on 1.10.3 it eventually sits at low water mark forever because the Docker engine stops consuming.

Making the buffer bigger would make this happen less frequently perhaps, but it is not a solution. Also no one has addressed that this was a fundamental change in the Docker engine and that it wasn’t in the changelogs. I know this is hard to get right all the time, but it should be retro-actively be added to the appropriate changelog so that anyone having not already upgraded can see it.

If there are actually people who prefer this behavior, can we have a CLI flag to switch it? If not, I’m not sure what logging solution I’ll recommend in production that leverages the Docker daemon, including in “Docker: Up and Running”. The only other way around it is to use a shim like we used to with the Spotify logger or some other supervisory process in the container that does the right thing.

Just fyi, for 1.14 we’ve added a new logging mode that you can pass through via log-opt. --log-opt mode=non-blocking --log-opt max-buffer-size=4m, for example. See #28762 for details.