From fbdbfa3487f7678a7e1156bb7178c6cf525142f3 Mon Sep 17 00:00:00 2001 From: Sarat Chandra Date: Thu, 7 Jul 2022 11:38:42 +0530 Subject: [PATCH 1/3] ref: Use variadic arguments for fields instead of passing a map. --- benchmark_test.go | 80 ++++++++++++++++++++++------------------------- examples/main.go | 14 +++------ field_logger.go | 35 --------------------- log.go | 71 ++++++++++++++++++++--------------------- log_test.go | 25 ++++++++------- 5 files changed, 90 insertions(+), 135 deletions(-) delete mode 100644 field_logger.go diff --git a/benchmark_test.go b/benchmark_test.go index be88bfd..8e84f8b 100644 --- a/benchmark_test.go +++ b/benchmark_test.go @@ -25,7 +25,7 @@ func BenchmarkOneField(b *testing.B) { b.ResetTimer() b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{"stack": "testing"}).Info("hello world") + logger.Info("hello world", "stack", "testing") } }) } @@ -37,11 +37,9 @@ func BenchmarkThreeFields(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{ - "component": "api", - "method": "GET", - "bytes": 1 << 18, - }).Info("request completed") + logger.Info("request completed", + "component", "api", "method", "GET", "bytes", 1<<18, + ) } }) } @@ -55,7 +53,7 @@ func BenchmarkErrorField(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithError(fakeErr).Error("request failed") + logger.Error("request fields", "error", fakeErr) } }) } @@ -67,18 +65,18 @@ func BenchmarkHugePayload(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{ - "id": 11, - "title": "perfume Oil", - "description": "Mega Discount, Impression of A...", - "price": 13, - "discountPercentage": 8.4, - "rating": 4.26, - "stock": 65, - "brand": "Impression of Acqua Di Gio", - "category": "fragrances", - "thumbnail": "https://dummyjson.com/image/i/products/11/thumbnail.jpg", - }).Info("fetched details") + logger.Info("fetched details", + "id", 11, + "title", "perfume Oil", + "description", "Mega Discount, Impression of A...", + "price", 13, + "discountPercentage", 8.4, + "rating", 4.26, + "stock", 65, + "brand", "Impression of Acqua Di Gio", + "category", "fragrances", + "thumbnail", "https://dummyjson.com/image/i/products/11/thumbnail.jpg", + ) } }) } @@ -91,11 +89,9 @@ func BenchmarkThreeFields_WithCaller(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{ - "component": "api", - "method": "GET", - "bytes": 1 << 18, - }).Info("request completed") + logger.Info("request completed", + "component", "api", "method", "GET", "bytes", 1<<18, + ) } }) } @@ -120,7 +116,7 @@ func BenchmarkOneField_WithColor(b *testing.B) { b.ResetTimer() b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{"stack": "testing"}).Info("hello world") + logger.Info("hello world", "stack", "testing") } }) } @@ -133,11 +129,9 @@ func BenchmarkThreeFields_WithColor(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{ - "component": "api", - "method": "GET", - "bytes": 1 << 18, - }).Info("request completed") + logger.Info("request completed", + "component", "api", "method", "GET", "bytes", 1<<18, + ) } }) } @@ -152,7 +146,7 @@ func BenchmarkErrorField_WithColor(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithError(fakeErr).Error("request failed") + logger.Error("request fields", "error", fakeErr) } }) } @@ -165,18 +159,18 @@ func BenchmarkHugePayload_WithColor(b *testing.B) { b.RunParallel(func(p *testing.PB) { for p.Next() { - logger.WithFields(logf.Fields{ - "id": 11, - "title": "perfume Oil", - "description": "Mega Discount, Impression of A...", - "price": 13, - "discountPercentage": 8.4, - "rating": 4.26, - "stock": 65, - "brand": "Impression of Acqua Di Gio", - "category": "fragrances", - "thumbnail": "https://dummyjson.com/image/i/products/11/thumbnail.jpg", - }).Info("fetched details") + logger.Info("fetched details", + "id", 11, + "title", "perfume Oil", + "description", "Mega Discount, Impression of A...", + "price", 13, + "discountPercentage", 8.4, + "rating", 4.26, + "stock", 65, + "brand", "Impression of Acqua Di Gio", + "category", "fragrances", + "thumbnail", "https://dummyjson.com/image/i/products/11/thumbnail.jpg", + ) } }) } diff --git a/examples/main.go b/examples/main.go index 9575fe2..eb3ceff 100644 --- a/examples/main.go +++ b/examples/main.go @@ -1,7 +1,6 @@ package main import ( - "errors" "os" "time" @@ -22,13 +21,10 @@ func main() { logger.Debug("meant for debugging app") // Add extra keys to the log. - logger.WithFields(logf.Fields{ - "component": "api", - "user": "karan", - }).Info("logging with some extra metadata") + logger.Info("logging with some extra metadata", "component", "api", "user", "karan") // Log with error key. - logger.WithError(errors.New("this is a dummy error")).Error("error fetching details") + logger.Error("error fetching details", "error", "this is a dummy error") // Enable `caller` field in the log and specify the number of frames to skip to get the caller. logger.SetCallerFrame(true, 3) @@ -36,9 +32,9 @@ func main() { logger.SetTimestampFormat(time.RFC3339Nano) // Create a logger and add fields which will be logged in every line. - requestLogger := logger.WithFields(logf.Fields{"request_id": "3MG91VKP", "ip": "1.1.1.1", "method": "method=GET"}) - requestLogger.Info("request success") - requestLogger.Warn("this isn't supposed to happen") + fields := []any{"request_id", "3MG91VKP", "ip", "1.1.1.1", "method", "method=GET"} + logger.Info("request success", fields...) + logger.Warn("this isn't supposed to happen", fields...) // Log the error and set exit code as 1. logger.Fatal("goodbye world") diff --git a/field_logger.go b/field_logger.go deleted file mode 100644 index 30b08d3..0000000 --- a/field_logger.go +++ /dev/null @@ -1,35 +0,0 @@ -package logf - -import "os" - -type FieldLogger struct { - fields Fields - logger Logger -} - -// Debug emits a debug log line. -func (l FieldLogger) Debug(msg string) { - l.logger.handleLog(msg, DebugLevel, l.fields) -} - -// Info emits a info log line. -func (l FieldLogger) Info(msg string) { - l.logger.handleLog(msg, InfoLevel, l.fields) -} - -// Warn emits a warning log line. -func (l FieldLogger) Warn(msg string) { - l.logger.handleLog(msg, WarnLevel, l.fields) -} - -// Error emits an error log line. -func (l FieldLogger) Error(msg string) { - l.logger.handleLog(msg, ErrorLevel, l.fields) -} - -// Fatal emits a fatal level log line. -// It aborts the current program with an exit code of 1. -func (l FieldLogger) Fatal(msg string) { - l.logger.handleLog(msg, ErrorLevel, l.fields) - os.Exit(1) -} diff --git a/log.go b/log.go index 6235e21..f23030b 100644 --- a/log.go +++ b/log.go @@ -34,10 +34,6 @@ type Logger struct { callerSkipFrameCount int // Number of frames to skip when detecting caller } -// Fields is a map of arbitrary KV pairs -// which will be used in logfmt representation of the log. -type Fields map[string]any - // Severity level of the log. type Level int @@ -161,54 +157,35 @@ func (l Logger) SetCallerFrame(caller bool, depth int) Logger { } // Debug emits a debug log line. -func (l Logger) Debug(msg string) { - l.handleLog(msg, DebugLevel, nil) +func (l Logger) Debug(msg string, fields ...any) { + l.handleLog(msg, DebugLevel, fields...) } // Info emits a info log line. -func (l Logger) Info(msg string) { - l.handleLog(msg, InfoLevel, nil) +func (l Logger) Info(msg string, fields ...any) { + l.handleLog(msg, InfoLevel, fields...) } // Warn emits a warning log line. -func (l Logger) Warn(msg string) { - l.handleLog(msg, WarnLevel, nil) +func (l Logger) Warn(msg string, fields ...any) { + l.handleLog(msg, WarnLevel, fields...) } // Error emits an error log line. -func (l Logger) Error(msg string) { - l.handleLog(msg, ErrorLevel, nil) +func (l Logger) Error(msg string, fields ...any) { + l.handleLog(msg, ErrorLevel, fields...) } // Fatal emits a fatal level log line. // It aborts the current program with an exit code of 1. -func (l Logger) Fatal(msg string) { - l.handleLog(msg, FatalLevel, nil) +func (l Logger) Fatal(msg string, fields ...any) { + l.handleLog(msg, FatalLevel, fields...) os.Exit(1) } -// WithFields returns a new entry with `fields` set. -func (l Logger) WithFields(fields Fields) FieldLogger { - return FieldLogger{ - fields: fields, - logger: l, - } -} - -// WithError returns a Logger with the "error" key set to `err`. -func (l Logger) WithError(err error) FieldLogger { - if err == nil { - return FieldLogger{logger: l} - } - - return l.WithFields(Fields{ - "error": err.Error(), - }) -} - // handleLog emits the log after filtering log level // and applying formatting of the fields. -func (l Logger) handleLog(msg string, lvl Level, fields Fields) { +func (l Logger) handleLog(msg string, lvl Level, fields ...any) { // Discard the log if the verbosity is higher. // For eg, if the lvl is `3` (error), but the incoming message is `0` (debug), skip it. if lvl < l.level { @@ -228,13 +205,33 @@ func (l Logger) handleLog(msg string, lvl Level, fields Fields) { } // Format the line as logfmt. - var count int // count is find out if this is the last key in while itering fields. - for k, v := range fields { + var ( + // count is find out if this is the last key in while itering fields. + count int + key string + val any + ) + + // If there are odd number of fields, ignore the last. + // TODO: Should we not ignore the last key here. + if len(fields)%2 != 0 { + fields = fields[0 : len(fields)-1] + } + + for i := range fields { space := false if count != len(fields)-1 { space = true } - writeToBuf(buf, k, v, lvl, l.enableColor, space) + + if i%2 == 0 { + key = fields[i].(string) + continue + } else { + val = fields[i] + } + + writeToBuf(buf, key, val, lvl, l.enableColor, space) count++ } buf.AppendString("\n") diff --git a/log_test.go b/log_test.go index 29c8979..00dd902 100644 --- a/log_test.go +++ b/log_test.go @@ -57,25 +57,28 @@ func TestLogFormat(t *testing.T) { buf.Reset() // Log with field. - fields := Fields{ - "stack": "testing", - } - fl := l.WithFields(fields) - assert.Equal(t, fl.fields, fields) - fl.Warn("testing fields") + l.Warn("testing fields", "stack", "testing") assert.Contains(t, buf.String(), `level=warn message="testing fields" stack=testing`, "warning log") buf.Reset() // Log with error. fakeErr := errors.New("this is a fake error") - el := l.WithError(fakeErr) - // Check if error key exists. - assert.Equal(t, el.fields["error"], fakeErr.Error()) - el.Error("testing error") + l.Error("testing error", "error", fakeErr) assert.Contains(t, buf.String(), `level=error message="testing error" error="this is a fake error"`, "error log") buf.Reset() } +func TestOddNumberedFields(t *testing.T) { + buf := &bytes.Buffer{} + l := New(buf) + l.SetColorOutput(false) + + // Give a odd number of fields. + l.Info("hello world", "key1", "val1", "key2") + assert.Contains(t, buf.String(), `level=info message="hello world" key1=val1`) + buf.Reset() +} + // These test are typically meant to be run with the data race detector. func TestLoggerConcurrency(t *testing.T) { buf := &bytes.Buffer{} @@ -94,6 +97,6 @@ func TestLoggerConcurrency(t *testing.T) { func genLogs(l Logger) { for i := 0; i < 100; i++ { - l.WithFields(Fields{"index": strconv.FormatInt(int64(i), 10)}).Info("random log") + l.Info("random log", "index", strconv.FormatInt(int64(i), 10)) } } From 0ace9d4bf51201e9107944e597c388157739e19a Mon Sep 17 00:00:00 2001 From: Sarat Chandra Date: Thu, 7 Jul 2022 12:21:10 +0530 Subject: [PATCH 2/3] doc: Update README.md with new api. --- README.md | 57 ++++++++++++++++++++---------------------------- examples/main.go | 5 ----- 2 files changed, 24 insertions(+), 38 deletions(-) diff --git a/README.md b/README.md index 34938df..818ee07 100644 --- a/README.md +++ b/README.md @@ -6,8 +6,7 @@ [![Go Report Card](https://goreportcard.com/badge/zerodha/logf)](https://goreportcard.com/report/zerodha/logf) [![GitHub Actions](https://github.com/zerodha/logf/actions/workflows/build.yml/badge.svg)](https://github.com/zerodha/logf/actions/workflows/build.yml) - -logf is a **high performance** logging library for Go applications with a **minimal** API overhead. It emits **structured logs** ([`logfmt`](https://brandur.org/logfmt) style) in human readable and machine friendly way. `logf` aims to be customisable without providing an overwhelming amount of things to configure. +logf is a **high performance**, **zero alloc** logging library for Go applications with a **minimal** API overhead. It emits **structured logs** ([`logfmt`](https://brandur.org/logfmt) style) in human readable and machine friendly way. `logf` aims to be customisable without providing an overwhelming amount of things to configure. ## Example @@ -15,40 +14,36 @@ logf is a **high performance** logging library for Go applications with a **mini package main import ( - "errors" + "os" "time" "github.com/zerodha/logf" ) func main() { - logger := logf.New() + logger := logf.New(os.Stderr) + // Basic log. logger.Info("starting app") + // Enable colored output. + logger.SetColorOutput(true) + // Change verbosity on the fly. logger.SetLevel(logf.DebugLevel) logger.Debug("meant for debugging app") // Add extra keys to the log. - logger.WithFields(logf.Fields{ - "component": "api", - "user": "karan", - }).Info("logging with some extra metadata") + logger.Info("logging with some extra metadata", "component", "api", "user", "karan") // Log with error key. - logger.WithError(errors.New("this is a dummy error")).Error("error fetching details") + logger.Error("error fetching details", "error", "this is a dummy error") - // Enable `caller` field in the log and specify the number of frames to skip to get the caller. + // Enable `caller` field in the log and specify the number of frames to skip to get the caller. logger.SetCallerFrame(true, 3) // Change the default timestamp format. logger.SetTimestampFormat(time.RFC3339Nano) - // Create a logger and add fields which will be logged in every line. - requestLogger := logger.WithFields(logf.Fields{"request_id": "3MG91VKP", "ip": "1.1.1.1", "method": "GET"}) - requestLogger.Info("request success") - requestLogger.Warn("this isn't supposed to happen") - // Log the error and set exit code as 1. logger.Fatal("goodbye world") } @@ -57,13 +52,10 @@ func main() { ### Text Output ```bash -timestamp=2022-06-26T11:56:46+05:30 level=info message=starting app caller=/home/karan/Code/Personal/logf/examples/main.go:13 -timestamp=2022-06-26T11:56:46+05:30 level=debug message=meant for debugging app caller=/home/karan/Code/Personal/logf/examples/main.go:17 level=debug message=meant for debugging app timestamp=2022-06-26T11:56:46+05:30 caller=/home/karan/Code/Personal/logf/examples/main.go:17 -timestamp=2022-06-26T11:56:46+05:30 level=info message=logging with some extra metadata component=api user=karan caller=/home/karan/Code/Personal/logf/examples/main.go:23 -timestamp=2022-06-26T11:56:46+05:30 level=error message=error fetching details error=this is a dummy error caller=/home/karan/Code/Personal/logf/examples/main.go:26 -timestamp=2022-06-26T11:56:46.412189111+05:30 level=info message=request success ip=1.1.1.1 method=GET request_id=3MG91VKP -timestamp=2022-06-26T11:56:46.412204619+05:30 level=warn message=this isn't supposed to happen ip=1.1.1.1 level=warn message=this isn't supposed to happen method=GET request_id=3MG91VKP timestamp=2022-06-26T11:56:46.412204619+05:30 -timestamp=2022-06-26T11:56:46.412218628+05:30 level=fatal message=goodbye world ip=1.1.1.1 level=fatal message=goodbye world method=GET request_id=3MG91VKP timestamp=2022-06-26T11:56:46.412218628+05:30 +timestamp=2022-07-07T12:09:10.221+05:30 level=info message="starting app" +timestamp=2022-07-07T12:09:10.221+05:30 level=info message="logging with some extra metadata" component=api user=karan +timestamp=2022-07-07T12:09:10.221+05:30 level=error message="error fetching details" error="this is a dummy error" +timestamp=2022-07-07T12:09:10.221+05:30 level=fatal message="goodbye world" ``` ### Console Output @@ -88,22 +80,21 @@ You can run benchmarks with `make bench`. ### No Colors (Default) ``` -BenchmarkNoField-8 7140398 175.3 ns/op 0 B/op 0 allocs/op -BenchmarkOneField-8 5061104 235.0 ns/op 336 B/op 2 allocs/op -BenchmarkThreeFields-8 4499778 265.4 ns/op 336 B/op 2 allocs/op -BenchmarkErrorField-8 4768662 252.4 ns/op 368 B/op 4 allocs/op -BenchmarkHugePayload-8 1784425 670.0 ns/op 1031 B/op 5 allocs/op -BenchmarkThreeFields_WithCaller-8 2144788 564.7 ns/op 704 B/op 8 allocs/op +BenchmarkNoField-8 7219110 173.0 ns/op 0 B/op 0 allocs/op +BenchmarkOneField-8 6421900 176.3 ns/op 0 B/op 0 allocs/op +BenchmarkThreeFields-8 5485582 221.3 ns/op 0 B/op 0 allocs/op +BenchmarkHugePayload-8 975226 1659 ns/op 0 B/op 0 allocs/op +BenchmarkThreeFields_WithCaller-8 1390599 906.4 ns/op 0 B/op 0 allocs/op +BenchmarkNoField_WithColor-8 1580092 644.2 ns/op 0 B/op 0 allocs/op ``` ### With Colors ``` -BenchmarkNoField_WithColor-8 6236416 197.8 ns/op 0 B/op 0 allocs/op -BenchmarkOneField_WithColor-8 4316852 296.9 ns/op 336 B/op 2 allocs/op -BenchmarkThreeFields_WithColor-8 2447352 517.2 ns/op 336 B/op 2 allocs/op -BenchmarkErrorField_WithColor-8 2673672 454.1 ns/op 368 B/op 4 allocs/op -BenchmarkHugePayload_WithColor-8 1000000 1252 ns/op 1032 B/op 5 allocs/op +BenchmarkNoField_WithColor-8 1580092 644.2 ns/op 0 B/op 0 allocs/op +BenchmarkOneField_WithColor-8 1810801 689.9 ns/op 0 B/op 0 allocs/op +BenchmarkThreeFields_WithColor-8 1592907 740.8 ns/op 0 B/op 0 allocs/op +BenchmarkHugePayload_WithColor-8 991813 1224 ns/op 0 B/op 0 allocs/op ``` For a comparison with existing popular libs, visit [uber-go/zap#performance](https://github.com/uber-go/zap#performance). diff --git a/examples/main.go b/examples/main.go index eb3ceff..a13894d 100644 --- a/examples/main.go +++ b/examples/main.go @@ -31,11 +31,6 @@ func main() { // Change the default timestamp format. logger.SetTimestampFormat(time.RFC3339Nano) - // Create a logger and add fields which will be logged in every line. - fields := []any{"request_id", "3MG91VKP", "ip", "1.1.1.1", "method", "method=GET"} - logger.Info("request success", fields...) - logger.Warn("this isn't supposed to happen", fields...) - // Log the error and set exit code as 1. logger.Fatal("goodbye world") } From a391cda4d158f562ad336ba9293c763f3dd524a7 Mon Sep 17 00:00:00 2001 From: Sarat Chandra Date: Thu, 7 Jul 2022 12:25:28 +0530 Subject: [PATCH 3/3] chore: Remove TODO. --- log.go | 1 - 1 file changed, 1 deletion(-) diff --git a/log.go b/log.go index f23030b..e8d97a6 100644 --- a/log.go +++ b/log.go @@ -213,7 +213,6 @@ func (l Logger) handleLog(msg string, lvl Level, fields ...any) { ) // If there are odd number of fields, ignore the last. - // TODO: Should we not ignore the last key here. if len(fields)%2 != 0 { fields = fields[0 : len(fields)-1] }