Improve nsexec logging

init.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"os"
 	"runtime"
+	"strconv"
 
 	"github.com/opencontainers/runc/libcontainer"
 	"github.com/opencontainers/runc/libcontainer/logs"
@@ -23,8 +24,13 @@ func init() {
 			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
 		}
 
+		logPipeFdStr := os.Getenv("_LIBCONTAINER_LOGPIPE")
+		logPipeFd, err := strconv.Atoi(logPipeFdStr)
+		if err != nil {
+			panic(fmt.Sprintf("libcontainer: failed to convert environment variable _LIBCONTAINER_LOGPIPE=%s to int: %s", logPipeFdStr, err))
+		}
 		err = logs.ConfigureLogging(logs.Config{
-			LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"),
+			LogPipeFd: logPipeFd,
 			LogFormat: "json",
 			LogLevel:  logLevel,
 		})

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

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

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
 	}

libcontainer/init_linux.go

@@ -35,8 +35,8 @@ const (
 )
 
 type pid struct {
-	Pid           int `json:"pid"`
-	PidFirstChild int `json:"pid_first"`
+	Pid           int `json:"stage2_pid"`
+	PidFirstChild int `json:"stage1_pid"`
 }
 
 // network is an internal struct used to setup container networks.
@@ -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)

libcontainer/logs/logs.go

@@ -6,14 +6,14 @@ import (
 	"fmt"
 	"io"
 	"os"
-	"strconv"
 	"sync"
 
+	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 )
 
 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
@@ -23,41 +23,44 @@ type Config struct {
 	LogLevel    logrus.Level
 	LogFormat   string
 	LogFilePath string
-	LogPipeFd   string
+	LogPipeFd   int
 }
 
-func ForwardLogs(logPipe io.Reader) {
-	lineReader := bufio.NewReader(logPipe)
-	for {
-		line, err := lineReader.ReadBytes('\n')
-		if len(line) > 0 {
-			processEntry(line)
-		}
-		if err == io.EOF {
-			logrus.Debugf("log pipe has been closed: %+v", err)
-			return
+func ForwardLogs(logPipe io.ReadCloser) chan error {
+	done := make(chan error, 1)
+	s := bufio.NewScanner(logPipe)
+
+	go func() {
+		for s.Scan() {
+			processEntry(s.Bytes())
 		}
-		if err != nil {
-			logrus.Errorf("log pipe read error: %+v", err)
+		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) {
-	type jsonLog struct {
+	if len(text) == 0 {
+		return
+	}
+
+	var jl struct {
 		Level string `json:"level"`
 		Msg   string `json:"msg"`
 	}
-
-	var jl jsonLog
 	if err := json.Unmarshal(text, &jl); err != nil {
-		logrus.Errorf("failed to decode %q to json: %+v", text, err)
+		logrus.Errorf("failed to decode %q to json: %v", text, err)
 		return
 	}
 
 	lvl, err := logrus.ParseLevel(jl.Level)
 	if err != nil {
-		logrus.Errorf("failed to parse log level %q: %v\n", jl.Level, err)
+		logrus.Errorf("failed to parse log level %q: %v", jl.Level, err)
 		return
 	}
 	logrus.StandardLogger().Logf(lvl, jl.Msg)
@@ -68,18 +71,15 @@ func ConfigureLogging(config Config) error {
 	defer configureMutex.Unlock()
 
 	if loggingConfigured {
-		logrus.Debug("logging has already been configured")
-		return nil
+		return errors.New("logging has already been configured")
 	}
 
 	logrus.SetLevel(config.LogLevel)
 
-	if config.LogPipeFd != "" {
-		logPipeFdInt, err := strconv.Atoi(config.LogPipeFd)
-		if err != nil {
-			return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", config.LogPipeFd, err)
-		}
-		logrus.SetOutput(os.NewFile(uintptr(logPipeFdInt), "logpipe"))
+	// XXX: while 0 is a valid fd (usually stdin), here we assume
+	// that we never deliberately set LogPipeFd to 0.
+	if config.LogPipeFd > 0 {
+		logrus.SetOutput(os.NewFile(uintptr(config.LogPipeFd), "logpipe"))
 	} else if config.LogFilePath != "" {
 		f, err := os.OpenFile(config.LogFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0644)
 		if err != nil {