log/experimental_level #357

peterbourgon · 2016-09-06T16:24:53Z

Still need to get some more tests and benchmarks in, but this API feels usable.

At the callsite, things work like this.

import (
    "github.com/go-kit/kit/log"
    "github.com/go-kit/kit/log/experimental_level"
)

func foo(logger log.Logger) {
    level.Debug(logger).Log("foo", "bar")  // level=debug foo=bar
    level.Error(logger).Log("baz", "quux") // level=error baz=quux
}

The filtering comes in at construction time.

var logger log.Logger
logger = log.NewLogfmtLogger(os.Stderr)
logger = level.New(logger, level.Config{Allowed: level.AllowWarnAndAbove})
logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC)

The Config object allows precise control over the behavior when callers log without a level, or log with a disallowed level; see that struct for details. And while the level package includes default Debug, Info, Warn, and Error levels, the user is free to define their own level values, provide whatever wrappers they like to the constructors, and define their own helper functions. It's all pretty flat.

nussjustin · 2016-09-06T16:46:57Z

log/experimental_level/level.go

+type Config struct {
+	// Allowed enumerates the accepted log levels. If a log event is encountered
+	// with a LevelKey set to a value that isn't explicitly allowed, the event
+	// will be equelched, and ErrSquelched returned.


s/equelched/squelched/ ?

peterbourgon · 2016-09-06T17:14:05Z

$ go test -bench=. -benchmem
BenchmarkNopBaseline-4             2000000    621 ns/op   288 B/op    9 allocs/op
BenchmarkNopDisallowedLevel-4      2000000    674 ns/op   288 B/op    9 allocs/op
BenchmarkNopAllowedLevel-4         2000000    678 ns/op   288 B/op    9 allocs/op
BenchmarkJSONBaseline-4             500000   3186 ns/op   968 B/op   22 allocs/op
BenchmarkJSONDisallowedLevel-4     2000000    725 ns/op   288 B/op    9 allocs/op
BenchmarkJSONAllowedLevel-4         500000   3230 ns/op   968 B/op   22 allocs/op
BenchmarkLogfmtBaseline-4          1000000   1326 ns/op   288 B/op    9 allocs/op
BenchmarkLogfmtDisallowedLevel-4   2000000    671 ns/op   288 B/op    9 allocs/op
BenchmarkLogfmtAllowedLevel-4      1000000   1400 ns/op   288 B/op    9 allocs/op

A good start; could be better.

peterbourgon · 2016-09-06T17:21:09Z

Ahoy, @ChrisHines @jstordeur @nelz9999 — this PR represents my vision for leveled logging. To the best of my ability it abides the guidelines set forth in the package log README section about enhancements, though it's certainly possible that I've overlooked something. Thus I'd love some early feedback, in particular things you want to do that seem difficult or impossible with this API, and/or any concerns you have about allocations.

peterbourgon · 2016-09-06T17:26:22Z

Also cc: @AlmogBaku for your feedback, if you care to provide it :)

peterbourgon · 2016-09-06T17:32:30Z

Also cc: @seh for your feedback, if you care to provide it :)

ChrisHines · 2016-09-07T00:31:18Z

Comments from my first reading:

The default choice to squelch, without error, log events without a level key seems dangerous. I can imagine many frustrations when retrofitting an existing project with levels. Could you explain the rationale behind this choice a bit?
I am a little concerned about using global variables for LevelKey and *LevelValue. I realize that it enables the nice level.Debug(logger).Log() usage style, but I wonder if it will stand the test of time.
AllowAll, AllowDebugAndAbove, etc. are fragile. They will quietly break if not updated when one of ErrorLevelValue, WarnLevelValue, etc. are given new values.

nelz9999 · 2016-09-07T06:26:12Z

log/experimental_level/level_test.go

