Add ability to customize level values

* Add event.CallerSkipFrame(skip int)

This indicates that, for this event, we should skip an additional
specified number of frames.

This is cumulative, calling it twice for the same event will add both
numbers together, and this is in addition to any skip frame settings set
through the context, or globally.

The indended purpose is for wrappers to Msg or Msgf, so that the actual
caller is always printed correctly.

* Use CallerSkipFrame for Print, Printf, and Write.

This allows us to use the correct caller when using these 3 functions.

Co-authored-by: Zephaniah E. Loss-Cutler-Hull <warp@aehallh.com>

.github/workflows/test.yml

@@ -0,0 +1,21 @@
+on: [push, pull_request]
+name: Test
+jobs:
+  test:
+    strategy:
+      matrix:
+        go-version: [1.15.x, 1.16.x]
+        os: [ubuntu-latest, macos-latest]
+    runs-on: ${{ matrix.os }}
+    steps:
+    - name: Install Go
+      uses: actions/setup-go@v2
+      with:
+        go-version: ${{ matrix.go-version }}
+    - name: Checkout code
+      uses: actions/checkout@v2
+    - name: Test
+      run: go test -race -bench . -benchmem ./...
+    - name: Test CBOR
+      run: go test -tags binary_log ./...
+

.gitignore

@@ -6,6 +6,7 @@
 # Folders
 _obj
 _test
+tmp
 
 # Architecture specific extensions/prefixes
 *.[568vq]

.travis.yml

@@ -1,13 +0,0 @@
-language: go
-go:
-- "1.7"
-- "1.8"
-- "1.9"
-- "1.10"
-- "master"
-matrix:
-  allow_failures:
-      - go: "master"
-script:
-  - go test -v -race -cpu=1,2,4 -bench . -benchmem ./...
-  - go test -v -tags binary_log -race -cpu=1,2,4 -bench . -benchmem ./...

CNAME

@@ -0,0 +1 @@
+zerolog.io

README.md

@@ -8,7 +8,7 @@ Zerolog's API is designed to provide both a great developer experience and stunn
 
 Uber's [zap](https://godoc.org/go.uber.org/zap) library pioneered this approach. Zerolog is taking this concept to the next level with a simpler to use API and even better performance.
 
