Adding File, Line, Stacktrace

[derekdowling]

This is just an initial approach to get the ball rolling in reference to #63 that I implemented last night really quickly. It needs test, hardening,etc. I am all for a much more permanent solution, but this is at least a start. The two things that need to be addressed are whether or not we are losing context by combining the file & line number like so:

INFO[0006] Request completed                             file=/bursa/src/bursa.io/kernel/kernel.go:96

and how to format the stack trace. Right now it is pretty gross:

DEBU[0001]                                               file=/bursa/.godeps/src/github.com/Sirupsen/logrus/logger.go line=100 stack=goroutine 3 [running]:
bursa.io/middleware/logtext.getTrace(0x756ec0, 0xc2100c8240)
    /bursa/src/bursa.io/middleware/logtext/logtext.go:46 +0x6e
bursa.io/middleware/logtext.(*Logtext).Format(0xc2100915e0, 0xc2100928c0, 0x43029a, 0x7d9860, 0xc21001ea80, ...)
    /bursa/src/bursa.io/middleware/logtext/logtext.go:36 +0x181
github.com/Sirupsen/logrus.(*Entry).Reader(0xc2100928c0, 0x376d4605, 0xc2100928c0, 0x0)
    /bursa/.godeps/src/github.com/Sirupsen/logrus/entry.go:41 +0x38
github.com/Sirupsen/logrus.(*Entry).log(0xc2100928c0, 0x5, 0x0, 0x0)
    /bursa/.godeps/src/github.com/Sirupsen/logrus/entry.go:84 +0x1e9
github.com/Sirupsen/logrus.(*Entry).Debug(0xc2100928c0, 0x7f64f0934a80, 0x1, 0x1)
    /bursa/.godeps/src/github.com/Sirupsen/logrus/entry.go:109 +0x75
github.com/Sirupsen/logrus.(*Logger).Debug(0xc21004a180, 0x7f64f0934a80, 0x1, 0x1)
    /bursa/.godeps/src/github.com/Sirupsen/logrus/logger.go:100 +0xa3
github.com/Sirupsen/logrus.Debug(0x7f64f0934a80, 0x1, 0x1)
    /bursa/.godeps/src/github.com/Sirupsen/logrus/exported.go:61 +0x48
bursa.io/controller/home.HandleSignup(0x7f64f0ab9ce0, 0xc210092740, 0xc21005e750)
    /bursa/src/bursa.io/controller/home/home.go:36 +0x2f7
net/http.HandlerFunc.ServeHTTP(0x902f78, 0x7f64f0ab9ce0, 0xc210092740, 0xc21005e750)
    /usr/local/go/src/pkg/net/http/server.go:1220 +0x40
github.com/gorilla/mux.(*Router).ServeHTTP(0xc21005a4b0, 0x7f64f0ab9ce0, 0xc210092740, 0xc21005e750)
    /bursa/.godeps/src/github.com/gorilla/mux/mux.go:98 +0x21c
github.com/codegangsta/negroni.func·001(0x7f64f0ab9ce0, 0xc210092740, 0xc21005e750, 0xc210091c40)
    /bursa/.godeps/src/github.com/codegangsta/negroni/negroni.go:41 +0x4c
github.com/codegangsta/negroni.HandlerFunc.ServeHTTP(0xc210093e60, 0x7f64f0ab9ce0, 0xc210092740, 0xc21005e750, 0xc210091c40)
    /bursa/.godeps/src/github.com/codegangsta/negroni/negroni.go:24 +0x4a
github.com/codegangsta/negroni.middleware.ServeHTTP(0x7f64f0ab8808, 0xc210093e60, 0xc210091a80, 0x7f64f0ab9ce0, 0xc210092740, ...)
    /bursa/.godeps/src/github.com/codegangsta/negroni/negroni.go:33 +0x82

In this example you add this functionality by:

log.SetFormatter(logtext.NewLogtext(new(log.TextFormatter), true))

[sirupsen]

Thanks @derekdowling, awesome to get work started on this.

I feel like benchmarks are a relevant concern for this work going forward, can you see if you can get some numbers on the impact of this?

[sirupsen]

Because if it's negligible, we could consider adding it to the core.. however, you might be right that it's more cleanly implemented as hooks since the formatters are run after the hooks anyway.

[placeybordeaux]

This didn't seem to work for me, but adding it to the core should make it simper. I just hacked to together for myself, but +1 for adding it directly to the core and letting it be a setting.

[robmccoll]

So if you just add this: _, file, line, _ := runtime.Caller(1) (or however many calls deep you want to intercept it) to logrus itself and provide that data through to any middleware that wants to use it, you're only adding 275 nanoseconds per actual logging call (which is nothing, and compared to the cost of writing to stdout or a file is double nothing).

As reported by:
func BenchmarkHello(b *testing.B) {
for i := 0; i < b.N; i++ {
_, file, line, _ := runtime.Caller(0)
if file == "" || line < 5 {
fmt.Println("Don't print")
}
}
}

