pkgerrors: quick refactoring for better readibility

Alternative approach to #118: fix the race condition by replacing the package-level customization settings with curried functions.

README.md

@@ -479,6 +479,7 @@ Some settings can be changed and will by applied to all loggers:
     // 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.
+* `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
 

console.go

@@ -35,20 +35,10 @@ var (
 			return bytes.NewBuffer(make([]byte, 0, 100))
 		},
 	}
+)
 
+const (
 	consoleDefaultTimeFormat = time.Kitchen
-	consoleDefaultFormatter  = func(i interface{}) string { return fmt.Sprintf("%s", i) }
-	consoleDefaultPartsOrder = func() []string {
-		return []string{
-			TimestampFieldName,
-			LevelFieldName,
-			CallerFieldName,
-			MessageFieldName,
-		}
-	}
-
-	consoleNoColor    = false
-	consoleTimeFormat = consoleDefaultTimeFormat
 )
 
 // Formatter transforms the input into a formatted string.
@@ -99,21 +89,12 @@ func (w ConsoleWriter) Write(p []byte) (n int, err error) {
 	if w.PartsOrder == nil {
 		w.PartsOrder = consoleDefaultPartsOrder()
 	}
-	if w.TimeFormat == "" && consoleTimeFormat != consoleDefaultTimeFormat {
-		consoleTimeFormat = consoleDefaultTimeFormat
-	}
-	if w.TimeFormat != "" && consoleTimeFormat != w.TimeFormat {
-		consoleTimeFormat = w.TimeFormat
-	}
-	if w.NoColor == false && consoleNoColor != false {
-		consoleNoColor = false
-	}
-	if w.NoColor == true && consoleNoColor != w.NoColor {
-		consoleNoColor = w.NoColor
-	}
 
 	var buf = consoleBufPool.Get().(*bytes.Buffer)
-	defer consoleBufPool.Put(buf)
+	defer func() {
+		buf.Reset()
+		consoleBufPool.Put(buf)
+	}()
 
 	var evt map[string]interface{}
 	p = decodeIfBinaryToBytes(p)
@@ -130,9 +111,12 @@ func (w ConsoleWriter) Write(p []byte) (n int, err error) {
 
 	w.writeFields(evt, buf)
 
-	buf.WriteByte('\n')
-	buf.WriteTo(w.Out)
-	return len(p), nil
+	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.
@@ -172,19 +156,19 @@ func (w ConsoleWriter) writeFields(evt map[string]interface{}, buf *bytes.Buffer
 
 		if field == ErrorFieldName {
 			if w.FormatErrFieldName == nil {
-				fn = consoleDefaultFormatErrFieldName
+				fn = consoleDefaultFormatErrFieldName(w.NoColor)
 			} else {
 				fn = w.FormatErrFieldName
 			}
 
 			if w.FormatErrFieldValue == nil {
-				fv = consoleDefaultFormatErrFieldValue
+				fv = consoleDefaultFormatErrFieldValue(w.NoColor)
 			} else {
 				fv = w.FormatErrFieldValue
 			}
 		} else {
 			if w.FormatFieldName == nil {
-				fn = consoleDefaultFormatFieldName
+				fn = consoleDefaultFormatFieldName(w.NoColor)
 			} else {
 				fn = w.FormatFieldName
 			}
@@ -229,13 +213,13 @@ func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{},
 	switch p {
 	case LevelFieldName:
 		if w.FormatLevel == nil {
-			f = consoleDefaultFormatLevel
+			f = consoleDefaultFormatLevel(w.NoColor)
 		} else {
 			f = w.FormatLevel
 		}
 	case TimestampFieldName:
 		if w.FormatTimestamp == nil {
-			f = consoleDefaultFormatTimestamp
+			f = consoleDefaultFormatTimestamp(w.TimeFormat, w.NoColor)
 		} else {
 			f = w.FormatTimestamp
 		}
@@ -247,7 +231,7 @@ func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{},
 		}
 	case CallerFieldName:
 		if w.FormatCaller == nil {
-			f = consoleDefaultFormatCaller
+			f = consoleDefaultFormatCaller(w.NoColor)
 		} else {
 			f = w.FormatCaller
 		}
@@ -289,46 +273,65 @@ func colorize(s interface{}, c int, disabled bool) string {
 
 // ----- DEFAULT FORMATTERS ---------------------------------------------------
 
-var (
-	consoleDefaultFormatTimestamp = func(i interface{}) string {
+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>"
-		if tt, ok := i.(string); ok {
-			ts, err := time.Parse(time.RFC3339, tt)
+		switch tt := i.(type) {
+		case string:
+			ts, err := time.Parse(TimeFieldFormat, tt)
 			if err != nil {
 				t = tt
 			} else {
-				t = ts.Format(consoleTimeFormat)
+				t = ts.Format(timeFormat)
 			}
+		case json.Number:
+			t = tt.String()
 		}
-		return colorize(t, colorFaint, consoleNoColor)
+		return colorize(t, colorFaint, noColor)
 	}
+}
 
-	consoleDefaultFormatLevel = func(i interface{}) string {
+func consoleDefaultFormatLevel(noColor bool) Formatter {
+	return func(i interface{}) string {
 		var l string
 		if ll, ok := i.(string); ok {
 			switch ll {
 			case "debug":
-				l = colorize("DBG", colorYellow, consoleNoColor)
+				l = colorize("DBG", colorYellow, noColor)
 			case "info":
-				l = colorize("INF", colorGreen, consoleNoColor)
+				l = colorize("INF", colorGreen, noColor)
 			case "warn":
-				l = colorize("WRN", colorRed, consoleNoColor)
+				l = colorize("WRN", colorRed, noColor)
 			case "error":
-				l = colorize(colorize("ERR", colorRed, consoleNoColor), colorBold, consoleNoColor)
+				l = colorize(colorize("ERR", colorRed, noColor), colorBold, noColor)
 			case "fatal":
-				l = colorize(colorize("FTL", colorRed, consoleNoColor), colorBold, consoleNoColor)
+				l = colorize(colorize("FTL", colorRed, noColor), colorBold, noColor)
 			case "panic":
-				l = colorize(colorize("PNC", colorRed, consoleNoColor), colorBold, consoleNoColor)
+				l = colorize(colorize("PNC", colorRed, noColor), colorBold, noColor)
 			default:
-				l = colorize("???", colorBold, consoleNoColor)
+				l = colorize("???", colorBold, noColor)
 			}
 		} else {
 			l = strings.ToUpper(fmt.Sprintf("%s", i))[0:3]
 		}
 		return l
 	}
+}
 
-	consoleDefaultFormatCaller = func(i interface{}) string {
+func consoleDefaultFormatCaller(noColor bool) Formatter {
+	return func(i interface{}) string {
 		var c string
 		if cc, ok := i.(string); ok {
 			c = cc
@@ -339,28 +342,34 @@ var (
 				c = strings.TrimPrefix(c, cwd)
 				c = strings.TrimPrefix(c, "/")
 			}
-			c = colorize(c, colorBold, consoleNoColor) + colorize(" >", colorFaint, consoleNoColor)
+			c = colorize(c, colorBold, noColor) + colorize(" >", colorFaint, noColor)
 		}
 		return c
 	}
+}
 
-	consoleDefaultFormatMessage = func(i interface{}) string {
-		return fmt.Sprintf("%s", i)
-	}
+func consoleDefaultFormatMessage(i interface{}) string {
+	return fmt.Sprintf("%s", i)
+}
 
-	consoleDefaultFormatFieldName = func(i interface{}) string {
-		return colorize(fmt.Sprintf("%s=", i), colorFaint, consoleNoColor)
+func consoleDefaultFormatFieldName(noColor bool) Formatter {
+	return func(i interface{}) string {
+		return colorize(fmt.Sprintf("%s=", i), colorFaint, noColor)
 	}
+}
 
-	consoleDefaultFormatFieldValue = func(i interface{}) string {
-		return fmt.Sprintf("%s", i)
-	}
+func consoleDefaultFormatFieldValue(i interface{}) string {
+	return fmt.Sprintf("%s", i)
+}
 
-	consoleDefaultFormatErrFieldName = func(i interface{}) string {
-		return colorize(fmt.Sprintf("%s=", i), colorRed, consoleNoColor)
+func consoleDefaultFormatErrFieldName(noColor bool) Formatter {
+	return func(i interface{}) string {
+		return colorize(fmt.Sprintf("%s=", i), colorRed, noColor)
 	}
+}
 
-	consoleDefaultFormatErrFieldValue = func(i interface{}) string {
-		return colorize(fmt.Sprintf("%s", i), colorRed, consoleNoColor)
+func consoleDefaultFormatErrFieldValue(noColor bool) Formatter {
+	return func(i interface{}) string {
+		return colorize(fmt.Sprintf("%s", i), colorRed, noColor)
 	}
-)
+}

context.go

@@ -362,6 +362,20 @@ func (c Context) Caller() Context {
 	return c
 }
 
+type stackTraceHook struct{}
+
+func (sh stackTraceHook) Run(e *Event, level Level, msg string) {
+	e.Stack()
+}
+
+var sh = stackTraceHook{}
+
+// Stack enables stack trace printing for the error passed to Err().
+func (c Context) Stack() Context {
+	c.l = c.l.Hook(sh)
+	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)

event.go

@@ -18,11 +18,6 @@ var eventPool = &sync.Pool{
 	},
 }
 
-// ErrorMarshalFunc allows customization of global error marshaling
-var ErrorMarshalFunc = func(err error) interface{} {
-	return err
-}
-
 // 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 {
@@ -30,6 +25,7 @@ type Event struct {
 	w     LevelWriter
 	level Level
 	done  func(msg string)
+	stack bool   // enable error stack trace
 	ch    []Hook // hooks from context
 }
 
@@ -137,8 +133,11 @@ func (e *Event) msg(msg string) {
 		defer e.done(msg)
 	}
 	if err := e.write(); err != nil {
-		fmt.Fprintf(os.Stderr,
-			`{"%s": "zerolog: could not write event: %v"}\n`, MessageFieldName, err)
+		if ErrorHandler != nil {
+			ErrorHandler(err)
+		} else {
+			fmt.Fprintf(os.Stderr, "zerolog: could not write event: %v\n", err)
+		}
 	}
 }
 
@@ -268,8 +267,10 @@ func (e *Event) RawJSON(key string, b []byte) *Event {
 // 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 {
-	marshaled := ErrorMarshalFunc(err)
-	switch m := marshaled.(type) {
+	if e == nil {
+		return e
+	}
+	switch m := ErrorMarshalFunc(err).(type) {
 	case nil:
 		return e
 	case LogObjectMarshaler:
@@ -289,11 +290,9 @@ func (e *Event) Errs(key string, errs []error) *Event {
 	if e == nil {
 		return e
 	}
-
 	arr := Arr()
 	for _, err := range errs {
-		marshaled := ErrorMarshalFunc(err)
-		switch m := marshaled.(type) {
+		switch m := ErrorMarshalFunc(err).(type) {
 		case LogObjectMarshaler:
 			arr = arr.Object(m)
 		case error:
@@ -311,10 +310,42 @@ func (e *Event) Errs(key string, errs []error) *Event {
 // 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.
+//
+// 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 e.stack && ErrorStackMarshaler != nil {
+		switch m := ErrorStackMarshaler(err).(type) {
+		case nil:
+		case LogObjectMarshaler:
+			e.Object(ErrorStackFieldName, m)
+		case error:
+			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
+}
+
 // Bool adds the field key with val as a bool to the *Event context.
 func (e *Event) Bool(key string, b bool) *Event {
 	if e == nil {

globals.go

@@ -22,6 +22,17 @@ var (
 	// CallerSkipFrameCount is the number of stack frames to skip to find the caller.
 	CallerSkipFrameCount = 2
 
+	// 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 an empty string, the time is formatted as an UNIX timestamp
 	// as integer.
@@ -37,6 +48,11 @@ 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 (

log_test.go

@@ -640,3 +640,24 @@ func TestErrorMarshalFunc(t *testing.T) {
 		t.Errorf("invalid log output:\ngot:  %v\nwant: %v", got, want)
 	}
 }
+
+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)
+	}
+}

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,41 @@
+// +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 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()
+	}
+}