diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go
index 65e2eace8c8..ac4beb63c5a 100644
--- a/libcontainer/container_linux.go
+++ b/libcontainer/container_linux.go
@@ -357,12 +357,26 @@ 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 init closing the _LIBCONTAINER_LOGPIPE log fd:
+ // For standard init, this is done by closeLogFD.
+ // For setns init, the fd is closed upon execve.
+ 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 f75084161a5..dd4c4a6a101 100644
--- a/libcontainer/logs/logs.go
+++ b/libcontainer/logs/logs.go
@@ -13,7 +13,7 @@ import (
)
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
@@ -26,16 +26,22 @@ type Config struct {
LogPipeFd int
}
-func ForwardLogs(logPipe io.Reader) {
+func ForwardLogs(logPipe io.ReadCloser) chan error {
+ done := make(chan error, 1)
s := bufio.NewScanner(logPipe)
- for s.Scan() {
- processEntry(s.Bytes())
- }
- if err := s.Err(); err != nil {
- logrus.Errorf("log pipe read error: %+v", err)
- } else {
- logrus.Debugf("log pipe closed")
- }
+
+ go func() {
+ for s.Scan() {
+ processEntry(s.Bytes())
+ }
+ if err := logPipe.Close(); err != nil {
+ logrus.Errorf("error closing log source: %v", err)
+ }
+ done <- s.Err()
+ close(done)
+ }()
+
+ return done
}
func processEntry(text []byte) {
diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go
index ec9ae4fc8b2..0baf7c4cbc0 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,109 @@ 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)
}
+ defer 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()
+ done := 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: done, 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)
+ file, err := os.OpenFile(logFile, os.O_RDWR, 0o600)
if err != nil {
t.Fatalf("failed to open log file: %v", err)
return
@@ -158,3 +126,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..9e7fc37dc5a 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,13 @@ func (l *linuxSetnsInit) Init() error {
return newSystemErrorWithCause(err, "init seccomp")
}
}
+ logrus.Debugf("init: about to exec")
+ // Close the log pipe fd so the parent's ForwardLogs can exit.
+ // Usually this would be done upon system.Execv below, as the fd
+ // has CLOEXEC flag set, but it may fail.
+ 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..0dee51b624c 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,19 @@ 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.
+ // Usually this would be done upon execve as the file descriptor
+ // has CLOEXEC flag set, but (1) execve might not happen due to
+ // any kind of error below; (2) in case of runc start, it spawns
+ // runc init and exits, while runc init (this code) waits on fifo
+ // for an indefinitely long time.
+ 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/tests/integration/debug.bats b/tests/integration/debug.bats
index cb7fe505c65..b2f87cf5f59 100644
--- a/tests/integration/debug.bats
+++ b/tests/integration/debug.bats
@@ -13,6 +13,7 @@ function teardown() {
function check_debug() {
[[ "$*" == *"nsexec started"* ]]
[[ "$*" == *"child process in init()"* ]]
+ [[ "$*" == *"init: closing the pipe to signal completion"* ]]
}
@test "global --debug" {
diff --git a/tests/integration/exec.bats b/tests/integration/exec.bats
index b7c9becbf47..779e7480a8e 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<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()"* ]]
+ [[ "$*" == *"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"
+}