From 201d60c51d0b78afb780841443200a25d63493a6 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 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 --- libcontainer/container_linux.go | 16 ++++++++++++++-- libcontainer/container_linux_test.go | 3 ++- libcontainer/factory_linux.go | 8 +++++++- libcontainer/init_linux.go | 4 +++- libcontainer/logs/logs.go | 28 ++++++++++++++++++---------- libcontainer/logs/logs_linux_test.go | 13 ++++++------- libcontainer/process_linux.go | 10 +++++----- libcontainer/restored_process.go | 6 ++++-- libcontainer/setns_init_linux.go | 6 ++++++ libcontainer/standard_init_linux.go | 7 +++++++ 10 files changed, 72 insertions(+), 29 deletions(-) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index b5c7764aa..93556a653 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -357,12 +357,24 @@ 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 + // runc init closing the _LIBCONTAINER_LOGPIPE log fd. + 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 2a9af6ad2..78071a926 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 0b4cf59eb..972b0f2b5 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 c57af0eeb..00f28e1f7 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 f75084161..b114a5f50 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,24 @@ 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) + } + // The only error we want to return is when reading from + // logPipe has failed. + 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 08b6dbeea..7e2b59d9c 100644 --- a/libcontainer/logs/logs_linux_test.go +++ b/libcontainer/logs/logs_linux_test.go @@ -72,7 +72,7 @@ func logToLogWriter(t *testing.T, l *log, message string) { type log struct { w io.WriteCloser file string - done chan struct{} + done chan error } func runLogForwarding(t *testing.T) *log { @@ -99,11 +99,8 @@ func runLogForwarding(t *testing.T) *log { if err := ConfigureLogging(logConfig); err != nil { t.Fatal(err) } - doneForwarding := make(chan struct{}) - go func() { - ForwardLogs(logR) - close(doneForwarding) - }() + + doneForwarding := ForwardLogs(logR) return &log{w: logW, done: doneForwarding, file: logFile} } @@ -111,7 +108,9 @@ func runLogForwarding(t *testing.T) *log { func finish(t *testing.T, l *log) { t.Helper() l.w.Close() - <-l.done + if err := <-l.done; err != nil { + t.Fatalf("ForwardLogs: %v", err) + } } func truncateLogFile(t *testing.T, logFile string) { diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 6f2828770..8315d709a 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 f861e82d1..97565d7fa 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 6b1e9a6e9..5dc7a0684 100644 --- a/libcontainer/setns_init_linux.go +++ b/libcontainer/setns_init_linux.go @@ -21,6 +21,7 @@ type linuxSetnsInit struct { pipe *os.File consoleSocket *os.File config *initConfig + logFd int } func (l *linuxSetnsInit) getSessionRingName() string { @@ -86,5 +87,10 @@ func (l *linuxSetnsInit) Init() error { return newSystemErrorWithCause(err, "init seccomp") } } + // Close the log pipe fd so the parent's ForwardLogs can exit. + 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 7ec506c46..60f9b79ed 100644 --- a/libcontainer/standard_init_linux.go +++ b/libcontainer/standard_init_linux.go @@ -24,6 +24,7 @@ type linuxStandardInit struct { consoleSocket *os.File parentPid int fifoFd int + logFd int config *initConfig } @@ -181,6 +182,12 @@ func (l *linuxStandardInit) Init() error { } // Close the pipe to signal that we have completed our init. l.pipe.Close() + + // Close the log pipe fd so the parent's ForwardLogs can exit. + 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