When swapped to actually print, the cost becomes ~2.8 microseconds in total. Running just the print with supplied data comes to ~2.4 microseconds, so I'd buy the 275 nanoseconds for the lookup and copy out.

[derekdowling]

Thanks @robmccoll for taking a look at this! Honestly, I think most people are willing to pay that price for better traceability. I think the bigger thing would be adding some configurability about how and when this additional metadata is logged.

In my experience, file/lineno are pretty universally useful in most circumstances. On the other hand, I only really want a stack trace on errors or on Debug prints when I am debugging/testing/deving. I'd also like to do some work around formatting the stack trace output as it's pretty gross.

I'll try and have a core integrated version this afternoon.

[derekdowling]

@placeybordeaux yeah, sorry I did a quick copy and paste job from my own project and didn't fix the package name/imports.

[derekdowling]

Okay, I took my first crack at baking it right into the core. I still need to deal with the stack trace, but that's going to take a bit more formatting and thought. The "caller" field will give you something like "logrus_test.go:56". I can probably do some fancier logic to make it more like "logrus/logrus_test.go:56" but I am trying to keep the call as fast as possible. I guess the other option is to print the absolute path, but in my opinion that clogs up the logging because of potentially how long the path might be.

[derekdowling]

Not sure when this case might occur, or what exactly we want to return if it does.

[robmccoll]

Cool! This looks good to me. Thanks

[derekdowling]

Not sure if we want this feature, but we can do something like only printing stack traces for Debug or Error/Fatal/Panic cases so we know how we got there.

[sirupsen]

I don't think the penalty of including it is too big. Capturing it only for certain levels can be confusing.

[derekdowling]

@sirupsen any thoughts on the features I've commented or asked for feedback on here? I'd like to try and keep this PR in line with whatever philosophies you want. As soon as I have feedback, I'll get this fully implemented/tested.

[sirupsen]

Sorry about the delay here, super busy atm. I'll try to get to this PR on the weekend.

[derekdowling]

Understandable, I have my own work around in place for now so I am not in a rush, but I'd like to add get this sorted out as well!

[rasky]

@sirupsen any update on this? I need this feature as well and if we have some guidance on how you prefer it to be implemented, I can help with the implementation.

[sirupsen]

What does this string look like? Is it necessary to cast?

[sirupsen]

Sorry for the terrible responsiveness on this ticket. We'll get this in before the new year for sure, hopefully in time for Christmas.

My thoughts here are:

• Baking it into core makes the API simpler, with minimal performance penalty. Most powerful logging frameworks do this as well. If you're logging so frequently that it causes significant overhead with Logrus, we'll revisit this—but I'd like to see a real-life situation for that first. I don't think it exists, unless you have a creative use of Logrus.
• The caller() and trace() should be set as special fields on the Entry, making it up to the formatter how it'll use it.
• The default ASCII formatter will be changed by default to include the caller() or trace() for now.

What I'm a little unsure of is whether we should include trace()? Allocating a 2kb array is a little more than just including the caller, and the majority of people don't care about this for anything but Debugging.

There are plenty of people in this thread, what are you use case for either?

Cheers!

[rasky]

• Agreed on having them as explicit fields in Entry
• caller() is very fast so I don't see it as a problem to always have it available in the formatter; trace() is slower; personally, I think I would like a stacktrace in console by default in the same situations in which I send a notification to a hook like airbrake or sentry; for instance in Python, anytime there is an exception, it is both send to sentry and I get the stacktrace in console. hooks are used at the Error level or above, so I would do the same; if they are configurable, I would (at least by default) use the configuration variable to tune both.
• For debugging, I think a WithTrace() function is fine: log.WithField("foo", "bar").WithTrace().Debug("whatever")

As for default text formatting of the caller, I would suggest having an explicit fixed-width "column" in the console,

WARN[0024] webserver:24    new request            peer=127.0.0.1 port=57647

allocating maybe 12-15 characters to it, truncating the filename if necessary, with no path. I think this would do for a good default for most people because there are rare situations in which you work on a project with conflicting file names even in different directories/packages.