-To keep the code base and the API simple, zerolog focuses on efficient structured logging only. Pretty logging on the console is made possible using the provided (but inefficient) `zerolog.ConsoleWriter`.
+To keep the code base and the API simple, zerolog focuses on efficient structured logging only. Pretty logging on the console is made possible using the provided (but inefficient) [`zerolog.ConsoleWriter`](#pretty-logging).
 
 ![Pretty Logging Image](pretty.png)
 
@@ -18,20 +18,21 @@ Find out [who uses zerolog](https://github.com/rs/zerolog/wiki/Who-uses-zerolog)
 
 ## Features
 
-* Blazing fast
-* Low to zero allocation
-* Level logging
-* Sampling
-* Hooks
-* Contextual fields
+* [Blazing fast](#benchmarks)
+* [Low to zero allocation](#benchmarks)
+* [Leveled logging](#leveled-logging)
+* [Sampling](#log-sampling)
+* [Hooks](#hooks)
+* [Contextual fields](#contextual-logging)
 * `context.Context` integration
-* `net/http` helpers
-* JSON and CBOR encoding formats
-* Pretty logging for development
+* [Integration with `net/http`](#integration-with-nethttp)
+* [JSON and CBOR encoding formats](#binary-encoding)
+* [Pretty logging for development](#pretty-logging)
+* [Error Logging (with optional Stacktrace)](#error-logging)
 
 ## Installation
 
-```go
+```bash
 go get -u github.com/rs/zerolog/log
 ```
 
@@ -51,16 +52,14 @@ import (
 
 func main() {
     // UNIX Time is faster and smaller than most timestamps
-    // If you set zerolog.TimeFieldFormat to an empty string,
-    // logs will write with UNIX time
-    zerolog.TimeFieldFormat = ""
+    zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
 
     log.Print("hello world")
 }
 
 // Output: {"time":1516134303,"level":"debug","message":"hello world"}
 ```
-
+> Note: By default log writes to `os.Stderr`
 > Note: The default log level for `log.Print` is *debug*
 
 ### Contextual Logging
@@ -76,15 +75,20 @@ import (
 )
 
 func main() {
-    zerolog.TimeFieldFormat = ""
+    zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
 
     log.Debug().
         Str("Scale", "833 cents").
         Float64("Interval", 833.09).
         Msg("Fibonacci is everywhere")
+    
+    log.Debug().
+        Str("Name", "Tom").
+        Send()
 }
 
-// Output: {"time":1524104936,"level":"debug","Scale":"833 cents","Interval":833.09,"message":"Fibonacci is everywhere"}
+// Output: {"level":"debug","Scale":"833 cents","Interval":833.09,"time":1562212768,"message":"Fibonacci is everywhere"}
+// Output: {"level":"debug","Name":"Tom","time":1562212768}
 ```
 
 > You'll note in the above example that when adding contextual fields, the fields are strongly typed. You can find the full list of supported fields [here](#standard-types)
@@ -102,7 +106,7 @@ import (
 )
 
 func main() {
-    zerolog.TimeFieldFormat = ""
+    zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
 
     log.Info().Msg("hello world")
 }
@@ -120,6 +124,7 @@ func main() {
 * warn (`zerolog.WarnLevel`, 2)
 * info (`zerolog.InfoLevel`, 1)
 * debug (`zerolog.DebugLevel`, 0)
+* trace (`zerolog.TraceLevel`, -1)
 
 You can set the Global logging level to any of these options using the `SetGlobalLevel` function in the zerolog package, passing in one of the given constants above, e.g. `zerolog.InfoLevel` would be the "info" level.  Whichever level is chosen, all logs with a level greater than or equal to that level will be written. To turn off logging entirely, pass the `zerolog.Disabled` constant.
 
@@ -138,7 +143,7 @@ import (
 )
 
 func main() {
-    zerolog.TimeFieldFormat = ""
+    zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
     debug := flag.Bool("debug", false, "sets log level to debug")
 
     flag.Parse()
@@ -189,7 +194,7 @@ import (
 )
 
 func main() {
-    zerolog.TimeFieldFormat = ""
+    zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
 
     log.Log().
         Str("foo", "bar").
@@ -199,6 +204,80 @@ func main() {
 // Output: {"time":1494567715,"foo":"bar"}
 ```
 
+### Error Logging
+
+You can log errors using the `Err` method
+
+```go
+package main
+
+import (
+	"errors"
+
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+)
+
+func main() {
+	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
+
+	err := errors.New("seems we have an error here")
+	log.Error().Err(err).Msg("")
+}
+
+// Output: {"level":"error","error":"seems we have an error here","time":1609085256}
+```
+
+> The default field name for errors is `error`, you can change this by setting `zerolog.ErrorFieldName` to meet your needs.
+
+#### Error Logging with Stacktrace
+
+Using `github.com/pkg/errors`, you can add a formatted stacktrace to your errors. 
+
+```go
+package main
+
+import (
+	"github.com/pkg/errors"
+	"github.com/rs/zerolog/pkgerrors"
+
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+)
+
+func main() {
+	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
+	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack
+
+	err := outer()
+	log.Error().Stack().Err(err).Msg("")
+}
+
+func inner() error {
+	return errors.New("seems we have an error here")
+}
+
+func middle() error {
+	err := inner()
+	if err != nil {
+		return err
+	}
+	return nil
+}
+
+func outer() error {
+	err := middle()
+	if err != nil {
+		return err
+	}
+	return nil
+}
+
+// Output: {"level":"error","stack":[{"func":"inner","line":"20","source":"errors.go"},{"func":"middle","line":"24","source":"errors.go"},{"func":"outer","line":"32","source":"errors.go"},{"func":"main","line":"15","source":"errors.go"},{"func":"main","line":"204","source":"proc.go"},{"func":"goexit","line":"1374","source":"asm_amd64.s"}],"error":"seems we have an error here","time":1609086683}
+```
+
+> zerolog.ErrorStackMarshaler must be set in order for the stack to output anything.
+
 #### Logging Fatal Messages
 
 ```go
@@ -215,7 +294,7 @@ func main() {
     err := errors.New("A repo man spends his life getting into tense situations")
     service := "myservice"
 
-    zerolog.TimeFieldFormat = ""
+    zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
 
     log.Fatal().
         Err(err).
@@ -229,6 +308,7 @@ func main() {
 
 > NOTE: Using `Msgf` generates one allocation even when the logger is disabled.
 
+
 ### Create logger instance to manage different outputs
 
 ```go
@@ -243,7 +323,7 @@ logger.Info().Str("foo", "bar").Msg("hello world")
 
 ```go
 sublogger := log.With().
-                 Str("component": "foo").
+                 Str("component", "foo").
                  Logger()
 sublogger.Info().Msg("hello world")
 
@@ -252,14 +332,38 @@ sublogger.Info().Msg("hello world")
 
 ### Pretty logging
 
+To log a human-friendly, colorized output, use `zerolog.ConsoleWriter`:
+
 ```go
-if isConsole {
-    log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
-}
+log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
 
 log.Info().Str("foo", "bar").Msg("Hello world")
 
-// Output: 1494567715 |INFO| Hello world foo=bar
+// Output: 3:04PM INF Hello World foo=bar
+```
+
+To customize the configuration and formatting:
+
+```go
+output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.RFC3339}
+output.FormatLevel = func(i interface{}) string {
+    return strings.ToUpper(fmt.Sprintf("| %-6s|", i))
+}
+output.FormatMessage = func(i interface{}) string {
+    return fmt.Sprintf("***%s****", i)
+}
+output.FormatFieldName = func(i interface{}) string {
+    return fmt.Sprintf("%s:", i)
+}
+output.FormatFieldValue = func(i interface{}) string {
+    return strings.ToUpper(fmt.Sprintf("%s", i))
+}
+
+log := zerolog.New(output).With().Timestamp().Logger()
+
+log.Info().Str("foo", "bar").Msg("Hello World")
+
+// Output: 2006-01-02T15:04:05Z07:00 | INFO  | ***Hello World**** foo:BAR
 ```
 
 ### Sub dictionary
@@ -293,16 +397,25 @@ log.Info().Msg("hello world")
 log.Logger = log.With().Str("foo", "bar").Logger()
 ```
 
+### Add file and line number to log
+
+```go
+log.Logger = log.With().Caller().Logger()
+log.Info().Msg("hello world")
+
+// Output: {"level": "info", "message": "hello world", "caller": "/go/src/your_project/some_file:21"}
+```
+
+
 ### Thread-safe, lock-free, non-blocking writer
 
 If your writer might be slow or not thread-safe and you need your log producers to never get slowed down by a slow writer, you can use a `diode.Writer` as follow:
 
 ```go
-d := diodes.NewManyToOne(1000, diodes.AlertFunc(func(missed int) {
-    fmt.Printf("Dropped %d messages\n", missed)
-}))
-w := diode.NewWriter(os.Stdout, d, 10*time.Millisecond)
-log := zerolog.New(w)
+wr := diode.NewWriter(os.Stdout, 1000, 10*time.Millisecond, func(missed int) {
+		fmt.Printf("Logger Dropped %d messages", missed)
+	})
+log := zerolog.New(wr)
 log.Print("test")
 ```
 
@@ -355,7 +468,7 @@ hooked.Warn().Msg("")
 ### Pass a sub-logger by context
 
 ```go
-ctx := log.With("component", "module").Logger().WithContext(ctx)
+ctx := log.With().Str("component", "module").Logger().WithContext(ctx)
 
 log.Ctx(ctx).Info().Msg("hello world")
 
@@ -396,11 +509,11 @@ c := alice.New()
 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.
+// Thanks to that handler, all our logs will come with some prepopulated fields.
 c = c.Append(hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) {
     hlog.FromRequest(r).Info().
         Str("method", r.Method).
-        Str("url", r.URL.String()).
+        Stringer("url", r.URL).
         Int("status", status).
         Int("size", size).
         Dur("duration", duration).
@@ -430,22 +543,40 @@ if err := http.ListenAndServe(":8080", nil); err != nil {
 }
 ```
 
+## Multiple Log Output
+`zerolog.MultiLevelWriter` may be used to send the log message to multiple outputs. 
+In this example, we send the log message to both `os.Stdout` and the in-built ConsoleWriter.
+```go
+func main() {
+	consoleWriter := zerolog.ConsoleWriter{Out: os.Stdout}
+
+	multi := zerolog.MultiLevelWriter(consoleWriter, os.Stdout)
+
+	logger := zerolog.New(multi).With().Timestamp().Logger()
+
+	logger.Info().Msg("Hello World!")
+}
+
+// Output (Line 1: Console; Line 2: Stdout)
+// 12:36PM INF Hello World!
+// {"level":"info","time":"2019-11-07T12:36:38+03:00","message":"Hello World!"}
+``` 
+
 ## Global Settings
 
 Some settings can be changed and will by applied to all loggers:
 
 * `log.Logger`: You can set this value to customize the global logger (the one used by package level methods).
-* `zerolog.SetGlobalLevel`: Can raise the minimum level of all loggers. Set this to `zerolog.Disable` to disable logging altogether (quiet mode).
+* `zerolog.SetGlobalLevel`: Can raise the minimum level of all loggers. Call this with `zerolog.Disabled` to disable logging altogether (quiet mode).
 * `zerolog.DisableSampling`: If argument is `true`, all sampled loggers will stop sampling and issue 100% of their log events.
 * `zerolog.TimestampFieldName`: Can be set to customize `Timestamp` field name.
 * `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.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.
-* `DurationFieldUnit`: Sets the unit of the fields added by `Dur` (default: `time.Millisecond`).
-* `DurationFieldInteger`: If set to true, `Dur` fields are formatted as integers instead of floats.
+* `zerolog.TimeFieldFormat`: Can be set to customize `Time` field value formatting. If set with `zerolog.TimeFormatUnix`, `zerolog.TimeFormatUnixMs` or `zerolog.TimeFormatUnixMicro`, times are formated as UNIX timestamp.
+* `zerolog.DurationFieldUnit`: Can be set to customize the unit for time.Duration type fields added by `Dur` (default: `time.Millisecond`).
+* `zerolog.DurationFieldInteger`: If set to `true`, `Dur` fields are formatted as integers instead of floats (default: `false`). 
+* `zerolog.ErrorHandler`: Called whenever zerolog fails to write an event on its output. If not set, an error is printed on the stderr. This handler must be thread safe and non-blocking.
 
 ## Field Types
 
@@ -459,13 +590,17 @@ Some settings can be changed and will by applied to all loggers:
 
 ### Advanced Fields
 
-* `Err`: Takes an `error` and render it as a string using the `zerolog.ErrorFieldName` field name.
-* `Timestamp`: Insert a timestamp field with `zerolog.TimestampFieldName` field name and formatted using `zerolog.TimeFieldFormat`.
-* `Time`: Adds a field with the time formated with the `zerolog.TimeFieldFormat`.
-* `Dur`: Adds a field with a `time.Duration`.
+* `Err`: Takes an `error` and renders it as a string using the `zerolog.ErrorFieldName` field name.
+* `Timestamp`: Inserts a timestamp field with `zerolog.TimestampFieldName` field name, formatted using `zerolog.TimeFieldFormat`.
+* `Time`: Adds a field with time formatted with `zerolog.TimeFieldFormat`.
+* `Dur`: Adds a field with `time.Duration`.
 * `Dict`: Adds a sub-key/value as a field of the event.
+* `RawJSON`: Adds a field with an already encoded JSON (`[]byte`)
+* `Hex`: Adds a field with value formatted as a hexadecimal string (`[]byte`)
 * `Interface`: Uses reflection to marshal the type.
 
+Most fields are also available in the slice format (`Strs` for `[]string`, `Errs` for `[]error` etc.)
+
 ## Binary Encoding
 
 In addition to the default JSON encoding, `zerolog` can produce binary logs using [CBOR](http://cbor.io) encoding. The choice of encoding can be decided at compile time using the build tag `binary_log` as follows:
@@ -480,9 +615,12 @@ with zerolog library is [CSD](https://github.com/toravir/csd/).
 ## Related Projects
 
 * [grpc-zerolog](https://github.com/cheapRoc/grpc-zerolog): Implementation of `grpclog.LoggerV2` interface using `zerolog`
+* [overlog](https://github.com/Trendyol/overlog): Implementation of `Mapped Diagnostic Context` interface using `zerolog`
 
 ## Benchmarks
 
+See [logbench](http://hackemist.com/logbench/) for more comprehensive and up-to-date benchmarks.
+
 All operations are allocation free (those numbers *include* JSON encoding):
 
 ```text
@@ -542,7 +680,7 @@ Log a static string, without any context or `printf`-style templating:
 
 ## Caveats
 
-Note that zerolog does de-duplication fields. Using the same key multiple times creates multiple keys in final JSON:
+Note that zerolog does no de-duplication of fields. Using the same key multiple times creates multiple keys in final JSON:
 
 ```go
 logger := zerolog.New(os.Stderr).With().Timestamp().Logger()
@@ -552,4 +690,4 @@ logger.Info().
 // Output: {"level":"info","time":1494567715,"time":1494567715,"message":"dup"}
 ```
 
-However, it’s not a big deal as JSON accepts dup keys; the last one prevails.
+In this case, many consumers will take the last value, but this is not guaranteed; check yours if in doubt.

_config.yml

@@ -0,0 +1 @@
+remote_theme: rs/gh-readme

array.go

@@ -20,6 +20,20 @@ type Array struct {
 	buf []byte
 }
 
+func putArray(a *Array) {
+	// Proper usage of a sync.Pool requires each entry to have approximately
+	// the same memory cost. To obtain this property when the stored type
+	// contains a variably-sized buffer, we add a hard limit on the maximum buffer
+	// to place back in the pool.
+	//
+	// See https://golang.org/issue/23199
+	const maxSize = 1 << 16 // 64KiB
+	if cap(a.buf) > maxSize {
+		return
+	}
+	arrayPool.Put(a)
+}
+
 // Arr creates an array to be added to an Event or Context.
 func Arr() *Array {
 	a := arrayPool.Get().(*Array)
@@ -38,7 +52,7 @@ func (a *Array) write(dst []byte) []byte {
 		dst = append(append(dst, a.buf...))
 	}
 	dst = enc.AppendArrayEnd(dst)
-	arrayPool.Put(a)
+	putArray(a)
 	return dst
 }
 
@@ -49,7 +63,7 @@ func (a *Array) Object(obj LogObjectMarshaler) *Array {
 	obj.MarshalZerologObject(e)
 	e.buf = enc.AppendEndMarker(e.buf)
 	a.buf = append(enc.AppendArrayDelim(a.buf), e.buf...)
-	eventPool.Put(e)
+	putEvent(e)
 	return a
 }
 
@@ -71,9 +85,33 @@ func (a *Array) Hex(val []byte) *Array {
 	return a
 }
 
-// Err append append the err as a string to the array.
+// RawJSON adds already encoded JSON to the array.
+func (a *Array) RawJSON(val []byte) *Array {
+	a.buf = appendJSON(enc.AppendArrayDelim(a.buf), val)
+	return a
+}
+
+// Err serializes and appends the err to the array.
 func (a *Array) Err(err error) *Array {
-	a.buf = enc.AppendError(enc.AppendArrayDelim(a.buf), err)
+	switch m := ErrorMarshalFunc(err).(type) {
+	case LogObjectMarshaler:
+		e := newEvent(nil, 0)
+		e.buf = e.buf[:0]
+		e.appendObject(m)
+		a.buf = append(enc.AppendArrayDelim(a.buf), e.buf...)
+		putEvent(e)
+	case error:
+		if m == nil || isNilValue(m) {
+			a.buf = enc.AppendNil(enc.AppendArrayDelim(a.buf))
+		} else {
+			a.buf = enc.AppendString(enc.AppendArrayDelim(a.buf), m.Error())
+		}
+	case string:
+		a.buf = enc.AppendString(enc.AppendArrayDelim(a.buf), m)
+	default:
+		a.buf = enc.AppendInterface(enc.AppendArrayDelim(a.buf), m)
+	}
+
 	return a
 }
 

array_test.go

@@ -24,10 +24,11 @@ func TestArray(t *testing.T) {
 		Str("a").
 		Bytes([]byte("b")).
 		Hex([]byte{0x1f}).
+		RawJSON([]byte(`{"some":"json"}`)).
 		Time(time.Time{}).
 		IPAddr(net.IP{192, 168, 0, 10}).
 		Dur(0)
-	want := `[true,1,2,3,4,5,6,7,8,9,10,11.98122,12.987654321,"a","b","1f","0001-01-01T00:00:00Z","192.168.0.10",0]`
+	want := `[true,1,2,3,4,5,6,7,8,9,10,11.98122,12.987654321,"a","b","1f",{"some":"json"},"0001-01-01T00:00:00Z","192.168.0.10",0]`
 	if got := decodeObjectToStr(a.write([]byte{})); got != want {
 		t.Errorf("Array.write()\ngot:  %s\nwant: %s", got, want)
 	}

benchmark_test.go

@@ -3,6 +3,7 @@ package zerolog
 import (
 	"errors"
 	"io/ioutil"
+	"net"
 	"testing"
 	"time"
 )
@@ -234,12 +235,13 @@ func BenchmarkLogFieldType(b *testing.B) {
 
 func BenchmarkContextFieldType(b *testing.B) {
 	oldFormat := TimeFieldFormat
-	TimeFieldFormat = ""
+	TimeFieldFormat = TimeFormatUnix
 	defer func() { TimeFieldFormat = oldFormat }()
 	bools := []bool{true, false, true, false, true, false, true, false, true, false}
 	ints := []int{0, 1, 2, 3, 4, 5, 6, 7, 8, 9}
 	floats := []float64{0, 1, 2, 3, 4, 5, 6, 7, 8, 9}
 	strings := []string{"a", "b", "c", "d", "e", "f", "g", "h", "i", "j"}
+	stringer := net.IP{127, 0, 0, 1}
 	durations := []time.Duration{0, 1, 2, 3, 4, 5, 6, 7, 8, 9}
 	times := []time.Time{
 		time.Unix(0, 0),
@@ -307,6 +309,9 @@ func BenchmarkContextFieldType(b *testing.B) {
 		"Strs": func(c Context) Context {
 			return c.Strs("k", strings)
 		},
+		"Stringer": func(c Context) Context {
+			return c.Stringer("k", stringer)
+		},
 		"Err": func(c Context) Context {
 			return c.Err(errs[0])
 		},

binary_test.go

@@ -6,6 +6,7 @@ import (
 	"bytes"
 	"errors"
 	"fmt"
+
 	//	"io/ioutil"
 	stdlog "log"
 	"time"
@@ -54,8 +55,8 @@ func ExampleLogger_Sample() {
 	log.Info().Msg("message 4")
 
 	fmt.Println(decodeIfBinaryToString(dst.Bytes()))
-	// Output: {"level":"info","message":"message 2"}
-	// {"level":"info","message":"message 4"}
+	// Output: {"level":"info","message":"message 1"}
+	// {"level":"info","message":"message 3"}
 }
 
 type LevelNameHook1 struct{}
@@ -107,6 +108,19 @@ func ExampleLogger_Printf() {
 	// Output: {"level":"debug","message":"hello world"}
 }
 
+func ExampleLogger_Trace() {
+	dst := bytes.Buffer{}
+	log := New(&dst)
+
+	log.Trace().
+		Str("foo", "bar").
+		Int("n", 123).
+		Msg("hello world")
+
+	fmt.Println(decodeIfBinaryToString(dst.Bytes()))
+	// Output: {"level":"trace","foo":"bar","n":123,"message":"hello world"}
+}
+
 func ExampleLogger_Debug() {
 	dst := bytes.Buffer{}
 	log := New(&dst)

cmd/lint/lint.go

@@ -0,0 +1,175 @@
+package main
+
+import (
+	"flag"
+	"fmt"
+	"go/ast"
+	"go/token"
+	"go/types"
+	"os"
+	"path/filepath"
+	"strings"
+
+	"golang.org/x/tools/go/loader"
+)
+
+var (
+	recursivelyIgnoredPkgs arrayFlag
+	ignoredPkgs            arrayFlag
+	ignoredFiles           arrayFlag
+	allowedFinishers       arrayFlag = []string{"Msg", "Msgf"}
+	rootPkg                string
+)
+
+// parse input flags and args
+func init() {
+	flag.Var(&recursivelyIgnoredPkgs, "ignorePkgRecursively", "ignore the specified package and all subpackages recursively")
+	flag.Var(&ignoredPkgs, "ignorePkg", "ignore the specified package")
+	flag.Var(&ignoredFiles, "ignoreFile", "ignore the specified file by its path and/or go path (package/file.go)")
+	flag.Var(&allowedFinishers, "finisher", "allowed finisher for the event chain")
+	flag.Parse()
+
+	// add zerolog to recursively ignored packages
+	recursivelyIgnoredPkgs = append(recursivelyIgnoredPkgs, "github.com/rs/zerolog")
+	args := flag.Args()
+	if len(args) != 1 {
+		fmt.Fprintln(os.Stderr, "you must provide exactly one package path")
+		os.Exit(1)
+	}
+	rootPkg = args[0]
+}
+
+func main() {
+	// load the package and all its dependencies
+	conf := loader.Config{}
+	conf.Import(rootPkg)
+	p, err := conf.Load()
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "Error: unable to load the root package. %s\n", err.Error())
+		os.Exit(1)
+	}
+
+	// get the github.com/rs/zerolog.Event type
+	event := getEvent(p)
+	if event == nil {
+		fmt.Fprintln(os.Stderr, "Error: github.com/rs/zerolog.Event declaration not found, maybe zerolog is not imported in the scanned package?")
+		os.Exit(1)
+	}
+
+	// get all selections (function calls) with the github.com/rs/zerolog.Event (or pointer) receiver
+	selections := getSelectionsWithReceiverType(p, event)
+
+	// print the violations (if any)
+	hasViolations := false
+	for _, s := range selections {
+		if hasBadFinisher(p, s) {
+			hasViolations = true
+			fmt.Printf("Error: missing or bad finisher for log chain, last call: %q at: %s:%v\n", s.fn.Name(), p.Fset.File(s.Pos()).Name(), p.Fset.Position(s.Pos()).Line)
+		}
+	}
+
+	// if no violations detected, return normally
+	if !hasViolations {
+		fmt.Println("No violations found")
+		return
+	}
+
+	// if violations were detected, return error code
+	os.Exit(1)
+}
+
+func getEvent(p *loader.Program) types.Type {
+	for _, pkg := range p.AllPackages {
+		if strings.HasSuffix(pkg.Pkg.Path(), "github.com/rs/zerolog") {
+			for _, d := range pkg.Defs {
+				if d != nil && d.Name() == "Event" {
+					return d.Type()
+				}
+			}
+		}
+	}
+
+	return nil
+}
+
+func getSelectionsWithReceiverType(p *loader.Program, targetType types.Type) map[token.Pos]selection {
+	selections := map[token.Pos]selection{}
+
+	for _, z := range p.AllPackages {
+		for i, t := range z.Selections {
+			switch o := t.Obj().(type) {
+			case *types.Func:
+				// this is not a bug, o.Type() is always *types.Signature, see docs
+				if vt := o.Type().(*types.Signature).Recv(); vt != nil {
+					typ := vt.Type()
+					if pointer, ok := typ.(*types.Pointer); ok {
+						typ = pointer.Elem()
+					}
+
+					if typ == targetType {
+						if s, ok := selections[i.Pos()]; !ok || i.End() > s.End() {
+							selections[i.Pos()] = selection{i, o, z.Pkg}
+						}
+					}
+				}
+			default:
+				// skip
+			}
+		}
+	}
+
+	return selections
+}
+
+func hasBadFinisher(p *loader.Program, s selection) bool {
+	pkgPath := strings.TrimPrefix(s.pkg.Path(), rootPkg+"/vendor/")
+	absoluteFilePath := strings.TrimPrefix(p.Fset.File(s.Pos()).Name(), rootPkg+"/vendor/")
+	goFilePath := pkgPath + "/" + filepath.Base(p.Fset.Position(s.Pos()).Filename)
+
+	for _, f := range allowedFinishers {
+		if f == s.fn.Name() {
+			return false
+		}
+	}
+
+	for _, ignoredPkg := range recursivelyIgnoredPkgs {
+		if strings.HasPrefix(pkgPath, ignoredPkg) {
+			return false
+		}
+	}
+
+	for _, ignoredPkg := range ignoredPkgs {
+		if pkgPath == ignoredPkg {
+			return false
+		}
+	}
+
+	for _, ignoredFile := range ignoredFiles {
+		if absoluteFilePath == ignoredFile {
+			return false
+		}
+
+		if goFilePath == ignoredFile {
+			return false
+		}
+	}
+
+	return true
+}
+
+type arrayFlag []string
+
+func (i *arrayFlag) String() string {
+	return fmt.Sprintf("%v", []string(*i))
+}
+
+func (i *arrayFlag) Set(value string) error {
+	*i = append(*i, value)
+	return nil
+}
+
+type selection struct {
+	*ast.SelectorExpr
+	fn  *types.Func
+	pkg *types.Package
+}

cmd/lint/readme.md

@@ -0,0 +1,37 @@
+# Zerolog Lint
+
+This is a basic linter that checks for missing log event finishers. Finds errors like: `log.Error().Int64("userID": 5)` - missing the `Msg`/`Msgf` finishers.
+
+## Problem
+
+When using zerolog it's easy to forget to finish the log event chain by calling a finisher - the `Msg` or `Msgf` function that will schedule the event for writing. The problem with this is that it doesn't warn/panic during compilation and it's not easily found by grep or other general tools. It's even prominently mentioned in the project's readme, that:
+
+> It is very important to note that when using the **zerolog** chaining API, as shown above (`log.Info().Msg("hello world"`), the chain must have either the `Msg` or `Msgf` method call. If you forget to add either of these, the log will not occur and there is no compile time error to alert you of this.
+
+## Solution
+
+A basic linter like this one here that looks for method invocations on `zerolog.Event` can examine the last call in a method call chain and check if it is a finisher, thus pointing out these errors.
+
+## Usage
+
+Just compile this and then run it. Or just run it via `go run` command via something like `go run cmd/lint/lint.go`.
+
+The command accepts only one argument - the package to be inspected - and 4 optional flags, all of which can occur multiple times. The standard synopsis of the command is:
+
+`lint [-finisher value] [-ignoreFile value] [-ignorePkg value] [-ignorePkgRecursively value] package`
+
+#### Flags
+
+- finisher
+    - specify which finishers to accept, defaults to `Msg` and `Msgf`
+- ignoreFile
+    - which files to ignore, either by full path or by go path (package/file.go)
+- ignorePkg
+    - do not inspect the specified package if found in the dependecy tree
+- ignorePkgRecursively
+    - do not inspect the specified package or its subpackages if found in the dependency tree
+
+## Drawbacks
+
+As it is, linter can generate a false positives in a specific case. These false positives come from the fact that if you have a method that returns a `zerolog.Event` the linter will flag it because you are obviously not finishing the event. This will be solved in later release.
+

console.go

@@ -5,6 +5,8 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"os"
+	"path/filepath"
 	"sort"
 	"strconv"
 	"strings"
@@ -13,122 +15,255 @@ import (
 )
 
 const (
-	cReset    = 0
-	cBold     = 1
-	cRed      = 31
-	cGreen    = 32
-	cYellow   = 33
-	cBlue     = 34
-	cMagenta  = 35
-	cCyan     = 36
-	cGray     = 37
-	cDarkGray = 90
+	colorBlack = iota + 30
+	colorRed
+	colorGreen
+	colorYellow
+	colorBlue
+	colorMagenta
+	colorCyan
+	colorWhite
+
+	colorBold     = 1
+	colorDarkGray = 90
 )
 
-var consoleBufPool = sync.Pool{
-	New: func() interface{} {
-		return bytes.NewBuffer(make([]byte, 0, 100))
-	},
-}
+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.
+const (
+	consoleDefaultTimeFormat = time.Kitchen
+)
+
+// Formatter transforms the input into a formatted string.
+type Formatter func(interface{}) string
+
+// ConsoleWriter parses the JSON input and writes it in an
+// (optionally) colorized, human-friendly format to Out.
 type ConsoleWriter struct {
-	Out     io.Writer
+	// Out is the output destination.
+	Out io.Writer
+
+	// NoColor disables the colorized output.
 	NoColor bool
+
+	// TimeFormat specifies the format for timestamp in output.
+	TimeFormat string
+
+	// PartsOrder defines the order of parts in output.
+	PartsOrder []string
+
+	// PartsExclude defines parts to not display in output.
+	PartsExclude []string
+
+	FormatTimestamp     Formatter
+	FormatLevel         Formatter
+	FormatCaller        Formatter
+	FormatMessage       Formatter
+	FormatFieldName     Formatter
+	FormatFieldValue    Formatter
+	FormatErrFieldName  Formatter
+	FormatErrFieldValue Formatter
 }
 
+// NewConsoleWriter creates and initializes a new ConsoleWriter.
+func NewConsoleWriter(options ...func(w *ConsoleWriter)) ConsoleWriter {
+	w := ConsoleWriter{
+		Out:        os.Stdout,
+		TimeFormat: consoleDefaultTimeFormat,
+		PartsOrder: consoleDefaultPartsOrder(),
+	}
+
+	for _, opt := range options {
+		opt(&w)
+	}
+
+	return w
+}
+
+// Write transforms the JSON input with formatters and appends to w.Out.
 func (w ConsoleWriter) Write(p []byte) (n int, err error) {
-	var event map[string]interface{}
+	if w.PartsOrder == nil {
+		w.PartsOrder = consoleDefaultPartsOrder()
+	}
+
+	var buf = consoleBufPool.Get().(*bytes.Buffer)
+	defer func() {
+		buf.Reset()
+		consoleBufPool.Put(buf)
+	}()
+
+	var evt map[string]interface{}
 	p = decodeIfBinaryToBytes(p)
 	d := json.NewDecoder(bytes.NewReader(p))
 	d.UseNumber()
-	err = d.Decode(&event)
+	err = d.Decode(&evt)
 	if err != nil {
-		return
+		return n, fmt.Errorf("cannot decode event: %s", err)
 	}
-	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]
+
+	for _, p := range w.PartsOrder {
+		w.writePart(buf, evt, p)
 	}
-	fmt.Fprintf(buf, "%s |%s| %s",
-		colorize(formatTime(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 {
+
+	w.writeFields(evt, buf)
+
+	err = buf.WriteByte('\n')
+	if err != nil {
+		return n, err
+	}
+	_, err = buf.WriteTo(w.Out)
+	return len(p), err
+}
+
+// writeFields appends formatted key-value pairs to buf.
+func (w ConsoleWriter) writeFields(evt map[string]interface{}, buf *bytes.Buffer) {
+	var fields = make([]string, 0, len(evt))
+	for field := range evt {
 		switch field {
-		case LevelFieldName, TimestampFieldName, MessageFieldName:
+		case LevelFieldName, TimestampFieldName, MessageFieldName, CallerFieldName:
 			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))
+
+	if len(fields) > 0 {
+		buf.WriteByte(' ')
+	}
+
+	// Move the "error" field to the front
+	ei := sort.Search(len(fields), func(i int) bool { return fields[i] >= ErrorFieldName })
+	if ei < len(fields) && fields[ei] == ErrorFieldName {
+		fields[ei] = ""
+		fields = append([]string{ErrorFieldName}, fields...)
+		var xfields = make([]string, 0, len(fields))
+		for _, field := range fields {
+			if field == "" { // Skip empty fields
+				continue
+			}
+			xfields = append(xfields, field)
+		}
+		fields = xfields
+	}
+
+	for i, field := range fields {
+		var fn Formatter
+		var fv Formatter
+
+		if field == ErrorFieldName {
+			if w.FormatErrFieldName == nil {
+				fn = consoleDefaultFormatErrFieldName(w.NoColor)
 			} else {
-				buf.WriteString(value)
+				fn = w.FormatErrFieldName
+			}
+
+			if w.FormatErrFieldValue == nil {
+				fv = consoleDefaultFormatErrFieldValue(w.NoColor)
+			} else {
+				fv = w.FormatErrFieldValue
+			}
+		} else {
+			if w.FormatFieldName == nil {
+				fn = consoleDefaultFormatFieldName(w.NoColor)
+			} else {
+				fn = w.FormatFieldName
+			}
+
+			if w.FormatFieldValue == nil {
+				fv = consoleDefaultFormatFieldValue
+			} else {
+				fv = w.FormatFieldValue
+			}
+		}
+
+		buf.WriteString(fn(field))
+
+		switch fValue := evt[field].(type) {
+		case string:
+			if needsQuote(fValue) {
+				buf.WriteString(fv(strconv.Quote(fValue)))
+			} else {
+				buf.WriteString(fv(fValue))
 			}
 		case json.Number:
-			fmt.Fprint(buf, value)
+			buf.WriteString(fv(fValue))
 		default:
-			b, err := json.Marshal(value)
+			b, err := json.Marshal(fValue)
 			if err != nil {
-				fmt.Fprintf(buf, "[error: %v]", err)
+				fmt.Fprintf(buf, colorize("[error: %v]", colorRed, w.NoColor), err)
 			} else {
-				fmt.Fprint(buf, string(b))
+				fmt.Fprint(buf, fv(b))
+			}
+		}
+
+		if i < len(fields)-1 { // Skip space for last field
+			buf.WriteByte(' ')
+		}
+	}
+}
+
+// writePart appends a formatted part to buf.
+func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{}, p string) {
+	var f Formatter
+
+	if w.PartsExclude != nil && len(w.PartsExclude) > 0 {
+		for _, exclude := range w.PartsExclude {
+			if exclude == p {
+				return
 			}
 		}
 	}
-	buf.WriteByte('\n')
-	buf.WriteTo(w.Out)
-	n = len(p)
-	return
-}
 
-func formatTime(t interface{}) string {
-	switch t := t.(type) {
-	case string:
-		return t
-	case json.Number:
-		u, _ := t.Int64()
-		return time.Unix(u, 0).Format(time.RFC3339)
-	}
-	return "<nil>"
-}
-
-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
+	switch p {
+	case LevelFieldName:
+		if w.FormatLevel == nil {
+			f = consoleDefaultFormatLevel(w.NoColor)
+		} else {
+			f = w.FormatLevel
+		}
+	case TimestampFieldName:
+		if w.FormatTimestamp == nil {
+			f = consoleDefaultFormatTimestamp(w.TimeFormat, w.NoColor)
+		} else {
+			f = w.FormatTimestamp
+		}
+	case MessageFieldName:
+		if w.FormatMessage == nil {
+			f = consoleDefaultFormatMessage
+		} else {
+			f = w.FormatMessage
+		}
+	case CallerFieldName:
+		if w.FormatCaller == nil {
+			f = consoleDefaultFormatCaller(w.NoColor)
+		} else {
+			f = w.FormatCaller
+		}
 	default:
-		return cReset
+		if w.FormatFieldValue == nil {
+			f = consoleDefaultFormatFieldValue
+		} else {
+			f = w.FormatFieldValue
+		}
+	}
+
+	var s = f(evt[p])
+
+	if len(s) > 0 {
+		buf.WriteString(s)
+		if p != w.PartsOrder[len(w.PartsOrder)-1] { // Skip space for last part
+			buf.WriteByte(' ')
+		}
 	}
 }
 
+// needsQuote returns true when the string s should be quoted in output.
 func needsQuote(s string) bool {
 	for i := range s {
 		if s[i] < 0x20 || s[i] > 0x7e || s[i] == ' ' || s[i] == '\\' || s[i] == '"' {
@@ -137,3 +272,138 @@ func needsQuote(s string) bool {
 	}
 	return false
 }
+
+// colorize returns the string s wrapped in ANSI code c, unless disabled is true.
+func colorize(s interface{}, c int, disabled bool) string {
+	if disabled {
+		return fmt.Sprintf("%s", s)
+	}
+	return fmt.Sprintf("\x1b[%dm%v\x1b[0m", c, s)
+}
+
+// ----- DEFAULT FORMATTERS ---------------------------------------------------
+
+func consoleDefaultPartsOrder() []string {
+	return []string{
+		TimestampFieldName,
+		LevelFieldName,
+		CallerFieldName,
+		MessageFieldName,
+	}
+}
+
+func consoleDefaultFormatTimestamp(timeFormat string, noColor bool) Formatter {
+	if timeFormat == "" {
+		timeFormat = consoleDefaultTimeFormat
+	}
+	return func(i interface{}) string {
+		t := "<nil>"
+		switch tt := i.(type) {
+		case string:
+			ts, err := time.Parse(TimeFieldFormat, tt)
+			if err != nil {
+				t = tt
+			} else {
+				t = ts.Format(timeFormat)
+			}
+		case json.Number:
+			i, err := tt.Int64()
+			if err != nil {
+				t = tt.String()
+			} else {
+				var sec, nsec int64 = i, 0
+				switch TimeFieldFormat {
+				case TimeFormatUnixMs:
+					nsec = int64(time.Duration(i) * time.Millisecond)
+					sec = 0
+				case TimeFormatUnixMicro:
+					nsec = int64(time.Duration(i) * time.Microsecond)
+					sec = 0
+				}
+				ts := time.Unix(sec, nsec).UTC()
+				t = ts.Format(timeFormat)
+			}
+		}
+		return colorize(t, colorDarkGray, noColor)
+	}
+}
+
+func consoleDefaultFormatLevel(noColor bool) Formatter {
+	return func(i interface{}) string {
+		var l string
+		if ll, ok := i.(string); ok {
+			switch ll {
+			case "trace":
+				l = colorize("TRC", colorMagenta, noColor)
+			case "debug":
+				l = colorize("DBG", colorYellow, noColor)
+			case "info":
+				l = colorize("INF", colorGreen, noColor)
+			case "warn":
+				l = colorize("WRN", colorRed, noColor)
+			case "error":
+				l = colorize(colorize("ERR", colorRed, noColor), colorBold, noColor)
+			case "fatal":
+				l = colorize(colorize("FTL", colorRed, noColor), colorBold, noColor)
+			case "panic":
+				l = colorize(colorize("PNC", colorRed, noColor), colorBold, noColor)
+			default:
+				l = colorize("???", colorBold, noColor)
+			}
+		} else {
+			if i == nil {
+				l = colorize("???", colorBold, noColor)
+			} else {
+				l = strings.ToUpper(fmt.Sprintf("%s", i))[0:3]
+			}
+		}
+		return l
+	}
+}
+
+func consoleDefaultFormatCaller(noColor bool) Formatter {
+	return func(i interface{}) string {
+		var c string
+		if cc, ok := i.(string); ok {
+			c = cc
+		}
+		if len(c) > 0 {
+			if cwd, err := os.Getwd(); err == nil {
+				if rel, err := filepath.Rel(cwd, c); err == nil {
+					c = rel
+				}
+			}
+			c = colorize(c, colorBold, noColor) + colorize(" >", colorCyan, noColor)
+		}
+		return c
+	}
+}
+
+func consoleDefaultFormatMessage(i interface{}) string {
+	if i == nil {
+		return ""
+	}
+	return fmt.Sprintf("%s", i)
+}
+
+func consoleDefaultFormatFieldName(noColor bool) Formatter {
+	return func(i interface{}) string {
+		return colorize(fmt.Sprintf("%s=", i), colorCyan, noColor)
+	}
+}
+
+func consoleDefaultFormatFieldValue(i interface{}) string {
+	return fmt.Sprintf("%s", i)
+}
+
+func consoleDefaultFormatErrFieldName(noColor bool) Formatter {
+	return func(i interface{}) string {
+		return colorize(fmt.Sprintf("%s=", i), colorRed, noColor)
+	}
+}
+
+func consoleDefaultFormatErrFieldValue(noColor bool) Formatter {
+	return func(i interface{}) string {
+		return colorize(fmt.Sprintf("%s", i), colorRed, noColor)
+	}
+}

console_test.go

@@ -2,29 +2,369 @@ package zerolog_test
 
 import (
 	"bytes"
+	"fmt"
+	"io/ioutil"
 	"os"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/rs/zerolog"
 )
 
-func ExampleConsoleWriter_Write() {
+func ExampleConsoleWriter() {
 	log := zerolog.New(zerolog.ConsoleWriter{Out: os.Stdout, NoColor: true})
 
-	log.Info().Msg("hello world")
-	// Output: <nil> |INFO| hello world
+	log.Info().Str("foo", "bar").Msg("Hello World")
+	// Output: <nil> INF Hello World foo=bar
 }
 
-func TestConsoleWriterNumbers(t *testing.T) {
-	buf := &bytes.Buffer{}
-	log := zerolog.New(zerolog.ConsoleWriter{Out: buf, NoColor: true})
-	log.Info().
-		Float64("float", 1.23).
-		Uint64("small", 123).
-		Uint64("big", 1152921504606846976).
-		Msg("msg")
-	if got, want := strings.TrimSpace(buf.String()), "<nil> |INFO| msg big=1152921504606846976 float=1.23 small=123"; got != want {
-		t.Errorf("\ngot:\n%s\nwant:\n%s", got, want)
+func ExampleConsoleWriter_customFormatters() {
+	out := zerolog.ConsoleWriter{Out: os.Stdout, NoColor: true}
+	out.FormatLevel = func(i interface{}) string { return strings.ToUpper(fmt.Sprintf("%-6s|", i)) }
+	out.FormatFieldName = func(i interface{}) string { return fmt.Sprintf("%s:", i) }
+	out.FormatFieldValue = func(i interface{}) string { return strings.ToUpper(fmt.Sprintf("%s", i)) }
+	log := zerolog.New(out)
+
+	log.Info().Str("foo", "bar").Msg("Hello World")
+	// Output: <nil> INFO  | Hello World foo:BAR
+}
+
+func ExampleNewConsoleWriter() {
+	out := zerolog.NewConsoleWriter()
+	out.NoColor = true // For testing purposes only
+	log := zerolog.New(out)
+
+	log.Debug().Str("foo", "bar").Msg("Hello World")
+	// Output: <nil> DBG Hello World foo=bar
+}
+
+func ExampleNewConsoleWriter_customFormatters() {
+	out := zerolog.NewConsoleWriter(
+		func(w *zerolog.ConsoleWriter) {
+			// Customize time format
+			w.TimeFormat = time.RFC822
+			// Customize level formatting
+			w.FormatLevel = func(i interface{}) string { return strings.ToUpper(fmt.Sprintf("[%-5s]", i)) }
+		},
+	)
+	out.NoColor = true // For testing purposes only
+
+	log := zerolog.New(out)
+
+	log.Info().Str("foo", "bar").Msg("Hello World")
+	// Output: <nil> [INFO ] Hello World foo=bar
+}
+
+func TestConsoleLogger(t *testing.T) {
+	t.Run("Numbers", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		log := zerolog.New(zerolog.ConsoleWriter{Out: buf, NoColor: true})
+		log.Info().
+			Float64("float", 1.23).
+			Uint64("small", 123).
+			Uint64("big", 1152921504606846976).
+			Msg("msg")
+		if got, want := strings.TrimSpace(buf.String()), "<nil> INF msg big=1152921504606846976 float=1.23 small=123"; got != want {
+			t.Errorf("\ngot:\n%s\nwant:\n%s", got, want)
+		}
+	})
+}
+
+func TestConsoleWriter(t *testing.T) {
+	t.Run("Default field formatter", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true, PartsOrder: []string{"foo"}}
+
+		_, err := w.Write([]byte(`{"foo": "DEFAULT"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "DEFAULT foo=DEFAULT\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Write colorized", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: false}
+
+		_, err := w.Write([]byte(`{"level": "warn", "message": "Foobar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "\x1b[90m<nil>\x1b[0m \x1b[31mWRN\x1b[0m Foobar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Write fields", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
+
+		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		_, err := w.Write([]byte(`{"time": "` + d + `", "level": "debug", "message": "Foobar", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "12:00AM DBG Foobar foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Unix timestamp input format", func(t *testing.T) {
+		of := zerolog.TimeFieldFormat
+		defer func() {
+			zerolog.TimeFieldFormat = of
+		}()
+		zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
+
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, TimeFormat: time.StampMilli, NoColor: true}
+
+		_, err := w.Write([]byte(`{"time": 1234, "level": "debug", "message": "Foobar", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "Jan  1 00:20:34.000 DBG Foobar foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Unix timestamp ms input format", func(t *testing.T) {
+		of := zerolog.TimeFieldFormat
+		defer func() {
+			zerolog.TimeFieldFormat = of
+		}()
+		zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMs
+
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, TimeFormat: time.StampMilli, NoColor: true}
+
+		_, err := w.Write([]byte(`{"time": 1234567, "level": "debug", "message": "Foobar", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "Jan  1 00:20:34.567 DBG Foobar foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Unix timestamp us input format", func(t *testing.T) {
+		of := zerolog.TimeFieldFormat
+		defer func() {
+			zerolog.TimeFieldFormat = of
+		}()
+		zerolog.TimeFieldFormat = zerolog.TimeFormatUnixMicro
+
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, TimeFormat: time.StampMicro, NoColor: true}
+
+		_, err := w.Write([]byte(`{"time": 1234567891, "level": "debug", "message": "Foobar", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "Jan  1 00:20:34.567891 DBG Foobar foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("No message field", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
+
+		_, err := w.Write([]byte(`{"level": "debug", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "<nil> DBG  foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("No level field", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
+
+		_, err := w.Write([]byte(`{"message": "Foobar", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "<nil> ??? Foobar foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Write colorized fields", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: false}
+
+		_, err := w.Write([]byte(`{"level": "warn", "message": "Foobar", "foo": "bar"}`))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "\x1b[90m<nil>\x1b[0m \x1b[31mWRN\x1b[0m Foobar \x1b[36mfoo=\x1b[0mbar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Write error field", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
+
+		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		evt := `{"time": "` + d + `", "level": "error", "message": "Foobar", "aaa": "bbb", "error": "Error"}`
+		// t.Log(evt)
+
+		_, err := w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "12:00AM ERR Foobar error=Error aaa=bbb\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Write caller field", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
+
+		cwd, err := os.Getwd()
+		if err != nil {
+			t.Fatalf("Cannot get working directory: %s", err)
+		}
+
+		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		evt := `{"time": "` + d + `", "level": "debug", "message": "Foobar", "foo": "bar", "caller": "` + cwd + `/foo/bar.go"}`
+		// t.Log(evt)
+
+		_, err = w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "12:00AM DBG foo/bar.go > Foobar foo=bar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Write JSON field", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true}
+
+		evt := `{"level": "debug", "message": "Foobar", "foo": [1, 2, 3], "bar": true}`
+		// t.Log(evt)
+
+		_, err := w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "<nil> DBG Foobar bar=true foo=[1,2,3]\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+}
+
+func TestConsoleWriterConfiguration(t *testing.T) {
+	t.Run("Sets TimeFormat", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true, TimeFormat: time.RFC3339}
+
+		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		evt := `{"time": "` + d + `", "level": "info", "message": "Foobar"}`
+
+		_, err := w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "1970-01-01T00:00:00Z INF Foobar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Sets PartsOrder", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true, PartsOrder: []string{"message", "level"}}
+
+		evt := `{"level": "info", "message": "Foobar"}`
+		_, err := w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "Foobar INF\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+
+	t.Run("Sets PartsExclude", func(t *testing.T) {
+		buf := &bytes.Buffer{}
+		w := zerolog.ConsoleWriter{Out: buf, NoColor: true, PartsExclude: []string{"time"}}
+
+		d := time.Unix(0, 0).UTC().Format(time.RFC3339)
+		evt := `{"time": "` + d + `", "level": "info", "message": "Foobar"}`
+		_, err := w.Write([]byte(evt))
+		if err != nil {
+			t.Errorf("Unexpected error when writing output: %s", err)
+		}
+
+		expectedOutput := "INF Foobar\n"
+		actualOutput := buf.String()
+		if actualOutput != expectedOutput {
+			t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput)
+		}
+	})
+}
+
+func BenchmarkConsoleWriter(b *testing.B) {
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	var msg = []byte(`{"level": "info", "foo": "bar", "message": "HELLO", "time": "1990-01-01"}`)
+
+	w := zerolog.ConsoleWriter{Out: ioutil.Discard, NoColor: false}
+
+	for i := 0; i < b.N; i++ {
+		w.Write(msg)
 	}
 }

context.go

@@ -1,7 +1,9 @@
 package zerolog
 
 import (
+	"fmt"
 	"io/ioutil"
+	"math"
 	"net"
 	"time"
 )
@@ -26,7 +28,7 @@ func (c Context) Fields(fields map[string]interface{}) Context {
 func (c Context) Dict(key string, dict *Event) Context {
 	dict.buf = enc.AppendEndMarker(dict.buf)
 	c.l.context = append(enc.AppendKey(c.l.context, key), dict.buf...)
-	eventPool.Put(dict)
+	putEvent(dict)
 	return c
 }
 
@@ -55,7 +57,7 @@ func (c Context) Object(key string, obj LogObjectMarshaler) Context {
 	e := newEvent(levelWriterAdapter{ioutil.Discard}, 0)
 	e.Object(key, obj)
 	c.l.context = enc.AppendObjectData(c.l.context, e.buf)
-	eventPool.Put(e)
+	putEvent(e)
 	return c
 }
 
@@ -64,7 +66,7 @@ func (c Context) EmbedObject(obj LogObjectMarshaler) Context {
 	e := newEvent(levelWriterAdapter{ioutil.Discard}, 0)
 	e.EmbedObject(obj)
 	c.l.context = enc.AppendObjectData(c.l.context, e.buf)
-	eventPool.Put(e)
+	putEvent(e)
 	return c
 }
 
@@ -80,6 +82,17 @@ func (c Context) Strs(key string, vals []string) Context {
 	return c
 }
 
+// Stringer adds the field key with val.String() (or null if val is nil) to the logger context.
+func (c Context) Stringer(key string, val fmt.Stringer) Context {
+	if val != nil {
+		c.l.context = enc.AppendString(enc.AppendKey(c.l.context, key), val.String())
+		return c
+	}
+
+	c.l.context = enc.AppendInterface(enc.AppendKey(c.l.context, key), nil)
+	return c
+}
+
 // Bytes adds the field key with val as a []byte to the logger context.
 func (c Context) Bytes(key string, val []byte) Context {
 	c.l.context = enc.AppendBytes(enc.AppendKey(c.l.context, key), val)
@@ -101,27 +114,53 @@ func (c Context) RawJSON(key string, b []byte) Context {
 	return c
 }
 
-// AnErr adds the field key with err as a string to the logger context.
+// AnErr adds the field key with serialized err to the logger context.
 func (c Context) AnErr(key string, err error) Context {
-	if err != nil {
-		c.l.context = enc.AppendError(enc.AppendKey(c.l.context, key), err)
+	switch m := ErrorMarshalFunc(err).(type) {
+	case nil:
+		return c
+	case LogObjectMarshaler:
+		return c.Object(key, m)
+	case error:
+		if m == nil || isNilValue(m) {
+			return c
+		} else {
+			return c.Str(key, m.Error())
+		}
+	case string:
+		return c.Str(key, m)
+	default:
+		return c.Interface(key, m)
 	}
-	return c
 }
 
-// Errs adds the field key with errs as an array of strings to the logger context.
+// Errs adds the field key with errs as an array of serialized errors to the
+// logger context.
 func (c Context) Errs(key string, errs []error) Context {
-	c.l.context = enc.AppendErrors(enc.AppendKey(c.l.context, key), errs)
-	return c
+	arr := Arr()
+	for _, err := range errs {
+		switch m := ErrorMarshalFunc(err).(type) {
+		case LogObjectMarshaler:
+			arr = arr.Object(m)
+		case error:
+			if m == nil || isNilValue(m) {
+				arr = arr.Interface(nil)
+			} else {
+				arr = arr.Str(m.Error())
+			}
+		case string:
+			arr = arr.Str(m)
+		default:
+			arr = arr.Interface(m)
+		}
+	}
+
+	return c.Array(key, arr)
 }
 
-// Err adds the field "error" with err as a string to the logger context.
-// To customize the key name, change zerolog.ErrorFieldName.
+// Err adds the field "error" with serialized err to the logger context.
 func (c Context) Err(err error) Context {
-	if err != nil {
-		c.l.context = enc.AppendError(enc.AppendKey(c.l.context, ErrorFieldName), err)
-	}
-	return c
+	return c.AnErr(ErrorFieldName, err)
 }
 
 // Bool adds the field key with val as a bool to the logger context.
@@ -327,14 +366,31 @@ func (c Context) Interface(key string, i interface{}) Context {
 	return c
 }
 
-type callerHook struct{}
-
-func (ch callerHook) Run(e *Event, level Level, msg string) {
-        //Two extra frames to skip (added by hook infra).
-	e.caller(CallerSkipFrameCount+2)
+type callerHook struct {
+	callerSkipFrameCount int
 }
 
-var ch = callerHook{}
+func newCallerHook(skipFrameCount int) callerHook {
+	return callerHook{callerSkipFrameCount: skipFrameCount}
+}
+
+func (ch callerHook) Run(e *Event, level Level, msg string) {
+	switch ch.callerSkipFrameCount {
+	case useGlobalSkipFrameCount:
+		// Extra frames to skip (added by hook infra).
+		e.caller(CallerSkipFrameCount + contextCallerSkipFrameCount)
+	default:
+		// Extra frames to skip (added by hook infra).
+		e.caller(ch.callerSkipFrameCount + contextCallerSkipFrameCount)
+	}
+}
+
+// useGlobalSkipFrameCount acts as a flag to informat callerHook.Run
+// to use the global CallerSkipFrameCount.
+const useGlobalSkipFrameCount = math.MinInt32
+
+// ch is the default caller hook using the global CallerSkipFrameCount.
+var ch = newCallerHook(useGlobalSkipFrameCount)
 
 // Caller adds the file:line of the caller with the zerolog.CallerFieldName key.
 func (c Context) Caller() Context {
@@ -342,6 +398,20 @@ func (c Context) Caller() Context {
 	return c
 }
 
+// CallerWithSkipFrameCount adds the file:line of the caller with the zerolog.CallerFieldName key.
+// The specified skipFrameCount int will override the global CallerSkipFrameCount for this context's respective logger.
+// If set to -1 the global CallerSkipFrameCount will be used.
+func (c Context) CallerWithSkipFrameCount(skipFrameCount int) Context {
+	c.l = c.l.Hook(newCallerHook(skipFrameCount))
+	return c
+}
+
+// Stack enables stack trace printing for the error passed to Err().
+func (c Context) Stack() Context {
+	c.l.stack = true
+	return c
+}
+
 // IPAddr adds IPv4 or IPv6 Address to the context
 func (c Context) IPAddr(key string, ip net.IP) Context {
 	c.l.context = enc.AppendIPAddr(enc.AppendKey(c.l.context, key), ip)

ctx.go

@@ -2,38 +2,40 @@ package zerolog
 
 import (
 	"context"
-	"io/ioutil"
 )
 
 var disabledLogger *Logger
 
 func init() {
-	l := New(ioutil.Discard).Level(Disabled)
+	SetGlobalLevel(TraceLevel)
+	l := Nop()
 	disabledLogger = &l
 }
 
 type ctxKey struct{}
 
 // 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.
+// is already in the context, the context is not updated.
 //
 // 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 {
+//     l.UpdateContext(func(c Context) Context {
+//         return c.Str("bar", "baz")
+//     })
+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 {
+		if lp == l {
+			// Do not store same logger.
+			return ctx
+		}
+	} else if l.level == Disabled {
 		// Do not store disabled logger.
 		return ctx
 	}
-	return context.WithValue(ctx, ctxKey{}, &l)
+	return context.WithValue(ctx, ctxKey{}, l)
 }
 
 // Ctx returns the Logger associated with the ctx. If no logger

ctx_test.go

@@ -30,18 +30,34 @@ func TestCtx(t *testing.T) {
 }
 
 func TestCtxDisabled(t *testing.T) {
-	ctx := disabledLogger.WithContext(context.Background())
+	dl := New(ioutil.Discard).Level(Disabled)
+	ctx := dl.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) {
+	l := New(ioutil.Discard).With().Str("foo", "bar").Logger()
+	ctx = l.WithContext(ctx)
+	if Ctx(ctx) != &l {
 		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")
+	l.UpdateContext(func(c Context) Context {
+		return c.Str("bar", "baz")
+	})
+	ctx = l.WithContext(ctx)
+	if Ctx(ctx) != &l {
+		t.Error("WithContext did not store updated logger")
+	}
+
+	l = l.Level(DebugLevel)
+	ctx = l.WithContext(ctx)
+	if Ctx(ctx) != &l {
+		t.Error("WithContext did not store copied logger")
+	}
+
+	ctx = dl.WithContext(ctx)
+	if Ctx(ctx) != &dl {
+		t.Error("WithContext did not overide logger with a disabled logger")
 	}
 }

diode/diode.go

@@ -8,7 +8,7 @@ import (
 	"sync"
 	"time"
 
-	diodes "code.cloudfoundry.org/go-diodes"
+	"github.com/rs/zerolog/diode/internal/diodes"
 )
 
 var bufPool = &sync.Pool{
@@ -17,12 +17,18 @@ var bufPool = &sync.Pool{
 	},
 }
 
+type Alerter func(missed int)
+
+type diodeFetcher interface {
+	diodes.Diode
+	Next() diodes.GenericDataType
+}
+
 // Writer is a io.Writer wrapper that uses a diode to make Write lock-free,
 // non-blocking and thread safe.
 type Writer struct {
 	w    io.Writer
-	d    *diodes.ManyToOne
-	p    *diodes.Poller
+	d    diodeFetcher
 	c    context.CancelFunc
 	done chan struct{}
 }
@@ -33,24 +39,34 @@ type Writer struct {
 //
 // Use a diode.Writer when
 //
-//     d := diodes.NewManyToOne(1000, diodes.AlertFunc(func(missed int) {
+//     wr := diode.NewWriter(w, 1000, 0, func(missed int) {
 //         log.Printf("Dropped %d messages", missed)
-//     }))
-//     w := diode.NewWriter(w, d, 10 * time.Millisecond)
-//     log := zerolog.New(w)
+//     })
+//     log := zerolog.New(wr)
+//
+// If pollInterval is greater than 0, a poller is used otherwise a waiter is
+// used.
 //
 // See code.cloudfoundry.org/go-diodes for more info on diode.
-func NewWriter(w io.Writer, manyToOneDiode *diodes.ManyToOne, poolInterval time.Duration) Writer {
+func NewWriter(w io.Writer, size int, pollInterval time.Duration, f Alerter) Writer {
 	ctx, cancel := context.WithCancel(context.Background())
 	dw := Writer{
-		w: w,
-		d: manyToOneDiode,
-		p: diodes.NewPoller(manyToOneDiode,
-			diodes.WithPollingInterval(poolInterval),
-			diodes.WithPollingContext(ctx)),
+		w:    w,
 		c:    cancel,
 		done: make(chan struct{}),
 	}
+	if f == nil {
+		f = func(int) {}
+	}
+	d := diodes.NewManyToOne(size, diodes.AlertFunc(f))
+	if pollInterval > 0 {
+		dw.d = diodes.NewPoller(d,
+			diodes.WithPollingInterval(pollInterval),
+			diodes.WithPollingContext(ctx))
+	} else {
+		dw.d = diodes.NewWaiter(d,
+			diodes.WithWaiterContext(ctx))
+	}
 	go dw.poll()
 	return dw
 }
@@ -77,12 +93,22 @@ func (dw Writer) Close() error {
 func (dw Writer) poll() {
 	defer close(dw.done)
 	for {
-		d := dw.p.Next()
+		d := dw.d.Next()
 		if d == nil {
 			return
 		}
 		p := *(*[]byte)(d)
 		dw.w.Write(p)
-		bufPool.Put(p[:0])
+
+		// Proper usage of a sync.Pool requires each entry to have approximately
+		// the same memory cost. To obtain this property when the stored type
+		// contains a variably-sized buffer, we add a hard limit on the maximum buffer
+		// to place back in the pool.
+		//
+		// See https://golang.org/issue/23199
+		const maxSize = 1 << 16 // 64KiB
+		if cap(p) <= maxSize {
+			bufPool.Put(p[:0])
+		}
 	}
 }

diode/diode_example_test.go

@@ -5,18 +5,15 @@ package diode_test
 import (
 	"fmt"
 	"os"
-	"time"
 
-	diodes "code.cloudfoundry.org/go-diodes"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/diode"
 )
 
 func ExampleNewWriter() {
-	d := diodes.NewManyToOne(1000, diodes.AlertFunc(func(missed int) {
+	w := diode.NewWriter(os.Stdout, 1000, 0, func(missed int) {
 		fmt.Printf("Dropped %d messages\n", missed)
-	}))
-	w := diode.NewWriter(os.Stdout, d, 10*time.Millisecond)
+	})
 	log := zerolog.New(w)
 	log.Print("test")
 

diode/diode_test.go

@@ -9,18 +9,16 @@ import (
 	"testing"
 	"time"
 
-	diodes "code.cloudfoundry.org/go-diodes"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/diode"
 	"github.com/rs/zerolog/internal/cbor"
 )
 
 func TestNewWriter(t *testing.T) {
-	d := diodes.NewManyToOne(1000, diodes.AlertFunc(func(missed int) {
-		fmt.Printf("Dropped %d messages\n", missed)
-	}))
 	buf := bytes.Buffer{}
-	w := diode.NewWriter(&buf, d, 10*time.Millisecond)
+	w := diode.NewWriter(&buf, 1000, 0, func(missed int) {
+		fmt.Printf("Dropped %d messages\n", missed)
+	})
 	log := zerolog.New(w)
 	log.Print("test")
 
@@ -35,16 +33,22 @@ func TestNewWriter(t *testing.T) {
 func Benchmark(b *testing.B) {
 	log.SetOutput(ioutil.Discard)
 	defer log.SetOutput(os.Stderr)
-	d := diodes.NewManyToOne(100000, nil)
-	w := diode.NewWriter(ioutil.Discard, d, 10*time.Millisecond)
-	log := zerolog.New(w)
-	defer w.Close()
-
-	b.SetParallelism(1000)
-	b.RunParallel(func(pb *testing.PB) {
-		for pb.Next() {
-			log.Print("test")
-		}
-	})
+	benchs := map[string]time.Duration{
+		"Waiter": 0,
+		"Pooler": 10 * time.Millisecond,
+	}
+	for name, interval := range benchs {
+		b.Run(name, func(b *testing.B) {
+			w := diode.NewWriter(ioutil.Discard, 100000, interval, nil)
+			log := zerolog.New(w)
+			defer w.Close()
 
+			b.SetParallelism(1000)
+			b.RunParallel(func(pb *testing.PB) {
+				for pb.Next() {
+					log.Print("test")
+				}
+			})
+		})
+	}
 }

diode/internal/diodes/README

@@ -0,0 +1 @@
+Copied from https://github.com/cloudfoundry/go-diodes to avoid test dependencies.

diode/internal/diodes/many_to_one.go

@@ -0,0 +1,130 @@
+package diodes
+
+import (
+	"log"
+	"sync/atomic"
+	"unsafe"
+)
+
+// ManyToOne diode is optimal for many writers (go-routines B-n) and a single
+// reader (go-routine A). It is not thread safe for multiple readers.
+type ManyToOne struct {
+	writeIndex uint64
+	readIndex  uint64
+	buffer     []unsafe.Pointer
+	alerter    Alerter
+}
+
+// NewManyToOne creates a new diode (ring buffer). The ManyToOne diode
+// is optimzed for many writers (on go-routines B-n) and a single reader
+// (on go-routine A). The alerter is invoked on the read's go-routine. It is
+// called when it notices that the writer go-routine has passed it and wrote
+// over data. A nil can be used to ignore alerts.
+func NewManyToOne(size int, alerter Alerter) *ManyToOne {
+	if alerter == nil {
+		alerter = AlertFunc(func(int) {})
+	}
+
+	d := &ManyToOne{
+		buffer:  make([]unsafe.Pointer, size),
+		alerter: alerter,
+	}
+
+	// Start write index at the value before 0
+	// to allow the first write to use AddUint64
+	// and still have a beginning index of 0
+	d.writeIndex = ^d.writeIndex
+	return d
+}
+
+// Set sets the data in the next slot of the ring buffer.
+func (d *ManyToOne) Set(data GenericDataType) {
+	for {
+		writeIndex := atomic.AddUint64(&d.writeIndex, 1)
+		idx := writeIndex % uint64(len(d.buffer))
+		old := atomic.LoadPointer(&d.buffer[idx])
+
+		if old != nil &&
+			(*bucket)(old) != nil &&
+			(*bucket)(old).seq > writeIndex-uint64(len(d.buffer)) {
+			log.Println("Diode set collision: consider using a larger diode")
+			continue
+		}
+
+		newBucket := &bucket{
+			data: data,
+			seq:  writeIndex,
+		}
+
+		if !atomic.CompareAndSwapPointer(&d.buffer[idx], old, unsafe.Pointer(newBucket)) {
+			log.Println("Diode set collision: consider using a larger diode")
+			continue
+		}
+
+		return
+	}
+}
+
+// TryNext will attempt to read from the next slot of the ring buffer.
+// If there is not data available, it will return (nil, false).
+func (d *ManyToOne) TryNext() (data GenericDataType, ok bool) {
+	// Read a value from the ring buffer based on the readIndex.
+	idx := d.readIndex % uint64(len(d.buffer))
+	result := (*bucket)(atomic.SwapPointer(&d.buffer[idx], nil))
+
+	// When the result is nil that means the writer has not had the
+	// opportunity to write a value into the diode. This value must be ignored
+	// and the read head must not increment.
+	if result == nil {
+		return nil, false
+	}
+
+	// When the seq value is less than the current read index that means a
+	// value was read from idx that was previously written but has since has
+	// been dropped. This value must be ignored and the read head must not
+	// increment.
+	//
+	// The simulation for this scenario assumes the fast forward occurred as
+	// detailed below.
+	//
+	// 5. The reader reads again getting seq 5. It then reads again expecting
+	//    seq 6 but gets seq 2. This is a read of a stale value that was
+	//    effectively "dropped" so the read fails and the read head stays put.
+	//    `| 4 | 5 | 2 | 3 |` r: 7, w: 6
+	//
+	if result.seq < d.readIndex {
+		return nil, false
+	}
+
+	// When the seq value is greater than the current read index that means a
+	// value was read from idx that overwrote the value that was expected to
+	// be at this idx. This happens when the writer has lapped the reader. The
+	// reader needs to catch up to the writer so it moves its write head to
+	// the new seq, effectively dropping the messages that were not read in
+	// between the two values.
+	//
+	// Here is a simulation of this scenario:
+	//
+	// 1. Both the read and write heads start at 0.
+	//    `| nil | nil | nil | nil |` r: 0, w: 0
+	// 2. The writer fills the buffer.
+	//    `| 0 | 1 | 2 | 3 |` r: 0, w: 4
+	// 3. The writer laps the read head.
+	//    `| 4 | 5 | 2 | 3 |` r: 0, w: 6
+	// 4. The reader reads the first value, expecting a seq of 0 but reads 4,
+	//    this forces the reader to fast forward to 5.
+	//    `| 4 | 5 | 2 | 3 |` r: 5, w: 6
+	//
+	if result.seq > d.readIndex {
+		dropped := result.seq - d.readIndex
+		d.readIndex = result.seq
+		d.alerter.Alert(int(dropped))
+	}
+
+	// Only increment read index if a regular read occurred (where seq was
+	// equal to readIndex) or a value was read that caused a fast forward
+	// (where seq was greater than readIndex).
+	//
+	d.readIndex++
+	return result.data, true
+}

diode/internal/diodes/one_to_one.go

@@ -0,0 +1,129 @@
+package diodes
+
+import (
+	"sync/atomic"
+	"unsafe"
+)
+
+// GenericDataType is the data type the diodes operate on.
+type GenericDataType unsafe.Pointer
+
+// Alerter is used to report how many values were overwritten since the
+// last write.
+type Alerter interface {
+	Alert(missed int)
+}
+
+// AlertFunc type is an adapter to allow the use of ordinary functions as
+// Alert handlers.
+type AlertFunc func(missed int)
+
+// Alert calls f(missed)
+func (f AlertFunc) Alert(missed int) {
+	f(missed)
+}
+
+type bucket struct {
+	data GenericDataType
+	seq  uint64 // seq is the recorded write index at the time of writing
+}
+
+// OneToOne diode is meant to be used by a single reader and a single writer.
+// It is not thread safe if used otherwise.
+type OneToOne struct {
+	writeIndex uint64
+	readIndex  uint64
+	buffer     []unsafe.Pointer
+	alerter    Alerter
+}
+
+// NewOneToOne creates a new diode is meant to be used by a single reader and
+// a single writer. The alerter is invoked on the read's go-routine. It is
+// called when it notices that the writer go-routine has passed it and wrote
+// over data. A nil can be used to ignore alerts.
+func NewOneToOne(size int, alerter Alerter) *OneToOne {
+	if alerter == nil {
+		alerter = AlertFunc(func(int) {})
+	}
+
+	return &OneToOne{
+		buffer:  make([]unsafe.Pointer, size),
+		alerter: alerter,
+	}
+}
+
+// Set sets the data in the next slot of the ring buffer.
+func (d *OneToOne) Set(data GenericDataType) {
+	idx := d.writeIndex % uint64(len(d.buffer))
+
+	newBucket := &bucket{
+		data: data,
+		seq:  d.writeIndex,
+	}
+	d.writeIndex++
+
+	atomic.StorePointer(&d.buffer[idx], unsafe.Pointer(newBucket))
+}
+
+// TryNext will attempt to read from the next slot of the ring buffer.
+// If there is no data available, it will return (nil, false).
+func (d *OneToOne) TryNext() (data GenericDataType, ok bool) {
+	// Read a value from the ring buffer based on the readIndex.
+	idx := d.readIndex % uint64(len(d.buffer))
+	result := (*bucket)(atomic.SwapPointer(&d.buffer[idx], nil))
+
+	// When the result is nil that means the writer has not had the
+	// opportunity to write a value into the diode. This value must be ignored
+	// and the read head must not increment.
+	if result == nil {
+		return nil, false
+	}
+
+	// When the seq value is less than the current read index that means a
+	// value was read from idx that was previously written but has since has
+	// been dropped. This value must be ignored and the read head must not
+	// increment.
+	//
+	// The simulation for this scenario assumes the fast forward occurred as
+	// detailed below.
+	//
+	// 5. The reader reads again getting seq 5. It then reads again expecting
+	//    seq 6 but gets seq 2. This is a read of a stale value that was
+	//    effectively "dropped" so the read fails and the read head stays put.
+	//    `| 4 | 5 | 2 | 3 |` r: 7, w: 6
+	//
+	if result.seq < d.readIndex {
+		return nil, false
+	}
+
+	// When the seq value is greater than the current read index that means a
+	// value was read from idx that overwrote the value that was expected to
+	// be at this idx. This happens when the writer has lapped the reader. The
+	// reader needs to catch up to the writer so it moves its write head to
+	// the new seq, effectively dropping the messages that were not read in
+	// between the two values.
+	//
+	// Here is a simulation of this scenario:
+	//
+	// 1. Both the read and write heads start at 0.
+	//    `| nil | nil | nil | nil |` r: 0, w: 0
+	// 2. The writer fills the buffer.
+	//    `| 0 | 1 | 2 | 3 |` r: 0, w: 4
+	// 3. The writer laps the read head.
+	//    `| 4 | 5 | 2 | 3 |` r: 0, w: 6
+	// 4. The reader reads the first value, expecting a seq of 0 but reads 4,
+	//    this forces the reader to fast forward to 5.
+	//    `| 4 | 5 | 2 | 3 |` r: 5, w: 6
+	//
+	if result.seq > d.readIndex {
+		dropped := result.seq - d.readIndex
+		d.readIndex = result.seq
+		d.alerter.Alert(int(dropped))
+	}
+
+	// Only increment read index if a regular read occurred (where seq was
+	// equal to readIndex) or a value was read that caused a fast forward
+	// (where seq was greater than readIndex).
+	d.readIndex++
+	return result.data, true
+}

diode/internal/diodes/poller.go

@@ -0,0 +1,80 @@
+package diodes
+
+import (
+	"context"
+	"time"
+)
+
+// Diode is any implementation of a diode.
+type Diode interface {
+	Set(GenericDataType)
+	TryNext() (GenericDataType, bool)
+}
+
+// Poller will poll a diode until a value is available.
+type Poller struct {
+	Diode
+	interval time.Duration
+	ctx      context.Context
+}
+
+// PollerConfigOption can be used to setup the poller.
+type PollerConfigOption func(*Poller)
+
+// WithPollingInterval sets the interval at which the diode is queried
+// for new data. The default is 10ms.
+func WithPollingInterval(interval time.Duration) PollerConfigOption {
+	return PollerConfigOption(func(c *Poller) {
+		c.interval = interval
+	})
+}
+
+// WithPollingContext sets the context to cancel any retrieval (Next()). It
+// will not change any results for adding data (Set()). Default is
+// context.Background().
+func WithPollingContext(ctx context.Context) PollerConfigOption {
+	return PollerConfigOption(func(c *Poller) {
+		c.ctx = ctx
+	})
+}
+
+// NewPoller returns a new Poller that wraps the given diode.
+func NewPoller(d Diode, opts ...PollerConfigOption) *Poller {
+	p := &Poller{
+		Diode:    d,
+		interval: 10 * time.Millisecond,
+		ctx:      context.Background(),
+	}
+
+	for _, o := range opts {
+		o(p)
+	}
+
+	return p
+}
+
+// Next polls the diode until data is available or until the context is done.
+// If the context is done, then nil will be returned.
+func (p *Poller) Next() GenericDataType {
+	for {
+		data, ok := p.Diode.TryNext()
+		if !ok {
+			if p.isDone() {
+				return nil
+			}
+
+			time.Sleep(p.interval)
+			continue
+		}
+		return data
+	}
+}
+
+func (p *Poller) isDone() bool {
+	select {
+	case <-p.ctx.Done():
+		return true
+	default:
+		return false
+	}
+}

diode/internal/diodes/waiter.go

@@ -0,0 +1,83 @@
+package diodes
+
+import (
+	"context"
+	"sync"
+)
+
+// Waiter will use a conditional mutex to alert the reader to when data is
+// available.
+type Waiter struct {
+	Diode
+	mu  sync.Mutex
+	c   *sync.Cond
+	ctx context.Context
+}
+
+// WaiterConfigOption can be used to setup the waiter.
+type WaiterConfigOption func(*Waiter)
+
+// WithWaiterContext sets the context to cancel any retrieval (Next()). It
+// will not change any results for adding data (Set()). Default is
+// context.Background().
+func WithWaiterContext(ctx context.Context) WaiterConfigOption {
+	return WaiterConfigOption(func(c *Waiter) {
+		c.ctx = ctx
+	})
+}
+
+// NewWaiter returns a new Waiter that wraps the given diode.
+func NewWaiter(d Diode, opts ...WaiterConfigOption) *Waiter {
+	w := new(Waiter)
+	w.Diode = d
+	w.c = sync.NewCond(&w.mu)
+	w.ctx = context.Background()
+
+	for _, opt := range opts {
+		opt(w)
+	}
+
+	go func() {
+		<-w.ctx.Done()
+		w.c.Broadcast()
+	}()
+
+	return w
+}
+
+// Set invokes the wrapped diode's Set with the given data and uses Broadcast
+// to wake up any readers.
+func (w *Waiter) Set(data GenericDataType) {
+	w.Diode.Set(data)
+	w.c.Broadcast()
+}
+
+// Next returns the next data point on the wrapped diode. If there is not any
+// new data, it will Wait for set to be called or the context to be done.
+// If the context is done, then nil will be returned.
+func (w *Waiter) Next() GenericDataType {
+	w.mu.Lock()
+	defer w.mu.Unlock()
+
+	for {
+		data, ok := w.Diode.TryNext()
+		if !ok {
+			if w.isDone() {
+				return nil
+			}
+
+			w.c.Wait()
+			continue
+		}
+		return data
+	}
+}
+
+func (w *Waiter) isDone() bool {
+	select {
+	case <-w.ctx.Done():
+		return true
+	default:
+		return false
+	}
+}

encoder.go

@@ -16,8 +16,6 @@ type encoder interface {
 	AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool) []byte
 	AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool) []byte
 	AppendEndMarker(dst []byte) []byte
-	AppendError(dst []byte, err error) []byte
-	AppendErrors(dst []byte, errs []error) []byte
 	AppendFloat32(dst []byte, val float32) []byte
 	AppendFloat64(dst []byte, val float64) []byte
 	AppendFloats32(dst []byte, vals []float32) []byte

event.go

@@ -5,7 +5,6 @@ import (
 	"net"
 	"os"
 	"runtime"
-	"strconv"
 	"sync"
 	"time"
 )
@@ -21,12 +20,27 @@ var eventPool = &sync.Pool{
 // Event represents a log event. It is instanced by one of the level method of
 // Logger and finalized by the Msg or Msgf method.
 type Event struct {
-	buf   []byte
-	w     LevelWriter
-	level Level
-	done  func(msg string)
-	ch    []Hook // hooks from context
-	h     []Hook
+	buf       []byte
+	w         LevelWriter
+	level     Level
+	done      func(msg string)
+	stack     bool   // enable error stack trace
+	ch        []Hook // hooks from context
+	skipFrame int    // The number of additional frames to skip when printing the caller.
+}
+
+func putEvent(e *Event) {
+	// Proper usage of a sync.Pool requires each entry to have approximately
+	// the same memory cost. To obtain this property when the stored type
+	// contains a variably-sized buffer, we add a hard limit on the maximum buffer
+	// to place back in the pool.
+	//
+	// See https://golang.org/issue/23199
+	const maxSize = 1 << 16 // 64KiB
+	if cap(e.buf) > maxSize {
+		return
+	}
+	eventPool.Put(e)
 }
 
 // LogObjectMarshaler provides a strongly-typed and encoding-agnostic interface
@@ -44,10 +58,12 @@ type LogArrayMarshaler interface {
 func newEvent(w LevelWriter, level Level) *Event {
 	e := eventPool.Get().(*Event)
 	e.buf = e.buf[:0]
-	e.h = e.h[:0]
+	e.ch = nil
 	e.buf = enc.AppendBeginMarker(e.buf)
 	e.w = w
 	e.level = level
+	e.stack = false
+	e.skipFrame = 0
 	return e
 }
 
@@ -55,19 +71,30 @@ func (e *Event) write() (err error) {
 	if e == nil {
 		return nil
 	}
-	e.buf = enc.AppendEndMarker(e.buf)
-	e.buf = enc.AppendLineBreak(e.buf)
-	if e.w != nil {
-		_, err = e.w.WriteLevel(e.level, e.buf)
+	if e.level != Disabled {
+		e.buf = enc.AppendEndMarker(e.buf)
+		e.buf = enc.AppendLineBreak(e.buf)
+		if e.w != nil {
+			_, err = e.w.WriteLevel(e.level, e.buf)
+		}
 	}
-	eventPool.Put(e)
+	putEvent(e)
 	return
 }
 
 // Enabled return false if the *Event is going to be filtered out by
 // log level or sampling.
 func (e *Event) Enabled() bool {
-	return e != nil
+	return e != nil && e.level != Disabled
+}
+
+// Discard disables the event so Msg(f) won't print it.
+func (e *Event) Discard() *Event {
+	if e == nil {
+		return e
+	}
+	e.level = Disabled
+	return nil
 }
 
 // Msg sends the *Event with msg added as the message field if not empty.
@@ -78,21 +105,33 @@ func (e *Event) Msg(msg string) {
 	if e == nil {
 		return
 	}
-	if len(e.ch) > 0 {
-		e.ch[0].Run(e, e.level, msg)
-		if len(e.ch) > 1 {
-			for _, hook := range e.ch[1:] {
-				hook.Run(e, e.level, msg)
-			}
-		}
+	e.msg(msg)
+}
+
+// Send is equivalent to calling Msg("").
+//
+// NOTICE: once this method is called, the *Event should be disposed.
+func (e *Event) Send() {
+	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)
-			}
-		}
+	e.msg("")
+}
+
+// Msgf sends the event with formatted msg added as the message field if not empty.
+//
+// NOTICE: once this method is called, the *Event should be disposed.
+// Calling Msgf twice can have unexpected result.
+func (e *Event) Msgf(format string, v ...interface{}) {
+	if e == nil {
+		return
+	}
+	e.msg(fmt.Sprintf(format, v...))
+}
+
+func (e *Event) msg(msg string) {
+	for _, hook := range e.ch {
+		hook.Run(e, e.level, msg)
 	}
 	if msg != "" {
 		e.buf = enc.AppendString(enc.AppendKey(e.buf, MessageFieldName), msg)
@@ -101,21 +140,14 @@ func (e *Event) Msg(msg string) {
 		defer e.done(msg)
 	}
 	if err := e.write(); err != nil {
-		fmt.Fprintf(os.Stderr, "zerolog: could not write event: %v", err)
+		if ErrorHandler != nil {
+			ErrorHandler(err)
+		} else {
+			fmt.Fprintf(os.Stderr, "zerolog: could not write event: %v\n", err)
+		}
 	}
 }
 
-// Msgf sends the event with formated msg added as the message field if not empty.
-//
-// NOTICE: once this methid is called, the *Event should be disposed.
-// Calling Msg twice can have unexpected result.
-func (e *Event) Msgf(format string, v ...interface{}) {
-	if e == nil {
-		return
-	}
-	e.Msg(fmt.Sprintf(format, v...))
-}
-
 // Fields is a helper function to use a map to set fields using type assertion.
 func (e *Event) Fields(fields map[string]interface{}) *Event {
 	if e == nil {
@@ -133,7 +165,7 @@ func (e *Event) Dict(key string, dict *Event) *Event {
 	}
 	dict.buf = enc.AppendEndMarker(dict.buf)
 	e.buf = append(enc.AppendKey(e.buf, key), dict.buf...)
-	eventPool.Put(dict)
+	putEvent(dict)
 	return e
 }
 
@@ -179,7 +211,7 @@ func (e *Event) Object(key string, obj LogObjectMarshaler) *Event {
 	return e
 }
 
-// Object marshals an object that implement the LogObjectMarshaler interface.
+// EmbedObject marshals an object that implement the LogObjectMarshaler interface.
 func (e *Event) EmbedObject(obj LogObjectMarshaler) *Event {
 	if e == nil {
 		return e
@@ -206,6 +238,21 @@ func (e *Event) Strs(key string, vals []string) *Event {
 	return e
 }
 
+// Stringer adds the field key with val.String() (or null if val is nil) to the *Event context.
+func (e *Event) Stringer(key string, val fmt.Stringer) *Event {
+	if e == nil {
+		return e
+	}
+
+	if val != nil {
+		e.buf = enc.AppendString(enc.AppendKey(e.buf, key), val.String())
+		return e
+	}
+
+	e.buf = enc.AppendInterface(enc.AppendKey(e.buf, key), nil)
+	return e
+}
+
 // Bytes adds the field key with val as a string to the *Event context.
 //
 // Runes outside of normal ASCII ranges will be hex-encoded in the resulting
@@ -239,37 +286,89 @@ func (e *Event) RawJSON(key string, b []byte) *Event {
 	return e
 }
 
-// AnErr adds the field key with err as a string to the *Event context.
+// AnErr adds the field key with serialized err to the *Event context.
 // If err is nil, no field is added.
 func (e *Event) AnErr(key string, err error) *Event {
 	if e == nil {
 		return e
 	}
-	if err != nil {
-		e.buf = enc.AppendError(enc.AppendKey(e.buf, key), err)
+	switch m := ErrorMarshalFunc(err).(type) {
+	case nil:
+		return e
+	case LogObjectMarshaler:
+		return e.Object(key, m)
+	case error:
+		if m == nil || isNilValue(m) {
+			return e
+		} else {
+			return e.Str(key, m.Error())
+		}
+	case string:
+		return e.Str(key, m)
+	default:
+		return e.Interface(key, m)
 	}
-	return e
 }
 
-// Errs adds the field key with errs as an array of strings to the *Event context.
-// If err is nil, no field is added.
+// Errs adds the field key with errs as an array of serialized errors to the
+// *Event context.
 func (e *Event) Errs(key string, errs []error) *Event {
 	if e == nil {
 		return e
 	}
-	e.buf = enc.AppendErrors(enc.AppendKey(e.buf, key), errs)
-	return e
+	arr := Arr()
+	for _, err := range errs {
+		switch m := ErrorMarshalFunc(err).(type) {
+		case LogObjectMarshaler:
+			arr = arr.Object(m)
+		case error:
+			arr = arr.Err(m)
+		case string:
+			arr = arr.Str(m)
+		default:
+			arr = arr.Interface(m)
+		}
+	}
+
+	return e.Array(key, arr)
 }
 
-// Err adds the field "error" with err as a string to the *Event context.
+// Err adds the field "error" with serialized err to the *Event context.
 // If err is nil, no field is added.
+//
 // To customize the key name, change zerolog.ErrorFieldName.
+//
+// If Stack() has been called before and zerolog.ErrorStackMarshaler is defined,
+// the err is passed to ErrorStackMarshaler and the result is appended to the
+// zerolog.ErrorStackFieldName.
 func (e *Event) Err(err error) *Event {
 	if e == nil {
 		return e
 	}
-	if err != nil {
-		e.buf = enc.AppendError(enc.AppendKey(e.buf, ErrorFieldName), err)
+	if e.stack && ErrorStackMarshaler != nil {
+		switch m := ErrorStackMarshaler(err).(type) {
+		case nil:
+		case LogObjectMarshaler:
+			e.Object(ErrorStackFieldName, m)
+		case error:
+			if m != nil && !isNilValue(m) {
+				e.Str(ErrorStackFieldName, m.Error())
+			}
+		case string:
+			e.Str(ErrorStackFieldName, m)
+		default:
+			e.Interface(ErrorStackFieldName, m)
+		}
+	}
+	return e.AnErr(ErrorFieldName, err)
+}
+
+// Stack enables stack trace printing for the error passed to Err().
+//
+// ErrorStackMarshaler must be set for this method to do something.
+func (e *Event) Stack() *Event {
+	if e != nil {
+		e.stack = true
 	}
 	return e
 }
@@ -588,20 +687,33 @@ func (e *Event) Interface(key string, i interface{}) *Event {
 	return e
 }
 
+// CallerSkipFrame instructs any future Caller calls to skip the specified number of frames.
+// This includes those added via hooks from the context.
+func (e *Event) CallerSkipFrame(skip int) *Event {
+	e.skipFrame += skip
+	return e
+}
+
 // Caller adds the file:line of the caller with the zerolog.CallerFieldName key.
-func (e *Event) Caller() *Event {
-	return e.caller(CallerSkipFrameCount)
+// The argument skip is the number of stack frames to ascend
+// Skip If not passed, use the global variable CallerSkipFrameCount
+func (e *Event) Caller(skip ...int) *Event {
+	sk := CallerSkipFrameCount
+	if len(skip) > 0 {
+		sk = skip[0] + CallerSkipFrameCount
+	}
+	return e.caller(sk)
 }
 
 func (e *Event) caller(skip int) *Event {
 	if e == nil {
 		return e
 	}
-	_, file, line, ok := runtime.Caller(skip)
+	_, file, line, ok := runtime.Caller(skip + e.skipFrame)
 	if !ok {
 		return e
 	}
-	e.buf = enc.AppendString(enc.AppendKey(e.buf, CallerFieldName), file+":"+strconv.Itoa(line))
+	e.buf = enc.AppendString(enc.AppendKey(e.buf, CallerFieldName), CallerMarshalFunc(file, line))
 	return e
 }
 

event_test.go

@@ -0,0 +1,39 @@
+// +build !binary_log
+
+package zerolog
+
+import (
+	"bytes"
+	"errors"
+	"strings"
+	"testing"
+)
+
+type nilError struct{}
+
+func (nilError) Error() string {
+	return ""
+}
+
+func TestEvent_AnErr(t *testing.T) {
+	tests := []struct {
+		name string
+		err  error
+		want string
+	}{
+		{"nil", nil, `{}`},
+		{"error", errors.New("test"), `{"err":"test"}`},
+		{"nil interface", func() *nilError { return nil }(), `{}`},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			var buf bytes.Buffer
+			e := newEvent(levelWriterAdapter{&buf}, DebugLevel)
+			e.AnErr("err", tt.err)
+			_ = e.write()
+			if got, want := strings.TrimSpace(buf.String()), tt.want; got != want {
+				t.Errorf("Event.AnErr() = %v, want %v", got, want)
+			}
+		})
+	}
+}

fields.go

@@ -4,8 +4,13 @@ import (
 	"net"
 	"sort"
 	"time"
+	"unsafe"
 )
 
+func isNilValue(i interface{}) bool {
+	return (*[2]uintptr)(unsafe.Pointer(&i))[1] == 0
+}
+
 func appendFields(dst []byte, fields map[string]interface{}) []byte {
 	keys := make([]string, 0, len(fields))
 	for key := range fields {
@@ -20,7 +25,7 @@ func appendFields(dst []byte, fields map[string]interface{}) []byte {
 			e.buf = e.buf[:0]
 			e.appendObject(val)
 			dst = append(dst, e.buf...)
-			eventPool.Put(e)
+			putEvent(e)
 			continue
 		}
 		switch val := val.(type) {
@@ -29,9 +34,51 @@ func appendFields(dst []byte, fields map[string]interface{}) []byte {
 		case []byte:
 			dst = enc.AppendBytes(dst, val)
 		case error:
-			dst = enc.AppendError(dst, val)
+			switch m := ErrorMarshalFunc(val).(type) {
+			case LogObjectMarshaler:
+				e := newEvent(nil, 0)
+				e.buf = e.buf[:0]
+				e.appendObject(m)
+				dst = append(dst, e.buf...)
+				putEvent(e)
+			case error:
+				if m == nil || isNilValue(m) {
+					dst = enc.AppendNil(dst)
+				} else {
+					dst = enc.AppendString(dst, m.Error())
+				}
+			case string:
+				dst = enc.AppendString(dst, m)
+			default:
+				dst = enc.AppendInterface(dst, m)
+			}
 		case []error:
-			dst = enc.AppendErrors(dst, val)
+			dst = enc.AppendArrayStart(dst)
+			for i, err := range val {
+				switch m := ErrorMarshalFunc(err).(type) {
+				case LogObjectMarshaler:
+					e := newEvent(nil, 0)
+					e.buf = e.buf[:0]
+					e.appendObject(m)
+					dst = append(dst, e.buf...)
+					putEvent(e)
+				case error:
+					if m == nil || isNilValue(m) {
+						dst = enc.AppendNil(dst)
+					} else {
+						dst = enc.AppendString(dst, m.Error())
+					}
+				case string:
+					dst = enc.AppendString(dst, m)
+				default:
+					dst = enc.AppendInterface(dst, m)
+				}
+
+				if i < (len(val) - 1) {
+					enc.AppendArrayDelim(dst)
+				}
+			}
+			dst = enc.AppendArrayEnd(dst)
 		case bool:
 			dst = enc.AppendBool(dst, val)
 		case int:
@@ -63,37 +110,101 @@ func appendFields(dst []byte, fields map[string]interface{}) []byte {
 		case time.Duration:
 			dst = enc.AppendDuration(dst, val, DurationFieldUnit, DurationFieldInteger)
 		case *string:
-			dst = enc.AppendString(dst, *val)
+			if val != nil {
+				dst = enc.AppendString(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *bool:
-			dst = enc.AppendBool(dst, *val)
+			if val != nil {
+				dst = enc.AppendBool(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *int:
-			dst = enc.AppendInt(dst, *val)
+			if val != nil {
+				dst = enc.AppendInt(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *int8:
-			dst = enc.AppendInt8(dst, *val)
+			if val != nil {
+				dst = enc.AppendInt8(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *int16:
-			dst = enc.AppendInt16(dst, *val)
+			if val != nil {
+				dst = enc.AppendInt16(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *int32:
-			dst = enc.AppendInt32(dst, *val)
+			if val != nil {
+				dst = enc.AppendInt32(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *int64:
-			dst = enc.AppendInt64(dst, *val)
+			if val != nil {
+				dst = enc.AppendInt64(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *uint:
-			dst = enc.AppendUint(dst, *val)
+			if val != nil {
+				dst = enc.AppendUint(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *uint8:
-			dst = enc.AppendUint8(dst, *val)
+			if val != nil {
+				dst = enc.AppendUint8(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *uint16:
-			dst = enc.AppendUint16(dst, *val)
+			if val != nil {
+				dst = enc.AppendUint16(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *uint32:
-			dst = enc.AppendUint32(dst, *val)
+			if val != nil {
+				dst = enc.AppendUint32(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *uint64:
-			dst = enc.AppendUint64(dst, *val)
+			if val != nil {
+				dst = enc.AppendUint64(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *float32:
-			dst = enc.AppendFloat32(dst, *val)
+			if val != nil {
+				dst = enc.AppendFloat32(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *float64:
-			dst = enc.AppendFloat64(dst, *val)
+			if val != nil {
+				dst = enc.AppendFloat64(dst, *val)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *time.Time:
-			dst = enc.AppendTime(dst, *val, TimeFieldFormat)
+			if val != nil {
+				dst = enc.AppendTime(dst, *val, TimeFieldFormat)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case *time.Duration:
-			dst = enc.AppendDuration(dst, *val, DurationFieldUnit, DurationFieldInteger)
+			if val != nil {
+				dst = enc.AppendDuration(dst, *val, DurationFieldUnit, DurationFieldInteger)
+			} else {
+				dst = enc.AppendNil(dst)
+			}
 		case []string:
 			dst = enc.AppendStrings(dst, val)
 		case []bool:

globals.go

@@ -1,7 +1,24 @@
 package zerolog
 
-import "time"
-import "sync/atomic"
+import (
+	"strconv"
+	"sync/atomic"
+	"time"
+)
+
+const (
+	// TimeFormatUnix defines a time format that makes time fields to be
+	// serialized as Unix timestamp integers.
+	TimeFormatUnix = ""
+
+	// TimeFormatUnixMs defines a time format that makes time fields to be
+	// serialized as Unix timestamp integers in milliseconds.
+	TimeFormatUnixMs = "UNIXMS"
+
+	// TimeFormatUnixMicro defines a time format that makes time fields to be
+	// serialized as Unix timestamp integers in microseconds.
+	TimeFormatUnixMicro = "UNIXMICRO"
+)
 
 var (
 	// TimestampFieldName is the field name used for the timestamp field.
@@ -10,6 +27,26 @@ var (
 	// LevelFieldName is the field name used for the level field.
 	LevelFieldName = "level"
 
+	// LevelTraceValue is the value used for the trace level field.
+	LevelTraceValue = "trace"
+	// LevelDebugValue is the value used for the debug level field.
+	LevelDebugValue = "debug"
+	// LevelInfoValue is the value used for the info level field.
+	LevelInfoValue = "info"
+	// LevelWarnValue is the value used for the warn level field.
+	LevelWarnValue = "warn"
+	// LevelErrorValue is the value used for the error level field.
+	LevelErrorValue = "error"
+	// LevelFatalValue is the value used for the fatal level field.
+	LevelFatalValue = "fatal"
+	// LevelPanicValue is the value used for the panic level field.
+	LevelPanicValue = "panic"
+
+	// LevelFieldMarshalFunc allows customization of global level field marshaling.
+	LevelFieldMarshalFunc = func(l Level) string {
+		return l.String()
+	}
+
 	// MessageFieldName is the field name used for the message field.
 	MessageFieldName = "message"
 
@@ -22,9 +59,25 @@ var (
 	// CallerSkipFrameCount is the number of stack frames to skip to find the caller.
 	CallerSkipFrameCount = 2
 
-	// 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.
+	// CallerMarshalFunc allows customization of global caller marshaling
+	CallerMarshalFunc = func(file string, line int) string {
+		return file + ":" + strconv.Itoa(line)
+	}
+
+	// ErrorStackFieldName is the field name used for error stacks.
+	ErrorStackFieldName = "stack"
+
+	// ErrorStackMarshaler extract the stack from err if any.
+	ErrorStackMarshaler func(err error) interface{}
+
+	// ErrorMarshalFunc allows customization of global error marshaling
+	ErrorMarshalFunc = func(err error) interface{} {
+		return err
+	}
+
+	// TimeFieldFormat defines the time format of the Time field type. If set to
+	// TimeFormatUnix, TimeFormatUnixMs or TimeFormatUnixMicro, the time is formatted as an UNIX
+	// timestamp as integer.
 	TimeFieldFormat = time.RFC3339
 
 	// TimestampFunc defines the function called to generate a timestamp.
@@ -37,11 +90,16 @@ var (
 	// DurationFieldInteger renders Dur fields as integer instead of float if
 	// set to true.
 	DurationFieldInteger = false
+
+	// ErrorHandler is called whenever zerolog fails to write an event on its
+	// output. If not set, an error is printed on the stderr. This handler must
+	// be thread safe and non-blocking.
+	ErrorHandler func(err error)
 )
 
 var (
-	gLevel          = new(uint32)
-	disableSampling = new(uint32)
+	gLevel          = new(int32)
+	disableSampling = new(int32)
 )
 
 // SetGlobalLevel sets the global override for log level. If this
@@ -49,23 +107,23 @@ var (
 //
 // To globally disable logs, set GlobalLevel to Disabled.
 func SetGlobalLevel(l Level) {
-	atomic.StoreUint32(gLevel, uint32(l))
+	atomic.StoreInt32(gLevel, int32(l))
 }
 
 // GlobalLevel returns the current global log level
 func GlobalLevel() Level {
-	return Level(atomic.LoadUint32(gLevel))
+	return Level(atomic.LoadInt32(gLevel))
 }
 
 // DisableSampling will disable sampling in all Loggers if true.
 func DisableSampling(v bool) {
-	var i uint32
+	var i int32
 	if v {
 		i = 1
 	}
-	atomic.StoreUint32(disableSampling, i)
+	atomic.StoreInt32(disableSampling, i)
 }
 
 func samplingDisabled() bool {
-	return atomic.LoadUint32(disableSampling) == 1
+	return atomic.LoadInt32(disableSampling) == 1
 }

go.mod

@@ -1 +1,8 @@
 module github.com/rs/zerolog
+
+require (
+	github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e
+	github.com/pkg/errors v0.9.1
+	github.com/rs/xid v1.2.1
+	golang.org/x/tools v0.1.0
+)

go.sum

@@ -0,0 +1,32 @@
+github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e h1:Wf6HqHfScWJN9/ZjdUKyjop4mf3Qdd+1TvvltAvM3m8=
+github.com/coreos/go-systemd v0.0.0-20190321100706-95778dfbb74e/go.mod h1:F5haX7vjVVG0kc13fIWeqUViNPyEJxv/OmvnBo0Yme4=
+github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/rs/xid v1.2.1 h1:mhH9Nq+C1fY2l1XIpgxIiUOfNpRBYH1kKcr+qfKgjRc=
+github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ=
+github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
+golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
+golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
+golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
+golang.org/x/mod v0.3.0 h1:RM4zey1++hCTbCVQfnWeKs9/IEsaBLA8vTkd0WVtmH4=
+golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
+golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
+golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
+golang.org/x/net v0.0.0-20201021035429-f5854403a974/go.mod h1:sp8m0HH+o8qH0wwXwYZr8TS3Oi6o0r6Gce1SSxlDquU=
+golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
+golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4 h1:myAQVi0cGEoqQVR5POX+8RR2mrocKqNN1hmeMqhX27k=
+golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
+golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
+golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
+golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/tools v0.1.0 h1:po9/4sTYwZU9lPhi1tOrb4hCv3qrhiQ77LZfGa2OjwY=
+golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0=
+golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
+golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
+golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE=
+golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

go112.go

@@ -0,0 +1,7 @@
+// +build go1.12
+
+package zerolog
+
+// Since go 1.12, some auto generated init functions are hidden from
+// runtime.Caller.
+const contextCallerSkipFrameCount = 2

hlog/hlog.go

@@ -9,8 +9,8 @@ import (
 
 	"github.com/rs/xid"
 	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/hlog/internal/mutil"
 	"github.com/rs/zerolog/log"
-	"github.com/zenazn/goji/web/mutil"
 )
 
 // FromRequest gets the logger in the request's context.
@@ -129,10 +129,20 @@ func IDFromRequest(r *http.Request) (id xid.ID, ok bool) {
 	if r == nil {
 		return
 	}
-	id, ok = r.Context().Value(idKey{}).(xid.ID)
+	return IDFromCtx(r.Context())
+}
+
+// IDFromCtx returns the unique id associated to the context if any.
+func IDFromCtx(ctx context.Context) (id xid.ID, ok bool) {
+	id, ok = ctx.Value(idKey{}).(xid.ID)
 	return
 }
 
+// CtxWithID adds the given xid.ID to the context
+func CtxWithID(ctx context.Context, id xid.ID) context.Context {
+	return context.WithValue(ctx, idKey{}, id)
+}
+
 // 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
@@ -149,7 +159,7 @@ func RequestIDHandler(fieldKey, headerName string) func(next http.Handler) http.
 			id, ok := IDFromRequest(r)
 			if !ok {
 				id = xid.New()
-				ctx = context.WithValue(ctx, idKey{}, id)
+				ctx = CtxWithID(ctx, id)
 				r = r.WithContext(ctx)
 			}
 			if fieldKey != "" {
@@ -166,6 +176,22 @@ func RequestIDHandler(fieldKey, headerName string) func(next http.Handler) http.
 	}
 }
 
+// CustomHeaderHandler adds given header from request's header as a field to
+// the context's logger using fieldKey as field key.
+func CustomHeaderHandler(fieldKey, header 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 val := r.Header.Get(header); val != "" {
+				log := zerolog.Ctx(r.Context())
+				log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+					return c.Str(fieldKey, val)
+				})
+			}
+			next.ServeHTTP(w, r)
+		})
+	}
+}
+
 // AccessHandler returns a handler that call f after each request.
 func AccessHandler(f func(r *http.Request, status, size int, duration time.Duration)) func(next http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {

hlog/hlog_test.go

@@ -4,16 +4,16 @@ package hlog
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"io/ioutil"
 	"net/http"
+	"net/http/httptest"
 	"net/url"
+	"reflect"
 	"testing"
 
-	"reflect"
-
-	"net/http/httptest"
-
+	"github.com/rs/xid"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/internal/cbor"
 )
@@ -182,6 +182,24 @@ func TestRequestIDHandler(t *testing.T) {
 	h.ServeHTTP(httptest.NewRecorder(), r)
 }
 
+func TestCustomHeaderHandler(t *testing.T) {
+	out := &bytes.Buffer{}
+	r := &http.Request{
+		Header: http.Header{
+			"X-Request-Id": []string{"514bbe5bb5251c92bd07a9846f4a1ab6"},
+		},
+	}
+	h := CustomHeaderHandler("reqID", "X-Request-Id")(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 := `{"reqID":"514bbe5bb5251c92bd07a9846f4a1ab6"}`+"\n", decodeIfBinary(out); want != got {
+		t.Errorf("Invalid log output, got: %s, want: %s", got, want)
+	}
+}
+
 func TestCombinedHandlers(t *testing.T) {
 	out := &bytes.Buffer{}
 	r := &http.Request{
@@ -244,3 +262,16 @@ func BenchmarkDataRace(b *testing.B) {
 		}
 	})
 }
+
+func TestCtxWithID(t *testing.T) {
+	ctx := context.Background()
+
+	id, _ := xid.FromString(`c0umremcie6smuu506pg`)
+
+	want := context.Background()
+	want = context.WithValue(want, idKey{}, id)
+
+	if got := CtxWithID(ctx, id); !reflect.DeepEqual(got, want) {
+		t.Errorf("CtxWithID() = %v, want %v", got, want)
+	}
+}

hlog/internal/mutil/LICENSE

@@ -0,0 +1,20 @@
+Copyright (c) 2014, 2015, 2016 Carl Jackson (carl@avtok.com)
+
+MIT License
+
+Permission is hereby granted, free of charge, to any person obtaining a copy of
+this software and associated documentation files (the "Software"), to deal in
+the Software without restriction, including without limitation the rights to
+use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of
+the Software, and to permit persons to whom the Software is furnished to do so,
+subject to the following conditions:
+
+The above copyright notice and this permission notice shall be included in all
+copies or substantial portions of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS
+FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER
+IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
+CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.

hlog/internal/mutil/mutil.go

@@ -0,0 +1,6 @@
+// Package mutil contains various functions that are helpful when writing http
+// middleware.
+//
+// It has been vendored from Goji v1.0, with the exception of the code for Go 1.8:
+// https://github.com/zenazn/goji/
+package mutil

hlog/internal/mutil/writer_proxy.go

@@ -0,0 +1,154 @@
+package mutil
+
+import (
+	"bufio"
+	"io"
+	"net"
+	"net/http"
+)
+
+// WriterProxy is a proxy around an http.ResponseWriter that allows you to hook
+// into various parts of the response process.
+type WriterProxy interface {
+	http.ResponseWriter
+	// Status returns the HTTP status of the request, or 0 if one has not
+	// yet been sent.
+	Status() int
+	// BytesWritten returns the total number of bytes sent to the client.
+	BytesWritten() int
+	// Tee causes the response body to be written to the given io.Writer in
+	// addition to proxying the writes through. Only one io.Writer can be
+	// tee'd to at once: setting a second one will overwrite the first.
+	// Writes will be sent to the proxy before being written to this
+	// io.Writer. It is illegal for the tee'd writer to be modified
+	// concurrently with writes.
+	Tee(io.Writer)
+	// Unwrap returns the original proxied target.
+	Unwrap() http.ResponseWriter
+}
+
+// WrapWriter wraps an http.ResponseWriter, returning a proxy that allows you to
+// hook into various parts of the response process.
+func WrapWriter(w http.ResponseWriter) WriterProxy {
+	_, cn := w.(http.CloseNotifier)
+	_, fl := w.(http.Flusher)
+	_, hj := w.(http.Hijacker)
+	_, rf := w.(io.ReaderFrom)
+
+	bw := basicWriter{ResponseWriter: w}
+	if cn && fl && hj && rf {
+		return &fancyWriter{bw}
+	}
+	if fl {
+		return &flushWriter{bw}
+	}
+	return &bw
+}
+
+// basicWriter wraps a http.ResponseWriter that implements the minimal
+// http.ResponseWriter interface.
+type basicWriter struct {
+	http.ResponseWriter
+	wroteHeader bool
+	code        int
+	bytes       int
+	tee         io.Writer
+}
+
+func (b *basicWriter) WriteHeader(code int) {
+	if !b.wroteHeader {
+		b.code = code
+		b.wroteHeader = true
+		b.ResponseWriter.WriteHeader(code)
+	}
+}
+
+func (b *basicWriter) Write(buf []byte) (int, error) {
+	b.WriteHeader(http.StatusOK)
+	n, err := b.ResponseWriter.Write(buf)
+	if b.tee != nil {
+		_, err2 := b.tee.Write(buf[:n])
+		// Prefer errors generated by the proxied writer.
+		if err == nil {
+			err = err2
+		}
+	}
+	b.bytes += n
+	return n, err
+}
+
+func (b *basicWriter) maybeWriteHeader() {
+	if !b.wroteHeader {
+		b.WriteHeader(http.StatusOK)
+	}
+}
+
+func (b *basicWriter) Status() int {
+	return b.code
+}
+
+func (b *basicWriter) BytesWritten() int {
+	return b.bytes
+}
+
+func (b *basicWriter) Tee(w io.Writer) {
+	b.tee = w
+}
+
+func (b *basicWriter) Unwrap() http.ResponseWriter {
+	return b.ResponseWriter
+}
+
+// fancyWriter is a writer that additionally satisfies http.CloseNotifier,
+// http.Flusher, http.Hijacker, and io.ReaderFrom. It exists for the common case
+// of wrapping the http.ResponseWriter that package http gives you, in order to
+// make the proxied object support the full method set of the proxied object.
+type fancyWriter struct {
+	basicWriter
+}
+
+func (f *fancyWriter) CloseNotify() <-chan bool {
+	cn := f.basicWriter.ResponseWriter.(http.CloseNotifier)
+	return cn.CloseNotify()
+}
+
+func (f *fancyWriter) Flush() {
+	fl := f.basicWriter.ResponseWriter.(http.Flusher)
+	fl.Flush()
+}
+
+func (f *fancyWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	hj := f.basicWriter.ResponseWriter.(http.Hijacker)
+	return hj.Hijack()
+}
+
+func (f *fancyWriter) ReadFrom(r io.Reader) (int64, error) {
+	if f.basicWriter.tee != nil {
+		n, err := io.Copy(&f.basicWriter, r)
+		f.bytes += int(n)
+		return n, err
+	}
+	rf := f.basicWriter.ResponseWriter.(io.ReaderFrom)
+	f.basicWriter.maybeWriteHeader()
+
+	n, err := rf.ReadFrom(r)
+	f.bytes += int(n)
+	return n, err
+}
+
+type flushWriter struct {
+	basicWriter
+}
+
+func (f *flushWriter) Flush() {
+	fl := f.basicWriter.ResponseWriter.(http.Flusher)
+	fl.Flush()
+}
+
+var (
+	_ http.CloseNotifier = &fancyWriter{}
+	_ http.Flusher       = &fancyWriter{}
+	_ http.Hijacker      = &fancyWriter{}
+	_ io.ReaderFrom      = &fancyWriter{}
+	_ http.Flusher       = &flushWriter{}
+)

hook.go

@@ -6,14 +6,27 @@ type Hook interface {
 	Run(e *Event, level Level, message string)
 }
 
+// HookFunc is an adaptor to allow the use of an ordinary function
+// as a Hook.
+type HookFunc func(e *Event, level Level, message string)
+
+// Run implements the Hook interface.
+func (h HookFunc) Run(e *Event, level Level, message string) {
+	h(e, level, message)
+}
+
 // LevelHook applies a different hook for each level.
 type LevelHook struct {
-	NoLevelHook, DebugHook, InfoHook, WarnHook, ErrorHook, FatalHook, PanicHook Hook
+	NoLevelHook, TraceHook, 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 TraceLevel:
+		if h.TraceHook != nil {
+			h.TraceHook.Run(e, level, message)
+		}
 	case DebugLevel:
 		if h.DebugHook != nil {
 			h.DebugHook.Run(e, level, message)

hook_test.go

@@ -6,204 +6,135 @@ import (
 	"testing"
 )
 
-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
+	levelNameHook = HookFunc(func(e *Event, level Level, msg string) {
+		levelName := level.String()
+		if level == NoLevel {
+			levelName = "nolevel"
+		}
+		e.Str("level_name", levelName)
+	})
+	simpleHook = HookFunc(func(e *Event, level Level, msg string) {
+		e.Bool("has_level", level != NoLevel)
+		e.Str("test", "logged")
+	})
+	copyHook = HookFunc(func(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)
+	})
+	nopHook = HookFunc(func(e *Event, level Level, message string) {
+	})
+	discardHook = HookFunc(func(e *Event, level Level, message string) {
+		e.Discard()
+	})
 )
 
 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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"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 := decodeIfBinaryToString(out.Bytes()), `{"level":"error"}`+"\n"; got != want {
-			t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
-		}
-	})
+	tests := []struct {
+		name string
+		want string
+		test func(log Logger)
+	}{
+		{"Message", `{"level_name":"nolevel","message":"test message"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook)
+			log.Log().Msg("test message")
+		}},
+		{"NoLevel", `{"level_name":"nolevel"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook)
+			log.Log().Msg("")
+		}},
+		{"Print", `{"level":"debug","level_name":"debug"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook)
+			log.Print("")
+		}},
+		{"Error", `{"level":"error","level_name":"error"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook)
+			log.Error().Msg("")
+		}},
+		{"Copy/1", `{"copy_has_level":false,"copy_msg":""}` + "\n", func(log Logger) {
+			log = log.Hook(copyHook)
+			log.Log().Msg("")
+		}},
+		{"Copy/2", `{"level":"info","copy_has_level":true,"copy_level":"info","copy_msg":"a message","message":"a message"}` + "\n", func(log Logger) {
+			log = log.Hook(copyHook)
+			log.Info().Msg("a message")
+		}},
+		{"Multi", `{"level":"error","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook).Hook(simpleHook)
+			log.Error().Msg("")
+		}},
+		{"Multi/Message", `{"level":"error","level_name":"error","has_level":true,"test":"logged","message":"a message"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook).Hook(simpleHook)
+			log.Error().Msg("a message")
+		}},
+		{"Output/single/pre", `{"level":"error","level_name":"error"}` + "\n", func(log Logger) {
+			ignored := &bytes.Buffer{}
+			log = New(ignored).Hook(levelNameHook).Output(log.w)
+			log.Error().Msg("")
+		}},
+		{"Output/single/post", `{"level":"error","level_name":"error"}` + "\n", func(log Logger) {
+			ignored := &bytes.Buffer{}
+			log = New(ignored).Output(log.w).Hook(levelNameHook)
+			log.Error().Msg("")
+		}},
+		{"Output/multi/pre", `{"level":"error","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			ignored := &bytes.Buffer{}
+			log = New(ignored).Hook(levelNameHook).Hook(simpleHook).Output(log.w)
+			log.Error().Msg("")
+		}},
+		{"Output/multi/post", `{"level":"error","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			ignored := &bytes.Buffer{}
+			log = New(ignored).Output(log.w).Hook(levelNameHook).Hook(simpleHook)
+			log.Error().Msg("")
+		}},
+		{"Output/mixed", `{"level":"error","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			ignored := &bytes.Buffer{}
+			log = New(ignored).Hook(levelNameHook).Output(log.w).Hook(simpleHook)
+			log.Error().Msg("")
+		}},
+		{"With/single/pre", `{"level":"error","with":"pre","level_name":"error"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook).With().Str("with", "pre").Logger()
+			log.Error().Msg("")
+		}},
+		{"With/single/post", `{"level":"error","with":"post","level_name":"error"}` + "\n", func(log Logger) {
+			log = log.With().Str("with", "post").Logger().Hook(levelNameHook)
+			log.Error().Msg("")
+		}},
+		{"With/multi/pre", `{"level":"error","with":"pre","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook).Hook(simpleHook).With().Str("with", "pre").Logger()
+			log.Error().Msg("")
+		}},
+		{"With/multi/post", `{"level":"error","with":"post","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			log = log.With().Str("with", "post").Logger().Hook(levelNameHook).Hook(simpleHook)
+			log.Error().Msg("")
+		}},
+		{"With/mixed", `{"level":"error","with":"mixed","level_name":"error","has_level":true,"test":"logged"}` + "\n", func(log Logger) {
+			log = log.Hook(levelNameHook).With().Str("with", "mixed").Logger().Hook(simpleHook)
+			log.Error().Msg("")
+		}},
+		{"Discard", "", func(log Logger) {
+			log = log.Hook(discardHook)
+			log.Log().Msg("test message")
+		}},
+		{"None", `{"level":"error"}` + "\n", func(log Logger) {
+			log.Error().Msg("")
+		}},
+	}
+	for _, tt := range tests {
+		tt := tt
+		t.Run(tt.name, func(t *testing.T) {
+			out := &bytes.Buffer{}
+			log := New(out)
+			tt.test(log)
+			if got, want := decodeIfBinaryToString(out.Bytes()), tt.want; got != want {
+				t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+			}
+		})
+	}
 }
 
 func BenchmarkHooks(b *testing.B) {

internal/cbor/base.go

@@ -8,38 +8,4 @@ func (e Encoder) AppendKey(dst []byte, key string) []byte {
 		dst = e.AppendBeginMarker(dst)
 	}
 	return e.AppendString(dst, key)
-}
-
-// AppendError adds the Error to the log message if error is NOT nil
-func (e Encoder) AppendError(dst []byte, err error) []byte {
-	if err == nil {
-		return append(dst, `null`...)
-	}
-	return e.AppendString(dst, err.Error())
-}
-
-// AppendErrors when given an array of errors,
-// adds them to the log message if a specific error is nil, then
-// Nil is added, or else the error string is added.
-func (e Encoder) AppendErrors(dst []byte, errs []error) []byte {
-	if len(errs) == 0 {
-		return e.AppendArrayEnd(e.AppendArrayStart(dst))
-	}
-	dst = e.AppendArrayStart(dst)
-	if errs[0] != nil {
-		dst = e.AppendString(dst, errs[0].Error())
-	} else {
-		dst = e.AppendNil(dst)
-	}
-	if len(errs) > 1 {
-		for _, err := range errs[1:] {
-			if err == nil {
-				dst = e.AppendNil(dst)
-				continue
-			}
-			dst = e.AppendString(dst, err.Error())
-		}
-	}
-	dst = e.AppendArrayEnd(dst)
-	return dst
-}
+}

internal/cbor/types.go

@@ -24,9 +24,9 @@ func (Encoder) AppendEndMarker(dst []byte) []byte {
 
 // AppendObjectData takes an object in form of a byte array and appends to dst.
 func (Encoder) AppendObjectData(dst []byte, o []byte) []byte {
-        // BeginMarker is present in the dst, which
-        // should not be copied when appending to existing data.
-        return append(dst, o[1:]...)
+	// BeginMarker is present in the dst, which
+	// should not be copied when appending to existing data.
+	return append(dst, o[1:]...)
 }
 
 // AppendArrayStart adds markers to indicate the start of an array.

internal/cbor/types_64_test.go

@@ -0,0 +1,34 @@
+// +build !386
+
+package cbor
+
+import (
+	"encoding/hex"
+	"testing"
+)
+
+var enc2 = Encoder{}
+
+var integerTestCases_64bit = []struct {
+	val    int
+	binary string
+}{
+	// Value in 8 bytes.
+	{0xabcd100000000, "\x1b\x00\x0a\xbc\xd1\x00\x00\x00\x00"},
+	{1000000000000, "\x1b\x00\x00\x00\xe8\xd4\xa5\x10\x00"},
+	// Value in 8 bytes.
+	{-0xabcd100000001, "\x3b\x00\x0a\xbc\xd1\x00\x00\x00\x00"},
+	{-1000000000001, "\x3b\x00\x00\x00\xe8\xd4\xa5\x10\x00"},
+}
+
+func TestAppendInt_64bit(t *testing.T) {
+	for _, tc := range integerTestCases_64bit {
+		s := enc2.AppendInt([]byte{}, tc.val)
+		got := string(s)
+		if got != tc.binary {
+			t.Errorf("AppendInt(0x%x)=0x%s, want: 0x%s",
+				tc.val, hex.EncodeToString(s),
+				hex.EncodeToString([]byte(tc.binary)))
+		}
+	}
+}

internal/cbor/types_test.go

@@ -88,11 +88,8 @@ var integerTestCases = []struct {
 	{0xFFFF, "\x19\xff\xff"},
 	// Value in 4 bytes.
 	{0x10000, "\x1a\x00\x01\x00\x00"},
-	{0xFFFFFFFE, "\x1a\xff\xff\xff\xfe"},
+	{0x7FFFFFFE, "\x1a\x7f\xff\xff\xfe"},
 	{1000000, "\x1a\x00\x0f\x42\x40"},
-	// Value in 8 bytes.
-	{0xabcd100000000, "\x1b\x00\x0a\xbc\xd1\x00\x00\x00\x00"},
-	{1000000000000, "\x1b\x00\x00\x00\xe8\xd4\xa5\x10\x00"},
 	// Negative number test cases.
 	// Value included in the type.
 	{-1, "\x20"},
@@ -116,11 +113,9 @@ var integerTestCases = []struct {
 	{-1000, "\x39\x03\xe7"},
 	// Value in 4 bytes.
 	{-0x10001, "\x3a\x00\x01\x00\x00"},
-	{-0xFFFFFFFE, "\x3a\xff\xff\xff\xfd"},
+	{-0x7FFFFFFE, "\x3a\x7f\xff\xff\xfd"},
 	{-1000000, "\x3a\x00\x0f\x42\x3f"},
-	// Value in 8 bytes.
-	{-0xabcd100000001, "\x3b\x00\x0a\xbc\xd1\x00\x00\x00\x00"},
-	{-1000000000001, "\x3b\x00\x00\x00\xe8\xd4\xa5\x10\x00"},
+
 }
 
 func TestAppendInt(t *testing.T) {

internal/json/base.go

@@ -4,43 +4,8 @@ type Encoder struct{}
 
 // AppendKey appends a new key to the output JSON.
 func (e Encoder) AppendKey(dst []byte, key string) []byte {
-	if len(dst) > 1 && dst[len(dst)-1] != '{' {
+	if dst[len(dst)-1] != '{' {
 		dst = append(dst, ',')
 	}
-	dst = e.AppendString(dst, key)
-	return append(dst, ':')
-}
-
-// AppendError encodes the error string to json and appends
-// the encoded string to the input byte slice.
-func (e Encoder) AppendError(dst []byte, err error) []byte {
-	if err == nil {
-		return append(dst, `null`...)
-	}
-	return e.AppendString(dst, err.Error())
-}
-
-// AppendErrors encodes the error strings to json and
-// appends the encoded string list to the input byte slice.
-func (e Encoder) AppendErrors(dst []byte, errs []error) []byte {
-	if len(errs) == 0 {
-		return append(dst, '[', ']')
-	}
-	dst = append(dst, '[')
-	if errs[0] != nil {
-		dst = e.AppendString(dst, errs[0].Error())
-	} else {
-		dst = append(dst, "null"...)
-	}
-	if len(errs) > 1 {
-		for _, err := range errs[1:] {
-			if err == nil {
-				dst = append(dst, ",null"...)
-				continue
-			}
-			dst = e.AppendString(append(dst, ','), err.Error())
-		}
-	}
-	dst = append(dst, ']')
-	return dst
+	return append(e.AppendString(dst, key), ':')
 }

internal/json/time.go

@@ -5,11 +5,23 @@ import (
 	"time"
 )
 
+const (
+	// Import from zerolog/global.go
+	timeFormatUnix   = ""
+	timeFormatUnixMs = "UNIXMS"
+	timeFormatUnixMicro = "UNIXMICRO"
+)
+
 // AppendTime formats the input time with the given format
 // and appends the encoded string to the input byte slice.
 func (e Encoder) AppendTime(dst []byte, t time.Time, format string) []byte {
-	if format == "" {
+	switch format {
+	case timeFormatUnix:
 		return e.AppendInt64(dst, t.Unix())
+	case timeFormatUnixMs:
+		return e.AppendInt64(dst, t.UnixNano()/1000000)
+	case timeFormatUnixMicro:
+		return e.AppendInt64(dst, t.UnixNano()/1000)
 	}
 	return append(t.AppendFormat(append(dst, '"'), format), '"')
 }
@@ -17,8 +29,11 @@ func (e Encoder) AppendTime(dst []byte, t time.Time, format string) []byte {
 // AppendTimes converts the input times with the given format
 // and appends the encoded string list to the input byte slice.
 func (Encoder) AppendTimes(dst []byte, vals []time.Time, format string) []byte {
-	if format == "" {
+	switch format {
+	case timeFormatUnix:
 		return appendUnixTimes(dst, vals)
+	case timeFormatUnixMs:
+		return appendUnixMsTimes(dst, vals)
 	}
 	if len(vals) == 0 {
 		return append(dst, '[', ']')
@@ -49,6 +64,21 @@ func appendUnixTimes(dst []byte, vals []time.Time) []byte {
 	return dst
 }
 
+func appendUnixMsTimes(dst []byte, vals []time.Time) []byte {
+	if len(vals) == 0 {
+		return append(dst, '[', ']')
+	}
+	dst = append(dst, '[')
+	dst = strconv.AppendInt(dst, vals[0].UnixNano()/1000000, 10)
+	if len(vals) > 1 {
+		for _, t := range vals[1:] {
+			dst = strconv.AppendInt(append(dst, ','), t.UnixNano()/1000000, 10)
+		}
+	}
+	dst = append(dst, ']')
+	return dst
+}
+
 // AppendDuration formats the input duration with the given unit & format
 // and appends the encoded string to the input byte slice.
 func (e Encoder) AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool) []byte {

internal/json/types.go

@@ -350,7 +350,7 @@ func (Encoder) AppendFloats64(dst []byte, vals []float64) []byte {
 		return append(dst, '[', ']')
 	}
 	dst = append(dst, '[')
-	dst = appendFloat(dst, vals[0], 32)
+	dst = appendFloat(dst, vals[0], 64)
 	if len(vals) > 1 {
 		for _, val := range vals[1:] {
 			dst = appendFloat(append(dst, ','), val, 64)
@@ -373,12 +373,16 @@ func (e Encoder) AppendInterface(dst []byte, i interface{}) []byte {
 // AppendObjectData takes in an object that is already in a byte array
 // and adds it to the dst.
 func (Encoder) AppendObjectData(dst []byte, o []byte) []byte {
-	// Two conditions we want to put a ',' between existing content and
-	// new content:
-	// 1. new content starts with '{' - which shd be dropped   OR
-	// 2. existing content has already other fields
+	// Three conditions apply here:
+	// 1. new content starts with '{' - which should be dropped   OR
+	// 2. new content starts with '{' - which should be replaced with ','
+	//    to separate with existing content OR
+	// 3. existing content has already other fields
 	if o[0] == '{' {
-		o[0] = ','
+		if len(dst) > 1 {
+			dst = append(dst, ',')
+		}
+		o = o[1:]
 	} else if len(dst) > 1 {
 		dst = append(dst, ',')
 	}

internal/json/types_test.go

@@ -165,3 +165,23 @@ func Test_appendMac(t *testing.T) {
 		})
 	}
 }
+
+func Test_appendObjectData(t *testing.T) {
+	tests := []struct {
+		dst  []byte
+		obj  []byte
+		want []byte
+	}{
+		{[]byte{}, []byte(`{"foo":"bar"}`), []byte(`"foo":"bar"}`)},
+		{[]byte(`{"qux":"quz"`), []byte(`{"foo":"bar"}`), []byte(`{"qux":"quz","foo":"bar"}`)},
+		{[]byte{}, []byte(`"foo":"bar"`), []byte(`"foo":"bar"`)},
+		{[]byte(`{"qux":"quz"`), []byte(`"foo":"bar"`), []byte(`{"qux":"quz","foo":"bar"`)},
+	}
+	for _, tt := range tests {
+		t.Run("ObjectData", func(t *testing.T) {
+			if got := enc.AppendObjectData(tt.dst, tt.obj); !reflect.DeepEqual(got, tt.want) {
+				t.Errorf("appendObjectData() = %s, want %s", got, tt.want)
+			}
+		})
+	}
+}

journald/journald.go

@@ -20,11 +20,12 @@ import (
 	"bytes"
 	"encoding/json"
 	"fmt"
+	"io"
+	"strings"
+
 	"github.com/coreos/go-systemd/journal"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/internal/cbor"
-	"io"
-	"strings"
 )
 
 const defaultJournalDPrio = journal.PriNotice
@@ -47,6 +48,8 @@ func levelToJPrio(zLevel string) journal.Priority {
 	lvl, _ := zerolog.ParseLevel(zLevel)
 
 	switch lvl {
+	case zerolog.TraceLevel:
+		return journal.PriDebug
 	case zerolog.DebugLevel:
 		return journal.PriDebug
 	case zerolog.InfoLevel:
@@ -67,10 +70,12 @@ func levelToJPrio(zLevel string) journal.Priority {
 
 func (w journalWriter) Write(p []byte) (n int, err error) {
 	if !journal.Enabled() {
-		err = fmt.Errorf("Cannot connect to journalD!!")
+		err = fmt.Errorf("cannot connect to journalD")
 		return
 	}
+
 	var event map[string]interface{}
+	origPLen := len(p)
 	p = cbor.DecodeIfBinaryToBytes(p)
 	d := json.NewDecoder(bytes.NewReader(p))
 	d.UseNumber()
@@ -111,5 +116,10 @@ func (w journalWriter) Write(p []byte) (n int, err error) {
 	}
 	args["JSON"] = string(p)
 	err = journal.Send(msg, jPrio, args)
+
+	if err == nil {
+		n = origPLen
+	}
+
 	return
 }

journald/journald_test.go

@@ -1,9 +1,15 @@
-// +build !windows
+// +build linux
 
 package journald_test
 
-import "github.com/rs/zerolog"
-import "github.com/rs/zerolog/journald"
+import (
+	"bytes"
+	"io"
+	"testing"
+
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/journald"
+)
 
 func ExampleNewJournalDWriter() {
 	log := zerolog.New(journald.NewJournalDWriter())
@@ -42,3 +48,39 @@ Thu 2018-04-26 22:30:20.768136 PDT [s=3284d695bde946e4b5017c77a399237f;i=329f0;b
     _PID=27103
     _SOURCE_REALTIME_TIMESTAMP=1524807020768136
 */
+
+func TestWriteReturnsNoOfWrittenBytes(t *testing.T) {
+	input := []byte(`{"level":"info","time":1570912626,"message":"Starting..."}`)
+	wr := journald.NewJournalDWriter()
+	want := len(input)
+	got, err := wr.Write(input)
+
+	if err != nil {
+		t.Errorf("Unexpected error %v", err)
+	}
+
+	if want != got {
+		t.Errorf("Expected %d bytes to be written got %d", want, got)
+	}
+}
+
+func TestMultiWrite(t *testing.T) {
+	var (
+		w1 = new(bytes.Buffer)
+		w2 = new(bytes.Buffer)
+		w3 = journald.NewJournalDWriter()
+	)
+
+	zerolog.ErrorHandler = func(err error) {
+		if err == io.ErrShortWrite {
+			t.Errorf("Unexpected ShortWriteError")
+			t.FailNow()
+		}
+	}
+
+	log := zerolog.New(io.MultiWriter(w1, w2, w3)).With().Logger()
+
+	for i := 0; i < 10; i++ {
+		log.Info().Msg("Tick!")
+	}
+}

log.go

@@ -94,8 +94,8 @@
 //            Msg("dup")
 //     // Output: {"level":"info","time":1494567715,"time":1494567715,"message":"dup"}
 //
-// However, it’s not a big deal though as JSON accepts dup keys,
-// the last one prevails.
+// In this case, many consumers will take the last value,
+// but this is not guaranteed; check yours if in doubt.
 package zerolog
 
 import (
@@ -107,7 +107,7 @@ import (
 )
 
 // Level defines log levels.
-type Level uint8
+type Level int8
 
 const (
 	// DebugLevel defines debug log level.
@@ -126,22 +126,29 @@ const (
 	NoLevel
 	// Disabled disables the logger.
 	Disabled
+
+	// TraceLevel defines trace log level.
+	TraceLevel Level = -1
 )
 
 func (l Level) String() string {
 	switch l {
+	case TraceLevel:
+		return LevelTraceValue
 	case DebugLevel:
-		return "debug"
+		return LevelDebugValue
 	case InfoLevel:
-		return "info"
+		return LevelInfoValue
 	case WarnLevel:
-		return "warn"
+		return LevelWarnValue
 	case ErrorLevel:
-		return "error"
+		return LevelErrorValue
 	case FatalLevel:
-		return "fatal"
+		return LevelFatalValue
 	case PanicLevel:
-		return "panic"
+		return LevelPanicValue
+	case Disabled:
+		return "disabled"
 	case NoLevel:
 		return ""
 	}
@@ -152,19 +159,23 @@ func (l Level) String() string {
 // returns an error if the input string does not match known values.
 func ParseLevel(levelStr string) (Level, error) {
 	switch levelStr {
-	case DebugLevel.String():
+	case LevelFieldMarshalFunc(TraceLevel):
+		return TraceLevel, nil
+	case LevelFieldMarshalFunc(DebugLevel):
 		return DebugLevel, nil
-	case InfoLevel.String():
+	case LevelFieldMarshalFunc(InfoLevel):
 		return InfoLevel, nil
-	case WarnLevel.String():
+	case LevelFieldMarshalFunc(WarnLevel):
 		return WarnLevel, nil
-	case ErrorLevel.String():
+	case LevelFieldMarshalFunc(ErrorLevel):
 		return ErrorLevel, nil
-	case FatalLevel.String():
+	case LevelFieldMarshalFunc(FatalLevel):
 		return FatalLevel, nil
-	case PanicLevel.String():
+	case LevelFieldMarshalFunc(PanicLevel):
 		return PanicLevel, nil
-	case NoLevel.String():
+	case LevelFieldMarshalFunc(Disabled):
+		return Disabled, nil
+	case LevelFieldMarshalFunc(NoLevel):
 		return NoLevel, nil
 	}
 	return NoLevel, fmt.Errorf("Unknown Level String: '%s', defaulting to NoLevel", levelStr)
@@ -172,7 +183,7 @@ func ParseLevel(levelStr string) (Level, error) {
 
 // A Logger represents an active logging object that generates lines
 // of JSON output to an io.Writer. Each logging operation makes a single
-// call to the Writer's Write method. There is no guaranty on access
+// call to the Writer's Write method. There is no guarantee on access
 // serialization to the Writer. If your Writer is not thread safe,
 // you may consider a sync wrapper.
 type Logger struct {
@@ -181,6 +192,7 @@ type Logger struct {
 	sampler Sampler
 	context []byte
 	hooks   []Hook
+	stack   bool
 }
 
 // New creates a root logger with given output writer. If the output writer implements
@@ -188,7 +200,7 @@ type Logger struct {
 // one.
 //
 // Each logging operation makes a single call to the Writer's Write method. There is no
-// guaranty on access serialization to the Writer. If your Writer is not thread safe,
+// guarantee on access serialization to the Writer. If your Writer is not thread safe,
 // you may consider using sync wrapper.
 func New(w io.Writer) Logger {
 	if w == nil {
@@ -198,7 +210,7 @@ func New(w io.Writer) Logger {
 	if !ok {
 		lw = levelWriterAdapter{w}
 	}
-	return Logger{w: lw}
+	return Logger{w: lw, level: TraceLevel}
 }
 
 // Nop returns a disabled logger for which all operation are no-op.
@@ -227,6 +239,10 @@ func (l Logger) With() Context {
 	l.context = make([]byte, 0, 500)
 	if context != nil {
 		l.context = append(l.context, context...)
+	} else {
+		// This is needed for AppendKey to not check len of input
+		// thus making it inlinable
+		l.context = enc.AppendBeginMarker(l.context)
 	}
 	return Context{l}
 }
@@ -241,6 +257,9 @@ func (l *Logger) UpdateContext(update func(c Context) Context) {
 	if cap(l.context) == 0 {
 		l.context = make([]byte, 0, 500)
 	}
+	if len(l.context) == 0 {
+		l.context = enc.AppendBeginMarker(l.context)
+	}
 	c := update(Context{*l})
 	l.context = c.l.context
 }
@@ -251,6 +270,11 @@ func (l Logger) Level(lvl Level) Logger {
 	return l
 }
 
+// GetLevel returns the current Level of l.
+func (l Logger) GetLevel() Level {
+	return l.level
+}
+
 // Sample returns a logger with the s sampler.
 func (l Logger) Sample(s Sampler) Logger {
 	l.sampler = s
@@ -263,6 +287,13 @@ func (l Logger) Hook(h Hook) Logger {
 	return l
 }
 
+// Trace starts a new message with trace level.
+//
+// You must call Msg on the returned event in order to send the event.
+func (l *Logger) Trace() *Event {
+	return l.newEvent(TraceLevel, nil)
+}
+
 // Debug starts a new message with debug level.
 //
 // You must call Msg on the returned event in order to send the event.
@@ -291,27 +322,43 @@ func (l *Logger) Error() *Event {
 	return l.newEvent(ErrorLevel, nil)
 }
 
+// Err starts a new message with error level with err as a field if not nil or
+// with info level if err is nil.
+//
+// You must call Msg on the returned event in order to send the event.
+func (l *Logger) Err(err error) *Event {
+	if err != nil {
+		return l.Error().Err(err)
+	}
+
+	return l.Info()
+}
+
 // Fatal starts a new message with fatal level. The os.Exit(1) function
-// is called by the Msg method.
+// is called by the Msg method, which terminates the program immediately.
 //
 // You must call Msg on the returned event in order to send the event.
 func (l *Logger) Fatal() *Event {
 	return l.newEvent(FatalLevel, func(msg string) { os.Exit(1) })
 }
 
-// Panic starts a new message with panic level. The message is also sent
-// to the panic function.
+// Panic starts a new message with panic level. The panic() function
+// is called by the Msg method, which stops the ordinary flow of a goroutine.
 //
 // You must call Msg on the returned event in order to send the event.
 func (l *Logger) Panic() *Event {
 	return l.newEvent(PanicLevel, func(msg string) { panic(msg) })
 }
 
-// WithLevel starts a new message with level.
+// WithLevel starts a new message with level. Unlike Fatal and Panic
+// methods, WithLevel does not terminate the program or stop the ordinary
+// flow of a gourotine when used with their respective levels.
 //
 // You must call Msg on the returned event in order to send the event.
 func (l *Logger) WithLevel(level Level) *Event {
 	switch level {
+	case TraceLevel:
+		return l.Trace()
 	case DebugLevel:
 		return l.Debug()
 	case InfoLevel:
@@ -321,9 +368,9 @@ func (l *Logger) WithLevel(level Level) *Event {
 	case ErrorLevel:
 		return l.Error()
 	case FatalLevel:
-		return l.Fatal()
+		return l.newEvent(FatalLevel, nil)
 	case PanicLevel:
-		return l.Panic()
+		return l.newEvent(PanicLevel, nil)
 	case NoLevel:
 		return l.Log()
 	case Disabled:
@@ -345,7 +392,7 @@ func (l *Logger) Log() *Event {
 // 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...))
+		e.CallerSkipFrame(1).Msg(fmt.Sprint(v...))
 	}
 }
 
@@ -353,7 +400,7 @@ func (l *Logger) Print(v ...interface{}) {
 // 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...))
+		e.CallerSkipFrame(1).Msg(fmt.Sprintf(format, v...))
 	}
 }
 
@@ -365,7 +412,7 @@ func (l Logger) Write(p []byte) (n int, err error) {
 		// Trim CR added by stdlog.
 		p = p[0 : n-1]
 	}
-	l.Log().Msg(string(p))
+	l.Log().CallerSkipFrame(1).Msg(string(p))
 	return
 }
 
@@ -377,12 +424,15 @@ func (l *Logger) newEvent(level Level, done func(string)) *Event {
 	e := newEvent(l.w, level)
 	e.done = done
 	e.ch = l.hooks
-	if level != NoLevel {
-		e.Str(LevelFieldName, level.String())
+	if level != NoLevel && LevelFieldName != "" {
+		e.Str(LevelFieldName, LevelFieldMarshalFunc(level))
 	}
-	if l.context != nil && len(l.context) > 0 {
+	if l.context != nil && len(l.context) > 1 {
 		e.buf = enc.AppendObjectData(e.buf, l.context)
 	}
+	if l.stack {
+		e.Stack()
+	}
 	return e
 }
 

log/log.go

@@ -3,6 +3,7 @@ package log
 
 import (
 	"context"
+	"fmt"
 	"io"
 	"os"
 
@@ -37,6 +38,21 @@ func Hook(h zerolog.Hook) zerolog.Logger {
 	return Logger.Hook(h)
 }
 
+// Err starts a new message with error level with err as a field if not nil or
+// with info level if err is nil.
+//
+// You must call Msg on the returned event in order to send the event.
+func Err(err error) *zerolog.Event {
+	return Logger.Err(err)
+}
+
+// Trace starts a new message with trace level.
+//
+// You must call Msg on the returned event in order to send the event.
+func Trace() *zerolog.Event {
+	return Logger.Trace()
+}
+
 // Debug starts a new message with debug level.
 //
 // You must call Msg on the returned event in order to send the event.
@@ -99,13 +115,13 @@ func Log() *zerolog.Event {
 // 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...)
+	Logger.Debug().CallerSkipFrame(1).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 Printf(format string, v ...interface{}) {
-	Logger.Printf(format, v...)
+	Logger.Debug().CallerSkipFrame(1).Msgf(format, v...)
 }
 
 // Ctx returns the Logger associated with the ctx. If no logger

log/log_example_test.go

@@ -54,6 +54,25 @@ func ExampleLog() {
 	// Output: {"time":1199811905,"message":"hello world"}
 }
 
+// Example of a conditional level based on the presence of an error.
+func ExampleErr() {
+	setup()
+	err := errors.New("some error")
+	log.Err(err).Msg("hello world")
+	log.Err(nil).Msg("hello world")
+
+	// Output: {"level":"error","error":"some error","time":1199811905,"message":"hello world"}
+	// {"level":"info","time":1199811905,"message":"hello world"}
+}
+
+// Example of a log at a particular "level" (in this case, "trace")
+func ExampleTrace() {
+	setup()
+	log.Trace().Msg("hello world")
+
+	// Output: {"level":"trace","time":1199811905,"message":"hello world"}
+}
+
 // Example of a log at a particular "level" (in this case, "debug")
 func ExampleDebug() {
 	setup()

log_example_test.go

@@ -48,8 +48,8 @@ func ExampleLogger_Sample() {
 	log.Info().Msg("message 3")
 	log.Info().Msg("message 4")
 
-	// Output: {"level":"info","message":"message 2"}
-	// {"level":"info","message":"message 4"}
+	// Output: {"level":"info","message":"message 1"}
+	// {"level":"info","message":"message 3"}
 }
 
 type LevelNameHook struct{}
@@ -95,6 +95,17 @@ func ExampleLogger_Printf() {
 	// Output: {"level":"debug","message":"hello world"}
 }
 
+func ExampleLogger_Trace() {
+	log := zerolog.New(os.Stdout)
+
+	log.Trace().
+		Str("foo", "bar").
+		Int("n", 123).
+		Msg("hello world")
+
+	// Output: {"level":"trace","foo":"bar","n":123,"message":"hello world"}
+}
+
 func ExampleLogger_Debug() {
 	log := zerolog.New(os.Stdout)
 

log_test.go

@@ -7,6 +7,8 @@ import (
 	"net"
 	"reflect"
 	"runtime"
+	"strconv"
+	"strings"
 	"testing"
 	"time"
 )
@@ -75,10 +77,30 @@ func TestInfo(t *testing.T) {
 	})
 }
 
+func TestEmptyLevelFieldName(t *testing.T) {
+	fieldName := LevelFieldName
+	LevelFieldName = ""
+
+	t.Run("empty setting", func(t *testing.T) {
+		out := &bytes.Buffer{}
+		log := New(out)
+		log.Info().
+			Str("foo", "bar").
+			Int("n", 123).
+			Msg("")
+		if got, want := decodeIfBinaryToString(out.Bytes()), `{"foo":"bar","n":123}`+"\n"; got != want {
+			t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+		}
+	})
+	LevelFieldName = fieldName
+}
+
 func TestWith(t *testing.T) {
 	out := &bytes.Buffer{}
 	ctx := New(out).With().
 		Str("string", "foo").
+		Stringer("stringer", net.IP{127, 0, 0, 1}).
+		Stringer("stringer_nil", nil).
 		Bytes("bytes", []byte("bar")).
 		Hex("hex", []byte{0x12, 0xef}).
 		RawJSON("json", []byte(`{"some":"json"}`)).
@@ -102,7 +124,21 @@ func TestWith(t *testing.T) {
 	caller := fmt.Sprintf("%s:%d", file, line+3)
 	log := ctx.Caller().Logger()
 	log.Log().Msg("")
-	if got, want := decodeIfBinaryToString(out.Bytes()), `{"string":"foo","bytes":"bar","hex":"12ef","json":{"some":"json"},"error":"some error","bool":true,"int":1,"int8":2,"int16":3,"int32":4,"int64":5,"uint":6,"uint8":7,"uint16":8,"uint32":9,"uint64":10,"float32":11.101,"float64":12.30303,"time":"0001-01-01T00:00:00Z","caller":"`+caller+`"}`+"\n"; got != want {
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"string":"foo","stringer":"127.0.0.1","stringer_nil":null,"bytes":"bar","hex":"12ef","json":{"some":"json"},"error":"some error","bool":true,"int":1,"int8":2,"int16":3,"int32":4,"int64":5,"uint":6,"uint8":7,"uint16":8,"uint32":9,"uint64":10,"float32":11.101,"float64":12.30303,"time":"0001-01-01T00:00:00Z","caller":"`+caller+`"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+
+	// Validate CallerWithSkipFrameCount.
+	out.Reset()
+	_, file, line, _ = runtime.Caller(0)
+	caller = fmt.Sprintf("%s:%d", file, line+5)
+	log = ctx.CallerWithSkipFrameCount(3).Logger()
+	func() {
+		log.Log().Msg("")
+	}()
+	// The above line is a little contrived, but the line above should be the line due
+	// to the extra frame skip.
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"string":"foo","stringer":"127.0.0.1","stringer_nil":null,"bytes":"bar","hex":"12ef","json":{"some":"json"},"error":"some error","bool":true,"int":1,"int8":2,"int16":3,"int32":4,"int64":5,"uint":6,"uint8":7,"uint16":8,"uint32":9,"uint64":10,"float32":11.101,"float64":12.30303,"time":"0001-01-01T00:00:00Z","caller":"`+caller+`"}`+"\n"; got != want {
 		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
 	}
 }
@@ -164,6 +200,52 @@ func TestFieldsMapPnt(t *testing.T) {
 	}
 }
 
+func TestFieldsMapNilPnt(t *testing.T) {
+	var (
+		stringPnt  *string
+		boolPnt    *bool
+		intPnt     *int
+		int8Pnt    *int8
+		int16Pnt   *int16
+		int32Pnt   *int32
+		int64Pnt   *int64
+		uintPnt    *uint
+		uint8Pnt   *uint8
+		uint16Pnt  *uint16
+		uint32Pnt  *uint32
+		uint64Pnt  *uint64
+		float32Pnt *float32
+		float64Pnt *float64
+		durPnt     *time.Duration
+		timePnt    *time.Time
+	)
+	out := &bytes.Buffer{}
+	log := New(out)
+	fields := map[string]interface{}{
+		"string":  stringPnt,
+		"bool":    boolPnt,
+		"int":     intPnt,
+		"int8":    int8Pnt,
+		"int16":   int16Pnt,
+		"int32":   int32Pnt,
+		"int64":   int64Pnt,
+		"uint":    uintPnt,
+		"uint8":   uint8Pnt,
+		"uint16":  uint16Pnt,
+		"uint32":  uint32Pnt,
+		"uint64":  uint64Pnt,
+		"float32": float32Pnt,
+		"float64": float64Pnt,
+		"dur":     durPnt,
+		"time":    timePnt,
+	}
+
+	log.Log().Fields(fields).Msg("")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"bool":null,"dur":null,"float32":null,"float64":null,"int":null,"int16":null,"int32":null,"int64":null,"int8":null,"string":null,"time":null,"uint":null,"uint16":null,"uint32":null,"uint64":null,"uint8":null}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+}
+
 func TestFields(t *testing.T) {
 	out := &bytes.Buffer{}
 	log := New(out)
@@ -173,6 +255,8 @@ func TestFields(t *testing.T) {
 	log.Log().
 		Caller().
 		Str("string", "foo").
+		Stringer("stringer", net.IP{127, 0, 0, 1}).
+		Stringer("stringer_nil", nil).
 		Bytes("bytes", []byte("bar")).
 		Hex("hex", []byte{0x12, 0xef}).
 		RawJSON("json", []byte(`{"some":"json"}`)).
@@ -199,7 +283,7 @@ func TestFields(t *testing.T) {
 		Time("time", time.Time{}).
 		TimeDiff("diff", now, now.Add(-10*time.Second)).
 		Msg("")
-	if got, want := decodeIfBinaryToString(out.Bytes()), `{"caller":"`+caller+`","string":"foo","bytes":"bar","hex":"12ef","json":{"some":"json"},"error":"some error","bool":true,"int":1,"int8":2,"int16":3,"int32":4,"int64":5,"uint":6,"uint8":7,"uint16":8,"uint32":9,"uint64":10,"IPv4":"192.168.0.100","IPv6":"2001:db8:85a3::8a2e:370:7334","Mac":"00:14:22:01:23:45","Prefix":"192.168.0.100/24","float32":11.1234,"float64":12.321321321,"dur":1000,"time":"0001-01-01T00:00:00Z","diff":10000}`+"\n"; got != want {
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"caller":"`+caller+`","string":"foo","stringer":"127.0.0.1","stringer_nil":null,"bytes":"bar","hex":"12ef","json":{"some":"json"},"error":"some error","bool":true,"int":1,"int8":2,"int16":3,"int32":4,"int64":5,"uint":6,"uint8":7,"uint16":8,"uint32":9,"uint64":10,"IPv4":"192.168.0.100","IPv6":"2001:db8:85a3::8a2e:370:7334","Mac":"00:14:22:01:23:45","Prefix":"192.168.0.100/24","float32":11.1234,"float64":12.321321321,"dur":1000,"time":"0001-01-01T00:00:00Z","diff":10000}`+"\n"; got != want {
 		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
 	}
 }
@@ -391,6 +475,24 @@ func TestLevel(t *testing.T) {
 	})
 }
 
+func TestGetLevel(t *testing.T) {
+	levels := []Level{
+		DebugLevel,
+		InfoLevel,
+		WarnLevel,
+		ErrorLevel,
+		FatalLevel,
+		PanicLevel,
+		NoLevel,
+		Disabled,
+	}
+	for _, level := range levels {
+		if got, want := New(nil).Level(level).GetLevel(), level; got != want {
+			t.Errorf("GetLevel() = %v, want: %v", got, want)
+		}
+	}
+}
+
 func TestSampling(t *testing.T) {
 	out := &bytes.Buffer{}
 	log := New(out).Sample(&BasicSampler{N: 2})
@@ -398,7 +500,22 @@ func TestSampling(t *testing.T) {
 	log.Log().Int("i", 2).Msg("")
 	log.Log().Int("i", 3).Msg("")
 	log.Log().Int("i", 4).Msg("")
-	if got, want := decodeIfBinaryToString(out.Bytes()), "{\"i\":2}\n{\"i\":4}\n"; got != want {
+	if got, want := decodeIfBinaryToString(out.Bytes()), "{\"i\":1}\n{\"i\":3}\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+}
+
+func TestDiscard(t *testing.T) {
+	out := &bytes.Buffer{}
+	log := New(out)
+	log.Log().Discard().Str("a", "b").Msgf("one %s %.1f %d %v", "two", 3.4, 5, errors.New("six"))
+	if got, want := decodeIfBinaryToString(out.Bytes()), ""; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+
+	// Double call
+	log.Log().Discard().Discard().Str("a", "b").Msgf("one %s %.1f %d %v", "two", 3.4, 5, errors.New("six"))
+	if got, want := decodeIfBinaryToString(out.Bytes()), ""; got != want {
 		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
 	}
 }
@@ -431,30 +548,34 @@ func TestLevelWriter(t *testing.T) {
 		}{},
 	}
 	log := New(lw)
+	log.Trace().Msg("0")
 	log.Debug().Msg("1")
 	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(TraceLevel).Msg("5")
+	log.WithLevel(DebugLevel).Msg("6")
+	log.WithLevel(InfoLevel).Msg("7")
+	log.WithLevel(WarnLevel).Msg("8")
+	log.WithLevel(ErrorLevel).Msg("9")
 	log.WithLevel(NoLevel).Msg("nolevel-2")
 
 	want := []struct {
 		l Level
 		p string
 	}{
+		{TraceLevel, `{"level":"trace","message":"0"}` + "\n"},
 		{DebugLevel, `{"level":"debug","message":"1"}` + "\n"},
 		{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"},
+		{TraceLevel, `{"level":"trace","message":"5"}` + "\n"},
+		{DebugLevel, `{"level":"debug","message":"6"}` + "\n"},
+		{InfoLevel, `{"level":"info","message":"7"}` + "\n"},
+		{WarnLevel, `{"level":"warn","message":"8"}` + "\n"},
+		{ErrorLevel, `{"level":"error","message":"9"}` + "\n"},
 		{NoLevel, `{"message":"nolevel-2"}` + "\n"},
 	}
 	if got := lw.ops; !reflect.DeepEqual(got, want) {
@@ -521,3 +642,226 @@ func TestOutputWithTimestamp(t *testing.T) {
 		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
 	}
 }
+
+type loggableError struct {
+	error
+}
+
+func (l loggableError) MarshalZerologObject(e *Event) {
+	e.Str("message", l.error.Error()+": loggableError")
+}
+
+func TestErrorMarshalFunc(t *testing.T) {
+	out := &bytes.Buffer{}
+	log := New(out)
+
+	// test default behaviour
+	log.Log().Err(errors.New("err")).Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"error":"err","message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+
+	log.Log().Err(loggableError{errors.New("err")}).Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"error":{"message":"err: loggableError"},"message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+
+	// test overriding the ErrorMarshalFunc
+	originalErrorMarshalFunc := ErrorMarshalFunc
+	defer func() {
+		ErrorMarshalFunc = originalErrorMarshalFunc
+	}()
+
+	ErrorMarshalFunc = func(err error) interface{} {
+		return err.Error() + ": marshaled string"
+	}
+	log.Log().Err(errors.New("err")).Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"error":"err: marshaled string","message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+
+	out.Reset()
+	ErrorMarshalFunc = func(err error) interface{} {
+		return errors.New(err.Error() + ": new error")
+	}
+	log.Log().Err(errors.New("err")).Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"error":"err: new error","message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+
+	out.Reset()
+	ErrorMarshalFunc = func(err error) interface{} {
+		return loggableError{err}
+	}
+	log.Log().Err(errors.New("err")).Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"error":{"message":"err: loggableError"},"message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+}
+
+func TestCallerMarshalFunc(t *testing.T) {
+	out := &bytes.Buffer{}
+	log := New(out)
+
+	// test default behaviour this is really brittle due to the line numbers
+	// actually mattering for validation
+	_, file, line, _ := runtime.Caller(0)
+	caller := fmt.Sprintf("%s:%d", file, line+2)
+	log.Log().Caller().Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"caller":"`+caller+`","message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+
+	// test custom behavior. In this case we'll take just the last directory
+	origCallerMarshalFunc := CallerMarshalFunc
+	defer func() { CallerMarshalFunc = origCallerMarshalFunc }()
+	CallerMarshalFunc = func(file string, line int) string {
+		parts := strings.Split(file, "/")
+		if len(parts) > 1 {
+			return strings.Join(parts[len(parts)-2:], "/") + ":" + strconv.Itoa(line)
+		}
+
+		return file + ":" + strconv.Itoa(line)
+	}
+	_, file, line, _ = runtime.Caller(0)
+	caller = CallerMarshalFunc(file, line+2)
+	log.Log().Caller().Msg("msg")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"caller":"`+caller+`","message":"msg"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+}
+
+func TestLevelFieldMarshalFunc(t *testing.T) {
+	origLevelFieldMarshalFunc := LevelFieldMarshalFunc
+	LevelFieldMarshalFunc = func(l Level) string {
+		return strings.ToUpper(l.String())
+	}
+	defer func() {
+		LevelFieldMarshalFunc = origLevelFieldMarshalFunc
+	}()
+	out := &bytes.Buffer{}
+	log := New(out)
+
+	log.Debug().Msg("test")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"level":"DEBUG","message":"test"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+
+	log.Info().Msg("test")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"level":"INFO","message":"test"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+
+	log.Warn().Msg("test")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"level":"WARN","message":"test"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+
+	log.Error().Msg("test")
+	if got, want := decodeIfBinaryToString(out.Bytes()), `{"level":"ERROR","message":"test"}`+"\n"; got != want {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+	out.Reset()
+}
+
+type errWriter struct {
+	error
+}
+
+func (w errWriter) Write(p []byte) (n int, err error) {
+	return 0, w.error
+}
+
+func TestErrorHandler(t *testing.T) {
+	var got error
+	want := errors.New("write error")
+	ErrorHandler = func(err error) {
+		got = err
+	}
+	log := New(errWriter{want})
+	log.Log().Msg("test")
+	if got != want {
+		t.Errorf("ErrorHandler err = %#v, want %#v", got, want)
+	}
+}
+
+func TestUpdateEmptyContext(t *testing.T) {
+	var buf bytes.Buffer
+	log := New(&buf)
+
+	log.UpdateContext(func(c Context) Context {
+		return c.Str("foo", "bar")
+	})
+	log.Info().Msg("no panic")
+
+	want := `{"level":"info","foo":"bar","message":"no panic"}` + "\n"
+
+	if got := decodeIfBinaryToString(buf.Bytes()); got != want {
+		t.Errorf("invalid log output:\ngot:  %q\nwant: %q", got, want)
+	}
+}
+
+func TestLevel_String(t *testing.T) {
+	tests := []struct {
+		name string
+		l    Level
+		want string
+	}{
+		{"trace", TraceLevel, "trace"},
+		{"debug", DebugLevel, "debug"},
+		{"info", InfoLevel, "info"},
+		{"warn", WarnLevel, "warn"},
+		{"error", ErrorLevel, "error"},
+		{"fatal", FatalLevel, "fatal"},
+		{"panic", PanicLevel, "panic"},
+		{"disabled", Disabled, "disabled"},
+		{"nolevel", NoLevel, ""},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			if got := tt.l.String(); got != tt.want {
+				t.Errorf("String() = %v, want %v", got, tt.want)
+			}
+		})
+	}
+}
+
+func TestParseLevel(t *testing.T) {
+	type args struct {
+		levelStr string
+	}
+	tests := []struct {
+		name    string
+		args    args
+		want    Level
+		wantErr bool
+	}{
+		{"trace", args{"trace"}, TraceLevel, false},
+		{"debug", args{"debug"}, DebugLevel, false},
+		{"info", args{"info"}, InfoLevel, false},
+		{"warn", args{"warn"}, WarnLevel, false},
+		{"error", args{"error"}, ErrorLevel, false},
+		{"fatal", args{"fatal"}, FatalLevel, false},
+		{"panic", args{"panic"}, PanicLevel, false},
+		{"disabled", args{"disabled"}, Disabled, false},
+		{"nolevel", args{""}, NoLevel, false},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got, err := ParseLevel(tt.args.levelStr)
+			if (err != nil) != tt.wantErr {
+				t.Errorf("ParseLevel() error = %v, wantErr %v", err, tt.wantErr)
+				return
+			}
+			if got != tt.want {
+				t.Errorf("ParseLevel() got = %v, want %v", got, tt.want)
+			}
+		})
+	}
+}

not_go112.go

@@ -0,0 +1,5 @@
+// +build !go1.12
+
+package zerolog
+
+const contextCallerSkipFrameCount = 3

pkgerrors/stacktrace.go

@@ -0,0 +1,65 @@
+package pkgerrors
+
+import (
+	"github.com/pkg/errors"
+)
+
+var (
+	StackSourceFileName     = "source"
+	StackSourceLineName     = "line"
+	StackSourceFunctionName = "func"
+)
+
+type state struct {
+	b []byte
+}
+
+// Write implement fmt.Formatter interface.
+func (s *state) Write(b []byte) (n int, err error) {
+	s.b = b
+	return len(b), nil
+}
+
+// Width implement fmt.Formatter interface.
+func (s *state) Width() (wid int, ok bool) {
+	return 0, false
+}
+
+// Precision implement fmt.Formatter interface.
+func (s *state) Precision() (prec int, ok bool) {
+	return 0, false
+}
+
+// Flag implement fmt.Formatter interface.
+func (s *state) Flag(c int) bool {
+	return false
+}
+
+func frameField(f errors.Frame, s *state, c rune) string {
+	f.Format(s, c)
+	return string(s.b)
+}
+
+// MarshalStack implements pkg/errors stack trace marshaling.
+//
+//   zerolog.ErrorStackMarshaler = MarshalStack
+func MarshalStack(err error) interface{} {
+	type stackTracer interface {
+		StackTrace() errors.StackTrace
+	}
+	sterr, ok := err.(stackTracer)
+	if !ok {
+		return nil
+	}
+	st := sterr.StackTrace()
+	s := &state{}
+	out := make([]map[string]string, 0, len(st))
+	for _, frame := range st {
+		out = append(out, map[string]string{
+			StackSourceFileName:     frameField(frame, s, 's'),
+			StackSourceLineName:     frameField(frame, s, 'd'),
+			StackSourceFunctionName: frameField(frame, s, 'n'),
+		})
+	}
+	return out
+}

pkgerrors/stacktrace_test.go

@@ -0,0 +1,57 @@
+// +build !binary_log
+
+package pkgerrors
+
+import (
+	"bytes"
+	"regexp"
+	"testing"
+
+	"github.com/pkg/errors"
+	"github.com/rs/zerolog"
+)
+
+func TestLogStack(t *testing.T) {
+	zerolog.ErrorStackMarshaler = MarshalStack
+
+	out := &bytes.Buffer{}
+	log := zerolog.New(out)
+
+	err := errors.Wrap(errors.New("error message"), "from error")
+	log.Log().Stack().Err(err).Msg("")
+
+	got := out.String()
+	want := `\{"stack":\[\{"func":"TestLogStack","line":"20","source":"stacktrace_test.go"\},.*\],"error":"from error: error message"\}\n`
+	if ok, _ := regexp.MatchString(want, got); !ok {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+}
+
+func TestLogStackFromContext(t *testing.T) {
+	zerolog.ErrorStackMarshaler = MarshalStack
+
+	out := &bytes.Buffer{}
+	log := zerolog.New(out).With().Stack().Logger() // calling Stack() on log context instead of event
+
+	err := errors.Wrap(errors.New("error message"), "from error")
+	log.Log().Err(err).Msg("") // not explicitly calling Stack()
+
+	got := out.String()
+	want := `\{"stack":\[\{"func":"TestLogStackFromContext","line":"36","source":"stacktrace_test.go"\},.*\],"error":"from error: error message"\}\n`
+	if ok, _ := regexp.MatchString(want, got); !ok {
+		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
+	}
+}
+
+func BenchmarkLogStack(b *testing.B) {
+	zerolog.ErrorStackMarshaler = MarshalStack
+	out := &bytes.Buffer{}
+	log := zerolog.New(out)
+	err := errors.Wrap(errors.New("error message"), "from error")
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		log.Log().Stack().Err(err).Msg("")
+		out.Reset()
+	}
+}

sampler.go

@@ -46,8 +46,12 @@ type BasicSampler struct {
 
 // Sample implements the Sampler interface.
 func (s *BasicSampler) Sample(lvl Level) bool {
+	n := s.N
+	if n == 1 {
+		return true
+	}
 	c := atomic.AddUint32(&s.counter, 1)
-	return c%s.N == 0
+	return c%n == 1
 }
 
 // BurstSampler lets Burst events pass per Period then pass the decision to
@@ -100,11 +104,15 @@ func (s *BurstSampler) inc() uint32 {
 
 // LevelSampler applies a different sampler for each level.
 type LevelSampler struct {
-	DebugSampler, InfoSampler, WarnSampler, ErrorSampler Sampler
+	TraceSampler, DebugSampler, InfoSampler, WarnSampler, ErrorSampler Sampler
 }
 
 func (s LevelSampler) Sample(lvl Level) bool {
 	switch lvl {
+	case TraceLevel:
+		if s.TraceSampler != nil {
+			return s.TraceSampler.Sample(lvl)
+		}
 	case DebugLevel:
 		if s.DebugSampler != nil {
 			return s.DebugSampler.Sample(lvl)

sampler_test.go

@@ -15,7 +15,14 @@ var samplers = []struct {
 	wantMax int
 }{
 	{
-		"BasicSampler",
+		"BasicSampler_1",
+		func() Sampler {
+			return &BasicSampler{N: 1}
+		},
+		100, 100, 100,
+	},
+	{
+		"BasicSampler_5",
 		func() Sampler {
 			return &BasicSampler{N: 5}
 		},

syslog.go

@@ -7,6 +7,10 @@ import (
 	"io"
 )
 
+// See http://cee.mitre.org/language/1.0-beta1/clt.html#syslog
+// or https://www.rsyslog.com/json-elasticsearch/
+const ceePrefix = "@cee:"
+
 // SyslogWriter is an interface matching a syslog.Writer struct.
 type SyslogWriter interface {
 	io.Writer
@@ -19,39 +23,58 @@ type SyslogWriter interface {
 }
 
 type syslogWriter struct {
-	w SyslogWriter
+	w      SyslogWriter
+	prefix string
 }
 
 // SyslogLevelWriter wraps a SyslogWriter and call the right syslog level
 // method matching the zerolog level.
 func SyslogLevelWriter(w SyslogWriter) LevelWriter {
-	return syslogWriter{w}
+	return syslogWriter{w, ""}
+}
+
+// SyslogCEEWriter wraps a SyslogWriter with a SyslogLevelWriter that adds a
+// MITRE CEE prefix for JSON syslog entries, compatible with rsyslog 
+// and syslog-ng JSON logging support. 
+// See https://www.rsyslog.com/json-elasticsearch/
+func SyslogCEEWriter(w SyslogWriter) LevelWriter {
+	return syslogWriter{w, ceePrefix}
 }
 
 func (sw syslogWriter) Write(p []byte) (n int, err error) {
-	return sw.w.Write(p)
+	var pn int
+	if sw.prefix != "" {
+		pn, err = sw.w.Write([]byte(sw.prefix))
+		if err != nil {
+			return pn, err
+		}
+	}
+	n, err = sw.w.Write(p)
+	return pn + n, err
 }
 
 // WriteLevel implements LevelWriter interface.
 func (sw syslogWriter) WriteLevel(level Level, p []byte) (n int, err error) {
 	switch level {
+	case TraceLevel:
 	case DebugLevel:
-		err = sw.w.Debug(string(p))
+		err = sw.w.Debug(sw.prefix + string(p))
 	case InfoLevel:
-		err = sw.w.Info(string(p))
+		err = sw.w.Info(sw.prefix + string(p))
 	case WarnLevel:
-		err = sw.w.Warning(string(p))
+		err = sw.w.Warning(sw.prefix + string(p))
 	case ErrorLevel:
-		err = sw.w.Err(string(p))
+		err = sw.w.Err(sw.prefix + string(p))
 	case FatalLevel:
-		err = sw.w.Emerg(string(p))
+		err = sw.w.Emerg(sw.prefix + string(p))
 	case PanicLevel:
-		err = sw.w.Crit(string(p))
+		err = sw.w.Crit(sw.prefix + string(p))
 	case NoLevel:
-		err = sw.w.Info(string(p))
+		err = sw.w.Info(sw.prefix + string(p))
 	default:
 		panic("invalid level")
 	}
+	// Any CEE prefix is not part of the message, so we don't include its length
 	n = len(p)
 	return
 }

syslog_test.go

@@ -3,8 +3,12 @@
 
 package zerolog
 
-import "testing"
-import "reflect"
+import (
+	"bytes"
+	"reflect"
+	"strings"
+	"testing"
+)
 
 type syslogEvent struct {
 	level string
@@ -17,6 +21,10 @@ type syslogTestWriter struct {
 func (w *syslogTestWriter) Write(p []byte) (int, error) {
 	return 0, nil
 }
+func (w *syslogTestWriter) Trace(m string) error {
+	w.events = append(w.events, syslogEvent{"Trace", m})
+	return nil
+}
 func (w *syslogTestWriter) Debug(m string) error {
 	w.events = append(w.events, syslogEvent{"Debug", m})
 	return nil
@@ -45,6 +53,7 @@ func (w *syslogTestWriter) Crit(m string) error {
 func TestSyslogWriter(t *testing.T) {
 	sw := &syslogTestWriter{}
 	log := New(SyslogLevelWriter(sw))
+	log.Trace().Msg("trace")
 	log.Debug().Msg("debug")
 	log.Info().Msg("info")
 	log.Warn().Msg("warn")
@@ -61,3 +70,39 @@ func TestSyslogWriter(t *testing.T) {
 		t.Errorf("Invalid syslog message routing: want %v, got %v", want, got)
 	}
 }
+
+type testCEEwriter struct {
+	buf *bytes.Buffer
+}
+
+// Only implement one method as we're just testing the prefixing
+func (c testCEEwriter) Debug(m string) error { return nil }
+
+func (c testCEEwriter) Info(m string) error {
+	_, err := c.buf.Write([]byte(m))
+	return err
+}
+
+func (c testCEEwriter) Warning(m string) error { return nil }
+
+func (c testCEEwriter) Err(m string) error { return nil }
+
+func (c testCEEwriter) Emerg(m string) error { return nil }
+
+func (c testCEEwriter) Crit(m string) error { return nil }
+
+func (c testCEEwriter) Write(b []byte) (int, error) {
+	return c.buf.Write(b)
+}
+
+func TestSyslogWriter_WithCEE(t *testing.T) {
+	var buf bytes.Buffer
+	sw := testCEEwriter{&buf}
+	log := New(SyslogCEEWriter(sw))
+	log.Info().Str("key", "value").Msg("message string")
+	got := string(buf.Bytes())
+	want := "@cee:{"
+	if !strings.HasPrefix(got, want) {
+		t.Errorf("Bad CEE message start: want %v, got %v", want, got)
+	}
+}

writer.go

@@ -26,11 +26,9 @@ type syncWriter struct {
 }
 
 // SyncWriter wraps w so that each call to Write is synchronized with a mutex.
-// This syncer can be the call to writer's Write method is not thread safe.
-// Note that os.File Write operation is using write() syscall which is supposed
-// to be thread-safe on POSIX systems. So there is no need to use this with
-// os.File on such systems as zerolog guaranties to issue a single Write call
-// per log event.
+// This syncer can be used to wrap the call to writer's Write method if it is
+// not thread safe. Note that you do not need this wrapper for os.File Write
+// operations on POSIX and Windows systems as they are already thread-safe.
 func SyncWriter(w io.Writer) io.Writer {
 	if lw, ok := w.(LevelWriter); ok {
 		return &syncWriter{lw: lw}
@@ -58,30 +56,30 @@ type multiLevelWriter struct {
 
 func (t multiLevelWriter) Write(p []byte) (n int, err error) {
 	for _, w := range t.writers {
-		n, err = w.Write(p)
-		if err != nil {
-			return
-		}
-		if n != len(p) {
-			err = io.ErrShortWrite
-			return
+		if _n, _err := w.Write(p); err == nil {
+			n = _n
+			if _err != nil {
+				err = _err
+			} else if _n != len(p) {
+				err = io.ErrShortWrite
+			}
 		}
 	}
-	return len(p), nil
+	return n, err
 }
 
 func (t multiLevelWriter) WriteLevel(l Level, p []byte) (n int, err error) {
 	for _, w := range t.writers {
-		n, err = w.WriteLevel(l, p)
-		if err != nil {
-			return
-		}
-		if n != len(p) {
-			err = io.ErrShortWrite
-			return
+		if _n, _err := w.WriteLevel(l, p); err == nil {
+			n = _n
+			if _err != nil {
+				err = _err
+			} else if _n != len(p) {
+				err = io.ErrShortWrite
+			}
 		}
 	}
-	return len(p), nil
+	return n, err
 }
 
 // MultiLevelWriter creates a writer that duplicates its writes to all the

writer_test.go

@@ -4,6 +4,8 @@
 package zerolog
 
 import (
+	"errors"
+	"io"
 	"reflect"
 	"testing"
 )
@@ -27,3 +29,85 @@ func TestMultiSyslogWriter(t *testing.T) {
 		t.Errorf("Invalid syslog message routing: want %v, got %v", want, got)
 	}
 }
+
+var writeCalls int
+
+type mockedWriter struct {
+	wantErr bool
+}
+
+func (c mockedWriter) Write(p []byte) (int, error) {
+	writeCalls++
+
+	if c.wantErr {
+		return -1, errors.New("Expected error")
+	}
+
+	return len(p), nil
+}
+
+// Tests that a new writer is only used if it actually works.
+func TestResilientMultiWriter(t *testing.T) {
+	tests := []struct {
+		name    string
+		writers []io.Writer
+	}{
+		{
+			name:    "All valid writers",
+			writers: []io.Writer{
+				mockedWriter {
+					wantErr: false,
+				},
+				mockedWriter {
+					wantErr: false,
+				},
+			},
+		},
+		{
+			name:    "All invalid writers",
+			writers: []io.Writer{
+				mockedWriter {
+					wantErr: true,
+				},
+				mockedWriter {
+					wantErr: true,
+				},
+			},
+		},
+		{
+			name:    "First invalid writer",
+			writers: []io.Writer{
+				mockedWriter {
+					wantErr: true,
+				},
+				mockedWriter {
+					wantErr: false,
+				},
+			},
+		},
+		{
+			name:    "First valid writer",
+			writers: []io.Writer{
+				mockedWriter {
+					wantErr: false,
+				},
+				mockedWriter {
+					wantErr: true,
+				},
+			},
+		},
+	}
+
+	for _, tt := range tests {
+		writers := tt.writers
+		multiWriter := MultiLevelWriter(writers...)
+
+		logger := New(multiWriter).With().Timestamp().Logger().Level(InfoLevel)
+		logger.Info().Msg("Test msg")
+
+		if len(writers) != writeCalls {
+			t.Errorf("Expected %d writers to have been called but only %d were.", len(writers), writeCalls)
+		}
+		writeCalls = 0
+	}
+}