From a1460818288b8addfe9b70c8931da83864251f7a Mon Sep 17 00:00:00 2001 From: Georgi Sabev Date: Tue, 23 Apr 2019 17:02:31 +0300 Subject: [PATCH] Write logs to stderr by default Minor refactoring to use the filePair struct for both init sock and log pipe Co-authored-by: Julia Nedialkova Signed-off-by: Georgi Sabev --- libcontainer/container_linux.go | 34 ++++++++-------- libcontainer/logs/logs.go | 6 +-- libcontainer/nsenter/nsenter_test.go | 4 +- libcontainer/process_linux.go | 58 ++++++++++++++-------------- main.go | 2 +- tests/integration/debug.bats | 5 +++ tests/integration/helpers.bash | 2 +- 7 files changed, 56 insertions(+), 55 deletions(-) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index e5f6ad88c24..d6c4ebdaa10 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -439,24 +439,24 @@ func (c *linuxContainer) includeExecFifo(cmd *exec.Cmd) error { } func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { - parentPipe, childPipe, err := utils.NewSockPair("init") + parentInitPipe, childInitPipe, err := utils.NewSockPair("init") if err != nil { return nil, newSystemErrorWithCause(err, "creating new init pipe") } - messagePipe := readWritePair{parentPipe, childPipe} + messageSockPair := filePair{parentInitPipe, childInitPipe} - r, w, err := os.Pipe() + parentLogPipe, childLogPipe, err := os.Pipe() if err != nil { return nil, fmt.Errorf("Unable to create the log pipe: %s", err) } - logPipe := readWritePair{r, w} + logFilePair := filePair{parentLogPipe, childLogPipe} - cmd, err := c.commandTemplate(p, childPipe, logPipe.w) + cmd, err := c.commandTemplate(p, childInitPipe, childLogPipe) if err != nil { return nil, newSystemErrorWithCause(err, "creating new command template") } if !p.Init { - return c.newSetnsProcess(p, cmd, messagePipe, logPipe) + return c.newSetnsProcess(p, cmd, messageSockPair, logFilePair) } // We only set up fifoFd if we're not doing a `runc exec`. The historic @@ -467,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, messagePipe, logPipe) + return c.newInitProcess(p, cmd, messageSockPair, logFilePair) } -func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe *os.File) (*exec.Cmd, error) { +func (c *linuxContainer) commandTemplate(p *Process, childInitPipe *os.File, childLogPipe *os.File) (*exec.Cmd, error) { cmd := exec.Command(c.initPath, c.initArgs[1:]...) cmd.Args[0] = c.initArgs[0] cmd.Stdin = p.Stdin @@ -488,13 +488,13 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe fmt.Sprintf("_LIBCONTAINER_CONSOLE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), ) } - cmd.ExtraFiles = append(cmd.ExtraFiles, childPipe) + cmd.ExtraFiles = append(cmd.ExtraFiles, childInitPipe) cmd.Env = append(cmd.Env, fmt.Sprintf("_LIBCONTAINER_INITPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), fmt.Sprintf("_LIBCONTAINER_STATEDIR=%s", c.root), ) - cmd.ExtraFiles = append(cmd.ExtraFiles, logPipe) + cmd.ExtraFiles = append(cmd.ExtraFiles, childLogPipe) cmd.Env = append(cmd.Env, fmt.Sprintf("_LIBCONTAINER_LOGPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), fmt.Sprintf("_LIBCONTAINER_LOGLEVEL=%s", p.LogLevel), @@ -509,7 +509,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe return cmd, nil } -func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, logPipe readWritePair) (*initProcess, error) { +func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, messageSockPair, logFilePair filePair) (*initProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initStandard)) nsMaps := make(map[configs.NamespaceType]string) for _, ns := range c.config.Namespaces { @@ -524,9 +524,8 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, log } init := &initProcess{ cmd: cmd, - childPipe: initPipe.w, - parentPipe: initPipe.r, - logPipe: logPipe, + messageSockPair: messageSockPair, + logFilePair: logFilePair, manager: c.cgroupManager, intelRdtManager: c.intelRdtManager, config: c.newInitConfig(p), @@ -539,7 +538,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, log return init, nil } -func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, nsPipe, logPipe readWritePair) (*setnsProcess, error) { +func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, messageSockPair, logFilePair filePair) (*setnsProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns)) state, err := c.currentState() if err != nil { @@ -556,9 +555,8 @@ func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, nsPipe, logP cgroupPaths: c.cgroupManager.GetPaths(), rootlessCgroups: c.config.RootlessCgroups, intelRdtPath: state.IntelRdtPath, - childPipe: nsPipe.w, - parentPipe: nsPipe.r, - logPipe: logPipe, + messageSockPair: messageSockPair, + logFilePair: logFilePair, config: c.newInitConfig(p), process: p, bootstrapData: data, diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index 50c5c3ac86c..1077e7b0145 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -13,7 +13,7 @@ import ( ) var ( - mutex = &sync.Mutex{} + configureMutex = sync.Mutex{} // loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`. // Subsequent invocations of `ConfigureLogging` would be no-op loggingConfigured = false @@ -64,8 +64,8 @@ func processEntry(text []byte) { } func ConfigureLogging(config Config) error { - mutex.Lock() - defer mutex.Unlock() + configureMutex.Lock() + defer configureMutex.Unlock() if loggingConfigured { logrus.Debug("logging has already been configured") diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go index c4c5af8f2f8..c4d3c863c69 100644 --- a/libcontainer/nsenter/nsenter_test.go +++ b/libcontainer/nsenter/nsenter_test.go @@ -22,8 +22,8 @@ type pid struct { } type logentry struct { - Msg string - Level string + Msg string `json:"msg"` + Level string `json:"level"` } func TestNsenterValidPaths(t *testing.T) { diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 8f920260693..a65d5521e5a 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -52,16 +52,15 @@ type parentProcess interface { forwardChildLogs() } -type readWritePair struct { - r *os.File - w *os.File +type filePair struct { + parent *os.File + child *os.File } type setnsProcess struct { cmd *exec.Cmd - parentPipe *os.File - childPipe *os.File - logPipe readWritePair + messageSockPair filePair + logFilePair filePair cgroupPaths map[string]string rootlessCgroups bool intelRdtPath string @@ -85,16 +84,16 @@ func (p *setnsProcess) signal(sig os.Signal) error { } func (p *setnsProcess) start() (err error) { - defer p.parentPipe.Close() + defer p.messageSockPair.parent.Close() err = p.cmd.Start() // close the write-side of the pipes (controlled by child) - p.childPipe.Close() - p.logPipe.w.Close() + p.messageSockPair.child.Close() + p.logFilePair.child.Close() if err != nil { return newSystemErrorWithCause(err, "starting setns process") } if p.bootstrapData != nil { - if _, err := io.Copy(p.parentPipe, p.bootstrapData); err != nil { + if _, err := io.Copy(p.messageSockPair.parent, p.bootstrapData); err != nil { return newSystemErrorWithCause(err, "copying bootstrap data to pipe") } } @@ -120,11 +119,11 @@ func (p *setnsProcess) start() (err error) { if err := setupRlimits(p.config.Rlimits, p.pid()); err != nil { return newSystemErrorWithCause(err, "setting rlimits for process") } - if err := utils.WriteJSON(p.parentPipe, p.config); err != nil { + if err := utils.WriteJSON(p.messageSockPair.parent, p.config); err != nil { return newSystemErrorWithCause(err, "writing config to pipe") } - ierr := parseSync(p.parentPipe, func(sync *syncT) error { + ierr := parseSync(p.messageSockPair.parent, func(sync *syncT) error { switch sync.Type { case procReady: // This shouldn't happen. @@ -137,7 +136,7 @@ func (p *setnsProcess) start() (err error) { } }) - if err := unix.Shutdown(int(p.parentPipe.Fd()), unix.SHUT_WR); err != nil { + if err := unix.Shutdown(int(p.messageSockPair.parent.Fd()), unix.SHUT_WR); err != nil { return newSystemErrorWithCause(err, "calling shutdown on init pipe") } // Must be done after Shutdown so the child will exit and we can wait for it. @@ -163,7 +162,7 @@ func (p *setnsProcess) execSetns() error { return newSystemError(&exec.ExitError{ProcessState: status}) } var pid *pid - if err := json.NewDecoder(p.parentPipe).Decode(&pid); err != nil { + if err := json.NewDecoder(p.messageSockPair.parent).Decode(&pid); err != nil { p.cmd.Wait() return newSystemErrorWithCause(err, "reading pid from init pipe") } @@ -217,14 +216,13 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { } func (p *setnsProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logPipe.r) + go logs.ForwardLogs(p.logFilePair.parent) } type initProcess struct { cmd *exec.Cmd - parentPipe *os.File - childPipe *os.File - logPipe readWritePair + messageSockPair filePair + logFilePair filePair config *initConfig manager cgroups.Manager intelRdtManager intelrdt.Manager @@ -246,7 +244,7 @@ func (p *initProcess) externalDescriptors() []string { // getChildPid receives the final child's pid over the provided pipe. func (p *initProcess) getChildPid() (int, error) { var pid pid - if err := json.NewDecoder(p.parentPipe).Decode(&pid); err != nil { + if err := json.NewDecoder(p.messageSockPair.parent).Decode(&pid); err != nil { p.cmd.Wait() return -1, err } @@ -282,12 +280,12 @@ func (p *initProcess) waitForChildExit(childPid int) error { } func (p *initProcess) start() error { - defer p.parentPipe.Close() + defer p.messageSockPair.parent.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() + p.messageSockPair.child.Close() + p.logFilePair.child.Close() if err != nil { p.process.ops = nil return newSystemErrorWithCause(err, "starting init process command") @@ -313,7 +311,7 @@ func (p *initProcess) start() error { } }() - if _, err := io.Copy(p.parentPipe, p.bootstrapData); err != nil { + if _, err := io.Copy(p.messageSockPair.parent, p.bootstrapData); err != nil { return newSystemErrorWithCause(err, "copying bootstrap data to pipe") } childPid, err := p.getChildPid() @@ -341,7 +339,7 @@ func (p *initProcess) start() error { } // Now it's time to setup cgroup namesapce if p.config.Config.Namespaces.Contains(configs.NEWCGROUP) && p.config.Config.Namespaces.PathOf(configs.NEWCGROUP) == "" { - if _, err := p.parentPipe.Write([]byte{createCgroupns}); err != nil { + if _, err := p.messageSockPair.parent.Write([]byte{createCgroupns}); err != nil { return newSystemErrorWithCause(err, "sending synchronization value to init process") } } @@ -368,7 +366,7 @@ func (p *initProcess) start() error { sentResume bool ) - ierr := parseSync(p.parentPipe, func(sync *syncT) error { + ierr := parseSync(p.messageSockPair.parent, func(sync *syncT) error { switch sync.Type { case procReady: // set rlimits, this has to be done here because we lose permissions @@ -404,7 +402,7 @@ func (p *initProcess) start() error { } } // Sync with child. - if err := writeSync(p.parentPipe, procRun); err != nil { + if err := writeSync(p.messageSockPair.parent, procRun); err != nil { return newSystemErrorWithCause(err, "writing syncT 'run'") } sentRun = true @@ -433,7 +431,7 @@ func (p *initProcess) start() error { } } // Sync with child. - if err := writeSync(p.parentPipe, procResume); err != nil { + if err := writeSync(p.messageSockPair.parent, procResume); err != nil { return newSystemErrorWithCause(err, "writing syncT 'resume'") } sentResume = true @@ -450,7 +448,7 @@ func (p *initProcess) start() error { if p.config.Config.Namespaces.Contains(configs.NEWNS) && !sentResume { return newSystemError(fmt.Errorf("could not synchronise after executing prestart hooks with container process")) } - if err := unix.Shutdown(int(p.parentPipe.Fd()), unix.SHUT_WR); err != nil { + if err := unix.Shutdown(int(p.messageSockPair.parent.Fd()), unix.SHUT_WR); err != nil { return newSystemErrorWithCause(err, "shutting down init pipe") } @@ -494,7 +492,7 @@ func (p *initProcess) sendConfig() error { // send the config to the container's init process, we don't use JSON Encode // here because there might be a problem in JSON decoder in some cases, see: // https://github.com/docker/docker/issues/14203#issuecomment-174177790 - return utils.WriteJSON(p.parentPipe, p.config) + return utils.WriteJSON(p.messageSockPair.parent, p.config) } func (p *initProcess) createNetworkInterfaces() error { @@ -527,7 +525,7 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { } func (p *initProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logPipe.r) + go logs.ForwardLogs(p.logFilePair.parent) } func getPipeFds(pid int) ([]string, error) { diff --git a/main.go b/main.go index 273aeb84c30..78913c04166 100644 --- a/main.go +++ b/main.go @@ -87,7 +87,7 @@ func main() { }, cli.StringFlag{ Name: "log", - Value: "/dev/null", + Value: "/dev/stderr", Usage: "set the log file path where internal debug information is written", }, cli.StringFlag{ diff --git a/tests/integration/debug.bats b/tests/integration/debug.bats index 187297990a2..e02cf4a1f37 100644 --- a/tests/integration/debug.bats +++ b/tests/integration/debug.bats @@ -16,6 +16,11 @@ function teardown() { runc --debug run test_hello echo "${output}" [ "$status" -eq 0 ] + + # check expected debug output was sent to stderr + [[ "${output}" == *"level=debug"* ]] + [[ "${output}" == *"nsexec started"* ]] + [[ "${output}" == *"child process in init()"* ]] } @test "global --debug to --log" { diff --git a/tests/integration/helpers.bash b/tests/integration/helpers.bash index 14181332873..0f04bbfcaf2 100644 --- a/tests/integration/helpers.bash +++ b/tests/integration/helpers.bash @@ -65,7 +65,7 @@ function runc() { # Raw wrapper for runc. function __runc() { - "$RUNC" ${RUNC_USE_SYSTEMD+--systemd-cgroup} --log /proc/self/fd/2 --root "$ROOT" "$@" + "$RUNC" ${RUNC_USE_SYSTEMD+--systemd-cgroup} --root "$ROOT" "$@" } # Wrapper for runc spec, which takes only one argument (the bundle path).