Refactored zerolog.ConsoleWriter to allow customization (#92)

* Added a simple benchmarking test for the ConsoleWriter
* Refactored `zerolog.ConsoleWriter` to allow customization

Closes #84
This commit is contained in:
Karel Minarik 2018-11-05 02:15:13 -08:00 committed by Olivier Poitrey
parent 51c79ca476
commit 96f91bb4f5
5 changed files with 560 additions and 113 deletions

1
.gitignore vendored
View File

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

View File

@ -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)
@ -252,14 +252,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.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

View File

@ -5,6 +5,7 @@ import (
"encoding/json"
"fmt"
"io"
"os"
"sort"
"strconv"
"strings"
@ -13,133 +14,260 @@ import (
)
const (
cReset = 0
cBold = 1
cRed = 31
cGreen = 32
cYellow = 33
cBlue = 34
cMagenta = 35
cCyan = 36
cGray = 37
cDarkGray = 90
colorBold = iota + 1
colorFaint
)
var consoleBufPool = sync.Pool{
const (
colorBlack = iota + 30
colorRed
colorGreen
colorYellow
colorBlue
colorMagenta
colorCyan
colorWhite
)
var (
consoleBufPool = sync.Pool{
New: func() interface{} {
return bytes.NewBuffer(make([]byte, 0, 100))
},
}
// LevelWidth defines the desired character width of the log level column.
// Default 0 does not trim or pad (variable width based level text, e.g. "INFO" or "ERROR")
var LevelWidth = 0
// ConsoleWriter reads a JSON object per write operation and output an
// optionally colored human readable version on the Out writer.
type ConsoleWriter struct {
Out io.Writer
NoColor bool
consoleDefaultTimeFormat = time.Kitchen
consoleDefaultFormatter = func(i interface{}) string { return fmt.Sprintf("%s", i) }
consoleDefaultPartsOrder = []string{
TimestampFieldName,
LevelFieldName,
CallerFieldName,
MessageFieldName,
}
consoleNoColor = false
consoleTimeFormat = consoleDefaultTimeFormat
)
// 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 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
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
}
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)
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)
for _, p := range w.PartsOrder {
w.writePart(buf, evt, p)
}
level = strings.ToUpper(l)
if LevelWidth > 0 {
if padding := LevelWidth - len(level); padding > 0 {
level += strings.Repeat(" ", padding)
} else {
level = level[0:LevelWidth]
w.writeFields(evt, buf)
buf.WriteByte('\n')
buf.WriteTo(w.Out)
return len(p), nil
}
}
}
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 {
// 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)
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 {
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 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
} else {
buf.WriteString(value)
fn = w.FormatErrFieldName
}
if w.FormatErrFieldValue == nil {
fv = consoleDefaultFormatErrFieldValue
} else {
fv = w.FormatErrFieldValue
}
} else {
if w.FormatFieldName == nil {
fn = consoleDefaultFormatFieldName
} 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))
}
}
}
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)
if i < len(fields)-1 { // Skip space for last field
buf.WriteByte(' ')
}
}
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)
}
// writePart appends a formatted part to buf.
func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{}, p string) {
var f Formatter
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
} else {
f = w.FormatLevel
}
case TimestampFieldName:
if w.FormatTimestamp == nil {
f = consoleDefaultFormatTimestamp
} else {
f = w.FormatTimestamp
}
case MessageFieldName:
if w.FormatMessage == nil {
f = consoleDefaultFormatMessage
} else {
f = w.FormatMessage
}
case CallerFieldName:
if w.FormatCaller == nil {
f = consoleDefaultFormatCaller
} 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] == '"' {
@ -148,3 +276,89 @@ 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 ---------------------------------------------------
var (
consoleDefaultFormatTimestamp = func(i interface{}) string {
t := "<nil>"
if tt, ok := i.(string); ok {
ts, err := time.Parse(time.RFC3339, tt)
if err != nil {
t = tt
} else {
t = ts.Format(consoleTimeFormat)
}
}
return colorize(t, colorFaint, consoleNoColor)
}
consoleDefaultFormatLevel = func(i interface{}) string {
var l string
if ll, ok := i.(string); ok {
switch ll {
case "debug":
l = colorize("DBG", colorYellow, consoleNoColor)
case "info":
l = colorize("INF", colorGreen, consoleNoColor)
case "warn":
l = colorize("WRN", colorRed, consoleNoColor)
case "error":
l = colorize(colorize("ERR", colorRed, consoleNoColor), colorBold, consoleNoColor)
case "fatal":
l = colorize(colorize("FTL", colorRed, consoleNoColor), colorBold, consoleNoColor)
case "panic":
l = colorize(colorize("PNC", colorRed, consoleNoColor), colorBold, consoleNoColor)
default:
l = colorize("???", colorBold, consoleNoColor)
}
} else {
l = strings.ToUpper(fmt.Sprintf("%s", i))[0:3]
}
return l
}
consoleDefaultFormatCaller = func(i interface{}) string {
var c string
if cc, ok := i.(string); ok {
c = cc
}
if len(c) > 0 {
cwd, err := os.Getwd()
if err == nil {
c = strings.TrimPrefix(c, cwd)
c = strings.TrimPrefix(c, "/")
}
c = colorize(c, colorBold, consoleNoColor) + colorize(" >", colorFaint, consoleNoColor)
}
return c
}
consoleDefaultFormatMessage = func(i interface{}) string {
return fmt.Sprintf("%s", i)
}
consoleDefaultFormatFieldName = func(i interface{}) string {
return colorize(fmt.Sprintf("%s=", i), colorFaint, consoleNoColor)
}
consoleDefaultFormatFieldValue = func(i interface{}) string {
return fmt.Sprintf("%s", i)
}
consoleDefaultFormatErrFieldName = func(i interface{}) string {
return colorize(fmt.Sprintf("%s=", i), colorRed, consoleNoColor)
}
consoleDefaultFormatErrFieldValue = func(i interface{}) string {
return colorize(fmt.Sprintf("%s", i), colorRed, consoleNoColor)
}
)

View File

@ -2,21 +2,62 @@ 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) {
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().
@ -24,7 +65,174 @@ func TestConsoleWriterNumbers(t *testing.T) {
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 {
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[2m<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("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)
}
})
}
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)
}
}

Binary file not shown.

Before

Width:  |  Height:  |  Size: 377 KiB

After

Width:  |  Height:  |  Size: 141 KiB