Add SugaredLogger #185

akshayjshah · 2016-11-21T17:45:08Z

This PR carries forward the work that @akabos did in #147. Once complete, this will resolve #138.

Relevant benchmarks for logrus, the regular zap logger, and the sugared logger:

BenchmarkLogrusAddingFields-4                         	  100000	     10219 ns/op	    5726 B/op	      77 allocs/op
BenchmarkLogrusWithAccumulatedContext-4               	  200000	      7760 ns/op	    3919 B/op	      61 allocs/op
BenchmarkLogrusWithoutFields-4                        	 1000000	      2317 ns/op	    1321 B/op	      25 allocs/op

BenchmarkZapAddingFields-4                            	 1000000	      1287 ns/op	     768 B/op	       4 allocs/op
BenchmarkZapWithAccumulatedContext-4                  	 5000000	       341 ns/op	      64 B/op	       2 allocs/op
BenchmarkZapWithoutFields-4                           	 5000000	       363 ns/op	      64 B/op	       2 allocs/op

BenchmarkZapSugarAddingFields-4                       	  500000	      4160 ns/op	    1443 B/op	      36 allocs/op
BenchmarkZapSugarWithAccumulatedContext-4             	 3000000	       408 ns/op	      80 B/op	       3 allocs/op
BenchmarkZapSugarWithoutFields-4                      	 5000000	       400 ns/op	      80 B/op	       3 allocs/op

By these benchmarks, we're doing pretty well - the sugared logger is similar to logrus in developer ergonomics, but is much, much faster and lower-allocation. However, the sugared field-adding API does introduce quite a bit of allocation overhead.

jcorbin · 2016-11-21T18:51:39Z

This is great, I think it may even deduplicate effort between uberfx and other ongoing internal work.

My only thoughts on a high level about its API are: it seems like we have strictly two things going on here:

adding sugared methods for adding fields in a less verbose way
providing it a way back to dynamic message string building

I'd really like to see us keep those concerns split (e.g.SugaredLogger embedded by FormattedLogger?) My primary concerns are around making it clear to other core zap pieces when they can and cannot assume that message is a manageable cardinality (e.g. the sampler would at worst degrade to no weighting, but we could do something even more graceful like degrade to an LRU counts table).

anuptalwalkar · 2016-11-22T18:40:12Z

@jcorbin I agree with not duplicating this effort. UberFx's current interface is conforming with SugarLogger. Once this PR is ready for merge, My plan is to cleanup UberFx log and embed sugar logger. That way we will get unified experience whether we are using UberFx or zap.

mikluko · 2016-12-24T11:01:11Z

Any progress on that? Is there anything I can assist with?

jcorbin

This is okay and all, my skepticism just dies hard ;-)

jcorbin · 2016-11-21T18:45:42Z

sugar.go

