sirupsen / logrus Goto Github PK

When a hook fails to fire for some reason, an error message is printed. The errors aren't printed using the formatters, however:

Failed to fire hook: Post http://internal.errors/api/4/store/: dial tcp: lookup internal.errors: no such host
{"egid": 0, "eid": 0, "env": "staging", "host": "stage1nas1", "level": "error", "pid": 30926, "time": "2015-01-19T23:57:32Z", "version": "b02ca56faf126efd94db11646b0bf4e33ea79aba", "subsystem": "heartbeat"}
{"egid": 0, "eid": 0, "env": "staging", "host": "stage1nas1", "level": "info", "pid": 30926, "time": "2015-01-19T23:57:34Z", "version": "b02ca56faf126efd94db11646b0bf4e33ea79aba", "subsystem": "zookeeper"}
{"egid": 0, "eid": 0, "env": "staging", "host": "stage1nas1", "level": "info", "pid": 30926, "time": "2015-01-19T23:57:36Z", "version": "b02ca56faf126efd94db11646b0bf4e33ea79aba", "subsystem": "zookeeper"}
{"egid": 0, "eid": 0, "env": "staging", "host": "stage1nas1", "level": "info", "pid": 30926, "time": "2015-01-19T23:57:38Z", "version": "b02ca56faf126efd94db11646b0bf4e33ea79aba", "subsystem": "zookeeper"}
{"egid": 0, "eid": 0, "env": "staging", "host": "stage1nas1", "level": "info", "pid": 30926, "time": "2015-01-19T23:57:39Z", "version": "b02ca56faf126efd94db11646b0bf4e33ea79aba", "subsystem": "getter"}

The culprits are those lines:

    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()
    }

    reader, err := entry.Reader()
    if err != nil {
        entry.Logger.mu.Lock()
        fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err)
        entry.Logger.mu.Unlock()
    }

    entry.Logger.mu.Lock()
    defer entry.Logger.mu.Unlock()

    _, err = io.Copy(entry.Logger.Out, reader)
    if err != nil {
        fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err)
    }

https://github.com/Sirupsen/logrus/blob/master/entry.go#L78-L97

They should be printing with the formatter, me thinks.

@sirupsen
cc: @macb

Systemd's journal support could be added by using the go-systemd lib:
https://github.com/coreos/go-systemd/blob/master/journal/send.go

It is kinda funny however to make it a "Hook" -- you kinda want it to be a log formatter, but the current interface for formatters assumes an io.Copy() interface, while for journal.Send you would want the 'formatter' to handle the 'write'.

A quick hack would be to allow Formatters to return nil, and in that case skip the io.Copy paths?

Hi,

Is there a possibility or a plan to provide the Logrus implementation as a custom io.Writer that can be used in conjonction with the standard library logger ?

https://godoc.org/github.com/Sirupsen/logrus#StdLogger is nice but it still makes the package depend on Logrus, only to get the interface.

I'm discussing the issue here: ant0ine/go-json-rest#62

Thanks,

Antoine

I want to use Sourcegraph code search and code review with logrus. A project maintainer needs to enable it to set up a webhook so the code is up-to-date there.

Could you please enable logrus on @sourcegraph by going to https://sourcegraph.com/github.com/Sirupsen/logrus and clicking on Settings? (It should only take 15 seconds.)

Thank you!

Hi, can you plz create git tag for stable version?
This will enable your package to be installed using http://labix.org/gopkg.in .

Somewhat related to #24, it is problematic that the "time" field is a string. This means that formatters have to parse the Go date format back into a real time.Time before they can reformat it. The Go date format has no constant defining it (and the Go maintainers have rejected requests to add one), so the caller has to hard-code the Go date format just to parse it and reformat it to something else. This would work better if "time" were kept a time.Time. Then formatters could just format it. (This would also eliminate the possibility of parsing errors that need to be checked for.)

I've poked through the source to see if I could resolve this myself but couldn't figure it out.

Logs being sent to Papertrail are incorrectly logging entry.Data["level"] Papertrail sees all of the logs as %!s(<nil>)

