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/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index 07592176b51..95deb0d6ca7 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -3,37 +3,28 @@ 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) + 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) @@ -47,60 +38,19 @@ 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 } 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) -} - -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 + logger.Log(jl.Level, jl.Msg) } diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go index 7e2b59d9cd7..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) } @@ -71,7 +78,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 +97,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,43 +117,40 @@ 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) } } -// 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) + 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 iter = 3 ) for i := 0; ; i++ { - st, err := os.Stat(l.file) + st, err := l.file.Stat() if err != nil { t.Fatal(err) } @@ -157,10 +158,10 @@ 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) } - check(t, l, txt) + check(t, l, txt, notxt) } diff --git a/main.go b/main.go index f141e79b443..bb69672f71d 100644 --- a/main.go +++ b/main.go @@ -1,13 +1,15 @@ package main import ( + "errors" "fmt" "io" "os" + "path/filepath" "runtime" + "strconv" "strings" - "github.com/opencontainers/runc/libcontainer/logs" "github.com/opencontainers/runc/libcontainer/seccomp" "github.com/opencontainers/runtime-spec/specs-go" @@ -149,7 +151,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 +175,42 @@ 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) + // 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 + }, + }) } - 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 }