+// WithStack adds a complete stack trace to the logger's context, using the key
+// "stacktrace".
+func (s *SugaredLogger) WithStack() *SugaredLogger {
+	return &SugaredLogger{core: s.core.With(Stack())}


As mentioned offline (followingf WIP brain dump in #183) I think that we can do better wrt caller(s) across all of zap. For this method, if everything works out, I'd like to shift it to:

// WithCallers adds a complete structured stack trace to a logger's context, using the // key "callers". func (s *SugaredLogger) WithCallers() *SugaredLogger { return &SugaredLogger{core: s.core.With(Callers()) }

jcorbin · 2017-01-13T19:59:15Z

sugar.go

+
+// Desugar unwraps a SugaredLogger, exposing the original Logger.
+func Desugar(s *SugaredLogger) Logger {
+	// TODO: decrement caller skip.


We can't naively just mutate a field on a struct tho if/when Logger becomes *Logger; I think we have to "return a copy with a lower skip" as a first approximation. As an optimization then, we may need to hold two *Logger: original, and mine (the one we actually use here); we then either return the original, or fault one in with a lower level of skip.

A corollary of all this applies to the logger passed into Sugar above: we can't just mutate, because it still needs to be correct for the caller to use directly.

TODO is to use whatever WithOptions thing we end up settling on.

jcorbin · 2017-01-13T20:01:10Z

sugar.go

+//     Object("user", User{name: "alice"}),
+//   )
+func (s *SugaredLogger) With(args ...interface{}) *SugaredLogger {
+	return &SugaredLogger{core: s.core.With(sweetenFields(args, s.core)...)}


Pulling my thread along about original, mine *Logger: I guess then that With should only with mine and set s.original = nil, leaving it up to an eventual desugar to fault in if someone wants to unwrap a contextified sugared logger.

Also, I feel that this method should just be "sugar" for WithFields: return s.WithFields(sweetenFields(args, s.core)...)

Sure, that's reasonable.

jcorbin · 2017-01-13T20:03:58Z

sugar.go

+	}
+}
+
+func sweetenFields(args []interface{}, errLogger Logger) []zapcore.Field {


Hmm, this is so close to being a more useful func ZipAny(...interface{}) ([]zapcore.Field, error).

Towards a counterfactual then, how bad would it be to not have this sugaredlogger, when logging sites could be:

log.Info("stuff", zap.ZipAny( "this", 2, "andThen", 3, "andFurthermore", map[string]string{"cantStop": "meNow!"}, )...) log.Debug(fmt.Sprintf("I just %s", "can't stop myself"))

In the real "approved" case, there's only one "zap" in play, and in the regrettable case, they clearly know what they've bought into...

(this counterfactual up against my prior "how really does this (un)wrapping work" meme)

Happy to consider ZipAny later on; in general, though, I think that there's an important place for a logger that makes these semi-magical behaviors the default. In contexts where performance isn't a primary concern, I'd like to have as little noise as possible around logging sites.

…ect field

The sugared logger benchmarks were artificially good because we weren't logging anything :/

prashantv

I really don't like the idea of messages and field names be interface{}.

prashantv · 2017-01-13T23:39:45Z

sugar.go

+// Debug logs a message and some key-value pairs at DebugLevel. Keys and values
+// are treated as they are in the With method.
+func (s *SugaredLogger) Debug(msg interface{}, keysAndValues ...interface{}) {
+	if ce := s.core.Check(DebugLevel, sweetenMsg(msg)); ce != nil {


Why duplicate these check + call to Write for each level? A single helper (that will probably be inlined) should clean up this implementation:

func (s *SugaredLogger) log(level zap.Level, msg interface{}, keysAndValues []interface{})

That breaks the caller skipping.

The caller skipping should allow skipping n frames, not just one. It seems a little arbitrary to say a logger can only skip a single call frame.

The problem isn't the number of frames skipped, it's the incongruence between the number of frames skipped when calling CheckedEntry.Write and logger.Info. Putting another layer of indirection in here dries up the logger, but prevents us from exposing a checking API. I'd intended to expose such an API; until that happens, I'll add the extra indirection back in.

Ahh, that makes sense. One other option is to have the sugar logger maintain 2 loggers internally, one with +2 skip, and one with +1 skip, and have the checking API use the one with less skip.

Definitely not ideal though. Considering this and @jcorbin's comment on #247 (review), I wonder if per-call site skip makes sense to consider.

prashantv · 2017-01-13T23:40:59Z

sugar.go

+
+// Debug logs a message and some key-value pairs at DebugLevel. Keys and values
+// are treated as they are in the With method.
+func (s *SugaredLogger) Debug(msg interface{}, keysAndValues ...interface{}) {


Why is msg an interface{}

Because we don't have sum types?

prashantv · 2017-01-13T23:46:31Z

sugar.go

+		return str
+	}
+	return fmt.Sprint(msg)
+}


I really dislike this "message is an interface" pattern.

You eat an extra allocation on every single log converting the string to an interface{}

Apart from error, I don't see many use cases for supporting arbitrary types as messages

No other logging library I know allows the message to be an interface{}. Either it only takes objects as interface{} where all objects are treated the same, or it takes a message string and some set of key-value pairs (possibly using interface{}).

In order:

That's true. However, if you're using the sugared logger, I don't think a single allocation is breaking the bank.

fmt.Stringer is the other obvious interface we should support, but yes, that's probably it. logger.Error(err) is so common that this seems worthwhile to me. This also makes debug-level logging much easier in development, since you can easily log arbitrary structs.

Can you clarify this last point a bit? Many Go loggers expect the message(s) to be interface{}: logrus, log15, and go-kit/kit/log all do this. Those libraries make different choices about how to represent key-value pairs; go-kit models them as ...interface{} too.

I agree that a single allocation isn't a huge deal, but it is another drawback of this approach.

I'm not sure I agree that a Stringer is useful. Can you provide use cases from real world code where users are calling .String() and passing it as a message right now?

There is no single message that is passed as a interface{}.

logrus supports a list of interface{} that it then puts together, which is more similar to the standard library log package. This pattern is very different to the SugaredLogger, since a log line like log.Info("dial failed", hostname, err) will just append everything together with logrus or log, but with the SugaredLogger, it will treat hostname as a key. Considering how differently these work, I'm not sure it's a good comparison.

log15 expects messages to be strings, see the Logger type.

The go-kit/log Logger doesn't even take a message, it only takes key-value pairs.

Excellent - glad we agree that, in this context, the perf impact of a single interface{} conversion isn't something to be concerned about.

Appeals to data are great. Typically, the onus of proof falls on the minority position - in this case, that's the argument for compile-time safety at log sites. Of course, any quantification of this is difficult because the problem is circular: developers don't explicitly stringify their messages because they overwhelmingly choose logging libraries that do so for them.

It seems to me that the strong consensus in logging, both in Go and in other languages, is to sacrifice some degree of compile-time type-checking for convenience. This is why Sprint-style interfaces are so common in Go. After your (accurate) correction regarding the log15 API, I know of three libraries that have strongly-typed string arguments as messages - log15, logxi, and apex/log. The standard library, glog, logrus, go-kit, go-logging, xlog, seelog, go-playground/log, sasbury/logging, logsip, and spacelog are all built around loosely-typed APIs. I'm quite confident that the majority of libraries I don't know about are also loosely-typed. They're loosely-typed because it's relatively cheap to accept interface{}s instead of strings, it's convenient, and the consequences of passing un-printable or otherwise problematic values are not particularly dire.

prashantv · 2017-01-13T23:47:31Z

field.go

+// necessary.
+func Any(key string, value interface{}) zapcore.Field {
+	switch val := value.(type) {
+	case zapcore.ObjectMarshaler:


Why no ArrayMarshaler here?

Just on oversight, since I was working on this before that branch landed.

prashantv · 2017-01-13T23:49:03Z

field.go

+		return Uintptr(key, val)
+	case string:
+		return String(key, val)
+	case error:


suggest putting this next to fmt.Stringer to group interfaces together

prashantv · 2017-01-13T23:50:15Z

sugar.go

+	"go.uber.org/zap/zapcore"
+)
+
+const oddNumberErrMsg = "Passed an odd number of keys and values to SugaredLogger, ignoring last."


nit: underscore prefix for unexported global which we seem to be using elsewhere in zap.

prashantv · 2017-01-13T23:51:34Z

sugar.go

+	}
+}
+
+func sweetenFields(args []interface{}, errLogger Logger) []zapcore.Field {


Why is this function not on *Sugar. The only field in Sugar is a logger, and this function takes that as an argument.

Sure, can move it.

prashantv · 2017-01-13T23:52:16Z

sugar.go

+
+	fields := make([]zapcore.Field, len(args)/2)
+	for i := range fields {
+		key := sweetenMsg(args[2*i])


I think we should enforce that keys are strings.

I've had a number of very long discussions about this, and I'm generally convinced that there's utility here. We already have a logger that's type-safe, low-allocation, and fast. For the sugared logger, I think there's value in supporting error and fmt.Stringer in addition to strings. Given the limitations of the type system and reasonable APIs, eating an allocation and accepting interface{} seems like a reasonable tradeoff.

akshayjshah · 2017-01-14T01:01:38Z

In summary: we've had this discussion with a number of people, in a number of different contexts. For the sugared logger, I think that the improved ergonomics of accepting interface{} where possible are worth the cost. This makes logging errors in production and arbitrary things in development much simpler.

The other reasonable option is logger.Info(string, map[string]interface{}), possibly with zap.Map or zap.SugaredFields offered as a type alias for map[string]interface{}. I find the wordiness of this API and the intrusiveness of the zap package quite unappealing.

An intermediate position is logger.Error(string, keysAndVals ...interface{}). I'm not wholly opposed to this, but I do really hate logger.Error(err.Error()) all over the place.

We can, of course, always just offer multiple options. There's not much code required.

Keep the sugared API wholly separate from the unsugared API: don't expose a way to add plan `zapcore.Field`s to the context, and don't plan to expose a checked entry API. This cleans up the sugared logger implementation. Since the sugared logger is a concrete type and not an interface, we can always add these curlicues back later.

prashantv · 2017-01-17T16:36:16Z

An intermediate position is logger.Error(string, keysAndVals ...interface{}). I'm not wholly opposed to this, but I do really hate logger.Error(err.Error()) all over the place.

Yeah this is the approach I'd prefer. Agreed that logger.Error(err.Error()) is not great, but it's something that the compiler will complain about, and would be better done as logger.Error("some context", "error", err).

Supporting fmt.Stringer for a message doesn't seem that useful, and I don't think anything other than a string makes sense for field keys.

Using interface{} has a few issues:

messages can now be nil, which seems like a bug.
harder to catch places where the message is accidentally replaced with some other random object (e.g., a bad merge)

Are there may other logging libraries that accept the equivalent of interface{} for messages and keys and stringify it? The only ones I can think of accept interface{} when accepting a list of objects, and they're either all merged using fmt.Sprint or use fmt.Sprintf with a template.

E.g., This logger looks very similar to log15, which allows passing context as ...interface{}, but it expects messages to be strings, and that field keys are strings:
https://github.com/inconshreveable/log15/blob/master/format.go#L146

I don't think the value of supporting automatic conversion of any type to strings is worth the potential for issues that the compiler can't help with.

ansel1 · 2017-01-17T22:25:53Z

logxi functions look like Info(s string, args ...interface{}), and generally require args to be balanced pairs of strings/interface{}. But it handles the special case of an args with a length of 1 (a single logged "thing" with no key). It's a compromise somewhere between Info(err) and Info("error occurred", "error", err):

Info("error occurred", err)  // or...
Info("user struct", user)

The key for a "bare" arg defaults to an underscore, so the entry ends up looking like:

Error occurred     _=error message

akshayjshah · 2017-01-18T00:43:57Z

To me, the point under debate here is how type-safe it's necessary for the sugared logger to be, and how much we're willing to sacrifice in ergonomics for that safety. My broad point, which is firmly borne out by the spectrum of existing logging libraries, is that type safety just isn't a priority for typical logging APIs. In the absolute worst case, we'll end up logging a message with a handful of oddly-named fields, which is certainly not the end of the world.

Given that, I don't see why we wouldn't make a best effort to support a wide variety of types. Errors are the most obvious case: while it's obviously feasible for users to call Error() themselves, it's needlessly irritating. This is the same reason logging libraries provide formatting helpers, instead of forcing users to call fmt.Sprintf directly.

The same is true regarding field names. Sure, we can log a DPanic when we encounter a non-string key, but why wouldn't we then make a best effort to also something useful? We're guaranteed that we won't affect any other fields, so I don't see the harm. It's certainly better than dropping a field.

It's also worth remembering that we already have a fully type-safe, performance-optimized logger. Anyone who cares deeply about log site correctness or shaving off a single allocation here or there will already be using that logger. I plan on using that logger most of the time. The sugared logger is explicitly intended to provide ergonomics and ease of use. Since the effect of passing problematic messages or keys is (a) minimal, and (b) easily caught in development with DPanic, I don't find the safety concerns compelling.

Let's discuss this in person and come to a conclusion tomorrow.

prashantv · 2017-01-18T08:21:23Z

Your main argument for supporting message as an interface{} is that a large number of existing loggers allow it. Almost every library you listed has a significant difference from SugaredLogger, they accept ...interface{} and stringify all objects and output a space-separated list, for all of the following: glog, logrus, go-logging, xlog, seelog, go-playground/log, sasburry/logging, logsip, spacelog

There is no special "message", or "field key" positional argument in any these interfaces, all arguments are treated exactly the same. It's fine to reorder the objects, and still have valid output. The same is definitely not true for the SugaredLogger interface. Given the significant difference in how arguments are handled, I don't think it makes any sense to use the existing interfaces as support for the "message should be interface{}" argument. The existing interfaces support the idea that all ...interface{} arguments should be treated the same.

Most of the logging libraries that do treat messages and key names separately use a string on the other hand (log15, logxi, apex/log, go-playground/log.

The go-kit logger treats keys and values in a similar way to SugaredLogger, but it also doesn't have the concept of a message.

My broad point, which is firmly borne out by the spectrum of existing logging libraries, is that type safety just isn't a priority for typical logging APIs. In the absolute worst case, we'll end up logging a message with a handful of oddly-named fields, which is certainly not the end of the world.

Structured logging is also not a priority based on existing libraries and existing code. However, the API we're debating is intended for structured logging, and this interface is more error-prone for structured logging. Existing logging library interfaces are not error-prone for their use case of logging a list of objects.

akshayjshah · 2017-01-18T16:16:14Z

As I said earlier, I don't think further back-and-forth in these comments is helpful. Let's discuss this in person.

Compromise on the type of the message: for the context-adding methods, accept only strings, but also provide Sprint-style methods that take ...interface{}.

prashantv

Looks good, I was worried about having too many methods, but the separation is definitely growing on me ("Just log all these things", "Format these", and "I want structure")

This was referenced Nov 21, 2016

Add a slightly slower, but less verbose, logger #147

Closed

Formatted logger uber-go/fx#73

Closed

akshayjshah changed the base branch from master to dev January 12, 2017 01:18

akshayjshah force-pushed the sugar branch from f4c0803 to 87b4e9f Compare January 13, 2017 00:54

akshayjshah requested a review from jcorbin January 13, 2017 01:03

akshayjshah added this to the 1.0.0 milestone Jan 13, 2017

jcorbin approved these changes Jan 13, 2017

View reviewed changes

mikluko added 20 commits January 13, 2017 15:33

Refs: #138

ccd2c79

added benchmark

2f71959

improved test coverage

f83f8a7

improved test coverage even more

d19b6d2

accept error as the first of variadic arguments

3e840ad

cleanup

e05c023

improved coverage

f2a8f56

mirrored relevant core logger benchmarks

9c9b46b

use CheckedMessage to cut off expensive argument parsing

73a65b2

used another form of type switch

859883a

fixed typo

f869f0d

getSugarFields errors are logged rather then returned

3786a4a

added support for Marshaler field, changed fallback from error to obj…

276f677

…ect field

pre-allocate fields slice

79c05a6

made test to fail if Object field is used in place of Marshaler

a0a3ee6

Removed LogMarshaler handling

7bb19f1

added some benchamrk helpers to reduce repeats

ef67c88

updated comments

3311b28

handle errors same way core logger does

3cc2db3

relay DFatal directly to core logger

40bb388

mikluko and others added 7 commits January 13, 2017 15:33

benchmark fix

6e41219

WIP, addressing comments on @akabos's PR

a5a3dac

Finish sugared logger, update tests & benchmarks

55b8718

Update the benchmarks

96da776

Fix benchmarks

ceba454

The sugared logger benchmarks were artificially good because we weren't logging anything :/

Add test coverage for zap.Any

3c9b89e

With should dispatch to WithFields

c4c498f

prashantv requested changes Jan 13, 2017

View reviewed changes

Update to use internal observer package

1e2740d

akshayjshah force-pushed the sugar branch from 2706003 to 1e2740d Compare January 13, 2017 23:54

akshayjshah force-pushed the sugar branch from 573ac71 to 12345bd Compare January 14, 2017 01:10

Some CR

2698eca

akshayjshah force-pushed the sugar branch from 12345bd to 2698eca Compare January 14, 2017 01:11

akshayjshah mentioned this pull request Jan 16, 2017

Alternate, map-based sugared logger #247

Closed

akshayjshah force-pushed the sugar branch 2 times, most recently from c1aa84b to 2482f20 Compare January 18, 2017 23:31

Compromise on message type

9f66b60

Compromise on the type of the message: for the context-adding methods, accept only strings, but also provide Sprint-style methods that take ...interface{}.

akshayjshah force-pushed the sugar branch from 84cde21 to 9f66b60 Compare January 18, 2017 23:49

prashantv approved these changes Jan 19, 2017

View reviewed changes

akshayjshah merged commit 64245ad into dev Jan 19, 2017

akshayjshah deleted the sugar branch January 19, 2017 20:56

Add SugaredLogger #185

Add SugaredLogger #185

Conversation

akshayjshah commented Nov 21, 2016 • edited Loading

jcorbin commented Nov 21, 2016

anuptalwalkar commented Nov 22, 2016

mikluko commented Dec 24, 2016

jcorbin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prashantv left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah Jan 14, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah commented Jan 14, 2017 • edited Loading

prashantv commented Jan 17, 2017

ansel1 commented Jan 17, 2017

akshayjshah commented Jan 18, 2017

prashantv commented Jan 18, 2017

akshayjshah commented Jan 18, 2017

prashantv left a comment

Choose a reason for hiding this comment

akshayjshah commented Nov 21, 2016 •

edited

Loading

akshayjshah Jan 14, 2017 •

edited

Loading

akshayjshah commented Jan 14, 2017 •

edited

Loading