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,24 +2,31 @@ 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() {
 	if len(os.Args) > 1 && os.Args[1] == "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`.
-// Subsequent invocations of `ConfigureLogging` would be no-op
-var loggingConfigured = false
+var (
+	mutex = &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 LoggingConfiguration struct {
-	IsDebug     bool
+type Config struct {
+	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)
-	if err := configureLogOutput(loggingConfig); err != nil {
-		return err
-	}
-	if err := configureLogFormat(loggingConfig); err != nil {
-		return err
-	}
+	logrus.SetLevel(config.LogLevel)
 
-	loggingConfigured = true
-	return nil
-}
-
-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 config.LogPipeFd != "" {
+		logPipeFdInt, err := strconv.Atoi(config.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)
-		return nil
-	}
-
-	return nil
-}
-
-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(os.NewFile(uintptr(logPipeFdInt), "logpipe"))
+	} 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)
 	}
-	logrus.SetOutput(f)
-	return nil
-}
 
-func configureLogFormat(loggingConfig *LoggingConfiguration) error {
-	switch loggingConfig.LogFormat {
+	switch config.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 {
-	PANIC = 0,
-	FATAL,
-	ERROR,
-	WARNING,
-	INFO,
-	DEBUG,
-} loglevel_t;
+#define PANIC   "panic"
+#define FATAL   "fatal"
+#define ERROR   "error"
+#define WARNING "warning"
+#define INFO    "info"
+#define DEBUG   "debug"
 
 int logfd;
 
@@ -142,20 +140,40 @@ 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;
 
 /* TODO(cyphar): Fix this so it correctly deals with syncT. */
 #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')
-		return -1;
-
-	pipenum = strtol(logpipe, &endptr, 10);
-	if (*endptr != '\0')
-		bail("unable to parse _LIBCONTAINER_LOGPIPE");
+	if (logpipe == NULL || *logpipe == '\0') {
+		logfd = -1;
+		return;
+	}
 
-	return pipenum;
+	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);
+	}
 }
 
 /* Returns the clone(2) flag for a namespace, given the name of a namespace. */
@@ -564,39 +584,19 @@ 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;
 	jmp_buf env;
 	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 */
-	logfd = logpipe();
-
-	write_log(DEBUG, "%s started", __FUNCTION__);
+	write_log(DEBUG, "nsexec started");
 
 	/* 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"