If a reader has caught up to the logger and is waiting for the next
message, it should stop waiting when the logger is closed. Otherwise
the reader will unnecessarily wait the full closedDrainTimeout for no
log messages to arrive.
This case was overlooked when the journald reader was recently
overhauled to be compatible with systemd 255, and the reader tests only
failed when a logical race happened to settle in such a way to exercise
the bugged code path. It was only after implicit flushing on close was
added to the journald test harness that the Follow tests would
repeatably fail due to this bug. (No new regression tests are needed.)
Signed-off-by: Cory Snider <csnider@mirantis.com>
errDrainDone is a sentinel error which is never supposed to escape the
package. Consequently, it needs to be filtered out of returns all over
the place, adding boilerplate. Forgetting to filter out these errors
would be a logic bug which the compiler would not help us catch. Replace
it with boolean multi-valued returns as they can't be accidentally
ignored or propagated.
Signed-off-by: Cory Snider <csnider@mirantis.com>
While it doesn't really matter if the reader waits for an extra
arbitrary period beyond an arbitrary hardcoded timeout, it's also
trivial and cheap to implement, and nice to have.
Signed-off-by: Cory Snider <csnider@mirantis.com>
The journald reader uses a timer to set an upper bound on how long to
wait for the final log message of a stopped container. However, the
timer channel is only received from in non-blocking select statements!
There isn't enough benefit of using a timer to offset the cost of having
to manage the timer resource. Setting a deadline and comparing the
current time is just as effective, without having to manage the
lifecycle of any runtime resources.
Signed-off-by: Cory Snider <csnider@mirantis.com>
The github.com/containerd/containerd/log package was moved to a separate
module, which will also be used by upcoming (patch) releases of containerd.
This patch moves our own uses of the package to use the new module.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Managed containerd processes are executed with SysProcAttr.Pdeathsig set
to syscall.SIGKILL so that the managed containerd is automatically
killed along with the daemon. At least, that is the intention. In
practice, the signal is sent to the process when the creating _OS
thread_ dies! If a goroutine exits while locked to an OS thread, the Go
runtime will terminate the thread. If that thread happens to be the
same thread which the subprocess was started from, the subprocess will
be signaled. Prevent the journald driver from sometimes unintentionally
killing child processes by ensuring that all runtime.LockOSThread()
calls are paired with runtime.UnlockOSThread().
Signed-off-by: Cory Snider <csnider@mirantis.com>
Implement --follow entirely correctly for the journald log reader, such
that it exits immediately upon reading back the last log message written
to the journal before the logger was closed. The impossibility of doing
so has been slightly exaggerated.
Signed-off-by: Cory Snider <csnider@mirantis.com>
Fix journald and logfile-powered (jsonfile, local) log readers
incorrectly filtering out messages with timestamps < Since which were
preceded by a message with a timestamp >= Since.
Signed-off-by: Cory Snider <csnider@mirantis.com>
Careful management of the journal read pointer is sufficient to ensure
that no entry is read more than once.
Unit test the journald logger without requiring a running journald by
using the systemd-journal-remote command to write arbitrary entries to
journal files.
Signed-off-by: Cory Snider <csnider@mirantis.com>
Wrap the libsystemd journal reading functionality in a more idiomatic Go
API and refactor the journald logging driver's ReadLogs implementation
to use the wrapper. Rewrite the parts of the ReadLogs implementation in
Go which were previously implemented in C as part of the cgo preamble.
Separating the business logic from the cgo minutiae should hopefully
make the code more accessible to a wider audience of developers for
reviewing the code and contributing improvements.
The structure of the ReadLogs implementation is retained with few
modifications. Any ignored errors were also ignored before the refactor;
the explicit error return values afforded by the sdjournal wrapper makes
this more obvious.
The package github.com/coreos/go-systemd/v22/sdjournal also provides a
more idiomatic Go wrapper around libsystemd. It is unsuitable for our
needs as it does not expose wrappers for the sd_journal_process and
sd_journal_get_fd functions.
Signed-off-by: Cory Snider <csnider@mirantis.com>
This was introduced in 906b979b88, which changed
a `goto` to a `break`, but afaics, the intent was still to break out of the loop.
(linter didn't catch this before because it didn't have the right build-tag set)
daemon/logger/journald/read.go:238:4: SA4011: ineffective break statement. Did you mean to break out of the outer loop? (staticcheck)
break // won't be able to write anything anymore
^
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Whether or not the logger has been closed is a property of the logger,
and only of concern to its log reading implementation, not log watchers.
The loggers and their reader implementations can communicate as they see
fit. A single channel per logger which is closed when the logger is
closed is plenty sufficient to broadcast the state to log readers, with
no extra bookeeping or synchronization required.
Signed-off-by: Cory Snider <csnider@mirantis.com>
daemon/logger/journald/read.go:128:3 comment on exported function `CErr` should be of the form `CErr ...`
daemon/logger/journald/read.go:131:36: unnecessary conversion (unconvert)
return C.GoString(C.strerror(C.int(-ret)))
^
daemon/logger/journald/read.go:380:2: S1023: redundant `return` statement (gosimple)
return
^
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
1. Use "in-place" variables for if statements to limit their scope to
the respectful `if` block.
2. Report the error returned from sd_journal_* by using CErr().
3. Use errors.New() instead of fmt.Errorf().
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
From the first glance, `docker logs --tail 0` does not make sense,
as it is supposed to produce no output, but `tail -n 0` from GNU
coreutils is working like that, plus there is even a test case
(`TestLogsTail` in integration-cli/docker_cli_logs_test.go).
Now, something like `docker logs --follow --tail 0` makes total
sense, so let's make it work.
(NOTE if --tail is not used, config.Tail is set to -1)
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
If we take a long time to process log messages, and during that time
journal file rotation occurs, the journald client library will keep
those rotated files open until sd_journal_process() is called.
By periodically calling sd_journal_process() during the processing
loop we shrink the window of time a client instance has open file
descriptors for rotated (deleted) journal files.
This code is modelled after that of journalctl [1]; the above explanation
as well as the value of 1024 is taken from there.
[v2: fix CErr() argument]
[1] https://github.com/systemd/systemd/blob/dc16327c48d/src/journal/journalctl.c#L2676
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
TL;DR: simplify the code, fix --follow hanging indefinitely
Do the following to simplify the followJournal() code:
1. Use Go-native select instead of C-native polling.
2. Use Watch{Producer,Consumer}Gone(), eliminating the need
to have journald.closed variable, and an extra goroutine.
3. Use sd_journal_wait(). In the words of its own man page:
> A synchronous alternative for using sd_journal_get_fd(),
> sd_journal_get_events(), sd_journal_get_timeout() and
> sd_journal_process() is sd_journal_wait().
Unfortunately, the logic is still not as simple as it
could be; the reason being, once the container has exited,
journald might still be writing some logs from its internal
buffers onto journal file(s), and there is no way to
figure out whether it's done so we are guaranteed to
read all of it back. This bug can be reproduced with
something like
> $ ID=$(docker run -d busybox seq 1 150000); docker logs --follow $ID
> ...
> 128123
> $
(The last expected output line should be `150000`).
To avoid exiting from followJournal() early, add the
following logic: once the container is gone, keep trying
to drain the journal until there's no new data for at
least `waitTimeout` time period.
Should fix https://github.com/docker/for-linux/issues/575
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
1. The journald client library initializes inotify watch(es)
during the first call to sd_journal_get_fd(), and it make sense
to open it earlier in order to not lose any journal file rotation
events.
2. It only makes sense to call this if we're going to use it
later on -- so add a check for config.Follow.
3. Remove the redundant call to sd_journal_get_fd().
NOTE that any subsequent calls to sd_journal_get_fd() return
the same file descriptor, so there's no real need to save it
for later use in wait_for_data_cancelable().
Based on earlier patch by Nalin Dahyabhai <nalin@redhat.com>.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
In case the LogConsumer is gone, the code that sends the message can
stuck forever. Wrap the code in select case, as all other loggers do.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
In case Tail=N parameter is requested, we need to show N lines.
It does not make sense to walk backwards one by one if we can
do it at once. Now, if Since=T is also provided, make sure we
haven't jumped too far (before T), and if we did, move forward.
The primary motivation for this was to make the code simpler.
This also fixes a tiny bug in the "since" implementation.
Before this commit:
> $ docker logs -t --tail=6000 --since="2019-03-10T03:54:25.00" $ID | head
> 2019-03-10T03:54:24.999821000Z 95981
After:
> $ docker logs -t --tail=6000 --since="2019-03-10T03:54:25.00" $ID | head
> 2019-03-10T03:54:25.000013000Z 95982
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
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)