An alternative would be using the package name by default instead of the filename (pro would be consistent logging even when you split existing code into multiple files, just like you keep consistent package API, con would be that many projects have large main package, where this wouldn't help much and basically just eat up 12-15 columns of space with the text main). Or you could have package name if not main, and filename if in main, but then it gets confusing fast. All in all, maybe just using always the filename is a better default.

[sirupsen]

@aybabtme what do you think about this? Interested to hear your opinion.

[aybabtme]

I think the caller=filename:no is useful.

For stacktraces, I prefer keeping this out. When we need a stacktrace using logrus, we use sentry hooks that fire and generate them. They could be logged at that point, in the hook. The same holds for airbrake hooks or other such exception reporting hooks. So I think the stacktrace part should be left out.

[rasky]

@aybabtme you mean left out by default or not including the function altogether? For dev, i don't configure sentry; i use that for testing released versions (either staging or production), but for dev on my own computer of my own working copy, I would prefer a local solution.

[aybabtme]

@rasky I meant leaving it out altogether. It seems to be something that would fit in a hook that you could add a development time when you need it.

[sirupsen]

I've been playing around with this a bit and I'm not sure there's a reliable way to get the constant of stack frames to skip right in all environments to get the file name.

Does anyone know of a better way?

[rasky]

Did you check what sentry-go does?

[sirupsen]

I don't see any logic for it.

I'm toying with this as a middleware. I'm stuck getting the file name reliably, because it's different in what seems to be three cases:

1. Logging from the test (test passes on current branch).
2. Normal conditions (e.g. Info)
3. Panic handler.

INFO[0000] A group of walrus emerges from the ocean      animal=walrus caller=proc.go:63 size=10
WARN[0000] The group's number increased tremendously!    caller=proc.go:63 number=122 omg=true
PANI[0000] It's over 9000!                               animal=orca caller=proc.go:63 size=9009
FATA[0000] The ice breaks!                               caller=asm_amd64.s:401 err=&{0x208222140 map[animal:orca size:9009 caller:proc.go:63] 2014-12-25 19:53:54.556701911 +0100 CET panic It's over 9000!} number=100 omg=true
exit status 1

I want it as a middleware, because I don't think there's any value in adding those fields to the core since it'll require hacking the formatters. It's much easier to leverage hooks, by just adding it and then getting the fields for free.

Most people are happy with the default formatters—just want the fields. I'm not going to enable the fields by default, because a lot of CLI applications use logrus (e.g. docker/machine and docker/docker), where the filename is irrelevant for customers. It should just be logrus.Hooks.Add(new(logrus_caller.CallerHook)), and then you'll have caller=<file>:<ln> in all your log entries from then on. Allowing you to customize the levels you want them for as a member of the struct.

[jeberly]

Any update on this? I came looking for a way to just get filename and line number. Thx. edit: I should add the middleware link you posted somewhat works for me when using log.WithFields, but prints wrong level/line/file when using plain log.Info, etc.

[sirupsen]

@jeberly Yep, that's the problem with this PR—runtime.Caller(4) is sketchy. The constant passed changes between platforms (and even programs) as far as I can tell. Perhaps someone can convince me of how it can be used safely and/or the approach can be reevaluated.

[alxdm]

Please looks at #133
Maybe you talk about this hook.

Usage example:

import (
    "github.com/Sirupsen/logrus"
    "github.com/Sirupsen/logrus/hooks/sourcefile"
)

var log = logrus.New()

func init() {
    log.Hooks.Add(&logrus_sourcefile.SourceFileHook{
        LogLevel: logrus.InfoLevel,
    })
}

func main() {
    defer func() {
        err := recover()
        if err != nil {
            log.WithFields(logrus.Fields{
                "omg":    true,
                "err":    err,
                "number": 100,
            }).Fatal("The ice breaks!")
        }
    }()

    log.WithFields(logrus.Fields{
        "animal": "walrus",
        "size":   10,
    }).Info("A group of walrus emerges from the ocean")

    log.WithFields(logrus.Fields{
        "omg":    true,
        "number": 122,
    }).Warn("The group's number increased tremendously!")

    log.WithFields(logrus.Fields{
        "animal": "orca",
        "size":   9009,
    }).Panic("It's over 9000!")
}

Output (See source_file field):

[t2y]

I want filename and line number, too. I'm very happy to do so. Any update?

[gonzaloserrano]

+1 :)

[archisgore]

+1

[aholic]

+1 :-)

[oli-g]

Hey, what's the status of this PR? Still blocked? Now way to reliably get them?

[sirupsen]

@oli-g I'm sure there is, but noone has convinced me of an implementation that works across platforms. I'd love for this to make it into core, but I can't merge something that has a hard-coded constant that only works on some machines.

[AkihiroSuda]

+1

[j16sdiz]

@sirupsen ,

The constant "4" is not platform dependant, it is just the number of callers:

github.com/Sirupsen/logrus.(*Entry).log( )     <-- 0
github.com/Sirupsen/logrus.(*Entry).Debug()    <-- 1
github.com/Sirupsen/logrus.(*Logger).Debug( )   <-- 2
github.com/Sirupsen/logrus.Debug( )   <--- 3
Main()   <--- 4

It won't change across platform. However, if the developer call (*Logger).Debug( ) directly, it will give wrong result. Need introduce a different stub call to make the number of calls equal.

[j16sdiz]

Maybe something like this: https://gist.github.com/978b2c102497b1f3f022
(you may take this code and use whatever licence you like)

[derekdowling]

So @sirupsen I'm back from the dead and have been playing with this code a bit more. I've isolated the tracing logic to only get called with a WithTrace() call that is fluent similar to WithFields. The caller logic is much trickier to pin down since there are so many entry points into the API that have various stack depths. As a compromise I'm going to push solely for getting Trace functionality. Those who really want caller info can just use this for now as well. Overkill, but it does the trick.

[Broadroad]

+1

[tzvatot]

+1