From 3a14578fd00458be128e74a60ac2a3c8cd902a7b Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Fri, 5 Mar 2021 21:00:24 -0800 Subject: [PATCH] runc run/start/exec: fix init log forwarding race 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 some undetermined 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. 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 eather than runc run; - refactors libcotainer/logs unit tests to simplify and update for the new ForwardLogs. PS I have to admit I still do not understand why closing 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 --- libcontainer/container_linux.go | 18 ++- libcontainer/container_linux_test.go | 3 +- libcontainer/factory_linux.go | 8 +- libcontainer/init_linux.go | 4 +- libcontainer/logs/logs.go | 26 ++-- libcontainer/logs/logs_linux_test.go | 175 ++++++++++++++------------- libcontainer/process_linux.go | 10 +- libcontainer/restored_process.go | 6 +- libcontainer/setns_init_linux.go | 10 ++ libcontainer/standard_init_linux.go | 14 +++ tests/integration/debug.bats | 1 + tests/integration/exec.bats | 34 +++++- 12 files changed, 201 insertions(+), 108 deletions(-) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index 65e2eace8c8..ac4beb63c5a 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -357,12 +357,26 @@ type openResult struct { err error } -func (c *linuxContainer) start(process *Process) error { +func (c *linuxContainer) start(process *Process) (retErr error) { parent, err := c.newParentProcess(process) if err != nil { return newSystemErrorWithCause(err, "creating new parent process") } - parent.forwardChildLogs() + + logsDone := parent.forwardChildLogs() + if logsDone != nil { + defer func() { + // Wait for log forwarder to finish. This depends + // on init closing the _LIBCONTAINER_LOGPIPE log fd: + // For standard init, this is done by closeLogFD. + // For setns init, the fd is closed upon execve. + err := <-logsDone + if err != nil && retErr == nil { + retErr = newSystemErrorWithCause(err, "forwarding init logs") + } + }() + } + if err := parent.start(); err != nil { return newSystemErrorWithCause(err, "starting container process") } diff --git a/libcontainer/container_linux_test.go b/libcontainer/container_linux_test.go index 2a9af6ad28e..78071a92651 100644 --- a/libcontainer/container_linux_test.go +++ b/libcontainer/container_linux_test.go @@ -139,7 +139,8 @@ func (m *mockProcess) externalDescriptors() []string { func (m *mockProcess) setExternalDescriptors(newFds []string) { } -func (m *mockProcess) forwardChildLogs() { +func (m *mockProcess) forwardChildLogs() chan error { + return nil } func TestGetContainerPids(t *testing.T) { diff --git a/libcontainer/factory_linux.go b/libcontainer/factory_linux.go index 0b4cf59eb19..972b0f2b5d9 100644 --- a/libcontainer/factory_linux.go +++ b/libcontainer/factory_linux.go @@ -365,6 +365,12 @@ func (l *LinuxFactory) StartInitialization() (err error) { defer consoleSocket.Close() } + 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) + } + // clear the current process's environment to clean any libcontainer // specific env vars. os.Clearenv() @@ -387,7 +393,7 @@ func (l *LinuxFactory) StartInitialization() (err error) { } }() - i, err := newContainerInit(it, pipe, consoleSocket, fifofd) + i, err := newContainerInit(it, pipe, consoleSocket, fifofd, logPipeFd) if err != nil { return err } diff --git a/libcontainer/init_linux.go b/libcontainer/init_linux.go index c57af0eebb8..00f28e1f7eb 100644 --- a/libcontainer/init_linux.go +++ b/libcontainer/init_linux.go @@ -76,7 +76,7 @@ type initer interface { Init() error } -func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd int) (initer, error) { +func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd, logFd int) (initer, error) { var config *initConfig if err := json.NewDecoder(pipe).Decode(&config); err != nil { return nil, err @@ -90,6 +90,7 @@ func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd pipe: pipe, consoleSocket: consoleSocket, config: config, + logFd: logFd, }, nil case initStandard: return &linuxStandardInit{ @@ -98,6 +99,7 @@ func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd parentPid: unix.Getppid(), config: config, fifoFd: fifoFd, + logFd: logFd, }, nil } return nil, fmt.Errorf("unknown init type %q", t) diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index f75084161a5..dd4c4a6a101 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -13,7 +13,7 @@ import ( ) var ( - configureMutex = sync.Mutex{} + configureMutex sync.Mutex // loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`. // Subsequent invocations of `ConfigureLogging` would be no-op loggingConfigured = false @@ -26,16 +26,22 @@ type Config struct { LogPipeFd int } -func ForwardLogs(logPipe io.Reader) { +func ForwardLogs(logPipe io.ReadCloser) chan error { + done := make(chan error, 1) s := bufio.NewScanner(logPipe) - for s.Scan() { - processEntry(s.Bytes()) - } - if err := s.Err(); err != nil { - logrus.Errorf("log pipe read error: %+v", err) - } else { - logrus.Debugf("log pipe closed") - } + + go func() { + for s.Scan() { + processEntry(s.Bytes()) + } + if err := logPipe.Close(); err != nil { + logrus.Errorf("error closing log source: %v", err) + } + done <- s.Err() + close(done) + }() + + return done } func processEntry(text []byte) { diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go index ec9ae4fc8b2..0baf7c4cbc0 100644 --- a/libcontainer/logs/logs_linux_test.go +++ b/libcontainer/logs/logs_linux_test.go @@ -1,10 +1,10 @@ package logs import ( - "errors" + "bytes" + "io" "io/ioutil" "os" - "strings" "testing" "time" @@ -12,141 +12,109 @@ import ( ) func TestLoggingToFile(t *testing.T) { - logW, logFile, _ := runLogForwarding(t) - defer os.Remove(logFile) - defer logW.Close() + l := runLogForwarding(t) - logToLogWriter(t, logW, `{"level": "info","msg":"kitten"}`) - - logFileContent := waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "kitten") { - t.Fatalf("%s does not contain kitten", logFileContent) - } + logToLogWriter(t, l, `{"level": "info","msg":"kitten"}`) + finish(t, l) + check(t, l, "kitten") } func TestLogForwardingDoesNotStopOnJsonDecodeErr(t *testing.T) { - logW, logFile, _ := runLogForwarding(t) - defer os.Remove(logFile) - defer logW.Close() - - logToLogWriter(t, logW, "invalid-json-with-kitten") + l := runLogForwarding(t) - logFileContent := waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "failed to decode") { - t.Fatalf("%q does not contain decoding error", logFileContent) - } - - truncateLogFile(t, logFile) + logToLogWriter(t, l, "invalid-json-with-kitten") + checkWait(t, l, "failed to decode") - logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`) + truncateLogFile(t, l.file) - logFileContent = waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "puppy") { - t.Fatalf("%s does not contain puppy", logFileContent) - } + logToLogWriter(t, l, `{"level": "info","msg":"puppy"}`) + finish(t, l) + check(t, l, "puppy") } func TestLogForwardingDoesNotStopOnLogLevelParsingErr(t *testing.T) { - logW, logFile, _ := runLogForwarding(t) - defer os.Remove(logFile) - defer logW.Close() + l := runLogForwarding(t) - logToLogWriter(t, logW, `{"level": "alert","msg":"puppy"}`) + logToLogWriter(t, l, `{"level": "alert","msg":"puppy"}`) + checkWait(t, l, "failed to parse log level") - logFileContent := waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "failed to parse log level") { - t.Fatalf("%q does not contain log level parsing error", logFileContent) - } - - truncateLogFile(t, logFile) - - logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`) + truncateLogFile(t, l.file) - logFileContent = waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "puppy") { - t.Fatalf("%s does not contain puppy", logFileContent) - } + logToLogWriter(t, l, `{"level": "info","msg":"puppy"}`) + finish(t, l) + check(t, l, "puppy") } func TestLogForwardingStopsAfterClosingTheWriter(t *testing.T) { - logW, logFile, doneForwarding := runLogForwarding(t) - defer os.Remove(logFile) + l := runLogForwarding(t) - logToLogWriter(t, logW, `{"level": "info","msg":"sync"}`) + logToLogWriter(t, l, `{"level": "info","msg":"sync"}`) - logFileContent := waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "sync") { - t.Fatalf("%q does not contain sync message", logFileContent) - } - - logW.Close() + // Do not use finish() here as we check done pipe ourselves. + l.w.Close() select { - case <-doneForwarding: + case <-l.done: case <-time.After(10 * time.Second): t.Fatal("log forwarding did not stop after closing the pipe") } + + check(t, l, "sync") } -func logToLogWriter(t *testing.T, logW *os.File, message string) { - _, err := logW.Write([]byte(message + "\n")) +func logToLogWriter(t *testing.T, l *log, message string) { + t.Helper() + _, err := l.w.Write([]byte(message + "\n")) if err != nil { t.Fatalf("failed to write %q to log writer: %v", message, err) } } -func runLogForwarding(t *testing.T) (*os.File, string, chan struct{}) { +type log struct { + w io.WriteCloser + file string + done chan error +} + +func runLogForwarding(t *testing.T) *log { + t.Helper() logR, logW, err := os.Pipe() if err != nil { t.Fatal(err) } + t.Cleanup(func() { + logR.Close() + logW.Close() + }) tempFile, err := ioutil.TempFile("", "") if err != nil { t.Fatal(err) } + defer tempFile.Close() logFile := tempFile.Name() + t.Cleanup(func() { os.Remove(logFile) }) logConfig := Config{LogLevel: logrus.InfoLevel, LogFormat: "json", LogFilePath: logFile} - return logW, logFile, startLogForwarding(t, logConfig, logR) -} - -func startLogForwarding(t *testing.T, logConfig Config, logR *os.File) chan struct{} { loggingConfigured = false if err := ConfigureLogging(logConfig); err != nil { t.Fatal(err) } - doneForwarding := make(chan struct{}) - go func() { - ForwardLogs(logR) - close(doneForwarding) - }() - return doneForwarding -} -func waitForLogContent(t *testing.T, logFile string) string { - startTime := time.Now() + done := ForwardLogs(logR) - for { - if time.Now().After(startTime.Add(10 * time.Second)) { - t.Fatal(errors.New("No content in log file after 10 seconds")) - break - } + return &log{w: logW, done: done, file: logFile} +} - fileContent, err := ioutil.ReadFile(logFile) - if err != nil { - t.Fatal(err) - } - if len(fileContent) == 0 { - continue - } - return string(fileContent) +func finish(t *testing.T, l *log) { + t.Helper() + l.w.Close() + if err := <-l.done; err != nil { + t.Fatalf("ForwardLogs: %v", err) } - - return "" } func truncateLogFile(t *testing.T, logFile string) { - file, err := os.OpenFile(logFile, os.O_RDWR, 0666) + file, err := os.OpenFile(logFile, os.O_RDWR, 0o600) if err != nil { t.Fatalf("failed to open log file: %v", err) return @@ -158,3 +126,40 @@ func truncateLogFile(t *testing.T, logFile string) { t.Fatalf("failed to truncate log file: %v", err) } } + +// check checks that file contains txt +func check(t *testing.T, l *log, txt string) { + t.Helper() + contents, err := ioutil.ReadFile(l.file) + if err != nil { + t.Fatal(err) + } + if !bytes.Contains(contents, []byte(txt)) { + t.Fatalf("%q does not contain %q", string(contents), txt) + } +} + +// checkWait checks that file contains txt. If the file is empty, +// it waits until it's not. +func checkWait(t *testing.T, l *log, txt string) { + t.Helper() + const ( + delay = 100 * time.Millisecond + iter = 3 + ) + for i := 0; ; i++ { + st, err := os.Stat(l.file) + if err != nil { + t.Fatal(err) + } + if st.Size() > 0 { + break + } + if i == iter { + t.Fatalf("waited %s for file %s to be non-empty but it still is", iter*delay, l.file) + } + time.Sleep(delay) + } + + check(t, l, txt) +} diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 6f2828770ee..8315d709aaa 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -51,7 +51,7 @@ type parentProcess interface { setExternalDescriptors(fds []string) - forwardChildLogs() + forwardChildLogs() chan error } type filePair struct { @@ -251,8 +251,8 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *setnsProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logFilePair.parent) +func (p *setnsProcess) forwardChildLogs() chan error { + return logs.ForwardLogs(p.logFilePair.parent) } type initProcess struct { @@ -605,8 +605,8 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *initProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logFilePair.parent) +func (p *initProcess) forwardChildLogs() chan error { + return logs.ForwardLogs(p.logFilePair.parent) } func getPipeFds(pid int) ([]string, error) { diff --git a/libcontainer/restored_process.go b/libcontainer/restored_process.go index f861e82d1b2..97565d7fa4b 100644 --- a/libcontainer/restored_process.go +++ b/libcontainer/restored_process.go @@ -77,7 +77,8 @@ func (p *restoredProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *restoredProcess) forwardChildLogs() { +func (p *restoredProcess) forwardChildLogs() chan error { + return nil } // nonChildProcess represents a process where the calling process is not @@ -125,5 +126,6 @@ func (p *nonChildProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *nonChildProcess) forwardChildLogs() { +func (p *nonChildProcess) forwardChildLogs() chan error { + return nil } diff --git a/libcontainer/setns_init_linux.go b/libcontainer/setns_init_linux.go index 6b1e9a6e97c..9e7fc37dc5a 100644 --- a/libcontainer/setns_init_linux.go +++ b/libcontainer/setns_init_linux.go @@ -12,6 +12,7 @@ import ( "github.com/opencontainers/runc/libcontainer/system" "github.com/opencontainers/selinux/go-selinux" "github.com/pkg/errors" + "github.com/sirupsen/logrus" "golang.org/x/sys/unix" ) @@ -21,6 +22,7 @@ type linuxSetnsInit struct { pipe *os.File consoleSocket *os.File config *initConfig + logFd int } func (l *linuxSetnsInit) getSessionRingName() string { @@ -86,5 +88,13 @@ func (l *linuxSetnsInit) Init() error { return newSystemErrorWithCause(err, "init seccomp") } } + logrus.Debugf("init: about to exec") + // Close the log pipe fd so the parent's ForwardLogs can exit. + // Usually this would be done upon system.Execv below, as the fd + // has CLOEXEC flag set, but it may fail. + if err := unix.Close(l.logFd); err != nil { + return newSystemErrorWithCause(err, "closing log pipe fd") + } + return system.Execv(l.config.Args[0], l.config.Args[0:], os.Environ()) } diff --git a/libcontainer/standard_init_linux.go b/libcontainer/standard_init_linux.go index 7ec506c462e..0dee51b624c 100644 --- a/libcontainer/standard_init_linux.go +++ b/libcontainer/standard_init_linux.go @@ -16,6 +16,7 @@ import ( "github.com/opencontainers/runtime-spec/specs-go" "github.com/opencontainers/selinux/go-selinux" "github.com/pkg/errors" + "github.com/sirupsen/logrus" "golang.org/x/sys/unix" ) @@ -24,6 +25,7 @@ type linuxStandardInit struct { consoleSocket *os.File parentPid int fifoFd int + logFd int config *initConfig } @@ -180,7 +182,19 @@ func (l *linuxStandardInit) Init() error { return err } // Close the pipe to signal that we have completed our init. + logrus.Debugf("init: closing the pipe to signal completion") l.pipe.Close() + + // Close the log pipe fd so the parent's ForwardLogs can exit. + // Usually this would be done upon execve as the file descriptor + // has CLOEXEC flag set, but (1) execve might not happen due to + // any kind of error below; (2) in case of runc start, it spawns + // runc init and exits, while runc init (this code) waits on fifo + // for an indefinitely long time. + if err := unix.Close(l.logFd); err != nil { + return newSystemErrorWithCause(err, "closing log pipe fd") + } + // Wait for the FIFO to be opened on the other side before exec-ing the // user process. We open it through /proc/self/fd/$fd, because the fd that // was given to us was an O_PATH fd to the fifo itself. Linux allows us to diff --git a/tests/integration/debug.bats b/tests/integration/debug.bats index cb7fe505c65..b2f87cf5f59 100644 --- a/tests/integration/debug.bats +++ b/tests/integration/debug.bats @@ -13,6 +13,7 @@ function teardown() { function check_debug() { [[ "$*" == *"nsexec started"* ]] [[ "$*" == *"child process in init()"* ]] + [[ "$*" == *"init: closing the pipe to signal completion"* ]] } @test "global --debug" { diff --git a/tests/integration/exec.bats b/tests/integration/exec.bats index b7c9becbf47..779e7480a8e 100644 --- a/tests/integration/exec.bats +++ b/tests/integration/exec.bats @@ -132,6 +132,38 @@ function teardown() { echo hello >preserve-fds.test # fd 3 is used by bats, so we use 4 exec 4&2 + # check expected debug output was sent to log.out + output=$(cat log.out) + [[ "${output}" == *"level=debug"* ]] + check_exec_debug "$output" +}