Fixes#27779
Currently `followLogs` can get into a deadlock if we receive an inotify
IN_MODIFY event while we are trying to close the `fileWatcher`. This is
due to the fact that closing the `fileWatcher` happens in the same block
as consumes events from the `fileWatcher`. We are trying to run
`fileWatcher.Close`, which is waiting for an IN_IGNORE event to come in
over inotify to confirm the watch was been removed. But, because an
IN_MODIFY event has appeared after `Close` was entered but before the
IN_IGNORE, the broadcast never comes. The IN_MODIFY cannot be consumed
as the events channel is unbuffered and the only `select` that reads
from it is busy waiting for the IN_IGNORE event.
In order to try and fix this race condition I've moved the removal of
the `fileWatcher` out to a separate go block that waits for a signal to
close, removes the watcher and then signals to the previous selects on
the close signal.
This has introduced a `fileWatcher.Remove` in the final case, but if we
try and remove a watcher that does not exist it will just return an
error saying so. We are not doing any checking on the return of `Remove`
so this shouldn't cause any side-effects.
Signed-off-by: Tom Booth <tombooth@gmail.com>
Upstream-commit: a69a59ffc7e3d028a72d1195c2c1535f447eaa84
Component: engine
`golint` had the following issue when linting this file:
```
daemon/logger/jsonfilelog/read.go:116:10: should omit type io.Reader
from declaration of var rdr; it will be inferred from the right-hand
side
```
In order to keep it happy changing it to an indirect assignment will
still maintain the same functionality.
Signed-off-by: Tom Booth <tombooth@gmail.com>
Upstream-commit: 6314bec641b473571c0160d85bdc70250342185a
Component: engine
Fixes a race where the log reader would get events for both an actual
rotation as we from fsnotify (`fsnotify.Rename`).
This issue becomes extremely apparent when rotations are fast, for
example:
```
$ docker run -d --name test --log-opt max-size=1 --log-opt max-file=2
busybox sh -c 'while true; do echo hello; usleep 100000; done'
```
With this change the log reader for jsonlogs can handle rotations that
happen as above.
Instead of listening for both fs events AND rotation events
simultaneously, potentially meaning we see 2 rotations for only a single
rotation due to channel buffering, only listen for fs events (like
`Rename`) and then wait to be notified about rotation by the logger.
This makes sure that we don't see 2 rotations for 1, and that we don't
start trying to read until the logger is actually ready for us to.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 84e60a7e10278e3acd2b783d0e6955dc5198b57c
Component: engine
If "docker logs" was used on an offline container, the logger is leaked, leaving it up to the finalizer to close the file handle, which could block removal of the container. Further, the json file logger could leak an open handle if the logs are read without follow due to an early return without a close. This change addresses both cases.
Signed-off-by: Stefan J. Wernli <swernli@microsoft.com>
Upstream-commit: 54f11b84d218c1a7ff4ab4e2148819265da213bc
Component: engine
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)
Upstream-commit: 513ec73831269947d38a644c278ce3cac36783b2
Component: engine
Log drivers are instantiated on a per-container basis, and passed the
container ID (along with other information) when they're initialized.
Drivers that care about that value are caching the value that they're
passed when they're initialized and using it in favor of the value
contained in Message structures that are passed to them, so the field in
Messages is unused, so we remove it.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com>
Upstream-commit: 7772d270c06cc6c26359b556c95563bae31c1038
Component: engine
The jsonlog logger currently allows specifying envs and labels that
should be propagated to the log message, however there has been no way
to read that back.
This adds a new API option to enable inserting these attrs back to the
log reader.
With timestamps, this looks like so:
```
92016-04-08T15:28:09.835913720Z foo=bar,hello=world hello
```
The extra attrs are comma separated before the log message but after
timestamps.
Without timestaps it looks like so:
```
foo=bar,hello=world hello
```
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: bd9d14a07b9f1c82625dc8483245caf3fa7fe9e6
Component: engine
This cleans up some of the use of the filepoller which makes reading
significantly more robust and gives fewer changes to fallback to the
polling based watcher.
In a lot of cases, if the file was being rotated while we were adding it
to the watcher, it would return an error that the file doesn't exist and
would fallback.
In some cases this fallback could be triggered multiple times even if we
were already on the fallback/poll-based watcher.
It also fixes an open file leak caused by not closing files properly on
rotate, as well as not closing files that were read via the `tail`
function until after the log reader is completed.
Prior to the above changes, it was relatively simple to cause the log
reader to error out by having quick rotations, for example:
```
$ docker run --name test --log-opt max-size=10b --log-opt max-files=10
-d busybox sh -c 'while true; do usleep 500000; echo hello; done'
$ docker logs -f test
```
After these changes I can run this forever without error.
Another fix removes 2 `os.Stat` calls when rotating files. The stat
calls are not needed since we are just calling `os.Rename` anyway, which
will in turn also just produce the same error that `Stat` would.
These `Stat` calls were also quite expensive.
Removing these stat calls also seemed to resolve an issue causing slow
memory growth on the daemon.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 1ae9dcf97dc6ccaf7a7977fe8ae1812b691ccba2
Component: engine
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 <mountkin@gmail.com>
try to fix broken test. will squash once tests pass
Signed-off-by: Shijiang Wei <mountkin@gmail.com>
Upstream-commit: b1594c59f5e0d1ac898eacde8d91b1ba33c2b626
Component: engine
- Move time json marshaling to the jsonlog package: this is a docker
internal hack that we should not promote as a library.
- Move Timestamp encoding/decoding functions to the API types: This is
only used there. It could be a standalone library but I don't this
it's worth having a separated repo for this. It could introduce more
complexity than it solves.
Signed-off-by: David Calavera <david.calavera@gmail.com>
Upstream-commit: 27220ecc6b1eedf650ca9cf94965cb0dc2054efd
Component: engine
The json decoder starts to decode immediately an inotify event is
received.
But at the time the inotify event is trigged, the json log
entry might haven't been fully written to the disk.
In this case the decoder will return an "io.UnexpectedEOF" error, but
there is still data remaining in the decoder's buffer. And the data
should be passed to the decoder when the next inotify event is
triggered.
Signed-off-by: Shijiang Wei <mountkin@gmail.com>
Upstream-commit: e41eae8b42052d07432405cca113ffcf8cf49c06
Component: engine
this allows jsonfile logger to collect extra metadata from containers with
`--log-opt labels=label1,label2 --log-opt env=env1,env2`.
Extra attributes are saved into `attrs` attributes for each log data.
Signed-off-by: Daniel Dao <dqminh@cloudflare.com>
Upstream-commit: 0083f6e984894b4d3697c1ae63547c07eea697af
Component: engine
After tailing a file, if the number of lines requested is > the number
of lines in the file, this would cause a json unmarshalling error to
occur when we later try to go follow the file.
So brute force set it to the end if any tailing occurred.
There is potential that there could be some missing log messages if logs
are being written very quickly, however I was not able to make this
happen even with `while true; do echo hello; done`, so this is probably
acceptable.
While testing this I also found a panic in LogWatcher.Close can be
called twice due to a race. Fix channel close to only close when there
has been no signal to the channel.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: c57faa91e2dab72a0a0905dc10e5cbdf55b545f5
Component: engine
- downcase and privatize exported variables that were unused
- make accurate an error message
- added package comments
- remove unused var ReadLogsNotSupported
- enable linter
- some spelling corrections
Signed-off-by: Morgan Bauer <mbauer@us.ibm.com>
Upstream-commit: ccbe539e86dfbb8749c09763ddfd73bf10ac57cc
Component: engine
Implement new reader interface on jsonfile.
Moves jsonlog decoding from daemon to jsonfile logger.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: c0391bf5545afef5e675138556c39e4c0e9bf91b
Component: engine
- noplog driver pkg for '--log-driver=none' (null object pattern)
- centralized factory for log drivers (instead of case/switch)
- logging drivers registers themselves to factory upon import
(easy plug/unplug of drivers in daemon/logdrivers.go)
- daemon now doesn't start with an invalid log driver
- Name() method of loggers is actually now their cli names (made it useful)
- generalized Read() logic, made it unsupported except json-file (preserves
existing behavior)
Spotted some duplication code around processing of legacy json-file
format, didn't touch that and refactored in both places.
Signed-off-by: Ahmet Alp Balkan <ahmetalpbalkan@gmail.com>
Upstream-commit: 3a8728b431df07249ad913ea9a12e27dc39b8956
Component: engine
