From 6a6144a10bde51f04fcdb0fbb0c50bca28a025f5 Mon Sep 17 00:00:00 2001 From: Olivier Poitrey Date: Sat, 20 May 2017 01:48:00 -0700 Subject: [PATCH] Add http.Handler helpers (adapted from xlog) --- README.md | 43 ++++++++++ ctx.go | 11 ++- ctx_test.go | 8 ++ hlog/hlog.go | 154 +++++++++++++++++++++++++++++++++ hlog/hlog_example_test.go | 51 +++++++++++ hlog/hlog_test.go | 173 ++++++++++++++++++++++++++++++++++++++ log.go | 2 +- 7 files changed, 438 insertions(+), 4 deletions(-) create mode 100644 hlog/hlog.go create mode 100644 hlog/hlog_example_test.go create mode 100644 hlog/hlog_test.go diff --git a/README.md b/README.md index 8edbeda..b43dbd9 100644 --- a/README.md +++ b/README.md @@ -9,6 +9,8 @@ The zerolog package provides a fast and simple logger dedicated to JSON output. * Level logging * Sampling * Contextual fields +* `context.Context` integration +* `net/http` helpers ## Performance @@ -200,6 +202,47 @@ log.Ctx(ctx).Info().Msg("hello world") // Output: {"component":"module","level":"info","message":"hello world"} ``` +### Integration with `net/http` + +The `github.com/rs/zerolog/hlog` package provides some helpers to integrate zerolog with `http.Handler`. + +In this example we use [alice](github.com/justinas/alice) to install logger for better readability. + +```go +log := zerolog.New(os.Stdout).With(). + Str("role", "my-service"). + Str("host", host). + Logger() + +c := alice.New() + +// Install the logger handler with default output on the console +c = c.Append(hlog.NewHandler(log)) + +// Install some provided extra handler to set some request's context fields. +// Thanks to those handler, all our logs will come with some pre-populated fields. +c = c.Append(hlog.RemoteAddrHandler("ip")) +c = c.Append(hlog.UserAgentHandler("user_agent")) +c = c.Append(hlog.RefererHandler("referer")) +c = c.Append(hlog.RequestIDHandler("req_id", "Request-Id")) + +// Here is your final handler +h := c.Then(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // Get the logger from the request's context. You can safely assume it + // will be always there: if the handler is removed, hlog.FromRequest + // will return a no-op logger. + hlog.FromRequest(r).Info(). + Str("user", "current user"). + Str("status", "ok"). + Msg("Something happend") +})) +http.Handle("/", h) + +if err := http.ListenAndServe(":8080", nil); err != nil { + log.Fatal().Err(err).Msg("Startup failed") +} +``` + ## Global Settings Some settings can be changed and will by applied to all loggers: diff --git a/ctx.go b/ctx.go index 4abf062..034eccd 100644 --- a/ctx.go +++ b/ctx.go @@ -11,14 +11,19 @@ type ctxKey struct{} // WithContext returns a copy of ctx with l associated. func (l Logger) WithContext(ctx context.Context) context.Context { - return context.WithValue(ctx, ctxKey{}, l) + if lp, ok := ctx.Value(ctxKey{}).(*Logger); ok { + // Update existing pointer. + *lp = l + return ctx + } + return context.WithValue(ctx, ctxKey{}, &l) } // Ctx returns the Logger associated with the ctx. If no logger // is associated, a disabled logger is returned. func Ctx(ctx context.Context) Logger { - if l, ok := ctx.Value(ctxKey{}).(Logger); ok { - return l + if l, ok := ctx.Value(ctxKey{}).(*Logger); ok { + return *l } return disabledLogger } diff --git a/ctx_test.go b/ctx_test.go index dc9943f..b5a05da 100644 --- a/ctx_test.go +++ b/ctx_test.go @@ -15,6 +15,14 @@ func TestCtx(t *testing.T) { t.Error("Ctx did not return the expected logger") } + // update + log = log.Level(InfoLevel) + ctx = log.WithContext(ctx) + log2 = Ctx(ctx) + if !reflect.DeepEqual(log, log2) { + t.Error("Ctx did not return the expected logger") + } + log2 = Ctx(context.Background()) if !reflect.DeepEqual(log2, disabledLogger) { t.Error("Ctx did not return the expected logger") diff --git a/hlog/hlog.go b/hlog/hlog.go new file mode 100644 index 0000000..40bb669 --- /dev/null +++ b/hlog/hlog.go @@ -0,0 +1,154 @@ +// Package hlog provides a set of http.Handler helpers for zerolog. +package hlog + +import ( + "context" + "net" + "net/http" + + "github.com/rs/xid" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +// FromRequest gets the logger in the request's context. +// This is a shortcut for log.Ctx(r.Context()) +func FromRequest(r *http.Request) zerolog.Logger { + return log.Ctx(r.Context()) +} + +// NewHandler injects log into requests context. +func NewHandler(log zerolog.Logger) func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + r = r.WithContext(log.WithContext(r.Context())) + next.ServeHTTP(w, r) + }) + } +} + +// URLHandler adds the requested URL as a field to the context's logger +// using fieldKey as field key. +func URLHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, r.URL.String()).Logger() + r = r.WithContext(log.WithContext(r.Context())) + next.ServeHTTP(w, r) + }) + } +} + +// MethodHandler adds the request method as a field to the context's logger +// using fieldKey as field key. +func MethodHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, r.Method).Logger() + r = r.WithContext(log.WithContext(r.Context())) + next.ServeHTTP(w, r) + }) + } +} + +// RequestHandler adds the request method and URL as a field to the context's logger +// using fieldKey as field key. +func RequestHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, r.Method+" "+r.URL.String()).Logger() + r = r.WithContext(log.WithContext(r.Context())) + next.ServeHTTP(w, r) + }) + } +} + +// RemoteAddrHandler adds the request's remote address as a field to the context's logger +// using fieldKey as field key. +func RemoteAddrHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if host, _, err := net.SplitHostPort(r.RemoteAddr); err == nil { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, host).Logger() + r = r.WithContext(log.WithContext(r.Context())) + } + next.ServeHTTP(w, r) + }) + } +} + +// UserAgentHandler adds the request's user-agent as a field to the context's logger +// using fieldKey as field key. +func UserAgentHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if ua := r.Header.Get("User-Agent"); ua != "" { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, ua).Logger() + r = r.WithContext(log.WithContext(r.Context())) + } + next.ServeHTTP(w, r) + }) + } +} + +// RefererHandler adds the request's referer as a field to the context's logger +// using fieldKey as field key. +func RefererHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if ref := r.Header.Get("Referer"); ref != "" { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, ref).Logger() + r = r.WithContext(log.WithContext(r.Context())) + } + next.ServeHTTP(w, r) + }) + } +} + +type idKey struct{} + +// IDFromRequest returns the unique id accociated to the request if any. +func IDFromRequest(r *http.Request) (id xid.ID, ok bool) { + if r == nil { + return + } + id, ok = r.Context().Value(idKey{}).(xid.ID) + return +} + +// RequestIDHandler returns a handler setting a unique id to the request which can +// be gathered using IDFromRequest(req). This generated id is added as a field to the +// logger using the passed fieldKey as field name. The id is also added as a response +// header if the headerName is not empty. +// +// The generated id is a URL safe base64 encoded mongo object-id-like unique id. +// Mongo unique id generation algorithm has been selected as a trade-off between +// size and ease of use: UUID is less space efficient and snowflake requires machine +// configuration. +func RequestIDHandler(fieldKey, headerName string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + id, ok := IDFromRequest(r) + if !ok { + id = xid.New() + ctx := context.WithValue(r.Context(), idKey{}, id) + r = r.WithContext(ctx) + } + if fieldKey != "" { + log := zerolog.Ctx(r.Context()) + log = log.With().Str(fieldKey, id.String()).Logger() + r = r.WithContext(log.WithContext(r.Context())) + } + if headerName != "" { + w.Header().Set(headerName, id.String()) + } + next.ServeHTTP(w, r) + }) + } +} diff --git a/hlog/hlog_example_test.go b/hlog/hlog_example_test.go new file mode 100644 index 0000000..3617a3e --- /dev/null +++ b/hlog/hlog_example_test.go @@ -0,0 +1,51 @@ +package hlog_test + +import ( + "net/http" + "os" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/hlog" +) + +// fake alice to avoid dep +type alice struct{} + +func (a alice) Append(interface{}) alice { return a } +func (alice) Then(h http.Handler) http.Handler { return h } + +func Example_handler() { + host, _ := os.Hostname() + log := zerolog.New(os.Stdout).With(). + Str("role", "my-service"). + Str("host", host). + Logger() + + c := alice{} + + // Install the logger handler with default output on the console + c = c.Append(hlog.NewHandler(log)) + + // Install some provided extra handler to set some request's context fields. + // Thanks to those handler, all our logs will come with some pre-populated fields. + c = c.Append(hlog.RemoteAddrHandler("ip")) + c = c.Append(hlog.UserAgentHandler("user_agent")) + c = c.Append(hlog.RefererHandler("referer")) + c = c.Append(hlog.RequestIDHandler("req_id", "Request-Id")) + + // Here is your final handler + h := c.Then(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // Get the logger from the request's context. You can safely assume it + // will be always there: if the handler is removed, hlog.FromRequest + // will return a no-op logger. + hlog.FromRequest(r).Info(). + Str("user", "current user"). + Str("status", "ok"). + Msg("Something happend") + })) + http.Handle("/", h) + + if err := http.ListenAndServe(":8080", nil); err != nil { + log.Fatal().Err(err).Msg("Startup failed") + } +} diff --git a/hlog/hlog_test.go b/hlog/hlog_test.go new file mode 100644 index 0000000..2654ecc --- /dev/null +++ b/hlog/hlog_test.go @@ -0,0 +1,173 @@ +// +build go1.7 + +package hlog + +import ( + "bytes" + "fmt" + "net/http" + "net/url" + "testing" + + "reflect" + + "net/http/httptest" + + "github.com/rs/zerolog" +) + +func TestNewHandler(t *testing.T) { + log := zerolog.New(nil).With(). + Str("foo", "bar"). + Logger() + lh := NewHandler(log) + h := lh(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + if !reflect.DeepEqual(l, log) { + t.Fail() + } + })) + h.ServeHTTP(nil, &http.Request{}) +} + +func TestURLHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + URL: &url.URL{Path: "/path", RawQuery: "foo=bar"}, + } + h := URLHandler("url")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"url":"/path?foo=bar"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestMethodHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + Method: "POST", + } + h := MethodHandler("method")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"method":"POST"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestRequestHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + Method: "POST", + URL: &url.URL{Path: "/path", RawQuery: "foo=bar"}, + } + h := RequestHandler("request")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"request":"POST /path?foo=bar"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestRemoteAddrHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + RemoteAddr: "1.2.3.4:1234", + } + h := RemoteAddrHandler("ip")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"ip":"1.2.3.4"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestRemoteAddrHandlerIPv6(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + RemoteAddr: "[2001:db8:a0b:12f0::1]:1234", + } + h := RemoteAddrHandler("ip")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"ip":"2001:db8:a0b:12f0::1"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestUserAgentHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + Header: http.Header{ + "User-Agent": []string{"some user agent string"}, + }, + } + h := UserAgentHandler("ua")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"ua":"some user agent string"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestRefererHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + Header: http.Header{ + "Referer": []string{"http://foo.com/bar"}, + }, + } + h := RefererHandler("referer")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + l := FromRequest(r) + l.Log().Msg("") + if want, got := `{"referer":"http://foo.com/bar"}`+"\n", out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(nil, r) +} + +func TestRequestIDHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + Header: http.Header{ + "Referer": []string{"http://foo.com/bar"}, + }, + } + h := RequestIDHandler("id", "Request-Id")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + id, ok := IDFromRequest(r) + if !ok { + t.Fatal("Missing id in request") + } + if want, got := id.String(), w.Header().Get("Request-Id"); got != want { + t.Errorf("Invalid Request-Id header, got: %s, want: %s", got, want) + } + l := FromRequest(r) + l.Log().Msg("") + if want, got := fmt.Sprintf(`{"id":"%s"}`+"\n", id), out.String(); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } + })) + h = NewHandler(zerolog.New(out))(h) + h.ServeHTTP(httptest.NewRecorder(), r) +} diff --git a/log.go b/log.go index 94fbaca..ab50cec 100644 --- a/log.go +++ b/log.go @@ -145,7 +145,7 @@ type Logger struct { // you may consider using sync wrapper. func New(w io.Writer) Logger { if w == nil { - panic("w is nil") + w = ioutil.Discard } lw, ok := w.(LevelWriter) if !ok {