Logrus: "Logger as an io.Writer"

[psmason]

package main

import (
    "github.com/Sirupsen/logrus"
    "log"
)

func main() {
    logrusInputWriter := logrus.StandardLogger().Writer()
    log.SetOutput(logrusInputWriter)
    log.Println("will this print?")
    logrusInputWriter.Close()
}

The issue is that the logging event is not guaranteed to happen, from a race between process exit and the read end of the pipe waking up. A solution I've played with involves Writer() returning not

*io.PipeWriter

but rather

io.WriteCloser

with the underlying returned struct using synchronization tools in the implementation. A sample gist is viewable at https://gist.github.com/psmason/839de8ddbdfa0ce21e30680987aa52cb.

Unfortunately it looks like fixing this in a backwards compatible way will be difficult, without playing with the return type.

[pasztorpisti]

In my opinion logrus shouldn't provide Logger.Writer - a generic builtin solution to this problem. Even if it provided one, it should be a completely separate package with building blocks similar to the example below.

Implementing an io.Writer that bridges the gap between the standard log pkg and logrus is straightforward and requires no go routines, pipes or other kind of black magic:

package main

import (
    "github.com/sirupsen/logrus"
    "log"
)

func main() {
    log.SetFlags(0)
    log.SetOutput(&log2LogrusWriter{
        entry: logrus.StandardLogger().WithField("logger", "std"),
    })

    log.Print("meow")
    logrus.Info("woof")
}

// log2LogrusWriter exploits the documented fact that the standard
// log pkg sends each log entry as a single io.Writer.Write call:
// https://golang.org/pkg/log/#Logger
type log2LogrusWriter struct {
    entry *logrus.Entry
}

func (w *log2LogrusWriter) Write(b []byte) (int, error) {
    n := len(b)
    if n > 0 && b[n-1] == '\n' {
        b = b[:n-1]
    }
    w.entry.Warning(string(b))
    return n, nil
}

The above solution has several advantages over Logger.Writer:

• No goroutines, no delays in logs
• You can implement your own writer in a configurable way (log level, custom fields, etc...)
• The above solution doesn't impose a limit on the logsize (as the Scanner used by Logger.Writer does)
• Writing a log that contains newlines appears as multiple logrus entries with the Logger.Writer solution because the scanner splits across newlines

I can see use cases for writer implementations that take their input as a continuous stream of bytes and split it up across newlines but those writers should also be implemented as external building blocks without the logrus core knowing about them and they could probably be implemented without goroutines.

[bklau]

@pasztorpisti I tried your solution. The only thing is that logrus will log all the messages from stdlog "log" at INFO level. That can make it nosy if you have many warnings or debugs like so:

origin x-app-id="ABCr" x-log-level="INFO" x-user-id="XYZ"] 2018-05-11T23:27:08Z /log_adapter.go:23 - RAFT Internal[WARN] raft: Heartbeat timeout from "" reached, starting election

[origin x-app-id="ABC" x-log-level="INFO" x-user-id="XYZ"] 2018-05-11T23:27:08Z /log_adapter.go:23 - RAFT Internal[INFO] raft: Node at 10.0.2.15:3131 [Candidate] entering Candidate state in term 3

Note: The "RAFT Internal[INFO] raft" or "RAFT Internal[WARN] raft" is emitted by a std logger to io.Writer from logrus.

Q: How do i reconcile the log level of std log to that of logrus?. What I mean is this, if I set my logging level in logrus to "INFO", I want to see only associated logging at equivalent "INFO" level from std log. That is I shouldn't see verbose DEBUG log messages.

[pasztorpisti]

@bklau

The standard logger is very minimalist (and I like that): it has 1 log level (so it doesn't have log levels at all). For this reason I don't really understand how can you have the problem of separating the info and debug levels of the standard logger.

Different convenience methods of the standard Logger (like Panic and Fatal) do the exact same thing as Print with some additional behavior. E.g.: Panic simply prints a message like Print and then it panics. Fatal prints a message like Print and then terminates the process with os.Exit.

Those people who want to use the standard logger with different log levels usually create several instances of the standard logger (with log.New) and put them into global variables (like warn, error, etc...). (Note that the global functions of the standard log package are also simply using an instance of that logger that is in a global variable in that package.) If you do this then you can channel these loggers into logrus with different log levels and/or log fields. But again, log levels paired up with the standard logger are already suspicious (or impossible?).

If you need log levels then using the std logger package doesn't make much sense. Using directly a logger pkg that supports levels is the way to go. This whole log2logrus relaying is useful only if you are writing your own app that uses logrus but you want to include a few packages that use the standard logger (which includes some standard packages too) and you want to see those logs in logrus. However those apps that use the std logger are (or should) be written with the "no log level" (linux stderr logging) philosophy which makes relaying them easy.

Several std logger instances belonging to different subsystems channeling logs into logrus with different log fields (like subsystem=whatever and perhaps other fields without the whole log level thingy) on the other hand would be quite nice design.

I'm personally not a big fan of log levels (and logrus) so using the std logger is pretty much enough for me most of the time.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.