runc --debug: more tests

First, add runc --debug exec test cases, very similar to those in
debug.bats but for runc exec (rather than runc run). Do not include json
tests as it is already tested in debug.bats.

Second, add logrus debug to late stages of runc init, and amend the
integration tests to check for those messages. This serves two purposes:

 - demonstrate that runc init can be amended with debug logrus which is
   properly forwarded to and logged by the parent runc create/run/exec;

 - improve the chances to catch the race fixed by the previous commit.

Signed-off-by: Kir Kolyshkin <[email protected]>

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"
 )
 
@@ -87,6 +88,7 @@ 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")

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"
 )
 
@@ -181,6 +182,7 @@ 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.

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

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"
+}