Add hook support (#24)

This commit is contained in:
Rodrigo Coelho 2017-12-01 15:52:37 -02:00 committed by Olivier Poitrey
parent 1251b38a89
commit c3d02683c7
11 changed files with 439 additions and 26 deletions

View File

@ -18,6 +18,7 @@ To keep the code base and the API simple, zerolog focuses on JSON logging only.
* Low to zero allocation
* Level logging
* Sampling
* Hooks
* Contextual fields
* `context.Context` integration
* `net/http` helpers
@ -185,6 +186,22 @@ sampled.Debug().Msg("hello world")
// Output: {"time":1494567715,"level":"debug","message":"hello world"}
```
### Hooks
```go
type SeverityHook struct{}
func (h SeverityHook) Run(e *zerolog.Event, level zerolog.Level, msg string) {
if level != zerolog.NoLevel {
e.Str("severity", level.String())
}
}
hooked := log.Hook(SeverityHook{})
hooked.Warn().Msg("")
// Output: {"level":"warn","severity":"warn"}
```
### Pass a sub-logger by context

View File

@ -25,6 +25,7 @@ type Event struct {
w LevelWriter
level Level
done func(msg string)
h []Hook
}
// LogObjectMarshaler provides a strongly-typed and encoding-agnostic interface
@ -45,6 +46,7 @@ func newEvent(w LevelWriter, level Level, enabled bool) *Event {
}
e := eventPool.Get().(*Event)
e.buf = e.buf[:1]
e.h = e.h[:0]
e.buf[0] = '{'
e.w = w
e.level = level
@ -75,6 +77,14 @@ func (e *Event) Msg(msg string) {
if e == nil {
return
}
if len(e.h) > 0 {
e.h[0].Run(e, e.level, msg)
if len(e.h) > 1 {
for _, hook := range e.h[1:] {
hook.Run(e, e.level, msg)
}
}
}
if msg != "" {
e.buf = json.AppendString(json.AppendKey(e.buf, MessageFieldName), msg)
}
@ -94,16 +104,7 @@ func (e *Event) Msgf(format string, v ...interface{}) {
if e == nil {
return
}
msg := fmt.Sprintf(format, v...)
if msg != "" {
e.buf = json.AppendString(json.AppendKey(e.buf, MessageFieldName), msg)
}
if e.done != nil {
defer e.done(msg)
}
if err := e.write(); err != nil {
fmt.Fprintf(os.Stderr, "zerolog: could not write event: %v", err)
}
e.Msg(fmt.Sprintf(format, v...))
}
// Fields is a helper function to use a map to set fields using type assertion.

51
hook.go Normal file
View File

@ -0,0 +1,51 @@
package zerolog
// Hook defines an interface to a log hook.
type Hook interface {
// Run runs the hook with the event.
Run(e *Event, level Level, message string)
}
// LevelHook applies a different hook for each level.
type LevelHook struct {
NoLevelHook, DebugHook, InfoHook, WarnHook, ErrorHook, FatalHook, PanicHook Hook
}
// Run implements the Hook interface.
func (h LevelHook) Run(e *Event, level Level, message string) {
switch level {
case DebugLevel:
if h.DebugHook != nil {
h.DebugHook.Run(e, level, message)
}
case InfoLevel:
if h.InfoHook != nil {
h.InfoHook.Run(e, level, message)
}
case WarnLevel:
if h.WarnHook != nil {
h.WarnHook.Run(e, level, message)
}
case ErrorLevel:
if h.ErrorHook != nil {
h.ErrorHook.Run(e, level, message)
}
case FatalLevel:
if h.FatalHook != nil {
h.FatalHook.Run(e, level, message)
}
case PanicLevel:
if h.PanicHook != nil {
h.PanicHook.Run(e, level, message)
}
case NoLevel:
if h.NoLevelHook != nil {
h.NoLevelHook.Run(e, level, message)
}
}
}
// NewLevelHook returns a new LevelHook.
func NewLevelHook() LevelHook {
return LevelHook{}
}

236
hook_test.go Normal file
View File

@ -0,0 +1,236 @@
package zerolog
import (
"testing"
"bytes"
"io/ioutil"
)
type LevelNameHook struct{}
func (h LevelNameHook) Run(e *Event, level Level, msg string) {
levelName := level.String()
if level == NoLevel {
levelName = "nolevel"
}
e.Str("level_name", levelName)
}
type SimpleHook struct{}
func (h SimpleHook) Run(e *Event, level Level, msg string) {
e.Bool("has_level", level != NoLevel)
e.Str("test", "logged")
}
type CopyHook struct{}
func (h CopyHook) Run(e *Event, level Level, msg string) {
hasLevel := level != NoLevel
e.Bool("copy_has_level", hasLevel)
if hasLevel {
e.Str("copy_level", level.String())
}
e.Str("copy_msg", msg)
}
type NopHook struct{}
func (h NopHook) Run(e *Event, level Level, msg string) {
}
var (
levelNameHook LevelNameHook
simpleHook SimpleHook
copyHook CopyHook
nopHook NopHook
)
func TestHook(t *testing.T) {
t.Run("Message", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook)
log.Log().Msg("test message")
if got, want := out.String(), `{"level_name":"nolevel","message":"test message"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("NoLevel", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook)
log.Log().Msg("")
if got, want := out.String(), `{"level_name":"nolevel"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Print", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook)
log.Print("")
if got, want := out.String(), `{"level":"debug","level_name":"debug"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Error", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Copy/1", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(copyHook)
log.Log().Msg("")
if got, want := out.String(), `{"copy_has_level":false,"copy_msg":""}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Copy/2", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(copyHook)
log.Info().Msg("a message")
if got, want := out.String(), `{"level":"info","copy_has_level":true,"copy_level":"info","copy_msg":"a message","message":"a message"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Multi", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook).Hook(simpleHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Multi/Message", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook).Hook(simpleHook)
log.Error().Msg("a message")
if got, want := out.String(), `{"level":"error","level_name":"error","has_level":true,"test":"logged","message":"a message"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Output/single/pre", func(t *testing.T) {
ignored := &bytes.Buffer{}
out := &bytes.Buffer{}
log := New(ignored).Hook(levelNameHook).Output(out)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Output/single/post", func(t *testing.T) {
ignored := &bytes.Buffer{}
out := &bytes.Buffer{}
log := New(ignored).Output(out).Hook(levelNameHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Output/multi/pre", func(t *testing.T) {
ignored := &bytes.Buffer{}
out := &bytes.Buffer{}
log := New(ignored).Hook(levelNameHook).Hook(simpleHook).Output(out)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Output/multi/post", func(t *testing.T) {
ignored := &bytes.Buffer{}
out := &bytes.Buffer{}
log := New(ignored).Output(out).Hook(levelNameHook).Hook(simpleHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Output/mixed", func(t *testing.T) {
ignored := &bytes.Buffer{}
out := &bytes.Buffer{}
log := New(ignored).Hook(levelNameHook).Output(out).Hook(simpleHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("With/single/pre", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook).With().Str("with", "pre").Logger()
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","with":"pre","level_name":"error"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("With/single/post", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).With().Str("with", "post").Logger().Hook(levelNameHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","with":"post","level_name":"error"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("With/multi/pre", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook).Hook(simpleHook).With().Str("with", "pre").Logger()
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","with":"pre","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("With/multi/post", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).With().Str("with", "post").Logger().Hook(levelNameHook).Hook(simpleHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","with":"post","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("With/mixed", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Hook(levelNameHook).With().Str("with", "mixed").Logger().Hook(simpleHook)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error","with":"mixed","level_name":"error","has_level":true,"test":"logged"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("None", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out)
log.Error().Msg("")
if got, want := out.String(), `{"level":"error"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
}
func BenchmarkHooks(b *testing.B) {
logger := New(ioutil.Discard)
b.ResetTimer()
b.Run("Nop/Single", func(b *testing.B) {
log := logger.Hook(nopHook)
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
log.Log().Msg("")
}
})
})
b.Run("Nop/Multi", func(b *testing.B) {
log := logger.Hook(nopHook).Hook(nopHook)
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
log.Log().Msg("")
}
})
})
b.Run("Simple", func(b *testing.B) {
log := logger.Hook(simpleHook)
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
log.Log().Msg("")
}
})
})
}

