diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 816f1646..a9725b3d 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -4,17 +4,17 @@ jobs: test: strategy: matrix: - go-version: [1.18.x, 1.19.x] + go-version: [1.18.x, 1.21.x] os: [ubuntu-latest, macos-latest] runs-on: ${{ matrix.os }} steps: - name: Install Go - uses: actions/setup-go@v4 + uses: actions/setup-go@v5 with: go-version: ${{ matrix.go-version }} - name: Checkout code - uses: actions/checkout@v3 - - uses: actions/cache@v3 + uses: actions/checkout@v4 + - uses: actions/cache@v4 with: path: ~/go/pkg/mod key: ${{ runner.os }}-go-${{ hashFiles('**/go.sum') }} @@ -24,4 +24,13 @@ jobs: run: go test -race -bench . -benchmem ./... - name: Test CBOR run: go test -tags binary_log ./... - + coverage: + runs-on: ubuntu-latest + steps: + - name: Update coverage report + uses: ncruces/go-coverage-report@main + with: + report: 'true' + chart: 'true' + amend: 'true' + continue-on-error: true diff --git a/README.md b/README.md index 68df81ef..1306a6c1 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,6 @@ # Zero Allocation JSON Logger -[![godoc](http://img.shields.io/badge/godoc-reference-blue.svg?style=flat)](https://godoc.org/github.com/rs/zerolog) [![license](http://img.shields.io/badge/license-MIT-red.svg?style=flat)](https://raw.githubusercontent.com/rs/zerolog/master/LICENSE) [![Build Status](https://travis-ci.org/rs/zerolog.svg?branch=master)](https://travis-ci.org/rs/zerolog) [![Coverage](http://gocover.io/_badge/github.com/rs/zerolog)](http://gocover.io/github.com/rs/zerolog) +[![godoc](http://img.shields.io/badge/godoc-reference-blue.svg?style=flat)](https://godoc.org/github.com/rs/zerolog) [![license](http://img.shields.io/badge/license-MIT-red.svg?style=flat)](https://raw.githubusercontent.com/rs/zerolog/master/LICENSE) [![Build Status](https://github.com/rs/zerolog/actions/workflows/test.yml/badge.svg)](https://github.com/rs/zerolog/actions/workflows/test.yml) [![Go Coverage](https://github.com/rs/zerolog/wiki/coverage.svg)](https://raw.githack.com/wiki/rs/zerolog/coverage.html) The zerolog package provides a fast and simple logger dedicated to JSON output. @@ -60,7 +60,7 @@ func main() { // 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* +> Note: The default log level for `log.Print` is *trace* ### Contextual Logging @@ -412,15 +412,7 @@ Equivalent of `Lshortfile`: ```go zerolog.CallerMarshalFunc = func(pc uintptr, file string, line int) string { - short := file - for i := len(file) - 1; i > 0; i-- { - if file[i] == '/' { - short = file[i+1:] - break - } - } - file = short - return file + ":" + strconv.Itoa(line) + return filepath.Base(file) + ":" + strconv.Itoa(line) } log.Logger = log.With().Caller().Logger() log.Info().Msg("hello world") @@ -513,25 +505,53 @@ stdlog.Print("hello world") ### context.Context integration -The `Logger` instance could be attached to `context.Context` values with `logger.WithContext(ctx)` -and extracted from it using `zerolog.Ctx(ctx)`. +Go contexts are commonly passed throughout Go code, and this can help you pass +your Logger into places it might otherwise be hard to inject. The `Logger` +instance may be attached to Go context (`context.Context`) using +`Logger.WithContext(ctx)` and extracted from it using `zerolog.Ctx(ctx)`. +For example: -Example to add logger to context: ```go -// this code attach logger instance to context fields -ctx := context.Background() -logger := zerolog.New(os.Stdout) -ctx = logger.WithContext(ctx) -someFunc(ctx) +func f() { + logger := zerolog.New(os.Stdout) + ctx := context.Background() + + // Attach the Logger to the context.Context + ctx = logger.WithContext(ctx) + someFunc(ctx) +} + +func someFunc(ctx context.Context) { + // Get Logger from the go Context. if it's nil, then + // `zerolog.DefaultContextLogger` is returned, if + // `DefaultContextLogger` is nil, then a disabled logger is returned. + logger := zerolog.Ctx(ctx) + logger.Info().Msg("Hello") +} ``` -Extracting logger from context: +A second form of `context.Context` integration allows you to pass the current +context.Context into the logged event, and retrieve it from hooks. This can be +useful to log trace and span IDs or other information stored in the go context, +and facilitates the unification of logging and tracing in some systems: + ```go -func someFunc(ctx context.Context) { - // get logger from context. if it's nill, then `zerolog.DefaultContextLogger` is returned, - // if `DefaultContextLogger` is nil, then disabled logger returned. - logger := zerolog.Ctx(ctx) - logger.Info().Msg("Hello") +type TracingHook struct{} + +func (h TracingHook) Run(e *zerolog.Event, level zerolog.Level, msg string) { + ctx := e.GetCtx() + spanId := getSpanIdFromContext(ctx) // as per your tracing framework + e.Str("span-id", spanId) +} + +func f() { + // Setup the logger + logger := zerolog.New(os.Stdout) + logger = logger.Hook(TracingHook{}) + + ctx := context.Background() + // Use the Ctx function to make the context available to the hook + logger.Info().Ctx(ctx).Msg("Hello") } ``` @@ -618,10 +638,14 @@ Some settings can be changed and will be applied to all loggers: * `zerolog.LevelFieldName`: Can be set to customize level field name. * `zerolog.MessageFieldName`: Can be set to customize message field name. * `zerolog.ErrorFieldName`: Can be set to customize `Err` field name. -* `zerolog.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.TimeFieldFormat`: Can be set to customize `Time` field value formatting. If set with `zerolog.TimeFormatUnix`, `zerolog.TimeFormatUnixMs` or `zerolog.TimeFormatUnixMicro`, times are formatted 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. +* `zerolog.FloatingPointPrecision`: If set to a value other than -1, controls the number +of digits when formatting float numbers in JSON. See +[strconv.FormatFloat](https://pkg.go.dev/strconv#FormatFloat) +for more details. ## Field Types @@ -666,7 +690,7 @@ with zerolog library is [CSD](https://github.com/toravir/csd/). ## Benchmarks -See [logbench](http://hackemist.com/logbench/) for more comprehensive and up-to-date benchmarks. +See [logbench](http://bench.zerolog.io/) for more comprehensive and up-to-date benchmarks. All operations are allocation free (those numbers *include* JSON encoding): @@ -727,6 +751,8 @@ Log a static string, without any context or `printf`-style templating: ## Caveats +### Field duplication + Note that zerolog does no de-duplication of fields. Using the same key multiple times creates multiple keys in final JSON: ```go @@ -738,3 +764,19 @@ logger.Info(). ``` In this case, many consumers will take the last value, but this is not guaranteed; check yours if in doubt. + +### Concurrency safety + +Be careful when calling UpdateContext. It is not concurrency safe. Use the With method to create a child logger: + +```go +func handler(w http.ResponseWriter, r *http.Request) { + // Create a child logger for concurrency safety + logger := log.Logger.With().Logger() + + // Add context fields, for example User-Agent from HTTP headers + logger.UpdateContext(func(c zerolog.Context) zerolog.Context { + ... + }) +} +``` diff --git a/array.go b/array.go index 99612ee9..ba35b283 100644 --- a/array.go +++ b/array.go @@ -183,13 +183,13 @@ func (a *Array) Uint64(i uint64) *Array { // Float32 appends f as a float32 to the array. func (a *Array) Float32(f float32) *Array { - a.buf = enc.AppendFloat32(enc.AppendArrayDelim(a.buf), f) + a.buf = enc.AppendFloat32(enc.AppendArrayDelim(a.buf), f, FloatingPointPrecision) return a } // Float64 appends f as a float64 to the array. func (a *Array) Float64(f float64) *Array { - a.buf = enc.AppendFloat64(enc.AppendArrayDelim(a.buf), f) + a.buf = enc.AppendFloat64(enc.AppendArrayDelim(a.buf), f, FloatingPointPrecision) return a } @@ -201,7 +201,7 @@ func (a *Array) Time(t time.Time) *Array { // Dur appends d to the array. func (a *Array) Dur(d time.Duration) *Array { - a.buf = enc.AppendDuration(enc.AppendArrayDelim(a.buf), d, DurationFieldUnit, DurationFieldInteger) + a.buf = enc.AppendDuration(enc.AppendArrayDelim(a.buf), d, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) return a } diff --git a/benchmark_test.go b/benchmark_test.go index 9aa41008..39a35da3 100644 --- a/benchmark_test.go +++ b/benchmark_test.go @@ -1,8 +1,9 @@ package zerolog import ( + "context" "errors" - "io/ioutil" + "io" "net" "testing" "time" @@ -14,7 +15,7 @@ var ( ) func BenchmarkLogEmpty(b *testing.B) { - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -24,7 +25,7 @@ func BenchmarkLogEmpty(b *testing.B) { } func BenchmarkDisabled(b *testing.B) { - logger := New(ioutil.Discard).Level(Disabled) + logger := New(io.Discard).Level(Disabled) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -34,7 +35,7 @@ func BenchmarkDisabled(b *testing.B) { } func BenchmarkInfo(b *testing.B) { - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -44,7 +45,7 @@ func BenchmarkInfo(b *testing.B) { } func BenchmarkContextFields(b *testing.B) { - logger := New(ioutil.Discard).With(). + logger := New(io.Discard).With(). Str("string", "four!"). Time("time", time.Time{}). Int("int", 123). @@ -59,7 +60,7 @@ func BenchmarkContextFields(b *testing.B) { } func BenchmarkContextAppend(b *testing.B) { - logger := New(ioutil.Discard).With(). + logger := New(io.Discard).With(). Str("foo", "bar"). Logger() b.ResetTimer() @@ -71,7 +72,7 @@ func BenchmarkContextAppend(b *testing.B) { } func BenchmarkLogFields(b *testing.B) { - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -101,7 +102,7 @@ func BenchmarkLogArrayObject(b *testing.B) { obj1 := obj{"a", "b", 2} obj2 := obj{"c", "d", 3} obj3 := obj{"e", "f", 4} - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() b.ReportAllocs() for i := 0; i < b.N; i++ { @@ -160,6 +161,7 @@ func BenchmarkLogFieldType(b *testing.B) { {"a", "a", 0}, } errs := []error{errors.New("a"), errors.New("b"), errors.New("c"), errors.New("d"), errors.New("e")} + ctx := context.Background() types := map[string]func(e *Event) *Event{ "Bool": func(e *Event) *Event { return e.Bool("k", bools[0]) @@ -191,6 +193,9 @@ func BenchmarkLogFieldType(b *testing.B) { "Errs": func(e *Event) *Event { return e.Errs("k", errs) }, + "Ctx": func(e *Event) *Event { + return e.Ctx(ctx) + }, "Time": func(e *Event) *Event { return e.Time("k", times[0]) }, @@ -219,7 +224,7 @@ func BenchmarkLogFieldType(b *testing.B) { return e.Object("k", objects[0]) }, } - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() for name := range types { f := types[name] @@ -284,6 +289,7 @@ func BenchmarkContextFieldType(b *testing.B) { {"a", "a", 0}, } errs := []error{errors.New("a"), errors.New("b"), errors.New("c"), errors.New("d"), errors.New("e")} + ctx := context.Background() types := map[string]func(c Context) Context{ "Bool": func(c Context) Context { return c.Bool("k", bools[0]) @@ -318,6 +324,9 @@ func BenchmarkContextFieldType(b *testing.B) { "Errs": func(c Context) Context { return c.Errs("k", errs) }, + "Ctx": func(c Context) Context { + return c.Ctx(ctx) + }, "Time": func(c Context) Context { return c.Time("k", times[0]) }, @@ -349,7 +358,7 @@ func BenchmarkContextFieldType(b *testing.B) { return c.Timestamp() }, } - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() for name := range types { f := types[name] diff --git a/binary_test.go b/binary_test.go index b4882d7b..6559735c 100644 --- a/binary_test.go +++ b/binary_test.go @@ -7,7 +7,6 @@ import ( "errors" "fmt" - // "io/ioutil" stdlog "log" "time" ) diff --git a/cmd/lint/README.md b/cmd/lint/README.md index fbd3d2af..32b65760 100644 --- a/cmd/lint/README.md +++ b/cmd/lint/README.md @@ -1,5 +1,7 @@ # Zerolog Lint +**DEPRECATED: In favor of https://github.com/ykadowak/zerologlint which is integrated with `go vet` and [golangci-lint](https://golangci-lint.run/).** + 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 diff --git a/cmd/prettylog/prettylog.go b/cmd/prettylog/prettylog.go index 61bf8b87..10d77994 100644 --- a/cmd/prettylog/prettylog.go +++ b/cmd/prettylog/prettylog.go @@ -1,9 +1,13 @@ package main import ( + "bufio" + "errors" + "flag" "fmt" "io" "os" + "time" "github.com/rs/zerolog" ) @@ -13,14 +17,66 @@ func isInputFromPipe() bool { return fileInfo.Mode()&os.ModeCharDevice == 0 } +func processInput(reader io.Reader, writer io.Writer) error { + scanner := bufio.NewScanner(reader) + for scanner.Scan() { + bytesToWrite := scanner.Bytes() + _, err := writer.Write(bytesToWrite) + if err != nil { + if errors.Is(err, io.EOF) { + break + } + + fmt.Printf("%s\n", bytesToWrite) + } + } + + return scanner.Err() +} + func main() { - if !isInputFromPipe() { - fmt.Println("The command is intended to work with pipes.") - fmt.Println("Usage: app_with_zerolog | 2> >(prettylog)") - os.Exit(1) - return + timeFormats := map[string]string{ + "default": time.Kitchen, + "full": time.RFC1123, + } + + timeFormatFlag := flag.String( + "time-format", + "default", + "Time format, either 'default' or 'full'", + ) + + flag.Parse() + + timeFormat, ok := timeFormats[*timeFormatFlag] + if !ok { + panic("Invalid time-format provided") } writer := zerolog.NewConsoleWriter() - _, _ = io.Copy(writer, os.Stdin) + writer.TimeFormat = timeFormat + + if isInputFromPipe() { + _ = processInput(os.Stdin, writer) + } else if flag.NArg() >= 1 { + for _, filename := range flag.Args() { + // Scan each line from filename and write it into writer + reader, err := os.Open(filename) + if err != nil { + fmt.Printf("%s open: %v", filename, err) + os.Exit(1) + } + + if err := processInput(reader, writer); err != nil { + fmt.Printf("%s scan: %v", filename, err) + os.Exit(1) + } + } + } else { + fmt.Println("Usage:") + fmt.Println(" app_with_zerolog | 2> >(prettylog)") + fmt.Println(" prettylog zerolog_output.jsonl") + os.Exit(1) + return + } } diff --git a/console.go b/console.go index 4ffa6fe6..9cff56f5 100644 --- a/console.go +++ b/console.go @@ -28,6 +28,8 @@ const ( colorBold = 1 colorDarkGray = 90 + + unknownLevel = "???" ) var ( @@ -57,12 +59,21 @@ type ConsoleWriter struct { // TimeFormat specifies the format for timestamp in output. TimeFormat string + // TimeLocation tells ConsoleWriter’s default FormatTimestamp + // how to localize the time. + TimeLocation *time.Location + // PartsOrder defines the order of parts in output. PartsOrder []string // PartsExclude defines parts to not display in output. PartsExclude []string + // FieldsOrder defines the order of contextual fields in output. + FieldsOrder []string + + fieldIsOrdered map[string]int + // FieldsExclude defines contextual fields to not display in output. FieldsExclude []string @@ -76,6 +87,8 @@ type ConsoleWriter struct { FormatErrFieldValue Formatter FormatExtra func(map[string]interface{}, *bytes.Buffer) error + + FormatPrepare func(map[string]interface{}) error } // NewConsoleWriter creates and initializes a new ConsoleWriter. @@ -124,6 +137,13 @@ func (w ConsoleWriter) Write(p []byte) (n int, err error) { return n, fmt.Errorf("cannot decode event: %s", err) } + if w.FormatPrepare != nil { + err = w.FormatPrepare(evt) + if err != nil { + return n, err + } + } + for _, p := range w.PartsOrder { w.writePart(buf, evt, p) } @@ -146,6 +166,15 @@ func (w ConsoleWriter) Write(p []byte) (n int, err error) { return len(p), err } +// Call the underlying writer's Close method if it is an io.Closer. Otherwise +// does nothing. +func (w ConsoleWriter) Close() error { + if closer, ok := w.Out.(io.Closer); ok { + return closer.Close() + } + return 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)) @@ -167,7 +196,12 @@ func (w ConsoleWriter) writeFields(evt map[string]interface{}, buf *bytes.Buffer } fields = append(fields, field) } - sort.Strings(fields) + + if len(w.FieldsOrder) > 0 { + w.orderFields(fields) + } else { + sort.Strings(fields) + } // Write space only if something has already been written to the buffer, and if there are fields. if buf.Len() > 0 && len(fields) > 0 { @@ -266,13 +300,13 @@ func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{}, } case TimestampFieldName: if w.FormatTimestamp == nil { - f = consoleDefaultFormatTimestamp(w.TimeFormat, w.NoColor) + f = consoleDefaultFormatTimestamp(w.TimeFormat, w.TimeLocation, w.NoColor) } else { f = w.FormatTimestamp } case MessageFieldName: if w.FormatMessage == nil { - f = consoleDefaultFormatMessage + f = consoleDefaultFormatMessage(w.NoColor, evt[LevelFieldName]) } else { f = w.FormatMessage } @@ -300,6 +334,32 @@ func (w ConsoleWriter) writePart(buf *bytes.Buffer, evt map[string]interface{}, } } +// orderFields takes an array of field names and an array representing field order +// and returns an array with any ordered fields at the beginning, in order, +// and the remaining fields after in their original order. +func (w ConsoleWriter) orderFields(fields []string) { + if w.fieldIsOrdered == nil { + w.fieldIsOrdered = make(map[string]int) + for i, fieldName := range w.FieldsOrder { + w.fieldIsOrdered[fieldName] = i + } + } + sort.Slice(fields, func(i, j int) bool { + ii, iOrdered := w.fieldIsOrdered[fields[i]] + jj, jOrdered := w.fieldIsOrdered[fields[j]] + if iOrdered && jOrdered { + return ii < jj + } + if iOrdered { + return true + } + if jOrdered { + return false + } + return fields[i] < fields[j] + }) +} + // needsQuote returns true when the string s should be quoted in output. func needsQuote(s string) bool { for i := range s { @@ -310,8 +370,13 @@ func needsQuote(s string) bool { return false } -// colorize returns the string s wrapped in ANSI code c, unless disabled is true. +// colorize returns the string s wrapped in ANSI code c, unless disabled is true or c is 0. func colorize(s interface{}, c int, disabled bool) string { + e := os.Getenv("NO_COLOR") + if e != "" || c == 0 { + disabled = true + } + if disabled { return fmt.Sprintf("%s", s) } @@ -329,19 +394,23 @@ func consoleDefaultPartsOrder() []string { } } -func consoleDefaultFormatTimestamp(timeFormat string, noColor bool) Formatter { +func consoleDefaultFormatTimestamp(timeFormat string, location *time.Location, noColor bool) Formatter { if timeFormat == "" { timeFormat = consoleDefaultTimeFormat } + if location == nil { + location = time.Local + } + return func(i interface{}) string { t := "" switch tt := i.(type) { case string: - ts, err := time.ParseInLocation(TimeFieldFormat, tt, time.Local) + ts, err := time.ParseInLocation(TimeFieldFormat, tt, location) if err != nil { t = tt } else { - t = ts.Local().Format(timeFormat) + t = ts.In(location).Format(timeFormat) } case json.Number: i, err := tt.Int64() @@ -362,45 +431,37 @@ func consoleDefaultFormatTimestamp(timeFormat string, noColor bool) Formatter { } ts := time.Unix(sec, nsec) - t = ts.Format(timeFormat) + t = ts.In(location).Format(timeFormat) } } return colorize(t, colorDarkGray, noColor) } } +func stripLevel(ll string) string { + if len(ll) == 0 { + return unknownLevel + } + if len(ll) > 3 { + ll = ll[:3] + } + return strings.ToUpper(ll) +} + func consoleDefaultFormatLevel(noColor bool) Formatter { return func(i interface{}) string { - var l string if ll, ok := i.(string); ok { - switch ll { - case LevelTraceValue: - l = colorize("TRC", colorMagenta, noColor) - case LevelDebugValue: - l = colorize("DBG", colorYellow, noColor) - case LevelInfoValue: - l = colorize("INF", colorGreen, noColor) - case LevelNoticeValue: - l = colorize("NTC", colorYellow, noColor) - case LevelWarnValue: - l = colorize("WRN", colorRed, noColor) - case LevelErrorValue: - l = colorize(colorize("ERR", colorRed, noColor), colorBold, noColor) - case LevelFatalValue: - l = colorize(colorize("FTL", colorRed, noColor), colorBold, noColor) - case LevelPanicValue: - l = colorize(colorize("PNC", colorRed, noColor), colorBold, noColor) - default: - l = colorize(ll, colorBold, noColor) - } - } else { - if i == nil { - l = colorize("???", colorBold, noColor) - } else { - l = strings.ToUpper(fmt.Sprintf("%s", i))[0:3] + level, _ := ParseLevel(ll) + fl, ok := FormattedLevels[level] + if ok { + return colorize(fl, LevelColors[level], noColor) } + return stripLevel(ll) + } + if i == nil { + return unknownLevel } - return l + return stripLevel(fmt.Sprintf("%s", i)) } } @@ -422,11 +483,18 @@ func consoleDefaultFormatCaller(noColor bool) Formatter { } } -func consoleDefaultFormatMessage(i interface{}) string { - if i == nil { - return "" +func consoleDefaultFormatMessage(noColor bool, level interface{}) Formatter { + return func(i interface{}) string { + if i == nil || i == "" { + return "" + } + switch level { + case LevelInfoValue, LevelWarnValue, LevelErrorValue, LevelFatalValue, LevelPanicValue: + return colorize(fmt.Sprintf("%s", i), colorBold, noColor) + default: + return fmt.Sprintf("%s", i) + } } - return fmt.Sprintf("%s", i) } func consoleDefaultFormatFieldName(noColor bool) Formatter { @@ -447,6 +515,6 @@ func consoleDefaultFormatErrFieldName(noColor bool) Formatter { func consoleDefaultFormatErrFieldValue(noColor bool) Formatter { return func(i interface{}) string { - return colorize(fmt.Sprintf("%s", i), colorRed, noColor) + return colorize(colorize(fmt.Sprintf("%s", i), colorBold, noColor), colorRed, noColor) } } diff --git a/console_test.go b/console_test.go index 18c2db70..179dfeef 100644 --- a/console_test.go +++ b/console_test.go @@ -3,7 +3,7 @@ package zerolog_test import ( "bytes" "fmt" - "io/ioutil" + "io" "os" "strings" "testing" @@ -97,13 +97,32 @@ func TestConsoleWriter(t *testing.T) { t.Errorf("Unexpected error when writing output: %s", err) } - expectedOutput := "\x1b[90m\x1b[0m \x1b[31mWRN\x1b[0m Foobar\n" + expectedOutput := "\x1b[90m\x1b[0m \x1b[33mWRN\x1b[0m \x1b[1mFoobar\x1b[0m\n" actualOutput := buf.String() if actualOutput != expectedOutput { t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput) } }) + t.Run("NO_COLOR = true", func(t *testing.T) { + os.Setenv("NO_COLOR", "anything") + + buf := &bytes.Buffer{} + w := zerolog.ConsoleWriter{Out: buf} + + _, err := w.Write([]byte(`{"level": "warn", "message": "Foobar"}`)) + if err != nil { + t.Errorf("Unexpected error when writing output: %s", err) + } + + expectedOutput := " WRN Foobar\n" + actualOutput := buf.String() + if actualOutput != expectedOutput { + t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput) + } + os.Unsetenv("NO_COLOR") + }) + t.Run("Write fields", func(t *testing.T) { buf := &bytes.Buffer{} w := zerolog.ConsoleWriter{Out: buf, NoColor: true} @@ -229,7 +248,7 @@ func TestConsoleWriter(t *testing.T) { t.Errorf("Unexpected error when writing output: %s", err) } - expectedOutput := "\x1b[90m\x1b[0m \x1b[31mWRN\x1b[0m Foobar \x1b[36mfoo=\x1b[0mbar\n" + expectedOutput := "\x1b[90m\x1b[0m \x1b[33mWRN\x1b[0m \x1b[1mFoobar\x1b[0m \x1b[36mfoo=\x1b[0mbar\n" actualOutput := buf.String() if actualOutput != expectedOutput { t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput) @@ -301,6 +320,85 @@ func TestConsoleWriter(t *testing.T) { t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput) } }) + + t.Run("With an extra 'level' field", func(t *testing.T) { + t.Run("malformed string", func(t *testing.T) { + cases := []struct { + field string + output string + }{ + {"", " ??? Hello World foo=bar\n"}, + {"-", " - Hello World foo=bar\n"}, + {"1", " " + zerolog.FormattedLevels[1] + " Hello World foo=bar\n"}, + {"a", " A Hello World foo=bar\n"}, + {"12", " 12 Hello World foo=bar\n"}, + {"a2", " A2 Hello World foo=bar\n"}, + {"2a", " 2A Hello World foo=bar\n"}, + {"ab", " AB Hello World foo=bar\n"}, + {"12a", " 12A Hello World foo=bar\n"}, + {"a12", " A12 Hello World foo=bar\n"}, + {"abc", " ABC Hello World foo=bar\n"}, + {"123", " 123 Hello World foo=bar\n"}, + {"abcd", " ABC Hello World foo=bar\n"}, + {"1234", " 123 Hello World foo=bar\n"}, + {"123d", " 123 Hello World foo=bar\n"}, + {"01", " " + zerolog.FormattedLevels[1] + " Hello World foo=bar\n"}, + {"001", " " + zerolog.FormattedLevels[1] + " Hello World foo=bar\n"}, + {"0001", " " + zerolog.FormattedLevels[1] + " Hello World foo=bar\n"}, + } + for i, c := range cases { + c := c + t.Run(fmt.Sprintf("case %d", i), func(t *testing.T) { + buf := &bytes.Buffer{} + out := zerolog.NewConsoleWriter() + out.NoColor = true + out.Out = buf + log := zerolog.New(out) + + log.Debug().Str("level", c.field).Str("foo", "bar").Msg("Hello World") + + actualOutput := buf.String() + if actualOutput != c.output { + t.Errorf("Unexpected output %q, want: %q", actualOutput, c.output) + } + }) + } + }) + + t.Run("weird value", func(t *testing.T) { + cases := []struct { + field interface{} + output string + }{ + {0, " 0 Hello World foo=bar\n"}, + {1, " 1 Hello World foo=bar\n"}, + {-1, " -1 Hello World foo=bar\n"}, + {-3, " -3 Hello World foo=bar\n"}, + {-32, " -32 Hello World foo=bar\n"}, + {-321, " -32 Hello World foo=bar\n"}, + {12, " 12 Hello World foo=bar\n"}, + {123, " 123 Hello World foo=bar\n"}, + {1234, " 123 Hello World foo=bar\n"}, + } + for i, c := range cases { + c := c + t.Run(fmt.Sprintf("case %d", i), func(t *testing.T) { + buf := &bytes.Buffer{} + out := zerolog.NewConsoleWriter() + out.NoColor = true + out.Out = buf + log := zerolog.New(out) + + log.Debug().Interface("level", c.field).Str("foo", "bar").Msg("Hello World") + + actualOutput := buf.String() + if actualOutput != c.output { + t.Errorf("Unexpected output %q, want: %q", actualOutput, c.output) + } + }) + } + }) + }) } func TestConsoleWriterConfiguration(t *testing.T) { @@ -324,6 +422,35 @@ func TestConsoleWriterConfiguration(t *testing.T) { } }) + t.Run("Sets TimeFormat and TimeLocation", func(t *testing.T) { + locs := []*time.Location{ time.Local, time.UTC } + + for _, location := range locs { + buf := &bytes.Buffer{} + w := zerolog.ConsoleWriter{ + Out: buf, + NoColor: true, + TimeFormat: time.RFC3339, + TimeLocation: location, + } + + ts := time.Unix(0, 0) + d := ts.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 := ts.In(location).Format(time.RFC3339) + " INF Foobar\n" + actualOutput := buf.String() + if actualOutput != expectedOutput { + t.Errorf("Unexpected output %q, want: %q (location=%s)", actualOutput, expectedOutput, location) + } + } + }) + t.Run("Sets PartsOrder", func(t *testing.T) { buf := &bytes.Buffer{} w := zerolog.ConsoleWriter{Out: buf, NoColor: true, PartsOrder: []string{"message", "level"}} @@ -359,6 +486,23 @@ func TestConsoleWriterConfiguration(t *testing.T) { } }) + t.Run("Sets FieldsOrder", func(t *testing.T) { + buf := &bytes.Buffer{} + w := zerolog.ConsoleWriter{Out: buf, NoColor: true, FieldsOrder: []string{"zebra", "aardvark"}} + + evt := `{"level": "info", "message": "Zoo", "aardvark": "Able", "mussel": "Mountain", "zebra": "Zulu"}` + _, err := w.Write([]byte(evt)) + if err != nil { + t.Errorf("Unexpected error when writing output: %s", err) + } + + expectedOutput := " INF Zoo zebra=Zulu aardvark=Able mussel=Mountain\n" + actualOutput := buf.String() + if actualOutput != expectedOutput { + t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput) + } + }) + t.Run("Sets FieldsExclude", func(t *testing.T) { buf := &bytes.Buffer{} w := zerolog.ConsoleWriter{Out: buf, NoColor: true, FieldsExclude: []string{"foo"}} @@ -399,6 +543,29 @@ func TestConsoleWriterConfiguration(t *testing.T) { } }) + t.Run("Sets FormatPrepare", func(t *testing.T) { + buf := &bytes.Buffer{} + w := zerolog.ConsoleWriter{ + Out: buf, NoColor: true, PartsOrder: []string{"level", "message"}, + FormatPrepare: func(evt map[string]interface{}) error { + evt["message"] = fmt.Sprintf("msg=%s", evt["message"]) + return nil + }, + } + + evt := `{"level": "info", "message": "Foobar"}` + _, err := w.Write([]byte(evt)) + if err != nil { + t.Errorf("Unexpected error when writing output: %s", err) + } + + expectedOutput := "INF msg=Foobar\n" + actualOutput := buf.String() + if actualOutput != expectedOutput { + t.Errorf("Unexpected output %q, want: %q", actualOutput, expectedOutput) + } + }) + t.Run("Uses local time for console writer without time zone", func(t *testing.T) { // Regression test for issue #483 (check there for more details) @@ -432,7 +599,7 @@ func BenchmarkConsoleWriter(b *testing.B) { var msg = []byte(`{"level": "info", "foo": "bar", "message": "HELLO", "time": "1990-01-01"}`) - w := zerolog.ConsoleWriter{Out: ioutil.Discard, NoColor: false} + w := zerolog.ConsoleWriter{Out: io.Discard, NoColor: false} for i := 0; i < b.N; i++ { w.Write(msg) diff --git a/context.go b/context.go index f398e319..ff9a3ae2 100644 --- a/context.go +++ b/context.go @@ -1,8 +1,9 @@ package zerolog import ( + "context" "fmt" - "io/ioutil" + "io" "math" "net" "time" @@ -22,7 +23,7 @@ func (c Context) Logger() Logger { // Only map[string]interface{} and []interface{} are accepted. []interface{} must // alternate string keys and arbitrary values, and extraneous ones are ignored. func (c Context) Fields(fields interface{}) Context { - c.l.context = appendFields(c.l.context, fields) + c.l.context = appendFields(c.l.context, fields, c.l.stack) return c } @@ -56,7 +57,7 @@ func (c Context) Array(key string, arr LogArrayMarshaler) Context { // Object marshals an object that implement the LogObjectMarshaler interface. func (c Context) Object(key string, obj LogObjectMarshaler) Context { - e := newEvent(levelWriterAdapter{ioutil.Discard}, 0) + e := newEvent(LevelWriterAdapter{io.Discard}, 0) e.Object(key, obj) c.l.context = enc.AppendObjectData(c.l.context, e.buf) putEvent(e) @@ -65,7 +66,7 @@ func (c Context) Object(key string, obj LogObjectMarshaler) Context { // EmbedObject marshals and Embeds an object that implement the LogObjectMarshaler interface. func (c Context) EmbedObject(obj LogObjectMarshaler) Context { - e := newEvent(levelWriterAdapter{ioutil.Discard}, 0) + e := newEvent(LevelWriterAdapter{io.Discard}, 0) e.EmbedObject(obj) c.l.context = enc.AppendObjectData(c.l.context, e.buf) putEvent(e) @@ -162,9 +163,34 @@ func (c Context) Errs(key string, errs []error) Context { // Err adds the field "error" with serialized err to the logger context. func (c Context) Err(err error) Context { + if c.l.stack && ErrorStackMarshaler != nil { + switch m := ErrorStackMarshaler(err).(type) { + case nil: + case LogObjectMarshaler: + c = c.Object(ErrorStackFieldName, m) + case error: + if m != nil && !isNilValue(m) { + c = c.Str(ErrorStackFieldName, m.Error()) + } + case string: + c = c.Str(ErrorStackFieldName, m) + default: + c = c.Interface(ErrorStackFieldName, m) + } + } + return c.AnErr(ErrorFieldName, err) } +// Ctx adds the context.Context to the logger context. The context.Context is +// not rendered in the error message, but is made available for hooks to use. +// A typical use case is to extract tracing information from the +// context.Context. +func (c Context) Ctx(ctx context.Context) Context { + c.l.ctx = ctx + return c +} + // Bool adds the field key with val as a bool to the logger context. func (c Context) Bool(key string, b bool) Context { c.l.context = enc.AppendBool(enc.AppendKey(c.l.context, key), b) @@ -299,25 +325,25 @@ func (c Context) Uints64(key string, i []uint64) Context { // Float32 adds the field key with f as a float32 to the logger context. func (c Context) Float32(key string, f float32) Context { - c.l.context = enc.AppendFloat32(enc.AppendKey(c.l.context, key), f) + c.l.context = enc.AppendFloat32(enc.AppendKey(c.l.context, key), f, FloatingPointPrecision) return c } // Floats32 adds the field key with f as a []float32 to the logger context. func (c Context) Floats32(key string, f []float32) Context { - c.l.context = enc.AppendFloats32(enc.AppendKey(c.l.context, key), f) + c.l.context = enc.AppendFloats32(enc.AppendKey(c.l.context, key), f, FloatingPointPrecision) return c } // Float64 adds the field key with f as a float64 to the logger context. func (c Context) Float64(key string, f float64) Context { - c.l.context = enc.AppendFloat64(enc.AppendKey(c.l.context, key), f) + c.l.context = enc.AppendFloat64(enc.AppendKey(c.l.context, key), f, FloatingPointPrecision) return c } // Floats64 adds the field key with f as a []float64 to the logger context. func (c Context) Floats64(key string, f []float64) Context { - c.l.context = enc.AppendFloats64(enc.AppendKey(c.l.context, key), f) + c.l.context = enc.AppendFloats64(enc.AppendKey(c.l.context, key), f, FloatingPointPrecision) return c } @@ -329,8 +355,9 @@ func (ts timestampHook) Run(e *Event, level Level, msg string) { var th = timestampHook{} -// Timestamp adds the current local time as UNIX timestamp to the logger context with the "time" key. +// Timestamp adds the current local time to the logger context with the "time" key, formatted using zerolog.TimeFieldFormat. // To customize the key name, change zerolog.TimestampFieldName. +// To customize the time format, change zerolog.TimeFieldFormat. // // NOTE: It won't dedupe the "time" key if the *Context has one already. func (c Context) Timestamp() Context { @@ -338,13 +365,13 @@ func (c Context) Timestamp() Context { return c } -// Time adds the field key with t formated as string using zerolog.TimeFieldFormat. +// Time adds the field key with t formatted as string using zerolog.TimeFieldFormat. func (c Context) Time(key string, t time.Time) Context { c.l.context = enc.AppendTime(enc.AppendKey(c.l.context, key), t, TimeFieldFormat) return c } -// Times adds the field key with t formated as string using zerolog.TimeFieldFormat. +// Times adds the field key with t formatted as string using zerolog.TimeFieldFormat. func (c Context) Times(key string, t []time.Time) Context { c.l.context = enc.AppendTimes(enc.AppendKey(c.l.context, key), t, TimeFieldFormat) return c @@ -352,22 +379,42 @@ func (c Context) Times(key string, t []time.Time) Context { // Dur adds the fields key with d divided by unit and stored as a float. func (c Context) Dur(key string, d time.Duration) Context { - c.l.context = enc.AppendDuration(enc.AppendKey(c.l.context, key), d, DurationFieldUnit, DurationFieldInteger) + c.l.context = enc.AppendDuration(enc.AppendKey(c.l.context, key), d, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) return c } // Durs adds the fields key with d divided by unit and stored as a float. func (c Context) Durs(key string, d []time.Duration) Context { - c.l.context = enc.AppendDurations(enc.AppendKey(c.l.context, key), d, DurationFieldUnit, DurationFieldInteger) + c.l.context = enc.AppendDurations(enc.AppendKey(c.l.context, key), d, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) return c } // Interface adds the field key with obj marshaled using reflection. func (c Context) Interface(key string, i interface{}) Context { + if obj, ok := i.(LogObjectMarshaler); ok { + return c.Object(key, obj) + } c.l.context = enc.AppendInterface(enc.AppendKey(c.l.context, key), i) return c } +// Type adds the field key with val's type using reflection. +func (c Context) Type(key string, val interface{}) Context { + c.l.context = enc.AppendType(enc.AppendKey(c.l.context, key), val) + return c +} + +// Any is a wrapper around Context.Interface. +func (c Context) Any(key string, i interface{}) Context { + return c.Interface(key, i) +} + +// Reset removes all the context fields. +func (c Context) Reset() Context { + c.l.context = enc.AppendBeginMarker(make([]byte, 0, 500)) + return c +} + type callerHook struct { callerSkipFrameCount int } diff --git a/ctx_test.go b/ctx_test.go index 5bc41e53..6315cf7a 100644 --- a/ctx_test.go +++ b/ctx_test.go @@ -1,14 +1,17 @@ package zerolog import ( + "bytes" "context" - "io/ioutil" + "io" "reflect" "testing" + + "github.com/rs/zerolog/internal/cbor" ) func TestCtx(t *testing.T) { - log := New(ioutil.Discard) + log := New(io.Discard) ctx := log.WithContext(context.Background()) log2 := Ctx(ctx) if !reflect.DeepEqual(log, *log2) { @@ -37,13 +40,13 @@ func TestCtx(t *testing.T) { } func TestCtxDisabled(t *testing.T) { - dl := New(ioutil.Discard).Level(Disabled) + dl := New(io.Discard).Level(Disabled) ctx := dl.WithContext(context.Background()) if ctx != context.Background() { t.Error("WithContext stored a disabled logger") } - l := New(ioutil.Discard).With().Str("foo", "bar").Logger() + l := New(io.Discard).With().Str("foo", "bar").Logger() ctx = l.WithContext(ctx) if !reflect.DeepEqual(Ctx(ctx), &l) { t.Error("WithContext did not store logger") @@ -68,3 +71,31 @@ func TestCtxDisabled(t *testing.T) { t.Error("WithContext did not override logger with a disabled logger") } } + +type logObjectMarshalerImpl struct { + name string + age int +} + +func (t logObjectMarshalerImpl) MarshalZerologObject(e *Event) { + e.Str("name", "custom_value").Int("age", t.age) +} + +func Test_InterfaceLogObjectMarshaler(t *testing.T) { + var buf bytes.Buffer + log := New(&buf) + ctx := log.WithContext(context.Background()) + + log2 := Ctx(ctx) + + withLog := log2.With().Interface("obj", &logObjectMarshalerImpl{ + name: "foo", + age: 29, + }).Logger() + + withLog.Info().Msg("test") + + if got, want := cbor.DecodeIfBinaryToString(buf.Bytes()), `{"level":"info","obj":{"name":"custom_value","age":29},"message":"test"}`+"\n"; got != want { + t.Errorf("got %q, want %q", got, want) + } +} diff --git a/diode/diode_test.go b/diode/diode_test.go index d0d0afff..ab6b55e3 100644 --- a/diode/diode_test.go +++ b/diode/diode_test.go @@ -3,9 +3,10 @@ package diode_test import ( "bytes" "fmt" - "io/ioutil" + "io" "log" "os" + "os/exec" "testing" "time" @@ -38,8 +39,45 @@ func TestClose(t *testing.T) { w.Close() } +func TestFatal(t *testing.T) { + if os.Getenv("TEST_FATAL") == "1" { + w := diode.NewWriter(os.Stderr, 1000, 0, func(missed int) { + fmt.Printf("Dropped %d messages\n", missed) + }) + defer w.Close() + log := zerolog.New(w) + log.Fatal().Msg("test") + return + } + + cmd := exec.Command(os.Args[0], "-test.run=TestFatal") + cmd.Env = append(os.Environ(), "TEST_FATAL=1") + stderr, err := cmd.StderrPipe() + if err != nil { + t.Fatal(err) + } + err = cmd.Start() + if err != nil { + t.Fatal(err) + } + slurp, err := io.ReadAll(stderr) + if err != nil { + t.Fatal(err) + } + err = cmd.Wait() + if err == nil { + t.Error("Expected log.Fatal to exit with non-zero status") + } + + want := "{\"level\":\"fatal\",\"message\":\"test\"}\n" + got := cbor.DecodeIfBinaryToString(slurp) + if got != want { + t.Errorf("Diode Fatal Test failed. got:%s, want:%s!", got, want) + } +} + func Benchmark(b *testing.B) { - log.SetOutput(ioutil.Discard) + log.SetOutput(io.Discard) defer log.SetOutput(os.Stderr) benchs := map[string]time.Duration{ "Waiter": 0, @@ -47,7 +85,7 @@ func Benchmark(b *testing.B) { } for name, interval := range benchs { b.Run(name, func(b *testing.B) { - w := diode.NewWriter(ioutil.Discard, 100000, interval, nil) + w := diode.NewWriter(io.Discard, 100000, interval, nil) log := zerolog.New(w) defer w.Close() diff --git a/encoder.go b/encoder.go index 09b24e80..4dbaf380 100644 --- a/encoder.go +++ b/encoder.go @@ -13,13 +13,13 @@ type encoder interface { AppendBool(dst []byte, val bool) []byte AppendBools(dst []byte, vals []bool) []byte AppendBytes(dst, s []byte) []byte - AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool) []byte - AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool) []byte + AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool, precision int) []byte + AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool, precision int) []byte AppendEndMarker(dst []byte) []byte - AppendFloat32(dst []byte, val float32) []byte - AppendFloat64(dst []byte, val float64) []byte - AppendFloats32(dst []byte, vals []float32) []byte - AppendFloats64(dst []byte, vals []float64) []byte + AppendFloat32(dst []byte, val float32, precision int) []byte + AppendFloat64(dst []byte, val float64, precision int) []byte + AppendFloats32(dst []byte, vals []float32, precision int) []byte + AppendFloats64(dst []byte, vals []float64, precision int) []byte AppendHex(dst, s []byte) []byte AppendIPAddr(dst []byte, ip net.IP) []byte AppendIPPrefix(dst []byte, pfx net.IPNet) []byte diff --git a/encoder_cbor.go b/encoder_cbor.go index 7b0dafef..36cb994b 100644 --- a/encoder_cbor.go +++ b/encoder_cbor.go @@ -24,6 +24,9 @@ func init() { func appendJSON(dst []byte, j []byte) []byte { return cbor.AppendEmbeddedJSON(dst, j) } +func appendCBOR(dst []byte, c []byte) []byte { + return cbor.AppendEmbeddedCBOR(dst, c) +} // decodeIfBinaryToString - converts a binary formatted log msg to a // JSON formatted String Log message. diff --git a/encoder_json.go b/encoder_json.go index 0e0450e2..6f96c68a 100644 --- a/encoder_json.go +++ b/encoder_json.go @@ -6,6 +6,7 @@ package zerolog // JSON encoded byte stream. import ( + "encoding/base64" "github.com/rs/zerolog/internal/json" ) @@ -25,6 +26,17 @@ func init() { func appendJSON(dst []byte, j []byte) []byte { return append(dst, j...) } +func appendCBOR(dst []byte, cbor []byte) []byte { + dst = append(dst, []byte("\"data:application/cbor;base64,")...) + l := len(dst) + enc := base64.StdEncoding + n := enc.EncodedLen(len(cbor)) + for i := 0; i < n; i++ { + dst = append(dst, '.') + } + enc.Encode(dst[l:], cbor) + return append(dst, '"') +} func decodeIfBinaryToString(in []byte) string { return string(in) diff --git a/event.go b/event.go index 2e736c83..56de6061 100644 --- a/event.go +++ b/event.go @@ -1,6 +1,7 @@ package zerolog import ( + "context" "fmt" "net" "os" @@ -24,9 +25,10 @@ type Event struct { 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. + stack bool // enable error stack trace + ch []Hook // hooks from context + skipFrame int // The number of additional frames to skip when printing the caller. + ctx context.Context // Optional Go context for event } func putEvent(e *Event) { @@ -162,7 +164,7 @@ func (e *Event) Fields(fields interface{}) *Event { if e == nil { return e } - e.buf = appendFields(e.buf, fields) + e.buf = appendFields(e.buf, fields, e.stack) return e } @@ -318,6 +320,18 @@ func (e *Event) RawJSON(key string, b []byte) *Event { return e } +// RawCBOR adds already encoded CBOR to the log line under key. +// +// No sanity check is performed on b +// Note: The full featureset of CBOR is supported as data will not be mapped to json but stored as data-url +func (e *Event) RawCBOR(key string, b []byte) *Event { + if e == nil { + return e + } + e.buf = appendCBOR(enc.AppendKey(e.buf, key), b) + return e +} + // 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 { @@ -405,6 +419,28 @@ func (e *Event) Stack() *Event { return e } +// Ctx adds the Go Context to the *Event context. The context is not rendered +// in the output message, but is available to hooks and to Func() calls via the +// GetCtx() accessor. A typical use case is to extract tracing information from +// the Go Ctx. +func (e *Event) Ctx(ctx context.Context) *Event { + if e != nil { + e.ctx = ctx + } + return e +} + +// GetCtx retrieves the Go context.Context which is optionally stored in the +// Event. This allows Hooks and functions passed to Func() to retrieve values +// which are stored in the context.Context. This can be useful in tracing, +// where span information is commonly propagated in the context.Context. +func (e *Event) GetCtx() context.Context { + if e == nil || e.ctx == nil { + return context.Background() + } + return e.ctx +} + // 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 { @@ -608,7 +644,7 @@ func (e *Event) Float32(key string, f float32) *Event { if e == nil { return e } - e.buf = enc.AppendFloat32(enc.AppendKey(e.buf, key), f) + e.buf = enc.AppendFloat32(enc.AppendKey(e.buf, key), f, FloatingPointPrecision) return e } @@ -617,7 +653,7 @@ func (e *Event) Floats32(key string, f []float32) *Event { if e == nil { return e } - e.buf = enc.AppendFloats32(enc.AppendKey(e.buf, key), f) + e.buf = enc.AppendFloats32(enc.AppendKey(e.buf, key), f, FloatingPointPrecision) return e } @@ -626,7 +662,7 @@ func (e *Event) Float64(key string, f float64) *Event { if e == nil { return e } - e.buf = enc.AppendFloat64(enc.AppendKey(e.buf, key), f) + e.buf = enc.AppendFloat64(enc.AppendKey(e.buf, key), f, FloatingPointPrecision) return e } @@ -635,7 +671,7 @@ func (e *Event) Floats64(key string, f []float64) *Event { if e == nil { return e } - e.buf = enc.AppendFloats64(enc.AppendKey(e.buf, key), f) + e.buf = enc.AppendFloats64(enc.AppendKey(e.buf, key), f, FloatingPointPrecision) return e } @@ -677,7 +713,7 @@ func (e *Event) Dur(key string, d time.Duration) *Event { if e == nil { return e } - e.buf = enc.AppendDuration(enc.AppendKey(e.buf, key), d, DurationFieldUnit, DurationFieldInteger) + e.buf = enc.AppendDuration(enc.AppendKey(e.buf, key), d, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) return e } @@ -688,7 +724,7 @@ func (e *Event) Durs(key string, d []time.Duration) *Event { if e == nil { return e } - e.buf = enc.AppendDurations(enc.AppendKey(e.buf, key), d, DurationFieldUnit, DurationFieldInteger) + e.buf = enc.AppendDurations(enc.AppendKey(e.buf, key), d, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) return e } @@ -703,7 +739,7 @@ func (e *Event) TimeDiff(key string, t time.Time, start time.Time) *Event { if t.After(start) { d = t.Sub(start) } - e.buf = enc.AppendDuration(enc.AppendKey(e.buf, key), d, DurationFieldUnit, DurationFieldInteger) + e.buf = enc.AppendDuration(enc.AppendKey(e.buf, key), d, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) return e } diff --git a/event_test.go b/event_test.go index 98041b34..e7cf4250 100644 --- a/event_test.go +++ b/event_test.go @@ -28,7 +28,7 @@ func TestEvent_AnErr(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { var buf bytes.Buffer - e := newEvent(levelWriterAdapter{&buf}, DebugLevel) + e := newEvent(LevelWriterAdapter{&buf}, DebugLevel) e.AnErr("err", tt.err) _ = e.write() if got, want := strings.TrimSpace(buf.String()), tt.want; got != want { @@ -40,7 +40,7 @@ func TestEvent_AnErr(t *testing.T) { func TestEvent_ObjectWithNil(t *testing.T) { var buf bytes.Buffer - e := newEvent(levelWriterAdapter{&buf}, DebugLevel) + e := newEvent(LevelWriterAdapter{&buf}, DebugLevel) _ = e.Object("obj", nil) _ = e.write() @@ -53,7 +53,7 @@ func TestEvent_ObjectWithNil(t *testing.T) { func TestEvent_EmbedObjectWithNil(t *testing.T) { var buf bytes.Buffer - e := newEvent(levelWriterAdapter{&buf}, DebugLevel) + e := newEvent(LevelWriterAdapter{&buf}, DebugLevel) _ = e.EmbedObject(nil) _ = e.write() diff --git a/example.jsonl b/example.jsonl new file mode 100644 index 00000000..d73193d7 --- /dev/null +++ b/example.jsonl @@ -0,0 +1,7 @@ +{"time":"5:41PM","level":"info","message":"Starting listener","listen":":8080","pid":37556} +{"time":"5:41PM","level":"debug","message":"Access","database":"myapp","host":"localhost:4962","pid":37556} +{"time":"5:41PM","level":"info","message":"Access","method":"GET","path":"/users","pid":37556,"resp_time":23} +{"time":"5:41PM","level":"info","message":"Access","method":"POST","path":"/posts","pid":37556,"resp_time":532} +{"time":"5:41PM","level":"warn","message":"Slow request","method":"POST","path":"/posts","pid":37556,"resp_time":532} +{"time":"5:41PM","level":"info","message":"Access","method":"GET","path":"/users","pid":37556,"resp_time":10} +{"time":"5:41PM","level":"error","message":"Database connection lost","database":"myapp","pid":37556,"error":"connection reset by peer"} diff --git a/fields.go b/fields.go index c1eb5ce7..99f52718 100644 --- a/fields.go +++ b/fields.go @@ -12,13 +12,13 @@ func isNilValue(i interface{}) bool { return (*[2]uintptr)(unsafe.Pointer(&i))[1] == 0 } -func appendFields(dst []byte, fields interface{}) []byte { +func appendFields(dst []byte, fields interface{}, stack bool) []byte { switch fields := fields.(type) { case []interface{}: if n := len(fields); n&0x1 == 1 { // odd number fields = fields[:n-1] } - dst = appendFieldList(dst, fields) + dst = appendFieldList(dst, fields, stack) case map[string]interface{}: keys := make([]string, 0, len(fields)) for key := range fields { @@ -28,13 +28,13 @@ func appendFields(dst []byte, fields interface{}) []byte { kv := make([]interface{}, 2) for _, key := range keys { kv[0], kv[1] = key, fields[key] - dst = appendFieldList(dst, kv) + dst = appendFieldList(dst, kv, stack) } } return dst } -func appendFieldList(dst []byte, kvList []interface{}) []byte { +func appendFieldList(dst []byte, kvList []interface{}, stack bool) []byte { for i, n := 0, len(kvList); i < n; i += 2 { key, val := kvList[i], kvList[i+1] if key, ok := key.(string); ok { @@ -74,6 +74,21 @@ func appendFieldList(dst []byte, kvList []interface{}) []byte { default: dst = enc.AppendInterface(dst, m) } + + if stack && ErrorStackMarshaler != nil { + dst = enc.AppendKey(dst, ErrorStackFieldName) + switch m := ErrorStackMarshaler(val).(type) { + case nil: + case error: + if m != nil && !isNilValue(m) { + dst = enc.AppendString(dst, m.Error()) + } + case string: + dst = enc.AppendString(dst, m) + default: + dst = enc.AppendInterface(dst, m) + } + } case []error: dst = enc.AppendArrayStart(dst) for i, err := range val { @@ -124,13 +139,13 @@ func appendFieldList(dst []byte, kvList []interface{}) []byte { case uint64: dst = enc.AppendUint64(dst, val) case float32: - dst = enc.AppendFloat32(dst, val) + dst = enc.AppendFloat32(dst, val, FloatingPointPrecision) case float64: - dst = enc.AppendFloat64(dst, val) + dst = enc.AppendFloat64(dst, val, FloatingPointPrecision) case time.Time: dst = enc.AppendTime(dst, val, TimeFieldFormat) case time.Duration: - dst = enc.AppendDuration(dst, val, DurationFieldUnit, DurationFieldInteger) + dst = enc.AppendDuration(dst, val, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) case *string: if val != nil { dst = enc.AppendString(dst, *val) @@ -205,13 +220,13 @@ func appendFieldList(dst []byte, kvList []interface{}) []byte { } case *float32: if val != nil { - dst = enc.AppendFloat32(dst, *val) + dst = enc.AppendFloat32(dst, *val, FloatingPointPrecision) } else { dst = enc.AppendNil(dst) } case *float64: if val != nil { - dst = enc.AppendFloat64(dst, *val) + dst = enc.AppendFloat64(dst, *val, FloatingPointPrecision) } else { dst = enc.AppendNil(dst) } @@ -223,7 +238,7 @@ func appendFieldList(dst []byte, kvList []interface{}) []byte { } case *time.Duration: if val != nil { - dst = enc.AppendDuration(dst, *val, DurationFieldUnit, DurationFieldInteger) + dst = enc.AppendDuration(dst, *val, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) } else { dst = enc.AppendNil(dst) } @@ -252,13 +267,13 @@ func appendFieldList(dst []byte, kvList []interface{}) []byte { case []uint64: dst = enc.AppendUints64(dst, val) case []float32: - dst = enc.AppendFloats32(dst, val) + dst = enc.AppendFloats32(dst, val, FloatingPointPrecision) case []float64: - dst = enc.AppendFloats64(dst, val) + dst = enc.AppendFloats64(dst, val, FloatingPointPrecision) case []time.Time: dst = enc.AppendTimes(dst, val, TimeFieldFormat) case []time.Duration: - dst = enc.AppendDurations(dst, val, DurationFieldUnit, DurationFieldInteger) + dst = enc.AppendDurations(dst, val, DurationFieldUnit, DurationFieldInteger, FloatingPointPrecision) case nil: dst = enc.AppendNil(dst) case net.IP: diff --git a/globals.go b/globals.go index 49bf6491..9d41bc63 100644 --- a/globals.go +++ b/globals.go @@ -1,6 +1,7 @@ package zerolog import ( + "bytes" "encoding/json" "strconv" "sync/atomic" @@ -83,8 +84,22 @@ var ( } // InterfaceMarshalFunc allows customization of interface marshaling. - // Default: "encoding/json.Marshal" - InterfaceMarshalFunc = json.Marshal + // Default: "encoding/json.Marshal" with disabled HTML escaping + InterfaceMarshalFunc = func(v interface{}) ([]byte, error) { + var buf bytes.Buffer + encoder := json.NewEncoder(&buf) + encoder.SetEscapeHTML(false) + err := encoder.Encode(v) + if err != nil { + return nil, err + } + b := buf.Bytes() + if len(b) > 0 { + // Remove trailing \n which is added by Encode. + return b[:len(b)-1], nil + } + return b, nil + } // TimeFieldFormat defines the time format of the Time field type. If set to // TimeFormatUnix, TimeFormatUnixMs, TimeFormatUnixMicro or TimeFormatUnixNano, the time is formatted as a UNIX @@ -110,6 +125,41 @@ var ( // DefaultContextLogger is returned from Ctx() if there is no logger associated // with the context. DefaultContextLogger *Logger + + // LevelColors are used by ConsoleWriter's consoleDefaultFormatLevel to color + // log levels. + LevelColors = map[Level]int{ + TraceLevel: colorBlue, + DebugLevel: 0, + InfoLevel: colorGreen, + WarnLevel: colorYellow, + ErrorLevel: colorRed, + FatalLevel: colorRed, + PanicLevel: colorRed, + NoticeLevel: colorYellow, + } + + // FormattedLevels are used by ConsoleWriter's consoleDefaultFormatLevel + // for a short level name. + FormattedLevels = map[Level]string{ + TraceLevel: "TRC", + DebugLevel: "DBG", + InfoLevel: "INF", + WarnLevel: "WRN", + ErrorLevel: "ERR", + FatalLevel: "FTL", + PanicLevel: "PNC", + NoticeLevel: "NTC", + } + + // TriggerLevelWriterBufferReuseLimit is a limit in bytes that a buffer is dropped + // from the TriggerLevelWriter buffer pool if the buffer grows above the limit. + TriggerLevelWriterBufferReuseLimit = 64 * 1024 + + // FloatingPointPrecision, if set to a value other than -1, controls the number + // of digits when formatting float numbers in JSON. See strconv.FormatFloat for + // more details. + FloatingPointPrecision = -1 ) var ( diff --git a/go.mod b/go.mod index 6ec5abcc..fd31c429 100644 --- a/go.mod +++ b/go.mod @@ -4,7 +4,9 @@ go 1.15 require ( github.com/coreos/go-systemd/v22 v22.5.0 - github.com/mattn/go-colorable v0.1.12 + github.com/mattn/go-colorable v0.1.13 + github.com/mattn/go-isatty v0.0.19 // indirect github.com/pkg/errors v0.9.1 - github.com/rs/xid v1.5.0 + github.com/rs/xid v1.6.0 + golang.org/x/sys v0.12.0 // indirect ) diff --git a/go.sum b/go.sum index 50b6327d..c2bf72f1 100644 --- a/go.sum +++ b/go.sum @@ -1,14 +1,16 @@ github.com/coreos/go-systemd/v22 v22.5.0 h1:RrqgGjYQKalulkV8NGVIfkXQf6YYmOyiJKk8iXXhfZs= github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= -github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40= -github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4= -github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y= -github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94= +github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= +github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA= +github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= 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.5.0 h1:mKX4bl4iPYJtEIxp6CYiUuLQ/8DYMoz0PUdtGgMFRVc= -github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= -golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 h1:foEbQz/B0Oz6YIqu/69kfXPYeFQAuuMYFkjaqXzl5Wo= -golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +github.com/rs/xid v1.6.0 h1:fV591PaemRlL6JfRxGDEPl69wICngIQ3shQtzfy2gxU= +github.com/rs/xid v1.6.0/go.mod h1:7XoLgs4eV+QndskICGsho+ADou8ySMSjJKDIan90Nz0= +golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.12.0 h1:CM0HF96J0hcLAwsHPJZjfdNzs0gftsLfgKt57wWHJ0o= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= diff --git a/hlog/hlog.go b/hlog/hlog.go index 37734008..06ca4adf 100644 --- a/hlog/hlog.go +++ b/hlog/hlog.go @@ -3,7 +3,9 @@ package hlog import ( "context" + "net" "net/http" + "strings" "time" "github.com/rs/xid" @@ -89,6 +91,35 @@ func RemoteAddrHandler(fieldKey string) func(next http.Handler) http.Handler { } } +func getHost(hostPort string) string { + if hostPort == "" { + return "" + } + + host, _, err := net.SplitHostPort(hostPort) + if err != nil { + return hostPort + } + return host +} + +// RemoteIPHandler is similar to RemoteAddrHandler, but logs only +// an IP, not a port. +func RemoteIPHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + ip := getHost(r.RemoteAddr) + if ip != "" { + log := zerolog.Ctx(r.Context()) + log.UpdateContext(func(c zerolog.Context) zerolog.Context { + return c.Str(fieldKey, ip) + }) + } + next.ServeHTTP(w, r) + }) + } +} + // UserAgentHandler adds the request's user-agent as a field to the context's logger // using fieldKey as field key. func UserAgentHandler(fieldKey string) func(next http.Handler) http.Handler { @@ -135,6 +166,21 @@ func ProtoHandler(fieldKey string) func(next http.Handler) http.Handler { } } +// HTTPVersionHandler is similar to ProtoHandler, but it does not store the "HTTP/" +// prefix in the protocol name. +func HTTPVersionHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + proto := strings.TrimPrefix(r.Proto, "HTTP/") + log := zerolog.Ctx(r.Context()) + log.UpdateContext(func(c zerolog.Context) zerolog.Context { + return c.Str(fieldKey, proto) + }) + next.ServeHTTP(w, r) + }) + } +} + type idKey struct{} // IDFromRequest returns the unique id associated to the request if any. @@ -205,14 +251,76 @@ func CustomHeaderHandler(fieldKey, header string) func(next http.Handler) http.H } } +// EtagHandler adds Etag header from response's header as a field to +// the context's logger using fieldKey as field key. +func EtagHandler(fieldKey string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + defer func() { + etag := w.Header().Get("Etag") + if etag != "" { + etag = strings.ReplaceAll(etag, `"`, "") + log := zerolog.Ctx(r.Context()) + log.UpdateContext(func(c zerolog.Context) zerolog.Context { + return c.Str(fieldKey, etag) + }) + } + }() + next.ServeHTTP(w, r) + }) + } +} + +func ResponseHeaderHandler(fieldKey, headerName string) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + defer func() { + value := w.Header().Get(headerName) + if value != "" { + log := zerolog.Ctx(r.Context()) + log.UpdateContext(func(c zerolog.Context) zerolog.Context { + return c.Str(fieldKey, value) + }) + } + }() + 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 { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() lw := mutil.WrapWriter(w) + defer func() { + f(r, lw.Status(), lw.BytesWritten(), time.Since(start)) + }() next.ServeHTTP(lw, r) - f(r, lw.Status(), lw.BytesWritten(), time.Since(start)) + }) + } +} + +// HostHandler adds the request's host as a field to the context's logger +// using fieldKey as field key. If trimPort is set to true, then port is +// removed from the host. +func HostHandler(fieldKey string, trimPort ...bool) func(next http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + var host string + if len(trimPort) > 0 && trimPort[0] { + host = getHost(r.Host) + } else { + host = r.Host + } + if host != "" { + log := zerolog.Ctx(r.Context()) + log.UpdateContext(func(c zerolog.Context) zerolog.Context { + return c.Str(fieldKey, host) + }) + } + next.ServeHTTP(w, r) }) } } diff --git a/hlog/hlog_test.go b/hlog/hlog_test.go index c584e98b..445d6b6f 100644 --- a/hlog/hlog_test.go +++ b/hlog/hlog_test.go @@ -7,7 +7,7 @@ import ( "bytes" "context" "fmt" - "io/ioutil" + "io" "net/http" "net/http/httptest" "net/url" @@ -122,6 +122,38 @@ func TestRemoteAddrHandlerIPv6(t *testing.T) { } } +func TestRemoteIPHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + RemoteAddr: "1.2.3.4:1234", + } + h := RemoteIPHandler("ip")(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 := `{"ip":"1.2.3.4"}`+"\n", decodeIfBinary(out); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } +} + +func TestRemoteIPHandlerIPv6(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + RemoteAddr: "[2001:db8:a0b:12f0::1]:1234", + } + h := RemoteIPHandler("ip")(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 := `{"ip":"2001:db8:a0b:12f0::1"}`+"\n", decodeIfBinary(out); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } +} + func TestUserAgentHandler(t *testing.T) { out := &bytes.Buffer{} r := &http.Request{ @@ -201,6 +233,46 @@ func TestCustomHeaderHandler(t *testing.T) { } } +func TestEtagHandler(t *testing.T) { + out := &bytes.Buffer{} + w := httptest.NewRecorder() + r := &http.Request{} + h := EtagHandler("etag")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Etag", `"abcdef"`) + w.WriteHeader(http.StatusOK) + })) + h2 := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + h.ServeHTTP(w, r) + l := FromRequest(r) + l.Log().Msg("") + }) + h3 := NewHandler(zerolog.New(out))(h2) + h3.ServeHTTP(w, r) + if want, got := `{"etag":"abcdef"}`+"\n", decodeIfBinary(out); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } +} + +func TestResponseHeaderHandler(t *testing.T) { + out := &bytes.Buffer{} + w := httptest.NewRecorder() + r := &http.Request{} + h := ResponseHeaderHandler("encoding", "Content-Encoding")(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Encoding", `gzip`) + w.WriteHeader(http.StatusOK) + })) + h2 := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + h.ServeHTTP(w, r) + l := FromRequest(r) + l.Log().Msg("") + }) + h3 := NewHandler(zerolog.New(out))(h2) + h3.ServeHTTP(w, r) + if want, got := `{"encoding":"gzip"}`+"\n", decodeIfBinary(out); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } +} + func TestProtoHandler(t *testing.T) { out := &bytes.Buffer{} r := &http.Request{ @@ -217,6 +289,22 @@ func TestProtoHandler(t *testing.T) { } } +func TestHTTPVersionHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{ + Proto: "HTTP/1.1", + } + h := HTTPVersionHandler("proto")(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 := `{"proto":"1.1"}`+"\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{ @@ -245,10 +333,10 @@ func BenchmarkHandlers(b *testing.B) { })) h2 := MethodHandler("method")(RequestHandler("request")(h1)) handlers := map[string]http.Handler{ - "Single": NewHandler(zerolog.New(ioutil.Discard))(h1), - "Combined": NewHandler(zerolog.New(ioutil.Discard))(h2), - "SingleDisabled": NewHandler(zerolog.New(ioutil.Discard).Level(zerolog.Disabled))(h1), - "CombinedDisabled": NewHandler(zerolog.New(ioutil.Discard).Level(zerolog.Disabled))(h2), + "Single": NewHandler(zerolog.New(io.Discard))(h1), + "Combined": NewHandler(zerolog.New(io.Discard))(h2), + "SingleDisabled": NewHandler(zerolog.New(io.Discard).Level(zerolog.Disabled))(h1), + "CombinedDisabled": NewHandler(zerolog.New(io.Discard).Level(zerolog.Disabled))(h2), } for name := range handlers { h := handlers[name] @@ -292,3 +380,56 @@ func TestCtxWithID(t *testing.T) { t.Errorf("CtxWithID() = %v, want %v", got, want) } } + +func TestHostHandler(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{Host: "example.com:8080"} + h := HostHandler("host")(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 := `{"host":"example.com:8080"}`+"\n", decodeIfBinary(out); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } +} + +func TestHostHandlerWithoutPort(t *testing.T) { + out := &bytes.Buffer{} + r := &http.Request{Host: "example.com:8080"} + h := HostHandler("host", true)(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 := `{"host":"example.com"}`+"\n", decodeIfBinary(out); want != got { + t.Errorf("Invalid log output, got: %s, want: %s", got, want) + } +} + +func TestGetHost(t *testing.T) { + tests := []struct { + input string + expected string + }{ + {"", ""}, + {"example.com:8080", "example.com"}, + {"example.com", "example.com"}, + {"invalid", "invalid"}, + {"192.168.0.1:8080", "192.168.0.1"}, + {"[2001:0db8:85a3:0000:0000:8a2e:0370:7334]:8080", "2001:0db8:85a3:0000:0000:8a2e:0370:7334"}, + {"こんにちは.com:8080", "こんにちは.com"}, + } + + for _, tt := range tests { + tt := tt + t.Run(tt.input, func(t *testing.T) { + result := getHost(tt.input) + if tt.expected != result { + t.Errorf("Invalid log output, got: %s, want: %s", result, tt.expected) + } + }) + } +} diff --git a/hook_test.go b/hook_test.go index 19bde9d4..100b71e6 100644 --- a/hook_test.go +++ b/hook_test.go @@ -2,10 +2,15 @@ package zerolog import ( "bytes" - "io/ioutil" + "context" + "io" "testing" ) +type contextKeyType int + +var contextKey contextKeyType + var ( levelNameHook = HookFunc(func(e *Event, level Level, msg string) { levelName := level.String() @@ -31,6 +36,12 @@ var ( discardHook = HookFunc(func(e *Event, level Level, message string) { e.Discard() }) + contextHook = HookFunc(func(e *Event, level Level, message string) { + contextData, ok := e.GetCtx().Value(contextKey).(string) + if ok { + e.Str("context-data", contextData) + } + }) ) func TestHook(t *testing.T) { @@ -120,6 +131,29 @@ func TestHook(t *testing.T) { log = log.Hook(discardHook) log.Log().Msg("test message") }}, + {"Context/Background", `{"level":"info","message":"test message"}` + "\n", func(log Logger) { + log = log.Hook(contextHook) + log.Info().Ctx(context.Background()).Msg("test message") + }}, + {"Context/nil", `{"level":"info","message":"test message"}` + "\n", func(log Logger) { + // passing `nil` where a context is wanted is against + // the rules, but people still do it. + log = log.Hook(contextHook) + log.Info().Ctx(nil).Msg("test message") // nolint + }}, + {"Context/valid", `{"level":"info","context-data":"12345abcdef","message":"test message"}` + "\n", func(log Logger) { + ctx := context.Background() + ctx = context.WithValue(ctx, contextKey, "12345abcdef") + log = log.Hook(contextHook) + log.Info().Ctx(ctx).Msg("test message") + }}, + {"Context/With/valid", `{"level":"info","context-data":"12345abcdef","message":"test message"}` + "\n", func(log Logger) { + ctx := context.Background() + ctx = context.WithValue(ctx, contextKey, "12345abcdef") + log = log.Hook(contextHook) + log = log.With().Ctx(ctx).Logger() + log.Info().Msg("test message") + }}, {"None", `{"level":"error"}` + "\n", func(log Logger) { log.Error().Msg("") }}, @@ -138,7 +172,7 @@ func TestHook(t *testing.T) { } func BenchmarkHooks(b *testing.B) { - logger := New(ioutil.Discard) + logger := New(io.Discard) b.ResetTimer() b.Run("Nop/Single", func(b *testing.B) { log := logger.Hook(nopHook) diff --git a/internal/cbor/cbor.go b/internal/cbor/cbor.go index bc54e37a..1bf14438 100644 --- a/internal/cbor/cbor.go +++ b/internal/cbor/cbor.go @@ -26,7 +26,8 @@ const ( additionalTypeBreak byte = 31 // Tag Sub-types. - additionalTypeTimestamp byte = 01 + additionalTypeTimestamp byte = 01 + additionalTypeEmbeddedCBOR byte = 63 // Extended Tags - from https://www.iana.org/assignments/cbor-tags/cbor-tags.xhtml additionalTypeTagNetworkAddr uint16 = 260 diff --git a/internal/cbor/decode_stream.go b/internal/cbor/decode_stream.go index fc16f98c..5633e666 100644 --- a/internal/cbor/decode_stream.go +++ b/internal/cbor/decode_stream.go @@ -5,6 +5,7 @@ package cbor import ( "bufio" "bytes" + "encoding/base64" "fmt" "io" "math" @@ -94,7 +95,7 @@ func decodeFloat(src *bufio.Reader) (float64, int) { switch minor { case additionalTypeFloat16: - panic(fmt.Errorf("float16 is not suppported in decodeFloat")) + panic(fmt.Errorf("float16 is not supported in decodeFloat")) case additionalTypeFloat32: pb := readNBytes(src, 4) @@ -213,6 +214,31 @@ func decodeString(src *bufio.Reader, noQuotes bool) []byte { } return append(result, '"') } +func decodeStringToDataUrl(src *bufio.Reader, mimeType string) []byte { + pb := readByte(src) + major := pb & maskOutAdditionalType + minor := pb & maskOutMajorType + if major != majorTypeByteString { + panic(fmt.Errorf("Major type is: %d in decodeString", major)) + } + length := decodeIntAdditionalType(src, minor) + l := int(length) + enc := base64.StdEncoding + lEnc := enc.EncodedLen(l) + result := make([]byte, len("\"data:;base64,\"")+len(mimeType)+lEnc) + dest := result + u := copy(dest, "\"data:") + dest = dest[u:] + u = copy(dest, mimeType) + dest = dest[u:] + u = copy(dest, ";base64,") + dest = dest[u:] + pbs := readNBytes(src, l) + enc.Encode(dest, pbs) + dest = dest[lEnc:] + dest[0] = '"' + return result +} func decodeUTF8String(src *bufio.Reader) []byte { pb := readByte(src) @@ -349,6 +375,20 @@ func decodeTagData(src *bufio.Reader) []byte { switch minor { case additionalTypeTimestamp: return decodeTimeStamp(src) + case additionalTypeIntUint8: + val := decodeIntAdditionalType(src, minor) + switch byte(val) { + case additionalTypeEmbeddedCBOR: + pb := readByte(src) + dataMajor := pb & maskOutAdditionalType + if dataMajor != majorTypeByteString { + panic(fmt.Errorf("Unsupported embedded Type: %d in decodeEmbeddedCBOR", dataMajor)) + } + src.UnreadByte() + return decodeStringToDataUrl(src, "application/cbor") + default: + panic(fmt.Errorf("Unsupported Additional Tag Type: %d in decodeTagData", val)) + } // Tag value is larger than 256 (so uint16). case additionalTypeIntUint16: diff --git a/internal/cbor/string.go b/internal/cbor/string.go index a33890a5..9fc9a4f8 100644 --- a/internal/cbor/string.go +++ b/internal/cbor/string.go @@ -93,3 +93,25 @@ func AppendEmbeddedJSON(dst, s []byte) []byte { } return append(dst, s...) } + +// AppendEmbeddedCBOR adds a tag and embeds input CBOR as such. +func AppendEmbeddedCBOR(dst, s []byte) []byte { + major := majorTypeTags + minor := additionalTypeEmbeddedCBOR + + // Append the TAG to indicate this is Embedded JSON. + dst = append(dst, major|additionalTypeIntUint8) + dst = append(dst, minor) + + // Append the CBOR Object as Byte String. + major = majorTypeByteString + + l := len(s) + if l <= additionalMax { + lb := byte(l) + dst = append(dst, major|lb) + } else { + dst = appendCborTypePrefix(dst, major, uint64(l)) + } + return append(dst, s...) +} diff --git a/internal/cbor/time.go b/internal/cbor/time.go index d81fb125..7c0eccee 100644 --- a/internal/cbor/time.go +++ b/internal/cbor/time.go @@ -29,7 +29,7 @@ func (e Encoder) appendFloatTimestamp(dst []byte, t time.Time) []byte { nanos := t.Nanosecond() var val float64 val = float64(secs)*1.0 + float64(nanos)*1e-9 - return e.AppendFloat64(dst, val) + return e.AppendFloat64(dst, val, -1) } // AppendTime encodes and adds a timestamp to the dst byte array. @@ -64,17 +64,17 @@ func (e Encoder) AppendTimes(dst []byte, vals []time.Time, unused string) []byte // AppendDuration encodes and adds a duration to the dst byte array. // useInt field indicates whether to store the duration as seconds (integer) or // as seconds+nanoseconds (float). -func (e Encoder) AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool) []byte { +func (e Encoder) AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool, unused int) []byte { if useInt { return e.AppendInt64(dst, int64(d/unit)) } - return e.AppendFloat64(dst, float64(d)/float64(unit)) + return e.AppendFloat64(dst, float64(d)/float64(unit), unused) } // AppendDurations encodes and adds an array of durations to the dst byte array. // useInt field indicates whether to store the duration as seconds (integer) or // as seconds+nanoseconds (float). -func (e Encoder) AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool) []byte { +func (e Encoder) AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool, unused int) []byte { major := majorTypeArray l := len(vals) if l == 0 { @@ -87,7 +87,7 @@ func (e Encoder) AppendDurations(dst []byte, vals []time.Duration, unit time.Dur dst = appendCborTypePrefix(dst, major, uint64(l)) } for _, d := range vals { - dst = e.AppendDuration(dst, d, unit, useInt) + dst = e.AppendDuration(dst, d, unit, useInt, unused) } return dst } diff --git a/internal/cbor/types.go b/internal/cbor/types.go index 6f538328..454d68bd 100644 --- a/internal/cbor/types.go +++ b/internal/cbor/types.go @@ -352,7 +352,7 @@ func (e Encoder) AppendUints64(dst []byte, vals []uint64) []byte { } // AppendFloat32 encodes and inserts a single precision float value into the dst byte array. -func (Encoder) AppendFloat32(dst []byte, val float32) []byte { +func (Encoder) AppendFloat32(dst []byte, val float32, unused int) []byte { switch { case math.IsNaN(float64(val)): return append(dst, "\xfa\x7f\xc0\x00\x00"...) @@ -372,7 +372,7 @@ func (Encoder) AppendFloat32(dst []byte, val float32) []byte { } // AppendFloats32 encodes and inserts an array of single precision float value into the dst byte array. -func (e Encoder) AppendFloats32(dst []byte, vals []float32) []byte { +func (e Encoder) AppendFloats32(dst []byte, vals []float32, unused int) []byte { major := majorTypeArray l := len(vals) if l == 0 { @@ -385,13 +385,13 @@ func (e Encoder) AppendFloats32(dst []byte, vals []float32) []byte { dst = appendCborTypePrefix(dst, major, uint64(l)) } for _, v := range vals { - dst = e.AppendFloat32(dst, v) + dst = e.AppendFloat32(dst, v, unused) } return dst } // AppendFloat64 encodes and inserts a double precision float value into the dst byte array. -func (Encoder) AppendFloat64(dst []byte, val float64) []byte { +func (Encoder) AppendFloat64(dst []byte, val float64, unused int) []byte { switch { case math.IsNaN(val): return append(dst, "\xfb\x7f\xf8\x00\x00\x00\x00\x00\x00"...) @@ -412,7 +412,7 @@ func (Encoder) AppendFloat64(dst []byte, val float64) []byte { } // AppendFloats64 encodes and inserts an array of double precision float values into the dst byte array. -func (e Encoder) AppendFloats64(dst []byte, vals []float64) []byte { +func (e Encoder) AppendFloats64(dst []byte, vals []float64, unused int) []byte { major := majorTypeArray l := len(vals) if l == 0 { @@ -425,7 +425,7 @@ func (e Encoder) AppendFloats64(dst []byte, vals []float64) []byte { dst = appendCborTypePrefix(dst, major, uint64(l)) } for _, v := range vals { - dst = e.AppendFloat64(dst, v) + dst = e.AppendFloat64(dst, v, unused) } return dst } diff --git a/internal/cbor/types_test.go b/internal/cbor/types_test.go index 2fbb162a..23093b12 100644 --- a/internal/cbor/types_test.go +++ b/internal/cbor/types_test.go @@ -169,7 +169,7 @@ var float32TestCases = []struct { func TestAppendFloat32(t *testing.T) { for _, tc := range float32TestCases { - s := enc.AppendFloat32([]byte{}, tc.val) + s := enc.AppendFloat32([]byte{}, tc.val, -1) got := string(s) if got != tc.binary { t.Errorf("AppendFloat32(%f)=0x%s, want: 0x%s", @@ -306,9 +306,9 @@ func BenchmarkAppendFloat(b *testing.B) { for i := 0; i < b.N; i++ { switch str.sz { case 4: - _ = enc.AppendFloat32(buf, float32(str.val)) + _ = enc.AppendFloat32(buf, float32(str.val), -1) case 8: - _ = enc.AppendFloat64(buf, str.val) + _ = enc.AppendFloat64(buf, str.val, -1) } } }) diff --git a/internal/json/time.go b/internal/json/time.go index 6a8dc912..08cbbd9b 100644 --- a/internal/json/time.go +++ b/internal/json/time.go @@ -88,24 +88,24 @@ func appendUnixNanoTimes(dst []byte, vals []time.Time, div int64) []byte { // 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 { +func (e Encoder) AppendDuration(dst []byte, d time.Duration, unit time.Duration, useInt bool, precision int) []byte { if useInt { return strconv.AppendInt(dst, int64(d/unit), 10) } - return e.AppendFloat64(dst, float64(d)/float64(unit)) + return e.AppendFloat64(dst, float64(d)/float64(unit), precision) } // AppendDurations formats the input durations with the given unit & format // and appends the encoded string list to the input byte slice. -func (e Encoder) AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool) []byte { +func (e Encoder) AppendDurations(dst []byte, vals []time.Duration, unit time.Duration, useInt bool, precision int) []byte { if len(vals) == 0 { return append(dst, '[', ']') } dst = append(dst, '[') - dst = e.AppendDuration(dst, vals[0], unit, useInt) + dst = e.AppendDuration(dst, vals[0], unit, useInt, precision) if len(vals) > 1 { for _, d := range vals[1:] { - dst = e.AppendDuration(append(dst, ','), d, unit, useInt) + dst = e.AppendDuration(append(dst, ','), d, unit, useInt, precision) } } dst = append(dst, ']') diff --git a/internal/json/types.go b/internal/json/types.go index ef3a2a7a..7930491a 100644 --- a/internal/json/types.go +++ b/internal/json/types.go @@ -299,7 +299,7 @@ func (Encoder) AppendUints64(dst []byte, vals []uint64) []byte { return dst } -func appendFloat(dst []byte, val float64, bitSize int) []byte { +func appendFloat(dst []byte, val float64, bitSize, precision int) []byte { // JSON does not permit NaN or Infinity. A typical JSON encoder would fail // with an error, but a logging library wants the data to get through so we // make a tradeoff and store those types as string. @@ -311,26 +311,47 @@ func appendFloat(dst []byte, val float64, bitSize int) []byte { case math.IsInf(val, -1): return append(dst, `"-Inf"`...) } - return strconv.AppendFloat(dst, val, 'f', -1, bitSize) + // convert as if by es6 number to string conversion + // see also https://cs.opensource.google/go/go/+/refs/tags/go1.20.3:src/encoding/json/encode.go;l=573 + strFmt := byte('f') + // If precision is set to a value other than -1, we always just format the float using that precision. + if precision == -1 { + // Use float32 comparisons for underlying float32 value to get precise cutoffs right. + if abs := math.Abs(val); abs != 0 { + if bitSize == 64 && (abs < 1e-6 || abs >= 1e21) || bitSize == 32 && (float32(abs) < 1e-6 || float32(abs) >= 1e21) { + strFmt = 'e' + } + } + } + dst = strconv.AppendFloat(dst, val, strFmt, precision, bitSize) + if strFmt == 'e' { + // Clean up e-09 to e-9 + n := len(dst) + if n >= 4 && dst[n-4] == 'e' && dst[n-3] == '-' && dst[n-2] == '0' { + dst[n-2] = dst[n-1] + dst = dst[:n-1] + } + } + return dst } // AppendFloat32 converts the input float32 to a string and // appends the encoded string to the input byte slice. -func (Encoder) AppendFloat32(dst []byte, val float32) []byte { - return appendFloat(dst, float64(val), 32) +func (Encoder) AppendFloat32(dst []byte, val float32, precision int) []byte { + return appendFloat(dst, float64(val), 32, precision) } // AppendFloats32 encodes the input float32s to json and // appends the encoded string list to the input byte slice. -func (Encoder) AppendFloats32(dst []byte, vals []float32) []byte { +func (Encoder) AppendFloats32(dst []byte, vals []float32, precision int) []byte { if len(vals) == 0 { return append(dst, '[', ']') } dst = append(dst, '[') - dst = appendFloat(dst, float64(vals[0]), 32) + dst = appendFloat(dst, float64(vals[0]), 32, precision) if len(vals) > 1 { for _, val := range vals[1:] { - dst = appendFloat(append(dst, ','), float64(val), 32) + dst = appendFloat(append(dst, ','), float64(val), 32, precision) } } dst = append(dst, ']') @@ -339,21 +360,21 @@ func (Encoder) AppendFloats32(dst []byte, vals []float32) []byte { // AppendFloat64 converts the input float64 to a string and // appends the encoded string to the input byte slice. -func (Encoder) AppendFloat64(dst []byte, val float64) []byte { - return appendFloat(dst, val, 64) +func (Encoder) AppendFloat64(dst []byte, val float64, precision int) []byte { + return appendFloat(dst, val, 64, precision) } // AppendFloats64 encodes the input float64s to json and // appends the encoded string list to the input byte slice. -func (Encoder) AppendFloats64(dst []byte, vals []float64) []byte { +func (Encoder) AppendFloats64(dst []byte, vals []float64, precision int) []byte { if len(vals) == 0 { return append(dst, '[', ']') } dst = append(dst, '[') - dst = appendFloat(dst, vals[0], 64) + dst = appendFloat(dst, vals[0], 64, precision) if len(vals) > 1 { for _, val := range vals[1:] { - dst = appendFloat(append(dst, ','), val, 64) + dst = appendFloat(append(dst, ','), val, 64, precision) } } dst = append(dst, ']') diff --git a/internal/json/types_test.go b/internal/json/types_test.go index 26dc3e80..217cd3a2 100644 --- a/internal/json/types_test.go +++ b/internal/json/types_test.go @@ -1,7 +1,9 @@ package json import ( + "encoding/json" "math" + "math/rand" "net" "reflect" "testing" @@ -9,18 +11,20 @@ import ( func TestAppendType(t *testing.T) { w := map[string]func(interface{}) []byte{ - "AppendInt": func(v interface{}) []byte { return enc.AppendInt([]byte{}, v.(int)) }, - "AppendInt8": func(v interface{}) []byte { return enc.AppendInt8([]byte{}, v.(int8)) }, - "AppendInt16": func(v interface{}) []byte { return enc.AppendInt16([]byte{}, v.(int16)) }, - "AppendInt32": func(v interface{}) []byte { return enc.AppendInt32([]byte{}, v.(int32)) }, - "AppendInt64": func(v interface{}) []byte { return enc.AppendInt64([]byte{}, v.(int64)) }, - "AppendUint": func(v interface{}) []byte { return enc.AppendUint([]byte{}, v.(uint)) }, - "AppendUint8": func(v interface{}) []byte { return enc.AppendUint8([]byte{}, v.(uint8)) }, - "AppendUint16": func(v interface{}) []byte { return enc.AppendUint16([]byte{}, v.(uint16)) }, - "AppendUint32": func(v interface{}) []byte { return enc.AppendUint32([]byte{}, v.(uint32)) }, - "AppendUint64": func(v interface{}) []byte { return enc.AppendUint64([]byte{}, v.(uint64)) }, - "AppendFloat32": func(v interface{}) []byte { return enc.AppendFloat32([]byte{}, v.(float32)) }, - "AppendFloat64": func(v interface{}) []byte { return enc.AppendFloat64([]byte{}, v.(float64)) }, + "AppendInt": func(v interface{}) []byte { return enc.AppendInt([]byte{}, v.(int)) }, + "AppendInt8": func(v interface{}) []byte { return enc.AppendInt8([]byte{}, v.(int8)) }, + "AppendInt16": func(v interface{}) []byte { return enc.AppendInt16([]byte{}, v.(int16)) }, + "AppendInt32": func(v interface{}) []byte { return enc.AppendInt32([]byte{}, v.(int32)) }, + "AppendInt64": func(v interface{}) []byte { return enc.AppendInt64([]byte{}, v.(int64)) }, + "AppendUint": func(v interface{}) []byte { return enc.AppendUint([]byte{}, v.(uint)) }, + "AppendUint8": func(v interface{}) []byte { return enc.AppendUint8([]byte{}, v.(uint8)) }, + "AppendUint16": func(v interface{}) []byte { return enc.AppendUint16([]byte{}, v.(uint16)) }, + "AppendUint32": func(v interface{}) []byte { return enc.AppendUint32([]byte{}, v.(uint32)) }, + "AppendUint64": func(v interface{}) []byte { return enc.AppendUint64([]byte{}, v.(uint64)) }, + "AppendFloat32": func(v interface{}) []byte { return enc.AppendFloat32([]byte{}, v.(float32), -1) }, + "AppendFloat64": func(v interface{}) []byte { return enc.AppendFloat64([]byte{}, v.(float64), -1) }, + "AppendFloat32SmallPrecision": func(v interface{}) []byte { return enc.AppendFloat32([]byte{}, v.(float32), 1) }, + "AppendFloat64SmallPrecision": func(v interface{}) []byte { return enc.AppendFloat64([]byte{}, v.(float64), 1) }, } tests := []struct { name string @@ -44,7 +48,7 @@ func TestAppendType(t *testing.T) { {"AppendFloat32(0)", "AppendFloat32", float32(0), []byte(`0`)}, {"AppendFloat32(-1.1)", "AppendFloat32", float32(-1.1), []byte(`-1.1`)}, {"AppendFloat32(1e20)", "AppendFloat32", float32(1e20), []byte(`100000000000000000000`)}, - {"AppendFloat32(1e21)", "AppendFloat32", float32(1e21), []byte(`1000000000000000000000`)}, + {"AppendFloat32(1e21)", "AppendFloat32", float32(1e21), []byte(`1e+21`)}, {"AppendFloat64(-Inf)", "AppendFloat64", float64(math.Inf(-1)), []byte(`"-Inf"`)}, {"AppendFloat64(+Inf)", "AppendFloat64", float64(math.Inf(1)), []byte(`"+Inf"`)}, @@ -52,7 +56,10 @@ func TestAppendType(t *testing.T) { {"AppendFloat64(0)", "AppendFloat64", float64(0), []byte(`0`)}, {"AppendFloat64(-1.1)", "AppendFloat64", float64(-1.1), []byte(`-1.1`)}, {"AppendFloat64(1e20)", "AppendFloat64", float64(1e20), []byte(`100000000000000000000`)}, - {"AppendFloat64(1e21)", "AppendFloat64", float64(1e21), []byte(`1000000000000000000000`)}, + {"AppendFloat64(1e21)", "AppendFloat64", float64(1e21), []byte(`1e+21`)}, + + {"AppendFloat32SmallPrecision(-1.123)", "AppendFloat32SmallPrecision", float32(-1.123), []byte(`-1.1`)}, + {"AppendFloat64SmallPrecision(-1.123)", "AppendFloat64SmallPrecision", float64(-1.123), []byte(`-1.1`)}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { @@ -207,3 +214,340 @@ func Test_appendObjectData(t *testing.T) { }) } } + +var float64Tests = []struct { + Name string + Val float64 + Want string +}{ + { + Name: "Positive integer", + Val: 1234.0, + Want: "1234", + }, + { + Name: "Negative integer", + Val: -5678.0, + Want: "-5678", + }, + { + Name: "Positive decimal", + Val: 12.3456, + Want: "12.3456", + }, + { + Name: "Negative decimal", + Val: -78.9012, + Want: "-78.9012", + }, + { + Name: "Large positive number", + Val: 123456789.0, + Want: "123456789", + }, + { + Name: "Large negative number", + Val: -987654321.0, + Want: "-987654321", + }, + { + Name: "Zero", + Val: 0.0, + Want: "0", + }, + { + Name: "Smallest positive value", + Val: math.SmallestNonzeroFloat64, + Want: "5e-324", + }, + { + Name: "Largest positive value", + Val: math.MaxFloat64, + Want: "1.7976931348623157e+308", + }, + { + Name: "Smallest negative value", + Val: -math.SmallestNonzeroFloat64, + Want: "-5e-324", + }, + { + Name: "Largest negative value", + Val: -math.MaxFloat64, + Want: "-1.7976931348623157e+308", + }, + { + Name: "NaN", + Val: math.NaN(), + Want: `"NaN"`, + }, + { + Name: "+Inf", + Val: math.Inf(1), + Want: `"+Inf"`, + }, + { + Name: "-Inf", + Val: math.Inf(-1), + Want: `"-Inf"`, + }, + { + Name: "Clean up e-09 to e-9 case 1", + Val: 1e-9, + Want: "1e-9", + }, + { + Name: "Clean up e-09 to e-9 case 2", + Val: -2.236734e-9, + Want: "-2.236734e-9", + }, +} + +func TestEncoder_AppendFloat64(t *testing.T) { + for _, tc := range float64Tests { + t.Run(tc.Name, func(t *testing.T) { + var b []byte + b = (Encoder{}).AppendFloat64(b, tc.Val, -1) + if s := string(b); tc.Want != s { + t.Errorf("%q", s) + } + }) + } +} + +func FuzzEncoder_AppendFloat64(f *testing.F) { + for _, tc := range float64Tests { + f.Add(tc.Val) + } + f.Fuzz(func(t *testing.T, val float64) { + actual := (Encoder{}).AppendFloat64(nil, val, -1) + if len(actual) == 0 { + t.Fatal("empty buffer") + } + + if actual[0] == '"' { + switch string(actual) { + case `"NaN"`: + if !math.IsNaN(val) { + t.Fatalf("expected %v got NaN", val) + } + case `"+Inf"`: + if !math.IsInf(val, 1) { + t.Fatalf("expected %v got +Inf", val) + } + case `"-Inf"`: + if !math.IsInf(val, -1) { + t.Fatalf("expected %v got -Inf", val) + } + default: + t.Fatalf("unexpected string: %s", actual) + } + return + } + + if expected, err := json.Marshal(val); err != nil { + t.Error(err) + } else if string(actual) != string(expected) { + t.Errorf("expected %s, got %s", expected, actual) + } + + var parsed float64 + if err := json.Unmarshal(actual, &parsed); err != nil { + t.Fatal(err) + } + + if parsed != val { + t.Fatalf("expected %v, got %v", val, parsed) + } + }) +} + +var float32Tests = []struct { + Name string + Val float32 + Want string +}{ + { + Name: "Positive integer", + Val: 1234.0, + Want: "1234", + }, + { + Name: "Negative integer", + Val: -5678.0, + Want: "-5678", + }, + { + Name: "Positive decimal", + Val: 12.3456, + Want: "12.3456", + }, + { + Name: "Negative decimal", + Val: -78.9012, + Want: "-78.9012", + }, + { + Name: "Large positive number", + Val: 123456789.0, + Want: "123456790", + }, + { + Name: "Large negative number", + Val: -987654321.0, + Want: "-987654340", + }, + { + Name: "Zero", + Val: 0.0, + Want: "0", + }, + { + Name: "Smallest positive value", + Val: math.SmallestNonzeroFloat32, + Want: "1e-45", + }, + { + Name: "Largest positive value", + Val: math.MaxFloat32, + Want: "3.4028235e+38", + }, + { + Name: "Smallest negative value", + Val: -math.SmallestNonzeroFloat32, + Want: "-1e-45", + }, + { + Name: "Largest negative value", + Val: -math.MaxFloat32, + Want: "-3.4028235e+38", + }, + { + Name: "NaN", + Val: float32(math.NaN()), + Want: `"NaN"`, + }, + { + Name: "+Inf", + Val: float32(math.Inf(1)), + Want: `"+Inf"`, + }, + { + Name: "-Inf", + Val: float32(math.Inf(-1)), + Want: `"-Inf"`, + }, + { + Name: "Clean up e-09 to e-9 case 1", + Val: 1e-9, + Want: "1e-9", + }, + { + Name: "Clean up e-09 to e-9 case 2", + Val: -2.236734e-9, + Want: "-2.236734e-9", + }, +} + +func TestEncoder_AppendFloat32(t *testing.T) { + for _, tc := range float32Tests { + t.Run(tc.Name, func(t *testing.T) { + var b []byte + b = (Encoder{}).AppendFloat32(b, tc.Val, -1) + if s := string(b); tc.Want != s { + t.Errorf("%q", s) + } + }) + } +} + +func FuzzEncoder_AppendFloat32(f *testing.F) { + for _, tc := range float32Tests { + f.Add(tc.Val) + } + f.Fuzz(func(t *testing.T, val float32) { + actual := (Encoder{}).AppendFloat32(nil, val, -1) + if len(actual) == 0 { + t.Fatal("empty buffer") + } + + if actual[0] == '"' { + val := float64(val) + switch string(actual) { + case `"NaN"`: + if !math.IsNaN(val) { + t.Fatalf("expected %v got NaN", val) + } + case `"+Inf"`: + if !math.IsInf(val, 1) { + t.Fatalf("expected %v got +Inf", val) + } + case `"-Inf"`: + if !math.IsInf(val, -1) { + t.Fatalf("expected %v got -Inf", val) + } + default: + t.Fatalf("unexpected string: %s", actual) + } + return + } + + if expected, err := json.Marshal(val); err != nil { + t.Error(err) + } else if string(actual) != string(expected) { + t.Errorf("expected %s, got %s", expected, actual) + } + + var parsed float32 + if err := json.Unmarshal(actual, &parsed); err != nil { + t.Fatal(err) + } + + if parsed != val { + t.Fatalf("expected %v, got %v", val, parsed) + } + }) +} + +func generateFloat32s(n int) []float32 { + floats := make([]float32, n) + for i := 0; i < n; i++ { + floats[i] = rand.Float32() + } + return floats +} + +func generateFloat64s(n int) []float64 { + floats := make([]float64, n) + for i := 0; i < n; i++ { + floats[i] = rand.Float64() + } + return floats +} + +// this is really just for the memory allocation characteristics +func BenchmarkEncoder_AppendFloat32(b *testing.B) { + floats := append(generateFloat32s(5000), float32(math.NaN()), float32(math.Inf(1)), float32(math.Inf(-1))) + dst := make([]byte, 0, 128) + + b.ResetTimer() + + for i := 0; i < b.N; i++ { + for _, f := range floats { + dst = (Encoder{}).AppendFloat32(dst[:0], f, -1) + } + } +} + +// this is really just for the memory allocation characteristics +func BenchmarkEncoder_AppendFloat64(b *testing.B) { + floats := append(generateFloat64s(5000), math.NaN(), math.Inf(1), math.Inf(-1)) + dst := make([]byte, 0, 128) + + b.ResetTimer() + + for i := 0; i < b.N; i++ { + for _, f := range floats { + dst = (Encoder{}).AppendFloat64(dst[:0], f, -1) + } + } +} diff --git a/log.go b/log.go index 4afef6ff..3a3ea256 100644 --- a/log.go +++ b/log.go @@ -24,7 +24,7 @@ // // Sub-loggers let you chain loggers with additional context: // -// sublogger := log.With().Str("component": "foo").Logger() +// sublogger := log.With().Str("component", "foo").Logger() // sublogger.Info().Msg("hello world") // // Output: {"time":1494567715,"level":"info","message":"hello world","component":"foo"} // @@ -84,6 +84,8 @@ // // # Caveats // +// Field duplication: +// // There is no fields deduplication out-of-the-box. // Using the same key multiple times creates new key in final JSON each time. // @@ -95,13 +97,27 @@ // // In this case, many consumers will take the last value, // but this is not guaranteed; check yours if in doubt. +// +// Concurrency safety: +// +// Be careful when calling UpdateContext. It is not concurrency safe. Use the With method to create a child logger: +// +// func handler(w http.ResponseWriter, r *http.Request) { +// // Create a child logger for concurrency safety +// logger := log.Logger.With().Logger() +// +// // Add context fields, for example User-Agent from HTTP headers +// logger.UpdateContext(func(c zerolog.Context) zerolog.Context { +// ... +// }) +// } package zerolog import ( + "context" "errors" "fmt" "io" - "io/ioutil" "os" "strconv" "strings" @@ -223,6 +239,7 @@ type Logger struct { context []byte hooks []Hook stack bool + ctx context.Context } // New creates a root logger with given output writer. If the output writer implements @@ -234,11 +251,11 @@ type Logger struct { // you may consider using sync wrapper. func New(w io.Writer) Logger { if w == nil { - w = ioutil.Discard + w = io.Discard } lw, ok := w.(LevelWriter) if !ok { - lw = levelWriterAdapter{w} + lw = LevelWriterAdapter{w} } return Logger{w: lw, level: TraceLevel} } @@ -280,7 +297,8 @@ func (l Logger) With() Context { // UpdateContext updates the internal logger's context. // -// Use this method with caution. If unsure, prefer the With method. +// Caution: This method is not concurrency safe. +// Use the With method to create a child logger before modifying the context from concurrent goroutines. func (l *Logger) UpdateContext(update func(c Context) Context) { if l == disabledLogger { return @@ -313,8 +331,13 @@ func (l Logger) Sample(s Sampler) Logger { } // Hook returns a logger with the h Hook. -func (l Logger) Hook(h Hook) Logger { - l.hooks = append(l.hooks, h) +func (l Logger) Hook(hooks ...Hook) Logger { + if len(hooks) == 0 { + return l + } + newHooks := make([]Hook, len(l.hooks), len(l.hooks)+len(hooks)) + copy(newHooks, l.hooks) + l.hooks = append(newHooks, hooks...) return l } @@ -377,7 +400,14 @@ func (l *Logger) Err(err error) *Event { // // 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) }) + return l.newEvent(FatalLevel, func(msg string) { + if closer, ok := l.w.(io.Closer); ok { + // Close the writer to flush any buffered message. Otherwise the message + // will be lost as os.Exit() terminates the program immediately. + closer.Close() + } + os.Exit(1) + }) } // Panic starts a new message with panic level. The panic() function @@ -444,6 +474,14 @@ func (l *Logger) Printf(format string, v ...interface{}) { } } +// Println sends a log event using debug level and no extra field. +// Arguments are handled in the manner of fmt.Println. +func (l *Logger) Println(v ...interface{}) { + if e := l.Debug(); e.Enabled() { + e.CallerSkipFrame(1).Msg(fmt.Sprintln(v...)) + } +} + // Write implements the io.Writer interface. This is useful to set as a writer // for the standard library log. func (l Logger) Write(p []byte) (n int, err error) { @@ -467,6 +505,7 @@ func (l *Logger) newEvent(level Level, done func(string)) *Event { e := newEvent(l.w, level) e.done = done e.ch = l.hooks + e.ctx = l.ctx if level != NoLevel && LevelFieldName != "" { e.Str(LevelFieldName, LevelFieldMarshalFunc(level)) } @@ -481,6 +520,9 @@ func (l *Logger) newEvent(level Level, done func(string)) *Event { // should returns true if the log event should be logged. func (l *Logger) should(lvl Level) bool { + if l.w == nil { + return false + } if lvl < l.level || lvl < GlobalLevel() { return false } diff --git a/log_example_test.go b/log_example_test.go index 70caa66a..c48a1e31 100644 --- a/log_example_test.go +++ b/log_example_test.go @@ -72,7 +72,7 @@ func ExampleLogger_Hook() { var levelNameHook LevelNameHook var messageHook MessageHook = "The message" - log := zerolog.New(os.Stdout).Hook(levelNameHook).Hook(messageHook) + log := zerolog.New(os.Stdout).Hook(levelNameHook, messageHook) log.Info().Msg("hello world") @@ -95,6 +95,14 @@ func ExampleLogger_Printf() { // Output: {"level":"debug","message":"hello world"} } +func ExampleLogger_Println() { + log := zerolog.New(os.Stdout) + + log.Println("hello world") + + // Output: {"level":"debug","message":"hello world\n"} +} + func ExampleLogger_Trace() { log := zerolog.New(os.Stdout) diff --git a/log_test.go b/log_test.go index bff2a841..c18e1133 100644 --- a/log_test.go +++ b/log_test.go @@ -2,6 +2,7 @@ package zerolog import ( "bytes" + "context" "errors" "fmt" "net" @@ -119,7 +120,8 @@ func TestWith(t *testing.T) { Uint64("uint64", 10). Float32("float32", 11.101). Float64("float64", 12.30303). - Time("time", time.Time{}) + Time("time", time.Time{}). + Ctx(context.Background()) _, file, line, _ := runtime.Caller(0) caller := fmt.Sprintf("%s:%d", file, line+3) log := ctx.Caller().Logger() @@ -143,6 +145,25 @@ func TestWith(t *testing.T) { } } +func TestWithReset(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). + Reset(). + Bytes("bytes", []byte("bar")). + Hex("hex", []byte{0x12, 0xef}). + Uint64("uint64", 10). + Float64("float64", 12.30303). + Ctx(context.Background()) + log := ctx.Logger() + log.Log().Msg("") + if got, want := decodeIfBinaryToString(out.Bytes()), `{"bytes":"bar","hex":"12ef","uint64":10,"float64":12.30303}`+"\n"; got != want { + t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) + } +} + func TestFieldsMap(t *testing.T) { out := &bytes.Buffer{} log := New(out) @@ -320,6 +341,7 @@ func TestFields(t *testing.T) { Bytes("bytes", []byte("bar")). Hex("hex", []byte{0x12, 0xef}). RawJSON("json", []byte(`{"some":"json"}`)). + RawCBOR("cbor", []byte{0x83, 0x01, 0x82, 0x02, 0x03, 0x82, 0x04, 0x05}). Func(func(e *Event) { e.Str("func", "func_output") }). AnErr("some_err", nil). Err(errors.New("some error")). @@ -343,8 +365,9 @@ func TestFields(t *testing.T) { Dur("dur", 1*time.Second). Time("time", time.Time{}). TimeDiff("diff", now, now.Add(-10*time.Second)). + Ctx(context.Background()). Msg("") - 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"},"func":"func_output","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"},"cbor":"data:application/cbor;base64,gwGCAgOCBAU=","func":"func_output","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) } } @@ -461,6 +484,7 @@ func TestFieldsDisabled(t *testing.T) { Dur("dur", 1*time.Second). Time("time", time.Time{}). TimeDiff("diff", now, now.Add(-10*time.Second)). + Ctx(context.Background()). Msg("") if got, want := decodeIfBinaryToString(out.Bytes()), ""; got != want { t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) @@ -1017,3 +1041,12 @@ func TestUnmarshalTextLevel(t *testing.T) { }) } } + +func TestHTMLNoEscaping(t *testing.T) { + out := &bytes.Buffer{} + log := New(out) + log.Log().Interface("head", "").Send() + if got, want := decodeIfBinaryToString(out.Bytes()), `{"head":""}`+"\n"; got != want { + t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) + } +} diff --git a/pkgerrors/stacktrace.go b/pkgerrors/stacktrace.go index 01420e64..2f62ffdd 100644 --- a/pkgerrors/stacktrace.go +++ b/pkgerrors/stacktrace.go @@ -42,15 +42,32 @@ func frameField(f errors.Frame, s *state, c rune) string { // MarshalStack implements pkg/errors stack trace marshaling. // -// zerolog.ErrorStackMarshaler = MarshalStack +// zerolog.ErrorStackMarshaler = MarshalStack func MarshalStack(err error) interface{} { type stackTracer interface { StackTrace() errors.StackTrace } - sterr, ok := err.(stackTracer) - if !ok { + var sterr stackTracer + var ok bool + for err != nil { + sterr, ok = err.(stackTracer) + if ok { + break + } + + u, ok := err.(interface { + Unwrap() error + }) + if !ok { + return nil + } + + err = u.Unwrap() + } + if sterr == nil { return nil } + st := sterr.StackTrace() s := &state{} out := make([]map[string]string, 0, len(st)) diff --git a/pkgerrors/stacktrace_test.go b/pkgerrors/stacktrace_test.go index 4f9838c4..787a0961 100644 --- a/pkgerrors/stacktrace_test.go +++ b/pkgerrors/stacktrace_test.go @@ -4,6 +4,7 @@ package pkgerrors import ( "bytes" + "fmt" "regexp" "testing" @@ -17,11 +18,27 @@ func TestLogStack(t *testing.T) { out := &bytes.Buffer{} log := zerolog.New(out) - err := errors.Wrap(errors.New("error message"), "from error") + err := fmt.Errorf("from error: %w", errors.New("error message")) 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` + want := `\{"stack":\[\{"func":"TestLogStack","line":"21","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 TestLogStackFields(t *testing.T) { + zerolog.ErrorStackMarshaler = MarshalStack + + out := &bytes.Buffer{} + log := zerolog.New(out) + + err := fmt.Errorf("from error: %w", errors.New("error message")) + log.Log().Stack().Fields([]interface{}{"error", err}).Msg("") + + got := out.String() + want := `\{"error":"from error: error message","stack":\[\{"func":"TestLogStackFields","line":"37","source":"stacktrace_test.go"\},.*\]\}\n` if ok, _ := regexp.MatchString(want, got); !ok { t.Errorf("invalid log output:\ngot: %v\nwant: %v", got, want) } @@ -33,11 +50,27 @@ func TestLogStackFromContext(t *testing.T) { 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") + err := fmt.Errorf("from error: %w", errors.New("error message")) 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` + want := `\{"stack":\[\{"func":"TestLogStackFromContext","line":"53","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 TestLogStackFromContextWith(t *testing.T) { + zerolog.ErrorStackMarshaler = MarshalStack + + err := fmt.Errorf("from error: %w", errors.New("error message")) + out := &bytes.Buffer{} + log := zerolog.New(out).With().Stack().Err(err).Logger() // calling Stack() on log context instead of event + + log.Error().Msg("") + + got := out.String() + want := `\{"level":"error","stack":\[\{"func":"TestLogStackFromContextWith","line":"66","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) } diff --git a/pretty.png b/pretty.png index 24203368..1449e45d 100644 Binary files a/pretty.png and b/pretty.png differ diff --git a/sampler.go b/sampler.go index 2aa9cb52..dd91f35a 100644 --- a/sampler.go +++ b/sampler.go @@ -47,6 +47,9 @@ type BasicSampler struct { // Sample implements the Sampler interface. func (s *BasicSampler) Sample(lvl Level) bool { n := s.N + if n == 0 { + return false + } if n == 1 { return true } @@ -84,7 +87,7 @@ func (s *BurstSampler) Sample(lvl Level) bool { } func (s *BurstSampler) inc() uint32 { - now := time.Now().UnixNano() + now := TimestampFunc().UnixNano() resetAt := atomic.LoadInt64(&s.resetAt) var c uint32 if now > resetAt { diff --git a/sampler_test.go b/sampler_test.go index e42ad3a9..248bd301 100644 --- a/sampler_test.go +++ b/sampler_test.go @@ -28,6 +28,13 @@ var samplers = []struct { }, 100, 20, 20, }, + { + "BasicSampler_0", + func() Sampler { + return &BasicSampler{N: 0} + }, + 100, 0, 0, + }, { "RandomSampler", func() Sampler { @@ -35,6 +42,13 @@ var samplers = []struct { }, 100, 10, 30, }, + { + "RandomSampler_0", + func() Sampler { + return RandomSampler(0) + }, + 100, 0, 0, + }, { "BurstSampler", func() Sampler { @@ -42,6 +56,13 @@ var samplers = []struct { }, 100, 20, 20, }, + { + "BurstSampler_0", + func() Sampler { + return &BurstSampler{Burst: 0, Period: time.Second} + }, + 100, 0, 0, + }, { "BurstSamplerNext", func() Sampler { diff --git a/syslog.go b/syslog.go index c4082830..a2b7285d 100644 --- a/syslog.go +++ b/syslog.go @@ -78,3 +78,12 @@ func (sw syslogWriter) WriteLevel(level Level, p []byte) (n int, err error) { n = len(p) return } + +// Call the underlying writer's Close method if it is an io.Closer. Otherwise +// does nothing. +func (sw syslogWriter) Close() error { + if c, ok := sw.w.(io.Closer); ok { + return c.Close() + } + return nil +} diff --git a/syslog_test.go b/syslog_test.go index c168ba6a..e889b01a 100644 --- a/syslog_test.go +++ b/syslog_test.go @@ -100,7 +100,7 @@ func TestSyslogWriter_WithCEE(t *testing.T) { sw := testCEEwriter{&buf} log := New(SyslogCEEWriter(sw)) log.Info().Str("key", "value").Msg("message string") - got := string(buf.Bytes()) + got := buf.String() want := "@cee:{" if !strings.HasPrefix(got, want) { t.Errorf("Bad CEE message start: want %v, got %v", want, got) diff --git a/writer.go b/writer.go index 26f5e632..41b394d7 100644 --- a/writer.go +++ b/writer.go @@ -17,14 +17,25 @@ type LevelWriter interface { WriteLevel(level Level, p []byte) (n int, err error) } -type levelWriterAdapter struct { +// LevelWriterAdapter adapts an io.Writer to support the LevelWriter interface. +type LevelWriterAdapter struct { io.Writer } -func (lw levelWriterAdapter) WriteLevel(l Level, p []byte) (n int, err error) { +// WriteLevel simply writes everything to the adapted writer, ignoring the level. +func (lw LevelWriterAdapter) WriteLevel(l Level, p []byte) (n int, err error) { return lw.Write(p) } +// Call the underlying writer's Close method if it is an io.Closer. Otherwise +// does nothing. +func (lw LevelWriterAdapter) Close() error { + if closer, ok := lw.Writer.(io.Closer); ok { + return closer.Close() + } + return nil +} + type syncWriter struct { mu sync.Mutex lw LevelWriter @@ -38,7 +49,7 @@ func SyncWriter(w io.Writer) io.Writer { if lw, ok := w.(LevelWriter); ok { return &syncWriter{lw: lw} } - return &syncWriter{lw: levelWriterAdapter{w}} + return &syncWriter{lw: LevelWriterAdapter{w}} } // Write implements the io.Writer interface. @@ -55,6 +66,15 @@ func (s *syncWriter) WriteLevel(l Level, p []byte) (n int, err error) { return s.lw.WriteLevel(l, p) } +func (s *syncWriter) Close() error { + s.mu.Lock() + defer s.mu.Unlock() + if closer, ok := s.lw.(io.Closer); ok { + return closer.Close() + } + return nil +} + type multiLevelWriter struct { writers []LevelWriter } @@ -87,6 +107,20 @@ func (t multiLevelWriter) WriteLevel(l Level, p []byte) (n int, err error) { return n, err } +// Calls close on all the underlying writers that are io.Closers. If any of the +// Close methods return an error, the remainder of the closers are not closed +// and the error is returned. +func (t multiLevelWriter) Close() error { + for _, w := range t.writers { + if closer, ok := w.(io.Closer); ok { + if err := closer.Close(); err != nil { + return err + } + } + } + return nil +} + // MultiLevelWriter creates a writer that duplicates its writes to all the // provided writers, similar to the Unix tee(1) command. If some writers // implement LevelWriter, their WriteLevel method will be used instead of Write. @@ -96,7 +130,7 @@ func MultiLevelWriter(writers ...io.Writer) LevelWriter { if lw, ok := w.(LevelWriter); ok { lwriters = append(lwriters, lw) } else { - lwriters = append(lwriters, levelWriterAdapter{w}) + lwriters = append(lwriters, LevelWriterAdapter{w}) } } return multiLevelWriter{lwriters} @@ -152,3 +186,161 @@ func ConsoleTestWriter(t TestingLog) func(w *ConsoleWriter) { w.Out = TestWriter{T: t, Frame: 6} } } + +// FilteredLevelWriter writes only logs at Level or above to Writer. +// +// It should be used only in combination with MultiLevelWriter when you +// want to write to multiple destinations at different levels. Otherwise +// you should just set the level on the logger and filter events early. +// When using MultiLevelWriter then you set the level on the logger to +// the lowest of the levels you use for writers. +type FilteredLevelWriter struct { + Writer LevelWriter + Level Level +} + +// Write writes to the underlying Writer. +func (w *FilteredLevelWriter) Write(p []byte) (int, error) { + return w.Writer.Write(p) +} + +// WriteLevel calls WriteLevel of the underlying Writer only if the level is equal +// or above the Level. +func (w *FilteredLevelWriter) WriteLevel(level Level, p []byte) (int, error) { + if level >= w.Level { + return w.Writer.WriteLevel(level, p) + } + return len(p), nil +} + +var triggerWriterPool = &sync.Pool{ + New: func() interface{} { + return bytes.NewBuffer(make([]byte, 0, 1024)) + }, +} + +// TriggerLevelWriter buffers log lines at the ConditionalLevel or below +// until a trigger level (or higher) line is emitted. Log lines with level +// higher than ConditionalLevel are always written out to the destination +// writer. If trigger never happens, buffered log lines are never written out. +// +// It can be used to configure "log level per request". +type TriggerLevelWriter struct { + // Destination writer. If LevelWriter is provided (usually), its WriteLevel is used + // instead of Write. + io.Writer + + // ConditionalLevel is the level (and below) at which lines are buffered until + // a trigger level (or higher) line is emitted. Usually this is set to DebugLevel. + ConditionalLevel Level + + // TriggerLevel is the lowest level that triggers the sending of the conditional + // level lines. Usually this is set to ErrorLevel. + TriggerLevel Level + + buf *bytes.Buffer + triggered bool + mu sync.Mutex +} + +func (w *TriggerLevelWriter) WriteLevel(l Level, p []byte) (n int, err error) { + w.mu.Lock() + defer w.mu.Unlock() + + // At first trigger level or above log line, we flush the buffer and change the + // trigger state to triggered. + if !w.triggered && l >= w.TriggerLevel { + err := w.trigger() + if err != nil { + return 0, err + } + } + + // Unless triggered, we buffer everything at and below ConditionalLevel. + if !w.triggered && l <= w.ConditionalLevel { + if w.buf == nil { + w.buf = triggerWriterPool.Get().(*bytes.Buffer) + } + + // We prefix each log line with a byte with the level. + // Hopefully we will never have a level value which equals a newline + // (which could interfere with reconstruction of log lines in the trigger method). + w.buf.WriteByte(byte(l)) + w.buf.Write(p) + return len(p), nil + } + + // Anything above ConditionalLevel is always passed through. + // Once triggered, everything is passed through. + if lw, ok := w.Writer.(LevelWriter); ok { + return lw.WriteLevel(l, p) + } + return w.Write(p) +} + +// trigger expects lock to be held. +func (w *TriggerLevelWriter) trigger() error { + if w.triggered { + return nil + } + w.triggered = true + + if w.buf == nil { + return nil + } + + p := w.buf.Bytes() + for len(p) > 0 { + // We do not use bufio.Scanner here because we already have full buffer + // in the memory and we do not want extra copying from the buffer to + // scanner's token slice, nor we want to hit scanner's token size limit, + // and we also want to preserve newlines. + i := bytes.IndexByte(p, '\n') + line := p[0 : i+1] + p = p[i+1:] + // We prefixed each log line with a byte with the level. + level := Level(line[0]) + line = line[1:] + var err error + if lw, ok := w.Writer.(LevelWriter); ok { + _, err = lw.WriteLevel(level, line) + } else { + _, err = w.Write(line) + } + if err != nil { + return err + } + } + + return nil +} + +// Trigger forces flushing the buffer and change the trigger state to +// triggered, if the writer has not already been triggered before. +func (w *TriggerLevelWriter) Trigger() error { + w.mu.Lock() + defer w.mu.Unlock() + + return w.trigger() +} + +// Close closes the writer and returns the buffer to the pool. +func (w *TriggerLevelWriter) Close() error { + w.mu.Lock() + defer w.mu.Unlock() + + if w.buf == nil { + return nil + } + + // We return the buffer only if it has not grown above the limit. + // This prevents accumulation of large buffers in the pool just + // because occasionally a large buffer might be needed. + if w.buf.Cap() <= TriggerLevelWriterBufferReuseLimit { + w.buf.Reset() + triggerWriterPool.Put(w.buf) + } + w.buf = nil + + return nil +} diff --git a/writer_test.go b/writer_test.go index 0c466b0e..f2a61df9 100644 --- a/writer_test.go +++ b/writer_test.go @@ -175,3 +175,78 @@ func TestTestWriter(t *testing.T) { } } + +func TestFilteredLevelWriter(t *testing.T) { + buf := bytes.Buffer{} + writer := FilteredLevelWriter{ + Writer: LevelWriterAdapter{&buf}, + Level: InfoLevel, + } + _, err := writer.WriteLevel(DebugLevel, []byte("no")) + if err != nil { + t.Error(err) + } + _, err = writer.WriteLevel(InfoLevel, []byte("yes")) + if err != nil { + t.Error(err) + } + p := buf.Bytes() + if want := "yes"; !bytes.Equal([]byte(want), p) { + t.Errorf("Expected %q, got %q.", want, p) + } +} + +type testWrite struct { + Level + Line []byte +} + +func TestTriggerLevelWriter(t *testing.T) { + tests := []struct { + write []testWrite + want []byte + all []byte + }{{ + []testWrite{ + {DebugLevel, []byte("no\n")}, + {InfoLevel, []byte("yes\n")}, + }, + []byte("yes\n"), + []byte("yes\nno\n"), + }, { + []testWrite{ + {DebugLevel, []byte("yes1\n")}, + {InfoLevel, []byte("yes2\n")}, + {ErrorLevel, []byte("yes3\n")}, + {DebugLevel, []byte("yes4\n")}, + }, + []byte("yes2\nyes1\nyes3\nyes4\n"), + []byte("yes2\nyes1\nyes3\nyes4\n"), + }} + + for k, tt := range tests { + t.Run(fmt.Sprintf("case=%d", k), func(t *testing.T) { + buf := bytes.Buffer{} + writer := TriggerLevelWriter{Writer: LevelWriterAdapter{&buf}, ConditionalLevel: DebugLevel, TriggerLevel: ErrorLevel} + t.Cleanup(func() { writer.Close() }) + for _, w := range tt.write { + _, err := writer.WriteLevel(w.Level, w.Line) + if err != nil { + t.Error(err) + } + } + p := buf.Bytes() + if want := tt.want; !bytes.Equal([]byte(want), p) { + t.Errorf("Expected %q, got %q.", want, p) + } + err := writer.Trigger() + if err != nil { + t.Error(err) + } + p = buf.Bytes() + if want := tt.all; !bytes.Equal([]byte(want), p) { + t.Errorf("Expected %q, got %q.", want, p) + } + }) + } +}