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 <[email protected]>

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)
 	}
 }
 

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
 }
 

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) {

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) {

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) {

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)
 }