Simplify copies

Update request logger's context thru its pointer in order to avoid
multiple copies/allocations.

.travis.yml

@@ -7,4 +7,4 @@ matrix:
   allow_failures:
       - go: tip
 script:
-    go test -v -race -cpu=1,2,4 ./...
+  go test -v -race -cpu=1,2,4 -bench . -benchmem ./...

README.md

@@ -8,7 +8,9 @@ Zerolog's API is designed to provide both a great developer experience and stunn
 
 The uber's [zap](https://godoc.org/go.uber.org/zap) library pioneered this approach. Zerolog is taking this concept to the next level with simpler to use API and even better performance.
 
-To keep the code base and the API simple, zerolog focuses on JSON logging only. Pretty logging on the console is made possible using the provided `zerolog.ConsoleWriter`.
+To keep the code base and the API simple, zerolog focuses on JSON logging only. Pretty logging on the console is made possible using the provided (but inefficient) `zerolog.ConsoleWriter`.
+
+![](pretty.png)
 
 ## Features
 
@@ -29,6 +31,13 @@ import "github.com/rs/zerolog/log"
 
 ### A global logger can be use for simple logging
 
+```go
+log.Print("hello world")
+
+// Output: {"level":"debug","time":1494567715,"message":"hello world"}
+```
+
+
 ```go
 log.Info().Msg("hello world")
 
@@ -152,12 +161,31 @@ log.Logger = log.With().Str("foo", "bar").Logger()
 ### Log Sampling
 
 ```go
-sampled := log.Sample(10)
+sampled := log.Sample(&zerolog.BasicSampler{N: 10})
 sampled.Info().Msg("will be logged every 10 messages")
 
-// Output: {"time":1494567715,"sample":10,"message":"will be logged every 10 messages"}
+// Output: {"time":1494567715,"level":"info","message":"will be logged every 10 messages"}
 ```
 
+More advanced sampling:
+
+```go
+// Will let 5 debug messages per period of 1 second.
+// Over 5 debug message, 1 every 100 debug messages are logged.
+// Other levels are not sampled.
+sampled := log.Sample(zerolog.LevelSampler{
+    DebugSampler: &zerolog.BurstSampler{
+        Burst: 5,
+        Period: 1*time.Second,
+        NextSampler: &zerolog.BasicSampler{N: 100},
+    },
+})
+sampled.Debug().Msg("hello world")
+
+// Output: {"time":1494567715,"level":"debug","message":"hello world"}
+```
+
+
 ### Pass a sub-logger by context
 
 ```go
@@ -247,7 +275,6 @@ Some settings can be changed and will by applied to all loggers:
 * `zerolog.LevelFieldName`: Can be set to customize level field name.
 * `zerolog.MessageFieldName`: Can be set to customize message field name.
 * `zerolog.ErrorFieldName`: Can be set to customize `Err` field name.
-* `zerolog.SampleFieldName`: Can be set to customize the field name added when sampling is enabled.
 * `zerolog.TimeFieldFormat`: Can be set to customize `Time` field value formatting. If set with an empty string, times are formated as UNIX timestamp.
 	// DurationFieldUnit defines the unit for time.Duration type fields added
 	// using the Dur method.
@@ -273,7 +300,7 @@ Some settings can be changed and will by applied to all loggers:
 * `Dict`: Adds a sub-key/value as a field of the event.
 * `Interface`: Uses reflection to marshal the type.
 
-## Performance
+## Benchmarks
 
 All operations are allocation free (those numbers *include* JSON encoding):
 
