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