Add hook support (rs#24)

openk8sai · Dec 1, 2017 · c3d0268 · c3d0268
1 parent 1251b38
commit c3d0268
Show file tree

Hide file tree

Showing 11 changed files with 439 additions and 26 deletions.
diff --git a/README.md b/README.md
@@ -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
 

diff --git a/event.go b/event.go
@@ -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.

diff --git a/hook.go b/hook.go
@@ -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{}
+}
diff --git a/hook_test.go b/hook_test.go
@@ -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("")
+			}
+		})
+	})
+}