From 9a599f62fbdc7cc366c09424485abea8efbbc004 Mon Sep 17 00:00:00 2001 From: Marco Vedovati Date: Fri, 3 Aug 2018 19:11:20 +0200 Subject: [PATCH] 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 --- init.go | 15 ++++++ libcontainer/container_linux.go | 28 ++++++++--- libcontainer/logs.go | 70 ++++++++++++++++++++++++++++ libcontainer/nsenter/nsenter_test.go | 59 +++++++++++++++++++++++ libcontainer/nsenter/nsexec.c | 53 +++++++++++++++++++++ libcontainer/process_linux.go | 21 +++++++++ libcontainer/restored_process.go | 6 +++ libcontainer/standard_init_linux.go | 5 ++ main.go | 6 +++ 9 files changed, 257 insertions(+), 6 deletions(-) create mode 100644 libcontainer/logs.go diff --git a/init.go b/init.go index c8f45319..0a10779d 100644 --- a/init.go +++ b/init.go @@ -3,9 +3,11 @@ 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" ) @@ -13,6 +15,19 @@ 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()") } } diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index 7e58e5e0..ecba1f9d 100644 --- a/libcontainer/container_linux.go +++ b/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, diff --git a/libcontainer/logs.go b/libcontainer/logs.go new file mode 100644 index 00000000..0b074a98 --- /dev/null +++ b/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)) + } +} diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go index 53215553..9be6a803 100644 --- a/libcontainer/nsenter/nsenter_test.go +++ b/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) diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c index 7750af35..af50cd87 100644 --- a/libcontainer/nsenter/nsexec.c +++ b/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); diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 6507f0e6..22fc1d7a 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -47,12 +47,20 @@ type parentProcess interface { externalDescriptors() []string setExternalDescriptors(fds []string) + + getChildLogs() +} + +type pipePair struct { + r *os.File + w *os.File } type setnsProcess struct { cmd *exec.Cmd parentPipe *os.File childPipe *os.File + logPipe pipePair cgroupPaths map[string]string rootlessCgroups bool intelRdtPath string @@ -78,7 +86,9 @@ func (p *setnsProcess) signal(sig os.Signal) error { func (p *setnsProcess) start() (err error) { defer p.parentPipe.Close() err = p.cmd.Start() + // close the write-side of the pipes (controlled by child) p.childPipe.Close() + p.logPipe.w.Close() if err != nil { return newSystemErrorWithCause(err, "starting setns process") } @@ -205,10 +215,15 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } +func (p *setnsProcess) getChildLogs() { + go forwardLogs(p.logPipe.r) +} + type initProcess struct { cmd *exec.Cmd parentPipe *os.File childPipe *os.File + logPipe pipePair config *initConfig manager cgroups.Manager intelRdtManager intelrdt.Manager @@ -269,7 +284,9 @@ func (p *initProcess) start() error { defer p.parentPipe.Close() err := p.cmd.Start() p.process.ops = p + // close the write-side of the pipes (controlled by child) p.childPipe.Close() + p.logPipe.w.Close() if err != nil { p.process.ops = nil return newSystemErrorWithCause(err, "starting init process command") @@ -508,6 +525,10 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } +func (p *initProcess) getChildLogs() { + go forwardLogs(p.logPipe.r) +} + func getPipeFds(pid int) ([]string, error) { fds := make([]string, 3) diff --git a/libcontainer/restored_process.go b/libcontainer/restored_process.go index 408916ad..f18875b0 100644 --- a/libcontainer/restored_process.go +++ b/libcontainer/restored_process.go @@ -76,6 +76,9 @@ func (p *restoredProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } +func (p *restoredProcess) getChildLogs() { +} + // nonChildProcess represents a process where the calling process is not // the parent process. This process is created when a factory loads a container from // a persisted state. @@ -120,3 +123,6 @@ func (p *nonChildProcess) externalDescriptors() []string { func (p *nonChildProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } + +func (p *nonChildProcess) getChildLogs() { +} diff --git a/libcontainer/standard_init_linux.go b/libcontainer/standard_init_linux.go index 4e03b8bc..ce65b17b 100644 --- a/libcontainer/standard_init_linux.go +++ b/libcontainer/standard_init_linux.go @@ -16,6 +16,7 @@ import ( "github.com/opencontainers/runc/libcontainer/system" "github.com/opencontainers/selinux/go-selinux/label" "github.com/pkg/errors" + "github.com/sirupsen/logrus" "golang.org/x/sys/unix" ) @@ -207,6 +208,10 @@ func (l *linuxStandardInit) Init() error { return newSystemErrorWithCause(err, "init seccomp") } } + + logPipe, _ := (logrus.StandardLogger().Out).(*(os.File)) + logPipe.Close() + if err := syscall.Exec(name, l.config.Args[0:], os.Environ()); err != nil { return newSystemErrorWithCause(err, "exec user process") } diff --git a/main.go b/main.go index 072447d1..2242cecf 100644 --- a/main.go +++ b/main.go @@ -133,6 +133,12 @@ func main() { updateCommand, } app.Before = func(context *cli.Context) error { + + // do nothing if logrus was already initialized in init.go + if logrus.StandardLogger().Out != logrus.New().Out { + return nil + } + if context.GlobalBool("debug") { logrus.SetLevel(logrus.DebugLevel) }