From 897d121e303cfe85b273696e1329c797b2408cf4 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Thu, 11 Mar 2021 11:27:02 -0800
Subject: [PATCH] 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 <kolyshkin@gmail.com>
---
 libcontainer/setns_init_linux.go    |  2 ++
 libcontainer/standard_init_linux.go |  2 ++
 tests/integration/debug.bats        |  1 +
 tests/integration/exec.bats         | 34 ++++++++++++++++++++++++++++-
 4 files changed, 38 insertions(+), 1 deletion(-)

diff --git a/libcontainer/setns_init_linux.go b/libcontainer/setns_init_linux.go
index 5dc7a068488..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"
 )
 
@@ -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")
diff --git a/libcontainer/standard_init_linux.go b/libcontainer/standard_init_linux.go
index 60f9b79ed61..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"
 )
 
@@ -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.
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..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<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"
+}