From f77fb7a3ee6d31327b46cb06662fd279ba512ddd Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Sun, 25 Jul 2021 20:43:17 -0700 Subject: [PATCH 1/6] 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. While at it, simplify errors on panic (errors from logrus.ParseLevel and strconv.Atoi already contain value which they fail to parse, and panic already contains enough context to figure out what's wrong). Signed-off-by: Kir Kolyshkin --- init.go | 24 ++++++++---------------- main.go | 40 ++++++++++++++++++++++++---------------- 2 files changed, 32 insertions(+), 32 deletions(-) diff --git a/init.go b/init.go index d39492952a3..61026e220e4 100644 --- a/init.go +++ b/init.go @@ -1,13 +1,11 @@ package main import ( - "fmt" "os" "runtime" "strconv" "github.com/opencontainers/runc/libcontainer" - "github.com/opencontainers/runc/libcontainer/logs" _ "github.com/opencontainers/runc/libcontainer/nsenter" "github.com/sirupsen/logrus" ) @@ -19,25 +17,19 @@ func init() { runtime.GOMAXPROCS(1) runtime.LockOSThread() - level := os.Getenv("_LIBCONTAINER_LOGLEVEL") - logLevel, err := logrus.ParseLevel(level) + logLevel, err := logrus.ParseLevel(os.Getenv("_LIBCONTAINER_LOGLEVEL")) if err != nil { - panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err)) + panic(err) } - logPipeFdStr := os.Getenv("_LIBCONTAINER_LOGPIPE") - logPipeFd, err := strconv.Atoi(logPipeFdStr) + logPipeFd, err := strconv.Atoi(os.Getenv("_LIBCONTAINER_LOGPIPE")) 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)) + panic(err) } + + logrus.SetLevel(logLevel) + 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..e610e4b657a 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,30 @@ 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"), + + switch f := context.GlobalString("log-format"); f { + case "": + // do nothing + case "text": + // do nothing + case "json": + logrus.SetFormatter(new(logrus.JSONFormatter)) + default: + return errors.New("invalid log-format: " + f) } - if context.GlobalBool("debug") { - config.LogLevel = logrus.DebugLevel + + 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) } - return config + return nil } From 8d8415ee469181ea15998da333358c83aa150e8e Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Sun, 25 Jul 2021 20:45:42 -0700 Subject: [PATCH 2/6] 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 --- 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 c4826905f1b3915e4c5b7f016ba721acacbbc155 Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Tue, 27 Jul 2021 13:02:55 -0700 Subject: [PATCH 3/6] 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 word (like "kitten") in the log output, which also happened to be there in case of an error (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 --- 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..d6563fd2e0e 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", contents, txt) + } + if notxt != "" && bytes.Contains(contents, []byte(notxt)) { + t.Fatalf("%s does contain %s", 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 c3910e7331c5d92f1c59a019734d362921f6cce0 Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Tue, 27 Jul 2021 13:08:26 -0700 Subject: [PATCH 4/6] 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 --- 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 b55b308143715914bd3569727237bb0b0ddb62bd Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Wed, 4 Aug 2021 17:36:10 -0700 Subject: [PATCH 5/6] 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 --- 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 a20c8b29d47988c7a4e60cb26d1c91146688aa40 Mon Sep 17 00:00:00 2001 From: Kir Kolyshkin Date: Wed, 4 Aug 2021 17:47:56 -0700 Subject: [PATCH 6/6] 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 --- main.go | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/main.go b/main.go index e610e4b657a..bb69672f71d 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 + }, + }) } switch f := context.GlobalString("log-format"); f {