Signed-off-by: Phil Estes <estesp@linux.vnet.ibm.com>
(cherry picked from commit f962bd06ed8824d1f75d8546b428965cd61bdf7f)
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Upstream-commit: 5591f0b1ee7dec101b490228258613cd7caf64ee
Component: engine
When daemon.ContainerLogs() is called with options.follow=true
(as in "docker logs --follow"), the "loggerutils.followLogs()"
function never returns (even then the logs consumer is gone).
As a result, all the resources associated with it (including
an opened file descriptor for the log file being read, two FDs
for a pipe, and two FDs for inotify watch) are never released.
If this is repeated (such as by running "docker logs --follow"
and pressing Ctrl-C a few times), this results in DoS caused by
either hitting the limit of inotify watches, or the limit of
opened files. The only cure is daemon restart.
Apparently, what happens is:
1. logs producer (a container) is gone, calling (*LogWatcher).Close()
for all its readers (daemon/logger/jsonfilelog/jsonfilelog.go:175).
2. WatchClose() is properly handled by a dedicated goroutine in
followLogs(), cancelling the context.
3. Upon receiving the ctx.Done(), the code in followLogs()
(daemon/logger/loggerutils/logfile.go#L626-L638) keeps to
send messages _synchronously_ (which is OK for now).
4. Logs consumer is gone (Ctrl-C is pressed on a terminal running
"docker logs --follow"). Method (*LogWatcher).Close() is properly
called (see daemon/logs.go:114). Since it was called before and
due to to once.Do(), nothing happens (which is kinda good, as
otherwise it will panic on closing a closed channel).
5. A goroutine (see item 3 above) keeps sending log messages
synchronously to the logWatcher.Msg channel. Since the
channel reader is gone, the channel send operation blocks forever,
and resource cleanup set up in defer statements at the beginning
of followLogs() never happens.
Alas, the fix is somewhat complicated:
1. Distinguish between close from logs producer and logs consumer.
To that effect,
- yet another channel is added to LogWatcher();
- {Watch,}Close() are renamed to {Watch,}ProducerGone();
- {Watch,}ConsumerGone() are added;
*NOTE* that ProducerGone()/WatchProducerGone() pair is ONLY needed
in order to stop ConsumerLogs(follow=true) when a container is stopped;
otherwise we're not interested in it. In other words, we're only
using it in followLogs().
2. Code that was doing (logWatcher*).Close() is modified to either call
ProducerGone() or ConsumerGone(), depending on the context.
3. Code that was waiting for WatchClose() is modified to wait for
either ConsumerGone() or ProducerGone(), or both, depending on the
context.
4. followLogs() are modified accordingly:
- context cancellation is happening on WatchProducerGone(),
and once it's received the FileWatcher is closed and waitRead()
returns errDone on EOF (i.e. log rotation handling logic is disabled);
- due to this, code that was writing synchronously to logWatcher.Msg
can be and is removed as the code above it handles this case;
- function returns once ConsumerGone is received, freeing all the
resources -- this is the bugfix itself.
While at it,
1. Let's also remove the ctx usage to simplify the code a bit.
It was introduced by commit a69a59ffc7e3d ("Decouple removing the
fileWatcher from reading") in order to fix a bug. The bug was actually
a deadlock in fsnotify, and the fix was just a workaround. Since then
the fsnofify bug has been fixed, and a new fsnotify was vendored in.
For more details, please see
https://github.com/moby/moby/pull/27782#issuecomment-416794490
2. Since `(*filePoller).Close()` is fixed to remove all the files
being watched, there is no need to explicitly call
fileWatcher.Remove(name) anymore, so get rid of the extra code.
Should fix https://github.com/moby/moby/issues/37391
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
(cherry picked from commit 916eabd459fe707b5c4a86377d12e2ad1871b353)
Upstream-commit: 84a5b528aede5579861201e869870d10fc98c07c
Component: engine
This makes it so consumers of `LogFile` should pass in how to get an
io.Reader to the requested number of lines to tail.
This is also much more efficient when tailing a large number of lines.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 94a10150f64a24793216f5324a34e62be3f31a2d
Component: engine
remove unnescessary import aliases, brackets, and so on.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Upstream-commit: f23c00d8701e4bd0f2372a586dacbf66a26f9a51
Component: engine
Docker daemon has a 16K buffer for log messages. If a message length
exceeds 16K, it should be split by the logger and merged at the
endpoint.
This change adds `PartialLogMetaData` struct for enhanced partial support
- LastPartial (bool) : indicates if this is the last of all partials.
- ID (string) : unique 32 bit ID. ID is same across all partials.
- Ordinal (int starts at 1) : indicates the position of msg in the series of partials.
Also, the timestamps across partials in the same.
Signed-off-by: Anusha Ragunathan <anusha.ragunathan@docker.com>
Upstream-commit: 0b4b0a7b5d5de8cb575b666312fceaa2cd58e658
Component: engine
This PR adds support for compressibility of log file.
I added a new option conpression for the jsonfile log driver,
this option allows the user to specify compression algorithm to
compress the log files. By default, the log files will be
not compressed. At present, only support 'gzip'.
Signed-off-by: Yanqiang Miao <miao.yanqiang@zte.com.cn>
'docker logs' can read from compressed files
Signed-off-by: Yanqiang Miao <miao.yanqiang@zte.com.cn>
Add Metadata to the gzip header, optmize 'readlog'
Signed-off-by: Yanqiang Miao <miao.yanqiang@zte.com.cn>
Upstream-commit: f69f09f44ce9fedbc9d70f11980c1fc8d7f77cec
Component: engine
This fixes an issue where the container LogPath was empty when the
non-blocking logging mode was enabled. This change sets the LogPath on
the container as soon as the path is generated, instead of setting the
LogPath on a logger struct and then attempting to pull it off that
logger at a later point. That attempt to pull the LogPath off the logger
was error prone since it assumed that the logger would only ever be a
single type.
Prior to this change docker inspect returned an empty string for
LogPath. This caused issues with tools that rely on docker inspect
output to discover container logs, e.g. Kubernetes.
This commit also removes some LogPath methods that are now unnecessary
and are never invoked.
Signed-off-by: junzhe and mnussbaum <code@getbraintree.com>
Upstream-commit: 20ca612a59c45c0bd58c71c199a7ebd2a6bf1a9e
Component: engine
This fix carries PR 34248: Added tag log option to json-logger
This fix changes to use RawAttrs based on review feedback.
This fix fixes 19803, this fix closes 34248.
Signed-off-by: Yong Tang <yong.tang.github@outlook.com>
Upstream-commit: e77267c5a682e2c5aaa32469f2c83c2479d57566
Component: engine
Fixes#19803
Updated the json-logger to utilize the common log option
'tag' that can define container/image information to include
as part of logging.
When the 'tag' log option is not included, there is no change
to the log content via the json-logger. When the 'tag' log option
is included, the tag will be parsed as a template and the result
will be stored within each log entry as the attribute 'tag'.
Update: Removing test added to integration_cli as those have been deprecated.
Update: Using proper test calls (require and assert) in jsonfilelog_test.go based on review.
Update: Added new unit test configs for logs with tag. Updated unit test error checking.
Update: Cleanup check in jsonlogbytes_test.go to match pending changes in PR #34946.
Update: Merging to correct conflicts from PR #34946.
Signed-off-by: bonczj <josh.bonczkowski@gmail.com>
Upstream-commit: 5f50f4f511cd84e79bf005817af346b1764df27f
Component: engine
This allows much of the read logic to be shared for other things,
especially for the new log driver proposed in
https://github.com/moby/moby/issues/33475
The only logic for reads in the json logger is around decoding log
messages, which gets passed into the log file object.
This also helps with implementing compression as it allows us to
simplify locking strategies.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 16f7cd674902b69b97692de2a83915a1a6be2cdb
Component: engine
Make the `*RotateFileWriter` specifically about writing
`logger.Message`'s, which is what it's used for.
This allows for future changes where the log writer can cache details
about log entries such as (e.g.) the timestamps included in a particular
log file, which can be used to optimize reads.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 52d82b4fbc9f0fe00f63e2df9a3d2a49d4095bda
Component: engine
Having a map per log entry seemed heavier than necessary. These
attributes end up being sorted and serialized, so storing them in a map
doesn't add anything (there's no random access element). In SwarmKit,
they originate as a slice, so there's an unnecessary conversion to a map
and back.
This also fixes the sort comparator, which used to inefficiently split
the string on each comparison.
Signed-off-by: Aaron Lehmann <aaron.lehmann@docker.com>
Upstream-commit: b642b3f21f17cf50c79e464d3aedc93b2dbf0fb0
Component: engine
Before this patch, a log reader is able to block all log writes
indefinitely (and other operations) by simply opening the log stream and
not consuming all the messages.
The reason for this is we protect the read stream from corruption by
ensuring there are no new writes while the log stream is consumed (and
caught up with the live entries).
We can get around this issue because log files are append only, so we
can limit reads to only the section of the file that was written to when
the log stream was first requested.
Now logs are only blocked until all files are opened, rather than
streamed to the client.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: e2209185ed1c959131d4068ec7fc93e194dc0802
Component: engine
This loop is not ever going to return since it's never actually setting
the `err` var except on the first iteration.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 7a179972ff963706404f91671960b144dec98d65
Component: engine
This reduces allocs and bytes used per log entry significantly as well
as some improvement to time per log operation.
Each log driver, however, must put messages back in the pool once they
are finished with the message.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Upstream-commit: 3f4fccb65f0ef286c9c4e0f01c4ae7bb09a6ad89
Component: engine
This commit addresses 2 issues:
1. in `tailfile()` if somehow the `logWatcher.Msg` were to become full and the watcher closed before space was made into it, we were getting stuck there forever since we were not checking for the watcher getting closed
2. when servicing `docker logs`, if the command was cancelled we were not closing the watcher (and hence notifying it to stop copying data)
Signed-off-by: Kenfe-Mickael Laventure <mickael.laventure@gmail.com>
Upstream-commit: fb2bb3653e2755d971f21debfecbd7c878a3c23f
Component: engine
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