@@ -285,7 +312,12 @@ BenchmarkContextFields-8   30000000	    44.9 ns/op	   0 B/op       0 allocs/op
 BenchmarkLogFields-8       10000000	   184 ns/op	   0 B/op       0 allocs/op
 ```
 
-Using Uber's zap [comparison benchmark](https://github.com/uber-go/zap#performance):
+There are a few Go logging benchmarks and comparisons that include zerolog.
+
+- [imkira/go-loggers-bench](https://github.com/imkira/go-loggers-bench)
+- [uber-common/zap](https://github.com/uber-go/zap#performance)
+
+Using Uber's zap comparison benchmark:
 
 Log a message and 10 fields:
 

benchmark_test.go

@@ -57,6 +57,18 @@ func BenchmarkContextFields(b *testing.B) {
 	})
 }
 
+func BenchmarkContextAppend(b *testing.B) {
+	logger := New(ioutil.Discard).With().
+		Str("foo", "bar").
+		Logger()
+	b.ResetTimer()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			logger.With().Str("bar", "baz")
+		}
+	})
+}
+
 func BenchmarkLogFields(b *testing.B) {
 	logger := New(ioutil.Discard)
 	b.ResetTimer()

console.go

@@ -0,0 +1,117 @@
+package zerolog
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"io"
+	"sort"
+	"strconv"
+	"strings"
+	"sync"
+)
+
+const (
+	cReset    = 0
+	cBold     = 1
+	cRed      = 31
+	cGreen    = 32
+	cYellow   = 33
+	cBlue     = 34
+	cMagenta  = 35
+	cCyan     = 36
+	cGray     = 37
+	cDarkGray = 90
+)
+
+var consoleBufPool = sync.Pool{
+	New: func() interface{} {
+		return bytes.NewBuffer(make([]byte, 0, 100))
+	},
+}
+
+// ConsoleWriter reads a JSON object per write operation and output an
+// optionally colored human readable version on the Out writer.
+type ConsoleWriter struct {
+	Out     io.Writer
+	NoColor bool
+}
+
+func (w ConsoleWriter) Write(p []byte) (n int, err error) {
+	var event map[string]interface{}
+	err = json.Unmarshal(p, &event)
+	if err != nil {
+		return
+	}
+	buf := consoleBufPool.Get().(*bytes.Buffer)
+	defer consoleBufPool.Put(buf)
+	lvlColor := cReset
+	level := "????"
+	if l, ok := event[LevelFieldName].(string); ok {
+		if !w.NoColor {
+			lvlColor = levelColor(l)
+		}
+		level = strings.ToUpper(l)[0:4]
+	}
+	fmt.Fprintf(buf, "%s |%s| %s",
+		colorize(event[TimestampFieldName], cDarkGray, !w.NoColor),
+		colorize(level, lvlColor, !w.NoColor),
+		colorize(event[MessageFieldName], cReset, !w.NoColor))
+	fields := make([]string, 0, len(event))
+	for field := range event {
+		switch field {
+		case LevelFieldName, TimestampFieldName, MessageFieldName:
+			continue
+		}
+		fields = append(fields, field)
+	}
+	sort.Strings(fields)
+	for _, field := range fields {
+		fmt.Fprintf(buf, " %s=", colorize(field, cCyan, !w.NoColor))
+		switch value := event[field].(type) {
+		case string:
+			if needsQuote(value) {
+				buf.WriteString(strconv.Quote(value))
+			} else {
+				buf.WriteString(value)
+			}
+		default:
+			fmt.Fprint(buf, value)
+		}
+	}
+	buf.WriteByte('\n')
+	buf.WriteTo(w.Out)
+	n = len(p)
+	return
+}
+
+func colorize(s interface{}, color int, enabled bool) string {
+	if !enabled {
+		return fmt.Sprintf("%v", s)
+	}
+	return fmt.Sprintf("\x1b[%dm%v\x1b[0m", color, s)
+}
+
+func levelColor(level string) int {
+	switch level {
+	case "debug":
+		return cMagenta
+	case "info":
+		return cGreen
+	case "warn":
+		return cYellow
+	case "error", "fatal", "panic":
+		return cRed
+	default:
+		return cReset
+	}
+}
+
+func needsQuote(s string) bool {
+	for i := range s {
+		if s[i] < 0x20 || s[i] > 0x7e || s[i] == ' ' || s[i] == '\\' || s[i] == '"' {
+			return true
+		}
+	}
+	return false
+}

ctx.go

@@ -5,25 +5,42 @@ import (
 	"io/ioutil"
 )
 
-var disabledLogger = New(ioutil.Discard).Level(Disabled)
+var disabledLogger *Logger
+
+func init() {
+	l := New(ioutil.Discard).Level(Disabled)
+	disabledLogger = &l
+}
 
 type ctxKey struct{}
 
-// WithContext returns a copy of ctx with l associated.
+// WithContext returns a copy of ctx with l associated. If an instance of Logger
+// is already in the context, the pointer to this logger is updated with l.
+//
+// For instance, to add a field to an existing logger in the context, use this
+// notation:
+//
+//     ctx := r.Context()
+//     l := zerolog.Ctx(ctx)
+//     ctx = l.With().Str("foo", "bar").WithContext(ctx)
 func (l Logger) WithContext(ctx context.Context) context.Context {
 	if lp, ok := ctx.Value(ctxKey{}).(*Logger); ok {
 		// Update existing pointer.
 		*lp = l
 		return ctx
 	}
+	if l.level == Disabled {
+		// Do not store disabled logger.
+		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 {
+func Ctx(ctx context.Context) *Logger {
 	if l, ok := ctx.Value(ctxKey{}).(*Logger); ok {
-		return *l
+		return l
 	}
 	return disabledLogger
 }

ctx_test.go

@@ -11,7 +11,7 @@ func TestCtx(t *testing.T) {
 	log := New(ioutil.Discard)
 	ctx := log.WithContext(context.Background())
 	log2 := Ctx(ctx)
-	if !reflect.DeepEqual(log, log2) {
+	if !reflect.DeepEqual(log, *log2) {
 		t.Error("Ctx did not return the expected logger")
 	}
 
@@ -19,12 +19,29 @@ func TestCtx(t *testing.T) {
 	log = log.Level(InfoLevel)
 	ctx = log.WithContext(ctx)
 	log2 = Ctx(ctx)
-	if !reflect.DeepEqual(log, log2) {
+	if !reflect.DeepEqual(log, *log2) {
 		t.Error("Ctx did not return the expected logger")
 	}
 
 	log2 = Ctx(context.Background())
-	if !reflect.DeepEqual(log2, disabledLogger) {
+	if log2 != disabledLogger {
 		t.Error("Ctx did not return the expected logger")
 	}
 }
+
+func TestCtxDisabled(t *testing.T) {
+	ctx := disabledLogger.WithContext(context.Background())
+	if ctx != context.Background() {
+		t.Error("WithContext stored a disabled logger")
+	}
+
+	ctx = New(ioutil.Discard).WithContext(ctx)
+	if reflect.DeepEqual(Ctx(ctx), disabledLogger) {
+		t.Error("WithContext did not store logger")
+	}
+
+	ctx = disabledLogger.WithContext(ctx)
+	if !reflect.DeepEqual(Ctx(ctx), disabledLogger) {
+		t.Error("WithContext did not update logger pointer with disabled logger")
+	}
+}

globals.go

@@ -16,9 +16,6 @@ var (
 	// ErrorFieldName is the field name used for error fields.
 	ErrorFieldName = "error"
 
-	// SampleFieldName is the name of the field used to report sampling.
-	SampleFieldName = "sample"
-
 	// TimeFieldFormat defines the time format of the Time field type.
 	// If set to an empty string, the time is formatted as an UNIX timestamp
 	// as integer.

hlog/hlog.go

@@ -15,7 +15,7 @@ import (
 
 // 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 {
+func FromRequest(r *http.Request) *zerolog.Logger {
 	return log.Ctx(r.Context())
 }
 
@@ -23,7 +23,10 @@ func FromRequest(r *http.Request) zerolog.Logger {
 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()))
+			// Create a copy of the logger (including internal context slice)
+			// to prevent data race when using UpdateContext.
+			l := log.With().Logger()
+			r = r.WithContext(l.WithContext(r.Context()))
 			next.ServeHTTP(w, r)
 		})
 	}
@@ -35,8 +38,9 @@ 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()))
+			log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+				return c.Str(fieldKey, r.URL.String())
+			})
 			next.ServeHTTP(w, r)
 		})
 	}
@@ -48,8 +52,9 @@ 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()))
+			log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+				return c.Str(fieldKey, r.Method)
+			})
 			next.ServeHTTP(w, r)
 		})
 	}
@@ -61,8 +66,9 @@ 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()))
+			log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+				return c.Str(fieldKey, r.Method+" "+r.URL.String())
+			})
 			next.ServeHTTP(w, r)
 		})
 	}
@@ -75,8 +81,9 @@ func RemoteAddrHandler(fieldKey string) 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()))
+				log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+					return c.Str(fieldKey, host)
+				})
 			}
 			next.ServeHTTP(w, r)
 		})
@@ -90,8 +97,9 @@ func UserAgentHandler(fieldKey string) 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()))
+				log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+					return c.Str(fieldKey, ua)
+				})
 			}
 			next.ServeHTTP(w, r)
 		})
@@ -105,8 +113,9 @@ func RefererHandler(fieldKey string) 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()))
+				log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+					return c.Str(fieldKey, ref)
+				})
 			}
 			next.ServeHTTP(w, r)
 		})
@@ -136,16 +145,18 @@ func IDFromRequest(r *http.Request) (id xid.ID, ok bool) {
 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) {
+			ctx := r.Context()
 			id, ok := IDFromRequest(r)
 			if !ok {
 				id = xid.New()
-				ctx := context.WithValue(r.Context(), idKey{}, id)
+				ctx = context.WithValue(ctx, 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()))
+				log := zerolog.Ctx(ctx)
+				log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+					return c.Str(fieldKey, id.String())
+				})
 			}
 			if headerName != "" {
 				w.Header().Set(headerName, id.String())

hlog/hlog_test.go

@@ -5,6 +5,7 @@ package hlog
 import (
 	"bytes"
 	"fmt"
+	"io/ioutil"
 	"net/http"
 	"net/url"
 	"testing"
@@ -23,7 +24,7 @@ func TestNewHandler(t *testing.T) {
 	lh := NewHandler(log)
 	h := lh(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		l := FromRequest(r)
-		if !reflect.DeepEqual(l, log) {
+		if !reflect.DeepEqual(*l, log) {
 			t.Fail()
 		}
 	}))
@@ -38,12 +39,12 @@ func TestURLHandler(t *testing.T) {
 	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)
+	if want, got := `{"url":"/path?foo=bar"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
 }
 
 func TestMethodHandler(t *testing.T) {
@@ -54,12 +55,12 @@ func TestMethodHandler(t *testing.T) {
 	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)
+	if want, got := `{"method":"POST"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
 }
 
 func TestRequestHandler(t *testing.T) {
@@ -71,12 +72,12 @@ func TestRequestHandler(t *testing.T) {
 	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)
+	if want, got := `{"request":"POST /path?foo=bar"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
 }
 
 func TestRemoteAddrHandler(t *testing.T) {
@@ -87,12 +88,12 @@ func TestRemoteAddrHandler(t *testing.T) {
 	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)
+	if want, got := `{"ip":"1.2.3.4"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
 }
 
 func TestRemoteAddrHandlerIPv6(t *testing.T) {
@@ -103,12 +104,12 @@ func TestRemoteAddrHandlerIPv6(t *testing.T) {
 	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)
+	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)
+	}
 }
 
 func TestUserAgentHandler(t *testing.T) {
@@ -121,12 +122,12 @@ func TestUserAgentHandler(t *testing.T) {
 	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)
+	if want, got := `{"ua":"some user agent string"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
 }
 
 func TestRefererHandler(t *testing.T) {
@@ -139,12 +140,12 @@ func TestRefererHandler(t *testing.T) {
 	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)
+	if want, got := `{"referer":"http://foo.com/bar"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
 }
 
 func TestRequestIDHandler(t *testing.T) {
@@ -171,3 +172,66 @@ func TestRequestIDHandler(t *testing.T) {
 	h = NewHandler(zerolog.New(out))(h)
 	h.ServeHTTP(httptest.NewRecorder(), r)
 }
+
+func TestCombinedHandlers(t *testing.T) {
+	out := &bytes.Buffer{}
+	r := &http.Request{
+		Method: "POST",
+		URL:    &url.URL{Path: "/path", RawQuery: "foo=bar"},
+	}
+	h := MethodHandler("method")(RequestHandler("request")(URLHandler("url")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		l := FromRequest(r)
+		l.Log().Msg("")
+	}))))
+	h = NewHandler(zerolog.New(out))(h)
+	h.ServeHTTP(nil, r)
+	if want, got := `{"method":"POST","request":"POST /path?foo=bar","url":"/path?foo=bar"}`+"\n", out.String(); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
+}
+
+func BenchmarkHandlers(b *testing.B) {
+	r := &http.Request{
+		Method: "POST",
+		URL:    &url.URL{Path: "/path", RawQuery: "foo=bar"},
+	}
+	h1 := URLHandler("url")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		l := FromRequest(r)
+		l.Log().Msg("")
+	}))
+	h2 := MethodHandler("method")(RequestHandler("request")(h1))
+	handlers := map[string]http.Handler{
+		"Single":           NewHandler(zerolog.New(ioutil.Discard))(h1),
+		"Combined":         NewHandler(zerolog.New(ioutil.Discard))(h2),
+		"SingleDisabled":   NewHandler(zerolog.New(ioutil.Discard).Level(zerolog.Disabled))(h1),
+		"CombinedDisabled": NewHandler(zerolog.New(ioutil.Discard).Level(zerolog.Disabled))(h2),
+	}
+	for name := range handlers {
+		h := handlers[name]
+		b.Run(name, func(b *testing.B) {
+			for i := 0; i < b.N; i++ {
+				h.ServeHTTP(nil, r)
+			}
+		})
+	}
+}
+
+func BenchmarkDataRace(b *testing.B) {
+	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)
+		l.UpdateContext(func(c zerolog.Context) zerolog.Context {
+			return c.Str("bar", "baz")
+		})
+		l.Log().Msg("")
+	}))
+
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			h.ServeHTTP(nil, &http.Request{})
+		}
+	})
+}

log.go

@@ -62,17 +62,17 @@
 //
 // Sample logs:
 //
-//     sampled := log.Sample(10)
+//     sampled := log.Sample(&zerolog.BasicSampler{N: 10})
 //     sampled.Info().Msg("will be logged every 10 messages")
 //
 package zerolog
 
 import (
+	"fmt"
 	"io"
 	"io/ioutil"
 	"os"
 	"strconv"
-	"sync/atomic"
 
 	"github.com/rs/zerolog/internal/json"
 )
@@ -115,15 +115,6 @@ func (l Level) String() string {
 	return ""
 }
 
-const (
-	// Often samples log every 10 events.
-	Often = 10
-	// Sometimes samples log every 100 events.
-	Sometimes = 100
-	// Rarely samples log every 1000 events.
-	Rarely = 1000
-)
-
 var disabledEvent = newEvent(levelWriterAdapter{ioutil.Discard}, 0, false)
 
 // A Logger represents an active logging object that generates lines
@@ -134,8 +125,7 @@ var disabledEvent = newEvent(levelWriterAdapter{ioutil.Discard}, 0, false)
 type Logger struct {
 	w       LevelWriter
 	level   Level
-	sample  uint32
-	counter *uint32
+	sampler Sampler
 	context []byte
 }
 
@@ -166,7 +156,8 @@ func Nop() Logger {
 func (l Logger) Output(w io.Writer) Logger {
 	l2 := New(w)
 	l2.level = l.level
-	l2.sample = l.sample
+	l2.sampler = l.sampler
+	l2.context = make([]byte, len(l.context), cap(l.context))
 	copy(l2.context, l.context)
 	return l2
 }
@@ -184,34 +175,30 @@ func (l Logger) With() Context {
 	return Context{l}
 }
 
-// Level creates a child logger with the minimum accepted level set to level.
-func (l Logger) Level(lvl Level) Logger {
-	return Logger{
-		w:       l.w,
-		level:   lvl,
-		sample:  l.sample,
-		counter: l.counter,
-		context: l.context,
+// UpdateContext updates the internal logger's context.
+//
+// Use this method with caution. If unsure, prefer the With method.
+func (l *Logger) UpdateContext(update func(c Context) Context) {
+	if l == disabledLogger {
+		return
 	}
+	if cap(l.context) == 0 {
+		l.context = make([]byte, 1, 500) // first byte is timestamp flag
+	}
+	c := update(Context{*l})
+	l.context = c.l.context
 }
 
-// Sample returns a logger that only let one message out of every to pass thru.
-func (l Logger) Sample(every int) Logger {
-	if every == 0 {
-		// Create a child with no sampling.
-		return Logger{
-			w:       l.w,
-			level:   l.level,
-			context: l.context,
-		}
-	}
-	return Logger{
-		w:       l.w,
-		level:   l.level,
-		sample:  uint32(every),
-		counter: new(uint32),
-		context: l.context,
-	}
+// Level creates a child logger with the minimum accepted level set to level.
+func (l Logger) Level(lvl Level) Logger {
+	l.level = lvl
+	return l
+}
+
+// Sample returns a logger with the s sampler.
+func (l Logger) Sample(s Sampler) Logger {
+	l.sampler = s
+	return l
 }
 
 // Debug starts a new message with debug level.
@@ -292,6 +279,22 @@ func (l Logger) Log() *Event {
 	return l.newEvent(PanicLevel, false, nil)
 }
 
+// Print sends a log event using debug level and no extra field.
+// Arguments are handled in the manner of fmt.Print.
+func (l Logger) Print(v ...interface{}) {
+	if e := l.Debug(); e.Enabled() {
+		e.Msg(fmt.Sprint(v...))
+	}
+}
+
+// Printf sends a log event using debug level and no extra field.
+// Arguments are handled in the manner of fmt.Printf.
+func (l Logger) Printf(format string, v ...interface{}) {
+	if e := l.Debug(); e.Enabled() {
+		e.Msg(fmt.Sprintf(format, v...))
+	}
+}
+
 // Write implements the io.Writer interface. This is useful to set as a writer
 // for the standard library log.
 func (l Logger) Write(p []byte) (n int, err error) {
@@ -313,7 +316,7 @@ func (l Logger) newEvent(level Level, addLevelField bool, done func(string)) *Ev
 	if addLevelField {
 		lvl = level
 	}
-	e := newEvent(l.w, lvl, enabled)
+	e := newEvent(l.w, lvl, true)
 	e.done = done
 	if l.context != nil && len(l.context) > 0 && l.context[0] > 0 {
 		// first byte of context is ts flag
@@ -322,9 +325,6 @@ func (l Logger) newEvent(level Level, addLevelField bool, done func(string)) *Ev
 	if addLevelField {
 		e.Str(LevelFieldName, level.String())
 	}
-	if l.sample > 0 && SampleFieldName != "" {
-		e.Uint32(SampleFieldName, l.sample)
-	}
 	if l.context != nil && len(l.context) > 1 {
 		if len(e.buf) > 1 {
 			e.buf = append(e.buf, ',')
@@ -339,9 +339,8 @@ func (l Logger) should(lvl Level) bool {
 	if lvl < l.level || lvl < globalLevel() {
 		return false
 	}
-	if l.sample > 0 && l.counter != nil && !samplingDisabled() {
-		c := atomic.AddUint32(l.counter, 1)
-		return c%l.sample == 0
+	if l.sampler != nil && !samplingDisabled() {
+		return l.sampler.Sample(lvl)
 	}
 	return true
 }

log/log.go

@@ -27,9 +27,9 @@ func Level(level zerolog.Level) zerolog.Logger {
 	return Logger.Level(level)
 }
 
-// Sample returns a logger that only let one message out of every to pass thru.
-func Sample(every int) zerolog.Logger {
-	return Logger.Sample(every)
+// Sample returns a logger with the s sampler.
+func Sample(s zerolog.Sampler) zerolog.Logger {
+	return Logger.Sample(s)
 }
 
 // Debug starts a new message with debug level.
@@ -84,8 +84,20 @@ func Log() *zerolog.Event {
 	return Logger.Log()
 }
 
+// Print sends a log event using debug level and no extra field.
+// Arguments are handled in the manner of fmt.Print.
+func Print(v ...interface{}) {
+	Logger.Print(v...)
+}
+
+// Printf sends a log event using debug level and no extra field.
+// Arguments are handled in the manner of fmt.Printf.
+func Printf(format string, v ...interface{}) {
+	Logger.Printf(format, v...)
+}
+
 // Ctx returns the Logger associated with the ctx. If no logger
 // is associated, a disabled logger is returned.
-func Ctx(ctx context.Context) zerolog.Logger {
+func Ctx(ctx context.Context) *zerolog.Logger {
 	return zerolog.Ctx(ctx)
 }

log_example_test.go

@@ -38,15 +38,31 @@ func ExampleLogger_Level() {
 }
 
 func ExampleLogger_Sample() {
-	log := zerolog.New(os.Stdout).Sample(2)
+	log := zerolog.New(os.Stdout).Sample(&zerolog.BasicSampler{N: 2})
 
 	log.Info().Msg("message 1")
 	log.Info().Msg("message 2")
 	log.Info().Msg("message 3")
 	log.Info().Msg("message 4")
 
-	// Output: {"level":"info","sample":2,"message":"message 2"}
-	// {"level":"info","sample":2,"message":"message 4"}
+	// Output: {"level":"info","message":"message 2"}
+	// {"level":"info","message":"message 4"}
+}
+
+func ExampleLogger_Print() {
+	log := zerolog.New(os.Stdout)
+
+	log.Print("hello world")
+
+	// Output: {"level":"debug","message":"hello world"}
+}
+
+func ExampleLogger_Printf() {
+	log := zerolog.New(os.Stdout)
+
+	log.Printf("hello %s", "world")
+
+	// Output: {"level":"debug","message":"hello world"}
 }
 
 func ExampleLogger_Debug() {

log_test.go

@@ -310,12 +310,12 @@ func TestLevel(t *testing.T) {
 
 func TestSampling(t *testing.T) {
 	out := &bytes.Buffer{}
-	log := New(out).Sample(2)
+	log := New(out).Sample(&BasicSampler{N: 2})
 	log.Log().Int("i", 1).Msg("")
 	log.Log().Int("i", 2).Msg("")
 	log.Log().Int("i", 3).Msg("")
 	log.Log().Int("i", 4).Msg("")
-	if got, want := out.String(), "{\"sample\":2,\"i\":2}\n{\"sample\":2,\"i\":4}\n"; got != want {
+	if got, want := out.String(), "{\"i\":2}\n{\"i\":4}\n"; got != want {
 		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
 	}
 }

sampler.go

@@ -0,0 +1,128 @@
+package zerolog
+
+import (
+	"math/rand"
+	"sync/atomic"
+	"time"
+)
+
+var (
+	// Often samples log every ~ 10 events.
+	Often = RandomSampler(10)
+	// Sometimes samples log every ~ 100 events.
+	Sometimes = RandomSampler(100)
+	// Rarely samples log every ~ 1000 events.
+	Rarely = RandomSampler(1000)
+)
+
+// Sampler defines an interface to a log sampler.
+type Sampler interface {
+	// Sample returns true if the event should be part of the sample, false if
+	// the event should be dropped.
+	Sample(lvl Level) bool
+}
+
+// RandomSampler use a PRNG to randomly sample an event out of N events,
+// regardless of their level.
+type RandomSampler uint32
+
+// Sample implements the Sampler interface.
+func (s RandomSampler) Sample(lvl Level) bool {
+	if s <= 0 {
+		return false
+	}
+	if s > 0 {
+		if rand.Intn(int(s)) != 0 {
+			return false
+		}
+	}
+	return true
+}
+
+// BasicSampler is a sampler that will send every Nth events, regardless of
+// there level.
+type BasicSampler struct {
+	N       uint32
+	counter uint32
+}
+
+// Sample implements the Sampler interface.
+func (s *BasicSampler) Sample(lvl Level) bool {
+	c := atomic.AddUint32(&s.counter, 1)
+	return c%s.N == 0
+}
+
+// BurstSampler lets Burst events pass per Period then pass the decision to
+// NextSampler. If Sampler is not set, all subsequent events are rejected.
+type BurstSampler struct {
+	// Burst is the maximum number of event per period allowed before calling
+	// NextSampler.
+	Burst uint32
+	// Period defines the burst period. If 0, NextSampler is always called.
+	Period time.Duration
+	// NextSampler is the sampler used after the burst is reached. If nil,
+	// events are always rejected after the burst.
+	NextSampler Sampler
+
+	counter uint32
+	resetAt int64
+}
+
+// Sample implements the Sampler interface.
+func (s *BurstSampler) Sample(lvl Level) bool {
+	if s.Burst > 9 && s.Period > 0 {
+		if s.inc() <= s.Burst {
+			return true
+		}
+	}
+	if s.NextSampler == nil {
+		return false
+	}
+	return s.NextSampler.Sample(lvl)
+}
+
+func (s *BurstSampler) inc() uint32 {
+	now := time.Now().UnixNano()
+	resetAt := atomic.LoadInt64(&s.resetAt)
+	var c uint32
+	if now > resetAt {
+		c = 1
+		atomic.StoreUint32(&s.counter, c)
+		newResetAt := now + s.Period.Nanoseconds()
+		reset := atomic.CompareAndSwapInt64(&s.resetAt, resetAt, newResetAt)
+		if !reset {
+			// Lost the race with another goroutine trying to reset.
+			c = atomic.AddUint32(&s.counter, 1)
+		}
+	} else {
+		c = atomic.AddUint32(&s.counter, 1)
+	}
+	return c
+}
+
+// LevelSampler applies a different sampler for each level.
+type LevelSampler struct {
+	DebugSampler, InfoSampler, WarnSampler, ErrorSampler Sampler
+}
+
+func (s LevelSampler) Sample(lvl Level) bool {
+	switch lvl {
+	case DebugLevel:
+		if s.DebugSampler != nil {
+			return s.DebugSampler.Sample(lvl)
+		}
+	case InfoLevel:
+		if s.InfoSampler != nil {
+			return s.InfoSampler.Sample(lvl)
+		}
+	case WarnLevel:
+		if s.WarnSampler != nil {
+			return s.WarnSampler.Sample(lvl)
+		}
+	case ErrorLevel:
+		if s.ErrorSampler != nil {
+			return s.ErrorSampler.Sample(lvl)
+		}
+	}
+	return true
+}

sampler_test.go

@@ -0,0 +1,75 @@
+package zerolog
+
+import (
+	"testing"
+	"time"
+)
+
+var samplers = []struct {
+	name    string
+	sampler func() Sampler
+	total   int
+	wantMin int
+	wantMax int
+}{
+	{
+		"BasicSampler",
+		func() Sampler {
+			return &BasicSampler{N: 5}
+		},
+		100, 20, 20,
+	},
+	{
+		"RandomSampler",
+		func() Sampler {
+			return RandomSampler(5)
+		},
+		100, 10, 30,
+	},
+	{
+		"BurstSampler",
+		func() Sampler {
+			return &BurstSampler{Burst: 20, Period: time.Second}
+		},
+		100, 20, 20,
+	},
+	{
+		"BurstSamplerNext",
+		func() Sampler {
+			return &BurstSampler{Burst: 20, Period: time.Second, NextSampler: &BasicSampler{N: 5}}
+		},
+		120, 40, 40,
+	},
+}
+
+func TestSamplers(t *testing.T) {
+	for i := range samplers {
+		s := samplers[i]
+		t.Run(s.name, func(t *testing.T) {
+			sampler := s.sampler()
+			got := 0
+			for t := s.total; t > 0; t-- {
+				if sampler.Sample(0) {
+					got++
+				}
+			}
+			if got < s.wantMin || got > s.wantMax {
+				t.Errorf("%s.Sample(0) == true %d on %d, want [%d, %d]", s.name, got, s.total, s.wantMin, s.wantMax)
+			}
+		})
+	}
+}
+
+func BenchmarkSamplers(b *testing.B) {
+	for i := range samplers {
+		s := samplers[i]
+		b.Run(s.name, func(b *testing.B) {
+			sampler := s.sampler()
+			b.RunParallel(func(pb *testing.PB) {
+				for pb.Next() {
+					sampler.Sample(0)
+				}
+			})
+		})
+	}
+}