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 <[email protected]>
Signed-off-by: Georgi Sabev <[email protected]>

Author: georgethebeatle

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,

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

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

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

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{

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" {

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