As in other similar drivers (jsonlog, local), use a set
(i.e. `map[whatever]struct{}`), making the code simpler.
While at it, make sure we remove the reader from the set
after calling `ProducerGone()` on it.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
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 a69a59ffc7 ("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>
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>
Make sure that the cursor value returned by followJournal() is the last
of the values returned by its goroutine's calls to drainJournal() by
waiting for it, rather than returning a value that may be superceded by
another if we're singalling the goroutine that it should exit by closing
a pipe.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com>
In the journald log driver, attempt to drain the journal 1 more time
after being told to stop following the log. Due to a possible race
condition, sometimes data is written to the journal at almost the same
time the log watch is closed, and depending on the order of operations,
sometimes you miss the last journal entry.
Signed-off-by: Andy Goldstein <agoldste@redhat.com>
We clean up the journald logger with these four changes.
1. Make field array static
2. Make function name more appropriate
3. Initialize the file descriptors only once
4. Avoid copying the journald cursor
Point 4 is the most significant change: instead of treating the journald
cursor like a Go string we use it as a raw C.char pointer. That way we
avoid the copying by the C.CString and C.GoString functions.
Signed-off-by: Silvan Jegen <s.jegen@gmail.com>
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)
When told to read additional attributes from logs that we've sent to the
journal, pull out all of the non-trusted, non-user fields that we didn't
hard-code ourselves. More of PR#20726 and PR#21889.
When reading entries in the journald log reader, set the time zone on
timestamps that we read to UTC, so that we send UTC values to the client
instead of values that are local to whatever timezone dockerd happens to
be running in.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
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>
Following a journal log almost always requires a descriptor to be
allocated. In cases where we're running out of descriptors, this means
we might get stuck while attempting to start following the journal, at a
point where it's too late to report it to the client and clean up
easily. The journal reading context will cache the value once it's
allocated, so here we move the check earlier, so that we can detect a
problem when we can still report it cleanly.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com>
When we set up to start following a journal, if we get error results
from sd_journal_get_fd() or sd_journal_get_events() that prevent us from
following the journal, report the error instead of just mysteriously
failing.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
When following a journal-based log, it was possible for the worker
goroutine, which reads the journal using the journal context and sends
entry data down the message channel, to be scheduled after the function
which started it had returned. This could create problems, since the
invoking function was closing the journal context object and message
channel before it returned, which could trigger use-after-free segfaults
and write-to-closed-channel panics in the worker goroutine.
Make the cleanup in the invoking function conditional so that it's only
done when we're not following the logs, and if we are, that it's left to
the worker goroutine to close them.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
The journald log reader keeps a map of following readers so that it can
close them properly when the journald reader object itself is closed,
but it was possible for its worker goroutine to be scheduled so that the
worker attempted to remove a reader from the map before the reader had
been added to the map. This patch adds the item to the map before
starting the goroutine which is expected to eventually remove it.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
When checking if we have the development files for libsystemd's journal
APIs, check for either 'libsystemd >= 209' and 'libsystemd-journal'. If
we find 'libsystemd', define the 'journald' tag, which defaults to using
the 'libsystemd.pc' file. If we find the older 'libsystemd-journal',
define both the 'journald' and 'journald_compat' tags, which causes the
'libsystemd-journal.pc' file to be consulted instead.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
@noxiouz points out that we don't need to check for a nil result from
C.CString(), since an out-of-memory condition causes a runtime panic
instead.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
If a logdriver doesn't register a callback function to validate log
options, it won't be usable. Fix the journald driver by adding a dummy
validator.
Teach the client and the daemon's "logs" logic that the server can also
supply "logs" data via the "journald" driver. Update documentation and
tests that depend on error messages.
Add support for reading log data from the systemd journal to the
journald log driver. The internal logic uses a goroutine to scan the
journal for matching entries after any specified cutoff time, formats
the messages from those entries as JSONLog messages, and stuffs the
results down a pipe whose reading end we hand back to the caller.
If we are missing any of the 'linux', 'cgo', or 'journald' build tags,
however, we don't implement a reader, so the 'logs' endpoint will still
return an error.
Make the necessary changes to the build setup to ensure that support for
reading container logs from the systemd journal is built.
Rename the Jmap member of the journald logdriver's struct to "vars" to
make it non-public, and to make it easier to tell that it's just there
to hold additional variable values that we want journald to record along
with log data that we're sending to it.
In the client, don't assume that we know which logdrivers the server
implements, and remove the check that looks at the server. It's
redundant because the server already knows, and the check also makes
using older clients with newer servers (which may have new logdrivers in
them) unnecessarily hard.
When we try to "logs" and have to report that the container's logdriver
doesn't support reading, send the error message through the
might-be-a-multiplexer so that clients which are expecting multiplexed
data will be able to properly display the error, instead of tripping
over the data and printing a less helpful "Unrecognized input header"
error.
Signed-off-by: Nalin Dahyabhai <nalin@redhat.com> (github: nalind)
