Add http.Handler helpers (adapted from xlog)

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:

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 {
+	if l, ok := ctx.Value(ctxKey{}).(*Logger); ok {
-		return l
+		return *l
 	}
 	return disabledLogger
 }

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

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)
+		})
+	}
+}

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

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)
+}

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 {