Merge pull request #2835 from kolyshkin/fix-init-log-race

Fix init log forwarding race

init.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"os"
 	"runtime"
+	"strconv"
 
 	"github.com/opencontainers/runc/libcontainer"
 	"github.com/opencontainers/runc/libcontainer/logs"
@@ -23,8 +24,13 @@ func init() {
 			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
 		}
 
+		logPipeFdStr := os.Getenv("_LIBCONTAINER_LOGPIPE")
+		logPipeFd, err := strconv.Atoi(logPipeFdStr)
+		if err != nil {
+			panic(fmt.Sprintf("libcontainer: failed to convert environment variable _LIBCONTAINER_LOGPIPE=%s to int: %s", logPipeFdStr, err))
+		}
 		err = logs.ConfigureLogging(logs.Config{
-			LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"),
+			LogPipeFd: logPipeFd,
 			LogFormat: "json",
 			LogLevel:  logLevel,
 		})

libcontainer/container_linux.go

@@ -357,12 +357,24 @@ type openResult struct {
 	err  error
 }
 
-func (c *linuxContainer) start(process *Process) error {
+func (c *linuxContainer) start(process *Process) (retErr error) {
 	parent, err := c.newParentProcess(process)
 	if err != nil {
 		return newSystemErrorWithCause(err, "creating new parent process")
 	}
-	parent.forwardChildLogs()
+
+	logsDone := parent.forwardChildLogs()
+	if logsDone != nil {
+		defer func() {
+			// Wait for log forwarder to finish. This depends on
+			// runc init closing the _LIBCONTAINER_LOGPIPE log fd.
+			err := <-logsDone
+			if err != nil && retErr == nil {
+				retErr = newSystemErrorWithCause(err, "forwarding init logs")
+			}
+		}()
+	}
+
 	if err := parent.start(); err != nil {
 		return newSystemErrorWithCause(err, "starting container process")
 	}

libcontainer/container_linux_test.go

@@ -139,7 +139,8 @@ func (m *mockProcess) externalDescriptors() []string {
 func (m *mockProcess) setExternalDescriptors(newFds []string) {
 }
 
-func (m *mockProcess) forwardChildLogs() {
+func (m *mockProcess) forwardChildLogs() chan error {
+	return nil
 }
 
 func TestGetContainerPids(t *testing.T) {

libcontainer/factory_linux.go

@@ -365,6 +365,12 @@ func (l *LinuxFactory) StartInitialization() (err error) {
 		defer consoleSocket.Close()
 	}
 
+	logPipeFdStr := os.Getenv("_LIBCONTAINER_LOGPIPE")
+	logPipeFd, err := strconv.Atoi(logPipeFdStr)
+	if err != nil {
+		return fmt.Errorf("unable to convert _LIBCONTAINER_LOGPIPE=%s to int: %s", logPipeFdStr, err)
+	}
+
 	// clear the current process's environment to clean any libcontainer
 	// specific env vars.
 	os.Clearenv()
@@ -387,7 +393,7 @@ func (l *LinuxFactory) StartInitialization() (err error) {
 		}
 	}()
 
-	i, err := newContainerInit(it, pipe, consoleSocket, fifofd)
+	i, err := newContainerInit(it, pipe, consoleSocket, fifofd, logPipeFd)
 	if err != nil {
 		return err
 	}

libcontainer/init_linux.go

@@ -76,7 +76,7 @@ type initer interface {
 	Init() error
 }
 
-func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd int) (initer, error) {
+func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd, logFd int) (initer, error) {
 	var config *initConfig
 	if err := json.NewDecoder(pipe).Decode(&config); err != nil {
 		return nil, err
@@ -90,6 +90,7 @@ func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd
 			pipe:          pipe,
 			consoleSocket: consoleSocket,
 			config:        config,
+			logFd:         logFd,
 		}, nil
 	case initStandard:
 		return &linuxStandardInit{
@@ -98,6 +99,7 @@ func newContainerInit(t initType, pipe *os.File, consoleSocket *os.File, fifoFd
 			parentPid:     unix.Getppid(),
 			config:        config,
 			fifoFd:        fifoFd,
+			logFd:         logFd,
 		}, nil
 	}
 	return nil, fmt.Errorf("unknown init type %q", t)

libcontainer/logs/logs.go

@@ -6,14 +6,14 @@ import (
 	"fmt"
 	"io"
 	"os"
-	"strconv"
 	"sync"
 
+	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 )
 
 var (
-	configureMutex = 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
@@ -23,41 +23,46 @@ type Config struct {
 	LogLevel    logrus.Level
 	LogFormat   string
 	LogFilePath string
-	LogPipeFd   string
+	LogPipeFd   int
 }
 
-func ForwardLogs(logPipe io.Reader) {
-	lineReader := bufio.NewReader(logPipe)
-	for {
-		line, err := lineReader.ReadBytes('\n')
-		if len(line) > 0 {
-			processEntry(line)
+func ForwardLogs(logPipe io.ReadCloser) chan error {
+	done := make(chan error, 1)
+	s := bufio.NewScanner(logPipe)
+
+	go func() {
+		for s.Scan() {
+			processEntry(s.Bytes())
 		}
-		if err == io.EOF {
-			logrus.Debugf("log pipe has been closed: %+v", err)
-			return
+		if err := logPipe.Close(); err != nil {
+			logrus.Errorf("error closing log source: %v", err)
 		}
-		if err != nil {
-			logrus.Errorf("log pipe read error: %+v", err)
-		}
-	}
+		// The only error we want to return is when reading from
+		// logPipe has failed.
+		done <- s.Err()
+		close(done)
+	}()
+
+	return done
 }
 
 func processEntry(text []byte) {
-	type jsonLog struct {
+	if len(text) == 0 {
+		return
+	}
+
+	var jl struct {
 		Level string `json:"level"`
 		Msg   string `json:"msg"`
 	}
-
-	var jl jsonLog
 	if err := json.Unmarshal(text, &jl); err != nil {
-		logrus.Errorf("failed to decode %q to json: %+v", text, err)
+		logrus.Errorf("failed to decode %q to json: %v", text, err)
 		return
 	}
 
 	lvl, err := logrus.ParseLevel(jl.Level)
 	if err != nil {
-		logrus.Errorf("failed to parse log level %q: %v\n", jl.Level, err)
+		logrus.Errorf("failed to parse log level %q: %v", jl.Level, err)
 		return
 	}
 	logrus.StandardLogger().Logf(lvl, jl.Msg)
@@ -68,18 +73,15 @@ func ConfigureLogging(config Config) error {
 	defer configureMutex.Unlock()
 
 	if loggingConfigured {
-		logrus.Debug("logging has already been configured")
-		return nil
+		return errors.New("logging has already been configured")
 	}
 
 	logrus.SetLevel(config.LogLevel)
 
-	if config.LogPipeFd != "" {
-		logPipeFdInt, err := strconv.Atoi(config.LogPipeFd)
-		if err != nil {
-			return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", config.LogPipeFd, err)
-		}
-		logrus.SetOutput(os.NewFile(uintptr(logPipeFdInt), "logpipe"))
+	// XXX: while 0 is a valid fd (usually stdin), here we assume
+	// that we never deliberately set LogPipeFd to 0.
+	if config.LogPipeFd > 0 {
+		logrus.SetOutput(os.NewFile(uintptr(config.LogPipeFd), "logpipe"))
 	} else if config.LogFilePath != "" {
 		f, err := os.OpenFile(config.LogFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0644)
 		if err != nil {

libcontainer/logs/logs_linux_test.go

@@ -1,10 +1,10 @@
 package logs
 
 import (
-	"errors"
+	"bytes"
+	"io"
 	"io/ioutil"
 	"os"
-	"strings"
 	"testing"
 	"time"
 
@@ -12,141 +12,110 @@ import (
 )
 
 func TestLoggingToFile(t *testing.T) {
-	logW, logFile, _ := runLogForwarding(t)
-	defer os.Remove(logFile)
-	defer logW.Close()
+	l := runLogForwarding(t)
 
-	logToLogWriter(t, logW, `{"level": "info","msg":"kitten"}`)
-
-	logFileContent := waitForLogContent(t, logFile)
-	if !strings.Contains(logFileContent, "kitten") {
-		t.Fatalf("%s does not contain kitten", logFileContent)
-	}
+	logToLogWriter(t, l, `{"level": "info","msg":"kitten"}`)
+	finish(t, l)
+	check(t, l, "kitten")
 }
 
 func TestLogForwardingDoesNotStopOnJsonDecodeErr(t *testing.T) {
-	logW, logFile, _ := runLogForwarding(t)
-	defer os.Remove(logFile)
-	defer logW.Close()
+	l := runLogForwarding(t)
 
-	logToLogWriter(t, logW, "invalid-json-with-kitten")
+	logToLogWriter(t, l, "invalid-json-with-kitten")
+	checkWait(t, l, "failed to decode")
 
-	logFileContent := waitForLogContent(t, logFile)
-	if !strings.Contains(logFileContent, "failed to decode") {
-		t.Fatalf("%q does not contain decoding error", logFileContent)
-	}
+	truncateLogFile(t, l.file)
 
-	truncateLogFile(t, logFile)
-
-	logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`)
-
-	logFileContent = waitForLogContent(t, logFile)
-	if !strings.Contains(logFileContent, "puppy") {
-		t.Fatalf("%s does not contain puppy", logFileContent)
-	}
+	logToLogWriter(t, l, `{"level": "info","msg":"puppy"}`)
+	finish(t, l)
+	check(t, l, "puppy")
 }
 
 func TestLogForwardingDoesNotStopOnLogLevelParsingErr(t *testing.T) {
-	logW, logFile, _ := runLogForwarding(t)
-	defer os.Remove(logFile)
-	defer logW.Close()
+	l := runLogForwarding(t)
 
-	logToLogWriter(t, logW, `{"level": "alert","msg":"puppy"}`)
+	logToLogWriter(t, l, `{"level": "alert","msg":"puppy"}`)
+	checkWait(t, l, "failed to parse log level")
 
-	logFileContent := waitForLogContent(t, logFile)
-	if !strings.Contains(logFileContent, "failed to parse log level") {
-		t.Fatalf("%q does not contain log level parsing error", logFileContent)
-	}
+	truncateLogFile(t, l.file)
 
-	truncateLogFile(t, logFile)
-
-	logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`)
-
-	logFileContent = waitForLogContent(t, logFile)
-	if !strings.Contains(logFileContent, "puppy") {
-		t.Fatalf("%s does not contain puppy", logFileContent)
-	}
+	logToLogWriter(t, l, `{"level": "info","msg":"puppy"}`)
+	finish(t, l)
+	check(t, l, "puppy")
 }
 
 func TestLogForwardingStopsAfterClosingTheWriter(t *testing.T) {
-	logW, logFile, doneForwarding := runLogForwarding(t)
-	defer os.Remove(logFile)
+	l := runLogForwarding(t)
 
-	logToLogWriter(t, logW, `{"level": "info","msg":"sync"}`)
+	logToLogWriter(t, l, `{"level": "info","msg":"sync"}`)
 
-	logFileContent := waitForLogContent(t, logFile)
-	if !strings.Contains(logFileContent, "sync") {
-		t.Fatalf("%q does not contain sync message", logFileContent)
-	}
-
-	logW.Close()
+	// Do not use finish() here as we check done pipe ourselves.
+	l.w.Close()
 	select {
-	case <-doneForwarding:
+	case <-l.done:
 	case <-time.After(10 * time.Second):
 		t.Fatal("log forwarding did not stop after closing the pipe")
 	}
+
+	check(t, l, "sync")
 }
 
-func logToLogWriter(t *testing.T, logW *os.File, message string) {
-	_, err := logW.Write([]byte(message + "\n"))
+func logToLogWriter(t *testing.T, l *log, message string) {
+	t.Helper()
+	_, err := l.w.Write([]byte(message + "\n"))
 	if err != nil {
 		t.Fatalf("failed to write %q to log writer: %v", message, err)
 	}
 }
 
-func runLogForwarding(t *testing.T) (*os.File, string, chan struct{}) {
+type log struct {
+	w    io.WriteCloser
+	file string
+	done chan error
+}
+
+func runLogForwarding(t *testing.T) *log {
+	t.Helper()
 	logR, logW, err := os.Pipe()
 	if err != nil {
 		t.Fatal(err)
 	}
+	t.Cleanup(func() {
+		logR.Close()
+		logW.Close()
+	})
 
 	tempFile, err := ioutil.TempFile("", "")
 	if err != nil {
 		t.Fatal(err)
 	}
+	tempFile.Close()
 	logFile := tempFile.Name()
+	t.Cleanup(func() { os.Remove(logFile) })
 
 	logConfig := Config{LogLevel: logrus.InfoLevel, LogFormat: "json", LogFilePath: logFile}
-	return logW, logFile, startLogForwarding(t, logConfig, logR)
-}
-
-func startLogForwarding(t *testing.T, logConfig Config, logR *os.File) chan struct{} {
 	loggingConfigured = false
 	if err := ConfigureLogging(logConfig); err != nil {
 		t.Fatal(err)
 	}
-	doneForwarding := make(chan struct{})
-	go func() {
-		ForwardLogs(logR)
-		close(doneForwarding)
-	}()
-	return doneForwarding
+
+	doneForwarding := ForwardLogs(logR)
+
+	return &log{w: logW, done: doneForwarding, file: logFile}
 }
 
-func waitForLogContent(t *testing.T, logFile string) string {
-	startTime := time.Now()
-
-	for {
-		if time.Now().After(startTime.Add(10 * time.Second)) {
-			t.Fatal(errors.New("No content in log file after 10 seconds"))
-			break
-		}
-
-		fileContent, err := ioutil.ReadFile(logFile)
-		if err != nil {
-			t.Fatal(err)
-		}
-		if len(fileContent) == 0 {
-			continue
-		}
-		return string(fileContent)
+func finish(t *testing.T, l *log) {
+	t.Helper()
+	l.w.Close()
+	if err := <-l.done; err != nil {
+		t.Fatalf("ForwardLogs: %v", err)
 	}
-
-	return ""
 }
 
 func truncateLogFile(t *testing.T, logFile string) {
-	file, err := os.OpenFile(logFile, os.O_RDWR, 0666)
+	t.Helper()
+	file, err := os.OpenFile(logFile, os.O_RDWR, 0o600)
 	if err != nil {
 		t.Fatalf("failed to open log file: %v", err)
 		return
@@ -158,3 +127,40 @@ func truncateLogFile(t *testing.T, logFile string) {
 		t.Fatalf("failed to truncate log file: %v", err)
 	}
 }
+
+// check checks that file contains txt
+func check(t *testing.T, l *log, txt string) {
+	t.Helper()
+	contents, err := ioutil.ReadFile(l.file)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if !bytes.Contains(contents, []byte(txt)) {
+		t.Fatalf("%q does not contain %q", string(contents), txt)
+	}
+}
+
+// checkWait checks that file contains txt. If the file is empty,
+// it waits until it's not.
+func checkWait(t *testing.T, l *log, txt string) {
+	t.Helper()
+	const (
+		delay = 100 * time.Millisecond
+		iter  = 3
+	)
+	for i := 0; ; i++ {
+		st, err := os.Stat(l.file)
+		if err != nil {
+			t.Fatal(err)
+		}
+		if st.Size() > 0 {
+			break
+		}
+		if i == iter {
+			t.Fatalf("waited %s for file %s to be non-empty but it still is", iter*delay, l.file)
+		}
+		time.Sleep(delay)
+	}
+
+	check(t, l, txt)
+}

libcontainer/process_linux.go

@@ -51,7 +51,7 @@ type parentProcess interface {
 
 	setExternalDescriptors(fds []string)
 
-	forwardChildLogs()
+	forwardChildLogs() chan error
 }
 
 type filePair struct {
@@ -251,8 +251,8 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) {
 	p.fds = newFds
 }
 
-func (p *setnsProcess) forwardChildLogs() {
-	go logs.ForwardLogs(p.logFilePair.parent)
+func (p *setnsProcess) forwardChildLogs() chan error {
+	return logs.ForwardLogs(p.logFilePair.parent)
 }
 
 type initProcess struct {
@@ -605,8 +605,8 @@ func (p *initProcess) setExternalDescriptors(newFds []string) {
 	p.fds = newFds
 }
 
-func (p *initProcess) forwardChildLogs() {
-	go logs.ForwardLogs(p.logFilePair.parent)
+func (p *initProcess) forwardChildLogs() chan error {
+	return logs.ForwardLogs(p.logFilePair.parent)
 }
 
 func getPipeFds(pid int) ([]string, error) {

libcontainer/restored_process.go

@@ -77,7 +77,8 @@ func (p *restoredProcess) setExternalDescriptors(newFds []string) {
 	p.fds = newFds
 }
 
-func (p *restoredProcess) forwardChildLogs() {
+func (p *restoredProcess) forwardChildLogs() chan error {
+	return nil
 }
 
 // nonChildProcess represents a process where the calling process is not
@@ -125,5 +126,6 @@ func (p *nonChildProcess) setExternalDescriptors(newFds []string) {
 	p.fds = newFds
 }
 
-func (p *nonChildProcess) forwardChildLogs() {
+func (p *nonChildProcess) forwardChildLogs() chan error {
+	return nil
 }

libcontainer/setns_init_linux.go

@@ -12,6 +12,7 @@ import (
 	"github.com/opencontainers/runc/libcontainer/system"
 	"github.com/opencontainers/selinux/go-selinux"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"golang.org/x/sys/unix"
 )
 
@@ -21,6 +22,7 @@ type linuxSetnsInit struct {
 	pipe          *os.File
 	consoleSocket *os.File
 	config        *initConfig
+	logFd         int
 }
 
 func (l *linuxSetnsInit) getSessionRingName() string {
@@ -86,5 +88,11 @@ func (l *linuxSetnsInit) Init() error {
 			return newSystemErrorWithCause(err, "init seccomp")
 		}
 	}
+	logrus.Debugf("setns_init: about to exec")
+	// Close the log pipe fd so the parent's ForwardLogs can exit.
+	if err := unix.Close(l.logFd); err != nil {
+		return newSystemErrorWithCause(err, "closing log pipe fd")
+	}
+
 	return system.Execv(l.config.Args[0], l.config.Args[0:], os.Environ())
 }

libcontainer/standard_init_linux.go

@@ -16,6 +16,7 @@ import (
 	"github.com/opencontainers/runtime-spec/specs-go"
 	"github.com/opencontainers/selinux/go-selinux"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"golang.org/x/sys/unix"
 )
 
@@ -24,6 +25,7 @@ type linuxStandardInit struct {
 	consoleSocket *os.File
 	parentPid     int
 	fifoFd        int
+	logFd         int
 	config        *initConfig
 }
 
@@ -180,7 +182,14 @@ func (l *linuxStandardInit) Init() error {
 		return err
 	}
 	// Close the pipe to signal that we have completed our init.
+	logrus.Debugf("init: closing the pipe to signal completion")
 	l.pipe.Close()
+
+	// Close the log pipe fd so the parent's ForwardLogs can exit.
+	if err := unix.Close(l.logFd); err != nil {
+		return newSystemErrorWithCause(err, "closing log pipe fd")
+	}
+
 	// Wait for the FIFO to be opened on the other side before exec-ing the
 	// user process. We open it through /proc/self/fd/$fd, because the fd that
 	// was given to us was an O_PATH fd to the fifo itself. Linux allows us to

main.go

@@ -142,7 +142,7 @@ func main() {
 				fmt.Fprintln(os.Stderr, "the path in $XDG_RUNTIME_DIR must be writable by the user")
 				fatal(err)
 			}
-			if err := os.Chmod(root, 0700|os.ModeSticky); err != nil {
+			if err := os.Chmod(root, os.FileMode(0o700)|os.ModeSticky); err != nil {
 				fmt.Fprintln(os.Stderr, "you should check permission of the path in $XDG_RUNTIME_DIR")
 				fatal(err)
 			}
@@ -150,6 +150,10 @@ func main() {
 		if err := reviseRootDir(context); err != nil {
 			return err
 		}
+		// let init configure logging on its own
+		if args := context.Args(); args != nil && args.First() == "init" {
+			return nil
+		}
 		return logs.ConfigureLogging(createLogConfig(context))
 	}
 
@@ -176,9 +180,9 @@ func (f *FatalWriter) Write(p []byte) (n int, err error) {
 
 func createLogConfig(context *cli.Context) logs.Config {
 	logFilePath := context.GlobalString("log")
-	logPipeFd := ""
+	logPipeFd := 0
 	if logFilePath == "" {
-		logPipeFd = "2"
+		logPipeFd = 2
 	}
 	config := logs.Config{
 		LogPipeFd:   logPipeFd,

tests/integration/debug.bats

@@ -10,16 +10,20 @@ function teardown() {
 	teardown_bundle
 }
 
+function check_debug() {
+	[[ "$*" == *"nsexec started"* ]]
+	[[ "$*" == *"child process in init()"* ]]
+	[[ "$*" == *"init: closing the pipe to signal completion"* ]]
+}
+
 @test "global --debug" {
 	# run hello-world
 	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()"* ]]
+	check_debug "$output"
 }
 
 @test "global --debug to --log" {
@@ -30,14 +34,11 @@ function teardown() {
 	# check output does not include debug info
 	[[ "${output}" != *"level=debug"* ]]
 
-	# check log.out was generated
-	[ -e log.out ]
-
+	cat log.out >&2
 	# check expected debug output was sent to log.out
 	output=$(cat log.out)
 	[[ "${output}" == *"level=debug"* ]]
-	[[ "${output}" == *"nsexec started"* ]]
-	[[ "${output}" == *"child process in init()"* ]]
+	check_debug "$output"
 }
 
 @test "global --debug to --log --log-format 'text'" {
@@ -48,14 +49,11 @@ function teardown() {
 	# check output does not include debug info
 	[[ "${output}" != *"level=debug"* ]]
 
-	# check log.out was generated
-	[ -e log.out ]
-
+	cat log.out >&2
 	# check expected debug output was sent to log.out
 	output=$(cat log.out)
 	[[ "${output}" == *"level=debug"* ]]
-	[[ "${output}" == *"nsexec started"* ]]
-	[[ "${output}" == *"child process in init()"* ]]
+	check_debug "$output"
 }
 
 @test "global --debug to --log --log-format 'json'" {
@@ -66,12 +64,9 @@ function teardown() {
 	# check output does not include debug info
 	[[ "${output}" != *"level=debug"* ]]
 
-	# check log.out was generated
-	[ -e log.out ]
-
+	cat log.out >&2
 	# check expected debug output was sent to log.out
 	output=$(cat log.out)
 	[[ "${output}" == *'"level":"debug"'* ]]
-	[[ "${output}" == *"nsexec started"* ]]
-	[[ "${output}" == *"child process in init()"* ]]
+	check_debug "$output"
 }

tests/integration/exec.bats

@@ -132,6 +132,38 @@ function teardown() {
 	echo hello >preserve-fds.test
 	# fd 3 is used by bats, so we use 4
 	exec 4<preserve-fds.test
-	output=$(__runc exec --preserve-fds=2 test_busybox cat /proc/self/fd/4)
+	runc exec --preserve-fds=2 test_busybox cat /proc/self/fd/4
+	[ "$status" -eq 0 ]
 	[[ "${output}" == "hello" ]]
 }
+
+function check_exec_debug() {
+	[[ "$*" == *"nsexec started"* ]]
+	[[ "$*" == *"child process in init()"* ]]
+	[[ "$*" == *"setns_init: about to exec"* ]]
+}
+
+@test "runc --debug exec" {
+	runc run -d --console-socket "$CONSOLE_SOCKET" test
+	[ "$status" -eq 0 ]
+
+	runc --debug exec test true
+	[ "$status" -eq 0 ]
+	[[ "${output}" == *"level=debug"* ]]
+	check_exec_debug "$output"
+}
+
+@test "runc --debug --log exec" {
+	runc run -d --console-socket "$CONSOLE_SOCKET" test
+	[ "$status" -eq 0 ]
+
+	runc --debug --log log.out exec test true
+	# check output does not include debug info
+	[[ "${output}" != *"level=debug"* ]]
+
+	cat log.out >&2
+	# check expected debug output was sent to log.out
+	output=$(cat log.out)
+	[[ "${output}" == *"level=debug"* ]]
+	check_exec_debug "$output"
+}