Support for logging from children processes

Add support for children processes logging (including nsexec).
A pipe is used to send logs from children to parent in JSON.
The JSON format used is the same used by logrus JSON formatted,
i.e. children process can use standard logrus APIs.

Signed-off-by: Marco Vedovati <mvedovati@suse.com>
Co-authored-by: Georgi Sabev <georgethebeatle@gmail.com>

Author: 2 people

init.go

@@ -3,16 +3,31 @@ package main
 import (
 	"os"
 	"runtime"
+	"strconv"
 
 	"github.com/opencontainers/runc/libcontainer"
 	_ "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()
+
+		// in child process, we need to retrieve the log pipe
+		envLogPipe := os.Getenv("_LIBCONTAINER_LOGPIPE")
+		logPipeFd, err := strconv.Atoi(envLogPipe)
+
+		if err != nil {
+			return
+		}
+		logPipe := os.NewFile(uintptr(logPipeFd), "logpipe")
+		logrus.SetOutput(logPipe)
+		logrus.SetFormatter(&logrus.JSONFormatter{})
+		logrus.SetLevel(logrus.DebugLevel)
+		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.getChildLogs()
 	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,19 @@ 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)
+
+	r, w, err := os.Pipe()
+	if err != nil {
+		return nil, fmt.Errorf("Unable to create the log pipe:  %s", err)
+	}
+	logPipe := pipePair{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, parentPipe, childPipe, &logPipe)
 	}
 
 	// We only set up fifoFd if we're not doing a `runc exec`. The historic
@@ -458,10 +466,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, parentPipe, childPipe, &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 +492,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 +507,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, parentPipe, childPipe *os.File, logPipe *pipePair) (*initProcess, error) {
 	cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initStandard))
 	nsMaps := make(map[configs.NamespaceType]string)
 	for _, ns := range c.config.Namespaces {
@@ -510,6 +524,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c
 		cmd:             cmd,
 		childPipe:       childPipe,
 		parentPipe:      parentPipe,
+		logPipe:         *logPipe,
 		manager:         c.cgroupManager,
 		intelRdtManager: c.intelRdtManager,
 		config:          c.newInitConfig(p),
@@ -522,7 +537,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, parentPipe, childPipe *os.File, logPipe *pipePair) (*setnsProcess, error) {
 	cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns))
 	state, err := c.currentState()
 	if err != nil {
@@ -541,6 +556,7 @@ func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe,
 		intelRdtPath:    state.IntelRdtPath,
 		childPipe:       childPipe,
 		parentPipe:      parentPipe,
+		logPipe:         *logPipe,
 		config:          c.newInitConfig(p),
 		process:         p,
 		bootstrapData:   data,

libcontainer/logs.go

@@ -0,0 +1,70 @@
+package libcontainer
+
+import (
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+
+	"github.com/sirupsen/logrus"
+)
+
+func forwardLogs(p *os.File) {
+	defer p.Close()
+
+	type jsonLog struct {
+		Level string `json:"level"`
+		Msg   string `json:"msg"`
+	}
+
+	dec := json.NewDecoder(p)
+	for {
+		var jl jsonLog
+
+		type logFuncTable map[logrus.Level]func(args ...interface{})
+		logMapping := logFuncTable{
+			logrus.PanicLevel: logrus.Panic,
+			logrus.FatalLevel: logrus.Fatal,
+			logrus.ErrorLevel: logrus.Error,
+			logrus.WarnLevel:  logrus.Warn,
+			logrus.InfoLevel:  logrus.Info,
+			logrus.DebugLevel: logrus.Debug,
+		}
+
+		err := dec.Decode(&jl)
+		if err != nil {
+			if err == io.EOF {
+				logrus.Debug("child pipe closed")
+				return
+			}
+			logrus.Errorf("json logs decoding error: %+v", err)
+			return
+		}
+
+		lvl, err := logrus.ParseLevel(jl.Level)
+		if err != nil {
+			fmt.Printf("parsing error\n")
+		}
+		if logMapping[lvl] != nil {
+			logMapping[lvl](jl.Msg)
+		}
+	}
+}
+
+func rawLogs(p *os.File) {
+	defer p.Close()
+
+	data := make([]byte, 128)
+	for {
+		_, err := p.Read(data)
+
+		if err != nil {
+			if err == io.EOF {
+				logrus.Debug("child pipe closed")
+				return
+			}
+			return
+		}
+		fmt.Printf("Read data: %s\n", string(data))
+	}
+}

libcontainer/nsenter/nsenter_test.go

@@ -21,6 +21,11 @@ type pid struct {
 	Pid int `json:"Pid"`
 }
 
+type logentry struct {
+	Msg   string
+	Level string
+}
+
 func TestNsenterValidPaths(t *testing.T) {
 	args := []string{"nsenter-exec"}
 	parent, child, err := newPipe()
@@ -159,6 +164,60 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 	}
 }
 
