mirror/runc
1
0
Fork 0
mirror of https://github.com/opencontainers/runc.git synced 2026-07-11 06:03:57 +08:00
Code Issues Packages Projects Releases Wiki Activity

merge branch 'pr-3157'

Browse Source 
Kir Kolyshkin (6):
  runc --debug: shorter caller info
  libct/logs: do not show caller in nsexec logs
  libct/logs: parse log level implicitly
  libct/logs: test: make more robust
  libct/logs: remove ConfigureLogging
  init.go, main.go: don't use logs.ConfigureLogging

LGTMs: thaJeztah cyphar
This commit is contained in:
Aleksa Sarai
2021-09-09 14:54:53 +10:00
parent 1e5fe26f4e a20c8b29d4
commit 3eccbe995e
4 changed files with 105 additions and 140 deletions
Download Patch File Download Diff File Expand all files Collapse all files
init.go
+8 -16
View File
@@ -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
+15 -65
View File
@@ -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
+43 -42
View File
@@ -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)
}
main.go
+39 -17
View File
@@ -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
}
config := logs.Config{
LogPipeFd: logPipeFd,
LogLevel: logrus.InfoLevel,
LogFilePath: logFilePath,
LogFormat: context.GlobalString("log-format"),
LogCaller: context.GlobalBool("debug"),
}
func configLogrus(context *cli.Context) error {
if context.GlobalBool("debug") {
config.LogLevel = logrus.DebugLevel
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
},
})
}
return config
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 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 nil
}