Logrus: How to separate Stdout and Stderr output?

[trong]

Hi!
How can I out levels debug, info, warn to Stdout and levels error, fatal, panic to Stderr in one logger instance?

[Robpol86]

This is how I accomplished this (info/debug to stdout, warn/error/fatal/panic to stderr). It's simple but kind of ugly:
https://github.com/Robpol86/githubBackup/commit/eb10087f0d9a5f152f93e95eebebd3fbf02e5d2c

So far seems to work for me. Not sure if I'd want to do this in a large application or a production environment.

Basically:

type stderrHook struct{}

func (h *stderrHook) Levels() []logrus.Level {
    return []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel}
}

func (h *stderrHook) Fire(entry *logrus.Entry) error {
    // logrus.Entry.log() is a non-pointer receiver function so it's goroutine safe to re-define *entry.Logger. The
    // only race condition is between hooks since there is no locking. However .log() calls all hooks in series, not
    // parallel. Therefore it should be ok to "duplicate" Logger and only change the Out field.
    loggerCopy := reflect.ValueOf(*entry.Logger).Interface().(logrus.Logger)
    entry.Logger = &loggerCopy
    entry.Logger.Out = os.Stderr
    return nil
}

// logrus.SetOutput(os.Stdout) // Default is stdout for info/debug which are emitted most often.
// logrus.AddHook(&stderrHook{})

[Robpol86]

Even better after a coworker pointed this out (still a bad idea though):

type stderrHook struct {
    logger *logrus.Logger
}

func (h *stderrHook) Levels() []logrus.Level {
    return []logrus.Level{logrus.PanicLevel, logrus.FatalLevel, logrus.ErrorLevel, logrus.WarnLevel}
}

func (h *stderrHook) Fire(entry *logrus.Entry) error {
    entry.Logger = h.logger
    return nil
}

//logrus.SetOutput(os.Stdout) // Default is stdout for info/debug which are emitted most often.
//loggerCopy := reflect.ValueOf(*logrus.StandardLogger()).Interface().(logrus.Logger)
//hook := stderrHook{logger: &loggerCopy}
//hook.logger.Out = os.Stderr
//logrus.AddHook(&hook)

[sirupsen]

Yeah, we won't support this directly in core since the use-case is too narrow. A custom hook or formatter is recommended.

[muhilan]

Please be aware that the suggestion here does not work now with this commit https://github.com/sirupsen/logrus/commit/89742aefa4b206dcf400792f3bd35b542998eb3b

I get 'fatal error: sync: unlock of unlocked mutex' now.

[krancour]

Yeah, we won't support this directly in core since the use-case is too narrow.

@sirupsen any chance you could consider re-opening this? I think there are log forwarders or aggregators that will assume messages received on stderr are indeed errors and therefore augment the message with text like ERR (for instance).

A co-worker recently ran into this with Cloud Foundry:

2017-09-08T06:38:28.86+0000 [APP/PROC/WEB/0] ERR time="2017-09-08T06:38:28Z" level=info msg="setting log level" logLevel=DEBUG
2017-09-08T06:38:28.86+0000 [APP/PROC/WEB/0] ERR time="2017-09-08T06:38:28Z" level=info msg="API server is listening" address="http://0.0.0.0:8080"

Given the prevalence of various container orchestrators and PaaSes and the wide array of log forwarders and aggregators they use (fluentd and logspout come to mind), this issue is likely to affect more and more people.

[emidander]

A simple solution is

type OutputSplitter struct{}

func (splitter *OutputSplitter) Write(p []byte) (n int, err error) {
    if bytes.Contains(p, []byte("level=error")) {
        return os.Stderr.Write(p)
    }
    return os.Stdout.Write(p)
}

and then

logrus.SetOutput(&OutputSplitter{})

But this introduces an extra step for each log write that shouldn't be necessary. Please add this feature! It's the only was we can get Stackdriver to display logs correctly when running as a Kubernetes app in Google's cloud.

[gnydick]

not supporting both stdout and stderr streams for logging IS NOT a narrow use case. it is THE way of separating output and is depended upon by at least 40years of convention.

[krancour]

I opened #671 to address this nearly a year ago and it hasn't even been reviewed. This is a real problem with a solution already having been offered... it's frankly ridiculous that this hasn't been taken seriously.

[danielyaa5]

It sucks @sirupsen doesn't even want to have a conversation about this. this is so dumb

[fearblackcat]

I have to create two instances of loggers that one of them is set to stdout and the other is set to stderr. Although it is ugly using way, but it is simple solution and not necessary to care the unmarshal the serialized data or overriding the write method.

var (
    Logger    *logrus.Entry
    ErrLogger *logrus.Entry
)

func init() {
    initStdoutLogger()
    initStderrLogger()
}

func initStdoutLogger() {
    stdoutLogger := logrus.New()
    stdoutLogger.SetOutput(os.Stdout)
    stdoutLogger.SetLevel(logrus.TraceLevel)
    Logger = stdoutLogger.WithFields(logrus.Fields{
        "type": "Console",
    })
}

func initStderrLogger() {
    stderrLogger := logrus.New()
    stderrLogger.SetOutput(os.Stderr)
    stderrLogger.SetLevel(logrus.WarnLevel)
    ErrLogger = stderrLogger.WithFields(logrus.Fields{
        "type": "Console",
    })
}

[krancour]

@fearblackcat, presumably you're going to use one logger only for writing messages less sever than a warning (to stdout) and the other for those as severe or moreso than a warning (to stderr)?

