Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
wants to merge 24 commits into from
Closed

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

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
24 commits
Select commit Hold shift + click to select a range
be920bc
Refs: #138
mikluko Sep 22, 2016
e513235
added benchmark
mikluko Sep 22, 2016
77b7321
improved test coverage
mikluko Sep 22, 2016
ae2b22c
improved test coverage even more
mikluko Sep 22, 2016
b41c502
accept error as the first of variadic arguments
mikluko Sep 23, 2016
18e13ed
cleanup
mikluko Sep 23, 2016
bcde07a
improved coverage
mikluko Sep 23, 2016
1591492
mirrored relevant core logger benchmarks
mikluko Sep 23, 2016
62a712a
use CheckedMessage to cut off expensive argument parsing
mikluko Sep 23, 2016
4dda6ea
used another form of type switch
mikluko Oct 4, 2016
596acf3
fixed typo
mikluko Oct 4, 2016
b819160
getSugarFields errors are logged rather then returned
mikluko Oct 5, 2016
729ad48
added support for Marshaler field, changed fallback from error to obj…
mikluko Oct 5, 2016
56a80f6
pre-allocate fields slice
mikluko Oct 5, 2016
79553b0
made test to fail if Object field is used in place of Marshaler
mikluko Oct 5, 2016
c925d2d
Removed LogMarshaler handling
mikluko Oct 10, 2016
d03d8f0
added some benchamrk helpers to reduce repeats
mikluko Oct 10, 2016
1398fd2
updated comments
mikluko Oct 10, 2016
8c913fb
handle errors same way core logger does
mikluko Oct 10, 2016
92b8c4e
relay DFatal directly to core logger
mikluko Oct 10, 2016
2162452
benchmark fix
mikluko Oct 10, 2016
66f4380
Merge branch 'master' into sugar
mikluko Oct 10, 2016
0e10f81
Merge branch 'master' into sugar
mikluko Oct 30, 2016
c22e1a3
Merge branch 'master' into sugar
akshayjshah Nov 10, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 16 additions & 14 deletions sugar.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -112,31 +112,33 @@ func getSugarFields(args ...interface{}) ([]Field, error) {
return nil, errors.New("field name must be string")
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed, please see b819160

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

}
} else {
switch value := value.(type) {
switch v := value.(type) {
case error:
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

return nil, errors.New("error can only be the first argument")
case bool:
fields = append(fields, Bool(key, value))
fields = append(fields, Bool(key, v))
case float64:
fields = append(fields, Float64(key, value))
fields = append(fields, Float64(key, v))
case int:
fields = append(fields, Int(key, value))
fields = append(fields, Int(key, v))
case int64:
fields = append(fields, Int64(key, value))
fields = append(fields, Int64(key, v))
case uint:
fields = append(fields, Uint(key, value))
fields = append(fields, Uint(key, v))
case uint64:
fields = append(fields, Uint64(key, value))
fields = append(fields, Uint64(key, v))
case string:
fields = append(fields, String(key, value))
fields = append(fields, String(key, v))
case time.Time:
fields = append(fields, Time(key, value))
fields = append(fields, Time(key, v))
case time.Duration:
fields = append(fields, Duration(key, value))
fields = append(fields, Duration(key, v))
case fmt.Stringer:
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

fields = append(fields, Stringer(key, value))
case error:
return nil, errors.New("error can only be the first argument")
fields = append(fields, Stringer(key, v))
case LogMarshaler:
Copy link
Contributor Author

@mikluko mikluko Oct 5, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@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.

Copy link
Contributor Author

@mikluko mikluko Oct 7, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

fields = append(fields, Marshaler(key, v))
default:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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"))

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

@akshayjshah akshayjshah Sep 28, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(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()))

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

return nil, errors.New("invalid argument type")
fields = append(fields, Object(key, value))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

}
}
}
Expand Down
39 changes: 20 additions & 19 deletions sugar_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,23 +40,20 @@ func TestSugarGetSugarFields(t *testing.T) {
_, err = getSugarFields("test1", 1, "test2")
assert.Error(t, err, "Should return error on invalid number of arguments")

_, err = getSugarFields("test1", nil)
assert.Error(t, err, "Should return error on argument of unknown type")

_, err = getSugarFields("test1", 1, "error", errors.New(""))
assert.Error(t, err, "Should return error when error passed as value (special case of unknown type)")

_, err = getSugarFields(1, 1)
assert.Error(t, err, "Should return error on non-string field name")

fields, _ = getSugarFields("test", 1)
assert.Equal(t, 1, len(fields), "Should return 1 field")
assert.Len(t, fields, 1, "Should return 1 field")

fields, _ = getSugarFields("test1", 1, "test2", 2)
assert.Equal(t, 2, len(fields), "Should return 2 fields")
assert.Len(t, fields, 2, "Should return 2 fields")

fields, _ = getSugarFields(errors.New("error"), "test1", 1)
assert.Equal(t, 2, len(fields), "Should return 2 fields")
assert.Len(t, fields, 2, "Should return 2 fields")
}

