Support for logging from children processes

init.go

@@ -1,18 +1,30 @@
 package main
 
 import (
-	"os"
-	"runtime"
-
+	"fmt"
 	"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"
+	"os"
+	"runtime"
 )
 
 func init() {
 	if len(os.Args) > 1 && os.Args[1] == "init" {
 		runtime.GOMAXPROCS(1)
 		runtime.LockOSThread()
+
+		err := logs.ConfigureLogging(&logs.LoggingConfiguration{
+			LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"),
+			LogFormat: "json",
+			IsDebug:   true,
+		})
+		if err != nil {
+			panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err))
+		}
+		logrus.Debug("child process in init()")
 	}
 }
 

libcontainer/container_linux.go

@@ -19,7 +19,7 @@ import (
 	"syscall" // only for SysProcAttr and Signal
 	"time"
 
-	"github.com/cyphar/filepath-securejoin"
+	securejoin "github.com/cyphar/filepath-securejoin"
 	"github.com/opencontainers/runc/libcontainer/cgroups"
 	"github.com/opencontainers/runc/libcontainer/configs"
 	"github.com/opencontainers/runc/libcontainer/intelrdt"
@@ -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,12 @@ 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),
+	)
+
 	// 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 +508,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 +523,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 +538,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 +555,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,150 @@
+package logs
+
+import (
+	"bufio"
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+	"strconv"
+
+	"github.com/sirupsen/logrus"
+)
+
+// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`.
+// Subsequent invocations of `ConfigureLogging` would be no-op
+var loggingConfigured = false
+
+type LoggingConfiguration struct {
+	IsDebug     bool
+	LogFormat   string
+	LogFilePath string
+	LogPipeFd   string
+}
+
+func ForwardLogs(logPipe io.Reader) {
+	type jsonLog struct {
+		Level string `json:"level"`
+		Msg   string `json:"msg"`
+	}
+
+	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
+	}
+	log(lvl, jl.Msg)
+}
+
+func log(level logrus.Level, args ...interface{}) {
+	switch level {
+	case logrus.PanicLevel:
+		logrus.Panic(args...)
+	case logrus.FatalLevel:
+		logrus.Fatal(args...)
+	case logrus.ErrorLevel:
+		logrus.Error(args...)
+	case logrus.WarnLevel:
+		logrus.Warn(args...)
+	case logrus.InfoLevel:
+		logrus.Info(args...)
+	case logrus.DebugLevel:
+		logrus.Debug(args...)
+	default:
+		logrus.Warnf("Unsupported log level %v while trying to log '%#v'", level, args)
+	}
+}
+
+func ConfigureLogging(loggingConfig *LoggingConfiguration) error {
+	if loggingConfigured {
+		logrus.Debug("logging has been already configured")
+		return nil
+	}
+
+	configureLogLevel(loggingConfig)
+	if err := configureLogOutput(loggingConfig); err != nil {
+		return err
+	}
+	if err := configureLogFormat(loggingConfig); err != nil {
+		return err
+	}
+
+	loggingConfigured = true
+	return nil
+}
+
+func configureLogLevel(loggingConfig *LoggingConfiguration) {
+	if loggingConfig.IsDebug {
+		logrus.SetLevel(logrus.DebugLevel)
+	}
+}
+
+func configureLogOutput(loggingConfig *LoggingConfiguration) error {
+	if loggingConfig.LogFilePath != "" {
+		return configureLogFileOutput(loggingConfig.LogFilePath)
+	}
+
+	if loggingConfig.LogPipeFd != "" {
+		logPipeFdInt, err := strconv.Atoi(loggingConfig.LogPipeFd)
+		if err != nil {
+			return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", loggingConfig.LogPipeFd, err)
+		}
+		configureLogPipeOutput(logPipeFdInt)
+		return nil
+	}
+
+	return nil
+}
+
+func configureLogPipeOutput(logPipeFd int) {
+	logrus.SetOutput(os.NewFile(uintptr(logPipeFd), "logpipe"))
+}
+
+func configureLogFileOutput(logFilePath string) error {
+	f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0644)
+	if err != nil {
+		return err
+	}
+	logrus.SetOutput(f)
+	return nil
+}
+
+func configureLogFormat(loggingConfig *LoggingConfiguration) error {
+	switch loggingConfig.LogFormat {
+	case "text":
+		// retain logrus's default.
+	case "json":
+		logrus.SetFormatter(new(logrus.JSONFormatter))
+	default:
+		return fmt.Errorf("unknown log-format %q", loggingConfig.LogFormat)
+	}
+	return nil
+}