Fix init log forwarding race #2835

kolyshkin · 2021-03-06T05:44:56Z

(originally developed in #2487; decided to split for clarity)

Sometimes debug.bats test cases are failing like this (issue #2756):

not ok 27 global --debug to --log --log-format 'json'
# (in test file tests/integration/debug.bats, line 77)
#   `[[ "${output}" == *"child process in init()"* ]]' failed

It happens more often while writing to disk.

The issue is caused by the fact that runc spawns log forwarding goroutine
(ForwardLogs) but does not wait for it to finish, resulting in missing
debug lines from nsexec.

ForwardLogs itself, though, never finishes, because it reads from a
reading side of a pipe whose writing side is not closed. This is
especially true in case of runc create, which spawns runc init and
exits; meanwhile runc init waits on exec fifo for some undetermined long
time before doing execve.

So, to fix the issue described above, we need to:

Make runc create/run/exec wait for ForwardLogs to finish;
Make runc init close its log pipe file descriptor (i.e.
the one which value is passed in _LIBCONTAINER_LOGPIPE
environment variable).

This is exactly what this commit does. In addition, it

adds logrus debug to late stages of runc init, and amends the
integration tests to check for those messages;
adds runc --debug exec test cases, similar to those in debug.bats
but for runc exec rather than runc run;
refactors libcontainer/logs unit tests to simplify and update for
the new ForwardLogs.

PS I have to admit I still do not understand why an explicit closing of log pipe
fd is required in e.g. (*linuxSetnsInit).Init, right before the execve
which (thanks to CLOEXEC) closes the fd anyway.

Fixes: #2756

kolyshkin · 2021-03-08T21:45:52Z

Looks like the "checkpoint --lazy-pages and restore" test case has stuck on Fedora, resulting in a timeout. Haven't seen it before.

CI restarted.

kolyshkin · 2021-03-10T20:06:14Z

Looks like the "checkpoint --lazy-pages and restore" test case has stuck on Fedora, resulting in a timeout. Haven't seen it before.

It was probably the VM itself, not the test case that got stuck (seen it elsewhere the same day)

kolyshkin · 2021-03-10T22:20:48Z

@cyphar @AkihiroSuda @mrunalp PTAL

kolyshkin · 2021-03-11T19:37:36Z

The last commit was kinda heavy and thus complex to review -- I have split it into three smaller and much more digestible ones.

kolyshkin · 2021-03-15T21:51:38Z

@cyphar @AkihiroSuda PTAL

libcontainer/container_linux.go

cyphar · 2021-03-18T05:17:29Z

I have to admit I still do not understand why an explicit closing of log pipe
fd is required in e.g. (*linuxSetnsInit).Init, right before the execve
which (thanks to CLOEXEC) closes the fd anyway.

It's to work around a kernel bug we found (and fixed in 4.10) during the resolution of CVE-2016-9962. Basically it turned out that O_CLOEXEC was applied after the non-dumpable flag was reset during execve(2) -- leading to a race where a container process could access host file descriptors that were marked O_CLOEXEC. So we just have a general policy in runc to close file descriptors even if O_CLOEXEC should be enough (and it is enough on newer kernels).

kolyshkin · 2021-03-18T19:13:04Z

It's to work around a kernel bug we found (and fixed in 4.10) during the resolution of CVE-2016-9962. Basically it turned out that O_CLOEXEC was applied after the non-dumpable flag was reset during execve(2) -- leading to a race where a container process could access host file descriptors that were marked O_CLOEXEC. So we just have a general policy in runc to close file descriptors even if O_CLOEXEC should be enough (and it is enough on newer kernels).

No, I was asking about the code that I have added in this PR, see unix.Close(l.logFd) in 9def77a#diff-f8136d4f3312c98ab4c92c6227d5b7731fb1d10d419afc88ffa02b3018187dc0 or https://github.com/kolyshkin/runc/blob/fix-init-log-race/libcontainer/setns_init_linux.go#L91-L97).

Anyway, this PR is working correctly, so my interest is purely theoretical.

kolyshkin · 2021-03-22T22:55:48Z

Added area/ci as it fixes a long-standing CI flake (#2756).

Once this is in, #2836 will be unblocked.

libcontainer/logs/logs_linux_test.go

kolyshkin · 2021-03-26T01:52:32Z

libcontainer/factory_linux.go

+	logPipeFdStr := os.Getenv("_LIBCONTAINER_LOGPIPE")
+	logPipeFd, err := strconv.Atoi(logPipeFdStr)
+	if err != nil {
+		return fmt.Errorf("unable to convert _LIBCONTAINER_LOGPIPE=%s to int: %s", logPipeFdStr, err)
+	}
+


Alternatively, we can pass logFd as a parameter to StartInitalization as we just converted it from env in init.go...

Decided to do it this way since all the other parameters are obtained from environment right here.

It does not make sense to have a string for a numeric type. Signed-off-by: Kir Kolyshkin <[email protected]>

1. Remove redundant "echo $output" from the first test case, as "runc" helper function already logs the output. 2. Show the contents of log.out to stderr, so it case of error we can see what is going on. 3. Remove the check that `log.out` file exists. This check is redundant, since right after it we do `cat log.out` and check its exit code. 4. Factor out common checks into check_debug. Signed-off-by: Kir Kolyshkin <[email protected]>

Error handling is slightly cleaner this way. While at it, do minor refactoring and fix error logging in processEntry. Signed-off-by: Kir Kolyshkin <[email protected]>

This fixes a big red warning in my vim. Signed-off-by: Kir Kolyshkin <[email protected]>

I have noticed that ConfigureLogs do not return an error in case logging was already configured -- instead it just warns about it. So I went ahead and changed the warning to the actual error... ... only to discover I broke things badly, because in case of runc init logging is configured twice. The fix is to not configure logging in case we are init. Signed-off-by: Kir Kolyshkin <[email protected]>

- add check, checkWait, and finish helpers; - move test cleanup to runLogForwarding; - introduce and use log struct. Signed-off-by: Kir Kolyshkin <[email protected]>

Sometimes debug.bats test cases are failing like this: > not ok 27 global --debug to --log --log-format 'json' > # (in test file tests/integration/debug.bats, line 77) > # `[[ "${output}" == *"child process in init()"* ]]' failed It happens more when writing to disk. This issue is caused by the fact that runc spawns log forwarding goroutine (ForwardLogs) but does not wait for it to finish, resulting in missing debug lines from nsexec. ForwardLogs itself, though, never finishes, because it reads from a reading side of a pipe which writing side is not closed. This is especially true in case of runc create, which spawns runc init and exits; meanwhile runc init waits on exec fifo for arbitrarily long time before doing execve. So, to fix the failure described above, we need to: 1. Make runc create/run/exec wait for ForwardLogs to finish; 2. Make runc init close its log pipe file descriptor (i.e. the one which value is passed in _LIBCONTAINER_LOGPIPE environment variable). This is exactly what this commit does: 1. Amend ForwardLogs to return a channel, and wait for it in start(). 2. In runc init, save the log fd and close it as late as possible. PS I have to admit I still do not understand why an explicit close of log pipe fd is required in e.g. (*linuxSetnsInit).Init, right before the execve which (thanks to CLOEXEC) closes the fd anyway. Signed-off-by: Kir Kolyshkin <[email protected]>

First, add runc --debug exec test cases, very similar to those in debug.bats but for runc exec (rather than runc run). Do not include json tests as it is already tested in debug.bats. Second, add logrus debug to late stages of runc init, and amend the integration tests to check for those messages. This serves two purposes: - demonstrate that runc init can be amended with debug logrus which is properly forwarded to and logged by the parent runc create/run/exec; - improve the chances to catch the race fixed by the previous commit. Signed-off-by: Kir Kolyshkin <[email protected]>

This was referenced Mar 6, 2021

Improve nsexec logging #2487

Closed

Improve nsexec logging #2836

Merged

kolyshkin requested review from cyphar and mrunalp March 8, 2021 16:01

kolyshkin force-pushed the fix-init-log-race branch from 3a14578 to d4210f6 Compare March 8, 2021 16:10

kolyshkin added the area/logging label Mar 8, 2021

kolyshkin added this to the 1.0.0-rc94 milestone Mar 8, 2021

kolyshkin mentioned this pull request Mar 8, 2021

[centos7] not ok 15 checkpoint --lazy-pages and restore #2760

Closed

kolyshkin force-pushed the fix-init-log-race branch from d4210f6 to 897d121 Compare March 11, 2021 19:35

mrunalp previously approved these changes Mar 12, 2021

View reviewed changes

kolyshkin mentioned this pull request Mar 17, 2021

libcontainer/apparmor: use sync.Once for AppArmor detection #2852

Merged

kolyshkin commented Mar 17, 2021

View reviewed changes

libcontainer/container_linux.go Outdated Show resolved Hide resolved

kolyshkin dismissed mrunalp’s stale review via 98fd91f March 18, 2021 02:07

kolyshkin force-pushed the fix-init-log-race branch 2 times, most recently from 98fd91f to 18dcb35 Compare March 18, 2021 02:07

kolyshkin added the area/ci label Mar 22, 2021

kolyshkin commented Mar 26, 2021

View reviewed changes

libcontainer/logs/logs_linux_test.go Outdated Show resolved Hide resolved

kolyshkin commented Mar 26, 2021

View reviewed changes

kolyshkin added 4 commits March 25, 2021 18:56

libcontainer/logs: use int for Config.LogPipeFd

d38d1f9

It does not make sense to have a string for a numeric type. Signed-off-by: Kir Kolyshkin <[email protected]>

libct/logs.ForwardLogs: use bufio.Scanner

69ec21a

Error handling is slightly cleaner this way. While at it, do minor refactoring and fix error logging in processEntry. Signed-off-by: Kir Kolyshkin <[email protected]>

main: cast Chmod argument to os.FileMode

dd6c8d7

This fixes a big red warning in my vim. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin added 4 commits March 25, 2021 18:56

libct/logs/test: refactor

c06f999

- add check, checkWait, and finish helpers; - move test cleanup to runLogForwarding; - introduce and use log struct. Signed-off-by: Kir Kolyshkin <[email protected]>

kolyshkin force-pushed the fix-init-log-race branch from 18dcb35 to 2726146 Compare March 26, 2021 02:20

AkihiroSuda approved these changes Mar 26, 2021

View reviewed changes

mrunalp approved these changes Mar 26, 2021

View reviewed changes

mrunalp merged commit 5479510 into opencontainers:master Mar 26, 2021

kolyshkin mentioned this pull request Mar 31, 2021

libct: fix some container.Run fd leaks, add fd leak test #2802

Merged

kolyshkin mentioned this pull request Dec 8, 2022

support to print stack #3667

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix init log forwarding race #2835

Fix init log forwarding race #2835

kolyshkin commented Mar 6, 2021 •

edited

Loading

kolyshkin commented Mar 8, 2021

kolyshkin commented Mar 10, 2021

kolyshkin commented Mar 10, 2021

kolyshkin commented Mar 11, 2021

kolyshkin commented Mar 15, 2021

cyphar commented Mar 18, 2021

kolyshkin commented Mar 18, 2021

kolyshkin commented Mar 22, 2021

kolyshkin Mar 26, 2021

Fix init log forwarding race #2835

Fix init log forwarding race #2835

Conversation

kolyshkin commented Mar 6, 2021 • edited Loading

kolyshkin commented Mar 8, 2021

kolyshkin commented Mar 10, 2021

kolyshkin commented Mar 10, 2021

kolyshkin commented Mar 11, 2021

kolyshkin commented Mar 15, 2021

cyphar commented Mar 18, 2021

kolyshkin commented Mar 18, 2021

kolyshkin commented Mar 22, 2021

kolyshkin Mar 26, 2021

Choose a reason for hiding this comment

kolyshkin commented Mar 6, 2021 •

edited

Loading