Improve nsexec logging

* Simplify logging function
* Logs contain __FUNCTION__:__LINE__
* Bail uses write_log

Co-authored-by: Julia Nedialkova <julianedialkova@hotmail.com>
Co-authored-by: Danail Branekov <danailster@gmail.com>
Signed-off-by: Georgi Sabev <georgethebeatle@gmail.com>

exec.go

@@ -136,6 +136,12 @@ func execProcess(context *cli.Context) (int, error) {
 	if err != nil {
 		return -1, err
 	}
+
+	logLevel := "info"
+	if context.GlobalBool("debug") {
+		logLevel = "debug"
+	}
+
 	r := &runner{
 		enableSubreaper: false,
 		shouldDestroy:   false,
@@ -146,6 +152,7 @@ func execProcess(context *cli.Context) (int, error) {
 		action:          CT_ACT_RUN,
 		init:            false,
 		preserveFDs:     context.Int("preserve-fds"),
+		logLevel:        logLevel,
 	}
 	return r.run(p)
 }

init.go

@@ -2,13 +2,14 @@ package main
 
 import (
 	"fmt"
+	"os"
+	"runtime"
+
 	"github.com/opencontainers/runc/libcontainer"
 	"github.com/opencontainers/runc/libcontainer/logs"
 	_ "github.com/opencontainers/runc/libcontainer/nsenter"
 	"github.com/sirupsen/logrus"
 	"github.com/urfave/cli"
-	"os"
-	"runtime"
 )
 
 func init() {
@@ -16,10 +17,16 @@ func init() {
 		runtime.GOMAXPROCS(1)
 		runtime.LockOSThread()
 
-		err := logs.ConfigureLogging(&logs.LoggingConfiguration{
+		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))
+		}
+
+		err = logs.ConfigureLogging(logs.Config{
 			LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"),
 			LogFormat: "json",
-			IsDebug:   true,
+			LogLevel:  logLevel,
 		})
 		if err != nil {
 			panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err))

libcontainer/container_linux.go

@@ -19,7 +19,7 @@ import (
 	"syscall" // only for SysProcAttr and Signal
 	"time"
 
-	securejoin "github.com/cyphar/filepath-securejoin"
+	"github.com/cyphar/filepath-securejoin"
 	"github.com/opencontainers/runc/libcontainer/cgroups"
 	"github.com/opencontainers/runc/libcontainer/configs"
 	"github.com/opencontainers/runc/libcontainer/intelrdt"
@@ -497,6 +497,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe
 	cmd.ExtraFiles = append(cmd.ExtraFiles, logPipe)
 	cmd.Env = append(cmd.Env,
 		fmt.Sprintf("_LIBCONTAINER_LOGPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1),
+		fmt.Sprintf("_LIBCONTAINER_LOGLEVEL=%s", p.LogLevel),
 	)
 
 	// NOTE: when running a container with no PID namespace and the parent process spawning the container is

libcontainer/logs/logs.go

@@ -7,27 +7,26 @@ import (
 	"io"
 	"os"
 	"strconv"
+	"sync"
 
 	"github.com/sirupsen/logrus"
 )
 
-// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`.
+var (
-// Subsequent invocations of `ConfigureLogging` would be no-op
+	mutex = &sync.Mutex{}
-var loggingConfigured = false
+	// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`.
+	// Subsequent invocations of `ConfigureLogging` would be no-op
+	loggingConfigured = false
+)
 
-type LoggingConfiguration struct {
+type Config struct {
-	IsDebug     bool
+	LogLevel    logrus.Level
 	LogFormat   string
 	LogFilePath string
 	LogPipeFd   string
 }
 
 func ForwardLogs(logPipe io.Reader) {
-	type jsonLog struct {
-		Level string `json:"level"`
-		Msg   string `json:"msg"`
-	}
-
 	lineReader := bufio.NewReader(logPipe)
 	for {
 		line, err := lineReader.ReadBytes('\n')
@@ -83,68 +82,40 @@ func log(level logrus.Level, args ...interface{}) {
 	}
 }
 
-func ConfigureLogging(loggingConfig *LoggingConfiguration) error {
+func ConfigureLogging(config Config) error {
+	mutex.Lock()
+	defer mutex.Unlock()
+
 	if loggingConfigured {
-		logrus.Debug("logging has been already configured")
+		logrus.Debug("logging has already been configured")
 		return nil
 	}
 
-	configureLogLevel(loggingConfig)
+	logrus.SetLevel(config.LogLevel)
-	if err := configureLogOutput(loggingConfig); err != nil {
-		return err
-	}
-	if err := configureLogFormat(loggingConfig); err != nil {
-		return err
-	}
 
-	loggingConfigured = true
+	if config.LogPipeFd != "" {
-	return nil
+		logPipeFdInt, err := strconv.Atoi(config.LogPipeFd)
-}
-
-func configureLogLevel(loggingConfig *LoggingConfiguration) {
-	if loggingConfig.IsDebug {
-		logrus.SetLevel(logrus.DebugLevel)
-	}
-}
-
-func configureLogOutput(loggingConfig *LoggingConfiguration) error {
-	if loggingConfig.LogFilePath != "" {
-		return configureLogFileOutput(loggingConfig.LogFilePath)
-	}
-
-	if loggingConfig.LogPipeFd != "" {
-		logPipeFdInt, err := strconv.Atoi(loggingConfig.LogPipeFd)
 		if err != nil {
-			return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", loggingConfig.LogPipeFd, err)
+			return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", config.LogPipeFd, err)
 		}
-		configureLogPipeOutput(logPipeFdInt)
+		logrus.SetOutput(os.NewFile(uintptr(logPipeFdInt), "logpipe"))
-		return nil
+	} 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 {
+			return err
+		}
+		logrus.SetOutput(f)
 	}
 
-	return nil
+	switch config.LogFormat {
-}
-
-func configureLogPipeOutput(logPipeFd int) {
-	logrus.SetOutput(os.NewFile(uintptr(logPipeFd), "logpipe"))
-}
-
-func configureLogFileOutput(logFilePath string) error {
-	f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0644)
-	if err != nil {
-		return err
-	}
-	logrus.SetOutput(f)
-	return nil
-}
-
-func configureLogFormat(loggingConfig *LoggingConfiguration) error {
-	switch loggingConfig.LogFormat {
 	case "text":
 		// retain logrus's default.
 	case "json":
 		logrus.SetFormatter(new(logrus.JSONFormatter))
 	default:
-		return fmt.Errorf("unknown log-format %q", loggingConfig.LogFormat)
+		return fmt.Errorf("unknown log-format %q", config.LogFormat)
 	}
+
+	loggingConfigured = true
 	return nil
 }

libcontainer/logs/logs_linux_test.go

@@ -7,6 +7,8 @@ import (
 	"strings"
 	"testing"
 	"time"
+
+	"github.com/sirupsen/logrus"
 )
 
 func TestLoggingToFile(t *testing.T) {
@@ -104,11 +106,11 @@ func runLogForwarding(t *testing.T) (*os.File, string, chan struct{}) {
 	}
 	logFile := tempFile.Name()
 
-	logConfig := &LoggingConfiguration{LogFormat: "json", LogFilePath: logFile}
+	logConfig := Config{LogLevel: logrus.InfoLevel, LogFormat: "json", LogFilePath: logFile}
 	return logW, logFile, startLogForwarding(t, logConfig, logR)
 }
 
-func startLogForwarding(t *testing.T, logConfig *LoggingConfiguration, logR *os.File) chan struct{} {
+func startLogForwarding(t *testing.T, logConfig Config, logR *os.File) chan struct{} {
 	loggingConfigured = false
 	if err := ConfigureLogging(logConfig); err != nil {
 		t.Fatal(err)

libcontainer/nsenter/nsexec.c

@@ -95,14 +95,12 @@ struct nlconfig_t {
 	size_t gidmappath_len;
 };
 
-typedef enum {
+#define PANIC   "panic"
-	PANIC = 0,
+#define FATAL   "fatal"
-	FATAL,
+#define ERROR   "error"
-	ERROR,
+#define WARNING "warning"
-	WARNING,
+#define INFO    "info"
-	INFO,
+#define DEBUG   "debug"
-	DEBUG,
-} loglevel_t;
 
 int logfd;
 
@@ -142,6 +140,26 @@ int setns(int fd, int nstype)
 }
 #endif
 
+void write_log_with_info(const char *level, const char *function, int line, const char *format, ...)
+{
+	static char message[1024];
+	va_list args;
+
+	if (logfd < 0 || level == NULL)
+		return;
+
+	va_start(args, format);
+	if (vsnprintf(message, 1024, format, args) < 0)
+		return;
+	va_end(args);
+
+	if (dprintf(logfd, "{\"level\":\"%s\", \"msg\": \"%s:%d %s\"}\n", level, function, line, message) < 0)
+		return;
+}
+
+#define write_log(level, fmt, ...) \
+	write_log_with_info(level, __FUNCTION__, __LINE__, fmt, ##__VA_ARGS__)
+
 /* XXX: This is ugly. */
 static int syncfd = -1;
 
@@ -149,13 +167,13 @@ static int syncfd = -1;
 #define bail(fmt, ...)								\
 	do {									\
 		int ret = __COUNTER__ + 1;					\
-		fprintf(stderr, "nsenter: " fmt ": %m\n", ##__VA_ARGS__);	\
+		write_log(DEBUG, "nsenter: " fmt ": %m", ##__VA_ARGS__);	\
 		if (syncfd >= 0) {						\
 			enum sync_t s = SYNC_ERR;				\
 			if (write(syncfd, &s, sizeof(s)) != sizeof(s))		\
-				fprintf(stderr, "nsenter: failed: write(s)");	\
+				write_log(DEBUG, "nsenter: failed: write(s)");	\
 			if (write(syncfd, &ret, sizeof(ret)) != sizeof(ret))	\
-				fprintf(stderr, "nsenter: failed: write(ret)");	\
+				write_log(DEBUG, "nsenter: failed: write(ret)");	\
 		}								\
 		exit(ret);							\
 	} while(0)
@@ -363,20 +381,22 @@ static int initpipe(void)
 	return pipenum;
 }
 
-static int logpipe(void)
+static void setup_logpipe(void)
 {
-	int pipenum;
 	char *logpipe, *endptr;
 
 	logpipe = getenv("_LIBCONTAINER_LOGPIPE");
-	if (logpipe == NULL || *logpipe == '\0')
+	if (logpipe == NULL || *logpipe == '\0') {
-		return -1;
+		logfd = -1;
+		return;
+	}
 
-	pipenum = strtol(logpipe, &endptr, 10);
+	logfd = strtol(logpipe, &endptr, 10);
-	if (*endptr != '\0')
+	if (logpipe == endptr || *endptr != '\0') {
-		bail("unable to parse _LIBCONTAINER_LOGPIPE");
+		fprintf(stderr, "unable to parse _LIBCONTAINER_LOGPIPE, value: %s\n", logpipe);
-
+		/* It is too early to use bail */
-	return pipenum;
+		exit(1);
+	}
 }
 
 /* Returns the clone(2) flag for a namespace, given the name of a namespace. */
@@ -564,32 +584,6 @@ void join_namespaces(char *nslist)
 /* Defined in cloned_binary.c. */
 extern int ensure_cloned_binary(void);
 
-void write_log(loglevel_t level, const char *format, ...)
-{
-	static const char *strlevel[] = {"panic", "fatal", "error", "warning", "info", "debug"};
-	static char jsonbuffer[1024];
-	int len, written;
-	va_list args;
-	if (logfd < 0 || level >= sizeof(strlevel) / sizeof(strlevel[0])) {
-		return;
-	}
-
-	len = snprintf(jsonbuffer, sizeof(jsonbuffer),
-				   "{\"level\":\"%s\", \"msg\": \"", strlevel[level]);
-	if (len < 0) return;
-
-	va_start(args, format);
-	written = vsnprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, format, args);
-	if (written < 0) return;
-	len += written;
-	va_end(args);
-
-	written = snprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, "\"}\n");
-	if (written < 0) return;
-	len += written;
-	write(logfd, jsonbuffer, len);
-}
-
 void nsexec(void)
 {
 	int pipenum;
@@ -597,6 +591,12 @@ void nsexec(void)
 	int sync_child_pipe[2], sync_grandchild_pipe[2];
 	struct nlconfig_t config = { 0 };
 
+	/*
+	 * Setup a pipe to send logs to the parent. This should happen
+	 * first, because bail will use that pipe.
+	 */
+	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.
@@ -613,10 +613,7 @@ void nsexec(void)
 	if (ensure_cloned_binary() < 0)
 		bail("could not ensure we are a cloned binary");
 
-	/* Get the log pipe */
+	write_log(DEBUG, "nsexec started");
-	logfd = logpipe();
-
-	write_log(DEBUG, "%s started", __FUNCTION__);
 
 	/* Parse all of the netlink configuration. */
 	nl_parse(pipenum, &config);

libcontainer/process.go

@@ -76,6 +76,8 @@ type Process struct {
 	Init bool
 
 	ops processOperations
+
+	LogLevel string
 }
 
 // Wait waits for the process to exit.

libcontainer/process_linux.go

@@ -13,11 +13,10 @@ import (
 	"strconv"
 	"syscall" // only for Signal
 
-	"github.com/opencontainers/runc/libcontainer/logs"
-
 	"github.com/opencontainers/runc/libcontainer/cgroups"
 	"github.com/opencontainers/runc/libcontainer/configs"
 	"github.com/opencontainers/runc/libcontainer/intelrdt"
+	"github.com/opencontainers/runc/libcontainer/logs"
 	"github.com/opencontainers/runc/libcontainer/system"
 	"github.com/opencontainers/runc/libcontainer/utils"
 

main.go

@@ -2,11 +2,12 @@ package main
 
 import (
 	"fmt"
-	"github.com/opencontainers/runc/libcontainer/logs"
 	"io"
 	"os"
 	"strings"
 
+	"github.com/opencontainers/runc/libcontainer/logs"
+
 	"github.com/opencontainers/runtime-spec/specs-go"
 
 	"github.com/sirupsen/logrus"
@@ -134,11 +135,7 @@ func main() {
 		updateCommand,
 	}
 	app.Before = func(context *cli.Context) error {
-		loggingConfig, err := createLoggingConfiguration(context)
+		return logs.ConfigureLogging(createLogConfig(context))
-		if err != nil {
-			return fmt.Errorf("failed to create logging configuration: %v", err)
-		}
-		return logs.ConfigureLogging(loggingConfig)
 	}
 
 	// If the command returns an error, cli takes upon itself to print
@@ -159,16 +156,15 @@ func (f *FatalWriter) Write(p []byte) (n int, err error) {
 	return f.cliErrWriter.Write(p)
 }
 
-func createLoggingConfiguration(context *cli.Context) (*logs.LoggingConfiguration, error) {
+func createLogConfig(context *cli.Context) logs.Config {
-	config := logs.LoggingConfiguration{
+	config := logs.Config{
-		IsDebug:     context.GlobalBool("debug"),
+		LogLevel:    logrus.InfoLevel,
 		LogFilePath: context.GlobalString("log"),
 		LogFormat:   context.GlobalString("log-format"),
 	}
-
+	if context.GlobalBool("debug") {
-	if envLogPipe, ok := os.LookupEnv("_LIBCONTAINER_LOGPIPE"); ok {
+		config.LogLevel = logrus.DebugLevel
-		config.LogPipeFd = envLogPipe
 	}
 
-	return &config, nil
+	return config
 }

tests/integration/debug.bats

@@ -33,6 +33,8 @@ function teardown() {
   run cat log.out
   [ "$status" -eq 0 ]
   [[ "${output}" == *"level=debug"* ]]
+  [[ "${output}" == *"nsexec started"* ]]
+  [[ "${output}" == *"child process in init()"* ]]
 }
 
 @test "global --debug to --log --log-format 'text'" {
@@ -50,6 +52,8 @@ function teardown() {
   run cat log.out
   [ "$status" -eq 0 ]
   [[ "${output}" == *"level=debug"* ]]
+  [[ "${output}" == *"nsexec started"* ]]
+  [[ "${output}" == *"child process in init()"* ]]
 }
 
 @test "global --debug to --log --log-format 'json'" {
@@ -67,4 +71,6 @@ function teardown() {
   run cat log.out
   [ "$status" -eq 0 ]
   [[ "${output}" == *'"level":"debug"'* ]]
+  [[ "${output}" == *"nsexec started"* ]]
+  [[ "${output}" == *"child process in init()"* ]]
 }

utils_linux.go

@@ -105,7 +105,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) (*libcontainer.Process, error) {
+func newProcess(p specs.Process, init bool, logLevel string) (*libcontainer.Process, error) {
 	lp := &libcontainer.Process{
 		Args: p.Args,
 		Env:  p.Env,
@@ -116,6 +116,7 @@ func newProcess(p specs.Process, init bool) (*libcontainer.Process, error) {
 		NoNewPrivileges: &p.NoNewPrivileges,
 		AppArmorProfile: p.ApparmorProfile,
 		Init:            init,
+		LogLevel:        logLevel,
 	}
 
 	if p.ConsoleSize != nil {
@@ -264,6 +265,7 @@ type runner struct {
 	action          CtAct
 	notifySocket    *notifySocket
 	criuOpts        *libcontainer.CriuOpts
+	logLevel        string
 }
 
 func (r *runner) run(config *specs.Process) (int, error) {
@@ -271,7 +273,7 @@ func (r *runner) run(config *specs.Process) (int, error) {
 		r.destroy()
 		return -1, err
 	}
-	process, err := newProcess(*config, r.init)
+	process, err := newProcess(*config, r.init, r.logLevel)
 	if err != nil {
 		r.destroy()
 		return -1, err
@@ -430,6 +432,12 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
 	if os.Getenv("LISTEN_FDS") != "" {
 		listenFDs = activation.Files(false)
 	}
+
+	logLevel := "info"
+	if context.GlobalBool("debug") {
+		logLevel = "debug"
+	}
+
 	r := &runner{
 		enableSubreaper: !context.Bool("no-subreaper"),
 		shouldDestroy:   true,
@@ -443,6 +451,7 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
 		action:          action,
 		criuOpts:        criuOpts,
 		init:            true,
+		logLevel:        logLevel,
 	}
 	return r.run(spec.Process)
 }