From da9d9bff3847080630f211e5c85ba8709e28e6cd Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Sun, 25 Jul 2021 20:43:17 -0700
Subject: [PATCH 01/16] init.go, main.go: don't use logs.ConfigureLogging

This function is somewhat strange and I always wanted to remove it,
as it tries to satisfy both init.go and main.go, which have somewhat
different needs.

It is more straightforward and readable to configure logrus directly.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 init.go | 15 ++++++---------
 main.go | 41 +++++++++++++++++++++++++----------------
 2 files changed, 31 insertions(+), 25 deletions(-)

diff --git a/init.go b/init.go
index d39492952a3..e7104331213 100644
--- a/init.go
+++ b/init.go
@@ -7,7 +7,6 @@ import (
 	"strconv"
 
 	"github.com/opencontainers/runc/libcontainer"
-	"github.com/opencontainers/runc/libcontainer/logs"
 	_ "github.com/opencontainers/runc/libcontainer/nsenter"
 	"github.com/sirupsen/logrus"
 )
@@ -19,25 +18,23 @@ func init() {
 		runtime.GOMAXPROCS(1)
 		runtime.LockOSThread()
 
+		// Configure logrus to talk to the parent.
 		level := os.Getenv("_LIBCONTAINER_LOGLEVEL")
 		logLevel, err := logrus.ParseLevel(level)
 		if err != nil {
 			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
 		}
+		logrus.SetLevel(logLevel)
 
 		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: logPipeFd,
-			LogFormat: "json",
-			LogLevel:  logLevel,
-		})
-		if err != nil {
-			panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err))
-		}
+
+		logrus.SetOutput(os.NewFile(uintptr(logPipeFd), "logpipe"))
+
+		logrus.SetFormatter(new(logrus.JSONFormatter))
 		logrus.Debug("child process in init()")
 
 		factory, _ := libcontainer.New("")
diff --git a/main.go b/main.go
index f141e79b443..8b19f69232f 100644
--- a/main.go
+++ b/main.go
@@ -1,13 +1,13 @@
 package main
 
 import (
+	"errors"
 	"fmt"
 	"io"
 	"os"
 	"runtime"
 	"strings"
 
-	"github.com/opencontainers/runc/libcontainer/logs"
 	"github.com/opencontainers/runc/libcontainer/seccomp"
 	"github.com/opencontainers/runtime-spec/specs-go"
 
@@ -149,7 +149,7 @@ func main() {
 			return err
 		}
 
-		return logs.ConfigureLogging(createLogConfig(context))
+		return configLogrus(context)
 	}
 
 	// If the command returns an error, cli takes upon itself to print
@@ -173,22 +173,31 @@ func (f *FatalWriter) Write(p []byte) (n int, err error) {
 	return len(p), nil
 }
 
