From 9a599f62fbdc7cc366c09424485abea8efbbc004 Mon Sep 17 00:00:00 2001 From: Marco Vedovati Date: Fri, 3 Aug 2018 19:11:20 +0200 Subject: [PATCH 1/7] Support for logging from children processes Add support for children processes logging (including nsexec). A pipe is used to send logs from children to parent in JSON. The JSON format used is the same used by logrus JSON formatted, i.e. children process can use standard logrus APIs. Signed-off-by: Marco Vedovati --- init.go | 15 ++++++ libcontainer/container_linux.go | 28 ++++++++--- libcontainer/logs.go | 70 ++++++++++++++++++++++++++++ libcontainer/nsenter/nsenter_test.go | 59 +++++++++++++++++++++++ libcontainer/nsenter/nsexec.c | 53 +++++++++++++++++++++ libcontainer/process_linux.go | 21 +++++++++ libcontainer/restored_process.go | 6 +++ libcontainer/standard_init_linux.go | 5 ++ main.go | 6 +++ 9 files changed, 257 insertions(+), 6 deletions(-) create mode 100644 libcontainer/logs.go diff --git a/init.go b/init.go index c8f453192..0a10779d7 100644 --- a/init.go +++ b/init.go @@ -3,9 +3,11 @@ package main import ( "os" "runtime" + "strconv" "github.com/opencontainers/runc/libcontainer" _ "github.com/opencontainers/runc/libcontainer/nsenter" + "github.com/sirupsen/logrus" "github.com/urfave/cli" ) @@ -13,6 +15,19 @@ func init() { if len(os.Args) > 1 && os.Args[1] == "init" { runtime.GOMAXPROCS(1) runtime.LockOSThread() + + // in child process, we need to retrieve the log pipe + envLogPipe := os.Getenv("_LIBCONTAINER_LOGPIPE") + logPipeFd, err := strconv.Atoi(envLogPipe) + + if err != nil { + return + } + logPipe := os.NewFile(uintptr(logPipeFd), "logpipe") + logrus.SetOutput(logPipe) + logrus.SetFormatter(&logrus.JSONFormatter{}) + logrus.SetLevel(logrus.DebugLevel) + logrus.Debug("child process in init()") } } diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index 7e58e5e00..ecba1f9d6 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -337,6 +337,7 @@ func (c *linuxContainer) start(process *Process) error { if err != nil { return newSystemErrorWithCause(err, "creating new parent process") } + parent.getChildLogs() if err := parent.start(); err != nil { // terminate the process to ensure that it properly is reaped. if err := ignoreTerminateErrors(parent.terminate()); err != nil { @@ -442,12 +443,19 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { if err != nil { return nil, newSystemErrorWithCause(err, "creating new init pipe") } - cmd, err := c.commandTemplate(p, childPipe) + + r, w, err := os.Pipe() + if err != nil { + return nil, fmt.Errorf("Unable to create the log pipe: %s", err) + } + logPipe := pipePair{r, w} + + cmd, err := c.commandTemplate(p, childPipe, logPipe.w) if err != nil { return nil, newSystemErrorWithCause(err, "creating new command template") } if !p.Init { - return c.newSetnsProcess(p, cmd, parentPipe, childPipe) + return c.newSetnsProcess(p, cmd, parentPipe, childPipe, &logPipe) } // We only set up fifoFd if we're not doing a `runc exec`. The historic @@ -458,10 +466,10 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { if err := c.includeExecFifo(cmd); err != nil { return nil, newSystemErrorWithCause(err, "including execfifo in cmd.Exec setup") } - return c.newInitProcess(p, cmd, parentPipe, childPipe) + return c.newInitProcess(p, cmd, parentPipe, childPipe, &logPipe) } -func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec.Cmd, error) { +func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe *os.File) (*exec.Cmd, error) { cmd := exec.Command(c.initPath, c.initArgs[1:]...) cmd.Args[0] = c.initArgs[0] cmd.Stdin = p.Stdin @@ -484,6 +492,12 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec. fmt.Sprintf("_LIBCONTAINER_INITPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), fmt.Sprintf("_LIBCONTAINER_STATEDIR=%s", c.root), ) + + cmd.ExtraFiles = append(cmd.ExtraFiles, logPipe) + cmd.Env = append(cmd.Env, + fmt.Sprintf("_LIBCONTAINER_LOGPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), + ) + // NOTE: when running a container with no PID namespace and the parent process spawning the container is // PID1 the pdeathsig is being delivered to the container's init process by the kernel for some reason // even with the parent still running. @@ -493,7 +507,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec. return cmd, nil } -func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File) (*initProcess, error) { +func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File, logPipe *pipePair) (*initProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initStandard)) nsMaps := make(map[configs.NamespaceType]string) for _, ns := range c.config.Namespaces { @@ -510,6 +524,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c cmd: cmd, childPipe: childPipe, parentPipe: parentPipe, + logPipe: *logPipe, manager: c.cgroupManager, intelRdtManager: c.intelRdtManager, config: c.newInitConfig(p), @@ -522,7 +537,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c return init, nil } -func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File) (*setnsProcess, error) { +func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File, logPipe *pipePair) (*setnsProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns)) state, err := c.currentState() if err != nil { @@ -541,6 +556,7 @@ func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, intelRdtPath: state.IntelRdtPath, childPipe: childPipe, parentPipe: parentPipe, + logPipe: *logPipe, config: c.newInitConfig(p), process: p, bootstrapData: data, diff --git a/libcontainer/logs.go b/libcontainer/logs.go new file mode 100644 index 000000000..0b074a987 --- /dev/null +++ b/libcontainer/logs.go @@ -0,0 +1,70 @@ +package libcontainer + +import ( + "encoding/json" + "fmt" + "io" + "os" + + "github.com/sirupsen/logrus" +) + +func forwardLogs(p *os.File) { + defer p.Close() + + type jsonLog struct { + Level string `json:"level"` + Msg string `json:"msg"` + } + + dec := json.NewDecoder(p) + for { + var jl jsonLog + + type logFuncTable map[logrus.Level]func(args ...interface{}) + logMapping := logFuncTable{ + logrus.PanicLevel: logrus.Panic, + logrus.FatalLevel: logrus.Fatal, + logrus.ErrorLevel: logrus.Error, + logrus.WarnLevel: logrus.Warn, + logrus.InfoLevel: logrus.Info, + logrus.DebugLevel: logrus.Debug, + } + + err := dec.Decode(&jl) + if err != nil { + if err == io.EOF { + logrus.Debug("child pipe closed") + return + } + logrus.Errorf("json logs decoding error: %+v", err) + return + } + + lvl, err := logrus.ParseLevel(jl.Level) + if err != nil { + fmt.Printf("parsing error\n") + } + if logMapping[lvl] != nil { + logMapping[lvl](jl.Msg) + } + } +} + +func rawLogs(p *os.File) { + defer p.Close() + + data := make([]byte, 128) + for { + _, err := p.Read(data) + + if err != nil { + if err == io.EOF { + logrus.Debug("child pipe closed") + return + } + return + } + fmt.Printf("Read data: %s\n", string(data)) + } +} diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go index 532155535..9be6a8038 100644 --- a/libcontainer/nsenter/nsenter_test.go +++ b/libcontainer/nsenter/nsenter_test.go @@ -21,6 +21,11 @@ type pid struct { Pid int `json:"Pid"` } +type logentry struct { + Msg string + Level string +} + func TestNsenterValidPaths(t *testing.T) { args := []string{"nsenter-exec"} parent, child, err := newPipe() @@ -159,6 +164,60 @@ func TestNsenterIncorrectPathType(t *testing.T) { } } +func TestNsenterChildLogging(t *testing.T) { + args := []string{"nsenter-exec"} + parent, child, err := newPipe() + logread, logwrite, err := os.Pipe() + if err != nil { + t.Fatalf("failed to create pipe %v", err) + } + + namespaces := []string{ + // join pid ns of the current process + fmt.Sprintf("pid:/proc/%d/ns/pid", os.Getpid()), + } + cmd := &exec.Cmd{ + Path: os.Args[0], + Args: args, + ExtraFiles: []*os.File{child, logwrite}, + Env: []string{"_LIBCONTAINER_INITPIPE=3", "_LIBCONTAINER_LOGPIPE=4"}, + Stdout: os.Stdout, + Stderr: os.Stderr, + } + + if err := cmd.Start(); err != nil { + t.Fatalf("nsenter failed to start %v", err) + } + // write cloneFlags + r := nl.NewNetlinkRequest(int(libcontainer.InitMsg), 0) + r.AddData(&libcontainer.Int32msg{ + Type: libcontainer.CloneFlagsAttr, + Value: uint32(unix.CLONE_NEWNET), + }) + r.AddData(&libcontainer.Bytemsg{ + Type: libcontainer.NsPathsAttr, + Value: []byte(strings.Join(namespaces, ",")), + }) + if _, err := io.Copy(parent, bytes.NewReader(r.Serialize())); err != nil { + t.Fatal(err) + } + + logsDecoder := json.NewDecoder(logread) + var logentry *logentry + + err = logsDecoder.Decode(&logentry) + if err != nil { + t.Fatalf("child log: %v", err) + } + if logentry.Level == "" || logentry.Msg == "" { + t.Fatalf("child log: empty log fileds: level=\"%s\" msg=\"%s\"", logentry.Level, logentry.Msg) + } + + if err := cmd.Wait(); err != nil { + t.Fatalf("nsenter exits with a non-zero exit status") + } +} + func init() { if strings.HasPrefix(os.Args[0], "nsenter-") { os.Exit(0) diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c index 7750af35e..af50cd87a 100644 --- a/libcontainer/nsenter/nsexec.c +++ b/libcontainer/nsenter/nsexec.c @@ -95,6 +95,17 @@ struct nlconfig_t { size_t gidmappath_len; }; +typedef enum { + PANIC = 0, + FATAL, + ERROR, + WARNING, + INFO, + DEBUG, +} loglevel_t; + +int logfd; + /* * List of netlink message types sent to us as part of bootstrapping the init. * These constants are defined in libcontainer/message_linux.go. @@ -352,6 +363,22 @@ static int initpipe(void) return pipenum; } +static int logpipe(void) +{ + int pipenum; + char *logpipe, *endptr; + + logpipe = getenv("_LIBCONTAINER_LOGPIPE"); + if (logpipe == NULL || *logpipe == '\0') + return -1; + + pipenum = strtol(logpipe, &endptr, 10); + if (*endptr != '\0') + bail("unable to parse _LIBCONTAINER_LOGPIPE"); + + return pipenum; +} + /* Returns the clone(2) flag for a namespace, given the name of a namespace. */ static int nsflag(char *name) { @@ -537,6 +564,27 @@ void join_namespaces(char *nslist) /* Defined in cloned_binary.c. */ extern int ensure_cloned_binary(void); +void write_log(loglevel_t level, const char *format, ...) +{ + static const char *strlevel[] = {"panic", "fatal", "error", "warning", "info", "debug"}; + static char jsonbuffer[1024]; + int len; + va_list args; + if (logfd < 0 || level >= sizeof(strlevel) / sizeof(strlevel[0])) { + return; + } + + len = snprintf(jsonbuffer, sizeof(jsonbuffer), + "{\"level\":\"%s\", \"msg\": \"", strlevel[level]); + + va_start(args, format); + len += vsnprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, format, args); + va_end(args); + + len += snprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, "\"}"); + write(logfd, jsonbuffer, len); +} + void nsexec(void) { int pipenum; @@ -560,6 +608,11 @@ void nsexec(void) if (ensure_cloned_binary() < 0) bail("could not ensure we are a cloned binary"); + /* Get the log pipe */ + logfd = logpipe(); + + write_log(DEBUG, "%s started", __FUNCTION__); + /* Parse all of the netlink configuration. */ nl_parse(pipenum, &config); diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 6507f0e69..22fc1d7a7 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -47,12 +47,20 @@ type parentProcess interface { externalDescriptors() []string setExternalDescriptors(fds []string) + + getChildLogs() +} + +type pipePair struct { + r *os.File + w *os.File } type setnsProcess struct { cmd *exec.Cmd parentPipe *os.File childPipe *os.File + logPipe pipePair cgroupPaths map[string]string rootlessCgroups bool intelRdtPath string @@ -78,7 +86,9 @@ func (p *setnsProcess) signal(sig os.Signal) error { func (p *setnsProcess) start() (err error) { defer p.parentPipe.Close() err = p.cmd.Start() + // close the write-side of the pipes (controlled by child) p.childPipe.Close() + p.logPipe.w.Close() if err != nil { return newSystemErrorWithCause(err, "starting setns process") } @@ -205,10 +215,15 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } +func (p *setnsProcess) getChildLogs() { + go forwardLogs(p.logPipe.r) +} + type initProcess struct { cmd *exec.Cmd parentPipe *os.File childPipe *os.File + logPipe pipePair config *initConfig manager cgroups.Manager intelRdtManager intelrdt.Manager @@ -269,7 +284,9 @@ func (p *initProcess) start() error { defer p.parentPipe.Close() err := p.cmd.Start() p.process.ops = p + // close the write-side of the pipes (controlled by child) p.childPipe.Close() + p.logPipe.w.Close() if err != nil { p.process.ops = nil return newSystemErrorWithCause(err, "starting init process command") @@ -508,6 +525,10 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } +func (p *initProcess) getChildLogs() { + go forwardLogs(p.logPipe.r) +} + func getPipeFds(pid int) ([]string, error) { fds := make([]string, 3) diff --git a/libcontainer/restored_process.go b/libcontainer/restored_process.go index 408916ad9..f18875b00 100644 --- a/libcontainer/restored_process.go +++ b/libcontainer/restored_process.go @@ -76,6 +76,9 @@ func (p *restoredProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } +func (p *restoredProcess) getChildLogs() { +} + // nonChildProcess represents a process where the calling process is not // the parent process. This process is created when a factory loads a container from // a persisted state. @@ -120,3 +123,6 @@ func (p *nonChildProcess) externalDescriptors() []string { func (p *nonChildProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } + +func (p *nonChildProcess) getChildLogs() { +} diff --git a/libcontainer/standard_init_linux.go b/libcontainer/standard_init_linux.go index 4e03b8bc0..ce65b17b5 100644 --- a/libcontainer/standard_init_linux.go +++ b/libcontainer/standard_init_linux.go @@ -16,6 +16,7 @@ import ( "github.com/opencontainers/runc/libcontainer/system" "github.com/opencontainers/selinux/go-selinux/label" "github.com/pkg/errors" + "github.com/sirupsen/logrus" "golang.org/x/sys/unix" ) @@ -207,6 +208,10 @@ func (l *linuxStandardInit) Init() error { return newSystemErrorWithCause(err, "init seccomp") } } + + logPipe, _ := (logrus.StandardLogger().Out).(*(os.File)) + logPipe.Close() + if err := syscall.Exec(name, l.config.Args[0:], os.Environ()); err != nil { return newSystemErrorWithCause(err, "exec user process") } diff --git a/main.go b/main.go index 072447d17..2242cecf5 100644 --- a/main.go +++ b/main.go @@ -133,6 +133,12 @@ func main() { updateCommand, } app.Before = func(context *cli.Context) error { + + // do nothing if logrus was already initialized in init.go + if logrus.StandardLogger().Out != logrus.New().Out { + return nil + } + if context.GlobalBool("debug") { logrus.SetLevel(logrus.DebugLevel) } From feebfac358ca83fe0a1132f1b2a6da5fca69f1ce Mon Sep 17 00:00:00 2001 From: Marco Vedovati Date: Fri, 10 Aug 2018 11:23:30 +0200 Subject: [PATCH 2/7] Remove pipe close before exec. Pipe close before exec is not necessary as os.Pipe() is calling pipe2 with O_CLOEXEC option. Signed-off-by: Marco Vedovati --- libcontainer/standard_init_linux.go | 5 ----- 1 file changed, 5 deletions(-) diff --git a/libcontainer/standard_init_linux.go b/libcontainer/standard_init_linux.go index ce65b17b5..4e03b8bc0 100644 --- a/libcontainer/standard_init_linux.go +++ b/libcontainer/standard_init_linux.go @@ -16,7 +16,6 @@ import ( "github.com/opencontainers/runc/libcontainer/system" "github.com/opencontainers/selinux/go-selinux/label" "github.com/pkg/errors" - "github.com/sirupsen/logrus" "golang.org/x/sys/unix" ) @@ -208,10 +207,6 @@ func (l *linuxStandardInit) Init() error { return newSystemErrorWithCause(err, "init seccomp") } } - - logPipe, _ := (logrus.StandardLogger().Out).(*(os.File)) - logPipe.Close() - if err := syscall.Exec(name, l.config.Args[0:], os.Environ()); err != nil { return newSystemErrorWithCause(err, "exec user process") } From c486e3c40633d571df38fca56da69f3ab0ab13fe Mon Sep 17 00:00:00 2001 From: Danail Branekov Date: Thu, 4 Apr 2019 14:57:28 +0300 Subject: [PATCH 3/7] Address comments in PR 1861 Refactor configuring logging into a reusable component so that it can be nicely used in both main() and init process init() Co-authored-by: Georgi Sabev Co-authored-by: Giuseppe Capizzi Co-authored-by: Claudia Beresford Signed-off-by: Danail Branekov --- init.go | 23 ++-- libcontainer/container_linux.go | 27 ++--- libcontainer/container_linux_test.go | 3 + libcontainer/logs.go | 70 ------------ libcontainer/logs/logs.go | 150 +++++++++++++++++++++++++ libcontainer/logs/logs_linux_test.go | 158 +++++++++++++++++++++++++++ libcontainer/nsenter/nsenter_test.go | 7 +- libcontainer/nsenter/nsexec.c | 11 +- libcontainer/process_linux.go | 18 +-- libcontainer/restored_process.go | 4 +- main.go | 44 ++++---- 11 files changed, 381 insertions(+), 134 deletions(-) delete mode 100644 libcontainer/logs.go create mode 100644 libcontainer/logs/logs.go create mode 100644 libcontainer/logs/logs_linux_test.go diff --git a/init.go b/init.go index 0a10779d7..51b7ce331 100644 --- a/init.go +++ b/init.go @@ -1,14 +1,14 @@ package main import ( - "os" - "runtime" - "strconv" - + "fmt" "github.com/opencontainers/runc/libcontainer" + "github.com/opencontainers/runc/libcontainer/logs" _ "github.com/opencontainers/runc/libcontainer/nsenter" "github.com/sirupsen/logrus" "github.com/urfave/cli" + "os" + "runtime" ) func init() { @@ -16,17 +16,14 @@ func init() { runtime.GOMAXPROCS(1) runtime.LockOSThread() - // in child process, we need to retrieve the log pipe - envLogPipe := os.Getenv("_LIBCONTAINER_LOGPIPE") - logPipeFd, err := strconv.Atoi(envLogPipe) - + err := logs.ConfigureLogging(&logs.LoggingConfiguration{ + LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"), + LogFormat: "json", + IsDebug: true, + }) if err != nil { - return + panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err)) } - logPipe := os.NewFile(uintptr(logPipeFd), "logpipe") - logrus.SetOutput(logPipe) - logrus.SetFormatter(&logrus.JSONFormatter{}) - logrus.SetLevel(logrus.DebugLevel) logrus.Debug("child process in init()") } } diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index ecba1f9d6..5cd669295 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -19,7 +19,7 @@ import ( "syscall" // only for SysProcAttr and Signal "time" - "github.com/cyphar/filepath-securejoin" + securejoin "github.com/cyphar/filepath-securejoin" "github.com/opencontainers/runc/libcontainer/cgroups" "github.com/opencontainers/runc/libcontainer/configs" "github.com/opencontainers/runc/libcontainer/intelrdt" @@ -337,7 +337,7 @@ func (c *linuxContainer) start(process *Process) error { if err != nil { return newSystemErrorWithCause(err, "creating new parent process") } - parent.getChildLogs() + parent.forwardChildLogs() if err := parent.start(); err != nil { // terminate the process to ensure that it properly is reaped. if err := ignoreTerminateErrors(parent.terminate()); err != nil { @@ -443,19 +443,20 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { if err != nil { return nil, newSystemErrorWithCause(err, "creating new init pipe") } + messagePipe := readWritePair{parentPipe, childPipe} r, w, err := os.Pipe() if err != nil { return nil, fmt.Errorf("Unable to create the log pipe: %s", err) } - logPipe := pipePair{r, w} + logPipe := readWritePair{r, w} cmd, err := c.commandTemplate(p, childPipe, logPipe.w) if err != nil { return nil, newSystemErrorWithCause(err, "creating new command template") } if !p.Init { - return c.newSetnsProcess(p, cmd, parentPipe, childPipe, &logPipe) + return c.newSetnsProcess(p, cmd, messagePipe, logPipe) } // We only set up fifoFd if we're not doing a `runc exec`. The historic @@ -466,7 +467,7 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { if err := c.includeExecFifo(cmd); err != nil { return nil, newSystemErrorWithCause(err, "including execfifo in cmd.Exec setup") } - return c.newInitProcess(p, cmd, parentPipe, childPipe, &logPipe) + return c.newInitProcess(p, cmd, messagePipe, logPipe) } func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe *os.File) (*exec.Cmd, error) { @@ -507,7 +508,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe return cmd, nil } -func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File, logPipe *pipePair) (*initProcess, error) { +func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, logPipe readWritePair) (*initProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initStandard)) nsMaps := make(map[configs.NamespaceType]string) for _, ns := range c.config.Namespaces { @@ -522,9 +523,9 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c } init := &initProcess{ cmd: cmd, - childPipe: childPipe, - parentPipe: parentPipe, - logPipe: *logPipe, + childPipe: initPipe.w, + parentPipe: initPipe.r, + logPipe: logPipe, manager: c.cgroupManager, intelRdtManager: c.intelRdtManager, config: c.newInitConfig(p), @@ -537,7 +538,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c return init, nil } -func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File, logPipe *pipePair) (*setnsProcess, error) { +func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, nsPipe, logPipe readWritePair) (*setnsProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns)) state, err := c.currentState() if err != nil { @@ -554,9 +555,9 @@ func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, cgroupPaths: c.cgroupManager.GetPaths(), rootlessCgroups: c.config.RootlessCgroups, intelRdtPath: state.IntelRdtPath, - childPipe: childPipe, - parentPipe: parentPipe, - logPipe: *logPipe, + childPipe: nsPipe.w, + parentPipe: nsPipe.r, + logPipe: logPipe, config: c.newInitConfig(p), process: p, bootstrapData: data, diff --git a/libcontainer/container_linux_test.go b/libcontainer/container_linux_test.go index 29ddbfad3..9e06865d4 100644 --- a/libcontainer/container_linux_test.go +++ b/libcontainer/container_linux_test.go @@ -114,6 +114,9 @@ func (m *mockProcess) externalDescriptors() []string { func (m *mockProcess) setExternalDescriptors(newFds []string) { } +func (m *mockProcess) forwardChildLogs() { +} + func TestGetContainerPids(t *testing.T) { container := &linuxContainer{ id: "myid", diff --git a/libcontainer/logs.go b/libcontainer/logs.go deleted file mode 100644 index 0b074a987..000000000 --- a/libcontainer/logs.go +++ /dev/null @@ -1,70 +0,0 @@ -package libcontainer - -import ( - "encoding/json" - "fmt" - "io" - "os" - - "github.com/sirupsen/logrus" -) - -func forwardLogs(p *os.File) { - defer p.Close() - - type jsonLog struct { - Level string `json:"level"` - Msg string `json:"msg"` - } - - dec := json.NewDecoder(p) - for { - var jl jsonLog - - type logFuncTable map[logrus.Level]func(args ...interface{}) - logMapping := logFuncTable{ - logrus.PanicLevel: logrus.Panic, - logrus.FatalLevel: logrus.Fatal, - logrus.ErrorLevel: logrus.Error, - logrus.WarnLevel: logrus.Warn, - logrus.InfoLevel: logrus.Info, - logrus.DebugLevel: logrus.Debug, - } - - err := dec.Decode(&jl) - if err != nil { - if err == io.EOF { - logrus.Debug("child pipe closed") - return - } - logrus.Errorf("json logs decoding error: %+v", err) - return - } - - lvl, err := logrus.ParseLevel(jl.Level) - if err != nil { - fmt.Printf("parsing error\n") - } - if logMapping[lvl] != nil { - logMapping[lvl](jl.Msg) - } - } -} - -func rawLogs(p *os.File) { - defer p.Close() - - data := make([]byte, 128) - for { - _, err := p.Read(data) - - if err != nil { - if err == io.EOF { - logrus.Debug("child pipe closed") - return - } - return - } - fmt.Printf("Read data: %s\n", string(data)) - } -} diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go new file mode 100644 index 000000000..d7fd28e8d --- /dev/null +++ b/libcontainer/logs/logs.go @@ -0,0 +1,150 @@ +package logs + +import ( + "bufio" + "encoding/json" + "fmt" + "io" + "os" + "strconv" + + "github.com/sirupsen/logrus" +) + +// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`. +// Subsequent invocations of `ConfigureLogging` would be no-op +var loggingConfigured = false + +type LoggingConfiguration struct { + IsDebug bool + LogFormat string + LogFilePath string + LogPipeFd string +} + +func ForwardLogs(logPipe io.Reader) { + type jsonLog struct { + Level string `json:"level"` + Msg string `json:"msg"` + } + + lineReader := bufio.NewReader(logPipe) + for { + line, err := lineReader.ReadBytes('\n') + if len(line) > 0 { + processEntry(line) + } + if err == io.EOF { + logrus.Debugf("log pipe has been closed: %+v", err) + return + } + if err != nil { + logrus.Errorf("log pipe read error: %+v", err) + } + } +} + +func processEntry(text []byte) { + type jsonLog struct { + Level string `json:"level"` + Msg string `json:"msg"` + } + + var jl jsonLog + 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\n", jl.Level, err) + return + } + log(lvl, jl.Msg) +} + +func log(level logrus.Level, args ...interface{}) { + switch level { + case logrus.PanicLevel: + logrus.Panic(args...) + case logrus.FatalLevel: + logrus.Fatal(args...) + case logrus.ErrorLevel: + logrus.Error(args...) + case logrus.WarnLevel: + logrus.Warn(args...) + case logrus.InfoLevel: + logrus.Info(args...) + case logrus.DebugLevel: + logrus.Debug(args...) + default: + logrus.Warnf("Unsupported log level %v while trying to log '%#v'", level, args) + } +} + +func ConfigureLogging(loggingConfig *LoggingConfiguration) error { + if loggingConfigured { + logrus.Debug("logging has been already configured") + return nil + } + + configureLogLevel(loggingConfig) + if err := configureLogOutput(loggingConfig); err != nil { + return err + } + if err := configureLogFormat(loggingConfig); err != nil { + return err + } + + loggingConfigured = true + return nil +} + +func configureLogLevel(loggingConfig *LoggingConfiguration) { + if loggingConfig.IsDebug { + logrus.SetLevel(logrus.DebugLevel) + } +} + +func configureLogOutput(loggingConfig *LoggingConfiguration) error { + if loggingConfig.LogFilePath != "" { + return configureLogFileOutput(loggingConfig.LogFilePath) + } + + if loggingConfig.LogPipeFd != "" { + logPipeFdInt, err := strconv.Atoi(loggingConfig.LogPipeFd) + if err != nil { + return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", loggingConfig.LogPipeFd, err) + } + configureLogPipeOutput(logPipeFdInt) + return nil + } + + return nil +} + +func configureLogPipeOutput(logPipeFd int) { + logrus.SetOutput(os.NewFile(uintptr(logPipeFd), "logpipe")) +} + +func configureLogFileOutput(logFilePath string) error { + f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0644) + if err != nil { + return err + } + logrus.SetOutput(f) + return nil +} + +func configureLogFormat(loggingConfig *LoggingConfiguration) error { + switch loggingConfig.LogFormat { + case "text": + // retain logrus's default. + case "json": + logrus.SetFormatter(new(logrus.JSONFormatter)) + default: + return fmt.Errorf("unknown log-format %q", loggingConfig.LogFormat) + } + return nil +} diff --git a/libcontainer/logs/logs_linux_test.go b/libcontainer/logs/logs_linux_test.go new file mode 100644 index 000000000..7cbfabd81 --- /dev/null +++ b/libcontainer/logs/logs_linux_test.go @@ -0,0 +1,158 @@ +package logs + +import ( + "errors" + "io/ioutil" + "os" + "strings" + "testing" + "time" +) + +func TestLoggingToFile(t *testing.T) { + logW, logFile, _ := runLogForwarding(t) + defer os.Remove(logFile) + defer logW.Close() + + logToLogWriter(t, logW, `{"level": "info","msg":"kitten"}`) + + logFileContent := waitForLogContent(t, logFile) + if !strings.Contains(string(logFileContent), "kitten") { + t.Fatalf("%s does not contain kitten", string(logFileContent)) + } +} + +func TestLogForwardingDoesNotStopOnJsonDecodeErr(t *testing.T) { + logW, logFile, _ := runLogForwarding(t) + defer os.Remove(logFile) + defer logW.Close() + + logToLogWriter(t, logW, "invalid-json-with-kitten") + + logFileContent := waitForLogContent(t, logFile) + if !strings.Contains(string(logFileContent), "failed to decode") { + t.Fatalf("%q does not contain decoding error", string(logFileContent)) + } + + truncateLogFile(t, logFile) + + logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`) + + logFileContent = waitForLogContent(t, logFile) + if !strings.Contains(string(logFileContent), "puppy") { + t.Fatalf("%s does not contain puppy", string(logFileContent)) + } +} + +func TestLogForwardingDoesNotStopOnLogLevelParsingErr(t *testing.T) { + logW, logFile, _ := runLogForwarding(t) + defer os.Remove(logFile) + defer logW.Close() + + logToLogWriter(t, logW, `{"level": "alert","msg":"puppy"}`) + + logFileContent := waitForLogContent(t, logFile) + if !strings.Contains(string(logFileContent), "failed to parse log level") { + t.Fatalf("%q does not contain log level parsing error", string(logFileContent)) + } + + truncateLogFile(t, logFile) + + logToLogWriter(t, logW, `{"level": "info","msg":"puppy"}`) + + logFileContent = waitForLogContent(t, logFile) + if !strings.Contains(string(logFileContent), "puppy") { + t.Fatalf("%s does not contain puppy", string(logFileContent)) + } +} + +func TestLogForwardingStopsAfterClosingTheWriter(t *testing.T) { + logW, logFile, doneForwarding := runLogForwarding(t) + defer os.Remove(logFile) + + logToLogWriter(t, logW, `{"level": "info","msg":"sync"}`) + + logFileContent := waitForLogContent(t, logFile) + if !strings.Contains(string(logFileContent), "sync") { + t.Fatalf("%q does not contain sync message", string(logFileContent)) + } + + logW.Close() + select { + case <-doneForwarding: + case <-time.After(10 * time.Second): + t.Fatal("log forwarding did not stop after closing the pipe") + } +} + +func logToLogWriter(t *testing.T, logW *os.File, message string) { + _, err := logW.Write([]byte(message + "\n")) + if err != nil { + t.Fatalf("failed to write %q to log writer: %v", message, err) + } +} + +func runLogForwarding(t *testing.T) (*os.File, string, chan struct{}) { + logR, logW, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + + tempFile, err := ioutil.TempFile("", "") + if err != nil { + t.Fatal(err) + } + logFile := tempFile.Name() + + logConfig := &LoggingConfiguration{LogFormat: "json", LogFilePath: logFile} + return logW, logFile, startLogForwarding(t, logConfig, logR) +} + +func startLogForwarding(t *testing.T, logConfig *LoggingConfiguration, logR *os.File) chan struct{} { + loggingConfigured = false + if err := ConfigureLogging(logConfig); err != nil { + t.Fatal(err) + } + doneForwarding := make(chan struct{}) + go func() { + ForwardLogs(logR) + close(doneForwarding) + }() + return doneForwarding +} + +func waitForLogContent(t *testing.T, logFile string) string { + startTime := time.Now() + + for { + if time.Now().After(startTime.Add(10 * time.Second)) { + t.Fatal(errors.New("No content in log file after 10 seconds")) + break + } + + fileContent, err := ioutil.ReadFile(logFile) + if err != nil { + t.Fatal(err) + } + if len(fileContent) == 0 { + continue + } + return string(fileContent) + } + + return "" +} + +func truncateLogFile(t *testing.T, logFile string) { + file, err := os.OpenFile(logFile, os.O_RDWR, 0666) + if err != nil { + t.Fatalf("failed to open log file: %v", err) + return + } + defer file.Close() + + err = file.Truncate(0) + if err != nil { + t.Fatalf("failed to truncate log file: %v", err) + } +} diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go index 9be6a8038..c4c5af8f2 100644 --- a/libcontainer/nsenter/nsenter_test.go +++ b/libcontainer/nsenter/nsenter_test.go @@ -167,10 +167,15 @@ func TestNsenterIncorrectPathType(t *testing.T) { func TestNsenterChildLogging(t *testing.T) { args := []string{"nsenter-exec"} parent, child, err := newPipe() + if err != nil { + t.Fatalf("failed to create exec pipe %v", err) + } logread, logwrite, err := os.Pipe() if err != nil { - t.Fatalf("failed to create pipe %v", err) + t.Fatalf("failed to create log pipe %v", err) } + defer logread.Close() + defer logwrite.Close() namespaces := []string{ // join pid ns of the current process diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c index af50cd87a..fef903165 100644 --- a/libcontainer/nsenter/nsexec.c +++ b/libcontainer/nsenter/nsexec.c @@ -568,7 +568,7 @@ void write_log(loglevel_t level, const char *format, ...) { static const char *strlevel[] = {"panic", "fatal", "error", "warning", "info", "debug"}; static char jsonbuffer[1024]; - int len; + int len, written; va_list args; if (logfd < 0 || level >= sizeof(strlevel) / sizeof(strlevel[0])) { return; @@ -576,12 +576,17 @@ void write_log(loglevel_t level, const char *format, ...) len = snprintf(jsonbuffer, sizeof(jsonbuffer), "{\"level\":\"%s\", \"msg\": \"", strlevel[level]); + if (len < 0) return; va_start(args, format); - len += vsnprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, format, args); + written = vsnprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, format, args); + if (written < 0) return; + len += written; va_end(args); - len += snprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, "\"}"); + written = snprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, "\"}\n"); + if (written < 0) return; + len += written; write(logfd, jsonbuffer, len); } diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 22fc1d7a7..c23f14687 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -13,6 +13,8 @@ import ( "strconv" "syscall" // only for Signal + "github.com/opencontainers/runc/libcontainer/logs" + "github.com/opencontainers/runc/libcontainer/cgroups" "github.com/opencontainers/runc/libcontainer/configs" "github.com/opencontainers/runc/libcontainer/intelrdt" @@ -48,10 +50,10 @@ type parentProcess interface { setExternalDescriptors(fds []string) - getChildLogs() + forwardChildLogs() } -type pipePair struct { +type readWritePair struct { r *os.File w *os.File } @@ -60,7 +62,7 @@ type setnsProcess struct { cmd *exec.Cmd parentPipe *os.File childPipe *os.File - logPipe pipePair + logPipe readWritePair cgroupPaths map[string]string rootlessCgroups bool intelRdtPath string @@ -215,15 +217,15 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *setnsProcess) getChildLogs() { - go forwardLogs(p.logPipe.r) +func (p *setnsProcess) forwardChildLogs() { + go logs.ForwardLogs(p.logPipe.r) } type initProcess struct { cmd *exec.Cmd parentPipe *os.File childPipe *os.File - logPipe pipePair + logPipe readWritePair config *initConfig manager cgroups.Manager intelRdtManager intelrdt.Manager @@ -525,8 +527,8 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *initProcess) getChildLogs() { - go forwardLogs(p.logPipe.r) +func (p *initProcess) forwardChildLogs() { + go logs.ForwardLogs(p.logPipe.r) } func getPipeFds(pid int) ([]string, error) { diff --git a/libcontainer/restored_process.go b/libcontainer/restored_process.go index f18875b00..28d52ad06 100644 --- a/libcontainer/restored_process.go +++ b/libcontainer/restored_process.go @@ -76,7 +76,7 @@ func (p *restoredProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *restoredProcess) getChildLogs() { +func (p *restoredProcess) forwardChildLogs() { } // nonChildProcess represents a process where the calling process is not @@ -124,5 +124,5 @@ func (p *nonChildProcess) setExternalDescriptors(newFds []string) { p.fds = newFds } -func (p *nonChildProcess) getChildLogs() { +func (p *nonChildProcess) forwardChildLogs() { } diff --git a/main.go b/main.go index 2242cecf5..d3cbc882b 100644 --- a/main.go +++ b/main.go @@ -2,6 +2,7 @@ package main import ( "fmt" + "github.com/opencontainers/runc/libcontainer/logs" "io" "os" "strings" @@ -133,32 +134,13 @@ func main() { updateCommand, } app.Before = func(context *cli.Context) error { - - // do nothing if logrus was already initialized in init.go - if logrus.StandardLogger().Out != logrus.New().Out { - return nil + loggingConfig, err := createLoggingConfiguration(context) + if err != nil { + return fmt.Errorf("failed to create logging configuration: %v", err) } - - if context.GlobalBool("debug") { - logrus.SetLevel(logrus.DebugLevel) - } - if path := context.GlobalString("log"); path != "" { - f, err := os.OpenFile(path, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0666) - if err != nil { - return err - } - logrus.SetOutput(f) - } - switch context.GlobalString("log-format") { - case "text": - // retain logrus's default. - case "json": - logrus.SetFormatter(new(logrus.JSONFormatter)) - default: - return fmt.Errorf("unknown log-format %q", context.GlobalString("log-format")) - } - return nil + return logs.ConfigureLogging(loggingConfig) } + // If the command returns an error, cli takes upon itself to print // the error on cli.ErrWriter and exit. // Use our own writer here to ensure the log gets sent to the right location. @@ -176,3 +158,17 @@ func (f *FatalWriter) Write(p []byte) (n int, err error) { logrus.Error(string(p)) return f.cliErrWriter.Write(p) } + +func createLoggingConfiguration(context *cli.Context) (*logs.LoggingConfiguration, error) { + config := logs.LoggingConfiguration{ + IsDebug: context.GlobalBool("debug"), + LogFilePath: context.GlobalString("log"), + LogFormat: context.GlobalString("log-format"), + } + + if envLogPipe, ok := os.LookupEnv("_LIBCONTAINER_LOGPIPE"); ok { + config.LogPipeFd = envLogPipe + } + + return &config, nil +} From ba3cabf932943cc927059a6782ae51b7dd862b4e Mon Sep 17 00:00:00 2001 From: Georgi Sabev Date: Fri, 19 Apr 2019 17:36:52 +0300 Subject: [PATCH 4/7] Improve nsexec logging * Simplify logging function * Logs contain __FUNCTION__:__LINE__ * Bail uses write_log Co-authored-by: Julia Nedialkova Co-authored-by: Danail Branekov Signed-off-by: Georgi Sabev --- exec.go | 7 ++ init.go | 15 +++-- libcontainer/container_linux.go | 3 +- libcontainer/logs/logs.go | 87 +++++++++---------------- libcontainer/logs/logs_linux_test.go | 6 +- libcontainer/nsenter/nsexec.c | 97 ++++++++++++++-------------- libcontainer/process.go | 2 + libcontainer/process_linux.go | 3 +- main.go | 22 +++---- tests/integration/debug.bats | 6 ++ utils_linux.go | 13 +++- 11 files changed, 129 insertions(+), 132 deletions(-) diff --git a/exec.go b/exec.go index 7fc04402a..b963d68e0 100644 --- a/exec.go +++ b/exec.go @@ -136,6 +136,12 @@ func execProcess(context *cli.Context) (int, error) { if err != nil { return -1, err } + + logLevel := "info" + if context.GlobalBool("debug") { + logLevel = "debug" + } + r := &runner{ enableSubreaper: false, shouldDestroy: false, @@ -146,6 +152,7 @@ func execProcess(context *cli.Context) (int, error) { action: CT_ACT_RUN, init: false, preserveFDs: context.Int("preserve-fds"), + logLevel: logLevel, } return r.run(p) } diff --git a/init.go b/init.go index 51b7ce331..08351fdb4 100644 --- a/init.go +++ b/init.go @@ -2,13 +2,14 @@ package main import ( "fmt" + "os" + "runtime" + "github.com/opencontainers/runc/libcontainer" "github.com/opencontainers/runc/libcontainer/logs" _ "github.com/opencontainers/runc/libcontainer/nsenter" "github.com/sirupsen/logrus" "github.com/urfave/cli" - "os" - "runtime" ) func init() { @@ -16,10 +17,16 @@ func init() { runtime.GOMAXPROCS(1) runtime.LockOSThread() - err := logs.ConfigureLogging(&logs.LoggingConfiguration{ + level := os.Getenv("_LIBCONTAINER_LOGLEVEL") + logLevel, err := logrus.ParseLevel(level) + if err != nil { + panic(fmt.Sprintf("libcontainer: failed to parse log level: %q: %v", level, err)) + } + + err = logs.ConfigureLogging(logs.Config{ LogPipeFd: os.Getenv("_LIBCONTAINER_LOGPIPE"), LogFormat: "json", - IsDebug: true, + LogLevel: logLevel, }) if err != nil { panic(fmt.Sprintf("libcontainer: failed to configure logging: %v", err)) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index 5cd669295..e5f6ad88c 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -19,7 +19,7 @@ import ( "syscall" // only for SysProcAttr and Signal "time" - securejoin "github.com/cyphar/filepath-securejoin" + "github.com/cyphar/filepath-securejoin" "github.com/opencontainers/runc/libcontainer/cgroups" "github.com/opencontainers/runc/libcontainer/configs" "github.com/opencontainers/runc/libcontainer/intelrdt" @@ -497,6 +497,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe cmd.ExtraFiles = append(cmd.ExtraFiles, logPipe) cmd.Env = append(cmd.Env, fmt.Sprintf("_LIBCONTAINER_LOGPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), + fmt.Sprintf("_LIBCONTAINER_LOGLEVEL=%s", p.LogLevel), ) // NOTE: when running a container with no PID namespace and the parent process spawning the container is diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index d7fd28e8d..35d8bdac9 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -7,27 +7,26 @@ import ( "io" "os" "strconv" + "sync" "github.com/sirupsen/logrus" ) -// loggingConfigured will be set once logging has been configured via invoking `ConfigureLogging`. -// Subsequent invocations of `ConfigureLogging` would be no-op -var loggingConfigured = false +var ( + mutex = &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 LoggingConfiguration struct { - IsDebug bool +type Config struct { + LogLevel logrus.Level LogFormat string LogFilePath string LogPipeFd string } func ForwardLogs(logPipe io.Reader) { - type jsonLog struct { - Level string `json:"level"` - Msg string `json:"msg"` - } - lineReader := bufio.NewReader(logPipe) for { line, err := lineReader.ReadBytes('\n') @@ -83,68 +82,40 @@ func log(level logrus.Level, args ...interface{}) { } } -func ConfigureLogging(loggingConfig *LoggingConfiguration) error { +func ConfigureLogging(config Config) error { + mutex.Lock() + defer mutex.Unlock() + if loggingConfigured { - logrus.Debug("logging has been already configured") + logrus.Debug("logging has already been configured") return nil } - configureLogLevel(loggingConfig) - if err := configureLogOutput(loggingConfig); err != nil { - return err - } - if err := configureLogFormat(loggingConfig); err != nil { - return err - } + logrus.SetLevel(config.LogLevel) - loggingConfigured = true - return nil -} - -func configureLogLevel(loggingConfig *LoggingConfiguration) { - if loggingConfig.IsDebug { - logrus.SetLevel(logrus.DebugLevel) - } -} - -func configureLogOutput(loggingConfig *LoggingConfiguration) error { - if loggingConfig.LogFilePath != "" { - return configureLogFileOutput(loggingConfig.LogFilePath) - } - - if loggingConfig.LogPipeFd != "" { - logPipeFdInt, err := strconv.Atoi(loggingConfig.LogPipeFd) + if config.LogPipeFd != "" { + logPipeFdInt, err := strconv.Atoi(config.LogPipeFd) if err != nil { - return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", loggingConfig.LogPipeFd, err) + return fmt.Errorf("failed to convert _LIBCONTAINER_LOGPIPE environment variable value %q to int: %v", config.LogPipeFd, err) } - configureLogPipeOutput(logPipeFdInt) - return nil + logrus.SetOutput(os.NewFile(uintptr(logPipeFdInt), "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) } - return nil -} - -func configureLogPipeOutput(logPipeFd int) { - logrus.SetOutput(os.NewFile(uintptr(logPipeFd), "logpipe")) -} - -func configureLogFileOutput(logFilePath string) error { - f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND|os.O_SYNC, 0644) - if err != nil { - return err - } - logrus.SetOutput(f) - return nil -} - -func configureLogFormat(loggingConfig *LoggingConfiguration) error { - switch loggingConfig.LogFormat { + switch config.LogFormat { case "text": // retain logrus's default. case "json": logrus.SetFormatter(new(logrus.JSONFormatter)) default: - return fmt.Errorf("unknown log-format %q", loggingConfig.LogFormat) + 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 7cbfabd81..83166fa8e 100644 --- a/libcontainer/logs/logs_linux_test.go +++ b/libcontainer/logs/logs_linux_test.go @@ -7,6 +7,8 @@ import ( "strings" "testing" "time" + + "github.com/sirupsen/logrus" ) func TestLoggingToFile(t *testing.T) { @@ -104,11 +106,11 @@ func runLogForwarding(t *testing.T) (*os.File, string, chan struct{}) { } logFile := tempFile.Name() - logConfig := &LoggingConfiguration{LogFormat: "json", LogFilePath: logFile} + logConfig := Config{LogLevel: logrus.InfoLevel, LogFormat: "json", LogFilePath: logFile} return logW, logFile, startLogForwarding(t, logConfig, logR) } -func startLogForwarding(t *testing.T, logConfig *LoggingConfiguration, logR *os.File) chan struct{} { +func startLogForwarding(t *testing.T, logConfig Config, logR *os.File) chan struct{} { loggingConfigured = false if err := ConfigureLogging(logConfig); err != nil { t.Fatal(err) diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c index fef903165..494e3411f 100644 --- a/libcontainer/nsenter/nsexec.c +++ b/libcontainer/nsenter/nsexec.c @@ -95,14 +95,12 @@ struct nlconfig_t { size_t gidmappath_len; }; -typedef enum { - PANIC = 0, - FATAL, - ERROR, - WARNING, - INFO, - DEBUG, -} loglevel_t; +#define PANIC "panic" +#define FATAL "fatal" +#define ERROR "error" +#define WARNING "warning" +#define INFO "info" +#define DEBUG "debug" int logfd; @@ -142,6 +140,26 @@ int setns(int fd, int nstype) } #endif +void write_log_with_info(const char *level, const char *function, int line, const char *format, ...) +{ + static char message[1024]; + va_list args; + + if (logfd < 0 || level == NULL) + return; + + va_start(args, format); + if (vsnprintf(message, 1024, format, args) < 0) + return; + va_end(args); + + if (dprintf(logfd, "{\"level\":\"%s\", \"msg\": \"%s:%d %s\"}\n", level, function, line, message) < 0) + return; +} + +#define write_log(level, fmt, ...) \ + write_log_with_info(level, __FUNCTION__, __LINE__, fmt, ##__VA_ARGS__) + /* XXX: This is ugly. */ static int syncfd = -1; @@ -149,13 +167,13 @@ static int syncfd = -1; #define bail(fmt, ...) \ do { \ int ret = __COUNTER__ + 1; \ - fprintf(stderr, "nsenter: " fmt ": %m\n", ##__VA_ARGS__); \ + write_log(DEBUG, "nsenter: " fmt ": %m", ##__VA_ARGS__); \ if (syncfd >= 0) { \ enum sync_t s = SYNC_ERR; \ if (write(syncfd, &s, sizeof(s)) != sizeof(s)) \ - fprintf(stderr, "nsenter: failed: write(s)"); \ + write_log(DEBUG, "nsenter: failed: write(s)"); \ if (write(syncfd, &ret, sizeof(ret)) != sizeof(ret)) \ - fprintf(stderr, "nsenter: failed: write(ret)"); \ + write_log(DEBUG, "nsenter: failed: write(ret)"); \ } \ exit(ret); \ } while(0) @@ -363,20 +381,22 @@ static int initpipe(void) return pipenum; } -static int logpipe(void) +static void setup_logpipe(void) { - int pipenum; char *logpipe, *endptr; logpipe = getenv("_LIBCONTAINER_LOGPIPE"); - if (logpipe == NULL || *logpipe == '\0') - return -1; + if (logpipe == NULL || *logpipe == '\0') { + logfd = -1; + return; + } - pipenum = strtol(logpipe, &endptr, 10); - if (*endptr != '\0') - bail("unable to parse _LIBCONTAINER_LOGPIPE"); - - return pipenum; + logfd = strtol(logpipe, &endptr, 10); + if (logpipe == endptr || *endptr != '\0') { + fprintf(stderr, "unable to parse _LIBCONTAINER_LOGPIPE, value: %s\n", logpipe); + /* It is too early to use bail */ + exit(1); + } } /* Returns the clone(2) flag for a namespace, given the name of a namespace. */ @@ -564,32 +584,6 @@ void join_namespaces(char *nslist) /* Defined in cloned_binary.c. */ extern int ensure_cloned_binary(void); -void write_log(loglevel_t level, const char *format, ...) -{ - static const char *strlevel[] = {"panic", "fatal", "error", "warning", "info", "debug"}; - static char jsonbuffer[1024]; - int len, written; - va_list args; - if (logfd < 0 || level >= sizeof(strlevel) / sizeof(strlevel[0])) { - return; - } - - len = snprintf(jsonbuffer, sizeof(jsonbuffer), - "{\"level\":\"%s\", \"msg\": \"", strlevel[level]); - if (len < 0) return; - - va_start(args, format); - written = vsnprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, format, args); - if (written < 0) return; - len += written; - va_end(args); - - written = snprintf(&jsonbuffer[len], sizeof(jsonbuffer) - len, "\"}\n"); - if (written < 0) return; - len += written; - write(logfd, jsonbuffer, len); -} - void nsexec(void) { int pipenum; @@ -597,6 +591,12 @@ void nsexec(void) int sync_child_pipe[2], sync_grandchild_pipe[2]; struct nlconfig_t config = { 0 }; + /* + * Setup a pipe to send logs to the parent. This should happen + * first, because bail will use that pipe. + */ + setup_logpipe(); + /* * If we don't have an init pipe, just return to the go routine. * We'll only get an init pipe for start or exec. @@ -613,10 +613,7 @@ void nsexec(void) if (ensure_cloned_binary() < 0) bail("could not ensure we are a cloned binary"); - /* Get the log pipe */ - logfd = logpipe(); - - write_log(DEBUG, "%s started", __FUNCTION__); + write_log(DEBUG, "nsexec started"); /* Parse all of the netlink configuration. */ nl_parse(pipenum, &config); diff --git a/libcontainer/process.go b/libcontainer/process.go index 9a7c60141..d3e472a4f 100644 --- a/libcontainer/process.go +++ b/libcontainer/process.go @@ -76,6 +76,8 @@ type Process struct { Init bool ops processOperations + + LogLevel string } // Wait waits for the process to exit. diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index c23f14687..8f9202606 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -13,11 +13,10 @@ import ( "strconv" "syscall" // only for Signal - "github.com/opencontainers/runc/libcontainer/logs" - "github.com/opencontainers/runc/libcontainer/cgroups" "github.com/opencontainers/runc/libcontainer/configs" "github.com/opencontainers/runc/libcontainer/intelrdt" + "github.com/opencontainers/runc/libcontainer/logs" "github.com/opencontainers/runc/libcontainer/system" "github.com/opencontainers/runc/libcontainer/utils" diff --git a/main.go b/main.go index d3cbc882b..273aeb84c 100644 --- a/main.go +++ b/main.go @@ -2,11 +2,12 @@ package main import ( "fmt" - "github.com/opencontainers/runc/libcontainer/logs" "io" "os" "strings" + "github.com/opencontainers/runc/libcontainer/logs" + "github.com/opencontainers/runtime-spec/specs-go" "github.com/sirupsen/logrus" @@ -134,11 +135,7 @@ func main() { updateCommand, } app.Before = func(context *cli.Context) error { - loggingConfig, err := createLoggingConfiguration(context) - if err != nil { - return fmt.Errorf("failed to create logging configuration: %v", err) - } - return logs.ConfigureLogging(loggingConfig) + return logs.ConfigureLogging(createLogConfig(context)) } // If the command returns an error, cli takes upon itself to print @@ -159,16 +156,15 @@ func (f *FatalWriter) Write(p []byte) (n int, err error) { return f.cliErrWriter.Write(p) } -func createLoggingConfiguration(context *cli.Context) (*logs.LoggingConfiguration, error) { - config := logs.LoggingConfiguration{ - IsDebug: context.GlobalBool("debug"), +func createLogConfig(context *cli.Context) logs.Config { + config := logs.Config{ + LogLevel: logrus.InfoLevel, LogFilePath: context.GlobalString("log"), LogFormat: context.GlobalString("log-format"), } - - if envLogPipe, ok := os.LookupEnv("_LIBCONTAINER_LOGPIPE"); ok { - config.LogPipeFd = envLogPipe + if context.GlobalBool("debug") { + config.LogLevel = logrus.DebugLevel } - return &config, nil + return config } diff --git a/tests/integration/debug.bats b/tests/integration/debug.bats index 971bc7e1f..187297990 100644 --- a/tests/integration/debug.bats +++ b/tests/integration/debug.bats @@ -33,6 +33,8 @@ function teardown() { run cat log.out [ "$status" -eq 0 ] [[ "${output}" == *"level=debug"* ]] + [[ "${output}" == *"nsexec started"* ]] + [[ "${output}" == *"child process in init()"* ]] } @test "global --debug to --log --log-format 'text'" { @@ -50,6 +52,8 @@ function teardown() { run cat log.out [ "$status" -eq 0 ] [[ "${output}" == *"level=debug"* ]] + [[ "${output}" == *"nsexec started"* ]] + [[ "${output}" == *"child process in init()"* ]] } @test "global --debug to --log --log-format 'json'" { @@ -67,4 +71,6 @@ function teardown() { run cat log.out [ "$status" -eq 0 ] [[ "${output}" == *'"level":"debug"'* ]] + [[ "${output}" == *"nsexec started"* ]] + [[ "${output}" == *"child process in init()"* ]] } diff --git a/utils_linux.go b/utils_linux.go index b05e7b609..9b51c9fb3 100644 --- a/utils_linux.go +++ b/utils_linux.go @@ -105,7 +105,7 @@ func getDefaultImagePath(context *cli.Context) string { // newProcess returns a new libcontainer Process with the arguments from the // spec and stdio from the current process. -func newProcess(p specs.Process, init bool) (*libcontainer.Process, error) { +func newProcess(p specs.Process, init bool, logLevel string) (*libcontainer.Process, error) { lp := &libcontainer.Process{ Args: p.Args, Env: p.Env, @@ -116,6 +116,7 @@ func newProcess(p specs.Process, init bool) (*libcontainer.Process, error) { NoNewPrivileges: &p.NoNewPrivileges, AppArmorProfile: p.ApparmorProfile, Init: init, + LogLevel: logLevel, } if p.ConsoleSize != nil { @@ -264,6 +265,7 @@ type runner struct { action CtAct notifySocket *notifySocket criuOpts *libcontainer.CriuOpts + logLevel string } func (r *runner) run(config *specs.Process) (int, error) { @@ -271,7 +273,7 @@ func (r *runner) run(config *specs.Process) (int, error) { r.destroy() return -1, err } - process, err := newProcess(*config, r.init) + process, err := newProcess(*config, r.init, r.logLevel) if err != nil { r.destroy() return -1, err @@ -430,6 +432,12 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp if os.Getenv("LISTEN_FDS") != "" { listenFDs = activation.Files(false) } + + logLevel := "info" + if context.GlobalBool("debug") { + logLevel = "debug" + } + r := &runner{ enableSubreaper: !context.Bool("no-subreaper"), shouldDestroy: true, @@ -443,6 +451,7 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp action: action, criuOpts: criuOpts, init: true, + logLevel: logLevel, } return r.run(spec.Process) } From 475aef10f7a85c9a64dd86111a0540a4c37fe53d Mon Sep 17 00:00:00 2001 From: Georgi Sabev Date: Mon, 22 Apr 2019 15:57:35 +0300 Subject: [PATCH 5/7] Remove redundant log function Bump logrus so that we can use logrus.StandardLogger().Logf instead Co-authored-by: Julia Nedialkova Signed-off-by: Georgi Sabev --- libcontainer/logs/logs.go | 21 +- vendor.conf | 2 +- vendor/github.com/sirupsen/logrus/README.md | 97 +++--- vendor/github.com/sirupsen/logrus/alt_exit.go | 18 +- vendor/github.com/sirupsen/logrus/entry.go | 306 +++++++++++++----- vendor/github.com/sirupsen/logrus/exported.go | 66 +++- .../github.com/sirupsen/logrus/formatter.go | 51 ++- .../sirupsen/logrus/json_formatter.go | 81 ++++- vendor/github.com/sirupsen/logrus/logger.go | 248 ++++++++------ vendor/github.com/sirupsen/logrus/logrus.go | 75 ++++- .../sirupsen/logrus/terminal_appengine.go | 10 - .../sirupsen/logrus/terminal_bsd.go | 10 - .../logrus/terminal_check_appengine.go | 11 + .../sirupsen/logrus/terminal_check_bsd.go | 13 + .../sirupsen/logrus/terminal_check_js.go | 11 + .../logrus/terminal_check_notappengine.go | 17 + .../sirupsen/logrus/terminal_check_unix.go | 13 + .../sirupsen/logrus/terminal_check_windows.go | 20 ++ .../sirupsen/logrus/terminal_linux.go | 14 - .../sirupsen/logrus/terminal_notwindows.go | 26 +- .../sirupsen/logrus/terminal_solaris.go | 21 -- .../sirupsen/logrus/terminal_windows.go | 76 +---- .../sirupsen/logrus/text_formatter.go | 224 +++++++++---- vendor/github.com/sirupsen/logrus/writer.go | 2 + 24 files changed, 898 insertions(+), 535 deletions(-) delete mode 100644 vendor/github.com/sirupsen/logrus/terminal_appengine.go delete mode 100644 vendor/github.com/sirupsen/logrus/terminal_bsd.go create mode 100644 vendor/github.com/sirupsen/logrus/terminal_check_appengine.go create mode 100644 vendor/github.com/sirupsen/logrus/terminal_check_bsd.go create mode 100644 vendor/github.com/sirupsen/logrus/terminal_check_js.go create mode 100644 vendor/github.com/sirupsen/logrus/terminal_check_notappengine.go create mode 100644 vendor/github.com/sirupsen/logrus/terminal_check_unix.go create mode 100644 vendor/github.com/sirupsen/logrus/terminal_check_windows.go delete mode 100644 vendor/github.com/sirupsen/logrus/terminal_linux.go delete mode 100644 vendor/github.com/sirupsen/logrus/terminal_solaris.go diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index 35d8bdac9..50c5c3ac8 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -60,26 +60,7 @@ func processEntry(text []byte) { logrus.Errorf("failed to parse log level %q: %v\n", jl.Level, err) return } - log(lvl, jl.Msg) -} - -func log(level logrus.Level, args ...interface{}) { - switch level { - case logrus.PanicLevel: - logrus.Panic(args...) - case logrus.FatalLevel: - logrus.Fatal(args...) - case logrus.ErrorLevel: - logrus.Error(args...) - case logrus.WarnLevel: - logrus.Warn(args...) - case logrus.InfoLevel: - logrus.Info(args...) - case logrus.DebugLevel: - logrus.Debug(args...) - default: - logrus.Warnf("Unsupported log level %v while trying to log '%#v'", level, args) - } + logrus.StandardLogger().Logf(lvl, jl.Msg) } func ConfigureLogging(config Config) error { diff --git a/vendor.conf b/vendor.conf index fb97650d8..13cf0a93f 100644 --- a/vendor.conf +++ b/vendor.conf @@ -7,7 +7,7 @@ github.com/checkpoint-restore/go-criu v3.11 github.com/mrunalp/fileutils ed869b029674c0e9ce4c0dfa781405c2d9946d08 github.com/opencontainers/selinux v1.2.1 github.com/seccomp/libseccomp-golang 84e90a91acea0f4e51e62bc1a75de18b1fc0790f -github.com/sirupsen/logrus a3f95b5c423586578a4e099b11a46c2479628cac +github.com/sirupsen/logrus 8bdbc7bcc01dcbb8ec23dc8a28e332258d25251f github.com/syndtr/gocapability db04d3cc01c8b54962a58ec7e491717d06cfcc16 github.com/vishvananda/netlink 1e2e08e8a2dcdacaae3f14ac44c5cfa31361f270 # systemd integration. diff --git a/vendor/github.com/sirupsen/logrus/README.md b/vendor/github.com/sirupsen/logrus/README.md index 82aeb4eef..a4796eb07 100644 --- a/vendor/github.com/sirupsen/logrus/README.md +++ b/vendor/github.com/sirupsen/logrus/README.md @@ -1,7 +1,7 @@ # Logrus :walrus: [![Build Status](https://travis-ci.org/sirupsen/logrus.svg?branch=master)](https://travis-ci.org/sirupsen/logrus) [![GoDoc](https://godoc.org/github.com/sirupsen/logrus?status.svg)](https://godoc.org/github.com/sirupsen/logrus) Logrus is a structured logger for Go (golang), completely API compatible with -the standard library logger. [Godoc][godoc]. +the standard library logger. **Seeing weird case-sensitive problems?** It's in the past been possible to import Logrus as both upper- and lower-case. Due to the Go package environment, @@ -56,8 +56,39 @@ time="2015-03-26T01:27:38-04:00" level=warning msg="The group's number increased time="2015-03-26T01:27:38-04:00" level=debug msg="Temperature changes" temperature=-4 time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca size=9009 time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x2082280c0 map[animal:orca size:9009] 2015-03-26 01:27:38.441574009 -0400 EDT panic It's over 9000!} number=100 omg=true -exit status 1 ``` +To ensure this behaviour even if a TTY is attached, set your formatter as follows: + +```go + log.SetFormatter(&log.TextFormatter{ + DisableColors: true, + FullTimestamp: true, + }) +``` + +#### Logging Method Name + +If you wish to add the calling method as a field, instruct the logger via: +```go +log.SetReportCaller(true) +``` +This adds the caller as 'method' like so: + +```json +{"animal":"penguin","level":"fatal","method":"github.com/sirupsen/arcticcreatures.migrate","msg":"a penguin swims by", +"time":"2014-03-10 19:57:38.562543129 -0400 EDT"} +``` + +```text +time="2015-03-26T01:27:38-04:00" level=fatal method=github.com/sirupsen/arcticcreatures.migrate msg="a penguin swims by" animal=penguin +``` +Note that this does add measurable overhead - the cost will depend on the version of Go, but is +between 20 and 40% in recent tests with 1.6 and 1.7. You can validate this in your +environment via benchmarks: +``` +go test -bench=.*CallerTracing +``` + #### Case-sensitivity @@ -220,7 +251,7 @@ Logrus comes with [built-in hooks](hooks/). Add those, or your custom hook, in ```go import ( log "github.com/sirupsen/logrus" - "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "aibrake" + "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "airbrake" logrus_syslog "github.com/sirupsen/logrus/hooks/syslog" "log/syslog" ) @@ -241,60 +272,15 @@ func init() { ``` Note: Syslog hook also support connecting to local syslog (Ex. "/dev/log" or "/var/run/syslog" or "/var/run/log"). For the detail, please check the [syslog hook README](hooks/syslog/README.md). -| Hook | Description | -| ----- | ----------- | -| [Airbrake "legacy"](https://github.com/gemnasium/logrus-airbrake-legacy-hook) | Send errors to an exception tracking service compatible with the Airbrake API V2. Uses [`airbrake-go`](https://github.com/tobi/airbrake-go) behind the scenes. | -| [Airbrake](https://github.com/gemnasium/logrus-airbrake-hook) | Send errors to the Airbrake API V3. Uses the official [`gobrake`](https://github.com/airbrake/gobrake) behind the scenes. | -| [Amazon Kinesis](https://github.com/evalphobia/logrus_kinesis) | Hook for logging to [Amazon Kinesis](https://aws.amazon.com/kinesis/) | -| [Amqp-Hook](https://github.com/vladoatanasov/logrus_amqp) | Hook for logging to Amqp broker (Like RabbitMQ) | -| [Bugsnag](https://github.com/Shopify/logrus-bugsnag/blob/master/bugsnag.go) | Send errors to the Bugsnag exception tracking service. | -| [DeferPanic](https://github.com/deferpanic/dp-logrus) | Hook for logging to DeferPanic | -| [Discordrus](https://github.com/kz/discordrus) | Hook for logging to [Discord](https://discordapp.com/) | -| [ElasticSearch](https://github.com/sohlich/elogrus) | Hook for logging to ElasticSearch| -| [Firehose](https://github.com/beaubrewer/logrus_firehose) | Hook for logging to [Amazon Firehose](https://aws.amazon.com/kinesis/firehose/) -| [Fluentd](https://github.com/evalphobia/logrus_fluent) | Hook for logging to fluentd | -| [Go-Slack](https://github.com/multiplay/go-slack) | Hook for logging to [Slack](https://slack.com) | -| [Graylog](https://github.com/gemnasium/logrus-graylog-hook) | Hook for logging to [Graylog](http://graylog2.org/) | -| [Hiprus](https://github.com/nubo/hiprus) | Send errors to a channel in hipchat. | -| [Honeybadger](https://github.com/agonzalezro/logrus_honeybadger) | Hook for sending exceptions to Honeybadger | -| [InfluxDB](https://github.com/Abramovic/logrus_influxdb) | Hook for logging to influxdb | -| [Influxus](http://github.com/vlad-doru/influxus) | Hook for concurrently logging to [InfluxDB](http://influxdata.com/) | -| [Journalhook](https://github.com/wercker/journalhook) | Hook for logging to `systemd-journald` | -| [KafkaLogrus](https://github.com/goibibo/KafkaLogrus) | Hook for logging to kafka | -| [LFShook](https://github.com/rifflock/lfshook) | Hook for logging to the local filesystem | -| [Logentries](https://github.com/jcftang/logentriesrus) | Hook for logging to [Logentries](https://logentries.com/) | -| [Logentrus](https://github.com/puddingfactory/logentrus) | Hook for logging to [Logentries](https://logentries.com/) | -| [Logmatic.io](https://github.com/logmatic/logmatic-go) | Hook for logging to [Logmatic.io](http://logmatic.io/) | -| [Logrusly](https://github.com/sebest/logrusly) | Send logs to [Loggly](https://www.loggly.com/) | -| [Logstash](https://github.com/bshuster-repo/logrus-logstash-hook) | Hook for logging to [Logstash](https://www.elastic.co/products/logstash) | -| [Mail](https://github.com/zbindenren/logrus_mail) | Hook for sending exceptions via mail | -| [Mattermost](https://github.com/shuLhan/mattermost-integration/tree/master/hooks/logrus) | Hook for logging to [Mattermost](https://mattermost.com/) | -| [Mongodb](https://github.com/weekface/mgorus) | Hook for logging to mongodb | -| [NATS-Hook](https://github.com/rybit/nats_logrus_hook) | Hook for logging to [NATS](https://nats.io) | -| [Octokit](https://github.com/dorajistyle/logrus-octokit-hook) | Hook for logging to github via octokit | -| [Papertrail](https://github.com/polds/logrus-papertrail-hook) | Send errors to the [Papertrail](https://papertrailapp.com) hosted logging service via UDP. | -| [PostgreSQL](https://github.com/gemnasium/logrus-postgresql-hook) | Send logs to [PostgreSQL](http://postgresql.org) | -| [Pushover](https://github.com/toorop/logrus_pushover) | Send error via [Pushover](https://pushover.net) | -| [Raygun](https://github.com/squirkle/logrus-raygun-hook) | Hook for logging to [Raygun.io](http://raygun.io/) | -| [Redis-Hook](https://github.com/rogierlommers/logrus-redis-hook) | Hook for logging to a ELK stack (through Redis) | -| [Rollrus](https://github.com/heroku/rollrus) | Hook for sending errors to rollbar | -| [Scribe](https://github.com/sagar8192/logrus-scribe-hook) | Hook for logging to [Scribe](https://github.com/facebookarchive/scribe)| -| [Sentry](https://github.com/evalphobia/logrus_sentry) | Send errors to the Sentry error logging and aggregation service. | -| [Slackrus](https://github.com/johntdyer/slackrus) | Hook for Slack chat. | -| [Stackdriver](https://github.com/knq/sdhook) | Hook for logging to [Google Stackdriver](https://cloud.google.com/logging/) | -| [Sumorus](https://github.com/doublefree/sumorus) | Hook for logging to [SumoLogic](https://www.sumologic.com/)| -| [Syslog](https://github.com/sirupsen/logrus/blob/master/hooks/syslog/syslog.go) | Send errors to remote syslog server. Uses standard library `log/syslog` behind the scenes. | -| [Syslog TLS](https://github.com/shinji62/logrus-syslog-ng) | Send errors to remote syslog server with TLS support. | -| [TraceView](https://github.com/evalphobia/logrus_appneta) | Hook for logging to [AppNeta TraceView](https://www.appneta.com/products/traceview/) | -| [Typetalk](https://github.com/dragon3/logrus-typetalk-hook) | Hook for logging to [Typetalk](https://www.typetalk.in/) | -| [logz.io](https://github.com/ripcurld00d/logrus-logzio-hook) | Hook for logging to [logz.io](https://logz.io), a Log as a Service using Logstash | -| [SQS-Hook](https://github.com/tsarpaul/logrus_sqs) | Hook for logging to [Amazon Simple Queue Service (SQS)](https://aws.amazon.com/sqs/) | +A list of currently known of service hook can be found in this wiki [page](https://github.com/sirupsen/logrus/wiki/Hooks) + #### Level logging -Logrus has six logging levels: Debug, Info, Warning, Error, Fatal and Panic. +Logrus has seven logging levels: Trace, Debug, Info, Warning, Error, Fatal and Panic. ```go +log.Trace("Something very low level.") log.Debug("Useful debugging information.") log.Info("Something noteworthy happened!") log.Warn("You should probably take a look at this.") @@ -366,15 +352,20 @@ The built-in logging formatters are: field to `true`. To force no colored output even if there is a TTY set the `DisableColors` field to `true`. For Windows, see [github.com/mattn/go-colorable](https://github.com/mattn/go-colorable). + * When colors are enabled, levels are truncated to 4 characters by default. To disable + truncation set the `DisableLevelTruncation` field to `true`. * All options are listed in the [generated docs](https://godoc.org/github.com/sirupsen/logrus#TextFormatter). * `logrus.JSONFormatter`. Logs fields as JSON. * All options are listed in the [generated docs](https://godoc.org/github.com/sirupsen/logrus#JSONFormatter). Third party logging formatters: +* [`FluentdFormatter`](https://github.com/joonix/log). Formats entries that can be parsed by Kubernetes and Google Container Engine. +* [`GELF`](https://github.com/fabienm/go-logrus-formatters). Formats entries so they comply to Graylog's [GELF 1.1 specification](http://docs.graylog.org/en/2.4/pages/gelf.html). * [`logstash`](https://github.com/bshuster-repo/logrus-logstash-hook). Logs fields as [Logstash](http://logstash.net) Events. * [`prefixed`](https://github.com/x-cray/logrus-prefixed-formatter). Displays log entry source along with alternative layout. * [`zalgo`](https://github.com/aybabtme/logzalgo). Invoking the P͉̫o̳̼̊w̖͈̰͎e̬͔̭͂r͚̼̹̲ ̫͓͉̳͈ō̠͕͖̚f̝͍̠ ͕̲̞͖͑Z̖̫̤̫ͪa͉̬͈̗l͖͎g̳̥o̰̥̅!̣͔̲̻͊̄ ̙̘̦̹̦. +* [`nested-logrus-formatter`](https://github.com/antonfisher/nested-logrus-formatter). Converts logrus fields to a nested structure. You can define your formatter by implementing the `Formatter` interface, requiring a `Format` method. `Format` takes an `*Entry`. `entry.Data` is a @@ -488,7 +479,7 @@ logrus.RegisterExitHandler(handler) #### Thread safety -By default Logger is protected by mutex for concurrent writes, this mutex is invoked when calling hooks and writing logs. +By default, Logger is protected by a mutex for concurrent writes. The mutex is held when calling hooks and writing logs. If you are sure such locking is not needed, you can call logger.SetNoLock() to disable the locking. Situation when locking is not needed includes: diff --git a/vendor/github.com/sirupsen/logrus/alt_exit.go b/vendor/github.com/sirupsen/logrus/alt_exit.go index 8af90637a..8fd189e1c 100644 --- a/vendor/github.com/sirupsen/logrus/alt_exit.go +++ b/vendor/github.com/sirupsen/logrus/alt_exit.go @@ -51,9 +51,9 @@ func Exit(code int) { os.Exit(code) } -// RegisterExitHandler adds a Logrus Exit handler, call logrus.Exit to invoke -// all handlers. The handlers will also be invoked when any Fatal log entry is -// made. +// RegisterExitHandler appends a Logrus Exit handler to the list of handlers, +// call logrus.Exit to invoke all handlers. The handlers will also be invoked when +// any Fatal log entry is made. // // This method is useful when a caller wishes to use logrus to log a fatal // message but also needs to gracefully shutdown. An example usecase could be @@ -62,3 +62,15 @@ func Exit(code int) { func RegisterExitHandler(handler func()) { handlers = append(handlers, handler) } + +// DeferExitHandler prepends a Logrus Exit handler to the list of handlers, +// call logrus.Exit to invoke all handlers. The handlers will also be invoked when +// any Fatal log entry is made. +// +// This method is useful when a caller wishes to use logrus to log a fatal +// message but also needs to gracefully shutdown. An example usecase could be +// closing database connections, or sending a alert that the application is +// closing. +func DeferExitHandler(handler func()) { + handlers = append([]func(){handler}, handlers...) +} diff --git a/vendor/github.com/sirupsen/logrus/entry.go b/vendor/github.com/sirupsen/logrus/entry.go index 320e5d5b8..63e25583c 100644 --- a/vendor/github.com/sirupsen/logrus/entry.go +++ b/vendor/github.com/sirupsen/logrus/entry.go @@ -2,13 +2,33 @@ package logrus import ( "bytes" + "context" "fmt" "os" + "reflect" + "runtime" + "strings" "sync" "time" ) -var bufferPool *sync.Pool +var ( + bufferPool *sync.Pool + + // qualified package name, cached at first use + logrusPackage string + + // Positions in the call stack when tracing to report the calling method + minimumCallerDepth int + + // Used for caller information initialisation + callerInitOnce sync.Once +) + +const ( + maximumCallerDepth int = 25 + knownLogrusFrames int = 4 +) func init() { bufferPool = &sync.Pool{ @@ -16,15 +36,18 @@ func init() { return new(bytes.Buffer) }, } + + // start at the bottom of the stack before the package-name cache is primed + minimumCallerDepth = 1 } // Defines the key when adding errors using WithError. var ErrorKey = "error" // An entry is the final or intermediate Logrus logging entry. It contains all -// the fields passed with WithField{,s}. It's finally logged when Debug, Info, -// Warn, Error, Fatal or Panic is called on it. These objects can be reused and -// passed around as much as you wish to avoid field duplication. +// the fields passed with WithField{,s}. It's finally logged when Trace, Debug, +// Info, Warn, Error, Fatal or Panic is called on it. These objects can be +// reused and passed around as much as you wish to avoid field duplication. type Entry struct { Logger *Logger @@ -34,21 +57,31 @@ type Entry struct { // Time at which the log entry was created Time time.Time - // Level the log entry was logged at: Debug, Info, Warn, Error, Fatal or Panic + // Level the log entry was logged at: Trace, Debug, Info, Warn, Error, Fatal or Panic + // This field will be set on entry firing and the value will be equal to the one in Logger struct field. Level Level - // Message passed to Debug, Info, Warn, Error, Fatal or Panic + // Calling method, with package name + Caller *runtime.Frame + + // Message passed to Trace, Debug, Info, Warn, Error, Fatal or Panic Message string - // When formatter is called in entry.log(), an Buffer may be set to entry + // When formatter is called in entry.log(), a Buffer may be set to entry Buffer *bytes.Buffer + + // Contains the context set by the user. Useful for hook processing etc. + Context context.Context + + // err may contain a field formatting error + err string } func NewEntry(logger *Logger) *Entry { return &Entry{ Logger: logger, - // Default is three fields, give a little extra room - Data: make(Fields, 5), + // Default is three fields, plus one optional. Give a little extra room. + Data: make(Fields, 6), } } @@ -68,6 +101,11 @@ func (entry *Entry) WithError(err error) *Entry { return entry.WithField(ErrorKey, err) } +// Add a context to the Entry. +func (entry *Entry) WithContext(ctx context.Context) *Entry { + return &Entry{Logger: entry.Logger, Data: entry.Data, Time: entry.Time, err: entry.err, Context: ctx} +} + // Add a single field to the Entry. func (entry *Entry) WithField(key string, value interface{}) *Entry { return entry.WithFields(Fields{key: value}) @@ -79,43 +117,120 @@ func (entry *Entry) WithFields(fields Fields) *Entry { for k, v := range entry.Data { data[k] = v } + fieldErr := entry.err for k, v := range fields { - data[k] = v + isErrField := false + if t := reflect.TypeOf(v); t != nil { + switch t.Kind() { + case reflect.Func: + isErrField = true + case reflect.Ptr: + isErrField = t.Elem().Kind() == reflect.Func + } + } + if isErrField { + tmp := fmt.Sprintf("can not add field %q", k) + if fieldErr != "" { + fieldErr = entry.err + ", " + tmp + } else { + fieldErr = tmp + } + } else { + data[k] = v + } } - return &Entry{Logger: entry.Logger, Data: data} + return &Entry{Logger: entry.Logger, Data: data, Time: entry.Time, err: fieldErr, Context: entry.Context} +} + +// Overrides the time of the Entry. +func (entry *Entry) WithTime(t time.Time) *Entry { + return &Entry{Logger: entry.Logger, Data: entry.Data, Time: t, err: entry.err, Context: entry.Context} +} + +// getPackageName reduces a fully qualified function name to the package name +// There really ought to be to be a better way... +func getPackageName(f string) string { + for { + lastPeriod := strings.LastIndex(f, ".") + lastSlash := strings.LastIndex(f, "/") + if lastPeriod > lastSlash { + f = f[:lastPeriod] + } else { + break + } + } + + return f +} + +// getCaller retrieves the name of the first non-logrus calling function +func getCaller() *runtime.Frame { + + // cache this package's fully-qualified name + callerInitOnce.Do(func() { + pcs := make([]uintptr, 2) + _ = runtime.Callers(0, pcs) + logrusPackage = getPackageName(runtime.FuncForPC(pcs[1]).Name()) + + // now that we have the cache, we can skip a minimum count of known-logrus functions + // XXX this is dubious, the number of frames may vary + minimumCallerDepth = knownLogrusFrames + }) + + // Restrict the lookback frames to avoid runaway lookups + pcs := make([]uintptr, maximumCallerDepth) + depth := runtime.Callers(minimumCallerDepth, pcs) + frames := runtime.CallersFrames(pcs[:depth]) + + for f, again := frames.Next(); again; f, again = frames.Next() { + pkg := getPackageName(f.Function) + + // If the caller isn't part of this package, we're done + if pkg != logrusPackage { + return &f + } + } + + // if we got here, we failed to find the caller's context + return nil +} + +func (entry Entry) HasCaller() (has bool) { + return entry.Logger != nil && + entry.Logger.ReportCaller && + entry.Caller != nil } // This function is not declared with a pointer value because otherwise // race conditions will occur when using multiple goroutines func (entry Entry) log(level Level, msg string) { var buffer *bytes.Buffer - entry.Time = time.Now() + + // Default to now, but allow users to override if they want. + // + // We don't have to worry about polluting future calls to Entry#log() + // with this assignment because this function is declared with a + // non-pointer receiver. + if entry.Time.IsZero() { + entry.Time = time.Now() + } + entry.Level = level entry.Message = msg - - if err := entry.Logger.Hooks.Fire(level, &entry); err != nil { - entry.Logger.mu.Lock() - fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) - entry.Logger.mu.Unlock() + if entry.Logger.ReportCaller { + entry.Caller = getCaller() } + + entry.fireHooks() + buffer = bufferPool.Get().(*bytes.Buffer) buffer.Reset() defer bufferPool.Put(buffer) entry.Buffer = buffer - serialized, err := entry.Logger.Formatter.Format(&entry) + + entry.write() + entry.Buffer = nil - if err != nil { - entry.Logger.mu.Lock() - fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) - entry.Logger.mu.Unlock() - } else { - entry.Logger.mu.Lock() - _, err = entry.Logger.Out.Write(serialized) - if err != nil { - fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) - } - entry.Logger.mu.Unlock() - } // To avoid Entry#log() returning a value that only would make sense for // panic() to use in Entry#Panic(), we avoid the allocation by checking @@ -125,26 +240,53 @@ func (entry Entry) log(level Level, msg string) { } } -func (entry *Entry) Debug(args ...interface{}) { - if entry.Logger.level() >= DebugLevel { - entry.log(DebugLevel, fmt.Sprint(args...)) +func (entry *Entry) fireHooks() { + entry.Logger.mu.Lock() + defer entry.Logger.mu.Unlock() + err := entry.Logger.Hooks.Fire(entry.Level, entry) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) } } +func (entry *Entry) write() { + entry.Logger.mu.Lock() + defer entry.Logger.mu.Unlock() + serialized, err := entry.Logger.Formatter.Format(entry) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) + } else { + _, err = entry.Logger.Out.Write(serialized) + if err != nil { + fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) + } + } +} + +func (entry *Entry) Log(level Level, args ...interface{}) { + if entry.Logger.IsLevelEnabled(level) { + entry.log(level, fmt.Sprint(args...)) + } +} + +func (entry *Entry) Trace(args ...interface{}) { + entry.Log(TraceLevel, args...) +} + +func (entry *Entry) Debug(args ...interface{}) { + entry.Log(DebugLevel, args...) +} + func (entry *Entry) Print(args ...interface{}) { entry.Info(args...) } func (entry *Entry) Info(args ...interface{}) { - if entry.Logger.level() >= InfoLevel { - entry.log(InfoLevel, fmt.Sprint(args...)) - } + entry.Log(InfoLevel, args...) } func (entry *Entry) Warn(args ...interface{}) { - if entry.Logger.level() >= WarnLevel { - entry.log(WarnLevel, fmt.Sprint(args...)) - } + entry.Log(WarnLevel, args...) } func (entry *Entry) Warning(args ...interface{}) { @@ -152,37 +294,37 @@ func (entry *Entry) Warning(args ...interface{}) { } func (entry *Entry) Error(args ...interface{}) { - if entry.Logger.level() >= ErrorLevel { - entry.log(ErrorLevel, fmt.Sprint(args...)) - } + entry.Log(ErrorLevel, args...) } func (entry *Entry) Fatal(args ...interface{}) { - if entry.Logger.level() >= FatalLevel { - entry.log(FatalLevel, fmt.Sprint(args...)) - } - Exit(1) + entry.Log(FatalLevel, args...) + entry.Logger.Exit(1) } func (entry *Entry) Panic(args ...interface{}) { - if entry.Logger.level() >= PanicLevel { - entry.log(PanicLevel, fmt.Sprint(args...)) - } + entry.Log(PanicLevel, args...) panic(fmt.Sprint(args...)) } // Entry Printf family functions -func (entry *Entry) Debugf(format string, args ...interface{}) { - if entry.Logger.level() >= DebugLevel { - entry.Debug(fmt.Sprintf(format, args...)) +func (entry *Entry) Logf(level Level, format string, args ...interface{}) { + if entry.Logger.IsLevelEnabled(level) { + entry.Log(level, fmt.Sprintf(format, args...)) } } +func (entry *Entry) Tracef(format string, args ...interface{}) { + entry.Logf(TraceLevel, format, args...) +} + +func (entry *Entry) Debugf(format string, args ...interface{}) { + entry.Logf(DebugLevel, format, args...) +} + func (entry *Entry) Infof(format string, args ...interface{}) { - if entry.Logger.level() >= InfoLevel { - entry.Info(fmt.Sprintf(format, args...)) - } + entry.Logf(InfoLevel, format, args...) } func (entry *Entry) Printf(format string, args ...interface{}) { @@ -190,9 +332,7 @@ func (entry *Entry) Printf(format string, args ...interface{}) { } func (entry *Entry) Warnf(format string, args ...interface{}) { - if entry.Logger.level() >= WarnLevel { - entry.Warn(fmt.Sprintf(format, args...)) - } + entry.Logf(WarnLevel, format, args...) } func (entry *Entry) Warningf(format string, args ...interface{}) { @@ -200,36 +340,36 @@ func (entry *Entry) Warningf(format string, args ...interface{}) { } func (entry *Entry) Errorf(format string, args ...interface{}) { - if entry.Logger.level() >= ErrorLevel { - entry.Error(fmt.Sprintf(format, args...)) - } + entry.Logf(ErrorLevel, format, args...) } func (entry *Entry) Fatalf(format string, args ...interface{}) { - if entry.Logger.level() >= FatalLevel { - entry.Fatal(fmt.Sprintf(format, args...)) - } - Exit(1) + entry.Logf(FatalLevel, format, args...) + entry.Logger.Exit(1) } func (entry *Entry) Panicf(format string, args ...interface{}) { - if entry.Logger.level() >= PanicLevel { - entry.Panic(fmt.Sprintf(format, args...)) - } + entry.Logf(PanicLevel, format, args...) } // Entry Println family functions -func (entry *Entry) Debugln(args ...interface{}) { - if entry.Logger.level() >= DebugLevel { - entry.Debug(entry.sprintlnn(args...)) +func (entry *Entry) Logln(level Level, args ...interface{}) { + if entry.Logger.IsLevelEnabled(level) { + entry.Log(level, entry.sprintlnn(args...)) } } +func (entry *Entry) Traceln(args ...interface{}) { + entry.Logln(TraceLevel, args...) +} + +func (entry *Entry) Debugln(args ...interface{}) { + entry.Logln(DebugLevel, args...) +} + func (entry *Entry) Infoln(args ...interface{}) { - if entry.Logger.level() >= InfoLevel { - entry.Info(entry.sprintlnn(args...)) - } + entry.Logln(InfoLevel, args...) } func (entry *Entry) Println(args ...interface{}) { @@ -237,9 +377,7 @@ func (entry *Entry) Println(args ...interface{}) { } func (entry *Entry) Warnln(args ...interface{}) { - if entry.Logger.level() >= WarnLevel { - entry.Warn(entry.sprintlnn(args...)) - } + entry.Logln(WarnLevel, args...) } func (entry *Entry) Warningln(args ...interface{}) { @@ -247,22 +385,16 @@ func (entry *Entry) Warningln(args ...interface{}) { } func (entry *Entry) Errorln(args ...interface{}) { - if entry.Logger.level() >= ErrorLevel { - entry.Error(entry.sprintlnn(args...)) - } + entry.Logln(ErrorLevel, args...) } func (entry *Entry) Fatalln(args ...interface{}) { - if entry.Logger.level() >= FatalLevel { - entry.Fatal(entry.sprintlnn(args...)) - } - Exit(1) + entry.Logln(FatalLevel, args...) + entry.Logger.Exit(1) } func (entry *Entry) Panicln(args ...interface{}) { - if entry.Logger.level() >= PanicLevel { - entry.Panic(entry.sprintlnn(args...)) - } + entry.Logln(PanicLevel, args...) } // Sprintlnn => Sprint no newline. This is to get the behavior of how diff --git a/vendor/github.com/sirupsen/logrus/exported.go b/vendor/github.com/sirupsen/logrus/exported.go index 013183eda..62fc2f219 100644 --- a/vendor/github.com/sirupsen/logrus/exported.go +++ b/vendor/github.com/sirupsen/logrus/exported.go @@ -1,7 +1,9 @@ package logrus import ( + "context" "io" + "time" ) var ( @@ -15,37 +17,38 @@ func StandardLogger() *Logger { // SetOutput sets the standard logger output. func SetOutput(out io.Writer) { - std.mu.Lock() - defer std.mu.Unlock() - std.Out = out + std.SetOutput(out) } // SetFormatter sets the standard logger formatter. func SetFormatter(formatter Formatter) { - std.mu.Lock() - defer std.mu.Unlock() - std.Formatter = formatter + std.SetFormatter(formatter) +} + +// SetReportCaller sets whether the standard logger will include the calling +// method as a field. +func SetReportCaller(include bool) { + std.SetReportCaller(include) } // SetLevel sets the standard logger level. func SetLevel(level Level) { - std.mu.Lock() - defer std.mu.Unlock() std.SetLevel(level) } // GetLevel returns the standard logger level. func GetLevel() Level { - std.mu.Lock() - defer std.mu.Unlock() - return std.level() + return std.GetLevel() +} + +// IsLevelEnabled checks if the log level of the standard logger is greater than the level param +func IsLevelEnabled(level Level) bool { + return std.IsLevelEnabled(level) } // AddHook adds a hook to the standard logger hooks. func AddHook(hook Hook) { - std.mu.Lock() - defer std.mu.Unlock() - std.Hooks.Add(hook) + std.AddHook(hook) } // WithError creates an entry from the standard logger and adds an error to it, using the value defined in ErrorKey as key. @@ -53,6 +56,11 @@ func WithError(err error) *Entry { return std.WithField(ErrorKey, err) } +// WithContext creates an entry from the standard logger and adds a context to it. +func WithContext(ctx context.Context) *Entry { + return std.WithContext(ctx) +} + // WithField creates an entry from the standard logger and adds a field to // it. If you want multiple fields, use `WithFields`. // @@ -72,6 +80,20 @@ func WithFields(fields Fields) *Entry { return std.WithFields(fields) } +// WithTime creats an entry from the standard logger and overrides the time of +// logs generated with it. +// +// Note that it doesn't log until you call Debug, Print, Info, Warn, Fatal +// or Panic on the Entry it returns. +func WithTime(t time.Time) *Entry { + return std.WithTime(t) +} + +// Trace logs a message at level Trace on the standard logger. +func Trace(args ...interface{}) { + std.Trace(args...) +} + // Debug logs a message at level Debug on the standard logger. func Debug(args ...interface{}) { std.Debug(args...) @@ -107,11 +129,16 @@ func Panic(args ...interface{}) { std.Panic(args...) } -// Fatal logs a message at level Fatal on the standard logger. +// Fatal logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatal(args ...interface{}) { std.Fatal(args...) } +// Tracef logs a message at level Trace on the standard logger. +func Tracef(format string, args ...interface{}) { + std.Tracef(format, args...) +} + // Debugf logs a message at level Debug on the standard logger. func Debugf(format string, args ...interface{}) { std.Debugf(format, args...) @@ -147,11 +174,16 @@ func Panicf(format string, args ...interface{}) { std.Panicf(format, args...) } -// Fatalf logs a message at level Fatal on the standard logger. +// Fatalf logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatalf(format string, args ...interface{}) { std.Fatalf(format, args...) } +// Traceln logs a message at level Trace on the standard logger. +func Traceln(args ...interface{}) { + std.Traceln(args...) +} + // Debugln logs a message at level Debug on the standard logger. func Debugln(args ...interface{}) { std.Debugln(args...) @@ -187,7 +219,7 @@ func Panicln(args ...interface{}) { std.Panicln(args...) } -// Fatalln logs a message at level Fatal on the standard logger. +// Fatalln logs a message at level Fatal on the standard logger then the process will exit with status set to 1. func Fatalln(args ...interface{}) { std.Fatalln(args...) } diff --git a/vendor/github.com/sirupsen/logrus/formatter.go b/vendor/github.com/sirupsen/logrus/formatter.go index b5fbe934d..408883773 100644 --- a/vendor/github.com/sirupsen/logrus/formatter.go +++ b/vendor/github.com/sirupsen/logrus/formatter.go @@ -2,7 +2,16 @@ package logrus import "time" -const DefaultTimestampFormat = time.RFC3339 +// Default key names for the default fields +const ( + defaultTimestampFormat = time.RFC3339 + FieldKeyMsg = "msg" + FieldKeyLevel = "level" + FieldKeyTime = "time" + FieldKeyLogrusError = "logrus_error" + FieldKeyFunc = "func" + FieldKeyFile = "file" +) // The Formatter interface is used to implement a custom Formatter. It takes an // `Entry`. It exposes all the fields, including the default ones: @@ -18,7 +27,7 @@ type Formatter interface { Format(*Entry) ([]byte, error) } -// This is to not silently overwrite `time`, `msg` and `level` fields when +// This is to not silently overwrite `time`, `msg`, `func` and `level` fields when // dumping it. If this code wasn't there doing: // // logrus.WithField("level", 1).Info("hello") @@ -30,16 +39,40 @@ type Formatter interface { // // It's not exported because it's still using Data in an opinionated way. It's to // avoid code duplication between the two default formatters. -func prefixFieldClashes(data Fields) { - if t, ok := data["time"]; ok { - data["fields.time"] = t +func prefixFieldClashes(data Fields, fieldMap FieldMap, reportCaller bool) { + timeKey := fieldMap.resolve(FieldKeyTime) + if t, ok := data[timeKey]; ok { + data["fields."+timeKey] = t + delete(data, timeKey) } - if m, ok := data["msg"]; ok { - data["fields.msg"] = m + msgKey := fieldMap.resolve(FieldKeyMsg) + if m, ok := data[msgKey]; ok { + data["fields."+msgKey] = m + delete(data, msgKey) } - if l, ok := data["level"]; ok { - data["fields.level"] = l + levelKey := fieldMap.resolve(FieldKeyLevel) + if l, ok := data[levelKey]; ok { + data["fields."+levelKey] = l + delete(data, levelKey) + } + + logrusErrKey := fieldMap.resolve(FieldKeyLogrusError) + if l, ok := data[logrusErrKey]; ok { + data["fields."+logrusErrKey] = l + delete(data, logrusErrKey) + } + + // If reportCaller is not set, 'func' will not conflict. + if reportCaller { + funcKey := fieldMap.resolve(FieldKeyFunc) + if l, ok := data[funcKey]; ok { + data["fields."+funcKey] = l + } + fileKey := fieldMap.resolve(FieldKeyFile) + if l, ok := data[fileKey]; ok { + data["fields."+fileKey] = l + } } } diff --git a/vendor/github.com/sirupsen/logrus/json_formatter.go b/vendor/github.com/sirupsen/logrus/json_formatter.go index e787ea175..098a21a06 100644 --- a/vendor/github.com/sirupsen/logrus/json_formatter.go +++ b/vendor/github.com/sirupsen/logrus/json_formatter.go @@ -1,18 +1,16 @@ package logrus import ( + "bytes" "encoding/json" "fmt" + "runtime" ) type fieldKey string -type FieldMap map[fieldKey]string -const ( - FieldKeyMsg = "msg" - FieldKeyLevel = "level" - FieldKeyTime = "time" -) +// FieldMap allows customization of the key names for default fields. +type FieldMap map[fieldKey]string func (f FieldMap) resolve(key fieldKey) string { if k, ok := f[key]; ok { @@ -22,6 +20,7 @@ func (f FieldMap) resolve(key fieldKey) string { return string(key) } +// JSONFormatter formats logs into parsable json type JSONFormatter struct { // TimestampFormat sets the format used for marshaling timestamps. TimestampFormat string @@ -29,20 +28,34 @@ type JSONFormatter struct { // DisableTimestamp allows disabling automatic timestamps in output DisableTimestamp bool - // FieldMap allows users to customize the names of keys for various fields. + // DataKey allows users to put all the log entry parameters into a nested dictionary at a given key. + DataKey string + + // FieldMap allows users to customize the names of keys for default fields. // As an example: // formatter := &JSONFormatter{ // FieldMap: FieldMap{ - // FieldKeyTime: "@timestamp", + // FieldKeyTime: "@timestamp", // FieldKeyLevel: "@level", - // FieldKeyMsg: "@message", + // FieldKeyMsg: "@message", + // FieldKeyFunc: "@caller", // }, // } FieldMap FieldMap + + // CallerPrettyfier can be set by the user to modify the content + // of the function and file keys in the json data when ReportCaller is + // activated. If any of the returned value is the empty string the + // corresponding key will be removed from json fields. + CallerPrettyfier func(*runtime.Frame) (function string, file string) + + // PrettyPrint will indent all json logs + PrettyPrint bool } +// Format renders a single log entry func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { - data := make(Fields, len(entry.Data)+3) + data := make(Fields, len(entry.Data)+4) for k, v := range entry.Data { switch v := v.(type) { case error: @@ -53,22 +66,56 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) { data[k] = v } } - prefixFieldClashes(data) + + if f.DataKey != "" { + newData := make(Fields, 4) + newData[f.DataKey] = data + data = newData + } + + prefixFieldClashes(data, f.FieldMap, entry.HasCaller()) timestampFormat := f.TimestampFormat if timestampFormat == "" { - timestampFormat = DefaultTimestampFormat + timestampFormat = defaultTimestampFormat } + if entry.err != "" { + data[f.FieldMap.resolve(FieldKeyLogrusError)] = entry.err + } if !f.DisableTimestamp { data[f.FieldMap.resolve(FieldKeyTime)] = entry.Time.Format(timestampFormat) } data[f.FieldMap.resolve(FieldKeyMsg)] = entry.Message data[f.FieldMap.resolve(FieldKeyLevel)] = entry.Level.String() - - serialized, err := json.Marshal(data) - if err != nil { - return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) + if entry.HasCaller() { + funcVal := entry.Caller.Function + fileVal := fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } + if funcVal != "" { + data[f.FieldMap.resolve(FieldKeyFunc)] = funcVal + } + if fileVal != "" { + data[f.FieldMap.resolve(FieldKeyFile)] = fileVal + } } - return append(serialized, '\n'), nil + + var b *bytes.Buffer + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + + encoder := json.NewEncoder(b) + if f.PrettyPrint { + encoder.SetIndent("", " ") + } + if err := encoder.Encode(data); err != nil { + return nil, fmt.Errorf("failed to marshal fields to JSON, %v", err) + } + + return b.Bytes(), nil } diff --git a/vendor/github.com/sirupsen/logrus/logger.go b/vendor/github.com/sirupsen/logrus/logger.go index b44966f97..c0c0b1e55 100644 --- a/vendor/github.com/sirupsen/logrus/logger.go +++ b/vendor/github.com/sirupsen/logrus/logger.go @@ -1,16 +1,18 @@ package logrus import ( + "context" "io" "os" "sync" "sync/atomic" + "time" ) type Logger struct { // The logs are `io.Copy`'d to this in a mutex. It's common to set this to a // file, or leave it default which is `os.Stderr`. You can also set this to - // something more adventorous, such as logging to Kafka. + // something more adventurous, such as logging to Kafka. Out io.Writer // Hooks for the logger instance. These allow firing events based on logging // levels and log entries. For example, to send errors to an error tracking @@ -23,16 +25,24 @@ type Logger struct { // own that implements the `Formatter` interface, see the `README` or included // formatters for examples. Formatter Formatter + + // Flag for whether to log caller info (off by default) + ReportCaller bool + // The logging level the logger should log at. This is typically (and defaults // to) `logrus.Info`, which allows Info(), Warn(), Error() and Fatal() to be - // logged. `logrus.Debug` is useful in + // logged. Level Level // Used to sync writing to the log. Locking is enabled by Default mu MutexWrap // Reusable empty entry entryPool sync.Pool + // Function to exit the application, defaults to `os.Exit()` + ExitFunc exitFunc } +type exitFunc func(int) + type MutexWrap struct { lock sync.Mutex disabled bool @@ -68,10 +78,12 @@ func (mw *MutexWrap) Disable() { // It's recommended to make this a global instance called `log`. func New() *Logger { return &Logger{ - Out: os.Stderr, - Formatter: new(TextFormatter), - Hooks: make(LevelHooks), - Level: InfoLevel, + Out: os.Stderr, + Formatter: new(TextFormatter), + Hooks: make(LevelHooks), + Level: InfoLevel, + ExitFunc: os.Exit, + ReportCaller: false, } } @@ -84,11 +96,12 @@ func (logger *Logger) newEntry() *Entry { } func (logger *Logger) releaseEntry(entry *Entry) { + entry.Data = map[string]interface{}{} logger.entryPool.Put(entry) } // Adds a field to the log entry, note that it doesn't log until you call -// Debug, Print, Info, Warn, Fatal or Panic. It only creates a log entry. +// Debug, Print, Info, Warn, Error, Fatal or Panic. It only creates a log entry. // If you want multiple fields, use `WithFields`. func (logger *Logger) WithField(key string, value interface{}) *Entry { entry := logger.newEntry() @@ -112,20 +125,38 @@ func (logger *Logger) WithError(err error) *Entry { return entry.WithError(err) } -func (logger *Logger) Debugf(format string, args ...interface{}) { - if logger.level() >= DebugLevel { +// Add a context to the log entry. +func (logger *Logger) WithContext(ctx context.Context) *Entry { + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithContext(ctx) +} + +// Overrides the time of the log entry. +func (logger *Logger) WithTime(t time.Time) *Entry { + entry := logger.newEntry() + defer logger.releaseEntry(entry) + return entry.WithTime(t) +} + +func (logger *Logger) Logf(level Level, format string, args ...interface{}) { + if logger.IsLevelEnabled(level) { entry := logger.newEntry() - entry.Debugf(format, args...) + entry.Logf(level, format, args...) logger.releaseEntry(entry) } } +func (logger *Logger) Tracef(format string, args ...interface{}) { + logger.Logf(TraceLevel, format, args...) +} + +func (logger *Logger) Debugf(format string, args ...interface{}) { + logger.Logf(DebugLevel, format, args...) +} + func (logger *Logger) Infof(format string, args ...interface{}) { - if logger.level() >= InfoLevel { - entry := logger.newEntry() - entry.Infof(format, args...) - logger.releaseEntry(entry) - } + logger.Logf(InfoLevel, format, args...) } func (logger *Logger) Printf(format string, args ...interface{}) { @@ -135,123 +166,91 @@ func (logger *Logger) Printf(format string, args ...interface{}) { } func (logger *Logger) Warnf(format string, args ...interface{}) { - if logger.level() >= WarnLevel { - entry := logger.newEntry() - entry.Warnf(format, args...) - logger.releaseEntry(entry) - } + logger.Logf(WarnLevel, format, args...) } func (logger *Logger) Warningf(format string, args ...interface{}) { - if logger.level() >= WarnLevel { - entry := logger.newEntry() - entry.Warnf(format, args...) - logger.releaseEntry(entry) - } + logger.Warnf(format, args...) } func (logger *Logger) Errorf(format string, args ...interface{}) { - if logger.level() >= ErrorLevel { - entry := logger.newEntry() - entry.Errorf(format, args...) - logger.releaseEntry(entry) - } + logger.Logf(ErrorLevel, format, args...) } func (logger *Logger) Fatalf(format string, args ...interface{}) { - if logger.level() >= FatalLevel { - entry := logger.newEntry() - entry.Fatalf(format, args...) - logger.releaseEntry(entry) - } - Exit(1) + logger.Logf(FatalLevel, format, args...) + logger.Exit(1) } func (logger *Logger) Panicf(format string, args ...interface{}) { - if logger.level() >= PanicLevel { + logger.Logf(PanicLevel, format, args...) +} + +func (logger *Logger) Log(level Level, args ...interface{}) { + if logger.IsLevelEnabled(level) { entry := logger.newEntry() - entry.Panicf(format, args...) + entry.Log(level, args...) logger.releaseEntry(entry) } } +func (logger *Logger) Trace(args ...interface{}) { + logger.Log(TraceLevel, args...) +} + func (logger *Logger) Debug(args ...interface{}) { - if logger.level() >= DebugLevel { - entry := logger.newEntry() - entry.Debug(args...) - logger.releaseEntry(entry) - } + logger.Log(DebugLevel, args...) } func (logger *Logger) Info(args ...interface{}) { - if logger.level() >= InfoLevel { - entry := logger.newEntry() - entry.Info(args...) - logger.releaseEntry(entry) - } + logger.Log(InfoLevel, args...) } func (logger *Logger) Print(args ...interface{}) { entry := logger.newEntry() - entry.Info(args...) + entry.Print(args...) logger.releaseEntry(entry) } func (logger *Logger) Warn(args ...interface{}) { - if logger.level() >= WarnLevel { - entry := logger.newEntry() - entry.Warn(args...) - logger.releaseEntry(entry) - } + logger.Log(WarnLevel, args...) } func (logger *Logger) Warning(args ...interface{}) { - if logger.level() >= WarnLevel { - entry := logger.newEntry() - entry.Warn(args...) - logger.releaseEntry(entry) - } + logger.Warn(args...) } func (logger *Logger) Error(args ...interface{}) { - if logger.level() >= ErrorLevel { - entry := logger.newEntry() - entry.Error(args...) - logger.releaseEntry(entry) - } + logger.Log(ErrorLevel, args...) } func (logger *Logger) Fatal(args ...interface{}) { - if logger.level() >= FatalLevel { - entry := logger.newEntry() - entry.Fatal(args...) - logger.releaseEntry(entry) - } - Exit(1) + logger.Log(FatalLevel, args...) + logger.Exit(1) } func (logger *Logger) Panic(args ...interface{}) { - if logger.level() >= PanicLevel { + logger.Log(PanicLevel, args...) +} + +func (logger *Logger) Logln(level Level, args ...interface{}) { + if logger.IsLevelEnabled(level) { entry := logger.newEntry() - entry.Panic(args...) + entry.Logln(level, args...) logger.releaseEntry(entry) } } +func (logger *Logger) Traceln(args ...interface{}) { + logger.Logln(TraceLevel, args...) +} + func (logger *Logger) Debugln(args ...interface{}) { - if logger.level() >= DebugLevel { - entry := logger.newEntry() - entry.Debugln(args...) - logger.releaseEntry(entry) - } + logger.Logln(DebugLevel, args...) } func (logger *Logger) Infoln(args ...interface{}) { - if logger.level() >= InfoLevel { - entry := logger.newEntry() - entry.Infoln(args...) - logger.releaseEntry(entry) - } + logger.Logln(InfoLevel, args...) } func (logger *Logger) Println(args ...interface{}) { @@ -261,44 +260,32 @@ func (logger *Logger) Println(args ...interface{}) { } func (logger *Logger) Warnln(args ...interface{}) { - if logger.level() >= WarnLevel { - entry := logger.newEntry() - entry.Warnln(args...) - logger.releaseEntry(entry) - } + logger.Logln(WarnLevel, args...) } func (logger *Logger) Warningln(args ...interface{}) { - if logger.level() >= WarnLevel { - entry := logger.newEntry() - entry.Warnln(args...) - logger.releaseEntry(entry) - } + logger.Warnln(args...) } func (logger *Logger) Errorln(args ...interface{}) { - if logger.level() >= ErrorLevel { - entry := logger.newEntry() - entry.Errorln(args...) - logger.releaseEntry(entry) - } + logger.Logln(ErrorLevel, args...) } func (logger *Logger) Fatalln(args ...interface{}) { - if logger.level() >= FatalLevel { - entry := logger.newEntry() - entry.Fatalln(args...) - logger.releaseEntry(entry) - } - Exit(1) + logger.Logln(FatalLevel, args...) + logger.Exit(1) } func (logger *Logger) Panicln(args ...interface{}) { - if logger.level() >= PanicLevel { - entry := logger.newEntry() - entry.Panicln(args...) - logger.releaseEntry(entry) + logger.Logln(PanicLevel, args...) +} + +func (logger *Logger) Exit(code int) { + runHandlers() + if logger.ExitFunc == nil { + logger.ExitFunc = os.Exit } + logger.ExitFunc(code) } //When file is opened with appending mode, it's safe to @@ -312,6 +299,53 @@ func (logger *Logger) level() Level { return Level(atomic.LoadUint32((*uint32)(&logger.Level))) } +// SetLevel sets the logger level. func (logger *Logger) SetLevel(level Level) { atomic.StoreUint32((*uint32)(&logger.Level), uint32(level)) } + +// GetLevel returns the logger level. +func (logger *Logger) GetLevel() Level { + return logger.level() +} + +// AddHook adds a hook to the logger hooks. +func (logger *Logger) AddHook(hook Hook) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Hooks.Add(hook) +} + +// IsLevelEnabled checks if the log level of the logger is greater than the level param +func (logger *Logger) IsLevelEnabled(level Level) bool { + return logger.level() >= level +} + +// SetFormatter sets the logger formatter. +func (logger *Logger) SetFormatter(formatter Formatter) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Formatter = formatter +} + +// SetOutput sets the logger output. +func (logger *Logger) SetOutput(output io.Writer) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.Out = output +} + +func (logger *Logger) SetReportCaller(reportCaller bool) { + logger.mu.Lock() + defer logger.mu.Unlock() + logger.ReportCaller = reportCaller +} + +// ReplaceHooks replaces the logger hooks and returns the old ones +func (logger *Logger) ReplaceHooks(hooks LevelHooks) LevelHooks { + logger.mu.Lock() + oldHooks := logger.Hooks + logger.Hooks = hooks + logger.mu.Unlock() + return oldHooks +} diff --git a/vendor/github.com/sirupsen/logrus/logrus.go b/vendor/github.com/sirupsen/logrus/logrus.go index dd3899974..8644761f7 100644 --- a/vendor/github.com/sirupsen/logrus/logrus.go +++ b/vendor/github.com/sirupsen/logrus/logrus.go @@ -14,22 +14,11 @@ type Level uint32 // Convert the Level to a string. E.g. PanicLevel becomes "panic". func (level Level) String() string { - switch level { - case DebugLevel: - return "debug" - case InfoLevel: - return "info" - case WarnLevel: - return "warning" - case ErrorLevel: - return "error" - case FatalLevel: - return "fatal" - case PanicLevel: - return "panic" + if b, err := level.MarshalText(); err == nil { + return string(b) + } else { + return "unknown" } - - return "unknown" } // ParseLevel takes a string level and returns the Logrus log level constant. @@ -47,12 +36,47 @@ func ParseLevel(lvl string) (Level, error) { return InfoLevel, nil case "debug": return DebugLevel, nil + case "trace": + return TraceLevel, nil } var l Level return l, fmt.Errorf("not a valid logrus Level: %q", lvl) } +// UnmarshalText implements encoding.TextUnmarshaler. +func (level *Level) UnmarshalText(text []byte) error { + l, err := ParseLevel(string(text)) + if err != nil { + return err + } + + *level = Level(l) + + return nil +} + +func (level Level) MarshalText() ([]byte, error) { + switch level { + case TraceLevel: + return []byte("trace"), nil + case DebugLevel: + return []byte("debug"), nil + case InfoLevel: + return []byte("info"), nil + case WarnLevel: + return []byte("warning"), nil + case ErrorLevel: + return []byte("error"), nil + case FatalLevel: + return []byte("fatal"), nil + case PanicLevel: + return []byte("panic"), nil + } + + return nil, fmt.Errorf("not a valid logrus level %d", level) +} + // A constant exposing all logging levels var AllLevels = []Level{ PanicLevel, @@ -61,6 +85,7 @@ var AllLevels = []Level{ WarnLevel, InfoLevel, DebugLevel, + TraceLevel, } // These are the different logging levels. You can set the logging level to log @@ -69,7 +94,7 @@ const ( // PanicLevel level, highest level of severity. Logs and then calls panic with the // message passed to Debug, Info, ... PanicLevel Level = iota - // FatalLevel level. Logs and then calls `os.Exit(1)`. It will exit even if the + // FatalLevel level. Logs and then calls `logger.Exit(1)`. It will exit even if the // logging level is set to Panic. FatalLevel // ErrorLevel level. Logs. Used for errors that should definitely be noted. @@ -82,6 +107,8 @@ const ( InfoLevel // DebugLevel level. Usually only enabled when debugging. Very verbose logging. DebugLevel + // TraceLevel level. Designates finer-grained informational events than the Debug. + TraceLevel ) // Won't compile if StdLogger can't be realized by a log.Logger @@ -140,4 +167,20 @@ type FieldLogger interface { Errorln(args ...interface{}) Fatalln(args ...interface{}) Panicln(args ...interface{}) + + // IsDebugEnabled() bool + // IsInfoEnabled() bool + // IsWarnEnabled() bool + // IsErrorEnabled() bool + // IsFatalEnabled() bool + // IsPanicEnabled() bool +} + +// Ext1FieldLogger (the first extension to FieldLogger) is superfluous, it is +// here for consistancy. Do not use. Use Logger or Entry instead. +type Ext1FieldLogger interface { + FieldLogger + Tracef(format string, args ...interface{}) + Trace(args ...interface{}) + Traceln(args ...interface{}) } diff --git a/vendor/github.com/sirupsen/logrus/terminal_appengine.go b/vendor/github.com/sirupsen/logrus/terminal_appengine.go deleted file mode 100644 index e011a8694..000000000 --- a/vendor/github.com/sirupsen/logrus/terminal_appengine.go +++ /dev/null @@ -1,10 +0,0 @@ -// +build appengine - -package logrus - -import "io" - -// IsTerminal returns true if stderr's file descriptor is a terminal. -func IsTerminal(f io.Writer) bool { - return true -} diff --git a/vendor/github.com/sirupsen/logrus/terminal_bsd.go b/vendor/github.com/sirupsen/logrus/terminal_bsd.go deleted file mode 100644 index 5f6be4d3c..000000000 --- a/vendor/github.com/sirupsen/logrus/terminal_bsd.go +++ /dev/null @@ -1,10 +0,0 @@ -// +build darwin freebsd openbsd netbsd dragonfly -// +build !appengine - -package logrus - -import "syscall" - -const ioctlReadTermios = syscall.TIOCGETA - -type Termios syscall.Termios diff --git a/vendor/github.com/sirupsen/logrus/terminal_check_appengine.go b/vendor/github.com/sirupsen/logrus/terminal_check_appengine.go new file mode 100644 index 000000000..2403de981 --- /dev/null +++ b/vendor/github.com/sirupsen/logrus/terminal_check_appengine.go @@ -0,0 +1,11 @@ +// +build appengine + +package logrus + +import ( + "io" +) + +func checkIfTerminal(w io.Writer) bool { + return true +} diff --git a/vendor/github.com/sirupsen/logrus/terminal_check_bsd.go b/vendor/github.com/sirupsen/logrus/terminal_check_bsd.go new file mode 100644 index 000000000..3c4f43f91 --- /dev/null +++ b/vendor/github.com/sirupsen/logrus/terminal_check_bsd.go @@ -0,0 +1,13 @@ +// +build darwin dragonfly freebsd netbsd openbsd + +package logrus + +import "golang.org/x/sys/unix" + +const ioctlReadTermios = unix.TIOCGETA + +func isTerminal(fd int) bool { + _, err := unix.IoctlGetTermios(fd, ioctlReadTermios) + return err == nil +} + diff --git a/vendor/github.com/sirupsen/logrus/terminal_check_js.go b/vendor/github.com/sirupsen/logrus/terminal_check_js.go new file mode 100644 index 000000000..0c209750a --- /dev/null +++ b/vendor/github.com/sirupsen/logrus/terminal_check_js.go @@ -0,0 +1,11 @@ +// +build js + +package logrus + +import ( + "io" +) + +func checkIfTerminal(w io.Writer) bool { + return false +} diff --git a/vendor/github.com/sirupsen/logrus/terminal_check_notappengine.go b/vendor/github.com/sirupsen/logrus/terminal_check_notappengine.go new file mode 100644 index 000000000..7be2d87c5 --- /dev/null +++ b/vendor/github.com/sirupsen/logrus/terminal_check_notappengine.go @@ -0,0 +1,17 @@ +// +build !appengine,!js,!windows + +package logrus + +import ( + "io" + "os" +) + +func checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + return isTerminal(int(v.Fd())) + default: + return false + } +} diff --git a/vendor/github.com/sirupsen/logrus/terminal_check_unix.go b/vendor/github.com/sirupsen/logrus/terminal_check_unix.go new file mode 100644 index 000000000..355dc966f --- /dev/null +++ b/vendor/github.com/sirupsen/logrus/terminal_check_unix.go @@ -0,0 +1,13 @@ +// +build linux aix + +package logrus + +import "golang.org/x/sys/unix" + +const ioctlReadTermios = unix.TCGETS + +func isTerminal(fd int) bool { + _, err := unix.IoctlGetTermios(fd, ioctlReadTermios) + return err == nil +} + diff --git a/vendor/github.com/sirupsen/logrus/terminal_check_windows.go b/vendor/github.com/sirupsen/logrus/terminal_check_windows.go new file mode 100644 index 000000000..3b9d2864c --- /dev/null +++ b/vendor/github.com/sirupsen/logrus/terminal_check_windows.go @@ -0,0 +1,20 @@ +// +build !appengine,!js,windows + +package logrus + +import ( + "io" + "os" + "syscall" +) + +func checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + var mode uint32 + err := syscall.GetConsoleMode(syscall.Handle(v.Fd()), &mode) + return err == nil + default: + return false + } +} diff --git a/vendor/github.com/sirupsen/logrus/terminal_linux.go b/vendor/github.com/sirupsen/logrus/terminal_linux.go deleted file mode 100644 index 308160ca8..000000000 --- a/vendor/github.com/sirupsen/logrus/terminal_linux.go +++ /dev/null @@ -1,14 +0,0 @@ -// Based on ssh/terminal: -// Copyright 2013 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build !appengine - -package logrus - -import "syscall" - -const ioctlReadTermios = syscall.TCGETS - -type Termios syscall.Termios diff --git a/vendor/github.com/sirupsen/logrus/terminal_notwindows.go b/vendor/github.com/sirupsen/logrus/terminal_notwindows.go index 190297abf..3dbd23720 100644 --- a/vendor/github.com/sirupsen/logrus/terminal_notwindows.go +++ b/vendor/github.com/sirupsen/logrus/terminal_notwindows.go @@ -1,28 +1,8 @@ -// Based on ssh/terminal: -// Copyright 2011 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build linux darwin freebsd openbsd netbsd dragonfly -// +build !appengine +// +build !windows package logrus -import ( - "io" - "os" - "syscall" - "unsafe" -) +import "io" -// IsTerminal returns true if stderr's file descriptor is a terminal. -func IsTerminal(f io.Writer) bool { - var termios Termios - switch v := f.(type) { - case *os.File: - _, _, err := syscall.Syscall6(syscall.SYS_IOCTL, uintptr(v.Fd()), ioctlReadTermios, uintptr(unsafe.Pointer(&termios)), 0, 0, 0) - return err == 0 - default: - return false - } +func initTerminal(w io.Writer) { } diff --git a/vendor/github.com/sirupsen/logrus/terminal_solaris.go b/vendor/github.com/sirupsen/logrus/terminal_solaris.go deleted file mode 100644 index 3c86b1abe..000000000 --- a/vendor/github.com/sirupsen/logrus/terminal_solaris.go +++ /dev/null @@ -1,21 +0,0 @@ -// +build solaris,!appengine - -package logrus - -import ( - "io" - "os" - - "golang.org/x/sys/unix" -) - -// IsTerminal returns true if the given file descriptor is a terminal. -func IsTerminal(f io.Writer) bool { - switch v := f.(type) { - case *os.File: - _, err := unix.IoctlGetTermios(int(v.Fd()), unix.TCGETA) - return err == nil - default: - return false - } -} diff --git a/vendor/github.com/sirupsen/logrus/terminal_windows.go b/vendor/github.com/sirupsen/logrus/terminal_windows.go index 7a336307e..b4ef5286c 100644 --- a/vendor/github.com/sirupsen/logrus/terminal_windows.go +++ b/vendor/github.com/sirupsen/logrus/terminal_windows.go @@ -1,82 +1,18 @@ -// Based on ssh/terminal: -// Copyright 2011 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build windows,!appengine +// +build !appengine,!js,windows package logrus import ( - "bytes" - "errors" "io" "os" - "os/exec" - "strconv" - "strings" "syscall" - "unsafe" + + sequences "github.com/konsorten/go-windows-terminal-sequences" ) -var kernel32 = syscall.NewLazyDLL("kernel32.dll") - -var ( - procGetConsoleMode = kernel32.NewProc("GetConsoleMode") - procSetConsoleMode = kernel32.NewProc("SetConsoleMode") -) - -const ( - enableProcessedOutput = 0x0001 - enableWrapAtEolOutput = 0x0002 - enableVirtualTerminalProcessing = 0x0004 -) - -func getVersion() (float64, error) { - stdout, stderr := &bytes.Buffer{}, &bytes.Buffer{} - cmd := exec.Command("cmd", "ver") - cmd.Stdout = stdout - cmd.Stderr = stderr - err := cmd.Run() - if err != nil { - return -1, err - } - - // The output should be like "Microsoft Windows [Version XX.X.XXXXXX]" - version := strings.Replace(stdout.String(), "\n", "", -1) - version = strings.Replace(version, "\r\n", "", -1) - - x1 := strings.Index(version, "[Version") - - if x1 == -1 || strings.Index(version, "]") == -1 { - return -1, errors.New("Can't determine Windows version") - } - - return strconv.ParseFloat(version[x1+9:x1+13], 64) -} - -func init() { - ver, err := getVersion() - if err != nil { - return - } - - // Activate Virtual Processing for Windows CMD - // Info: https://msdn.microsoft.com/en-us/library/windows/desktop/ms686033(v=vs.85).aspx - if ver >= 10 { - handle := syscall.Handle(os.Stderr.Fd()) - procSetConsoleMode.Call(uintptr(handle), enableProcessedOutput|enableWrapAtEolOutput|enableVirtualTerminalProcessing) - } -} - -// IsTerminal returns true if stderr's file descriptor is a terminal. -func IsTerminal(f io.Writer) bool { - switch v := f.(type) { +func initTerminal(w io.Writer) { + switch v := w.(type) { case *os.File: - var st uint32 - r, _, e := syscall.Syscall(procGetConsoleMode.Addr(), 2, uintptr(v.Fd()), uintptr(unsafe.Pointer(&st)), 0) - return r != 0 && e == 0 - default: - return false + sequences.EnableVirtualTerminalProcessing(syscall.Handle(v.Fd()), true) } } diff --git a/vendor/github.com/sirupsen/logrus/text_formatter.go b/vendor/github.com/sirupsen/logrus/text_formatter.go index 6aa48cfb6..1569161eb 100644 --- a/vendor/github.com/sirupsen/logrus/text_formatter.go +++ b/vendor/github.com/sirupsen/logrus/text_formatter.go @@ -3,6 +3,8 @@ package logrus import ( "bytes" "fmt" + "os" + "runtime" "sort" "strings" "sync" @@ -10,22 +12,19 @@ import ( ) const ( - nocolor = 0 - red = 31 - green = 32 - yellow = 33 - blue = 36 - gray = 37 + red = 31 + yellow = 33 + blue = 36 + gray = 37 ) -var ( - baseTimestamp time.Time -) +var baseTimestamp time.Time func init() { baseTimestamp = time.Now() } +// TextFormatter formats logs into text type TextFormatter struct { // Set to true to bypass checking for a TTY before outputting colors. ForceColors bool @@ -33,6 +32,9 @@ type TextFormatter struct { // Force disabling colors. DisableColors bool + // Override coloring based on CLICOLOR and CLICOLOR_FORCE. - https://bixense.com/clicolors/ + EnvironmentOverrideColors bool + // Disable timestamp logging. useful when output is redirected to logging // system that already adds timestamps. DisableTimestamp bool @@ -49,66 +51,155 @@ type TextFormatter struct { // be desired. DisableSorting bool + // The keys sorting function, when uninitialized it uses sort.Strings. + SortingFunc func([]string) + + // Disables the truncation of the level text to 4 characters. + DisableLevelTruncation bool + // QuoteEmptyFields will wrap empty fields in quotes if true QuoteEmptyFields bool - // QuoteCharacter can be set to the override the default quoting character " - // with something else. For example: ', or `. - QuoteCharacter string - // Whether the logger's out is to a terminal isTerminal bool - sync.Once + // FieldMap allows users to customize the names of keys for default fields. + // As an example: + // formatter := &TextFormatter{ + // FieldMap: FieldMap{ + // FieldKeyTime: "@timestamp", + // FieldKeyLevel: "@level", + // FieldKeyMsg: "@message"}} + FieldMap FieldMap + + // CallerPrettyfier can be set by the user to modify the content + // of the function and file keys in the data when ReportCaller is + // activated. If any of the returned value is the empty string the + // corresponding key will be removed from fields. + CallerPrettyfier func(*runtime.Frame) (function string, file string) + + terminalInitOnce sync.Once } func (f *TextFormatter) init(entry *Entry) { - if len(f.QuoteCharacter) == 0 { - f.QuoteCharacter = "\"" - } if entry.Logger != nil { - f.isTerminal = IsTerminal(entry.Logger.Out) + f.isTerminal = checkIfTerminal(entry.Logger.Out) + + if f.isTerminal { + initTerminal(entry.Logger.Out) + } } } +func (f *TextFormatter) isColored() bool { + isColored := f.ForceColors || (f.isTerminal && (runtime.GOOS != "windows")) + + if f.EnvironmentOverrideColors { + if force, ok := os.LookupEnv("CLICOLOR_FORCE"); ok && force != "0" { + isColored = true + } else if ok && force == "0" { + isColored = false + } else if os.Getenv("CLICOLOR") == "0" { + isColored = false + } + } + + return isColored && !f.DisableColors +} + +// Format renders a single log entry func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { - var b *bytes.Buffer - keys := make([]string, 0, len(entry.Data)) - for k := range entry.Data { + data := make(Fields) + for k, v := range entry.Data { + data[k] = v + } + prefixFieldClashes(data, f.FieldMap, entry.HasCaller()) + keys := make([]string, 0, len(data)) + for k := range data { keys = append(keys, k) } - if !f.DisableSorting { - sort.Strings(keys) + var funcVal, fileVal string + + fixedKeys := make([]string, 0, 4+len(data)) + if !f.DisableTimestamp { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyTime)) } + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLevel)) + if entry.Message != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyMsg)) + } + if entry.err != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyLogrusError)) + } + if entry.HasCaller() { + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } else { + funcVal = entry.Caller.Function + fileVal = fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + } + + if funcVal != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyFunc)) + } + if fileVal != "" { + fixedKeys = append(fixedKeys, f.FieldMap.resolve(FieldKeyFile)) + } + } + + if !f.DisableSorting { + if f.SortingFunc == nil { + sort.Strings(keys) + fixedKeys = append(fixedKeys, keys...) + } else { + if !f.isColored() { + fixedKeys = append(fixedKeys, keys...) + f.SortingFunc(fixedKeys) + } else { + f.SortingFunc(keys) + } + } + } else { + fixedKeys = append(fixedKeys, keys...) + } + + var b *bytes.Buffer if entry.Buffer != nil { b = entry.Buffer } else { b = &bytes.Buffer{} } - prefixFieldClashes(entry.Data) - - f.Do(func() { f.init(entry) }) - - isColored := (f.ForceColors || f.isTerminal) && !f.DisableColors + f.terminalInitOnce.Do(func() { f.init(entry) }) timestampFormat := f.TimestampFormat if timestampFormat == "" { - timestampFormat = DefaultTimestampFormat + timestampFormat = defaultTimestampFormat } - if isColored { - f.printColored(b, entry, keys, timestampFormat) + if f.isColored() { + f.printColored(b, entry, keys, data, timestampFormat) } else { - if !f.DisableTimestamp { - f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) - } - f.appendKeyValue(b, "level", entry.Level.String()) - if entry.Message != "" { - f.appendKeyValue(b, "msg", entry.Message) - } - for _, key := range keys { - f.appendKeyValue(b, key, entry.Data[key]) + + for _, key := range fixedKeys { + var value interface{} + switch { + case key == f.FieldMap.resolve(FieldKeyTime): + value = entry.Time.Format(timestampFormat) + case key == f.FieldMap.resolve(FieldKeyLevel): + value = entry.Level.String() + case key == f.FieldMap.resolve(FieldKeyMsg): + value = entry.Message + case key == f.FieldMap.resolve(FieldKeyLogrusError): + value = entry.err + case key == f.FieldMap.resolve(FieldKeyFunc) && entry.HasCaller(): + value = funcVal + case key == f.FieldMap.resolve(FieldKeyFile) && entry.HasCaller(): + value = fileVal + default: + value = data[key] + } + f.appendKeyValue(b, key, value) } } @@ -116,10 +207,10 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) { return b.Bytes(), nil } -func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []string, timestampFormat string) { +func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []string, data Fields, timestampFormat string) { var levelColor int switch entry.Level { - case DebugLevel: + case DebugLevel, TraceLevel: levelColor = gray case WarnLevel: levelColor = yellow @@ -129,17 +220,42 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *Entry, keys []strin levelColor = blue } - levelText := strings.ToUpper(entry.Level.String())[0:4] + levelText := strings.ToUpper(entry.Level.String()) + if !f.DisableLevelTruncation { + levelText = levelText[0:4] + } + + // Remove a single newline if it already exists in the message to keep + // the behavior of logrus text_formatter the same as the stdlib log package + entry.Message = strings.TrimSuffix(entry.Message, "\n") + + caller := "" + if entry.HasCaller() { + funcVal := fmt.Sprintf("%s()", entry.Caller.Function) + fileVal := fmt.Sprintf("%s:%d", entry.Caller.File, entry.Caller.Line) + + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } + + if fileVal == "" { + caller = funcVal + } else if funcVal == "" { + caller = fileVal + } else { + caller = fileVal + " " + funcVal + } + } if f.DisableTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m %-44s ", levelColor, levelText, entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m%s %-44s ", levelColor, levelText, caller, entry.Message) } else if !f.FullTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d] %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]%s %-44s ", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second), caller, entry.Message) } else { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), entry.Message) + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]%s %-44s ", levelColor, levelText, entry.Time.Format(timestampFormat), caller, entry.Message) } for _, k := range keys { - v := entry.Data[k] + v := data[k] fmt.Fprintf(b, " \x1b[%dm%s\x1b[0m=", levelColor, k) f.appendValue(b, v) } @@ -161,11 +277,12 @@ func (f *TextFormatter) needsQuoting(text string) bool { } func (f *TextFormatter) appendKeyValue(b *bytes.Buffer, key string, value interface{}) { - + if b.Len() > 0 { + b.WriteByte(' ') + } b.WriteString(key) b.WriteByte('=') f.appendValue(b, value) - b.WriteByte(' ') } func (f *TextFormatter) appendValue(b *bytes.Buffer, value interface{}) { @@ -177,13 +294,6 @@ func (f *TextFormatter) appendValue(b *bytes.Buffer, value interface{}) { if !f.needsQuoting(stringVal) { b.WriteString(stringVal) } else { - b.WriteString(f.quoteString(stringVal)) + b.WriteString(fmt.Sprintf("%q", stringVal)) } } - -func (f *TextFormatter) quoteString(v string) string { - escapedQuote := fmt.Sprintf("\\%s", f.QuoteCharacter) - escapedValue := strings.Replace(v, f.QuoteCharacter, escapedQuote, -1) - - return fmt.Sprintf("%s%v%s", f.QuoteCharacter, escapedValue, f.QuoteCharacter) -} diff --git a/vendor/github.com/sirupsen/logrus/writer.go b/vendor/github.com/sirupsen/logrus/writer.go index 7bdebedc6..9e1f75135 100644 --- a/vendor/github.com/sirupsen/logrus/writer.go +++ b/vendor/github.com/sirupsen/logrus/writer.go @@ -24,6 +24,8 @@ func (entry *Entry) WriterLevel(level Level) *io.PipeWriter { var printFunc func(args ...interface{}) switch level { + case TraceLevel: + printFunc = entry.Trace case DebugLevel: printFunc = entry.Debug case InfoLevel: From 68b4ff5b3725777172db52f897a84e86db7da5cd Mon Sep 17 00:00:00 2001 From: Georgi Sabev Date: Tue, 23 Apr 2019 12:51:49 +0300 Subject: [PATCH 6/7] Simplify bail logic & minor nsexec improvements Co-authored-by: Julia Nedialkova Signed-off-by: Georgi Sabev --- libcontainer/nsenter/nsexec.c | 46 ++++++++--------------------------- 1 file changed, 10 insertions(+), 36 deletions(-) diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c index 494e3411f..3b08c5e33 100644 --- a/libcontainer/nsenter/nsexec.c +++ b/libcontainer/nsenter/nsexec.c @@ -37,9 +37,6 @@ enum sync_t { SYNC_RECVPID_ACK = 0x43, /* PID was correctly received by parent. */ SYNC_GRANDCHILD = 0x44, /* The grandchild is ready to run. */ SYNC_CHILD_READY = 0x45, /* The child or grandchild is ready to return. */ - - /* XXX: This doesn't help with segfaults and other such issues. */ - SYNC_ERR = 0xFF, /* Fatal error, no turning back. The error code follows. */ }; /* @@ -102,7 +99,7 @@ struct nlconfig_t { #define INFO "info" #define DEBUG "debug" -int logfd; +static int logfd = -1; /* * List of netlink message types sent to us as part of bootstrapping the init. @@ -140,16 +137,17 @@ int setns(int fd, int nstype) } #endif -void write_log_with_info(const char *level, const char *function, int line, const char *format, ...) +static void write_log_with_info(const char *level, const char *function, int line, const char *format, ...) { - static char message[1024]; + char message[1024] = {}; + va_list args; if (logfd < 0 || level == NULL) return; va_start(args, format); - if (vsnprintf(message, 1024, format, args) < 0) + if (vsnprintf(message, sizeof(message), format, args) < 0) return; va_end(args); @@ -158,24 +156,15 @@ void write_log_with_info(const char *level, const char *function, int line, cons } #define write_log(level, fmt, ...) \ - write_log_with_info(level, __FUNCTION__, __LINE__, fmt, ##__VA_ARGS__) + write_log_with_info((level), __FUNCTION__, __LINE__, (fmt), ##__VA_ARGS__) /* XXX: This is ugly. */ static int syncfd = -1; -/* TODO(cyphar): Fix this so it correctly deals with syncT. */ -#define bail(fmt, ...) \ - do { \ - int ret = __COUNTER__ + 1; \ - write_log(DEBUG, "nsenter: " fmt ": %m", ##__VA_ARGS__); \ - if (syncfd >= 0) { \ - enum sync_t s = SYNC_ERR; \ - if (write(syncfd, &s, sizeof(s)) != sizeof(s)) \ - write_log(DEBUG, "nsenter: failed: write(s)"); \ - if (write(syncfd, &ret, sizeof(ret)) != sizeof(ret)) \ - write_log(DEBUG, "nsenter: failed: write(ret)"); \ - } \ - exit(ret); \ +#define bail(fmt, ...) \ + do { \ + write_log(FATAL, "nsenter: " fmt ": %m", ##__VA_ARGS__); \ + exit(1); \ } while(0) static int write_file(char *data, size_t data_len, char *pathfmt, ...) @@ -387,7 +376,6 @@ static void setup_logpipe(void) logpipe = getenv("_LIBCONTAINER_LOGPIPE"); if (logpipe == NULL || *logpipe == '\0') { - logfd = -1; return; } @@ -731,7 +719,6 @@ void nsexec(void) */ while (!ready) { enum sync_t s; - int ret; syncfd = sync_child_pipe[1]; close(sync_child_pipe[0]); @@ -740,12 +727,6 @@ void nsexec(void) bail("failed to sync with child: next state"); switch (s) { - case SYNC_ERR: - /* We have to mirror the error code of the child. */ - if (read(syncfd, &ret, sizeof(ret)) != sizeof(ret)) - bail("failed to sync with child: read(error code)"); - - exit(ret); case SYNC_USERMAP_PLS: /* * Enable setgroups(2) if we've been asked to. But we also @@ -814,7 +795,6 @@ void nsexec(void) ready = false; while (!ready) { enum sync_t s; - int ret; syncfd = sync_grandchild_pipe[1]; close(sync_grandchild_pipe[0]); @@ -829,12 +809,6 @@ void nsexec(void) bail("failed to sync with child: next state"); switch (s) { - case SYNC_ERR: - /* We have to mirror the error code of the child. */ - if (read(syncfd, &ret, sizeof(ret)) != sizeof(ret)) - bail("failed to sync with child: read(error code)"); - - exit(ret); case SYNC_CHILD_READY: ready = true; break; From a1460818288b8addfe9b70c8931da83864251f7a Mon Sep 17 00:00:00 2001 From: Georgi Sabev Date: Tue, 23 Apr 2019 17:02:31 +0300 Subject: [PATCH 7/7] Write logs to stderr by default Minor refactoring to use the filePair struct for both init sock and log pipe Co-authored-by: Julia Nedialkova Signed-off-by: Georgi Sabev --- libcontainer/container_linux.go | 34 ++++++++-------- libcontainer/logs/logs.go | 6 +-- libcontainer/nsenter/nsenter_test.go | 4 +- libcontainer/process_linux.go | 58 ++++++++++++++-------------- main.go | 2 +- tests/integration/debug.bats | 5 +++ tests/integration/helpers.bash | 2 +- 7 files changed, 56 insertions(+), 55 deletions(-) diff --git a/libcontainer/container_linux.go b/libcontainer/container_linux.go index e5f6ad88c..d6c4ebdaa 100644 --- a/libcontainer/container_linux.go +++ b/libcontainer/container_linux.go @@ -439,24 +439,24 @@ func (c *linuxContainer) includeExecFifo(cmd *exec.Cmd) error { } func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { - parentPipe, childPipe, err := utils.NewSockPair("init") + parentInitPipe, childInitPipe, err := utils.NewSockPair("init") if err != nil { return nil, newSystemErrorWithCause(err, "creating new init pipe") } - messagePipe := readWritePair{parentPipe, childPipe} + messageSockPair := filePair{parentInitPipe, childInitPipe} - r, w, err := os.Pipe() + parentLogPipe, childLogPipe, err := os.Pipe() if err != nil { return nil, fmt.Errorf("Unable to create the log pipe: %s", err) } - logPipe := readWritePair{r, w} + logFilePair := filePair{parentLogPipe, childLogPipe} - cmd, err := c.commandTemplate(p, childPipe, logPipe.w) + cmd, err := c.commandTemplate(p, childInitPipe, childLogPipe) if err != nil { return nil, newSystemErrorWithCause(err, "creating new command template") } if !p.Init { - return c.newSetnsProcess(p, cmd, messagePipe, logPipe) + return c.newSetnsProcess(p, cmd, messageSockPair, logFilePair) } // We only set up fifoFd if we're not doing a `runc exec`. The historic @@ -467,10 +467,10 @@ func (c *linuxContainer) newParentProcess(p *Process) (parentProcess, error) { if err := c.includeExecFifo(cmd); err != nil { return nil, newSystemErrorWithCause(err, "including execfifo in cmd.Exec setup") } - return c.newInitProcess(p, cmd, messagePipe, logPipe) + return c.newInitProcess(p, cmd, messageSockPair, logFilePair) } -func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe *os.File) (*exec.Cmd, error) { +func (c *linuxContainer) commandTemplate(p *Process, childInitPipe *os.File, childLogPipe *os.File) (*exec.Cmd, error) { cmd := exec.Command(c.initPath, c.initArgs[1:]...) cmd.Args[0] = c.initArgs[0] cmd.Stdin = p.Stdin @@ -488,13 +488,13 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe fmt.Sprintf("_LIBCONTAINER_CONSOLE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), ) } - cmd.ExtraFiles = append(cmd.ExtraFiles, childPipe) + cmd.ExtraFiles = append(cmd.ExtraFiles, childInitPipe) cmd.Env = append(cmd.Env, fmt.Sprintf("_LIBCONTAINER_INITPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), fmt.Sprintf("_LIBCONTAINER_STATEDIR=%s", c.root), ) - cmd.ExtraFiles = append(cmd.ExtraFiles, logPipe) + cmd.ExtraFiles = append(cmd.ExtraFiles, childLogPipe) cmd.Env = append(cmd.Env, fmt.Sprintf("_LIBCONTAINER_LOGPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1), fmt.Sprintf("_LIBCONTAINER_LOGLEVEL=%s", p.LogLevel), @@ -509,7 +509,7 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File, logPipe return cmd, nil } -func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, logPipe readWritePair) (*initProcess, error) { +func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, messageSockPair, logFilePair filePair) (*initProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initStandard)) nsMaps := make(map[configs.NamespaceType]string) for _, ns := range c.config.Namespaces { @@ -524,9 +524,8 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, log } init := &initProcess{ cmd: cmd, - childPipe: initPipe.w, - parentPipe: initPipe.r, - logPipe: logPipe, + messageSockPair: messageSockPair, + logFilePair: logFilePair, manager: c.cgroupManager, intelRdtManager: c.intelRdtManager, config: c.newInitConfig(p), @@ -539,7 +538,7 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, initPipe, log return init, nil } -func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, nsPipe, logPipe readWritePair) (*setnsProcess, error) { +func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, messageSockPair, logFilePair filePair) (*setnsProcess, error) { cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns)) state, err := c.currentState() if err != nil { @@ -556,9 +555,8 @@ func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, nsPipe, logP cgroupPaths: c.cgroupManager.GetPaths(), rootlessCgroups: c.config.RootlessCgroups, intelRdtPath: state.IntelRdtPath, - childPipe: nsPipe.w, - parentPipe: nsPipe.r, - logPipe: logPipe, + messageSockPair: messageSockPair, + logFilePair: logFilePair, config: c.newInitConfig(p), process: p, bootstrapData: data, diff --git a/libcontainer/logs/logs.go b/libcontainer/logs/logs.go index 50c5c3ac8..1077e7b01 100644 --- a/libcontainer/logs/logs.go +++ b/libcontainer/logs/logs.go @@ -13,7 +13,7 @@ import ( ) var ( - mutex = &sync.Mutex{} + 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 @@ -64,8 +64,8 @@ func processEntry(text []byte) { } func ConfigureLogging(config Config) error { - mutex.Lock() - defer mutex.Unlock() + configureMutex.Lock() + defer configureMutex.Unlock() if loggingConfigured { logrus.Debug("logging has already been configured") diff --git a/libcontainer/nsenter/nsenter_test.go b/libcontainer/nsenter/nsenter_test.go index c4c5af8f2..c4d3c863c 100644 --- a/libcontainer/nsenter/nsenter_test.go +++ b/libcontainer/nsenter/nsenter_test.go @@ -22,8 +22,8 @@ type pid struct { } type logentry struct { - Msg string - Level string + Msg string `json:"msg"` + Level string `json:"level"` } func TestNsenterValidPaths(t *testing.T) { diff --git a/libcontainer/process_linux.go b/libcontainer/process_linux.go index 8f9202606..a65d5521e 100644 --- a/libcontainer/process_linux.go +++ b/libcontainer/process_linux.go @@ -52,16 +52,15 @@ type parentProcess interface { forwardChildLogs() } -type readWritePair struct { - r *os.File - w *os.File +type filePair struct { + parent *os.File + child *os.File } type setnsProcess struct { cmd *exec.Cmd - parentPipe *os.File - childPipe *os.File - logPipe readWritePair + messageSockPair filePair + logFilePair filePair cgroupPaths map[string]string rootlessCgroups bool intelRdtPath string @@ -85,16 +84,16 @@ func (p *setnsProcess) signal(sig os.Signal) error { } func (p *setnsProcess) start() (err error) { - defer p.parentPipe.Close() + defer p.messageSockPair.parent.Close() err = p.cmd.Start() // close the write-side of the pipes (controlled by child) - p.childPipe.Close() - p.logPipe.w.Close() + p.messageSockPair.child.Close() + p.logFilePair.child.Close() if err != nil { return newSystemErrorWithCause(err, "starting setns process") } if p.bootstrapData != nil { - if _, err := io.Copy(p.parentPipe, p.bootstrapData); err != nil { + if _, err := io.Copy(p.messageSockPair.parent, p.bootstrapData); err != nil { return newSystemErrorWithCause(err, "copying bootstrap data to pipe") } } @@ -120,11 +119,11 @@ func (p *setnsProcess) start() (err error) { if err := setupRlimits(p.config.Rlimits, p.pid()); err != nil { return newSystemErrorWithCause(err, "setting rlimits for process") } - if err := utils.WriteJSON(p.parentPipe, p.config); err != nil { + if err := utils.WriteJSON(p.messageSockPair.parent, p.config); err != nil { return newSystemErrorWithCause(err, "writing config to pipe") } - ierr := parseSync(p.parentPipe, func(sync *syncT) error { + ierr := parseSync(p.messageSockPair.parent, func(sync *syncT) error { switch sync.Type { case procReady: // This shouldn't happen. @@ -137,7 +136,7 @@ func (p *setnsProcess) start() (err error) { } }) - if err := unix.Shutdown(int(p.parentPipe.Fd()), unix.SHUT_WR); err != nil { + if err := unix.Shutdown(int(p.messageSockPair.parent.Fd()), unix.SHUT_WR); err != nil { return newSystemErrorWithCause(err, "calling shutdown on init pipe") } // Must be done after Shutdown so the child will exit and we can wait for it. @@ -163,7 +162,7 @@ func (p *setnsProcess) execSetns() error { return newSystemError(&exec.ExitError{ProcessState: status}) } var pid *pid - if err := json.NewDecoder(p.parentPipe).Decode(&pid); err != nil { + if err := json.NewDecoder(p.messageSockPair.parent).Decode(&pid); err != nil { p.cmd.Wait() return newSystemErrorWithCause(err, "reading pid from init pipe") } @@ -217,14 +216,13 @@ func (p *setnsProcess) setExternalDescriptors(newFds []string) { } func (p *setnsProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logPipe.r) + go logs.ForwardLogs(p.logFilePair.parent) } type initProcess struct { cmd *exec.Cmd - parentPipe *os.File - childPipe *os.File - logPipe readWritePair + messageSockPair filePair + logFilePair filePair config *initConfig manager cgroups.Manager intelRdtManager intelrdt.Manager @@ -246,7 +244,7 @@ func (p *initProcess) externalDescriptors() []string { // getChildPid receives the final child's pid over the provided pipe. func (p *initProcess) getChildPid() (int, error) { var pid pid - if err := json.NewDecoder(p.parentPipe).Decode(&pid); err != nil { + if err := json.NewDecoder(p.messageSockPair.parent).Decode(&pid); err != nil { p.cmd.Wait() return -1, err } @@ -282,12 +280,12 @@ func (p *initProcess) waitForChildExit(childPid int) error { } func (p *initProcess) start() error { - defer p.parentPipe.Close() + defer p.messageSockPair.parent.Close() err := p.cmd.Start() p.process.ops = p // close the write-side of the pipes (controlled by child) - p.childPipe.Close() - p.logPipe.w.Close() + p.messageSockPair.child.Close() + p.logFilePair.child.Close() if err != nil { p.process.ops = nil return newSystemErrorWithCause(err, "starting init process command") @@ -313,7 +311,7 @@ func (p *initProcess) start() error { } }() - if _, err := io.Copy(p.parentPipe, p.bootstrapData); err != nil { + if _, err := io.Copy(p.messageSockPair.parent, p.bootstrapData); err != nil { return newSystemErrorWithCause(err, "copying bootstrap data to pipe") } childPid, err := p.getChildPid() @@ -341,7 +339,7 @@ func (p *initProcess) start() error { } // Now it's time to setup cgroup namesapce if p.config.Config.Namespaces.Contains(configs.NEWCGROUP) && p.config.Config.Namespaces.PathOf(configs.NEWCGROUP) == "" { - if _, err := p.parentPipe.Write([]byte{createCgroupns}); err != nil { + if _, err := p.messageSockPair.parent.Write([]byte{createCgroupns}); err != nil { return newSystemErrorWithCause(err, "sending synchronization value to init process") } } @@ -368,7 +366,7 @@ func (p *initProcess) start() error { sentResume bool ) - ierr := parseSync(p.parentPipe, func(sync *syncT) error { + ierr := parseSync(p.messageSockPair.parent, func(sync *syncT) error { switch sync.Type { case procReady: // set rlimits, this has to be done here because we lose permissions @@ -404,7 +402,7 @@ func (p *initProcess) start() error { } } // Sync with child. - if err := writeSync(p.parentPipe, procRun); err != nil { + if err := writeSync(p.messageSockPair.parent, procRun); err != nil { return newSystemErrorWithCause(err, "writing syncT 'run'") } sentRun = true @@ -433,7 +431,7 @@ func (p *initProcess) start() error { } } // Sync with child. - if err := writeSync(p.parentPipe, procResume); err != nil { + if err := writeSync(p.messageSockPair.parent, procResume); err != nil { return newSystemErrorWithCause(err, "writing syncT 'resume'") } sentResume = true @@ -450,7 +448,7 @@ func (p *initProcess) start() error { if p.config.Config.Namespaces.Contains(configs.NEWNS) && !sentResume { return newSystemError(fmt.Errorf("could not synchronise after executing prestart hooks with container process")) } - if err := unix.Shutdown(int(p.parentPipe.Fd()), unix.SHUT_WR); err != nil { + if err := unix.Shutdown(int(p.messageSockPair.parent.Fd()), unix.SHUT_WR); err != nil { return newSystemErrorWithCause(err, "shutting down init pipe") } @@ -494,7 +492,7 @@ func (p *initProcess) sendConfig() error { // send the config to the container's init process, we don't use JSON Encode // here because there might be a problem in JSON decoder in some cases, see: // https://github.com/docker/docker/issues/14203#issuecomment-174177790 - return utils.WriteJSON(p.parentPipe, p.config) + return utils.WriteJSON(p.messageSockPair.parent, p.config) } func (p *initProcess) createNetworkInterfaces() error { @@ -527,7 +525,7 @@ func (p *initProcess) setExternalDescriptors(newFds []string) { } func (p *initProcess) forwardChildLogs() { - go logs.ForwardLogs(p.logPipe.r) + go logs.ForwardLogs(p.logFilePair.parent) } func getPipeFds(pid int) ([]string, error) { diff --git a/main.go b/main.go index 273aeb84c..78913c041 100644 --- a/main.go +++ b/main.go @@ -87,7 +87,7 @@ func main() { }, cli.StringFlag{ Name: "log", - Value: "/dev/null", + Value: "/dev/stderr", Usage: "set the log file path where internal debug information is written", }, cli.StringFlag{ diff --git a/tests/integration/debug.bats b/tests/integration/debug.bats index 187297990..e02cf4a1f 100644 --- a/tests/integration/debug.bats +++ b/tests/integration/debug.bats @@ -16,6 +16,11 @@ function teardown() { runc --debug run test_hello echo "${output}" [ "$status" -eq 0 ] + + # check expected debug output was sent to stderr + [[ "${output}" == *"level=debug"* ]] + [[ "${output}" == *"nsexec started"* ]] + [[ "${output}" == *"child process in init()"* ]] } @test "global --debug to --log" { diff --git a/tests/integration/helpers.bash b/tests/integration/helpers.bash index 141813328..0f04bbfca 100644 --- a/tests/integration/helpers.bash +++ b/tests/integration/helpers.bash @@ -65,7 +65,7 @@ function runc() { # Raw wrapper for runc. function __runc() { - "$RUNC" ${RUNC_USE_SYSTEMD+--systemd-cgroup} --log /proc/self/fd/2 --root "$ROOT" "$@" + "$RUNC" ${RUNC_USE_SYSTEMD+--systemd-cgroup} --root "$ROOT" "$@" } # Wrapper for runc spec, which takes only one argument (the bundle path).