All of the sub-packages in logrus are prefixed with logrus_. The GO convention states that package names should be a single word, and the name of the directory they are in. Thus hooks/papertrail/papertrail.go would be package papertrail.

Yes, this is convention, and not hard requirement, but I just wanted to bring it up since changing things like this becomes more difficult once logrus goes 1.0.

I'm using goxc to cross compile my project. Doing so now results in:

../../Sirupsen/logrus/text_formatter.go:28: undefined: IsTerminal
[goxc:xc] 2015/01/16 20:50:30 'go' returned error: exit status 2
[goxc:xc] 2015/01/16 20:50:30 Error: exit status 2
[goxc:xc] 2015/01/16 20:50:30 Have you run `goxc -t` for this platform (amd64p32,nacl)???

This error is repeated for every platform.

I'm using c6a969a and Go 1.4 on Ubuntu 14.04.
Running goxc in the examples/basic directory is enough to reproduce the problem. I have ran goxc -t of course and I know this worked previous to introducing logrus.

I recently migrated some parts of our code from glog to logrus and noticed some serious decrease (close to 45%) in performance. We are not doing anything fancy, just level logging to a file. So I started to profile and noticed that a lot of time is spend on memmove and scanblock. When I accumulate all garbage collection related operations I see that roughly 26% of the time is spend on garbage collection.

One of the hotspots I discovered it the formatting and I spiked a few tweaks to introduce pooled buffers. This will change the API since buffers need to be released after they have been used.

My changes have a huge impact on the code and break almost all hooks. Not in a bad way, it's just because types are slightly different. So, before I spend a lot of time trying to complete this, I want to discuss if the logrus community would like to move into this direction?

The first benchmark's show an performance improvement 12% for small log entries and up to 35% for larger entries with an mean of 28%. My assumption is that is also significantly lowers memory usage and because it generates less garbage, we spend less time in Go's stop the world garbage collector.

My concrete question: is the logrus community willing to accept changes that effect the entire codebase and hook interface to gain performance and generate less garbage? If so, I want to discuss the next steps and willing to invest time in it to make it happen.

JSONFormatter seems to have trouble with errors passed to log.Fields

log.SetFormatter(&log.JSONFormatter{})
err := errors.New("this will come up as {}")
log.WithFields(log.Fields{
  "err": err,
}).Warn("the error field will be empty")

The code above will output out the following:

{"err":{},"level":"warning","msg":"the error field will be empty","time":"2015-01-16T20:51:40-08:00"}

The TextFormatter works as expected so this issue is specific to the JSONFormatter as far as I can tell.

The entry stores data in the same map than where the Fields are set. This means that "time", "msg" and "level" are reserved field name.

https://github.com/Sirupsen/logrus/blob/master/entry.go#L61-L63

Using those keys should be fine, or somehow tell the user by returning an error or panicking. I think the two last options aren't really options.

Hooks imply order, specifically that they're run before the entry is actually logged—however, that's not the case, since for Logrus to be as customizable as possible the hooks should allow modifying the entry before it's logged. The proper name for such modules is a 'middleware', so I propose we rename hooks to middleware everywhere in Logrus.

@aybabtme

It would be nice if the package name of the airbrake hook would match the import path:

• Package name: package logrus_airbrake
• Import string: github.com/Sirupsen/logrus/hooks/airbrake

There are two reasons for this.

1. Mismatch between import strings and package name are always a bit confusing. Especially for newcomers to Go, but even for experienced users as it's usual that import string match package names.
2. logrus_airbrake is an odd package name. Super scientific smoke test: http://www.pkgname.com/?pkgname=logrus_airbrake

Like the standard log library, and the glog project; having a package global logger is very convenient to avoid having to pass a logger everywhere in your application.

I propose adding the following package exported funcs with a default logger to stdout:

• WithField
• WithFields
• Debug
• Info
• Warn
• Error
• Panic
• Fatal

Here I don't list the Print and Warning family of functions because I don't think they are useful given the other levels. Also, the f and ln families, because:

• Printf like funcs are covered by WithField(s)
• Println like funcs are redundant with the Print like funcs, since each log entry is a line anyways.

Good evening,

