From ba3cabf932943cc927059a6782ae51b7dd862b4e Mon Sep 17 00:00:00 2001 From: Georgi Sabev Date: Fri, 19 Apr 2019 17:36:52 +0300 Subject: [PATCH] Improve nsexec logging * Simplify logging function * Logs contain __FUNCTION__:__LINE__ * Bail uses write_log Co-authored-by: Julia Nedialkova Co-authored-by: Danail Branekov Signed-off-by: Georgi Sabev --- exec.go | 7 ++ init.go | 15 +++-- libcontainer/container_linux.go | 3 +- libcontainer/logs/logs.go | 87 +++++++++---------------- libcontainer/logs/logs_linux_test.go | 6 +- libcontainer/nsenter/nsexec.c | 97 ++++++++++++++-------------- libcontainer/process.go | 2 + libcontainer/process_linux.go | 3 +- main.go | 22 +++---- tests/integration/debug.bats | 6 ++ utils_linux.go | 13 +++- 11 files changed, 129 insertions(+), 132 deletions(-) diff --git a/exec.go b/exec.go index 7fc04402a25..b963d68e018 100644 --- a/exec.go +++ b/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) } diff --git a/init.go b/init.go index 51b7ce33140..08351fdb488 100644 --- a/init.go +++ b/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)) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index 5cd66929509..e5f6ad88c24 100644 --- a/libcontainer/container_linux.go +++ b/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 diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index d7fd28e8db6..35d8bdac949 100644 --- a/libcontainer/logs/logs.go +++ b/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 } diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go index 7cbfabd81c2..83166fa8ee4 100644 --- a/libcontainer/logs/logs_linux_test.go +++ b/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) diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c index fef903165b8..494e3411faa 100644 --- a/libcontainer/nsenter/nsexec.c +++ b/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,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') - 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,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 */ - logfd = logpipe(); - - write_log(DEBUG, "%s started", __FUNCTION__); + write_log(DEBUG, "nsexec started"); /* Parse all of the netlink configuration. */ nl_parse(pipenum, &config); diff --git a/libcontainer/process.go b/libcontainer/process.go index 9a7c6014121..d3e472a4fdb 100644 --- a/libcontainer/process.go +++ b/libcontainer/process.go @@ -76,6 +76,8 @@ type Process struct { Init bool ops processOperations + + LogLevel string } // Wait waits for the process to exit. diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index c23f14687ff..8f920260693 100644 --- a/libcontainer/process_linux.go +++ b/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" diff --git a/main.go b/main.go index d3cbc882bad..273aeb84c30 100644 --- a/main.go +++ b/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) - if err != nil { - return fmt.Errorf("failed to create logging configuration: %v", err) - } - return logs.ConfigureLogging(loggingConfig) + return logs.ConfigureLogging(createLogConfig(context)) } // 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) { - config := logs.LoggingConfiguration{ - IsDebug: context.GlobalBool("debug"), +func createLogConfig(context *cli.Context) logs.Config { + config := logs.Config{ + LogLevel: logrus.InfoLevel, LogFilePath: context.GlobalString("log"), LogFormat: context.GlobalString("log-format"), } - - if envLogPipe, ok := os.LookupEnv("_LIBCONTAINER_LOGPIPE"); ok { - config.LogPipeFd = envLogPipe + if context.GlobalBool("debug") { + config.LogLevel = logrus.DebugLevel } - return &config, nil + return config } diff --git a/tests/integration/debug.bats b/tests/integration/debug.bats index 971bc7e1f83..187297990a2 100644 --- a/tests/integration/debug.bats +++ b/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()"* ]] } diff --git a/utils_linux.go b/utils_linux.go index b05e7b609d8..9b51c9fb332 100644 --- a/utils_linux.go +++ b/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) }