Support for logging from children processes

exec.go

@@ -136,6 +136,12 @@ func execProcess(context *cli.Context) (int, error) {
 	if err != nil {
 		return -1, err
 	}
+
+	logLevel := "info"
+	if context.GlobalBool("debug") {
+		logLevel = "debug"
+	}
+
 	r := &runner{
 		enableSubreaper: false,
 		shouldDestroy:   false,
@@ -146,6 +152,7 @@ func execProcess(context *cli.Context) (int, error) {
 		action:          CT_ACT_RUN,
 		init:            false,
 		preserveFDs:     context.Int("preserve-fds"),
+		logLevel:        logLevel,
 	}
 	return r.run(p)
 }

init.go

@@ -1,18 +1,37 @@
 package main
 
 import (
+	"fmt"
 	"os"
 	"runtime"
 
 	"github.com/opencontainers/runc/libcontainer"
+	"github.com/opencontainers/runc/libcontainer/logs"
 	_ "github.com/opencontainers/runc/libcontainer/nsenter"
+	"github.com/sirupsen/logrus"
 	"github.com/urfave/cli"
 )
 
 func init() {
 	if len(os.Args) > 1 && os.Args[1] == "init" {
 		runtime.GOMAXPROCS(1)
 		runtime.LockOSThread()
+
+		level := os.Getenv("_LIBCONTAINER_LOGLEVEL")
+		logLevel, err := logrus.ParseLevel(level)
+		if err != nil {
+			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
+		}
+
+		err = logs.ConfigureLogging(logs.Config{
+			LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"),
+			LogFormat: "json",
+			LogLevel:  logLevel,
+		})
+		if err != nil {
+			panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err))
+		}
+		logrus.Debug("child process in init()")
 	}
 }
 

libcontainer/container_linux.go

@@ -337,6 +337,7 @@ func (c *linuxContainer) start(process *Process) error {
 	if err != nil {
 		return newSystemErrorWithCause(err, "creating new parent process")
 	}
+	parent.forwardChildLogs()
 	if err := parent.start(); err != nil {
 		// terminate the process to ensure that it properly is reaped.
 		if err := ignoreTerminateErrors(parent.terminate()); err != nil {
@@ -442,12 +443,20 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) {
 	if err != nil {
 		return nil, newSystemErrorWithCause(err, "creating new init pipe")
 	}
-	cmd, err := c.commandTemplate(p, childPipe)
+	messagePipe := readWritePair{parentPipe, childPipe}
+
+	r, w, err := os.Pipe()
+	if err != nil {
+		return nil, fmt.Errorf("Unable to create the log pipe:  %s", err)
+	}
+	logPipe := readWritePair{r, w}
+
+	cmd, err := c.commandTemplate(p, childPipe, logPipe.w)
 	if err != nil {
 		return nil, newSystemErrorWithCause(err, "creating new command template")
 	}
 	if !p.Init {
-		return c.newSetnsProcess(p, cmd, parentPipe, childPipe)
+		return c.newSetnsProcess(p, cmd, messagePipe, logPipe)
 	}
 
 	// We only set up fifoFd if we're not doing a `runc exec`. The historic
@@ -458,10 +467,10 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) {
 	if err := c.includeExecFifo(cmd); err != nil {
 		return nil, newSystemErrorWithCause(err, "including execfifo in cmd.Exec setup")
 	}
-	return c.newInitProcess(p, cmd, parentPipe, childPipe)
+	return c.newInitProcess(p, cmd, messagePipe, logPipe)
 }
 
-func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec.Cmd, error) {
+func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe *os.File) (*exec.Cmd, error) {
 	cmd := exec.Command(c.initPath, c.initArgs[1:]...)
 	cmd.Args[0] = c.initArgs[0]
 	cmd.Stdin = p.Stdin
@@ -484,6 +493,13 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec.
 		fmt.Sprintf("_LIBCONTAINER_INITPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1),
 		fmt.Sprintf("_LIBCONTAINER_STATEDIR=%s", c.root),
 	)
+
+	cmd.ExtraFiles = append(cmd.ExtraFiles, logPipe)
+	cmd.Env = append(cmd.Env,
+		fmt.Sprintf("_LIBCONTAINER_LOGPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1),
+		fmt.Sprintf("_LIBCONTAINER_LOGLEVEL=%s", p.LogLevel),
+	)
+
 	// NOTE: when running a container with no PID namespace and the parent process spawning the container is
 	// PID1 the pdeathsig is being delivered to the container's init process by the kernel for some reason
 	// even with the parent still running.
@@ -493,7 +509,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec.
 	return cmd, nil
 }
 
-func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File) (*initProcess, error) {
+func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, logPipe readWritePair) (*initProcess, error) {
 	cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initStandard))
 	nsMaps := make(map[configs.NamespaceType]string)
 	for _, ns := range c.config.Namespaces {
@@ -508,8 +524,9 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c
 	}
 	init := &initProcess{
 		cmd:             cmd,
-		childPipe:       childPipe,
-		parentPipe:      parentPipe,
+		childPipe:       initPipe.w,
+		parentPipe:      initPipe.r,
+		logPipe:         logPipe,
 		manager:         c.cgroupManager,
 		intelRdtManager: c.intelRdtManager,
 		config:          c.newInitConfig(p),
@@ -522,7 +539,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c
 	return init, nil
 }
 
