checked message confuses AddCaller

[mranney]

AddCaller appears to run from within Check() instead of at Write() time.

this program:

package main

import "github.com/uber-go/zap"

func main() {
    log := zap.NewJSON(zap.AddCaller())
    if cm := log.Check(zap.InfoLevel, "check"); cm.OK() {
        cm.Write(zap.String("line", "write"))
    }
}

generates this output on my machine:

{"msg":"checked_message.go:57: check","level":"info","ts":1466538422225435174,"fields":{"line":"write"}}

[akshayjshah]

In general, I'm reconsidering the implementation of AddCaller - managing an offset is a bit too error-prone and difficult to wrap. Finding the first stack frame that's outside the zap libraries (excluding _test files) is probably better, but we'll have to benchmark how much slower it is.

[prashantv]

I still think it'd be good to dynamically adjust the skip level so that wrappers outside of the core library can also be skipped. It'll probably also be more efficient since you can just check the specific level rather than getting the whole call stack.

[zhenkai]

I think efficiency is not a major concern here, as this hopefully should only be called at initialization time. (unless you need to initialize loggers at on demand?)

To me, the most important thing is that this should automatically figure out the caller, somehow, not depending on a specific skip value.

I'm not sure what prashantv meant by dynamically adjusting skip level, but if that's a number that the users have to set (by manually counting the stack level), it's pretty fragile. Code could be refactored and the level could easily be wrong.

[prashantv]

@zhenkai This is not something you could do at initialization time, but you would need to do on every log call, since the underlying logger does not know whether it's receiving a call directly, or from a wrapped logger. Since it has to be done on every single call, efficiency is extremely important.

By dynamically adjusting the skip level, I don't mean the user having to set anything manually. I'm talking about having the wrapped loggers call an API to increment the number of callers to skip.

[zhenkai]

Interesting. I thought it's only for initializing loggers, which is the case for us.

So wrapped loggers won't have to provide the number of levels to skip to this API? Otherwise, they'd still have to manage the numbers, although a bit easier as they're not managing the toal. Also, if you can make this call to the API a compile-time check, somehow, (they actually HAVE to call it), that would be great :)

[akshayjshah]

Closing as a duplicate of #40.