62
log.go
View File

@ -65,6 +65,23 @@
// sampled := log.Sample(&zerolog.BasicSampler{N: 10})
// sampled.Info().Msg("will be logged every 10 messages")
//
// Log with contextual hooks:
//
// // Create the hook:
// type SeverityHook struct{}
//
// func (h SeverityHook) Run(e *zerolog.Event, level zerolog.Level, msg string) {
// if level != zerolog.NoLevel {
// e.Str("severity", level.String())
// }
// }
//
// // And use it:
// var h SeverityHook
// log := zerolog.New(os.Stdout).Hook(h)
// log.Warn().Msg("")
// // Output: {"level":"warn","severity":"warn"}
//
package zerolog
import (
@ -93,6 +110,8 @@ const (
FatalLevel
// PanicLevel defines panic log level.
PanicLevel
// NoLevel defines an absent log level.
NoLevel
// Disabled disables the logger.
Disabled
)
@ -111,6 +130,8 @@ func (l Level) String() string {
return "fatal"
case PanicLevel:
return "panic"
case NoLevel:
return ""
}
return ""
}
@ -125,6 +146,7 @@ type Logger struct {
level Level
sampler Sampler
context []byte
hooks []Hook
}
// New creates a root logger with given output writer. If the output writer implements
@ -155,6 +177,9 @@ func (l Logger) Output(w io.Writer) Logger {
l2 := New(w)
l2.level = l.level
l2.sampler = l.sampler
if len(l.hooks) > 0 {
l2.hooks = append(l2.hooks, l.hooks...)
}
if l.context != nil {
l2.context = make([]byte, len(l.context), cap(l.context))
copy(l2.context, l.context)
@ -201,32 +226,38 @@ func (l Logger) Sample(s Sampler) Logger {
return l
}
// Hook returns a logger with the h Hook.
func (l Logger) Hook(h Hook) Logger {
l.hooks = append(l.hooks, h)
return l
}
// Debug starts a new message with debug level.
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Debug() *Event {
return l.newEvent(DebugLevel, true, nil)
return l.newEvent(DebugLevel, nil)
}
// Info starts a new message with info level.
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Info() *Event {
return l.newEvent(InfoLevel, true, nil)
return l.newEvent(InfoLevel, nil)
}
// Warn starts a new message with warn level.
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Warn() *Event {
return l.newEvent(WarnLevel, true, nil)
return l.newEvent(WarnLevel, nil)
}
// Error starts a new message with error level.
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Error() *Event {
return l.newEvent(ErrorLevel, true, nil)
return l.newEvent(ErrorLevel, nil)
}
// Fatal starts a new message with fatal level. The os.Exit(1) function
@ -234,7 +265,7 @@ func (l *Logger) Error() *Event {
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Fatal() *Event {
return l.newEvent(FatalLevel, true, func(msg string) { os.Exit(1) })
return l.newEvent(FatalLevel, func(msg string) { os.Exit(1) })
}
// Panic starts a new message with panic level. The message is also sent
@ -242,7 +273,7 @@ func (l *Logger) Fatal() *Event {
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Panic() *Event {
return l.newEvent(PanicLevel, true, func(msg string) { panic(msg) })
return l.newEvent(PanicLevel, func(msg string) { panic(msg) })
}
// WithLevel starts a new message with level.
@ -262,6 +293,8 @@ func (l *Logger) WithLevel(level Level) *Event {
return l.Fatal()
case PanicLevel:
return l.Panic()
case NoLevel:
return l.Log()
case Disabled:
return nil
default:
@ -274,9 +307,7 @@ func (l *Logger) WithLevel(level Level) *Event {
//
// You must call Msg on the returned event in order to send the event.
func (l *Logger) Log() *Event {
// We use panic level with addLevelField=false to make Log passthrough all
// levels except Disabled.
return l.newEvent(PanicLevel, false, nil)
return l.newEvent(NoLevel, nil)
}
// Print sends a log event using debug level and no extra field.
@ -307,22 +338,18 @@ func (l Logger) Write(p []byte) (n int, err error) {
return
}
func (l *Logger) newEvent(level Level, addLevelField bool, done func(string)) *Event {
func (l *Logger) newEvent(level Level, done func(string)) *Event {
enabled := l.should(level)
if !enabled {
return nil
}
lvl := InfoLevel
if addLevelField {
lvl = level
}
e := newEvent(l.w, lvl, true)
e := newEvent(l.w, level, true)
e.done = done
if l.context != nil && len(l.context) > 0 && l.context[0] > 0 {
// first byte of context is ts flag
e.buf = json.AppendTime(json.AppendKey(e.buf, TimestampFieldName), TimestampFunc(), TimeFieldFormat)
}
if addLevelField {
if level != NoLevel {
e.Str(LevelFieldName, level.String())
}
if l.context != nil && len(l.context) > 1 {
@ -331,6 +358,9 @@ func (l *Logger) newEvent(level Level, addLevelField bool, done func(string)) *E
}
e.buf = append(e.buf, l.context[1:]...)
}
if len(l.hooks) > 0 {
e.h = append(e.h, l.hooks...)
}
return e
}

View File

@ -32,6 +32,11 @@ func Sample(s zerolog.Sampler) zerolog.Logger {
return Logger.Sample(s)
}
// Hook returns a logger with the h Hook.
func Hook(h zerolog.Hook) zerolog.Logger {
return Logger.Hook(h)
}
// Debug starts a new message with debug level.
//
// You must call Msg on the returned event in order to send the event.

View File

@ -49,6 +49,33 @@ func ExampleLogger_Sample() {
// {"level":"info","message":"message 4"}
}
type LevelNameHook struct{}
func (h LevelNameHook) Run(e *zerolog.Event, l zerolog.Level, msg string) {
if l != zerolog.NoLevel {
e.Str("level_name", l.String())
} else {
e.Str("level_name", "NoLevel")
}
}
type MessageHook string
func (h MessageHook) Run(e *zerolog.Event, l zerolog.Level, msg string) {
e.Str("the_message", msg)
}
func ExampleLogger_Hook() {
var levelNameHook LevelNameHook
var messageHook MessageHook = "The message"
log := zerolog.New(os.Stdout).Hook(levelNameHook).Hook(messageHook)
log.Info().Msg("hello world")
// Output: {"level":"info","level_name":"info","the_message":"hello world","message":"hello world"}
}
func ExampleLogger_Print() {
log := zerolog.New(os.Stdout)

View File

@ -299,6 +299,42 @@ func TestLevel(t *testing.T) {
}
})
t.Run("NoLevel/Disabled", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Level(Disabled)
log.Log().Msg("test")
if got, want := out.String(), ""; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("NoLevel/Info", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Level(InfoLevel)
log.Log().Msg("test")
if got, want := out.String(), `{"message":"test"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("NoLevel/Panic", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Level(PanicLevel)
log.Log().Msg("test")
if got, want := out.String(), `{"message":"test"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("NoLevel/WithLevel", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Level(InfoLevel)
log.WithLevel(NoLevel).Msg("test")
if got, want := out.String(), `{"message":"test"}`+"\n"; got != want {
t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want)
}
})
t.Run("Info", func(t *testing.T) {
out := &bytes.Buffer{}
log := New(out).Level(InfoLevel)
@ -352,10 +388,12 @@ func TestLevelWriter(t *testing.T) {
log.Info().Msg("2")
log.Warn().Msg("3")
log.Error().Msg("4")
log.Log().Msg("nolevel-1")
log.WithLevel(DebugLevel).Msg("5")
log.WithLevel(InfoLevel).Msg("6")
log.WithLevel(WarnLevel).Msg("7")
log.WithLevel(ErrorLevel).Msg("8")
log.WithLevel(NoLevel).Msg("nolevel-2")
want := []struct {
l Level
@ -365,10 +403,12 @@ func TestLevelWriter(t *testing.T) {
{InfoLevel, `{"level":"info","message":"2"}` + "\n"},
{WarnLevel, `{"level":"warn","message":"3"}` + "\n"},
{ErrorLevel, `{"level":"error","message":"4"}` + "\n"},
{NoLevel, `{"message":"nolevel-1"}` + "\n"},
{DebugLevel, `{"level":"debug","message":"5"}` + "\n"},
{InfoLevel, `{"level":"info","message":"6"}` + "\n"},
{WarnLevel, `{"level":"warn","message":"7"}` + "\n"},
{ErrorLevel, `{"level":"error","message":"8"}` + "\n"},
{NoLevel, `{"message":"nolevel-2"}` + "\n"},
}
if got := lw.ops; !reflect.DeepEqual(got, want) {
t.Errorf("invalid ops:\ngot:\n%v\nwant:\n%v", got, want)

View File

@ -44,6 +44,8 @@ func (sw syslogWriter) WriteLevel(level Level, p []byte) (n int, err error) {
err = sw.w.Emerg(string(p))
case PanicLevel:
err = sw.w.Crit(string(p))
case NoLevel:
err = sw.w.Info(string(p))
default:
panic("invalid level")
}

View File

@ -48,11 +48,13 @@ func TestSyslogWriter(t *testing.T) {
log.Info().Msg("info")
log.Warn().Msg("warn")
log.Error().Msg("error")
log.Log().Msg("nolevel")
want := []syslogEvent{
{"Debug", `{"level":"debug","message":"debug"}` + "\n"},
{"Info", `{"level":"info","message":"info"}` + "\n"},
{"Warning", `{"level":"warn","message":"warn"}` + "\n"},
{"Err", `{"level":"error","message":"error"}` + "\n"},
{"Info", `{"message":"nolevel"}` + "\n"},
}
if got := sw.events; !reflect.DeepEqual(got, want) {
t.Errorf("Invalid syslog message routing: want %v, got %v", want, got)

View File

@ -14,11 +14,13 @@ func TestMultiSyslogWriter(t *testing.T) {
log.Info().Msg("info")
log.Warn().Msg("warn")
log.Error().Msg("error")
log.Log().Msg("nolevel")
want := []syslogEvent{
{"Debug", `{"level":"debug","message":"debug"}` + "\n"},
{"Info", `{"level":"info","message":"info"}` + "\n"},
{"Warning", `{"level":"warn","message":"warn"}` + "\n"},
{"Err", `{"level":"error","message":"error"}` + "\n"},
{"Info", `{"message":"nolevel"}` + "\n"},
}
if got := sw.events; !reflect.DeepEqual(got, want) {
t.Errorf("Invalid syslog message routing: want %v, got %v", want, got)