Reduce the amount of time ReadLogs holds the LogFile fsop lock by
releasing it as soon as all the files are opened, before parsing the
compressed file headers.
Signed-off-by: Cory Snider <csnider@mirantis.com>
File watches have been a source of complexity and unreliability in the
LogFile follow implementation, especially when combined with file
rotation. File change events can be unreliably delivered, especially on
Windows, and the polling fallback adds latency. Following across
rotations has never worked reliably on Windows. Without synchronization
between the log writer and readers, race conditions abound: readers can
read from the file while a log entry is only partially written, leading
to decode errors and necessitating retries.
In addition to the complexities stemming from file watches, the LogFile
follow implementation had complexity from needing to handle file
truncations, and (due to a now-fixed bug in the polling file watcher
implementation) evictions to unlock the log file so it could be rotated.
Log files are now always rotated, never truncated, so these situations
no longer need to be handled by the follow code.
Rewrite the LogFile follow implementation in terms of waiting until
LogFile notifies it that a new message has been written to the log file.
The LogFile informs the follower of the file offset of the last complete
write so that the follower knows not to read past that, preventing it
from attempting to decode partial messages and making retries
unnecessary. Synchronization between LogFile and its followers is used
at critical points to prevent missed notifications of writes and races
between file rotations and the follower opening files for read.
Signed-off-by: Cory Snider <csnider@mirantis.com>
The refCounter used for sharing temporary decompressed log files and
tracking when the files can be deleted is keyed off the source file's
path. But the path of a log file is not stable: it is renamed on each
rotation. Consequently, when logging is configured with both rotation
and compression, multiple concurrent readers of a container's logs could
read logs out of order, see duplicates or decompress a log file which
has already been decompressed.
Replace refCounter with a new implementation, sharedTempFileConverter,
which is agnostic to the file path, keying off the source file's
identity instead. Additionally, sharedTempFileConverter handles the full
lifecycle of the temporary file, from creation to deletion. This is all
abstracted from the consumer: all the bookkeeping and cleanup is handled
behind the scenes when Close() is called on the returned reader value.
Only one file descriptor is used per temporary file, which is shared by
all readers.
A channel is used for concurrency control so that the lock can be
acquired inside a select statement. While not currently utilized, this
makes it possible to add support for cancellation to
sharedTempFileConverter in the future.
Signed-off-by: Cory Snider <csnider@mirantis.com>
Truncating the current log file while a reader is still reading through
it results in log lines getting missed. In contrast, rotating the file
allows readers who have the file open can continue to read from it
undisturbed. Rotating frees up the file name for the logger to create a
new file in its place. This remains true even when max-file=1; the
current log file is "rotated" from its name without giving it a new one.
On POSIXy filesystem APIs, rotating the last file is straightforward:
unlink()ing a file name immediately deletes the name from the filesystem
and makes it available for reuse, even if processes have the file open
at the time. Windows on the other hand only makes the name available
for reuse once the file itself is deleted, which only happens when no
processes have it open. To reuse the file name while the file is still
in use, the file needs to be renamed. So that's what we have to do:
rotate the file to a temporary name before marking it for deletion.
Signed-off-by: Cory Snider <csnider@mirantis.com>
The json-file driver appends a newline character to log messages with
PLogMetaData.Last set, but the local driver did not. Alter the behavior
of the local driver to match that of the json-file driver.
Signed-off-by: Cory Snider <csnider@mirantis.com>
The LogFile follower would stop immediately upon the producer closing.
The close signal would race the file watcher; if a message were to be
logged and the logger immediately closed, the follower could miss that
last message if the close signal (formerly ProducerGone) was to win the
race. Add logic to perform one more round of reading when the producer
is closed to catch up on any final logs.
Signed-off-by: Cory Snider <csnider@mirantis.com>
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>
The asynchronous startup of the log-reading goroutine made the
follow-tail tests nondeterministic. The Log calls in the tests which
were supposed to happen after the reader started reading would sometimes
execute before the reader, throwing off the counts. Tweak the ReadLogs
implementation so that the order of operations is deterministic.
Signed-off-by: Cory Snider <csnider@mirantis.com>
Add an extensive test suite for validating the behavior of any
LogReader. Test the current LogFile-based implementations against it.
Signed-off-by: Cory Snider <csnider@mirantis.com>
The jsonfilelog read benchmark was incorrectly reusing the same message
pointer in the producer loop. The message value would be reset after the
first call to jsonlogger.Log, resulting in all subsequent calls logging
a zero-valued message. This is not a representative workload for
benchmarking and throws off the throughput metric.
Reduce variation between benchmark runs by using a constant timestamp.
Write to the producer goroutine's error channel only on a non-nil error
to eliminate spurious synchronization between producer and consumer
goroutines external to the logger being benchmarked.
Signed-off-by: Cory Snider <csnider@mirantis.com>
This commit replaces `os.Setenv` with `t.Setenv` in tests. The
environment variable is automatically restored to its original value
when the test and all its subtests complete.
Reference: https://pkg.go.dev/testing#T.Setenv
Signed-off-by: Eng Zer Jun <engzerjun@gmail.com>
Some packages were using `logrus.Fatal()` in init functions (which logs the error,
and (by default) calls `os.Exit(1)` after logging).
Given that logrus formatting and outputs have not yet been configured during the
initialization stage, it does not provide much benefits over a plain `panic()`.
This patch replaces some instances of `logrus.Fatal()` with `panic()`, which has
the added benefits of not introducing logrus as a dependency in some of these
packages, and also produces a stacktrace, which could help locating the problem
in the unlikely event an `init()` fails.
Before this change, an error would look like:
$ dockerd
FATA[0000] something bad happened
After this change, the same error looks like:
$ dockerd
panic: something bad happened
goroutine 1 [running]:
github.com/docker/docker/daemon/logger/awslogs.init.0()
/go/src/github.com/docker/docker/daemon/logger/awslogs/cloudwatchlogs.go:128 +0x89
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
pkg/urlutil (despite its poorly chosen name) is not really intended as a generic
utility to handle URLs, and should only be used by the builder to handle (remote)
build contexts.
This patch:
- fix some cases where the host was ignored for valid addresses.
- removes a redundant use of urlutil.IsTransportURL(); instead adding code to
check if the given scheme (protocol) is supported.
- improve port validation for out of range ports.
- fix some missing validation: the driver was silently ignoring path elements,
but expected a host (not an URL)
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
fix some missing validation: the driver was silently ignoring path elements
in some cases, and expecting a host (not an URL), and for unix sockets did
not validate if a path was specified.
For the latter case, we should have a fix in the upstream driver, as it
uses an empty path as default path for the socket (`defaultSocketPath`),
and performs no validation.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
pkg/urlutil (despite its poorly chosen name) is not really intended as a generic
utility to handle URLs, and should only be used by the builder to handle (remote)
build contexts.
This patch:
- removes a redundant use of urlutil.IsTransportURL(); instead adding some code
to check if the given scheme (protocol) is supported.
- define a `defaultPort` const for the default port.
- use `net.JoinHostPort()` instead of string concatenating, to account for possible
issues with IPv6 addresses.
- renames a variable that collided with an imported package.
- improves test coverage, and moves an integration test.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
pkg/urlutil (despite its poorly chosen name) is not really intended as a generic
utility to handle URLs, and should only be used by the builder to handle (remote)
build contexts.
This patch removes the use of urlutil.IsURL(), in favor of just checking if the
provided scheme (protocol) is supported.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
pkg/urlutil (despite its poorly chosen name) is not really intended as a generic
utility to handle URLs, and should only be used by the builder to handle (remote)
build contexts.
This patch:
- removes a redundant use of urlutil.IsTransportURL(); code further below already
checked if the given scheme (protocol) was supported.
- renames some variables that collided with imported packages.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
This function is marked deprecated in Go 1.18; however, the suggested replacement
brings in a large amount of new code, and most strings we generate will be ASCII,
so this would only be in case it's used for some user-provided string. We also
don't have a language to use, so would be using the "default".
Adding a `//nolint` comment to suppress the linting failure instead.
daemon/logger/templates/templates.go:23:14: SA1019: strings.Title is deprecated: The rule Title uses for word boundaries does not handle Unicode punctuation properly. Use golang.org/x/text/cases instead. (staticcheck)
"title": strings.Title,
^
pkg/plugins/pluginrpc-gen/template.go:67:9: SA1019: strings.Title is deprecated: The rule Title uses for word boundaries does not handle Unicode punctuation properly. Use golang.org/x/text/cases instead. (staticcheck)
return strings.Title(s)
^
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
The log message's timestamp was being read after it was returned to the
pool. By coincidence the timestamp field happened to not be zeroed on
reset so much of the time things would work as expected. But if the
message value was to be taken back out of the pool before WriteLogEntry
returned, the timestamp recorded in the gzip header of compressed
rotated log files would be incorrect.
Make future use-after-put bugs fail fast by zeroing all fields of the
Message value, including the timestamp, when it is put into the pool.
Signed-off-by: Cory Snider <csnider@mirantis.com>
followLogs() is getting really long (170+ lines) and complex.
The function has multiple inner functions that mutate its variables.
To refactor the function, this change introduces follow{} struct.
The inner functions are now defined as ordinal methods, which are
accessible from tests.
Signed-off-by: Kazuyoshi Kato <katokazu@amazon.com>
* When async is enabled, this option defines the interval (ms) at which the connection
to the fluentd-address is re-established. This option is useful if the address
may resolve to one or more IP addresses, e.g. a Consul service address.
While the change in #42979 resolves the issue where a Docker container can be stuck
if the fluentd-address is unavailable, this functionality adds an additional benefit
in that a new and healthy fluentd-address can be resolved, allowing logs to flow once again.
This adds a `fluentd-async-reconnect-interval` log-opt for the fluentd logging driver.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
Signed-off-by: Conor Evans <coevans@tcd.ie>
Co-authored-by: Sebastiaan van Stijn <github@gone.nl>
Co-authored-by: Conor Evans <coevans@tcd.ie>
Before this change, if Decode() couldn't read a log record fully,
the subsequent invocation of Decode() would read the record's non-header part
as a header and cause a huge heap allocation.
This change prevents such a case by having the intermediate buffer in
the decoder struct.
Fixes#42125.
Signed-off-by: Kazuyoshi Kato <katokazu@amazon.com>
The flag ForceStopAsyncSend was added to fluent logger lib in v1.5.0 (at
this time named AsyncStop) to tell fluentd to abort sending logs
asynchronously as soon as possible, when its Close() method is called.
However this flag was broken because of the way the lib was handling it
(basically, the lib could be stucked in retry-connect loop without
checking this flag).
Since fluent logger lib v1.7.0, calling Close() (when ForceStopAsyncSend
is true) will really stop all ongoing send/connect procedure,
wherever it's stucked.
Signed-off-by: Albin Kerouanton <albinker@gmail.com>
Added an option 'awslogs-format' to allow specifying
a log format for the logs sent CloudWatch from the aws log driver.
For now, only the 'json/emf' format is supported.
If no option is provided, the log format header in the
request to CloudWatch will be omitted as before.
Signed-off-by: James Sanders <james3sanders@gmail.com>
The io/ioutil package has been deprecated in Go 1.16. This commit
replaces the existing io/ioutil functions with their new definitions in
io and os packages.
Signed-off-by: Eng Zer Jun <engzerjun@gmail.com>
daemon/volumes_unix_test.go:228:13: SA4001: &*x will be simplified to x. It will not copy x. (staticcheck)
mp: &(*c.MountPoints["/jambolan"]), // copy the mountpoint, expect no changes
^
daemon/logger/local/local_test.go:214:22: SA4001: &*x will be simplified to x. It will not copy x. (staticcheck)
dst.PLogMetaData = &(*src.PLogMetaData)
^
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
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>
Logging to daemon logs every time there's an error with a log driver can be
problematic since daemon logs can grow rapidly, potentially exhausting disk
space.
Instead, it's preferable to limit the rate at which log driver errors are allowed
to be written. By default, this limit is 333 entries per second max.
Signed-off-by: Angel Velazquez <angelcar@amazon.com>
The underlying Loggers Close() function can be called with the the
run() goroutine still writing to the driver. This is causing the
fluentd-golang-logger to panic cause it doesn't defensively check
for the closing of the channel before writing to it.
It relies on the docker daemon to keep the contract of not calling Log()
if Close() has already been called.
Contributions by: James Johnston <james.johnston@thumbtack.com>
Nathan Wong <nathanw@thumbtack.com>
Signed-off-by: Anuj Varma <anujvarma@thumbtack.com>
Tonis mentioned that we can run into issues if there is more error
handling added here. This adds a custom reader implementation which is
like io.MultiReader except it does not cache EOF's.
What got us into trouble in the first place is `io.MultiReader` will
always return EOF once it has received an EOF, however the error
handling that we are going for is to recover from an EOF because the
underlying file is a file which can have more data added to it after
EOF.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
When the multireader hits EOF, we will always get EOF from it, so we
cannot store the multrireader fro later error handling, only for the
decoder.
Thanks @tobiasstadler for pointing this error out.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Added an option `awslogs-create-stream` to allow skipping log stream
creation for awslogs log driver. The default value is still true to
keep the behavior be consistent with before.
Signed-off-by: Xia Wu <xwumzn@amazon.com>
Loggers that implement BufSize() (e.g. awslogs) uses the method to
tell Copier about the maximum log line length. However loggerWithCache
and RingBuffer hide the method by wrapping loggers.
As a result, Copier uses its default 16KB limit which breaks log
lines > 16kB even the destinations can handle that.
This change implements BufSize() on loggerWithCache and RingBuffer to
make sure these logger wrappes don't hide the method on the underlying
loggers.
Fixes#41794.
Signed-off-by: Kazuyoshi Kato <katokazu@amazon.com>
This fixes the case where log rotation fails on Windows while there are
clients reading container logs.
Evicts readers if there is an error during rotation and try rotation again.
This is needed for Windows with this scenario:
1. `docker logs -f` is called
2. Log rotation occurs (log.txt -> log.txt.1, truncate and re-open
log.txt)
3. Log rotation occurs again (rm log.txt.1, log.txt -> log.txt.1)
On step 3, before this change, the log rotation will fail with `Access
is denied`.
In this case, what we have is a reader holding a file handle to the
primary log file. The log file is then rotated, but the reader still has
a the handle open. `FILE_SHARE_DELETE` allows this to happen... but then
we try to do it again for the next rotation and it blows up.
So when it blows up we force all the readers to disconnect, close the
log file, and try rotation again, which will succeed based on the added
tests.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
This makes sure, on Windows, that all files are opened with
FILE_SHARE_DELETE.
On non-Windows this just calls the same `os.Open()`.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
- Ignore some pointless errors (like not exist on remove)
- Consolidate error handling/logging
- Fix race condition reading last log timestamp in the compression
goroutine. This needs to be done while holding the write lock, which
is not (or may not be) locked while compressing a rotated log file.
- Remove some indentation and consolidate mutex unlocking in
`compressFile`
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
The cloud logging client should be closed when the log driver is closed. Otherwise dockerd will keep a gRPC connection to the logging endpoint open indefinitely.
This results in a slow leak of tcp sockets (1) and memory (~200Kb) any time that a container using `--log-driver=gcplogs` is terminates.
Signed-off-by: Patrick Haas <patrickhaas@google.com>
add all partial metadata available to journald logs to allow easier reassembly of partial messages in downstream logging systems
fixes#41403
Signed-off-by: Christian Becker <christian.becker@sixt.com>
The test was looking for the wrong file name.
Since compression happens asyncronously, sometimes the test would
succeed and sometimes fail.
This change makes sure to wait for the compressed version of the file
since we can't know when the compression is going to occur.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
This prevents getting into a situation where a container log cannot make
progress because we tried to rotate a file, got an error, and now the
file is closed. The next time we try to write a log entry it will try
and rotate again but error that the file is already closed.
I wonder if there is more we can do to beef up this rotation logic.
Found this issue while investigating missing logs with errors in the
docker daemon logs like:
```
Failed to log message for json-file: error closing file: close <file>:
file already closed
```
I'm not sure why the original rotation failed since the data was no
longer available.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Before this change, the log decoder function provided by the log driver
to logfile would not be able to re-use buffers, causing undeeded
allocations and memory bloat for dockerd.
This change introduces an interface that allows the log driver to manage
it's memory usge more effectively.
This only affects json-file and local log drivers.
`json-file` still is not great just because of how the json decoder in the
stdlib works.
`local` is significantly improved.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
Configuration over the API per container is intentionally left out for
the time being, but is supported to configure the default from the
daemon config.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
(cherry picked from commit cbecf48bc352e680a5390a7ca9cff53098cd16d7)
Signed-off-by: Madhu Venugopal <madhu@docker.com>
This supplements any log driver which does not support reads with a
custom read implementation that uses a local file cache.
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
(cherry picked from commit d675e2bf2b75865915c7a4552e00802feeb0847f)
Signed-off-by: Madhu Venugopal <madhu@docker.com>
This adds a new `fluentd-request-ack` logging option for the Fluentd
logging driver. If enabled, the server will respond with an acknowledgement.
This option improves the reliability of the message transmission. This
change is not versioned, and affects all API versions.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
This extracts parsing the driver's configuration to a
function, and uses the same function both when initializing
the driver, and when validating logging options.
Doing so allows validating if the provided options are in
the correct format when calling `ValidateOpts`, instead
of resulting in an error when initializing the logging driver.
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
The [gelf payload specification](http://docs.graylog.org/en/2.4/pages/gelf.html#gelf-payload-specification)
demands that the field `short_message` *MUST* be set by the client library.
Since docker logging via the gelf driver sends messages line by line, it can happen that messages with an empty
`short_message` are passed on. This causes strict downstream processors (like graylog) to raise an exception.
The logger now skips messages with an empty line.
Resolves: #40232
See also: #37572
Signed-off-by: Jonas Heinrich <Jonas@JonasHeinrich.com>
Previously there was no way for the splunk log driver to work if index
acknowledgment was set on the HEC, and it would in fact fail silently.
This will now allow users to specify if index acknowledgment is set and
will work with that setting.
Signed-off-by: Devon Estes <devon.c.estes@gmail.com>
About github.com/opencontainers/runc/libcontainer/user:
According to 195d8d544a
this package has two functions:
- Have a static implementation of user lookup, which is now supported in the
os/user stdlib package with the osusergo build tag, but wasn't at the time.
- Have extra functions that os/user doesn't have, but none of those are used
in homedir.
Since https://github.com/moby/moby/pull/11287, homedir depended directly on
libcontainer's user package for CurrentUser().
This is being replaced with os/user.Current(), because all of our static
binaries are compiled with the osusergo tag, and for dynamic libraries it
is more correct to use libc's implementation than parsing /etc/passwd.
About github.com/docker/docker/pkg/idtools:
Only dependency was from GetStatic() which uses idtools.LookupUID(uid).
The implementation of idtools.LookupUID just calls to
github.com/opencontainers/runc/libcontainer/user.LookupUid or fallbacks
to exec-ing to getent (since https://github.com/moby/moby/pull/27599).
This patch replaces calls to homedir.GetStatic by homedir.Get(), opting out
of supporting nss lookups in static binaries via exec-ing to getent for
the homedir package.
If homedir package users need to support nss lookups, they are advised
to compile dynamically instead.
Signed-off-by: Tibor Vass <tibor@docker.com>
This fixes issues where one goroutine tries to delete or rename a file
while another goroutine has the file open (e.g. a log reader).
Signed-off-by: Brian Goff <cpuguy83@gmail.com>
In case jsonlogfile is used with max-file=1 and max-size set,
the log rotation is not perfomed; instead, the log file is closed
and re-open with O_TRUNC.
This situation is not handled by the log reader in follow mode,
leading to an issue of log reader being stuck forever.
This situation (file close/reopen) could be handled in waitRead(),
but fsnotify library chose to not listen to or deliver this event
(IN_CLOSE_WRITE in inotify lingo).
So, we have to handle this by checking the file size upon receiving
io.EOF from the log reader, and comparing the size with the one received
earlier. In case the new size is less than the old one, the file was
truncated and we need to seek to its beginning.
Fixes#39235.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
TestLogBlocking is intended to test that the Log method blocks by
default. It does this by mocking out the internals of the
awslogs.logStream and replacing one of its internal channels with one
that is controlled by the test. The call to Log occurs inside a
goroutine. Go may or may not schedule the goroutine immediately and the
blocking may or may not be observed outside the goroutine immediately
due to decisions made by the Go runtime. This change adds a small
timeout for test failure so that the Go runtime has the opportunity to
run the goroutine before the test fails.
Signed-off-by: Samuel Karp <skarp@amazon.com>
this looks to be a false positive, but this field is not
used if journald is not supported, which may be the cause
```
daemon/logger/journald/journald.go:21:2: U1000: field `mu` is unused (unused)
```
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
staticcheck go linter says:
> daemon/logger/copier_test.go:451:2: SA2002: the goroutine calls T.Fatal, which must be called in the same goroutine as the test (staticcheck)
What it doesn't say is why. The reason is, t.Fatal() calls t.FailNow(),
which is expected to stop test execution right now. It does so by
calling runtime.Goexit(), which, unless called from a main goroutine,
does not stop test execution.
Anyway, long story short, if we don't care much about stopping the test
case immediately, we can just replace t.Fatalf() with t.Errorf() which
still marks the test case as failed, but won't stop it immediately.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Fix warnings like this one:
> daemon/logger/jsonfilelog/jsonfilelog_test.go:191:3: SA5001: should check returned error before deferring file.Close() (staticcheck)
> defer file.Close()
> ^
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Format the source according to latest goimports.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