+	logger = log.NewContext(logger).With("caller", log.DefaultCaller)
+
+	level.Info(logger).Log("foo", "bar")
+	if want, have := `caller=level_test.go:134 level=info foo=bar`, strings.TrimSpace(buf.String()); want != have {


Oof, this looks brittle... If anyone adds/removes non-zero number of lines above this, the line number will get out of sync.

nelz9999 · 2016-09-07T06:44:05Z

In general, I really like this as an elegant way of eliding all the different concerns. Thank you!

I agree with @ChrisHines that defaulting to squelch non-"level" logs quietly is challenging. Do you think there would be negative impact on inverting AllowNoLevel so that it defaults to not squelching? (I.e. DisallowNoLevel...)

I think it would be possible to have levelKey be configurable by making a member var on the logger struct, initialized to the default in the New(...) function if the config doesn't have an override for "level".

peterbourgon · 2016-09-07T09:10:49Z

Thanks for the feedback! Exactly what I needed, thanks.

@ChrisHines

The default choice to squelch, without error, log events without a level key seems dangerous . . .

Yes—and yes to similar feedback from @nelz9999. Upon reflection, I agree. Updated.

I am a little concerned about using global variables for LevelKey and *LevelValue. I realize that it enables the nice level.Debug(logger).Log() usage style, but I wonder if it will stand the test of time.

It's true. I'd love to be able to do as @nelz9999 suggests and have the level key be part of the config struct. But, the UX of level.Debug(logger).Log is absolutely foundational to this proposal, and I can't think of a way to parameterize the level key in a way that preserves it. I'll keep thinking. For now I've made levelKey an unexported const, as in practice I can't think of many who would want to change it.

AllowAll, AllowDebugAndAbove, etc. are fragile. They will quietly break if not updated when one of ErrorLevelValue, WarnLevelValue, etc. are given new values.

Great point. I've also unexported and made const the various fooLevelValues, and changed the AllowFoo vars to functions. This makes the level value strings a bit more difficult to change—users will have to replace the whole value chain, so to speak—but in practice I think no one would actually do that, and it makes things safer, as you note.

@nelz9999

Oof, this looks brittle...

Yes! It is. But we've done similar things elsewhere in the project, and the nice thing is when it breaks you know exactly why :)

I'm considering if it might be better to have a default-allow, rather than default-deny policy. That would lead to enumerating a Disallowed (c.f. Allowed) set of levels. But I need to think on that a bit more.

Also considering if it might make sense to have some way to declare that all un-leveled log events should get a specified level. But that may have too-complex interactions with other decisions that are important for UX. Need to think there, too.

- Unexport level key and default level values - Migrate Allow vars to functions - By default, un-leveled log events are allowed

nelz9999 · 2016-09-07T09:42:51Z

So, one of the things I think I'm seeing in both the original levels package, and in this one, is that these "extensions" are all having trouble because they are trying to wrap their own configuration around a log.Context that they then have to delegate to in order to do it's actual logging.

But what if the log.Context had a way to store arbitrary values on it, kind of like the stdlib context.WithValue(...)? You could still use a package level function at construction time, then the logger that is handed around would remain the vehicle for all state, and then do the same level.Debug(logger).Log at the callsite as you have here.

I know this impacts a higher package, but it seems like a very flexible way of allowing arbitrary extensions built on top of the log package.

AlmogBaku · 2016-09-07T12:17:59Z

Hi,
TBH I have a little hesitations about the API, which doesn't looks so standard:

level.Debug(logger).Log("foo", "bar")
//Instead of standard API like
logger.Debug("foo", "bar")

logger = level.New(logger, level.Config{Allowed: level.AllowWarnAndAbove})
//Instead of
logger = level.New(logger, level.Config{Level: level.DEBUG})

I find it a little bit confusing from DX, since the majority of the loggers from any language I know looks pretty similar..

Other Notes

I liked the idea that you can specify an array of allowed verbosity levels, however it might be redundant in case you want to use "hierarchy of logs", also it introduced a complexer decision making based on iterating the log level String over the "allowed logs"
I'm not sure why when log is not allowed it returns an error.. it's just should be ignored. That's may confuse me as an user
I believe log-level should be int value and then to be translated into a string. This way you can do mathematical equation which is quite effective

Bottom line

Although we have a problem with implementing the log-levels as an implementation of Logger(as specified in #269), I believe we should try to create an api which is similar to what the standards in the industry, and not reinvent the wheel, but to find other workaround to the issues raised. I think DX is extremely important on this case.

peterbourgon · 2016-09-07T12:30:32Z

@AlmogBaku logger.Debug implies we'd be changing the Logger interface, which is something I think we all want to avoid. So there will be some contortion involved—but I hear your feedback that this may be a bit too awkward. Thanks for that and I'll dwell on it.

peterbourgon · 2016-09-07T12:31:27Z

I'm going to merge this as-is so a user can get sort of alpha-style access to it, and I'll start another issue to track iterations, enhancements, or potentially deleting it. Thanks again to everyone!

AlmogBaku · 2016-09-07T12:34:58Z

Sorry, for that 😞
But thanks for the PR and keep the awesome work dude!

On Wednesday, 7 September 2016, Peter Bourgon [email protected]
wrote:

I'm going to merge this as-is so a user can get sort of alpha-style access
to it, and I'll start another issue to track iterations, enhancements, or
potentially deleting it. Thanks again to everyone!

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#357 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAGCphwdgm4Dvq_atm_FbsNTq80f1fq8ks5qnq6tgaJpZM4J2Bs-
.

http://www.rimoto.net/

www.rimoto.com http://www.rimoto.net/

Almog Baku

CTO & Cofounder *
Mobile: +972.50.2288.744
Social: * http://www.facebook.com/AlmogBaku
http://www.linkedin.com/in/almogbaku

jstordeur · 2016-09-07T13:07:02Z

log/experimental_level/level.go

+			continue
+		}
+		hasLevel = true
+		if i >= len(keyvals) {


What is this check for? Unless I'm missing something I believe this is always false.

seh · 2016-10-02T22:08:36Z

Please see #368 for an alternate approach.

log/experimental_level: initial functionality

09ecc88

nussjustin reviewed Sep 6, 2016
View reviewed changes

peterbourgon added 4 commits September 6, 2016 19:11

log: add nop_logger_test for benchmark completeness

7388193

log/experimental_level: add basic valuer tests

b8b37a1

log/experimental_level: add basic benchmarks

2e8df44

log/experimental_level: fix typo (thanks @nuss-justin!)

4a563ef

peterbourgon mentioned this pull request Sep 6, 2016

Candidate for log level filtering #349

Closed

nelz9999 reviewed Sep 7, 2016
View reviewed changes

log/experimental_level: package documentation

78f29dc

log/experimental_level: review feedback

6cabf8e

- Unexport level key and default level values - Migrate Allow vars to functions - By default, un-leveled log events are allowed

peterbourgon force-pushed the experimental-levels branch from d4a3c9d to 6cabf8e Compare September 7, 2016 09:11

peterbourgon changed the title ~~[WIP] log/experimental_level~~ log/experimental_level Sep 7, 2016

peterbourgon merged commit d3b614b into master Sep 7, 2016

peterbourgon deleted the experimental-levels branch September 7, 2016 12:40

jstordeur reviewed Sep 7, 2016
View reviewed changes

seh mentioned this pull request Oct 2, 2016

log/alt_experimental_level: concept demonstration #368

Closed

peterbourgon mentioned this pull request Oct 20, 2016

Add filtered leveled logging and error promotion #252

Closed

seh mentioned this pull request Jan 20, 2017

log/alt_experimental_level: concept demonstration #444

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log/experimental_level #357

log/experimental_level #357

peterbourgon commented Sep 6, 2016 •

edited

Loading

nussjustin Sep 6, 2016

peterbourgon commented Sep 6, 2016 •

edited

Loading

peterbourgon commented Sep 6, 2016

peterbourgon commented Sep 6, 2016 •

edited

Loading

peterbourgon commented Sep 6, 2016 •

edited

Loading

ChrisHines commented Sep 7, 2016

nelz9999 Sep 7, 2016

nelz9999 commented Sep 7, 2016

peterbourgon commented Sep 7, 2016

nelz9999 commented Sep 7, 2016

AlmogBaku commented Sep 7, 2016 •

edited

Loading

peterbourgon commented Sep 7, 2016

peterbourgon commented Sep 7, 2016

AlmogBaku commented Sep 7, 2016

jstordeur Sep 7, 2016

seh commented Oct 2, 2016

log/experimental_level #357

log/experimental_level #357

Conversation

peterbourgon commented Sep 6, 2016 • edited Loading

nussjustin Sep 6, 2016

Choose a reason for hiding this comment

peterbourgon commented Sep 6, 2016 • edited Loading

peterbourgon commented Sep 6, 2016

peterbourgon commented Sep 6, 2016 • edited Loading

peterbourgon commented Sep 6, 2016 • edited Loading

ChrisHines commented Sep 7, 2016

nelz9999 Sep 7, 2016

Choose a reason for hiding this comment

nelz9999 commented Sep 7, 2016

peterbourgon commented Sep 7, 2016

nelz9999 commented Sep 7, 2016

AlmogBaku commented Sep 7, 2016 • edited Loading

Other Notes

Bottom line

peterbourgon commented Sep 7, 2016

peterbourgon commented Sep 7, 2016

AlmogBaku commented Sep 7, 2016

jstordeur Sep 7, 2016

Choose a reason for hiding this comment

seh commented Oct 2, 2016

peterbourgon commented Sep 6, 2016 •

edited

Loading

peterbourgon commented Sep 6, 2016 •

edited

Loading

peterbourgon commented Sep 6, 2016 •

edited

Loading

peterbourgon commented Sep 6, 2016 •

edited

Loading

AlmogBaku commented Sep 7, 2016 •

edited

Loading