Here is a sample of what I'd like to do http://play.golang.org/p/Wwoo0eW0x5 (Currently, `e.Data["test"] = "changed" doesn't change anything to the output.)

Basically my question is, should a hook be able to modify the data of the entry? I think that yes, a hook should be like a middleware and should be able to filter things.

I ran into an unexpected issue with the hooks functionality.

It was my impression that invoking log.Error("something") would set the entry.Data["error"] field to the message, in this case "something"

It seems the "error" field is only set if using log.WithFields().Error()

Is this by design or unintentional?

Want to reuse several fields between log entries. Do the following:

l := log.WithFields(log.Fields{
    ".message-id": messageId,
    ".job-name": jobName,
})

then:

l.Info("started")
l.Info("finished")

got:

INFO[0000] started                                       .job-name=select-vk-groups .message-id=4204cb9a
INFO[0000] finished                                      .job-name=select-vk-groups .message-id=4204cb9a fields.level=info fields.msg=started fields.time=2014-08-23T02:49:37+03:00

I didn't expect these fields.* fields to be displayed. Also, looks like depend on the previous state: fields.msg=started

I'm not sure how many other people use logrus in this manner, but it's very common that I create a single log instance to use throughout a HTTP route or log-running method, so that I can set the fields once and continue to use this. I find this incredibly useful for tracking the file or route that I'm working on, etc.

Unfortunately, the prefix-clash copies the last-used message as fields.msg, causing each log line after the first to contain the message for the previous log. Here's a small program that demonstrates this:

package main

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


func init() {
  // Log as JSON instead of the default ASCII formatter.
  log.SetFormatter(&log.JSONFormatter{})
}

func main() {
    ll := log.WithFields(log.Fields{"test_field":"test_field_data"})
    ll.Info("Test Message 1")
    ll.Info("Test Message 2")
}

