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

mikluko · 2016-09-22T15:11:41Z

Benchmark10FieldsSugar-8     1000000          1365 ns/op        2554 B/op         26 allocs/op
Benchmark10Fields-8          2000000           597 ns/op         642 B/op          1 allocs/op

This sugar implementation is twice as slow if compared to core, but still twice as fast if compared to nearest competition.

billf

quick, non-authoritative review.

billf · 2016-09-22T18:43:26Z

sugar_bench_test.go

@@ -0,0 +1,54 @@
+// Copyright (c) 2016 Uber Technologies, Inc.


belongs in benchmarks/, yes?

All your points about benchmarks are absolutely valid. But my intention for this file was to have means of comparison between core logger and sugared one. So I basically mirrored Benchmark10Fields from logger_test_bench.go.

billf · 2016-09-22T18:44:55Z

sugar_bench_test.go

+	})
+}
+
+func Benchmark10FieldsSugar(b *testing.B) {


there should be three benchmarks here, BenchmarkSugarAddingFields, BenchmarkSugarAccumulatedContext, and BenchmarkSugarWithoutFields

billf · 2016-09-22T18:46:02Z

sugar_bench_test.go

+func Benchmark10FieldsSugar(b *testing.B) {
+	withBenchedSugar(b, func(log Sugar) {
+		log.Info("Ten fields, passed at the log site.",
+			"one", 1,


add a variety of types here, see the other benchmarks,
e.g.

"int", 1, "int64", int64(1), "float", 3.0, "string", "four!", "bool", true, "time", time.Unix(0, 0), "error", errExample.Error(), "duration", time.Second, "user-defined type", _jane, "another string", "done!",

billf · 2016-09-22T19:04:05Z

sugar.go

+				fields = append(fields, Duration(key, value.(time.Duration)))
+			case fmt.Stringer:
+				fields = append(fields, Stringer(key, value.(fmt.Stringer)))
+			default:


this is missing support for the error type.

in the existing zap logger, logging an error writes a key named "error". with the field count being used here, we have to decide if we want to support:

sugar.With("k1", 42, errors.New("this automatically goes into 'error'))`

or

sugar.With("k1", errors.New("nothing automatic"), "k2", errors.New("field is an errorType still"))

I suggest sugar logger should accept optional error value as the first of variadic arguments. E.g.:

sugar.Warn("message", errors.New("this is a error"), "a", "b")

{"level":"warn","msg":"message","err":"this is a error","a":"b"}

Motivation behind my suggestion is that having more then one errors in single log message is probably pretty rare requirement which don't need to be covered by syntax sugar.

(amended after looking more closely)

I'd prefer not to do this, since ~~the common (non-error) case will then require passing a nil~~ it makes our treatment of the first of the variadic arguments a bit too magical.

I'd prefer an API in which callers need to pass both the key and the value for errors: sugar.With("error", err). We'll need to add a case like this:

case error: fields = append(fields, String(key, value.(error).Error()))

I missed this earlier, but it seems like both @akshayjshah and I think we should remove the first variadic argument can be error.

As for the checking the case error, I'd consider only allowing that for a field named "error", just in case someone wants to log a type that happens to implement error but they acutally want the object logged.

billf · 2016-09-22T19:05:24Z

sugar.go

+
+// Log ...
+func (s *sugar) Log(lvl Level, msg string, args ...interface{}) error {
+	fields, err := getSugarFields(args...)


since this may be an expensive operation due to reflection and, in some cases, calling receivers on arguments passed in, this should check to see if the log level is valid before calling getSugarFields

Perfectly valid point!

akshayjshah

@akabos, thanks for this PR! Kudos for taking the initiative to tackle this issue. I've left a few comments throughout; most are pretty small issues.

I'm only available on and off over the next few weeks, so I'm leaving this as a comment instead of a "request changes" review. Please fix the issues above, and then one of the other maintainers can take another pass over the code.

akshayjshah · 2016-09-28T04:04:53Z

sugar.go

+	"time"
+)
+
+// Sugar is a wrapper around core logger whith less verbose API


nit: "with", not "whith"

akshayjshah · 2016-09-28T04:05:39Z

sugar.go

+
+	// Log a message at the given level. Messages include any context that's
+	// accumulated on the logger, as well as any fields added at the log site.
+	Log(Level, string, ...interface{}) error


Let's get rid of this; in an interface that's designed to be terse, I don't think it adds much.

I'm not sure what exactly you'd like to get rid of. I'm pretty sure Log method is very useful even in context of "terse interface".

akshayjshah · 2016-09-28T04:19:36Z

sugar.go

+		noErrArgs = args[1:]
+	default:
+		noErrArgs = args
+	}


I'd prefer to remove this block; treating the first of the variadic arguments differently from the rest is a little too much magic for me.

So how do you suggest treating errors then? Alternative approach is expecting an error in any position and would involve even more magic.

akshayjshah · 2016-09-28T04:23:56Z

sugar.go

+			case error:
+				return nil, errors.New("error can only be the first argument")
+			default:
+				return nil, errors.New("invalid argument type")


In addition to supporting errors (as @billf mentioned), please make sure to support all the types that zap has fields for. I believe that this switch is missing uintptr and zap.Marshaler.

Rather than returning an error if the argument doesn't match one of the types zap explicitly supports, fall back to using zap.Object, which attempts to use an encoder-appropriate serialization.

Added support for zap.Marshaler and changed fall back from error to zap.Object. And I couldn't find a singe mention of uintptr in zap codebase.

akshayjshah · 2016-09-28T04:27:04Z

sugar.go

+				return nil, errors.New("field name must be string")
+			}
+		} else {
+			switch value.(type) {


Have you seen the switch value := value.(type) form of type switches? It's described in Effective Go.

Using that form will reduce duplication below, since you won't have to type-cast in each case.

Sorry about that. I'm still very new to Go, so your notice is really appreciated.

Fixed.

akshayjshah · 2016-09-28T04:30:05Z

sugar.go

+func getSugarFields(args ...interface{}) ([]Field, error) {
+	var (
+		noErrArgs []interface{}
+		fields    []Field


Let's pre-allocate the right amount of space here - we should be able to do fields := make([]Field, 0, len(args)/2).

akshayjshah · 2016-09-28T04:36:59Z

sugar.go

+
+	if (len(noErrArgs) % 2) != 0 {
+		return nil, errors.New("invalid number of arguments")
+	}


Instead of returning an error, let's add a field to the log output describing the issue. In that case, we should ignore the last argument and include it in the error:

fields = append(fields, zap.String("numLogArgsError", fmt.Sprintf("odd number of arguments passed to logger, ignoring last arg: %v", args[len(args)-1])))`

I'm not sure I implemented it the way you expected, but please see b819160

Latest commit makes sugar logger handle internal errors in the same way core logger does.

akshayjshah · 2016-09-28T04:38:04Z

sugar.go

+
+// Log ...
+func (s *sugar) Log(lvl Level, msg string, args ...interface{}) error {
+	if cm := s.core.Check(lvl, msg); cm.OK() {


Awesome - thanks for being careful to use the checked message API!

Since we're updating getSugarFields so that it won't need to return an error, let's not have this method (or any of the Info, Debug, Error, etc. method) return errors either.

akshayjshah · 2016-09-28T04:42:42Z

sugar.go

+	Fatal(string, ...interface{}) error
+	// If the logger is in development mode (via the Development option), DFatal
+	// logs at the Fatal level. Otherwise, it logs at the Error level.
+	DFatal(string, ...interface{}) error


It seems like all these methods return errors because getSugarFields can return an error. I'd like to avoid this, since it's awkward for loggers to return errors - what's the user going to do, log the error?

I've left some comments on getSugarFields that should remove the returned error. Once those changes are in, let's change With, Debug, Info, etc. to not return errors either.

ascandella · 2016-10-02T19:41:08Z

any updates / timeline on this? we'd like to use it. would you like my team to take over this PR and finish addressing comments or were you planning to?

cc @uber-go/service-framework

ascandella · 2016-10-03T01:24:28Z

@akabos to be clear that question was directed at you -- do you plan on working on this any more, or would you like us to pick it up for you?

anuptalwalkar · 2016-10-03T20:33:22Z

@akabos Are you continuing to work on this PR? We are running on a tight schedule and this work seems really useful and relevant for us. I am happy to take over your work, address comments and fixes for this Logger.

mikluko · 2016-10-04T08:05:17Z

@sectioneight @anuptalwalkar I'd like to finish that myself. Please give me couple of days.

anuptalwalkar · 2016-10-04T20:17:47Z

@akabos Thank you so much! I appreciate speeding up the timeline. This is fantastic work:)

anuptalwalkar · 2016-10-04T21:42:53Z

sugar.go

+			case string:
+				key = value.(string)
+			default:
+				return nil, errors.New("field name must be string")


Just my $0.02- Loggers usually don't throw/return errors and rather gulp them down to the log files. Instead of returning error for this function, you want to just add a string field with a tiny message "unparsable argument" or something. It should be on the devs to notice an fix the logging format later in the game.

Fixed, please see b819160

Latest commit makes sugar logger handle internal errors in the same way core logger does.

ascandella

Looks awesome! Can't wait. I'm a human linter, I couldn't help myself.

ascandella · 2016-10-05T05:53:00Z

sugar.go

+
+// Sugar is a wrapper around core logger with less verbose API
+type Sugar interface {
+	// Check the minimum enabled log level.


I think this violates golint or vet or one of the tools? The comment should start with "Level", right?

Well, I don't know much about how golint should work, but apparently it doesn't have any objections about all these comments. Furthermore, they are basically copied over from zap.Logger interface definition, see https://github.com/uber-go/zap/blob/master/logger.go#L33

Normally comments in Go are Field is [...] or Func does blah. In this case, I think rather than Check the minimum enabled log level, Level returns the minimum enabled log level. might be a better comment

For example, look at the comments on this interface in the standard library:
https://golang.org/pkg/net/http/#CookieJar

ascandella · 2016-10-05T05:53:05Z

sugar.go

+	// Change the level of this logger, as well as all its ancestors and
+	// descendants. This makes it easy to change the log level at runtime
+	// without restarting your application.
+	SetLevel(Level)


Same comment here

Same as above

ascandella · 2016-10-05T05:53:11Z

sugar.go

+	SetLevel(Level)
+
+	// Create a child logger, and optionally add some context to that logger.
+	With(...interface{}) (Sugar, error)


…ect field

mikluko · 2016-10-05T08:42:33Z

sugar.go

-			case error:
-				return nil, errors.New("error can only be the first argument")
+				fields = append(fields, Stringer(key, v))
+			case LogMarshaler:


@akshayjshah @anuptalwalkar @sectioneight

I looked through coverage report and eventually found that LogMarshaler never get caught. Object field is always used instead. I'm going to update test suite to fail in such case, but what's important is that I don't really have a clue why would it happen. Can anyone please comment on the situation?

@akabos I bet (Just guessing) the LogMarshaler didn't understand unexported struct. I commented on the test below to update m9e to json serializable struct that seemed to fix the test coverage issue you are seeing.

As far as I understand Go exported/unexported logic, these fields are only used by m9e own method and the fact they are unexported should not affect anything.

anuptalwalkar · 2016-10-07T04:55:38Z

sugar_test.go

+type m9e struct {
+	foo int
+	bar bool
+}


You need this struct to be json formattable. This will fix the failing TestSugarLogTypes test -

type m9e struct { Foo intjson:"foo" Bar booljson:"bar" }

This will fix test but no the issue. When you define struct as json formatable Object field start to mimic expected LogMarshal output.

I removed LogMarshaler altogether because type switch fail to catch structs implementing this interface.

prashantv · 2016-10-09T20:47:48Z

sugar.go

+			}
+		} else {
+			switch v := value.(type) {
+			case error:


I'm not sure about this special casing for error. I think it's a little surprising, complicates the code, and will possibly cause unexpected errors.

For example, if some struct happens to satisfy the error interface (E.g., Thrift exceptions), then they will never be able to use it as a value.

I'm not sure either but I don't see much options here. Also I think this wrapper supposed to be merely syntax sugar. It's not supposed to satisfy all possible requirements and just have to be "ok for most uses".

I'm open to any ideas about handling errors, but as for now this is the only working and (mostly) magic free implementation I can think of.

prashantv · 2016-10-09T20:49:03Z

benchmarks/zap_sugar_bench_test.go

+}
+
+func BenchmarkZapSugarDisabledLevelsWithoutFields(b *testing.B) {
+	logger := zap.NewSugar(zap.New(zap.NewJSONEncoder(), zap.ErrorLevel, zap.DiscardOutput))


we duplicate the zap.New(...) quite a lot, maybe a helper could help

func newSugarLogger(options [...]) zap.Sugar

and by defualt the options should probably just created a JSON encoder that with discard output

prashantv · 2016-10-09T20:52:51Z

sugar.go

+
+// Sugar is a wrapper around core logger with less verbose API
+type Sugar interface {
+	// Check the minimum enabled log level.


Normally comments in Go are Field is [...] or Func does blah. In this case, I think rather than Check the minimum enabled log level, Level returns the minimum enabled log level. might be a better comment

For example, look at the comments on this interface in the standard library:
https://golang.org/pkg/net/http/#CookieJar

prashantv · 2016-10-09T20:53:43Z

sugar.go

+	// Change the level of this logger, as well as all its ancestors and
+	// descendants. This makes it easy to change the log level at runtime
+	// without restarting your application.
+	SetLevel(Level)


Same as above

prashantv · 2016-10-09T20:55:24Z

sugar.go

+	s.core.SetLevel(lvl)
+}
+
+func (s *sugar) With(args ...interface{}) (Sugar, error) {


I'm not sure if returning errors from this method is useful -- users can't really do much. I think perhaps we should just write an error to the ErrorOutput?

prashantv · 2016-10-09T20:57:50Z

sugar.go

+				fields = append(fields, Time(key, v))
+			case time.Duration:
+				fields = append(fields, Duration(key, v))
+			case fmt.Stringer:


fmt.Stringer should come after LogMarshaler -- if the type knows how to serialize itself, I think we should prefer that.

Please add a unit test to ensure that's the case as well.

I removed LogMarshaler altogether. As I mentioned in previous comments, type switch fails to catch structs implementing this interface for some reason.

Can you explain more about the type switch not catching this -- I think keeping log marshaler is a good idea, and it should work,

prashantv · 2016-10-09T20:59:31Z

sugar.go

+			case LogMarshaler:
+				fields = append(fields, Marshaler(key, v))
+			default:
+				fields = append(fields, Object(key, value))


In this approach, if a type has String, there's no way to serialize the fields using the JSON marshaller.

prashantv · 2016-10-09T20:59:47Z

sugar.go

+	return fields, nil
+}
+
+// Log ...


incomplete comment. You can delete comments on exported methods on private types -- since the interface already has documentation

prashantv · 2016-10-09T21:00:34Z

sugar.go

+	if cm := s.core.Check(lvl, msg); cm.OK() {
+		fields, err = getSugarFields(args...)
+		if err != nil {
+			fields = []Field{Error(err)}


If the user has an error field, it would get overwritten by this error field.

I think we have to get away from returning errors when converting fields

Everything user tried to log would get overwritten with error returned from getSugarFields. I'm pretty sure it is valid way of handling invalid arguments.

Not relevant any more. I made sugar logger to handle internal error in the same manner core logger does.

prashantv · 2016-10-09T21:02:30Z

sugar.go

+
+func (s *sugar) DFatal(msg string, args ...interface{}) {
+	lvl := ErrorLevel
+	if s.core.(*logger).Development {


Please use the underlying Logger's DFatal method. This method will panic if the passed in logger is wrapped via Sample, or some other wrapper which implements the Logger interface but is not the base logger.

Can we add a unit test that would have caught this issue?

I made DFatal to relay directly to core logger's DFatal.

But speaking of unit test that would have caught this issue, I really doubt that sugar logger suite should include tests for core logger's logic.

Thanks for fixing it. I'm not suggesting unit testing the core logger's DFatal method, but a test which ensures that the DFatal method here doesn't panic if it's passed an implementation of zap.Logger which isn't the underlying logger type.

prashantv · 2016-10-09T21:07:38Z

Thanks for the contribution @akabos

I think the big issues to figure out are:

whether we should do the special-casing for errors, and only allowing them as the first field.
dealing with errors when converting between the list of interface{} to a list of zap.Field

Would appreciate feedback from others as well. My personal opinion is that the special-casing of the first field of error is a little surprising, and that we shouldn't return errors during conversion.

mikluko · 2016-10-10T10:12:14Z

@prashantv

Thanks for your comments! After latest commits, Sugar logger does not inject own error fields into log messages any more. I agree that it was petty awkward way to handle internal errors.

Instead, I made it to behave exactly as core logger does. I hope this is going to satisfy everyone who expressed concern on the matter.

mikluko · 2016-10-10T10:15:46Z

@prashantv

By no means I insist on "error only on first place" approach. But this special case is the consequence of the special nature of error field. Among all fields only this one has no name so it has to be dealt with specially in any case. I chose this approach only because it seemed easiest to implement while benefits from allowing error in arbitrary position seemed questionable.

I still think that having "first place" restriction for errors is valid, but I'd like to see this PR merged ASAP and I'm ready to change sugar logger to handle errors in any particular way you see appropriate. Just let me know what exactly you see appropriate.

prashantv · 2016-10-11T06:28:44Z

sugar.go

+}
+
+func (s *sugar) internalError(msg string) {
+	s.core.(*logger).internalError(msg)


There should be no casts from Logger to *logger, as that will panic if the user passes some sort of wrapped logger (e.g., like one returned from sampling).

internalErroris not declared for Logger interface. I'm not sure if there is another way to access it. Even if I re-implement this method on Sugar, ErrorOutput is still not declared on LoggerInterface. What do you suggest?

Feel free to defer this with a TODO, and we can circle back to it, since this will require some thinking about.

For now, make the internal error just do s.core.Error("Logger error", zap.String("message", msg)) or something.

As a separate PR, we need to think about either exposing the error output, or trying to cast the passed in logger to something that implements an internalError method, and if it's not implemented doing the log to the normal error stream.

prashantv · 2016-10-11T06:32:01Z

@akabos The Error field is a helper that we don't have to support. I think it's OK to pass ("error", err).

Thanks for fixing the error handling, I think logging it as an internal error is definitely better. We need to figure out a way to do that that won't cause panics, but otherwise the error handling is better.

I don't have strong opinions no whether we should always look for error type everywhere, or only for a field named "error".

akshayjshah · 2016-11-21T17:46:04Z

@akabos, I'm carrying forward this work in #185; of course, I'm preserving your commits.

mikluko added 4 commits September 22, 2016 17:38

Refs: uber-go#138

be920bc

added benchmark

e513235

improved test coverage

77b7321

improved test coverage even more

ae2b22c

mikluko changed the title ~~Sugar~~ Add a slightly slower, but less verbose, logger Sep 22, 2016

billf suggested changes Sep 22, 2016

View reviewed changes

mikluko added 5 commits September 23, 2016 14:07

accept error as the first of variadic arguments

b41c502

cleanup

18e13ed

improved coverage

bcde07a

mirrored relevant core logger benchmarks

1591492

use CheckedMessage to cut off expensive argument parsing

62a712a

ascandella mentioned this pull request Sep 26, 2016

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

Closed

akshayjshah reviewed Sep 28, 2016

View reviewed changes

mikluko added 2 commits October 4, 2016 16:53

used another form of type switch

4dda6ea

fixed typo

596acf3

anuptalwalkar reviewed Oct 4, 2016

View reviewed changes

ascandella reviewed Oct 5, 2016

View reviewed changes

mikluko added 3 commits October 5, 2016 10:07

getSugarFields errors are logged rather then returned

b819160

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

729ad48

…ect field

pre-allocate fields slice

56a80f6

mikluko commented Oct 5, 2016

View reviewed changes

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

79553b0

anuptalwalkar reviewed Oct 7, 2016

View reviewed changes

prashantv requested changes Oct 9, 2016

View reviewed changes

mikluko added 6 commits October 10, 2016 11:04

Removed LogMarshaler handling

c925d2d

added some benchamrk helpers to reduce repeats

d03d8f0

updated comments

1398fd2

handle errors same way core logger does

8c913fb

relay DFatal directly to core logger

92b8c4e

benchmark fix

2162452

Merge branch 'master' into sugar

66f4380

prashantv reviewed Oct 11, 2016

View reviewed changes

mikluko and others added 2 commits October 30, 2016 10:24

Merge branch 'master' into sugar

0e10f81

Merge branch 'master' into sugar

c22e1a3

akshayjshah mentioned this pull request Nov 21, 2016

Add SugaredLogger #185

Merged

akshayjshah closed this Nov 21, 2016

		@@ -0,0 +1,54 @@
		// Copyright (c) 2016 Uber Technologies, Inc.

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

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

Conversation

mikluko commented Sep 22, 2016 • edited Loading

billf left a comment

Choose a reason for hiding this comment

billf Sep 22, 2016 • 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

akshayjshah Sep 28, 2016 • 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

akshayjshah left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah Sep 28, 2016 • 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

akshayjshah Sep 28, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akshayjshah Sep 28, 2016 • 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

akshayjshah Sep 28, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ascandella commented Oct 2, 2016

ascandella commented Oct 3, 2016

anuptalwalkar commented Oct 3, 2016

mikluko commented Oct 4, 2016

anuptalwalkar commented Oct 4, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ascandella left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prashantv Oct 9, 2016 • 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

mikluko Oct 5, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mikluko Oct 7, 2016 • 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

prashantv Oct 9, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prashantv Oct 9, 2016 • 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

mikluko commented Sep 22, 2016 •

edited

Loading

billf Sep 22, 2016 •

edited

Loading

akshayjshah Sep 28, 2016 •

edited

Loading

akshayjshah Sep 28, 2016 •

edited

Loading

akshayjshah Sep 28, 2016 •

edited

Loading

akshayjshah Sep 28, 2016 •

edited

Loading

akshayjshah Sep 28, 2016 •

edited

Loading

prashantv Oct 9, 2016 •

edited

Loading

mikluko Oct 5, 2016 •

edited

Loading

mikluko Oct 7, 2016 •

edited

Loading

prashantv Oct 9, 2016 •

edited

Loading

prashantv Oct 9, 2016 •

edited

Loading

prashantv Oct 9, 2016 •

edited

Loading

mikluko Oct 10, 2016 •

edited

Loading