Logging improvements

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("")

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)
 }

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,20 +65,20 @@ 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)
 	}
 }
 
 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,54 +117,51 @@ 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)
 		}
 		if st.Size() > 0 {
 			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)
 }