diff --git a/init.go b/init.go index 08351fdb488..59ce1e8c739 100644 --- a/init.go +++ b/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, }) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index b5c7764aad2..93556a6534e 100644 --- a/libcontainer/container_linux.go +++ b/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") } diff --git a/libcontainer/container_linux_test.go b/libcontainer/container_linux_test.go index 2a9af6ad28e..78071a92651 100644 --- a/libcontainer/container_linux_test.go +++ b/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) { diff --git a/libcontainer/factory_linux.go b/libcontainer/factory_linux.go index 0b4cf59eb19..972b0f2b5d9 100644 --- a/libcontainer/factory_linux.go +++ b/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 } diff --git a/libcontainer/init_linux.go b/libcontainer/init_linux.go index c57af0eebb8..00f28e1f7eb 100644 --- a/libcontainer/init_linux.go +++ b/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) diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index 1077e7b0145..b114a5f50a5 100644 --- a/libcontainer/logs/logs.go +++ b/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) - } - if err == io.EOF { - logrus.Debugf("log pipe has been closed: %+v", err) - return +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 != nil { - logrus.Errorf("log pipe read error: %+v", err) + if err := logPipe.Close(); err != nil { + logrus.Errorf("error closing log source: %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 { diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go index ec9ae4fc8b2..7e2b59d9cd7 100644 --- a/libcontainer/logs/logs_linux_test.go +++ b/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() - - logToLogWriter(t, logW, "invalid-json-with-kitten") + l := runLogForwarding(t) - logFileContent := waitForLogContent(t, logFile) - if !strings.Contains(logFileContent, "failed to decode") { - t.Fatalf("%q does not contain decoding error", logFileContent) - } - - truncateLogFile(t, logFile) + logToLogWriter(t, l, "invalid-json-with-kitten") + checkWait(t, l, "failed to decode") - logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`) + truncateLogFile(t, l.file) - 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, logFile) - - logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`) + truncateLogFile(t, l.file) - 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 -} -func waitForLogContent(t *testing.T, logFile string) string { - startTime := time.Now() + doneForwarding := ForwardLogs(logR) - for { - if time.Now().After(startTime.Add(10 * time.Second)) { - t.Fatal(errors.New("No content in log file after 10 seconds")) - break - } + return &log{w: logW, done: doneForwarding, file: logFile} +} - 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) +} diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 6f2828770ee..8315d709aaa 100644 --- a/libcontainer/process_linux.go +++ b/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) { diff --git a/libcontainer/restored_process.go b/libcontainer/restored_process.go index f861e82d1b2..97565d7fa4b 100644 --- a/libcontainer/restored_process.go +++ b/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 } diff --git a/libcontainer/setns_init_linux.go b/libcontainer/setns_init_linux.go index 6b1e9a6e97c..97987f1d038 100644 --- a/libcontainer/setns_init_linux.go +++ b/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()) } diff --git a/libcontainer/standard_init_linux.go b/libcontainer/standard_init_linux.go index 7ec506c462e..d77022ad4d6 100644 --- a/libcontainer/standard_init_linux.go +++ b/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 diff --git a/main.go b/main.go index 57d7f4282e6..97bce5bf5a3 100644 --- a/main.go +++ b/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, diff --git a/tests/integration/debug.bats b/tests/integration/debug.bats index 16f1b2fb0cc..b2f87cf5f59 100644 --- a/tests/integration/debug.bats +++ b/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" } diff --git a/tests/integration/exec.bats b/tests/integration/exec.bats index b7c9becbf47..f80754a821e 100644 --- a/tests/integration/exec.bats +++ b/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&2 + # check expected debug output was sent to log.out + output=$(cat log.out) + [[ "${output}" == *"level=debug"* ]] + check_exec_debug "$output" +}