+func TestNsenterChildLogging(t *testing.T) {
+	args := []string{"nsenter-exec"}
+	parent, child, err := newPipe()
+	logread, logwrite, err := os.Pipe()
+	if err != nil {
+		t.Fatalf("failed to create pipe %v", err)
+	}
+
+	namespaces := []string{
+		// join pid ns of the current process
+		fmt.Sprintf("pid:/proc/%d/ns/pid", os.Getpid()),
+	}
+	cmd := &exec.Cmd{
+		Path:       os.Args[0],
+		Args:       args,
+		ExtraFiles: []*os.File{child, logwrite},
+		Env:        []string{"_LIBCONTAINER_INITPIPE=3", "_LIBCONTAINER_LOGPIPE=4"},
+		Stdout:     os.Stdout,
+		Stderr:     os.Stderr,
+	}
+
+	if err := cmd.Start(); err != nil {
+		t.Fatalf("nsenter failed to start %v", err)
+	}
+	// write cloneFlags
+	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
+	r.AddData(&libcontainer.Int32msg{
+		Type:  libcontainer.CloneFlagsAttr,
+		Value: uint32(unix.CLONE_NEWNET),
+	})
+	r.AddData(&libcontainer.Bytemsg{
+		Type:  libcontainer.NsPathsAttr,
+		Value: []byte(strings.Join(namespaces, ",")),
+	})
+	if _, err := io.Copy(parent, bytes.NewReader(r.Serialize())); err != nil {
+		t.Fatal(err)
+	}
+
+	logsDecoder := json.NewDecoder(logread)
+	var logentry *logentry
+
+	err = logsDecoder.Decode(&logentry)
+	if err != nil {
+		t.Fatalf("child log: %v", err)
+	}
+	if logentry.Level == "" || logentry.Msg == "" {
+		t.Fatalf("child log: empty log fileds: level=\"%s\" msg=\"%s\"", logentry.Level, logentry.Msg)
+	}
+
+	if err := cmd.Wait(); err != nil {
+		t.Fatalf("nsenter exits with a non-zero exit status")
+	}
+}
+
 func init() {
 	if strings.HasPrefix(os.Args[0], "nsenter-") {
 		os.Exit(0)

libcontainer/nsenter/nsexec.c

@@ -95,6 +95,17 @@ struct nlconfig_t {
 	size_t gidmappath_len;
 };
 
+typedef enum {
+	PANIC = 0,
+	FATAL,
+	ERROR,
+	WARNING,
+	INFO,
+	DEBUG,
+} loglevel_t;
+
+int logfd;
+
 /*
  * List of netlink message types sent to us as part of bootstrapping the init.
  * These constants are defined in libcontainer/message_linux.go.
@@ -352,6 +363,22 @@ static int initpipe(void)
 	return pipenum;
 }
 
+static int logpipe(void)
+{
+	int pipenum;
+	char *logpipe, *endptr;
+
+	logpipe = getenv("_LIBCONTAINER_LOGPIPE");
+	if (logpipe == NULL || *logpipe == '\0')
+		return -1;
+
+	pipenum = strtol(logpipe, &endptr, 10);
+	if (*endptr != '\0')
+		bail("unable to parse _LIBCONTAINER_LOGPIPE");
+
+	return pipenum;
+}
+
 /* Returns the clone(2) flag for a namespace, given the name of a namespace. */
 static int nsflag(char *name)
 {
@@ -537,6 +564,27 @@ void join_namespaces(char *nslist)
 /* Defined in cloned_binary.c. */
 extern int ensure_cloned_binary(void);
 
+void write_log(loglevel_t level, const char *format, ...)
+{
+	static const char *strlevel[] = {"panic", "fatal", "error", "warning", "info", "debug"};
+	static char jsonbuffer[1024];
+	int len;
+	va_list args;
+	if (logfd < 0 || level >= sizeof(strlevel) / sizeof(strlevel[0])) {
+		return;
+	}
+
+	len = snprintf(jsonbuffer, sizeof(jsonbuffer),
+				   "{\"level\":\"%s\", \"msg\": \"", strlevel[level]);
+
+	va_start(args, format);
+	len += vsnprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, format, args);
+	va_end(args);
+
+	len += snprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, "\"}");
+	write(logfd, jsonbuffer, len);
+}
+
 void nsexec(void)
 {
 	int pipenum;
@@ -560,6 +608,11 @@ void nsexec(void)
 	if (ensure_cloned_binary() < 0)
 		bail("could not ensure we are a cloned binary");
 
+	/* Get the log pipe */
+	logfd = logpipe();
+
+	write_log(DEBUG, "%s started", __FUNCTION__);
+
 	/* Parse all of the netlink configuration. */
 	nl_parse(pipenum, &config);