init: wait for log forwarder to finish

Since the extended logging was added to runc, some test cases from
debug.bats, notably those that write to a log file, started failing
sometimes in our CI, not showing the complete logs as expected, but
only the first few lines.

Presumably this happens because the binary exits before logrus forwarder
has a chance to finish forwarding/writing the logs to the file. To fix,
add a channel to signal that ForwardLogs has finished, and use it from
Finish().

Signed-off-by: Kir Kolyshkin <[email protected]>

libcontainer/logs/logs.go

@@ -16,6 +16,9 @@ var (
 	// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`.
 	// Subsequent invocations of `ConfigureLogging` would be no-op
 	loggingConfigured = false
+
+	inputPipe   io.ReadCloser
+	forwardDone chan struct{}
 )
 
 type Config struct {
@@ -25,7 +28,12 @@ type Config struct {
 	LogPipeFd   int
 }
 
-func ForwardLogs(logPipe io.Reader) {
+func ForwardLogs(logPipe io.ReadCloser) {
+	configureMutex.Lock()
+	forwardDone = make(chan struct{})
+	inputPipe = logPipe
+	configureMutex.Unlock()
+
 	s := bufio.NewScanner(logPipe)
 	for s.Scan() {
 		processEntry(s.Bytes())
@@ -35,6 +43,7 @@ func ForwardLogs(logPipe io.Reader) {
 	} else {
 		logrus.Debugf("log pipe closed")
 	}
+	close(forwardDone)
 }
 
 func processEntry(text []byte) {
@@ -61,6 +70,15 @@ func processEntry(text []byte) {
 	logrus.StandardLogger().Logf(lvl, jl.Msg)
 }
 
+func Finish() {
+	configureMutex.Lock()
+	defer configureMutex.Unlock()
+	if inputPipe != nil {
+		inputPipe.Close()
+		<-forwardDone
+	}
+}
+
 func ConfigureLogging(config Config) error {
 	configureMutex.Lock()
 	defer configureMutex.Unlock()

libcontainer/setns_init_linux.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/opencontainers/runc/libcontainer/apparmor"
 	"github.com/opencontainers/runc/libcontainer/keys"
+	"github.com/opencontainers/runc/libcontainer/logs"
 	"github.com/opencontainers/runc/libcontainer/seccomp"
 	"github.com/opencontainers/runc/libcontainer/system"
 	"github.com/opencontainers/selinux/go-selinux"
@@ -87,5 +88,6 @@ func (l *linuxSetnsInit) Init() error {
 			return newSystemErrorWithCause(err, "init seccomp")
 		}
 	}
+	logs.Finish()
 	return system.Execv(l.config.Args[0], l.config.Args[0:], os.Environ())
 }

libcontainer/standard_init_linux.go

@@ -11,11 +11,13 @@ import (
 	"github.com/opencontainers/runc/libcontainer/apparmor"
 	"github.com/opencontainers/runc/libcontainer/configs"
 	"github.com/opencontainers/runc/libcontainer/keys"
+	"github.com/opencontainers/runc/libcontainer/logs"
 	"github.com/opencontainers/runc/libcontainer/seccomp"
 	"github.com/opencontainers/runc/libcontainer/system"
 	"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"
 )
 
@@ -180,7 +182,10 @@ 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")
+	logs.Finish() // no more logrus below
 	l.pipe.Close()
+
 	// 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