-func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File) (*setnsProcess, error) {
+func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, nsPipe, logPipe readWritePair) (*setnsProcess, error) {
 	cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns))
 	state, err := c.currentState()
 	if err != nil {
@@ -539,8 +556,9 @@ func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe,
 		cgroupPaths:     c.cgroupManager.GetPaths(),
 		rootlessCgroups: c.config.RootlessCgroups,
 		intelRdtPath:    state.IntelRdtPath,
-		childPipe:       childPipe,
-		parentPipe:      parentPipe,
+		childPipe:       nsPipe.w,
+		parentPipe:      nsPipe.r,
+		logPipe:         logPipe,
 		config:          c.newInitConfig(p),
 		process:         p,
 		bootstrapData:   data,

libcontainer/container_linux_test.go

@@ -114,6 +114,9 @@ func (m *mockProcess) externalDescriptors() []string {
 func (m *mockProcess) setExternalDescriptors(newFds []string) {
 }
 
+func (m *mockProcess) forwardChildLogs() {
+}
+
 func TestGetContainerPids(t *testing.T) {
 	container := &linuxContainer{
 		id:            "myid",

libcontainer/logs/logs.go

@@ -0,0 +1,102 @@
+package logs
+
+import (
+	"bufio"
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+	"strconv"
+	"sync"
+
+	"github.com/sirupsen/logrus"
+)
+
+var (
+	mutex = &sync.Mutex{}
+	// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`.
+	// Subsequent invocations of `ConfigureLogging` would be no-op
+	loggingConfigured = false
+)
+
+type Config struct {
+	LogLevel    logrus.Level
+	LogFormat   string
+	LogFilePath string
+	LogPipeFd   string
+}
+
+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
+		}
+		if err != nil {
+			logrus.Errorf("log pipe read error: %+v", err)
+		}
+	}
+}
+
+func processEntry(text []byte) {
+	type jsonLog 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)
+		return
+	}
+
+	lvl, err := logrus.ParseLevel(jl.Level)
+	if err != nil {
+		logrus.Errorf("failed to parse log level %q: %v\n", jl.Level, err)
+		return
+	}
+	logrus.StandardLogger().Logf(lvl, jl.Msg)
+}
+
+func ConfigureLogging(config Config) error {
+	mutex.Lock()
+	defer mutex.Unlock()
+
+	if loggingConfigured {
+		logrus.Debug("logging has already been configured")
+		return nil
+	}
+
+	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"))
+	} 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 {
+			return err
+		}
+		logrus.SetOutput(f)
+	}
+
+	switch config.LogFormat {
+	case "text":
+		// retain logrus's default.
+	case "json":
+		logrus.SetFormatter(new(logrus.JSONFormatter))
+	default:
+		return fmt.Errorf("unknown log-format %q", config.LogFormat)
+	}
+
+	loggingConfigured = true
+	return nil
+}