From 4d79b064c2fbe903591289a2484873b668ee86c3 Mon Sep 17 00:00:00 2001 From: Vladimir Skipor Date: Sun, 19 Feb 2017 20:45:32 +0300 Subject: [PATCH 1/5] CallerEncoder (#319) CallerEncoder similar to other encoders for complex types. It allows to configure caller presentation in log. --- config.go | 2 ++ zapcore/encoder.go | 31 +++++++++++++++++++++++++++---- zapcore/encoder_test.go | 37 +++++++++++++++++++++++++++++++++++++ zapcore/json_encoder.go | 3 ++- 4 files changed, 68 insertions(+), 5 deletions(-) diff --git a/config.go b/config.go index 099d1b34c..1382b1b7f 100644 --- a/config.go +++ b/config.go @@ -89,6 +89,7 @@ func NewProductionEncoderConfig() zapcore.EncoderConfig { EncodeLevel: zapcore.LowercaseLevelEncoder, EncodeTime: zapcore.EpochTimeEncoder, EncodeDuration: zapcore.SecondsDurationEncoder, + EncodeCaller: zapcore.FullPathCallerEncoder, } } @@ -126,6 +127,7 @@ func NewDevelopmentEncoderConfig() zapcore.EncoderConfig { EncodeLevel: zapcore.CapitalLevelEncoder, EncodeTime: zapcore.ISO8601TimeEncoder, EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: zapcore.FullPathCallerEncoder, } } diff --git a/zapcore/encoder.go b/zapcore/encoder.go index a1d46506f..826ac426f 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -162,14 +162,36 @@ func (e *DurationEncoder) UnmarshalText(text []byte) error { return nil } +// A CallerEncoder serializes a EntryCaller to a primitive type. +type CallerEncoder func(EntryCaller, PrimitiveArrayEncoder) + +// FullPathCallerEncoder serializes caller in /full/path/file:line format. +func FullPathCallerEncoder(caller EntryCaller, enc PrimitiveArrayEncoder) { + // OPTIMIZE: after adding AppendBytes to PrimitiveArrayEncoder just copy bytes + // from buffer to not allocate string. + enc.AppendString(caller.String()) +} + +// UnmarshalText unmarshals text to a CallerEncoder. +// Anything is unmarshaled to FullPathCallerEncoder at that moment. +func (e *CallerEncoder) UnmarshalText(text []byte) error { + switch string(text) { + //case "gopath": // TODO + default: + *e = FullPathCallerEncoder + } + return nil +} + // An EncoderConfig allows users to configure the concrete encoders supplied by // zapcore. type EncoderConfig struct { // Set the keys used for each log entry. - MessageKey string `json:"messageKey" yaml:"messageKey"` - LevelKey string `json:"levelKey" yaml:"levelKey"` - TimeKey string `json:"timeKey" yaml:"timeKey"` - NameKey string `json:"nameKey" yaml:"nameKey"` + MessageKey string `json:"messageKey" yaml:"messageKey"` + LevelKey string `json:"levelKey" yaml:"levelKey"` + TimeKey string `json:"timeKey" yaml:"timeKey"` + NameKey string `json:"nameKey" yaml:"nameKey"` + // CallerKey sets key for caller. If empty, caller is not logged. CallerKey string `json:"callerKey" yaml:"callerKey"` StacktraceKey string `json:"stacktraceKey" yaml:"stacktraceKey"` // Configure the primitive representations of common complex types. For @@ -178,6 +200,7 @@ type EncoderConfig struct { EncodeLevel LevelEncoder `json:"levelEncoder" yaml:"levelEncoder"` EncodeTime TimeEncoder `json:"timeEncoder" yaml:"timeEncoder"` EncodeDuration DurationEncoder `json:"durationEncoder" yaml:"durationEncoder"` + EncodeCaller CallerEncoder `json:"callerEncoder" yaml:"callerEncoder"` } // ObjectEncoder is a strongly-typed, encoding-agnostic interface for adding a diff --git a/zapcore/encoder_test.go b/zapcore/encoder_test.go index d9af56688..a96f28424 100644 --- a/zapcore/encoder_test.go +++ b/zapcore/encoder_test.go @@ -53,6 +53,7 @@ func testEncoderConfig() EncoderConfig { EncodeTime: EpochTimeEncoder, EncodeLevel: LowercaseLevelEncoder, EncodeDuration: SecondsDurationEncoder, + EncodeCaller: FullPathCallerEncoder, } } @@ -105,6 +106,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tinfo\tmain@foo.go:42\thello\nfake-stack", @@ -121,6 +123,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tmain@foo.go:42\thello\nfake-stack", @@ -137,6 +140,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "info\tmain@foo.go:42\thello\nfake-stack", @@ -153,6 +157,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","S":"fake-stack"}`, expectedConsole: "0\tinfo\tmain@foo.go:42\nfake-stack", @@ -169,6 +174,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tinfo\tfoo.go:42\thello\nfake-stack", @@ -185,6 +191,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tinfo\tmain\thello\nfake-stack", @@ -201,6 +208,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello"}`, expectedConsole: "0\tinfo\tmain@foo.go:42\thello", @@ -217,6 +225,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: func(t time.Time, enc PrimitiveArrayEncoder) { enc.AppendString(t.String()) }, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, extra: func(enc Encoder) { enc.AddTime("extra", _epoch) @@ -242,6 +251,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: StringDurationEncoder, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, extra: func(enc Encoder) { enc.AddDuration("extra", time.Second) @@ -267,6 +277,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: CapitalLevelEncoder, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"INFO","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tINFO\tmain@foo.go:42\thello\nfake-stack", @@ -283,6 +294,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, extra: func(enc Encoder) { enc.OpenNamespace("outer") @@ -307,6 +319,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: func(time.Time, PrimitiveArrayEncoder) {}, EncodeDuration: base.EncodeDuration, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, extra: func(enc Encoder) { enc.AddTime("sometime", time.Unix(0, 100)) }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","sometime":100,"S":"fake-stack"}`, @@ -324,6 +337,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: func(time.Duration, PrimitiveArrayEncoder) {}, EncodeLevel: base.EncodeLevel, + EncodeCaller: base.EncodeCaller, }, extra: func(enc Encoder) { enc.AddDuration("someduration", time.Microsecond) }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","someduration":1000,"S":"fake-stack"}`, @@ -341,6 +355,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeTime: base.EncodeTime, EncodeDuration: base.EncodeDuration, EncodeLevel: func(Level, PrimitiveArrayEncoder) {}, + EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tmain@foo.go:42\thello\nfake-stack", @@ -452,6 +467,28 @@ func TestDurationEncoders(t *testing.T) { } } +func TestCallerEncoders(t *testing.T) { + caller := _testEntry.Caller + tests := []struct { + name string + expected interface{} // output of serializing caller + }{ + {"", "foo.go:42"}, + {"something-random", "foo.go:42"}, + } + + for _, tt := range tests { + var ce CallerEncoder + require.NoError(t, ce.UnmarshalText([]byte(tt.name)), "Unexpected error unmarshaling %q.", tt.name) + assertAppended( + t, + tt.expected, + func(arr ArrayEncoder) { ce(caller, arr) }, + "Unexpected output serializing file name as %v with %q.", tt.expected, tt.name, + ) + } +} + func assertAppended(t testing.TB, expected interface{}, f func(ArrayEncoder), msgAndArgs ...interface{}) { mem := NewMapObjectEncoder() mem.AddArray("k", ArrayMarshalerFunc(func(arr ArrayEncoder) error { diff --git a/zapcore/json_encoder.go b/zapcore/json_encoder.go index ce225dfc3..a51ea6fbf 100644 --- a/zapcore/json_encoder.go +++ b/zapcore/json_encoder.go @@ -295,7 +295,8 @@ func (enc *jsonEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, if ent.Caller.Defined && final.CallerKey != "" { // NOTE: we add the field here for parity compromise with text // prepending, while not actually mutating the message string. - final.AddString(final.CallerKey, ent.Caller.String()) + final.addKey(final.CallerKey) + final.EncodeCaller(ent.Caller, final) } if final.MessageKey != "" { final.addKey(enc.MessageKey) From 77a9fcc52977f6a42c7208297b5f32f5c1014ca9 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Mon, 13 Mar 2017 15:27:45 -0700 Subject: [PATCH 2/5] Clean up default implementation of EncodeCaller --- zapcore/encoder.go | 10 ++++------ zapcore/encoder_test.go | 23 ++++++++++++++++++++--- zapcore/json_encoder.go | 8 ++++++-- 3 files changed, 30 insertions(+), 11 deletions(-) diff --git a/zapcore/encoder.go b/zapcore/encoder.go index 826ac426f..34a40dd2d 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -162,21 +162,19 @@ func (e *DurationEncoder) UnmarshalText(text []byte) error { return nil } -// A CallerEncoder serializes a EntryCaller to a primitive type. +// A CallerEncoder serializes an EntryCaller to a primitive type. type CallerEncoder func(EntryCaller, PrimitiveArrayEncoder) -// FullPathCallerEncoder serializes caller in /full/path/file:line format. +// FullPathCallerEncoder serializes a caller in /full/path/file:line format. func FullPathCallerEncoder(caller EntryCaller, enc PrimitiveArrayEncoder) { - // OPTIMIZE: after adding AppendBytes to PrimitiveArrayEncoder just copy bytes - // from buffer to not allocate string. + // TODO: consider using a byte-oriented API to save an allocation. enc.AppendString(caller.String()) } // UnmarshalText unmarshals text to a CallerEncoder. -// Anything is unmarshaled to FullPathCallerEncoder at that moment. +// FIXME: Support more options. func (e *CallerEncoder) UnmarshalText(text []byte) error { switch string(text) { - //case "gopath": // TODO default: *e = FullPathCallerEncoder } diff --git a/zapcore/encoder_test.go b/zapcore/encoder_test.go index a96f28424..8ef7277f3 100644 --- a/zapcore/encoder_test.go +++ b/zapcore/encoder_test.go @@ -360,6 +360,23 @@ func TestEncoderConfiguration(t *testing.T) { expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, expectedConsole: "0\tmain@foo.go:42\thello\nfake-stack", }, + { + desc: "handle no-op EncodeCaller", + cfg: EncoderConfig{ + LevelKey: "L", + TimeKey: "T", + MessageKey: "M", + NameKey: "N", + CallerKey: "C", + StacktraceKey: "S", + EncodeTime: base.EncodeTime, + EncodeDuration: base.EncodeDuration, + EncodeLevel: base.EncodeLevel, + EncodeCaller: func(EntryCaller, PrimitiveArrayEncoder) {}, + }, + expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, + expectedConsole: "0\tinfo\tmain@foo.go:42\thello\nfake-stack", + }, } for i, tt := range tests { @@ -468,13 +485,13 @@ func TestDurationEncoders(t *testing.T) { } func TestCallerEncoders(t *testing.T) { - caller := _testEntry.Caller + caller := EntryCaller{Defined: true, File: "/home/jack/src/github.com/foo/foo.go", Line: 42} tests := []struct { name string expected interface{} // output of serializing caller }{ - {"", "foo.go:42"}, - {"something-random", "foo.go:42"}, + {"", "/home/jack/src/github.com/foo/foo.go:42"}, + {"something-random", "/home/jack/src/github.com/foo/foo.go:42"}, } for _, tt := range tests { diff --git a/zapcore/json_encoder.go b/zapcore/json_encoder.go index a51ea6fbf..e0a19ab37 100644 --- a/zapcore/json_encoder.go +++ b/zapcore/json_encoder.go @@ -293,10 +293,14 @@ func (enc *jsonEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, final.AppendString(ent.LoggerName) } if ent.Caller.Defined && final.CallerKey != "" { - // NOTE: we add the field here for parity compromise with text - // prepending, while not actually mutating the message string. final.addKey(final.CallerKey) + cur := final.buf.Len() final.EncodeCaller(ent.Caller, final) + if cur == final.buf.Len() { + // User-supplied EncodeCaller was a no-op. Fall back to strings to + // keep output JSON valid. + final.AppendString(ent.Caller.String()) + } } if final.MessageKey != "" { final.addKey(enc.MessageKey) From f785f2a6d5908bc261ad7b86b08a8a52647dd4ac Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Tue, 14 Mar 2017 09:44:07 -0700 Subject: [PATCH 3/5] Add a shorter EncodeCaller variant --- benchmarks/zap_test.go | 3 +-- config.go | 4 ++-- zapcore/encoder.go | 20 +++++++++++++++----- zapcore/encoder_test.go | 8 +++++--- zapcore/entry.go | 39 ++++++++++++++++++++++++++++++++++++--- zapcore/entry_test.go | 29 +++++++++++++++++++++-------- 6 files changed, 80 insertions(+), 23 deletions(-) diff --git a/benchmarks/zap_test.go b/benchmarks/zap_test.go index c42667f0b..e0f2b08e6 100644 --- a/benchmarks/zap_test.go +++ b/benchmarks/zap_test.go @@ -69,8 +69,7 @@ var _jane = user{ func newZapLogger(lvl zapcore.Level) *zap.Logger { // use the canned production encoder configuration - cfg := zap.NewProductionConfig() - enc := zapcore.NewJSONEncoder(cfg.EncoderConfig) + enc := zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()) return zap.New(zapcore.NewCore( enc, &zaptest.Discarder{}, diff --git a/config.go b/config.go index 1382b1b7f..a198f16ea 100644 --- a/config.go +++ b/config.go @@ -89,7 +89,7 @@ func NewProductionEncoderConfig() zapcore.EncoderConfig { EncodeLevel: zapcore.LowercaseLevelEncoder, EncodeTime: zapcore.EpochTimeEncoder, EncodeDuration: zapcore.SecondsDurationEncoder, - EncodeCaller: zapcore.FullPathCallerEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, } } @@ -127,7 +127,7 @@ func NewDevelopmentEncoderConfig() zapcore.EncoderConfig { EncodeLevel: zapcore.CapitalLevelEncoder, EncodeTime: zapcore.ISO8601TimeEncoder, EncodeDuration: zapcore.StringDurationEncoder, - EncodeCaller: zapcore.FullPathCallerEncoder, + EncodeCaller: zapcore.ShortCallerEncoder, } } diff --git a/zapcore/encoder.go b/zapcore/encoder.go index 34a40dd2d..54a814423 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -165,18 +165,28 @@ func (e *DurationEncoder) UnmarshalText(text []byte) error { // A CallerEncoder serializes an EntryCaller to a primitive type. type CallerEncoder func(EntryCaller, PrimitiveArrayEncoder) -// FullPathCallerEncoder serializes a caller in /full/path/file:line format. -func FullPathCallerEncoder(caller EntryCaller, enc PrimitiveArrayEncoder) { +// FullCallerEncoder serializes a caller in /full/path/to/package/file:line +// format. +func FullCallerEncoder(caller EntryCaller, enc PrimitiveArrayEncoder) { // TODO: consider using a byte-oriented API to save an allocation. enc.AppendString(caller.String()) } -// UnmarshalText unmarshals text to a CallerEncoder. -// FIXME: Support more options. +// ShortCallerEncoder serializes a caller in package/file:line format, trimming +// all but the final directory from the full path. +func ShortCallerEncoder(caller EntryCaller, enc PrimitiveArrayEncoder) { + // TODO: consider using a byte-oriented API to save an allocation. + enc.AppendString(caller.TrimmedPath()) +} + +// UnmarshalText unmarshals text to a CallerEncoder. "full" is unmarshaled to +// FullCallerEncoder and anything else is unmarshaled to ShortCallerEncoder. func (e *CallerEncoder) UnmarshalText(text []byte) error { switch string(text) { + case "full": + *e = FullCallerEncoder default: - *e = FullPathCallerEncoder + *e = ShortCallerEncoder } return nil } diff --git a/zapcore/encoder_test.go b/zapcore/encoder_test.go index 8ef7277f3..adb9f1fe3 100644 --- a/zapcore/encoder_test.go +++ b/zapcore/encoder_test.go @@ -53,7 +53,7 @@ func testEncoderConfig() EncoderConfig { EncodeTime: EpochTimeEncoder, EncodeLevel: LowercaseLevelEncoder, EncodeDuration: SecondsDurationEncoder, - EncodeCaller: FullPathCallerEncoder, + EncodeCaller: ShortCallerEncoder, } } @@ -490,8 +490,10 @@ func TestCallerEncoders(t *testing.T) { name string expected interface{} // output of serializing caller }{ - {"", "/home/jack/src/github.com/foo/foo.go:42"}, - {"something-random", "/home/jack/src/github.com/foo/foo.go:42"}, + {"", "foo/foo.go:42"}, + {"something-random", "foo/foo.go:42"}, + {"short", "foo/foo.go:42"}, + {"full", "/home/jack/src/github.com/foo/foo.go:42"}, } for _, tt := range tests { diff --git a/zapcore/entry.go b/zapcore/entry.go index b580141ab..9bab935b2 100644 --- a/zapcore/entry.go +++ b/zapcore/entry.go @@ -22,6 +22,8 @@ package zapcore import ( "fmt" + "os" + "strings" "sync" "time" @@ -74,11 +76,16 @@ type EntryCaller struct { Line int } -// String returns a "file:line" string if the EntryCaller is Defined, and the -// empty string otherwise. +// String returns the full path and line number of the caller. func (ec EntryCaller) String() string { + return ec.FullPath() +} + +// FullPath returns a /full/path/to/package/file:line description of the +// caller. +func (ec EntryCaller) FullPath() string { if !ec.Defined { - return "" + return "undefined" } buf := bufferpool.Get() buf.AppendString(ec.File) @@ -89,6 +96,32 @@ func (ec EntryCaller) String() string { return caller } +// TrimmedPath returns a package/file:line description of the caller, +// preserving only the leaf directory name and file name. +func (ec EntryCaller) TrimmedPath() string { + if !ec.Defined { + return "undefined" + } + // Find the last separator. + idx := strings.LastIndexByte(ec.File, os.PathSeparator) + if idx == -1 { + return ec.FullPath() + } + // Find the penultimate separator. + idx = strings.LastIndexByte(ec.File[:idx], os.PathSeparator) + if idx == -1 { + return ec.FullPath() + } + buf := bufferpool.Get() + // Keep everything after the penultimate separator. + buf.AppendString(ec.File[idx+1:]) + buf.AppendByte(':') + buf.AppendInt(int64(ec.Line)) + caller := buf.String() + bufferpool.Put(buf) + return caller +} + // An Entry represents a complete log message. The entry's structured context // is already serialized, but the log level, time, message, and call site // information are available for inspection and modification. diff --git a/zapcore/entry_test.go b/zapcore/entry_test.go index 1198b5db9..569c4e1e0 100644 --- a/zapcore/entry_test.go +++ b/zapcore/entry_test.go @@ -59,18 +59,31 @@ func TestPutNilEntry(t *testing.T) { func TestEntryCaller(t *testing.T) { tests := []struct { - ok bool - want EntryCaller - str string + caller EntryCaller + full string + short string }{ - {true, EntryCaller{PC: 100, Defined: true, File: "foo.go", Line: 42}, "foo.go:42"}, - {false, EntryCaller{}, ""}, + { + caller: NewEntryCaller(100, "/path/to/foo.go", 42, false), + full: "undefined", + short: "undefined", + }, + { + caller: NewEntryCaller(100, "/path/to/foo.go", 42, true), + full: "/path/to/foo.go:42", + short: "to/foo.go:42", + }, + { + caller: NewEntryCaller(100, "to/foo.go", 42, true), + full: "to/foo.go:42", + short: "to/foo.go:42", + }, } for _, tt := range tests { - caller := NewEntryCaller(100, "foo.go", 42, tt.ok) - assert.Equal(t, tt.want, caller, "Unexpected output from NewEntryCaller.") - assert.Equal(t, tt.str, caller.String(), "Unexpected string output from EntryCaller") + assert.Equal(t, tt.full, tt.caller.String(), "Unexpected string from EntryCaller.") + assert.Equal(t, tt.full, tt.caller.FullPath(), "Unexpected FullPath from EntryCaller.") + assert.Equal(t, tt.short, tt.caller.TrimmedPath(), "Unexpected TrimmedPath from EntryCaller.") } } From 308e32efc1675194a1010fafc94b5a833939c114 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Tue, 14 Mar 2017 10:50:18 -0700 Subject: [PATCH 4/5] Use EncodeCaller in console encoder --- config_test.go | 10 +++++----- zapcore/console_encoder.go | 35 +++++++++-------------------------- zapcore/encoder_test.go | 28 ++++++++++++++-------------- 3 files changed, 28 insertions(+), 45 deletions(-) diff --git a/config_test.go b/config_test.go index 293f87151..65bcfb112 100644 --- a/config_test.go +++ b/config_test.go @@ -40,16 +40,16 @@ func TestConfig(t *testing.T) { desc: "production", cfg: NewProductionConfig(), expectN: 2 + 100 + 1, // 2 from initial logs, 100 initial sampled logs, 1 from off-by-one in sampler - expectRe: `{"level":"info","caller":".*/go.uber.org/zap/config_test.go:\d+","msg":"info","k":"v","z":"zz"}` + "\n" + - `{"level":"warn","caller":".*/go.uber.org/zap/config_test.go:\d+","msg":"warn","k":"v","z":"zz"}` + "\n", + expectRe: `{"level":"info","caller":"zap/config_test.go:\d+","msg":"info","k":"v","z":"zz"}` + "\n" + + `{"level":"warn","caller":"zap/config_test.go:\d+","msg":"warn","k":"v","z":"zz"}` + "\n", }, { desc: "development", cfg: NewDevelopmentConfig(), expectN: 3 + 200, // 3 initial logs, all 200 subsequent logs - expectRe: "DEBUG\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" + - "INFO\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" + - "WARN\t.*go.uber.org/zap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" + + expectRe: "DEBUG\tzap/config_test.go:" + `\d+` + "\tdebug\t" + `{"k": "v", "z": "zz"}` + "\n" + + "INFO\tzap/config_test.go:" + `\d+` + "\tinfo\t" + `{"k": "v", "z": "zz"}` + "\n" + + "WARN\tzap/config_test.go:" + `\d+` + "\twarn\t" + `{"k": "v", "z": "zz"}` + "\n" + `go.uber.org/zap.Stack`, }, } diff --git a/zapcore/console_encoder.go b/zapcore/console_encoder.go index 65cb7860a..724fa15c1 100644 --- a/zapcore/console_encoder.go +++ b/zapcore/console_encoder.go @@ -66,19 +66,25 @@ func (c consoleEncoder) Clone() Encoder { func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, error) { line := bufferpool.Get() - // We don't want the date and level to be quoted and escaped (if they're + // We don't want the entry's metadata to be quoted and escaped (if it's // encoded as strings), which means that we can't use the JSON encoder. The // simplest option is to use the memory encoder and fmt.Fprint. // // If this ever becomes a performance bottleneck, we can implement // ArrayEncoder for our plain-text format. arr := getSliceEncoder() - if c.TimeKey != "" { + if c.TimeKey != "" && c.EncodeTime != nil { c.EncodeTime(ent.Time, arr) } - if c.LevelKey != "" { + if c.LevelKey != "" && c.EncodeLevel != nil { c.EncodeLevel(ent.Level, arr) } + if ent.LoggerName != "" && c.NameKey != "" { + arr.AppendString(ent.LoggerName) + } + if ent.Caller.Defined && c.CallerKey != "" && c.EncodeCaller != nil { + c.EncodeCaller(ent.Caller, arr) + } for i := range arr.elems { if i > 0 { line.AppendByte('\t') @@ -87,9 +93,6 @@ func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, } putSliceEncoder(arr) - // Compose the logger name and caller info into a call site and add it. - c.writeCallSite(line, ent.LoggerName, ent.Caller) - // Add the message itself. if c.MessageKey != "" { c.addTabIfNecessary(line) @@ -110,26 +113,6 @@ func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, return line, nil } -func (c consoleEncoder) writeCallSite(line *buffer.Buffer, name string, caller EntryCaller) { - shouldWriteName := name != "" && c.NameKey != "" - shouldWriteCaller := caller.Defined && c.CallerKey != "" - if !shouldWriteName && !shouldWriteCaller { - return - } - c.addTabIfNecessary(line) - if shouldWriteName { - line.AppendString(name) - if shouldWriteCaller { - line.AppendByte('@') - } - } - if shouldWriteCaller { - line.AppendString(caller.File) - line.AppendByte(':') - line.AppendInt(int64(caller.Line)) - } -} - func (c consoleEncoder) writeContext(line *buffer.Buffer, extra []Field) { context := c.jsonEncoder.Clone().(*jsonEncoder) defer bufferpool.Put(context.buf) diff --git a/zapcore/encoder_test.go b/zapcore/encoder_test.go index adb9f1fe3..c9b57d8c8 100644 --- a/zapcore/encoder_test.go +++ b/zapcore/encoder_test.go @@ -92,7 +92,7 @@ func TestEncoderConfiguration(t *testing.T) { return ent }, expectedJSON: `{"level":"info","ts":0,"name":"main","caller":"foo.go:42","msg":"hello\\","stacktrace":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello\\\nfake-stack", + expectedConsole: "0\tinfo\tmain\tfoo.go:42\thello\\\nfake-stack", }, { desc: "use custom entry keys in JSON output and ignore them in console output", @@ -109,7 +109,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello\nfake-stack", + expectedConsole: "0\tinfo\tmain\tfoo.go:42\thello\nfake-stack", }, { desc: "skip level if LevelKey is omitted", @@ -126,7 +126,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, - expectedConsole: "0\tmain@foo.go:42\thello\nfake-stack", + expectedConsole: "0\tmain\tfoo.go:42\thello\nfake-stack", }, { desc: "skip timestamp if TimeKey is omitted", @@ -143,7 +143,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, - expectedConsole: "info\tmain@foo.go:42\thello\nfake-stack", + expectedConsole: "info\tmain\tfoo.go:42\thello\nfake-stack", }, { desc: "skip message if MessageKey is omitted", @@ -160,7 +160,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","S":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\nfake-stack", + expectedConsole: "0\tinfo\tmain\tfoo.go:42\nfake-stack", }, { desc: "skip name if NameKey is omitted", @@ -211,7 +211,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello", + expectedConsole: "0\tinfo\tmain\tfoo.go:42\thello", }, { desc: "use the supplied EncodeTime, for both the entry and any times added", @@ -235,7 +235,7 @@ func TestEncoderConfiguration(t *testing.T) { })) }, expectedJSON: `{"L":"info","T":"1970-01-01 00:00:00 +0000 UTC","N":"main","C":"foo.go:42","M":"hello","extra":"1970-01-01 00:00:00 +0000 UTC","extras":["1970-01-01 00:00:00 +0000 UTC"],"S":"fake-stack"}`, - expectedConsole: "1970-01-01 00:00:00 +0000 UTC\tinfo\tmain@foo.go:42\thello\t" + // plain-text preamble + expectedConsole: "1970-01-01 00:00:00 +0000 UTC\tinfo\tmain\tfoo.go:42\thello\t" + // plain-text preamble `{"extra": "1970-01-01 00:00:00 +0000 UTC", "extras": ["1970-01-01 00:00:00 +0000 UTC"]}` + // JSON context "\nfake-stack", // stacktrace after newline }, @@ -261,7 +261,7 @@ func TestEncoderConfiguration(t *testing.T) { })) }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","extra":"1s","extras":["1m0s"],"S":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello\t" + // preamble + expectedConsole: "0\tinfo\tmain\tfoo.go:42\thello\t" + // preamble `{"extra": "1s", "extras": ["1m0s"]}` + // context "\nfake-stack", // stacktrace }, @@ -280,7 +280,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"INFO","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, - expectedConsole: "0\tINFO\tmain@foo.go:42\thello\nfake-stack", + expectedConsole: "0\tINFO\tmain\tfoo.go:42\thello\nfake-stack", }, { desc: "close all open namespaces", @@ -303,7 +303,7 @@ func TestEncoderConfiguration(t *testing.T) { enc.OpenNamespace("innermost") }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","outer":{"inner":{"foo":"bar","innermost":{}}},"S":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello\t" + + expectedConsole: "0\tinfo\tmain\tfoo.go:42\thello\t" + `{"outer": {"inner": {"foo": "bar", "innermost": {}}}}` + "\nfake-stack", }, @@ -323,7 +323,7 @@ func TestEncoderConfiguration(t *testing.T) { }, extra: func(enc Encoder) { enc.AddTime("sometime", time.Unix(0, 100)) }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","sometime":100,"S":"fake-stack"}`, - expectedConsole: "info\tmain@foo.go:42\thello\t" + `{"sometime": 100}` + "\nfake-stack", + expectedConsole: "info\tmain\tfoo.go:42\thello\t" + `{"sometime": 100}` + "\nfake-stack", }, { desc: "handle no-op EncodeDuration", @@ -341,7 +341,7 @@ func TestEncoderConfiguration(t *testing.T) { }, extra: func(enc Encoder) { enc.AddDuration("someduration", time.Microsecond) }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","someduration":1000,"S":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello\t" + `{"someduration": 1000}` + "\nfake-stack", + expectedConsole: "0\tinfo\tmain\tfoo.go:42\thello\t" + `{"someduration": 1000}` + "\nfake-stack", }, { desc: "handle no-op EncodeLevel", @@ -358,7 +358,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: base.EncodeCaller, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, - expectedConsole: "0\tmain@foo.go:42\thello\nfake-stack", + expectedConsole: "0\tmain\tfoo.go:42\thello\nfake-stack", }, { desc: "handle no-op EncodeCaller", @@ -375,7 +375,7 @@ func TestEncoderConfiguration(t *testing.T) { EncodeCaller: func(EntryCaller, PrimitiveArrayEncoder) {}, }, expectedJSON: `{"L":"info","T":0,"N":"main","C":"foo.go:42","M":"hello","S":"fake-stack"}`, - expectedConsole: "0\tinfo\tmain@foo.go:42\thello\nfake-stack", + expectedConsole: "0\tinfo\tmain\thello\nfake-stack", }, } From ac0e3e2ebbb58675e132bf8782c59b8dbca45040 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Tue, 14 Mar 2017 11:03:00 -0700 Subject: [PATCH 5/5] Update comment --- zapcore/encoder.go | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/zapcore/encoder.go b/zapcore/encoder.go index 54a814423..854b2572b 100644 --- a/zapcore/encoder.go +++ b/zapcore/encoder.go @@ -194,12 +194,12 @@ func (e *CallerEncoder) UnmarshalText(text []byte) error { // An EncoderConfig allows users to configure the concrete encoders supplied by // zapcore. type EncoderConfig struct { - // Set the keys used for each log entry. - MessageKey string `json:"messageKey" yaml:"messageKey"` - LevelKey string `json:"levelKey" yaml:"levelKey"` - TimeKey string `json:"timeKey" yaml:"timeKey"` - NameKey string `json:"nameKey" yaml:"nameKey"` - // CallerKey sets key for caller. If empty, caller is not logged. + // Set the keys used for each log entry. If any key is empty, that portion + // of the entry is omitted. + MessageKey string `json:"messageKey" yaml:"messageKey"` + LevelKey string `json:"levelKey" yaml:"levelKey"` + TimeKey string `json:"timeKey" yaml:"timeKey"` + NameKey string `json:"nameKey" yaml:"nameKey"` CallerKey string `json:"callerKey" yaml:"callerKey"` StacktraceKey string `json:"stacktraceKey" yaml:"stacktraceKey"` // Configure the primitive representations of common complex types. For