This will output the following (I've pretty printed it):

{
  "level": "info",
  "msg": "Test Message 1",
  "test_field": "test_field_data",
  "time": "2014-12-09T18:11:38-08:00"
}
{
  "fields.level": "info",
  "fields.msg": "Test Message 1",
  "fields.time": "2014-12-09T18:11:38-08:00",
  "level": "info",
  "msg": "Test Message 2",
  "test_field": "test_field_data",
  "time": "2014-12-09T18:11:38-08:00"
}

Notice how the second log has the correct message in the message field, but fields.msg contains the msg body from the previous. Furthermore, the fields data is not present in the first log at all.

glog has this nice feature where it can log to stderr on top of logging to its normal output, if a certain threshold is met:

See flag -stderrthreshold=ERROR in glog.

Something like that would be very useful.

Logrus won't compile when using AppEngine Managed VM's because it's missing the IsTerminal() function, since there is a build flag on the terminal_notwindows.go file. Removing this flag allows it compile. The package won't run on regular app engine anyway since there are other syscalls.
Is there any reason to keep this build flag?

I think it's safe to assume that the output of a formatter doesn't become a terminal randomly. If that's true, then there's no need to call IsTerminal at every log entry (IsTerminal makes a syscall`):

https://github.com/Sirupsen/logrus/blob/master/text_formatter.go#L38

@sirupsen; thoughts?

I think this function is very usefull,Do we have a plan to support it.
Then the log files will look like "xxx.log.2015-02-25 xxx.log.wf.2015-02-25"
"xxx.log.2015-02-25" will include "INFO level logs"
"xxx.log.wf.2015-02-25" will include "WARN and FATAL level logs"

Both stdlib package log and many other logging frameworks are supporting this (e.g. https://github.com/inconshreveable/log15). Am I missing how to enable it or is it not supported?

When using the packaged syslog hook, the data being sent to syslog uses the format sent to the default destination. This means that syslog is receiving a payload with the severity level in the message content, when it already has severity as part of the syslog headers. It has a timestamp when syslog has a timestamp. It has ANSI color escape codes, and alignment formatting.

Basically each output destination needs its own formatter.

When running tests I would like to disable any kind of logging. For some reason the package-level exported logger doesn't seem to be responding to SetOutput(ioutil.Discard) and still sends stuff to my stdout.

I assume that happens when a value in logrus.Fields is an integer.

https://github.com/Sirupsen/logrus/blob/master/text_formatter.go#L117

I'm opening this issue so we can discuss the drawbacks and advantages of the multiple options to solve the issue of logrus overwriting user supplied fields.

option 1 #33

The argument against option 1 is that nested 'fields' might cause problems with log aggregators. I'm not sure about that.

option 2

The argument against 2 is that what the user logs will be different from what the logs contain. For instance:

log.WithFields(logrus.Fields{
    "msg": "derp message",
}).Info("received message")

The field msg will be prefixed with fields, avoiding collisions:

{
    "time": "00:00:00 ...", 
    "level": "info", 
    "msg": "received message", 
    "fields.msg": "derp message",
}

While it's true that the name of the user supplied field is not the same the one provided,
it's not very hard to figure out where it comes from. It also makes it clear that this field is a
user supplied field. With a clear documentation to that effect, I think that would be a viable
solution.

option 3 (current situation)

The argument against 3 is that it erases user supplied fields. The fact that it
does that is not documented, and the logger doesn't warn or panic or anything
when it erases the field.

All this together looks very bad to me, if the other
options aren't optimal, at least they are correct and don't lose data.

option 4 (mitigate current situation)

This is a sort of hybrid of option 2 and 3. The argument against it
is that it can still erase user supplied fields, although less likely; and
it's kind of a bandaid solution.

The concept is to use a prefix that is unlikely to be chosen by a user:

log.WithFields(logrus.Fields{
    "msg": "derp message",
}).Info("received message")

All logrus default fields are prefixed by the string logrus:

{
    "logrus.time": "00:00:00 ...", 
    "logrus.level": "info", 
    "logrus.msg": "received message", 
    "msg": "derp message",
}

You can then document that the keys of logrus are in a namespace logrus.something, and
tell users not to use that name space. Perhaps even check, when adding a field,
that users don't use logrus reserved names, and panic if they do.

In README:

import (
  log "github.com/Sirupsen/logrus"
  "github.com/Sirupsen/logrus/hooks/airbrake"
  "github.com/Sirupsen/logrus/hooks/syslog"
)

func init() {
  log.AddHook(new(logrus_airbrake.AirbrakeHook))
  log.AddHook(logrus_syslog.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, ""))
}

But NewSyslogHook returns both a hook and an error, os it should be:

sh, err := log.AddHook(logrus_syslog.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, ""))
if err == nil {
  log.AddHook(sh)
}

Also, log/syslog should be imported to get syslog.LOG_INFO.

To have a similar behavior as the go standard log package, it may be interesting to have a default instance to do something like logrus.Debug("Something") directly without instanciating a new logger.

What do you think of that?

The Go fmt package has different spacing between arguments for Print and Println. This is described in the documentation.

Logrus does not use the same spacing as the go fmt/log packages inhibiting it's ability to be a drop in replacement. Can this be changed or is forking necessary here?

Structured, pleasent logging for Go.

"pleasent" should be "pleasant".

http://labix.org/gopkg.in

Allows for super easy version control, so we don't have to worry about backwards compatibility much anymore.

Thoughts @aybabtme?

It would be nice to be able to set the level with a string. I'm using something like this to set the level from CLI flags:

func SetLogLevel(level string) {
    switch level {
    case "panic":
        log.SetLevel(log.PanicLevel)
    case "fatal":
        log.SetLevel(log.FatalLevel)
    case "error":
        log.SetLevel(log.ErrorLevel)
    case "warn":
        log.SetLevel(log.WarnLevel)
    case "info":
        log.SetLevel(log.InfoLevel)
    case "debug":
        log.SetLevel(log.DebugLevel)
    }
}

It would be nice to have an additional level between Info and Warning Notice. I tend to use logging as follows:

• Notice: System start/stop, significant-but-normal events
• Info: Detail: User connected, transaction applied etc.
• Debug: In depth debugging/tracing, e.g. packet dumps

I usually would have the default log level set to Notice and have Errors, Fatal and Panic logged to a remote server for analysis.

The title says it all, "Is there a way to get access to the current *http.Request in middleware?", Ideally, I would like to print out IP address, etc in fields.

log.WithError(err) -> log.WithField("error", err)

Like the standard log library, and the glog project; having a package global logger is very convenient to avoid having to pass a logger everywhere in your application.

I propose adding the following package exported funcs with a default logger to stdout:

• WithField
• WithFields
• Debug
• Info
• Warn
• Error
• Panic
• Fatal

Here I don't list the Print and Warning family of functions because I don't think they are useful given the other levels. Also, the f and ln families, because:

• Printf like funcs are covered by WithField(s)
• Println like funcs are redundant with the Print like funcs, since each log entry is a line anyways.

Hello! Very happy with logrus so far, thank you for your work! :)

I'd like to be able to configure the appearance of the "time" field. Specifically, my intention is to use RFC3339Nano in UTC.

Any thoughts on how to approach this? I attempted to use a hook to replace the time field with my own string, but that doesn't seem to work; specifically, inside the hook the time field is changed, but after the hook it has the same original value (something not being passed as a pointer?).

Sample code attempted:

type LogrusTimeFixerHook struct {}
func (l *LogrusTimeFixerHook) Fire(entry *logrus.Entry) error {
  fmt.Println("Fire!")
  entry.Data["time"] = time.Now().UTC().Format(time.RFC3339Nano)
  fmt.Printf("%#v\n", entry.Data)
  return nil
}

func (l *LogrusTimeFixerHook) Levels() []logrus.Level {
  return []logrus.Level{ logrus.Panic, logrus.Fatal, logrus.Error, logrus.Warn, logrus.Info, logrus.Debug }
}

func init() {
  log.Formatter = new(logrus.JSONFormatter)
  log.Level = logrus.Warn
  log.Hooks.Add(new(LogrusTimeFixerHook))
  log.Warn("Logging is ready!")
}

output:

Fire!
datanow: logrus.Fields{"time":"2014-05-02T05:40:55.393196518Z", "level":"warning", "msg":"Logging is ready!"}
{"level":"warning","msg":"Logging is ready!","time":"2014-05-01 22:40:55.393034888 -0700 PDT"}

It would be cool to have syslog hooks so logs can be routed to logstash/heka/papertrail/splunk.

I'm not actually asking for log rotation as a logrus feature. I think it's best managed through a separate Writer. But is there a rotating Writer that's recommended for use with logrus?

It would be useful to be able to disable the TextFormatter from sorting fields.

Hello,

I wrote a logrus hook for loggly.com

https://github.com/sebest/logrusly

thanx

Standar log pakcage have the Output method for Logger http://golang.org/pkg/log/#Logger.Output
Maybe Entry should have that method so it interface exactly with std Logger.

The fact that msg, time, and level have special meaning, but are treated as standard fields leads to a lot of headaches IMO. I have more than once passed a field called "msg" that collided with the built-in msg (it quietly is thrown away). The fact that you have to type-assert these mandatory fields is also an opportunity for bugs.

I recommend that msg, time and level be promoted to actual struct fields in Entry. This will give them types and will allow these field names to exist in the Fields map.

Hi!

The syslog hook doesn't log anything unless a field "level" is set by the user.

It can be corrected by using entry.Level.String() in syslog.go. However, in this case, logging is done with ANSI codes (I get something like this: #033[34mINFO#033[0m[0000] proxy: start serving requests).

Hello,

I just created https://github.com/johntdyer/slackrus and I wanted to see if you wanted to maybe add it to the readme. I can do a PR if you want but wanted to make sure you'd consider it.

Thanks

John

The default formatters and hooks all have pointer receivers on their method, but non of them actually need to.

Removing the pointer receivers would not break any clients and it would make the usage of them hooks easier/less awkward.

current code is generating every log line with a trailing space, which is not good and should be eliminated

tf := &TextFormatter{DisableColors: true}
byts, _ := tf.Format(&Entry{Message: "msg content"})
fmt.Printf("%q\n", string(byts))

"time=\"0001-01-01T00:00:00Z\" level=panic msg=\"msg content\" \n"