If you're putting direct knowledge of what messages go where directly in your logic, doesn't that almost entirely defeat the purpose of using a runtime configurable logger?

[fearblackcat]

@fearblackcat, presumably you're going to use one logger only for writing messages less sever than a warning (to stdout) and the other for those as severe or moreso than a warning (to stderr)?

If you're putting direct knowledge of what messages go where directly in your logic, doesn't that almost entirely defeat the purpose of using a runtime configurable logger?

@krancour In my way, I also encapsulate the logger interface for user. e.g.:
Assume my logrus is initialized in common package.

type Log struct {
        context.Context
}

func (log *Log) Trace(format string, v ...interface{}) {
    common.Logger.WithContext(log.Context).Tracef(format, v...)
}

func (log *Log) Debug(format string, v ...interface{}) {
    common.Logger.WithContext(log.Context).Debugf(format, v...)
}

func (log *Log) Info(format string, v ...interface{}) {
    common.Logger.WithContext(log.Context).Infof(format, v...)
}

func (log *Log) Warn(format string, v ...interface{}) {
    common.ErrLogger.WithContext(log.Context).Warnf(format, v...)
}

func (log *Log) Error(format string, v ...interface{}) {
    common.ErrLogger.WithContext(log.Context).Errorf(format, v...)
}

If you want to configure in runtime, it will always do what u want with one handler ( the Log instance).
BTW, the log config can also be define in yaml or toml config file. And u can use inotify to listen the config file if some config fields is changed.

[krancour]

@fearblackcat, clever. I like it.

[iam-veeramalla]

This is implemented and well documented here:
https://github.com/sirupsen/logrus/tree/f104497f2b2129ab888fd274891f3a278756bcde/hooks/writer

[krancour]

@iam-veeramalla many folks have considered and rejected the solution you linked to for performance reasons. Every log message will be formatted twice and in one of those two cases, only to subsequently be discarded.

[dgsb]

@krancour let's reopen this issue, because discussion here will happen below the radar.

We can see what can be done on this topic.

[dgsb]

We have two options here either:

• we can improve reduce the number of entry formatting with the current hook based solution
• or use something similar to your solution but maybe less specific

[iam-veeramalla]

@iam-veeramalla many folks have considered and rejected the solution you linked to for performance reasons. Every log message will be formatted twice and in one of those two cases, only to subsequently be discarded.

I just realised that. Thanks for correcting @dgsb

[iam-veeramalla]

@dgsb @krancour Is there any plan to fix this issue in near future ? I think this should be considered as an important issue, Many users will be benefitted from this :)

[krancour]

@iam-veeramalla don't ask me. This isn't my project. I submitted a PR that would have fixed it and it was ignored for four years. I've stopped caring at this point. I no longer use this library because of this.

[iam-veeramalla]

@iam-veeramalla don't ask me. This isn't my project. I submitted a PR that would have fixed it and it was ignored for four years. I've stopped caring at this point. I no longer use this library because of this.

@krancour My bad, Sorry for that !! I hope this will be considered as priority, else I might as well need to find a new project for this.

[iam-veeramalla]

@krancour I am planning to use the below wrapper function in my project

package main

import (
    "os"
    "regexp"
    "fmt"

    log "github.com/sirupsen/logrus"
)

type LogWriter struct{}

var levelRegex *regexp.Regexp

const (
    LevelError   = "error"
    LevelWarning = "warning"
    LevelFatal   = "fatal"
    LevelPanic   = "panic"
    LevelDebug   = "debug"
    LevelTrace   = "trace"
)

func init() {
    var err error       
    levelRegex, err = regexp.Compile("level=([a-z]+)")
    if err != nil {
        log.WithError(err).Fatal("Cannot setup log level")
    }
}

func (w *LogWriter) detectLogLevel(p []byte) (level string) {
    matches := levelRegex.FindStringSubmatch(string(p))
    if len(matches) > 1 {
        level = matches[1]
    }
    return
}

func (w *LogWriter) Write(p []byte) (n int, err error) {
    level := w.detectLogLevel(p)

    if level == LevelError || level == LevelWarning || level == LevelFatal || level == LevelPanic {
        return os.Stderr.Write(p)
    }
    return os.Stdout.Write(p)
}

func main() {
    log.SetLevel(log.DebugLevel)
    log.SetOutput(&LogWriter{})
}

[nicolas-martin]

It would be interesting to run benchmarks to compare the impacts of the suggested solution which I involves writing every log twice. Once to io.Discard and once to appropriate stream vs parsing the regex in the message itself.

I'm not too familiar with go's built in benchmarking capability but it'll give it a shot.

edit: ran a quick benchmark test and it seems like the regex is much faster

HookInfo            31689            33846 ns/op
HookErr             29824            40997 ns/op
RegexInfo           44926            28788 ns/op
RegexErr            46003            27248 ns/op

[iam-veeramalla]

It would be interesting to run benchmarks to compare the impacts of the suggested solution which I involves writing every log twice. Once to io.Discard and once to appropriate stream vs parsing the regex in the message itself.

I'm not too familiar with go's built in benchmarking capability but it'll give it a shot.

edit: ran a quick benchmark test and it seems like the regex is much faster

HookInfo            31689            33846 ns/op
HookErr             29824            40997 ns/op
RegexInfo           44926            28788 ns/op
RegexErr            46003            27248 ns/op

amazing :)