func TestSugarLevel(t *testing.T) {
Expand All @@ -83,6 +80,17 @@ func withSugarLogger(t testing.TB, opts []Option, f func(Sugar, *testBuffer)) {
f(sugar, sink)
}

type m9e struct {
Foo int `json:"foo"`
Bar bool `json:"bar"`
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


func (m *m9e) MarshalLog(kv KeyValue) error {
kv.AddInt("foo", m.Foo)
kv.AddBool("bar", m.Bar)
return nil
}

func TestSugarLog(t *testing.T) {
opts := opts(Fields(Int("foo", 42)))
withSugarLogger(t, opts, func(logger Sugar, buf *testBuffer) {
Expand All @@ -101,6 +109,7 @@ func TestSugarLog(t *testing.T) {

func TestSugarLogTypes(t *testing.T) {
withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) {
logger.Debug("")
logger.Debug("", "bool", true)
logger.Debug("", "float64", float64(1.23456789))
logger.Debug("", "int", int(-1))
Expand All @@ -111,7 +120,10 @@ func TestSugarLogTypes(t *testing.T) {
logger.Debug("", "time", time.Unix(0, 0))
logger.Debug("", "duration", time.Second)
logger.Debug("", "stringer", DebugLevel)
logger.Debug("", "marshaler", m9e{1, true})
logger.Debug("", "object", []string{"foo", "bar"})
assert.Equal(t, []string{
`{"level":"debug","msg":""}`,
`{"level":"debug","msg":"","bool":true}`,
`{"level":"debug","msg":"","float64":1.23456789}`,
`{"level":"debug","msg":"","int":-1}`,
Expand All @@ -122,15 +134,8 @@ func TestSugarLogTypes(t *testing.T) {
`{"level":"debug","msg":"","time":0}`,
`{"level":"debug","msg":"","duration":1000000000}`,
`{"level":"debug","msg":"","stringer":"debug"}`,
}, buf.Lines(), "Incorrect output from logger")
})
}

func TestSugarLogNoArgs(t *testing.T) {
withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) {
logger.Debug("no args message")
assert.Equal(t, []string{
`{"level":"debug","msg":"no args message"}`,
`{"level":"debug","msg":"","marshaler":{"foo":1,"bar":true}}`,
`{"level":"debug","msg":"","object":["foo","bar"]}`,
}, buf.Lines(), "Incorrect output from logger")
})
}
Expand Down Expand Up @@ -190,10 +195,6 @@ func TestSugarLogErrors(t *testing.T) {
logger.Log(InfoLevel, "foo", "foo", errors.New("b"))
assert.Equal(t, `{"level":"info","msg":"foo","error":"error can only be the first argument"}`, buf.Stripped(), "Should log error argument position is invalid")
})
withSugarLogger(t, nil, func(logger Sugar, buf *testBuffer) {
logger.Log(InfoLevel, "foo", "bar", nil)
assert.Equal(t, `{"level":"info","msg":"foo","error":"invalid argument type"}`, buf.Stripped(), "Should log invalid argument type")
})
}

func TestSugarLogDiscards(t *testing.T) {
Expand Down