gournal icon indicating copy to clipboard operation
gournal copied to clipboard

Example 03 defines an incorrect FieldsKey func

Open germanvazquez-rfk opened this issue 9 years ago • 13 comments

I think that "main()" function in "examples/03" needs to be fixed.

Check this line https://github.com/codedellemc/gournal/blob/master/examples/03/main.go#L48. Fourth param args in func(ctx gournal.Context, lvl gournal.Level, fields map[string]interface{}, args ...interface{}) ... shall be of type string and not ...interface{}.

BTW, is this project still active?

germanvazquez-rfk avatar Nov 17 '16 15:11 germanvazquez-rfk

Hi @germanvazquez-rfk,

Thank you for the note. Yes, it's still active. I just haven't had an opportunity to work on it of late. What are your thoughts on it as a whole?

akutz avatar Nov 23 '16 17:11 akutz

I started using it in a project. I am totally aligned with having the context within each log call. In fact I required the contest because I am instrumenting the code and need request/thread-local info to instrument the log entries. Not sure if that may be something that others wont use/need. Is this your personal project or someway backed by dell emc?

germanvazquez-rfk avatar Nov 23 '16 18:11 germanvazquez-rfk

Hi @germanvazquez-rfk,

It is my personal project backed by Dell EMC :) It is used partially in libStorage and REX-Ray, and will soon take the place of logrus as the primary go-to for logging in those projects. Whether I continue to use logrus as the actual behind-the-scenes framework remains to be seen. Zap seems a little faster. The beauty is that with Gournal I can replace it without worry.

I needed thread-scoped logging, and absent that, the context made sense. I started doing that with a custom context in libStorage and realized I could move that functionality into a separate library. I spent quite a bit of time optimizing it to make it as efficient as possible. The one comment I've had is why retain the WithField and WithFields notation, and honestly, because I like it. While the stdlib logger doesn't embrace structured logging, most of the popular Go logging frameworks do in some form or fashion. I wasn't originally a fan, but grew to like it.

My primary goals are to:

  1. Properly and efficiently implement hierarchical logging scopes/levels via the context
  2. Make sure nested errors are properly unwrapped and laid out when logging an error. This ties into my Goof project, but I am thinking about how to simplify that. Essentially too much important information is omitted when errors are "rethrown" or wrapped. I want Gournal to play a part in making sure that is no longer the case.

akutz avatar Nov 23 '16 18:11 akutz

great to hear! I am using also "WithField" a lot. I don't very much like "WithFields" cause it is too verbose to create the map every time I need to log multiple fields so I use, but just a matter of personal taste.

germanvazquez-rfk avatar Nov 23 '16 18:11 germanvazquez-rfk

Hi @germanvazquez-rfk,

Let me show you when WithFields works well. See the Login function for libStorage's EBS storage driver. Note the map accumulates different fields dependending on different situations. Then the map can be used to do multiple log emissions as the function progresses.

akutz avatar Nov 23 '16 18:11 akutz

I see. You use it when you need to collect info before calling the log.Info. You are not using gournal there, arent you?

germanvazquez-rfk avatar Nov 23 '16 18:11 germanvazquez-rfk

No, I'm not. I'm using the libStorage context type on which much of Gournal is modeled. I haven't switched all of that out for Gournal in libStorage yet. The one thing that Gournal doesn't yet do as part of its std package is this from libStoage.

Essentially this file enables the context's implementation of the logger to have special keys that are always logged, with every log entry. See this log file as an example.

The package even allows for the registration of custom keys to be used.

I want to make this part of Gournal as well.

akutz avatar Nov 23 '16 18:11 akutz

Hi @germanvazquez-rfk,

May I ask in which project you are employing Gournal? Just curious. I have a local branch I haven't pushed that actually reduces the overhead to zero :) Someone else using the project is enough of a push to make me get off my butt and get that branch tested and merged.

akutz avatar Nov 23 '16 18:11 akutz

But you are not changing the gournal.Entry interface no? It will still receive as first parameter context.context? I ask because I am using that interface and I am instrumenting the code when a request comes by passing a instrumentation function with "gournal.FieldsKey()". That functioon extracts request info from the context and log custom fields automatically. I intend to keep things that way.

germanvazquez-rfk avatar Nov 23 '16 18:11 germanvazquez-rfk

not an open source project

germanvazquez-rfk avatar Nov 23 '16 18:11 germanvazquez-rfk

Oh no, the interfaces are staying the same. I just realized what was causing my overhead.

akutz avatar Nov 23 '16 18:11 akutz

Well, crap, it does change some. Take a look at the branch diff I just pushed. It's not even a PR yet.

Basically anywhere the interface{} type is used there is overhead. This includes using ...interface{} variadic for log functions. A few notes on the changes:

All variations of a level's log function are condensed. No more Infoln and Infof and Info. Just Info. I may add these others back though. I condensed them primarily for testing.

However, the one thing I did do was change this signature:

Info(ctx context.Context, args ...interface{})

to

Info(ctx context.Context, msg string, args ...interface{})

The reason being that making the msg a part of the variadic array incurred a malloc, and Go's memory allocation is actually not very fast. This way a message can be passed as just a message.

The other big deal is that the Key constants are no longer constants. You must use the GetContextKey(k Key) interface{} function to return the key you wish. For example, to get or set the log level you'd use context.WithValue(gournal.GetContextKey(gournal.LevelKey),.... Why? Because constants stored in a Golang context also incur a malloc penalty when placed on the heap due to the use of the interface{} param type with the way a Context type works. I did a lot of testing to figure this out, and I am going to end up recommending to Google that they implement constant pointers for this reason. Otherwise unless you want a lot of inefficiency, you should not use constants for context keys unless you place them all on the heap once and use those references so that they're not placed on the heap every time you set or get a value from the context.

akutz avatar Nov 23 '16 18:11 akutz

I see. Those are cool additions, having 0 overhead and memory allocations is excellent. Anyway, the change in the signature for Info(ctx context.Context, msg string, args ...interface{}) is harmless, it wont break current code, cause I am using Info() always with at least 2 params, currently.

On the other hand, did you check issue #19 ? I think that when passing nil context to sendToAppender() you should use gournal. Defaultcontext and not the private defaultContext, no? That way I can change the global, public Defaultcontext to my needs and the appender function will use that when passing a nil context to Info() (I guess :) )

germanvazquez-rfk avatar Nov 23 '16 20:11 germanvazquez-rfk