From 634317da9cadb32c7ac82dad0b286cbaef2fee99 Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Tue, 14 Jul 2020 15:36:45 -0700 Subject: [PATCH] libc/logs: wait for init/nsenter logs Adding more nsenter debug logging revealed a bug: some logs were lost, resulting in random failures of debug.bats tests (usually the ones that write to a file). The bug happens because the main thread does not wait for the ForwardLogs goroutine to do its work, and it is reproducible with a short-lived container and a (relatively) slow operation of writing logs to a file. Obviously, a way to fix this is to make the main thread wait for the ForwardLogs goroutine. This works only if we explicitly close the writing end of a log pipe, so this closing had to be added. Signed-off-by: Kir Kolyshkin --- init.go | 4 ++++ libcontainer/container_linux.go | 5 ++++- libcontainer/container_linux_test.go | 3 ++- libcontainer/logs/logs.go | 3 ++- libcontainer/process_linux.go | 11 ++++++----- libcontainer/restored_process.go | 6 ++++-- 6 files changed, 22 insertions(+), 10 deletions(-) diff --git a/init.go b/init.go index 59ce1e8c739..b31ff260d78 100644 --- a/init.go +++ b/init.go @@ -11,6 +11,7 @@ import ( _ "github.com/opencontainers/runc/libcontainer/nsenter" "github.com/sirupsen/logrus" "github.com/urfave/cli" + "golang.org/x/sys/unix" ) func init() { @@ -38,6 +39,9 @@ func init() { panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err)) } logrus.Debug("child process in init()") + + // let ForwardLogs exit. Note no more logrus logging is possible after + unix.Close(logPipeFd) } } diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index c5188b1dbba..91c94b951b4 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -361,7 +361,8 @@ func (c *linuxContainer) start(process *Process) error { if err != nil { return newSystemErrorWithCause(err, "creating new parent process") } - parent.forwardChildLogs() + logsDone := make(chan struct{}) + parent.forwardChildLogs(logsDone) if err := parent.start(); err != nil { // terminate the process to ensure that it properly is reaped. if err := ignoreTerminateErrors(parent.terminate()); err != nil { @@ -395,6 +396,8 @@ func (c *linuxContainer) start(process *Process) error { } } } + // wait for forwardChildLogs to finish + <-logsDone return nil } diff --git a/libcontainer/container_linux_test.go b/libcontainer/container_linux_test.go index 72ca1ef7266..73b9d87dde9 100644 --- a/libcontainer/container_linux_test.go +++ b/libcontainer/container_linux_test.go @@ -135,7 +135,8 @@ func (m *mockProcess) externalDescriptors() []string { func (m *mockProcess) setExternalDescriptors(newFds []string) { } -func (m *mockProcess) forwardChildLogs() { +func (m *mockProcess) forwardChildLogs(done chan struct{}) { + close(done) } func TestGetContainerPids(t *testing.T) { diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index 9706a9168ea..835f8bb4ef7 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -25,7 +25,7 @@ type Config struct { LogPipeFd int } -func ForwardLogs(logPipe io.Reader) { +func ForwardLogs(logPipe io.Reader, done chan struct{}) { s := bufio.NewScanner(logPipe) for s.Scan() { processEntry(s.Bytes()) @@ -35,6 +35,7 @@ func ForwardLogs(logPipe io.Reader) { } else { logrus.Debugf("log pipe closed") } + close(done) } func processEntry(text []byte) { diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 028fe8ab5e2..cb21d0c1f53 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -50,7 +50,7 @@ type parentProcess interface { setExternalDescriptors(fds []string) - forwardChildLogs() + forwardChildLogs(done chan struct{}) } type filePair struct { @@ -70,6 +70,7 @@ type setnsProcess struct { process *Process bootstrapData io.Reader initProcessPid int + logsDone chan struct{} } func (p *setnsProcess) startTime() (uint64, error) { @@ -235,8 +236,8 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *setnsProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logFilePair.parent) +func (p *setnsProcess) forwardChildLogs(done chan struct{}) { + go logs.ForwardLogs(p.logFilePair.parent, done) } type initProcess struct { @@ -547,8 +548,8 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *initProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logFilePair.parent) +func (p *initProcess) forwardChildLogs(done chan struct{}) { + go logs.ForwardLogs(p.logFilePair.parent, done) } func getPipeFds(pid int) ([]string, error) { diff --git a/libcontainer/restored_process.go b/libcontainer/restored_process.go index f861e82d1b2..c53edc1e971 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(done chan struct{}) { + close(done) } // 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(done chan struct{}) { + close(done) }