mirror of
https://github.com/opencontainers/runc.git
synced 2026-07-12 09:46:25 +08:00
Kir Kolyshkin
201d60c51d
Sometimes debug.bats test cases are failing like this:
> not ok 27 global --debug to --log --log-format 'json'
> # (in test file tests/integration/debug.bats, line 77)
> # `[[ "${output}" == *"child process in init()"* ]]' failed
It happens more when writing to disk.
This issue is caused by the fact that runc spawns log forwarding goroutine
(ForwardLogs) but does not wait for it to finish, resulting in missing
debug lines from nsexec.
ForwardLogs itself, though, never finishes, because it reads from a
reading side of a pipe which writing side is not closed. This is
especially true in case of runc create, which spawns runc init and
exits; meanwhile runc init waits on exec fifo for arbitrarily long
time before doing execve.
So, to fix the failure described above, we need to:
1. Make runc create/run/exec wait for ForwardLogs to finish;
2. Make runc init close its log pipe file descriptor (i.e.
the one which value is passed in _LIBCONTAINER_LOGPIPE
environment variable).
This is exactly what this commit does:
1. Amend ForwardLogs to return a channel, and wait for it in start().
2. In runc init, save the log fd and close it as late as possible.
PS I have to admit I still do not understand why an explicit close of
log pipe fd is required in e.g. (*linuxSetnsInit).Init, right before
the execve which (thanks to CLOEXEC) closes the fd anyway.
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
105 lines
2.2 KiB
Go
105 lines
2.2 KiB
Go
package logs
|
|
|
|
import (
|
|
"bufio"
|
|
"encoding/json"
|
|
"fmt"
|
|
"io"
|
|
"os"
|
|
"sync"
|
|
|
|
"github.com/pkg/errors"
|
|
"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
|
|
}
|
|
|
|
func ForwardLogs(logPipe io.ReadCloser) chan error {
|
|
done := make(chan error, 1)
|
|
s := bufio.NewScanner(logPipe)
|
|
|
|
go func() {
|
|
for s.Scan() {
|
|
processEntry(s.Bytes())
|
|
}
|
|
if err := logPipe.Close(); err != nil {
|
|
logrus.Errorf("error closing log source: %v", err)
|
|
}
|
|
// The only error we want to return is when reading from
|
|
// logPipe has failed.
|
|
done <- s.Err()
|
|
close(done)
|
|
}()
|
|
|
|
return done
|
|
}
|
|
|
|
func processEntry(text []byte) {
|
|
if len(text) == 0 {
|
|
return
|
|
}
|
|
|
|
var jl struct {
|
|
Level string `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)
|
|
|
|
// 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, 0644)
|
|
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
|
|
}
|