diff --git a/.gitignore b/.gitignore index daf913b..8ebe58b 100644 --- a/.gitignore +++ b/.gitignore @@ -6,6 +6,7 @@ # Folders _obj _test +tmp # Architecture specific extensions/prefixes *.[568vq] diff --git a/README.md b/README.md index 91c75f0..6241b59 100644 --- a/README.md +++ b/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) @@ -60,7 +60,7 @@ func main() { // Output: {"time":1516134303,"level":"debug","message":"hello world"} ``` -> Note: By default log writes to `os.Stderr` +> Note: By default log writes to `os.Stderr` > Note: The default log level for `log.Print` is *debug* ### Contextual Logging @@ -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.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 diff --git a/console.go b/console.go index 98de5d7..95bfd27 100644 --- a/console.go +++ b/console.go @@ -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{ - New: func() interface{} { - return bytes.NewBuffer(make([]byte, 0, 100)) - }, -} +const ( + colorBlack = iota + 30 + colorRed + colorGreen + colorYellow + colorBlue + colorMagenta + colorCyan + colorWhite +) -// 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 +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. + 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 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 + + 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) - } - level = strings.ToUpper(l) - if LevelWidth > 0 { - if padding := LevelWidth - len(level); padding > 0 { - level += strings.Repeat(" ", padding) - } else { - level = level[0:LevelWidth] - } - } + + 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) + + buf.WriteByte('\n') + buf.WriteTo(w.Out) + return len(p), nil +} + +// 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)) - } else { - buf.WriteString(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 } - case json.Number: - fmt.Fprint(buf, value) - default: - b, err := json.Marshal(value) - if err != nil { - fmt.Fprintf(buf, "[error: %v]", err) + 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 { - fmt.Fprint(buf, string(b)) + 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: + buf.WriteString(fv(fValue)) + default: + b, err := json.Marshal(fValue) + if err != nil { + fmt.Fprintf(buf, colorize("[error: %v]", colorRed, w.NoColor), err) + } else { + fmt.Fprint(buf, fv(b)) + } + } + + if i < len(fields)-1 { // Skip space for last field + buf.WriteByte(' ') + } } - 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 "" -} +// writePart appends a formatted part to buf. +func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{}, p string) { + var f Formatter -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 + } 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 := "" + 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) + } +) diff --git a/console_test.go b/console_test.go index a6e7e06..5bdfdaa 100644 --- a/console_test.go +++ b/console_test.go @@ -2,29 +2,237 @@ 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: |INFO| hello world + log.Info().Str("foo", "bar").Msg("Hello World") + // Output: 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()), " |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: 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: 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: [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()), " 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\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 := " 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) } } diff --git a/pretty.png b/pretty.png index c181164..34e4308 100644 Binary files a/pretty.png and b/pretty.png differ