-func createLogConfig(context *cli.Context) logs.Config {
-	logFilePath := context.GlobalString("log")
-	logPipeFd := 0
-	if logFilePath == "" {
-		logPipeFd = 2
+func configLogrus(context *cli.Context) error {
+	if context.GlobalBool("debug") {
+		logrus.SetLevel(logrus.DebugLevel)
+		logrus.SetReportCaller(true)
 	}
-	config := logs.Config{
-		LogPipeFd:   logPipeFd,
-		LogLevel:    logrus.InfoLevel,
-		LogFilePath: logFilePath,
-		LogFormat:   context.GlobalString("log-format"),
-		LogCaller:   context.GlobalBool("debug"),
+
+	if file := context.GlobalString("log"); file != "" {
+		f, err := os.OpenFile(file, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0o644)
+		if err != nil {
+			return err
+		}
+		logrus.SetOutput(f)
 	}
-	if context.GlobalBool("debug") {
-		config.LogLevel = logrus.DebugLevel
+
+	fmt := context.GlobalString("log-format")
+	switch fmt {
+	case "":
+		// do nothing
+	case "text":
+		// do nothing
+	case "json":
+		logrus.SetFormatter(new(logrus.JSONFormatter))
+	default:
+		return errors.New("invalid log-format: " + fmt)
 	}
 
-	return config
+	return nil
 }

From 40cd3fdffcfd00d20f86ffa7619433f234f7c3f1 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Sun, 25 Jul 2021 20:45:42 -0700
Subject: [PATCH 02/16] libct/logs: remove ConfigureLogging

Previous commits removed all its users -- the only one left is package's
own unit tests.

Modify those unit tests to configure logrus directly, and remove
ConfigureLogging for good. The world is better without it.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/logs/logs.go            | 55 ----------------------------
 libcontainer/logs/logs_linux_test.go | 35 +++++++-----------
 2 files changed, 13 insertions(+), 77 deletions(-)

diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go
index 07592176b51..e625abc7468 100644
--- a/libcontainer/logs/logs.go
+++ b/libcontainer/logs/logs.go
@@ -3,30 +3,11 @@ package logs
 import (
 	"bufio"
 	"encoding/json"
-	"errors"
-	"fmt"
 	"io"
-	"os"
-	"sync"
 
 	"github.com/sirupsen/logrus"
 )
 
-var (
-	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
-)
-
-type Config struct {
-	LogLevel    logrus.Level
-	LogFormat   string
-	LogFilePath string
-	LogPipeFd   int
-	LogCaller   bool
-}
-
 func ForwardLogs(logPipe io.ReadCloser) chan error {
 	done := make(chan error, 1)
 	s := bufio.NewScanner(logPipe)
@@ -68,39 +49,3 @@ func processEntry(text []byte) {
 	}
 	logrus.StandardLogger().Logf(lvl, jl.Msg)
 }
-
-func ConfigureLogging(config Config) error {
-	configureMutex.Lock()
-	defer configureMutex.Unlock()
-
-	if loggingConfigured {
-		return errors.New("logging has already been configured")
-	}
-
-	logrus.SetLevel(config.LogLevel)
-	logrus.SetReportCaller(config.LogCaller)
-
-	// 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, 0o644)
-		if err != nil {
-			return err
-		}
-		logrus.SetOutput(f)
-	}
-
-	switch config.LogFormat {
-	case "text":
-		// retain logrus's default.
-	case "json":
-		logrus.SetFormatter(new(logrus.JSONFormatter))
-	default:
-		return fmt.Errorf("unknown log-format %q", config.LogFormat)
-	}
-
-	loggingConfigured = true
-	return nil
-}
diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go
index 7e2b59d9cd7..17bcf6e05f8 100644
--- a/libcontainer/logs/logs_linux_test.go
+++ b/libcontainer/logs/logs_linux_test.go
@@ -71,7 +71,7 @@ func logToLogWriter(t *testing.T, l *log, message string) {
 
 type log struct {
 	w    io.WriteCloser
-	file string
+	file *os.File
 	done chan error
 }
 
@@ -90,19 +90,16 @@ func runLogForwarding(t *testing.T) *log {
 	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}
-	loggingConfigured = false
-	if err := ConfigureLogging(logConfig); err != nil {
-		t.Fatal(err)
-	}
+	t.Cleanup(func() {
+		tempFile.Close()
+		os.Remove(tempFile.Name())
+	})
 
+	logrus.SetOutput(tempFile)
+	logrus.SetFormatter(&logrus.JSONFormatter{})
 	doneForwarding := ForwardLogs(logR)
 
-	return &log{w: logW, done: doneForwarding, file: logFile}
+	return &log{w: logW, done: doneForwarding, file: tempFile}
 }
 
 func finish(t *testing.T, l *log) {
@@ -113,16 +110,10 @@ func finish(t *testing.T, l *log) {
 	}
 }
 
-func truncateLogFile(t *testing.T, logFile string) {
+func truncateLogFile(t *testing.T, file *os.File) {
 	t.Helper()
-	file, err := os.OpenFile(logFile, os.O_RDWR, 0o600)
-	if err != nil {
-		t.Fatalf("failed to open log file: %v", err)
-		return
-	}
-	defer file.Close()
 
-	err = file.Truncate(0)
+	err := file.Truncate(0)
 	if err != nil {
 		t.Fatalf("failed to truncate log file: %v", err)
 	}
@@ -131,7 +122,7 @@ func truncateLogFile(t *testing.T, logFile string) {
 // check checks that file contains txt
 func check(t *testing.T, l *log, txt string) {
 	t.Helper()
-	contents, err := ioutil.ReadFile(l.file)
+	contents, err := ioutil.ReadFile(l.file.Name())
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -149,7 +140,7 @@ func checkWait(t *testing.T, l *log, txt string) {
 		iter  = 3
 	)
 	for i := 0; ; i++ {
-		st, err := os.Stat(l.file)
+		st, err := l.file.Stat()
 		if err != nil {
 			t.Fatal(err)
 		}
@@ -157,7 +148,7 @@ func checkWait(t *testing.T, l *log, txt string) {
 			break
 		}
 		if i == iter {
-			t.Fatalf("waited %s for file %s to be non-empty but it still is", iter*delay, l.file)
+			t.Fatalf("waited %s for file %s to be non-empty but it still is", iter*delay, l.file.Name())
 		}
 		time.Sleep(delay)
 	}

From c8f32ea6e7cfad8a0841ce87017f5e5d7b3d72f0 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 13:02:55 -0700
Subject: [PATCH 03/16] libct/logs: test: make more robust

When playing with the log forwarder, I broke it, but all the units tests
were still passing. This happened because test cases were merely looking
for a work like "kitten" in the log output, which was also there as a
part of an error message produced by log forwarder.

Make the test a bit more robust by
 - looking for a complete log message, not just part of it;
 - also checking that log file does not contain errors.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/logs/logs_linux_test.go | 50 +++++++++++++++++-----------
 1 file changed, 30 insertions(+), 20 deletions(-)

diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go
index 17bcf6e05f8..5f975c8da57 100644
--- a/libcontainer/logs/logs_linux_test.go
+++ b/libcontainer/logs/logs_linux_test.go
@@ -11,44 +11,51 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
+const msgErr = `"level":"error"`
+
 func TestLoggingToFile(t *testing.T) {
 	l := runLogForwarding(t)
 
-	logToLogWriter(t, l, `{"level": "info","msg":"kitten"}`)
+	msg := `"level":"info","msg":"kitten"`
+	logToLogWriter(t, l, msg)
 	finish(t, l)
-	check(t, l, "kitten")
+	check(t, l, msg, msgErr)
 }
 
 func TestLogForwardingDoesNotStopOnJsonDecodeErr(t *testing.T) {
 	l := runLogForwarding(t)
 
-	logToLogWriter(t, l, "invalid-json-with-kitten")
-	checkWait(t, l, "failed to decode")
+	logToLogWriter(t, l, `"invalid-json-with-kitten"`)
+	checkWait(t, l, msgErr, "")
 
 	truncateLogFile(t, l.file)
 
-	logToLogWriter(t, l, `{"level": "info","msg":"puppy"}`)
+	msg := `"level":"info","msg":"puppy"`
+	logToLogWriter(t, l, msg)
 	finish(t, l)
-	check(t, l, "puppy")
+	check(t, l, msg, msgErr)
 }
 
 func TestLogForwardingDoesNotStopOnLogLevelParsingErr(t *testing.T) {
 	l := runLogForwarding(t)
 
-	logToLogWriter(t, l, `{"level": "alert","msg":"puppy"}`)
-	checkWait(t, l, "failed to parse log level")
+	msg := `"level":"alert","msg":"puppy"`
+	logToLogWriter(t, l, msg)
+	checkWait(t, l, msgErr, msg)
 
 	truncateLogFile(t, l.file)
 
-	logToLogWriter(t, l, `{"level": "info","msg":"puppy"}`)
+	msg = `"level":"info","msg":"puppy"`
+	logToLogWriter(t, l, msg)
 	finish(t, l)
-	check(t, l, "puppy")
+	check(t, l, msg, msgErr)
 }
 
 func TestLogForwardingStopsAfterClosingTheWriter(t *testing.T) {
 	l := runLogForwarding(t)
 
-	logToLogWriter(t, l, `{"level": "info","msg":"sync"}`)
+	msg := `"level":"info","msg":"sync"`
+	logToLogWriter(t, l, msg)
 
 	// Do not use finish() here as we check done pipe ourselves.
 	l.w.Close()
@@ -58,12 +65,12 @@ func TestLogForwardingStopsAfterClosingTheWriter(t *testing.T) {
 		t.Fatal("log forwarding did not stop after closing the pipe")
 	}
 
-	check(t, l, "sync")
+	check(t, l, msg, msgErr)
 }
 
 func logToLogWriter(t *testing.T, l *log, message string) {
 	t.Helper()
-	_, err := l.w.Write([]byte(message + "\n"))
+	_, err := l.w.Write([]byte("{" + message + "}\n"))
 	if err != nil {
 		t.Fatalf("failed to write %q to log writer: %v", message, err)
 	}
@@ -119,21 +126,24 @@ func truncateLogFile(t *testing.T, file *os.File) {
 	}
 }
 
-// check checks that file contains txt
-func check(t *testing.T, l *log, txt string) {
+// check checks that the file contains txt and does not contain notxt.
+func check(t *testing.T, l *log, txt, notxt string) {
 	t.Helper()
 	contents, err := ioutil.ReadFile(l.file.Name())
 	if err != nil {
 		t.Fatal(err)
 	}
-	if !bytes.Contains(contents, []byte(txt)) {
-		t.Fatalf("%q does not contain %q", string(contents), txt)
+	if txt != "" && !bytes.Contains(contents, []byte(txt)) {
+		t.Fatalf("%s does not contain %s", string(contents), txt)
+	}
+	if notxt != "" && bytes.Contains(contents, []byte(notxt)) {
+		t.Fatalf("%s does contain %s", string(contents), notxt)
 	}
 }
 
-// checkWait checks that file contains txt. If the file is empty,
+// checkWait is like check, but if the file is empty,
 // it waits until it's not.
-func checkWait(t *testing.T, l *log, txt string) {
+func checkWait(t *testing.T, l *log, txt string, notxt string) {
 	t.Helper()
 	const (
 		delay = 100 * time.Millisecond
@@ -153,5 +163,5 @@ func checkWait(t *testing.T, l *log, txt string) {
 		time.Sleep(delay)
 	}
 
-	check(t, l, txt)
+	check(t, l, txt, notxt)
 }

From 44fdfa6c3ac877a189bdc7039cca3a4ea0dda88b Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 13:08:26 -0700
Subject: [PATCH 04/16] libct/logs: parse log level implicitly

There's no need to call logrus.ParseLevel as logrus.Level already
implements encoding.TextUnmarshaler interface.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/logs/logs.go | 11 +++--------
 1 file changed, 3 insertions(+), 8 deletions(-)

diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go
index e625abc7468..d9a6991be06 100644
--- a/libcontainer/logs/logs.go
+++ b/libcontainer/logs/logs.go
@@ -34,18 +34,13 @@ func processEntry(text []byte) {
 	}
 
 	var jl struct {
-		Level string `json:"level"`
-		Msg   string `json:"msg"`
+		Level logrus.Level `json:"level"`
+		Msg   string       `json:"msg"`
 	}
 	if err := json.Unmarshal(text, &jl); err != nil {
 		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", jl.Level, err)
-		return
-	}
-	logrus.StandardLogger().Logf(lvl, jl.Msg)
+	logrus.StandardLogger().Logf(jl.Level, jl.Msg)
 }

From a6342149b1eb03ed21d151a1a8c4364436e60ebd Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Wed, 4 Aug 2021 17:36:10 -0700
Subject: [PATCH 05/16] libct/logs: do not show caller in nsexec logs

Commit 9f3d7534eaf236c2 enabled logrus to show information about log
caller, if --debug is set. It is helpful in many scenarios, but does
not work very well when we are debugging runc init, for example:

	# runc --debug run -d xx4557
	DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: logging set up
	DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: logging set up
	DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: => nsexec container setup
	DEBU[0000]libcontainer/logs/logs.go:45 github.com/opencontainers/runc/libcontainer/logs.processEntry() nsexec[279687]: update /proc/self/oom_score_adj to '30'

As we're merely forwarding the logs here, printing out filename:line and
function is useless and clutters the logs a log.

To fix, create and use a copy of the standard logger with caller info
turned off.

With this in place, nsexec logs are sane again:

	# runc --debug --log-format=text run -d xe34
	DEBU[0000] nsexec[293595]: logging set up
	DEBU[0000] nsexec[293595]: logging set up
	DEBU[0000] nsexec[293595]: => nsexec container setup
	DEBU[0000] nsexec[293595]: update /proc/self/oom_score_adj to '30'

This patch also changes Logf to Log in processEntry, as this is what it
should be.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/logs/logs.go | 16 +++++++++++++---
 1 file changed, 13 insertions(+), 3 deletions(-)

diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go
index d9a6991be06..95deb0d6ca7 100644
--- a/libcontainer/logs/logs.go
+++ b/libcontainer/logs/logs.go
@@ -12,9 +12,19 @@ func ForwardLogs(logPipe io.ReadCloser) chan error {
 	done := make(chan error, 1)
 	s := bufio.NewScanner(logPipe)
 
+	logger := logrus.StandardLogger()
+	if logger.ReportCaller {
+		// Need a copy of the standard logger, but with ReportCaller
+		// turned off, as the logs are merely forwarded and their
+		// true source is not this file/line/function.
+		logNoCaller := *logrus.StandardLogger()
+		logNoCaller.ReportCaller = false
+		logger = &logNoCaller
+	}
+
 	go func() {
 		for s.Scan() {
-			processEntry(s.Bytes())
+			processEntry(s.Bytes(), logger)
 		}
 		if err := logPipe.Close(); err != nil {
 			logrus.Errorf("error closing log source: %v", err)
@@ -28,7 +38,7 @@ func ForwardLogs(logPipe io.ReadCloser) chan error {
 	return done
 }
 
-func processEntry(text []byte) {
+func processEntry(text []byte, logger *logrus.Logger) {
 	if len(text) == 0 {
 		return
 	}
@@ -42,5 +52,5 @@ func processEntry(text []byte) {
 		return
 	}
 
-	logrus.StandardLogger().Logf(jl.Level, jl.Msg)
+	logger.Log(jl.Level, jl.Msg)
 }

From 746f04484d3d163d4d45925fbe03862abab8a640 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 14:27:36 -0700
Subject: [PATCH 06/16] libct/nsenter: test: logging nits

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsenter_test.go | 20 ++++++++++----------
 1 file changed, 10 insertions(+), 10 deletions(-)

diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go
index 9627a61fe53..59f2ed43903 100644
--- a/libcontainer/nsenter/nsenter_test.go
+++ b/libcontainer/nsenter/nsenter_test.go
@@ -47,7 +47,7 @@ func TestNsenterValidPaths(t *testing.T) {
 	}
 
 	if err := cmd.Start(); err != nil {
-		t.Fatalf("nsenter failed to start %v", err)
+		t.Fatal("nsenter failed to start:", err)
 	}
 
 	// write cloneFlags
@@ -70,7 +70,7 @@ func TestNsenterValidPaths(t *testing.T) {
 	var pid *pid
 
 	if err := cmd.Wait(); err != nil {
-		t.Fatalf("nsenter exits with a non-zero exit status")
+		t.Fatal("nsenter error:", err)
 	}
 	if err := decoder.Decode(&pid); err != nil {
 		dir, _ := ioutil.ReadDir(fmt.Sprintf("/proc/%d/ns", os.Getpid()))
@@ -106,7 +106,7 @@ func TestNsenterInvalidPaths(t *testing.T) {
 	}
 
 	if err := cmd.Start(); err != nil {
-		t.Fatal(err)
+		t.Fatal("nsenter failed to start:", err)
 	}
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
@@ -124,7 +124,7 @@ func TestNsenterInvalidPaths(t *testing.T) {
 
 	initWaiter(t, parent)
 	if err := cmd.Wait(); err == nil {
-		t.Fatalf("nsenter exits with a zero exit status")
+		t.Fatal("nsenter error:", err)
 	}
 }
 
@@ -132,7 +132,7 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 	args := []string{"nsenter-exec"}
 	parent, child, err := newPipe()
 	if err != nil {
-		t.Fatalf("failed to create pipe %v", err)
+		t.Fatal("failed to create pipe:", err)
 	}
 
 	namespaces := []string{
@@ -147,7 +147,7 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 	}
 
 	if err := cmd.Start(); err != nil {
-		t.Fatal(err)
+		t.Fatal("nsenter failed to start:", err)
 	}
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
@@ -165,7 +165,7 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 
 	initWaiter(t, parent)
 	if err := cmd.Wait(); err == nil {
-		t.Fatalf("nsenter exits with a zero exit status")
+		t.Fatal("nsenter error:", err)
 	}
 }
 
@@ -198,7 +198,7 @@ func TestNsenterChildLogging(t *testing.T) {
 	}
 
 	if err := cmd.Start(); err != nil {
-		t.Fatalf("nsenter failed to start %v", err)
+		t.Fatal("nsenter failed to start:", err)
 	}
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
@@ -228,7 +228,7 @@ func TestNsenterChildLogging(t *testing.T) {
 	}
 
 	if err := cmd.Wait(); err != nil {
-		t.Fatalf("nsenter exits with a non-zero exit status")
+		t.Fatal("nsenter error:", err)
 	}
 }
 
@@ -259,5 +259,5 @@ func initWaiter(t *testing.T, r io.Reader) {
 			return
 		}
 	}
-	t.Fatalf("waiting for init preliminary setup: %v", err)
+	t.Fatal("waiting for init preliminary setup:", err)
 }

From 4cb9e8051b2e8dfbd72cc29620ec3618fc26f243 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 16:10:28 -0700
Subject: [PATCH 07/16] libct/nsenter: test: improve newPipe

1. Make sure we close all file descriptors at the end of the test.

2. Make sure we close child fds after the start.

3. Use newPipe for logs as well, for simplicity and uniformity.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsenter_test.go | 52 +++++++++++++---------------
 1 file changed, 24 insertions(+), 28 deletions(-)

diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go
index 59f2ed43903..c607208e851 100644
--- a/libcontainer/nsenter/nsenter_test.go
+++ b/libcontainer/nsenter/nsenter_test.go
@@ -28,10 +28,7 @@ type logentry struct {
 
 func TestNsenterValidPaths(t *testing.T) {
 	args := []string{"nsenter-exec"}
-	parent, child, err := newPipe()
-	if err != nil {
-		t.Fatalf("failed to create pipe %v", err)
-	}
+	parent, child := newPipe(t)
 
 	namespaces := []string{
 		// join pid ns of the current process
@@ -49,6 +46,7 @@ func TestNsenterValidPaths(t *testing.T) {
 	if err := cmd.Start(); err != nil {
 		t.Fatal("nsenter failed to start:", err)
 	}
+	child.Close()
 
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
@@ -89,10 +87,7 @@ func TestNsenterValidPaths(t *testing.T) {
 
 func TestNsenterInvalidPaths(t *testing.T) {
 	args := []string{"nsenter-exec"}
-	parent, child, err := newPipe()
-	if err != nil {
-		t.Fatalf("failed to create pipe %v", err)
-	}
+	parent, child := newPipe(t)
 
 	namespaces := []string{
 		// join pid ns of the current process
@@ -108,6 +103,8 @@ func TestNsenterInvalidPaths(t *testing.T) {
 	if err := cmd.Start(); err != nil {
 		t.Fatal("nsenter failed to start:", err)
 	}
+	child.Close()
+
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
 	r.AddData(&libcontainer.Int32msg{
@@ -130,10 +127,7 @@ func TestNsenterInvalidPaths(t *testing.T) {
 
 func TestNsenterIncorrectPathType(t *testing.T) {
 	args := []string{"nsenter-exec"}
-	parent, child, err := newPipe()
-	if err != nil {
-		t.Fatal("failed to create pipe:", err)
-	}
+	parent, child := newPipe(t)
 
 	namespaces := []string{
 		// join pid ns of the current process
@@ -149,6 +143,8 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 	if err := cmd.Start(); err != nil {
 		t.Fatal("nsenter failed to start:", err)
 	}
+	child.Close()
+
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
 	r.AddData(&libcontainer.Int32msg{
@@ -171,18 +167,8 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 
 func TestNsenterChildLogging(t *testing.T) {
 	args := []string{"nsenter-exec"}
-	parent, child, err := newPipe()
-	if err != nil {
-		t.Fatalf("failed to create exec pipe %v", err)
-	}
-	logread, logwrite, err := os.Pipe()
-	if err != nil {
-		t.Fatalf("failed to create log pipe %v", err)
-	}
-	defer func() {
-		_ = logwrite.Close()
-		_ = logread.Close()
-	}()
+	parent, child := newPipe(t)
+	logread, logwrite := newPipe(t)
 
 	namespaces := []string{
 		// join pid ns of the current process
@@ -200,6 +186,9 @@ func TestNsenterChildLogging(t *testing.T) {
 	if err := cmd.Start(); err != nil {
 		t.Fatal("nsenter failed to start:", err)
 	}
+	child.Close()
+	logwrite.Close()
+
 	// write cloneFlags
 	r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0)
 	r.AddData(&libcontainer.Int32msg{
@@ -219,7 +208,7 @@ func TestNsenterChildLogging(t *testing.T) {
 	logsDecoder := json.NewDecoder(logread)
 	var logentry *logentry
 
-	err = logsDecoder.Decode(&logentry)
+	err := logsDecoder.Decode(&logentry)
 	if err != nil {
 		t.Fatalf("child log: %v", err)
 	}
@@ -238,12 +227,19 @@ func init() {
 	}
 }
 
-func newPipe() (parent *os.File, child *os.File, err error) {
+func newPipe(t *testing.T) (parent *os.File, child *os.File) {
+	t.Helper()
 	fds, err := unix.Socketpair(unix.AF_LOCAL, unix.SOCK_STREAM|unix.SOCK_CLOEXEC, 0)
 	if err != nil {
-		return nil, nil, err
+		t.Fatal("socketpair failed:", err)
 	}
-	return os.NewFile(uintptr(fds[1]), "parent"), os.NewFile(uintptr(fds[0]), "child"), nil
+	parent = os.NewFile(uintptr(fds[1]), "parent")
+	child = os.NewFile(uintptr(fds[0]), "child")
+	t.Cleanup(func() {
+		parent.Close()
+		child.Close()
+	})
+	return
 }
 
 // initWaiter reads back the initial \0 from runc init

From 17977491da203d9fa654d8a819eb9767e5b6bb5a Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 16:33:29 -0700
Subject: [PATCH 08/16] libct/nsenter: test: fix TestNsenterValidPaths

The test was not working since at least commit 64bb59f5920b1
renamed pid to stage2_pid (or maybe even earlier), so the pid
was never received (i.e. pid.Pid was 0).

The problem was not caught because os.FindProcess never return an error
on Unix.

Factor out and fix pid decode function:
 - use DisallowUnknownInput to get error if JSON will be changed;
 - check pids to make sure they are valid
 - and use unix.Wait4 to reap zombies.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsenter_test.go | 41 ++++++++++++++--------------
 1 file changed, 21 insertions(+), 20 deletions(-)

diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go
index c607208e851..ce5a42726dd 100644
--- a/libcontainer/nsenter/nsenter_test.go
+++ b/libcontainer/nsenter/nsenter_test.go
@@ -6,7 +6,6 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"io/ioutil"
 	"os"
 	"os/exec"
 	"strings"
@@ -17,10 +16,6 @@ import (
 	"golang.org/x/sys/unix"
 )
 
-type pid struct {
-	Pid int `json:"Pid"`
-}
-
 type logentry struct {
 	Msg   string `json:"msg"`
 	Level string `json:"level"`
@@ -64,25 +59,11 @@ func TestNsenterValidPaths(t *testing.T) {
 
 	initWaiter(t, parent)
 
-	decoder := json.NewDecoder(parent)
-	var pid *pid
-
 	if err := cmd.Wait(); err != nil {
 		t.Fatal("nsenter error:", err)
 	}
-	if err := decoder.Decode(&pid); err != nil {
-		dir, _ := ioutil.ReadDir(fmt.Sprintf("/proc/%d/ns", os.Getpid()))
-		for _, d := range dir {
-			t.Log(d.Name())
-		}
-		t.Fatalf("%v", err)
-	}
 
-	p, err := os.FindProcess(pid.Pid)
-	if err != nil {
-		t.Fatalf("%v", err)
-	}
-	_, _ = p.Wait()
+	reapChild(t, parent)
 }
 
 func TestNsenterInvalidPaths(t *testing.T) {
@@ -257,3 +238,23 @@ func initWaiter(t *testing.T, r io.Reader) {
 	}
 	t.Fatal("waiting for init preliminary setup:", err)
 }
+
+func reapChild(t *testing.T, parent *os.File) {
+	t.Helper()
+	decoder := json.NewDecoder(parent)
+	decoder.DisallowUnknownFields()
+	var pid struct {
+		Pid2 int `json:"stage2_pid"`
+		Pid1 int `json:"stage1_pid"`
+	}
+	if err := decoder.Decode(&pid); err != nil {
+		t.Fatal(err)
+	}
+	if pid.Pid1 == 0 || pid.Pid2 == 0 {
+		t.Fatal("got pids:", pid)
+	}
+
+	// Reap children.
+	_, _ = unix.Wait4(pid.Pid1, nil, 0, nil)
+	_, _ = unix.Wait4(pid.Pid2, nil, 0, nil)
+}

From 428d62729b471becef1307accd5c94b9a0e75f2b Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 16:41:41 -0700
Subject: [PATCH 09/16] libct/nsenter: test: improve TestNsenterChildLogging

Instead of reading a single message, do read all the logs from the init,
and use DisallowUnknownFields for stricter checking.

While at it, use reapChildren to reap zombies (and add an extra check).

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsenter_test.go | 41 +++++++++++++++++-----------
 1 file changed, 25 insertions(+), 16 deletions(-)

diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go
index ce5a42726dd..a7e454ca1be 100644
--- a/libcontainer/nsenter/nsenter_test.go
+++ b/libcontainer/nsenter/nsenter_test.go
@@ -16,11 +16,6 @@ import (
 	"golang.org/x/sys/unix"
 )
 
-type logentry struct {
-	Msg   string `json:"msg"`
-	Level string `json:"level"`
-}
-
 func TestNsenterValidPaths(t *testing.T) {
 	args := []string{"nsenter-exec"}
 	parent, child := newPipe(t)
@@ -186,20 +181,12 @@ func TestNsenterChildLogging(t *testing.T) {
 
 	initWaiter(t, parent)
 
-	logsDecoder := json.NewDecoder(logread)
-	var logentry *logentry
-
-	err := logsDecoder.Decode(&logentry)
-	if err != nil {
-		t.Fatalf("child log: %v", err)
-	}
-	if logentry.Level == "" || logentry.Msg == "" {
-		t.Fatalf("child log: empty log fileds: level=\"%s\" msg=\"%s\"", logentry.Level, logentry.Msg)
-	}
-
+	getLogs(t, logread)
 	if err := cmd.Wait(); err != nil {
 		t.Fatal("nsenter error:", err)
 	}
+
+	reapChild(t, parent)
 }
 
 func init() {
@@ -258,3 +245,25 @@ func reapChild(t *testing.T, parent *os.File) {
 	_, _ = unix.Wait4(pid.Pid1, nil, 0, nil)
 	_, _ = unix.Wait4(pid.Pid2, nil, 0, nil)
 }
+
+func getLogs(t *testing.T, logread *os.File) {
+	logsDecoder := json.NewDecoder(logread)
+	logsDecoder.DisallowUnknownFields()
+	var logentry struct {
+		Level string `json:"level"`
+		Msg   string `json:"msg"`
+	}
+
+	for {
+		if err := logsDecoder.Decode(&logentry); err != nil {
+			if errors.Is(err, io.EOF) {
+				return
+			}
+			t.Fatal("init log decoding error:", err)
+		}
+		t.Logf("logentry: %+v", logentry)
+		if logentry.Level == "" || logentry.Msg == "" {
+			t.Fatalf("init log: empty log entry: %+v", logentry)
+		}
+	}
+}

From 4eb38d56e534669092dd4e972743458ff6253ef3 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 17:46:35 -0700
Subject: [PATCH 10/16] libct/nsenter: test: rm misleading comments

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsenter_test.go | 2 --
 1 file changed, 2 deletions(-)

diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go
index a7e454ca1be..188a3fc5cd2 100644
--- a/libcontainer/nsenter/nsenter_test.go
+++ b/libcontainer/nsenter/nsenter_test.go
@@ -66,7 +66,6 @@ func TestNsenterInvalidPaths(t *testing.T) {
 	parent, child := newPipe(t)
 
 	namespaces := []string{
-		// join pid ns of the current process
 		fmt.Sprintf("pid:/proc/%d/ns/pid", -1),
 	}
 	cmd := &exec.Cmd{
@@ -106,7 +105,6 @@ func TestNsenterIncorrectPathType(t *testing.T) {
 	parent, child := newPipe(t)
 
 	namespaces := []string{
-		// join pid ns of the current process
 		fmt.Sprintf("net:/proc/%d/ns/pid", os.Getpid()),
 	}
 	cmd := &exec.Cmd{

From d542ee75796f383982c38c1688920d184f88971e Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 29 Jun 2021 17:22:08 -0700
Subject: [PATCH 11/16] utils_linux: simplify newProcess

newProcess do not need those extra arguments, they can be handled
in the caller.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 utils_linux.go | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)

diff --git a/utils_linux.go b/utils_linux.go
index 8b8d9e57eaf..bd45abf0e10 100644
--- a/utils_linux.go
+++ b/utils_linux.go
@@ -99,7 +99,7 @@ func getDefaultImagePath(context *cli.Context) string {
 
 // newProcess returns a new libcontainer Process with the arguments from the
 // spec and stdio from the current process.
-func newProcess(p specs.Process, init bool, logLevel string) (*libcontainer.Process, error) {
+func newProcess(p specs.Process) (*libcontainer.Process, error) {
 	lp := &libcontainer.Process{
 		Args: p.Args,
 		Env:  p.Env,
@@ -109,8 +109,6 @@ func newProcess(p specs.Process, init bool, logLevel string) (*libcontainer.Proc
 		Label:           p.SelinuxLabel,
 		NoNewPrivileges: &p.NoNewPrivileges,
 		AppArmorProfile: p.ApparmorProfile,
-		Init:            init,
-		LogLevel:        logLevel,
 	}
 
 	if p.ConsoleSize != nil {
@@ -272,10 +270,13 @@ func (r *runner) run(config *specs.Process) (int, error) {
 	if err = r.checkTerminal(config); err != nil {
 		return -1, err
 	}
-	process, err := newProcess(*config, r.init, r.logLevel)
+	process, err := newProcess(*config)
 	if err != nil {
 		return -1, err
 	}
+	// Populate the fields that come from runner.
+	process.Init = r.init
+	process.LogLevel = r.logLevel
 	if len(r.listenFDs) > 0 {
 		process.Env = append(process.Env, "LISTEN_FDS="+strconv.Itoa(len(r.listenFDs)), "LISTEN_PID=1")
 		process.ExtraFiles = append(process.ExtraFiles, r.listenFDs...)

From f86f43ffa5e7c7259a1e6499e6db62391113130d Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Sun, 25 Jul 2021 20:47:26 -0700
Subject: [PATCH 12/16] runc init: pass _LIBCONTAINER_LOGLEVEL as int

Instead of passing _LIBCONTAINER_LOGLEVEL as a string
(like "debug" or "info"), use a numeric value.

Also, simplify the init log level passing code -- since we actually use
the same level as the runc binary, just get it from logrus.

This is a preparation for the next commit.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 exec.go        | 6 ------
 init.go        | 7 +++----
 utils_linux.go | 9 +--------
 3 files changed, 4 insertions(+), 18 deletions(-)

diff --git a/exec.go b/exec.go
index f8baff3d152..65d0ce42e90 100644
--- a/exec.go
+++ b/exec.go
@@ -134,11 +134,6 @@ func execProcess(context *cli.Context) (int, error) {
 		return -1, err
 	}
 
-	logLevel := "info"
-	if context.GlobalBool("debug") {
-		logLevel = "debug"
-	}
-
 	r := &runner{
 		enableSubreaper: false,
 		shouldDestroy:   false,
@@ -149,7 +144,6 @@ func execProcess(context *cli.Context) (int, error) {
 		action:          CT_ACT_RUN,
 		init:            false,
 		preserveFDs:     context.Int("preserve-fds"),
-		logLevel:        logLevel,
 	}
 	return r.run(p)
 }
diff --git a/init.go b/init.go
index e7104331213..24ca4847b4f 100644
--- a/init.go
+++ b/init.go
@@ -19,12 +19,11 @@ func init() {
 		runtime.LockOSThread()
 
 		// Configure logrus to talk to the parent.
-		level := os.Getenv("_LIBCONTAINER_LOGLEVEL")
-		logLevel, err := logrus.ParseLevel(level)
+		level, err := strconv.Atoi(os.Getenv("_LIBCONTAINER_LOGLEVEL"))
 		if err != nil {
-			panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err))
+			panic(fmt.Sprintf("libcontainer: failed to parse _LIBCONTAINER_LOGLEVEL: %s", err))
 		}
-		logrus.SetLevel(logLevel)
+		logrus.SetLevel(logrus.Level(level))
 
 		logPipeFdStr := os.Getenv("_LIBCONTAINER_LOGPIPE")
 		logPipeFd, err := strconv.Atoi(logPipeFdStr)
diff --git a/utils_linux.go b/utils_linux.go
index bd45abf0e10..d21b194fa33 100644
--- a/utils_linux.go
+++ b/utils_linux.go
@@ -257,7 +257,6 @@ type runner struct {
 	action          CtAct
 	notifySocket    *notifySocket
 	criuOpts        *libcontainer.CriuOpts
-	logLevel        string
 }
 
 func (r *runner) run(config *specs.Process) (int, error) {
@@ -274,9 +273,9 @@ func (r *runner) run(config *specs.Process) (int, error) {
 	if err != nil {
 		return -1, err
 	}
+	process.LogLevel = strconv.Itoa(int(logrus.GetLevel()))
 	// Populate the fields that come from runner.
 	process.Init = r.init
-	process.LogLevel = r.logLevel
 	if len(r.listenFDs) > 0 {
 		process.Env = append(process.Env, "LISTEN_FDS="+strconv.Itoa(len(r.listenFDs)), "LISTEN_PID=1")
 		process.ExtraFiles = append(process.ExtraFiles, r.listenFDs...)
@@ -433,11 +432,6 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
 		listenFDs = activation.Files(false)
 	}
 
-	logLevel := "info"
-	if context.GlobalBool("debug") {
-		logLevel = "debug"
-	}
-
 	r := &runner{
 		enableSubreaper: !context.Bool("no-subreaper"),
 		shouldDestroy:   true,
@@ -451,7 +445,6 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
 		action:          action,
 		criuOpts:        criuOpts,
 		init:            true,
-		logLevel:        logLevel,
 	}
 	return r.run(spec.Process)
 }

From c153ebcf8eb77ad6cc2904ad1f0d42fdfcc6efac Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 17:16:37 -0700
Subject: [PATCH 13/16] libct/nsenter/nsexec.c: improve bail

This makes it possible to use bail() even if logging is not set up
(yet), so we don't have to think whether it's OK to use it or not.
In addition, this might help some unit tests that do not set log
forwarding.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsexec.c | 16 +++++++++-------
 1 file changed, 9 insertions(+), 7 deletions(-)

diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c
index ee7b75b1e5a..dd6265b2a8a 100644
--- a/libcontainer/nsenter/nsexec.c
+++ b/libcontainer/nsenter/nsexec.c
@@ -175,10 +175,14 @@ static void write_log(const char *level, const char *format, ...)
 /* XXX: This is ugly. */
 static int syncfd = -1;
 
-#define bail(fmt, ...)                                       \
-	do {                                                       \
-		write_log(FATAL, fmt ": %m", ##__VA_ARGS__); \
-		exit(1);                                                 \
+#define bail(fmt, ...)                                               \
+	do {                                                         \
+		if (logfd < 0)                                       \
+			fprintf(stderr, "FATAL: " fmt ": %m\n",      \
+				##__VA_ARGS__);                      \
+		else                                                 \
+			write_log(FATAL, fmt ": %m", ##__VA_ARGS__); \
+		exit(1);                                             \
 	} while(0)
 
 static int write_file(char *data, size_t data_len, char *pathfmt, ...)
@@ -400,9 +404,7 @@ static void setup_logpipe(void)
 
 	logfd = strtol(logpipe, &endptr, 10);
 	if (logpipe == endptr || *endptr != '\0') {
-		fprintf(stderr, "unable to parse _LIBCONTAINER_LOGPIPE, value: %s\n", logpipe);
-		/* It is too early to use bail */
-		exit(1);
+		bail("unable to parse _LIBCONTAINER_LOGPIPE, value: %s", logpipe);
 	}
 }
 

From ef71d3aa7c9f991478517299e76852dcdd88a83b Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 18:32:18 -0700
Subject: [PATCH 14/16] libct/nsenter/nsexec.c: factor out getenv_int

The code already parses an environment variable into an integer twice,
and we're about to add a third one.

Factor it out to getenv_int().

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsexec.c | 62 +++++++++++++++++++++--------------
 1 file changed, 37 insertions(+), 25 deletions(-)

diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c
index dd6265b2a8a..fdacec67ed2 100644
--- a/libcontainer/nsenter/nsexec.c
+++ b/libcontainer/nsenter/nsexec.c
@@ -373,39 +373,48 @@ static int clone_parent(jmp_buf *env, int jmpval)
 }
 
 /*
- * Gets the init pipe fd from the environment, which is used to read the
- * bootstrap data and tell the parent what the new pid is after we finish
- * setting up the environment.
+ * Returns an environment variable value as a non-negative integer, or -ENOENT
+ * if the variable was not found or has an empty value.
+ *
+ * If the value can not be converted to an integer, or the result is out of
+ * range, the function bails out.
  */
-static int initpipe(void)
+static int getenv_int(const char *name)
 {
-	int pipenum;
-	char *initpipe, *endptr;
+	char *val, *endptr;
+	int ret;
 
-	initpipe = getenv("_LIBCONTAINER_INITPIPE");
-	if (initpipe == NULL || *initpipe == '\0')
-		return -1;
+	val = getenv(name);
+	/* Treat empty value as unset variable. */
+	if (val == NULL || *val == '\0')
+		return -ENOENT;
 
-	pipenum = strtol(initpipe, &endptr, 10);
-	if (*endptr != '\0')
-		bail("unable to parse _LIBCONTAINER_INITPIPE");
+	ret = strtol(val, &endptr, 10);
+	if (val == endptr || *endptr != '\0')
+		bail("unable to parse %s=%s", name, val);
+	/*
+	 * Sanity check: this must be a non-negative number.
+	 */
+	if (ret < 0)
+		bail("bad value for %s=%s (%d)", name, val, ret);
 
-	return pipenum;
+	return ret;
 }
 
+/*
+ * Sets up logging by getting log fd from the environment,
+ * if available.
+ */
 static void setup_logpipe(void)
 {
-	char *logpipe, *endptr;
+	int i;
 
-	logpipe = getenv("_LIBCONTAINER_LOGPIPE");
-	if (logpipe == NULL || *logpipe == '\0') {
+	i = getenv_int("_LIBCONTAINER_LOGPIPE");
+	if (i < 0) {
+		/* We are not runc init, or log pipe was not provided. */
 		return;
 	}
-
-	logfd = strtol(logpipe, &endptr, 10);
-	if (logpipe == endptr || *endptr != '\0') {
-		bail("unable to parse _LIBCONTAINER_LOGPIPE, value: %s", logpipe);
-	}
+	logfd = i;
 }
 
 /* Returns the clone(2) flag for a namespace, given the name of a namespace. */
@@ -616,12 +625,15 @@ void nsexec(void)
 	setup_logpipe();
 
 	/*
-	 * If we don't have an init pipe, just return to the go routine.
-	 * We'll only get an init pipe for start or exec.
+	 * Get the init pipe fd from the environment. The init pipe is used to
+	 * read the bootstrap data and tell the parent what the new pids are
+	 * after the setup is done.
 	 */
-	pipenum = initpipe();
-	if (pipenum == -1)
+	pipenum = getenv_int("_LIBCONTAINER_INITPIPE");
+	if (pipenum < 0) {
+		/* We are not a runc init. Just return to go runtime. */
 		return;
+	}
 
 	/*
 	 * We need to re-exec if we are not in a cloned binary. This is necessary

From 903aa2a7af60910cb4ff033b6ca8c75e6d97ff64 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Tue, 27 Jul 2021 18:46:31 -0700
Subject: [PATCH 15/16] libct/nsenter/nsexec.c: honor _LIBCONTAINER_LOGLEVEL

Currently, if the log level is not set to e.g. "debug", runc init sends
some debug logs to the parent, which parses and discards it.

It is better to not send those in the first place.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 libcontainer/nsenter/nsexec.c | 41 ++++++++++++++++++++++++-----------
 1 file changed, 28 insertions(+), 13 deletions(-)

diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c
index fdacec67ed2..8d4d5dd1604 100644
--- a/libcontainer/nsenter/nsexec.c
+++ b/libcontainer/nsenter/nsexec.c
@@ -89,14 +89,21 @@ struct nlconfig_t {
 	size_t gidmappath_len;
 };
 
-#define PANIC   "panic"
-#define FATAL   "fatal"
-#define ERROR   "error"
-#define WARNING "warning"
-#define INFO    "info"
-#define DEBUG   "debug"
+/*
+ * Log levels are the same as in logrus.
+ */
+#define PANIC   0
+#define FATAL   1
+#define ERROR   2
+#define WARNING 3
+#define INFO    4
+#define DEBUG   5
+#define TRACE   6
+
+static const char *level_str[] = { "panic", "fatal", "error", "warning", "info", "debug", "trace" };
 
 static int logfd = -1;
+static int loglevel = INFO;
 
 /*
  * List of netlink message types sent to us as part of bootstrapping the init.
@@ -134,13 +141,13 @@ int setns(int fd, int nstype)
 }
 #endif
 
-static void write_log(const char *level, const char *format, ...)
+static void write_log(int level, const char *format, ...)
 {
 	char *message = NULL, *stage = NULL, *json = NULL;
 	va_list args;
 	int ret;
 
-	if (logfd < 0 || level == NULL)
+	if (logfd < 0 || level > loglevel)
 		goto out;
 
 	va_start(args, format);
@@ -158,7 +165,8 @@ static void write_log(const char *level, const char *format, ...)
 	if (ret < 0)
 		goto out;
 
-	ret = asprintf(&json, "{\"level\":\"%s\", \"msg\": \"%s[%d]: %s\"}\n", level, stage, getpid(), message);
+	ret = asprintf(&json, "{\"level\":\"%s\", \"msg\": \"%s[%d]: %s\"}\n",
+		       level_str[level], stage, getpid(), message);
 	if (ret < 0) {
 		json = NULL;
 		goto out;
@@ -393,16 +401,18 @@ static int getenv_int(const char *name)
 	if (val == endptr || *endptr != '\0')
 		bail("unable to parse %s=%s", name, val);
 	/*
-	 * Sanity check: this must be a non-negative number.
-	 */
-	if (ret < 0)
+	 * Sanity check: this must be a small non-negative number.
+	 * Practically, we pass two fds (3 and 4) and a log level,
+	 * for which the maximum is 6 (TRACE).
+	 * */
+	if (ret < 0 || ret > TRACE)
 		bail("bad value for %s=%s (%d)", name, val, ret);
 
 	return ret;
 }
 
 /*
- * Sets up logging by getting log fd from the environment,
+ * Sets up logging by getting log fd and log level from the environment,
  * if available.
  */
 static void setup_logpipe(void)
@@ -415,6 +425,11 @@ static void setup_logpipe(void)
 		return;
 	}
 	logfd = i;
+
+	i = getenv_int("_LIBCONTAINER_LOGLEVEL");
+	if (i < 0)
+		return;
+	loglevel = i;
 }
 
 /* Returns the clone(2) flag for a namespace, given the name of a namespace. */

From 0e9891533712cda77ef44101bf0625298f4b4088 Mon Sep 17 00:00:00 2001
From: Kir Kolyshkin <kolyshkin@gmail.com>
Date: Wed, 4 Aug 2021 17:47:56 -0700
Subject: [PATCH 16/16] runc --debug: shorter caller info

Commit 9f3d7534eaf236c2 enabled logrus to show information about log
caller, if --debug is set.

The problem is, the file name and in many cases the function name have a
long prefix of github.com/opencontainers/runc (this is with -trimpath,
and without it it's worse).

Add a function to trim the prefix.

Note all this happens only when --debug is given.

Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
---
 main.go | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

diff --git a/main.go b/main.go
index 8b19f69232f..ed00ce6ede1 100644
--- a/main.go
+++ b/main.go
@@ -5,7 +5,9 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"path/filepath"
 	"runtime"
+	"strconv"
 	"strings"
 
 	"github.com/opencontainers/runc/libcontainer/seccomp"
@@ -177,6 +179,18 @@ func configLogrus(context *cli.Context) error {
 	if context.GlobalBool("debug") {
 		logrus.SetLevel(logrus.DebugLevel)
 		logrus.SetReportCaller(true)
+		// Shorten function and file names reported by the logger, by
+		// trimming common "github.com/opencontainers/runc" prefix.
+		// This is only done for text formatter.
+		_, file, _, _ := runtime.Caller(0)
+		prefix := filepath.Dir(file) + "/"
+		logrus.SetFormatter(&logrus.TextFormatter{
+			CallerPrettyfier: func(f *runtime.Frame) (string, string) {
+				function := strings.TrimPrefix(f.Function, prefix) + "()"
+				fileLine := strings.TrimPrefix(f.File, prefix) + ":" + strconv.Itoa(f.Line)
+				return function, fileLine
+			},
+		})
 	}
 
 	if file := context.GlobalString("log"); file != "" {