From e6aeabc01bcbd055791159eed9fcad9fb5979558 Mon Sep 17 00:00:00 2001 From: Gerard Vanloo Date: Fri, 8 Apr 2022 13:13:13 -0400 Subject: [PATCH] Updating library to v2; Reorganizing files; Cleaning up test cases --- .github/workflows/ci.yaml | 2 +- MIGRATION.md | 41 +-- README.md | 263 ++++------------ go.mod | 4 +- internal/kv/kv.go | 20 +- {log => internal/sink}/encoding.go | 2 +- internal/sink/line.go | 78 +++++ internal/sink/line_test.go | 96 ++++++ log/logsink.go => internal/sink/sink.go | 112 +------ internal/sink/sink_test.go | 244 +++++++++++++++ internal/sink/verbosity.go | 18 ++ kverrors/kverrors.go | 2 +- kverrors/kverrors_test.go | 4 +- log/fake_test.go | 17 -- log/fakes_test.go | 28 -- log/log.go | 56 +--- log/log_test.go | 179 +---------- log/logsink_test.go | 380 ------------------------ log/observer_test.go | 164 ---------- log/options.go | 14 +- 20 files changed, 580 insertions(+), 1144 deletions(-) rename {log => internal/sink}/encoding.go (96%) create mode 100644 internal/sink/line.go create mode 100644 internal/sink/line_test.go rename log/logsink.go => internal/sink/sink.go (61%) create mode 100644 internal/sink/sink_test.go create mode 100644 internal/sink/verbosity.go delete mode 100644 log/fake_test.go delete mode 100644 log/fakes_test.go delete mode 100644 log/logsink_test.go delete mode 100644 log/observer_test.go diff --git a/.github/workflows/ci.yaml b/.github/workflows/ci.yaml index 4d72063..a06824e 100644 --- a/.github/workflows/ci.yaml +++ b/.github/workflows/ci.yaml @@ -13,7 +13,7 @@ jobs: strategy: fail-fast: false matrix: - go: ['1.15', '1.16', '1.17'] + go: ['1.17'] steps: - name: Set up Go 1.x diff --git a/MIGRATION.md b/MIGRATION.md index cc44f58..fec1055 100644 --- a/MIGRATION.md +++ b/MIGRATION.md @@ -1,37 +1,26 @@ -# 2.0.0 +# v2.0.0 -As of `logr@v1.0.0`, the `logr.Logger` is considered to be a defined `struct` instead of an `interface`. The implementation layer (now referred to as `logr.LogSink`) has been entirely restructured. Now, the `logerr` library will provide `logr.Logger` objects and ways to affect the underlying `Sink` operations. +## Removal of singleton behavior -- Instead of `log.V()`, `log.Info()`, `log.Error()` methods, use `log.DefaultLogger().V()`, `log.DefaultLogger().Info()`, `log.DefaultLogger().Error()` +Due to the structural changes of `logr@v1`, several features of this library have been modified. Most notable of these changes is the lack of a singleton logger. It is recommended that developers create a logger instance with `NewLogger` and either keep it as their own singleton or pass the instance throughout the application to use where needed. Methods like `Info` and `Error` are still callable with a `logr.Logger` instance. -- Instead of `log.SetOutput()`, `log.SetLogLevel()`, use either of the following methods: +ex: -Method 1: -```go -l := log.DefaultLogger() -s, err := log.GetSink(l) +```golang +import ( + "github.com/ViaQ/logerr/v2/log" +) -if err != nil { - // Some action -} +logger := log.NewLogger("example-logger") -s.SetVerbosity(1) -s.SetOutput(ioutil.Discard) - -l.Info("hello world") +logger.Info("Now logging info message") +logger.Error(errors.New("New error"), "Now logging new error") ``` -Method 2: -```go -l := log.DefaultLogger() -// This method panics, but DefaultLogger will not -// panic because it uses Sink. -log.MustGetSink(l).SetVerbosity(1) -log.MustGetSink(l).SetOutput(ioutil.Discard) +## Logger Creation -l.Info("hello world") -``` +`Init` and `InitWithOptions` have been removed. Please use `NewLogger(component string, opts ...Option)`. -- Instead of `log.UseLogger`, `log.GetLogger`, keep the logger instance until it is no longer needed +## Removal of explicit `SetOutput` and `SetLevel` -- Instead of `log.Init` or `log.InitWithOptions`, use `log.NewLogger` or `log.NewLoggerWithOption` +As a byproduct of the changes in `logr@v1`, these methods have been moved into the internal logging implementation of `logr.Sink`: `Sink`. It is recommended that a logger instance is created with the intended writer and verbosity level. If the writer or verbosity needs to be changed, a new logger should be generated. diff --git a/README.md b/README.md index 80e8d56..e0e25e4 100644 --- a/README.md +++ b/README.md @@ -1,205 +1,74 @@ # logerr -logerr provides structured logging and kverrors packages that work together. - -This package does not: - -* Provide a complex API -* Log to any external loggers -* Promise any other features that aren't central to the - [logr](https://github.com/go-logr/logr) interface - -This package does: - -* Create a structured, uniform, singleton, sane logging package to use across - the life cycle of the application -* Provide structured errors with key/value pairs that can easily be extracted at - log time -* Log structured (JSON) logs. If you are a human and you can't read your JSON - logs then install [humanlog](https://github.com/aybabtme/humanlog) - -## Logging TL;DR - -As much as I hate the concept of TL;DR, the short of it is simple: - -* logs are logs. There are no "levels" of logs. An error log is a log with an error -* log.Error = log.Info with an error key/value -* log.Info = log.V(0).Info -* log.V(1).Info will not be printed unless you set the log level to 1 or above -* Use higher V for noisier, less useful logs -* Use lower V for more useful, less noisy logs -* Try to stick to a limited range of V because stretching the range only makes - debugging that much more difficult. We recommend V 0-3 or 0-5 at most. - -## Errors TL;DR - -`kverrors` provides a package for creating key/value errors that create -key/value (aka Structured) errors. Errors should never contain sprintf strings, -instead you should place your key/value information into separate context that -can be easily queried later (with jq or an advanced log framework like -elasticsearch). The `log` package understands how to print kverrors as -structured. - -## Log Verbosity - -The log package of logerr does not have or support traditional "levels" such as -Trace, Debug, Info, Error, Fatal, Panic, etc. These levels are excessive and -unnecessary. Instead this library adapts the "verbosity" format. What does that -mean? If you have ever used tcpdump, memcached, ansible, ssh, or rsync you would -have used the -v, -vv, -v 3 idioms. These flags increase the logging verbosity -rather than changing levels. verbosity level 0 is always logged and should be -used for your standard logging. log.Info is identical to log.V(0).Info. - -There is log.Error, which is _not_ a level, but rather a helper function to log -a go `error`. `log.Error(err, "message")` is identical to -`log.Info("message", "cause", err)`. It merely provides a uniform interface for -logging errors. - -Let me explain with some examples: - -```go -log.V(1).Info("I will only be printed if log level is set to 1+") -log.V(2).Info("I will only be printed if log level is set to 2+") -log.V(3).Info("I will only be printed if log level is set to 3+") - -// These two logs are identical because Error is a helper that provides a -// uniform interface -log.V(3).Info("I will only be printed if log level is set to 3+", "cause", io.ErrClosedPipe) -log.V(3).Error(io.ErrClosedPipe, "I will only be printed if log level is set to 3+") +logerr is a library which uses [logr](https://github.com/go-logr/logr) to provide structured logging for applications. + +For migration information between versions, please check the [guide](./MIGRATION.md) + +## Quick `logr` Overview + +The `logr.Logger` differs from the traditional "log levels" (ex: trace, debug, info, error, fatal, etc) in favor of verbosity. The higher the verbosity level, the noisier the logs. + +Ex: + +```golang +// Traditional logger +logger.Trace("Entering method X. Useful for trace through, but not much else.") +logger.Fatal("Method X has crashed because of reason Y. This is useful info.") + +// logr +logger.V(5).Info("Entering method X. Useful for trace through, but not much else.") +logger.V(0).Info("Method X has crashed because of reason Y. This is useful info.") +``` + +A `logr.Logger` is created with an initial level of 0. Calling the `V` method will generate a new logger with a higher level. + +```golang +logger.V(1).Info("This logger's level has been raised by 1.") +logger.V(5).Info("This logger's level has been raised by 5.") +``` + +_Note: The `V` method is always additive. So logger.V(1).V(1) has a logger level of 2 instead of 1._ + +Every log has a verbosity, which is controlled by the internal logging mechanism `logr.Sink`. + +Logs are recorded in two scenarios: + +1. The log is an error. Errors - regardless of verbosity - are always logged (they are recorded at verbosity 0). +2. The log's verbosity is greater than or equal to the logger's level. + +Ex: + +```golang +logger.Info("This is a brand new logger. The log's verbosity is at 0 and the logger's level is 0. This log is recorded.") +logger.V(1).Info("Now this logger's level is 1, but the verbosity is still 0. This log is not recorded.") +logger.V(1).Error(errors.New("an error", "But this is an error. It's always recorded.")) ``` -This allows output control by limiting verbose messages. By default, only V -level 0 is printed. If you set verbosity to 1 then V level 0-1 will be printed. -Instead of controlling arbitrary message "levels" think of controlling the -amount of output pushed by your application. More verbose messages produce more -logs, but provide more information. You probably don't care about higher -verbosity messages unless you are trying to find a bug. When you are running -locally - -### How to choose? - -Traditional log levels give you the option of logging the level that you feel is -appropriate for the message. For example, log.Trace is typically referred to as -the most verbose output that contains lots of extra information such as -durations of method execution, printing variables, entering and exiting areas of -code, etc. However, this gets confusing when you compare it with log.Debug. -Where do you draw the line between trace and debug? There is no answer because -it's entirely arbitrary no matter how much you try to define it. With logerr the -answer of "how do I choose which verbosity level" is simple and also arbitrary. -You ask yourself "how much output is this going to produce and how useful is -that output? If you think the usefulness is high and the verbosity is low, then -you may just use log.Info which is _always_ logged. As the usefulness shrinks -and the verbosity raises, you should raise your the verbosity level of the log -line. - -## Log Verbosity Examples - -```go -func ServeHTTP(w http.ResponseWriter, r *http.Request) { - // this is going to be pretty noisy so lets set the verbosity level - // pretty high - log.V(3).Info("received HTTP request", - "url": r.URL, - "method": r.Method, - "remoteAddr": r.RemoteAddr, - ) - - userID, err := lookupUserID(r) - if err != nil { - // This is a critical path for us so we log.Error (verbosity 0) - // which is always printed and can never be suppressed - // log.Error and log.Info are identical to log.V(0).Error and - // log.V(0).Info, respectively - log.Error(err, "failed to lookup user ID") - w.WriteHeader(500) - return - } - - cache, err := redis.LookupCachedResponse(userID, r.URL, r.Method) - if err != nil { - // an error means something didn't happen like Redis wasn't - // reachable etc. Our caching layer isn't critical because we - // only use it for quicker responses, however our backend can - // handle 100% of traffic. This may cause a slight increase in - // response times, but it's going to get noisy and may cause - // Lets choose V 1 here - log.V(1).Error(err, "response cache error") - } - - if cache == nil { - // a cache miss isn't really important or helpful in production - // systems. We could use it when debugging to figure out how the - // code is handling requests though. This may be somewhat noisy, - // but it's not really helpful because a cache miss just means - // we will go to the source of truth so it's not a big deal. - log.V(2).Info("cache miss", - "user_id": userID, - "url": r.URL, - "method": r.Method, - ) - } -} +_Note: As mentioned above, with no concept of an "error" log, there is no error level. The `error` method simply provides a way to print an error log in a structured manner._ + +## log + +`log` provides methods for creating `logr.Logger` instances with a `logr.Sink` (`Sink`) that understands how to create JSON logs with key/value information. In general, the `Sink` does not need to be changed. +Logger Types: + +```golang +logger := log.NewLogger("default-logger") +logger.Info("Log verbosity is 0. Logs are written to stdout.") + +buffer := bytes.NewBuffer(nil) +newLogger := log.NewLogger("customized-logger", log.WithOutput(buffer), log.WithVerbosity(1)) +newLogger.Info("Log verbosity is 1. Logs are written to byte buffer.") ``` -As you can see the verbosity is _arbitrarily_ chosen based on a quick guess of -noisiness and usefulness. Less useful, more noisy messages get a higher V -level. More useful, less noisy messages use the default V 0 output so that they -are always printed. The philosophy is simple **spend less time thinking about -your log verbosity and more time coding**. Think of it like choosing scrum -points: compare it to previous log entries and ask yourself if it's greater -than, less than or the same in noise/usefulness. - -## Usage Examples - -```go -package main - -import ( - "github.com/ViaQ/logerr/kverrors" - "github.com/ViaQ/logerr/log" -) - -func Logging() { - err := TrySomething() - log.Error(err, "failed to do something", "application", "example") - // { - // "level": 0, <- this is verbosity - // "ts": "", - // "msg": "failed to do something", - // "application": "example" - // "cause": { - // "msg": "this was never meant to pass", - // "reason": "unimplemented", - // } - // } - - // Nested Errors - err = TrySomethingElse() - log.Error(err, "failed to do something", "application", "example") - // { - // "level": 0, <- this is verbosity - // "ts": "", - // "msg": "failed to do something", - // "application": "example" - // "cause": { - // "msg": "failed to execute method", - // "method": "TrySomething", - // "cause": { - // "msg": "this was never meant to pass", - // "reason": "unimplemented", - // } - // } - // } -} - - -func TrySomething() error { - return kverrors.New("this was never meant to pass", "reason", "unimplemented") -} - -func TrySomethingElse() error { - err := TrySomething() - return kverrors.Wrap(err, "failed to execute method", "method", "TrySomething") -} +As mentions, the `Sink` will transform messages into JSON logs. Key/value information that is included in the message is also included in the log. + +Ex: + +```golang +logger.Info("Log with key values", "key1", "value1", "key2", "value2") ``` + +## kverrors + +`kverrors` provides a package for creating key/value errors that create key/value (aka structured) errors. Errors should never contain sprintf strings, instead place key/value information into separate context that can be easily queried later (with jq or an advanced log framework like elasticsearch). diff --git a/go.mod b/go.mod index b04aaf0..fec7697 100644 --- a/go.mod +++ b/go.mod @@ -1,4 +1,4 @@ -module github.com/ViaQ/logerr +module github.com/ViaQ/logerr/v2 go 1.17 @@ -12,5 +12,3 @@ require ( github.com/pmezard/go-difflib v1.0.0 // indirect gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c // indirect ) - -retract [v1.1.0, v1.1.1] // Improper versioning of breaking changes diff --git a/internal/kv/kv.go b/internal/kv/kv.go index a4cbeb4..2a0b4ac 100644 --- a/internal/kv/kv.go +++ b/internal/kv/kv.go @@ -6,17 +6,21 @@ import ( // ToMap converts keysAndValues to a map func ToMap(keysAndValues ...interface{}) map[string]interface{} { - kve := map[string]interface{}{} + kvlen := len(keysAndValues) + kve := make(map[string]interface{}, kvlen/2) - for i, kv := range keysAndValues { - if i%2 == 1 { - continue - } - if len(keysAndValues) <= i+1 { - continue + for i, j := 0, 1; i < kvlen && j < kvlen; i, j = i+2, j+2 { + key, ok := keysAndValues[i].(string) + + // Expecting a string as the key, however will make a + // best guess through conversion if it isn't. + if !ok { + key = fmt.Sprintf("%s", keysAndValues[i]) } - kve[fmt.Sprintf("%s", kv)] = keysAndValues[i+1] + + kve[key] = keysAndValues[j] } + return kve } diff --git a/log/encoding.go b/internal/sink/encoding.go similarity index 96% rename from log/encoding.go rename to internal/sink/encoding.go index 0e14eb6..15b05bc 100644 --- a/log/encoding.go +++ b/internal/sink/encoding.go @@ -1,4 +1,4 @@ -package log +package sink import ( "encoding/json" diff --git a/internal/sink/line.go b/internal/sink/line.go new file mode 100644 index 0000000..28afad3 --- /dev/null +++ b/internal/sink/line.go @@ -0,0 +1,78 @@ +package sink + +import ( + "encoding/json" + "fmt" + "strconv" +) + +// Keys used to log specific builtin fields +const ( + TimeStampKey = "_ts" + FileLineKey = "_file:line" + LevelKey = "_level" + ComponentKey = "_component" + MessageKey = "_message" + ErrorKey = "_error" +) + +// Line orders log line fields +type Line struct { + Timestamp string + FileLine string + Verbosity string + Component string + Message string + Context map[string]interface{} +} + +// LineJSON add json tags to Line struct (production logs) +type LineJSON struct { + Timestamp string `json:"_ts"` + FileLine string `json:"-"` + Verbosity string `json:"_level"` + Component string `json:"_component"` + Message string `json:"_message"` + Context map[string]interface{} `json:"-"` +} + +// LineJSONDev add json tags to Line struct (developer logs, enable using environment variable LOG_DEV) +type LineJSONDev struct { + Timestamp string `json:"_ts"` + FileLine string `json:"_file:line"` + Verbosity string `json:"_level"` + Component string `json:"_component"` + Message string `json:"_message"` + Context map[string]interface{} `json:"-"` +} + +// MarshalJSON implements custom marshaling for log line: (1) flattening context (2) support for developer mode +func (l Line) MarshalJSON() ([]byte, error) { + lineTemp := LineJSON(l) + + lineValue, err := json.Marshal(lineTemp) + if err != nil { + return nil, err + } + verbosity, errConvert := strconv.Atoi(l.Verbosity) + if verbosity > 1 && errConvert == nil { + lineTempDev := LineJSONDev(l) + lineValue, err = json.Marshal(lineTempDev) + if err != nil { + return nil, err + } + } + lineValue = lineValue[1 : len(lineValue)-1] + + contextValue, err := json.Marshal(lineTemp.Context) + if err != nil { + return nil, err + } + contextValue = contextValue[1 : len(contextValue)-1] + + sep := "" + if len(contextValue) > 0 { + sep = "," + } + return []byte(fmt.Sprintf("{%s%s%s}", lineValue, sep, contextValue)), nil +} diff --git a/internal/sink/line_test.go b/internal/sink/line_test.go new file mode 100644 index 0000000..d23ddc9 --- /dev/null +++ b/internal/sink/line_test.go @@ -0,0 +1,96 @@ +package sink_test + +import ( + "fmt" + "testing" + + "github.com/ViaQ/logerr/v2/internal/sink" + "github.com/ViaQ/logerr/v2/kverrors" + "github.com/stretchr/testify/require" +) + +func TestLine_ProductionLogs(t *testing.T) { + // Logs with a level of 0 or 1 are considered to be production level logs + msg := "hello, world" + s, b := sinkWithBuffer("", 1) + + s.Info(0, msg) + logMsg := string(b.Bytes()) + + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, sink.MessageKey, msg)) + require.NotContains(t, logMsg, fmt.Sprintf(`%q`, sink.FileLineKey)) +} + +func TestLine_DeveloperLogs(t *testing.T) { + // Logs with a higher level than 1 are considered to be developer level logs + msg := "hello, world" + s, b := sinkWithBuffer("", 2) + + s.Info(1, msg) + logMsg := string(b.Bytes()) + + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, sink.MessageKey, msg)) + require.Contains(t, logMsg, fmt.Sprintf(`%q`, sink.FileLineKey)) +} + +func TestLine_WithNoContext(t *testing.T) { + msg := "hello, world" + l := sink.Line{Message: msg} + + b, err := l.MarshalJSON() + + require.NoError(t, err) + require.Contains(t, string(b), fmt.Sprintf(`%q:%q`, sink.MessageKey, msg)) +} + +func TestLine_LogLevel(t *testing.T) { + s, b := sinkWithBuffer("", 0) + + for level := 0; level < 5; level++ { + b.Reset() + s.SetVerbosity(level) + + s.Info(0, "hello, world") + + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:"%d"`, sink.LevelKey, level)) + } +} + +func TestLine_WithKVError(t *testing.T) { + err := kverrors.New("an error", "key", "value") + msg := "Error bypasses the enabled check." + + kverrMsg, _ := err.(*kverrors.KVError).MarshalJSON() + + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + errorValue := fmt.Sprintf(`%q:%v`, sink.ErrorKey, string(kverrMsg)) + + s, b := sinkWithBuffer("", 0) + + s.Error(err, msg) + + logMsg := string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, errorValue) +} + +func TestLine_WithNestedKVError(t *testing.T) { + err := kverrors.New("an error", "key", "value") + wrappedErr := kverrors.Wrap(err, "main error", "key", "value") + msg := "Error bypasses the enabled check." + + kverrMsg, _ := wrappedErr.(*kverrors.KVError).MarshalJSON() + + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + errorValue := fmt.Sprintf(`%q:%v`, sink.ErrorKey, string(kverrMsg)) + + s, b := sinkWithBuffer("", 0) + + s.Error(wrappedErr, msg) + + logMsg := string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, errorValue) +} diff --git a/log/logsink.go b/internal/sink/sink.go similarity index 61% rename from log/logsink.go rename to internal/sink/sink.go index 4a8573d..39d2fd9 100644 --- a/log/logsink.go +++ b/internal/sink/sink.go @@ -1,7 +1,6 @@ -package log +package sink import ( - "encoding/json" "fmt" "io" "os" @@ -12,95 +11,11 @@ import ( "sync" "time" - "github.com/ViaQ/logerr/internal/kv" - "github.com/ViaQ/logerr/kverrors" + "github.com/ViaQ/logerr/v2/internal/kv" + "github.com/ViaQ/logerr/v2/kverrors" "github.com/go-logr/logr" ) -// Keys used to log specific builtin fields -const ( - TimeStampKey = "_ts" - FileLineKey = "_file:line" - LevelKey = "_level" - ComponentKey = "_component" - MessageKey = "_message" - ErrorKey = "_error" -) - -// Line orders log line fields -type Line struct { - Timestamp string - FileLine string - Verbosity string - Component string - Message string - Context map[string]interface{} -} - -// LineJSON add json tags to Line struct (production logs) -type LineJSON struct { - Timestamp string `json:"_ts"` - FileLine string `json:"-"` - Verbosity string `json:"_level"` - Component string `json:"_component"` - Message string `json:"_message"` - Context map[string]interface{} `json:"-"` -} - -// LineJSONDev add json tags to Line struct (developer logs, enable using environment variable LOG_DEV) -type LineJSONDev struct { - Timestamp string `json:"_ts"` - FileLine string `json:"_file:line"` - Verbosity string `json:"_level"` - Component string `json:"_component"` - Message string `json:"_message"` - Context map[string]interface{} `json:"-"` -} - -// MarshalJSON implements custom marshaling for log line: (1) flattening context (2) support for developer mode -func (l Line) MarshalJSON() ([]byte, error) { - lineTemp := LineJSON(l) - - lineValue, err := json.Marshal(lineTemp) - if err != nil { - return nil, err - } - verbosity, errConvert := strconv.Atoi(l.Verbosity) - if verbosity > 1 && errConvert == nil { - lineTempDev := LineJSONDev(l) - lineValue, err = json.Marshal(lineTempDev) - if err != nil { - return nil, err - } - } - lineValue = lineValue[1 : len(lineValue)-1] - - contextValue, err := json.Marshal(lineTemp.Context) - if err != nil { - return nil, err - } - contextValue = contextValue[1 : len(contextValue)-1] - - sep := "" - if len(contextValue) > 0 { - sep = "," - } - return []byte(fmt.Sprintf("{%s%s%s}", lineValue, sep, contextValue)), nil -} - -// Verbosity is a level of verbosity to log between 0 and math.MaxInt32 -// However it is recommended to keep the numbers between 0 and 3 -type Verbosity int - -func (v Verbosity) String() string { - return strconv.Itoa(int(v)) -} - -// MarshalJSON marshas JSON -func (v Verbosity) MarshalJSON() ([]byte, error) { - return []byte(v.String()), nil -} - // TimestampFunc returns a string formatted version of the current time. // This should probably only be used with tests or if you want to change // the default time formatting of the output logs. @@ -213,11 +128,17 @@ func (s *Sink) SetVerbosity(v int) { s.verbosity = Verbosity(v) } +// GetVerbosity returns the log level +func (s *Sink) GetVerbosity() int { + return int(s.verbosity) +} + // log will log the message. It DOES NOT check Enabled() first so that should // be checked by it's callers func (s *Sink) log(msg string, context map[string]interface{}) { _, file, line, _ := runtime.Caller(3) file = sourcePath(file) + m := Line{ Timestamp: TimestampFunc(), FileLine: fmt.Sprintf("%s:%s", file, strconv.Itoa(line)), @@ -238,19 +159,16 @@ func (s *Sink) log(msg string, context map[string]interface{}) { // combine creates a new map combining context and keysAndValues. func combine(context map[string]interface{}, keysAndValues ...interface{}) map[string]interface{} { nc := make(map[string]interface{}, len(context)+len(keysAndValues)/2) - for i := 0; i < len(keysAndValues); i += 2 { - if i+1 < len(keysAndValues) { - key, ok := keysAndValues[i].(string) // It should be a string. - if !ok { // But this is not the place to panic - key = fmt.Sprintf("%s", keysAndValues[i]) // So use this expensive conversion instead. - } - nc[key] = keysAndValues[i+1] - } - } + for k, v := range context { nc[k] = v } + kve := kv.ToMap(keysAndValues...) + for k, v := range kve { + nc[k] = v + } + return nc } diff --git a/internal/sink/sink_test.go b/internal/sink/sink_test.go new file mode 100644 index 0000000..cc136c1 --- /dev/null +++ b/internal/sink/sink_test.go @@ -0,0 +1,244 @@ +package sink_test + +import ( + "bytes" + "fmt" + "io" + "math" + "testing" + + "github.com/ViaQ/logerr/v2/internal/sink" + "github.com/ViaQ/logerr/v2/kverrors" + "github.com/go-logr/logr" + "github.com/stretchr/testify/require" +) + +func TestSink_Enabled(t *testing.T) { + s, _ := sinkWithBuffer("", 0) + + require.True(t, s.Enabled(0)) + require.False(t, s.Enabled(1)) + + ss, _ := sinkWithBuffer("", 1) + + require.True(t, ss.Enabled(1)) + require.True(t, ss.Enabled(0)) + require.False(t, ss.Enabled(2)) +} + +func TestSink_Info(t *testing.T) { + msg := "Same or lower than current verbosity. This should be logged." + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + + s, b := sinkWithBuffer("", 0) + + s.Info(0, msg) + + logMsg := string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + + // Reset the buffer to ensure to avoid false positive of message + b.Reset() + s.Info(0, msg, "hello", "world") + + logMsg = string(b.Bytes()) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, "hello", "world")) +} + +func TestSink_Info_Enabled(t *testing.T) { + s, b := sinkWithBuffer("", 1) + + s.Info(2, "Above current verbosity. This should not be logged.") + require.Empty(t, b.Bytes()) + + s.Info(0, "Same or lower than current verbosity. This should be logged.") + require.NotEmpty(t, b.Bytes()) +} + +func TestSink_Error(t *testing.T) { + err := kverrors.New("an error") + msg := "Error bypasses the enabled check." + + kverrMsg, _ := err.(*kverrors.KVError).MarshalJSON() + + msgValue := fmt.Sprintf(`%q:%q`, sink.MessageKey, msg) + levelValue := fmt.Sprintf(`%q:"%d"`, sink.LevelKey, 0) + errorValue := fmt.Sprintf(`%q:%v`, sink.ErrorKey, string(kverrMsg)) + + s, b := sinkWithBuffer("", 0) + + s.Error(err, msg) + + logMsg := string(b.Bytes()) + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, levelValue) + require.Contains(t, logMsg, errorValue) + + // Reset the buffer to ensure to avoid false positive of message + b.Reset() + + s.Error(err, msg, "hello", "world") + + logMsg = string(b.Bytes()) + require.NotEmpty(t, logMsg) + require.Contains(t, logMsg, msgValue) + require.Contains(t, logMsg, levelValue) + require.Contains(t, logMsg, errorValue) + require.Contains(t, logMsg, fmt.Sprintf(`%q:%q`, "hello", "world")) +} + +func TestSink_Error_Enabled(t *testing.T) { + // Use a logger to create a scenario in which the logger's + // level will be greater than the current verbosity. This means + // that info will not work. However, error should always work, regardless. + s, b := sinkWithBuffer("", 0) + + // Logger level: 2, Sink Verbosity: 0 + l := logr.New(s).V(2) + require.Equal(t, 0, s.GetVerbosity()) + + l.Info("Above current verbosity. This should not be logged.") + require.Empty(t, b.Bytes()) + + l.Error(kverrors.New("an error"), "Error bypasses the enabled check.") + require.NotEmpty(t, b.Bytes()) +} + +func TestSink_Error_WithNilError(t *testing.T) { + // Use a logger to create a scenario in which the logger's + // level will be greater than the current verbosity. This means + // that info will not work. However, error should always work, regardless. + s, b := sinkWithBuffer("", 0) + + s.Error(nil, "No error sent. This should be logged.") + msg := string(b.Bytes()) + + require.NotEmpty(t, msg) +} + +func TestSink_Error_WithNonKVError(t *testing.T) { + err := io.ErrClosedPipe + errValue := fmt.Sprintf(`%q:{"msg":%q}`, sink.ErrorKey, err.Error()) + + s, b := sinkWithBuffer("", 0, "hello", "world") + + s.Error(err, "hello, world") + msg := string(b.Bytes()) + + require.NotEmpty(t, msg) + require.Contains(t, msg, errValue) +} + +func TestSink_WithValues(t *testing.T) { + s, b := sinkWithBuffer("", 0, "hello", "world") + + s.Info(0, "First.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "hello", "world")) + + ss := s.WithValues("foo", "bar") + + ss.Error(nil, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "hello", "world")) + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "foo", "bar")) +} + +func TestSink_WithValues_NoKeyValues(t *testing.T) { + s, b := sinkWithBuffer("", 0, nil) + ss := s.WithValues("foo", "bar") + + ss.Error(nil, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, "foo", "bar")) +} + +func TestSink_WithKeyAndNoValues(t *testing.T) { + s, b := sinkWithBuffer("", 0, "hello") + + s.Info(0, "First.") + + // Ensuring that dangling key/values are not recorded + require.NotContains(t, string(b.Bytes()), fmt.Sprintf(`%q:`, "hello")) +} + +func TestSink_WithName(t *testing.T) { + s, b := sinkWithBuffer("new", 0) + + s.Info(0, "First.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, sink.ComponentKey, "new")) + + ss := s.WithName("append") + + ss.Info(0, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, sink.ComponentKey, "new_append")) +} + +func TestSink_WithEmptyName(t *testing.T) { + s, b := sinkWithBuffer("", 0) + + s.Info(0, "First.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:""`, sink.ComponentKey)) + + ss := s.WithName("new") + + ss.Info(0, "Second.") + require.Contains(t, string(b.Bytes()), fmt.Sprintf(`%q:%q`, sink.ComponentKey, "new")) +} + +func TestSink_SetOutput(t *testing.T) { + bb := bytes.NewBuffer(nil) + + s, b := sinkWithBuffer("", 0) + s.SetOutput(bb) + + s.Info(0, "Same or lower than current verbosity. This should be logged.") + require.Empty(t, b.Bytes()) + require.NotEmpty(t, bb.Bytes()) +} + +func TestSink_SetVerbosity(t *testing.T) { + s, b := sinkWithBuffer("", 0) + + s.Info(1, "Above current verbosity. This should not be logged.") + require.Empty(t, b.Bytes()) + + s.SetVerbosity(1) + + s.Info(1, "Same or lower than current verbosity. This should be logged.") + require.NotEmpty(t, b.Bytes()) +} + +func TestSink_GetVerbosity(t *testing.T) { + s, _ := sinkWithBuffer("", 0) + require.Equal(t, 0, s.GetVerbosity()) + + s.SetVerbosity(10) + require.Equal(t, 10, s.GetVerbosity()) +} + +func TestSink_Log_EncodingFailure(t *testing.T) { + unsupportedValues := []float64{ + math.NaN(), + math.Inf(-1), + math.Inf(1), + } + + for _, unsupportedValue := range unsupportedValues { + s, b := sinkWithBuffer("", 0) + + // Info and Error use the same mechanism, so using Info for the test + s.Info(0, "Test unsupported value", "value", unsupportedValue) + msg := string(b.Bytes()) + + require.NotEmpty(t, msg) + require.Contains(t, msg, "failed to encode message") + require.Contains(t, msg, fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) + } +} + +func sinkWithBuffer(component string, level int, keyValuePairs ...interface{}) (*sink.Sink, *bytes.Buffer) { + buffer := bytes.NewBuffer(nil) + sink := sink.NewLogSink(component, buffer, sink.Verbosity(level), sink.JSONEncoder{}, keyValuePairs...) + + return sink, buffer +} diff --git a/internal/sink/verbosity.go b/internal/sink/verbosity.go new file mode 100644 index 0000000..38c9a82 --- /dev/null +++ b/internal/sink/verbosity.go @@ -0,0 +1,18 @@ +package sink + +import ( + "strconv" +) + +// Verbosity is a level of verbosity to log between 0 and math.MaxInt32 +// However it is recommended to keep the numbers between 0 and 3 +type Verbosity int + +func (v Verbosity) String() string { + return strconv.Itoa(int(v)) +} + +// MarshalJSON marshas JSON +func (v Verbosity) MarshalJSON() ([]byte, error) { + return []byte(v.String()), nil +} diff --git a/kverrors/kverrors.go b/kverrors/kverrors.go index 626da03..7c312a2 100644 --- a/kverrors/kverrors.go +++ b/kverrors/kverrors.go @@ -5,7 +5,7 @@ import ( "errors" "fmt" - "github.com/ViaQ/logerr/internal/kv" + "github.com/ViaQ/logerr/v2/internal/kv" ) // Keys used to log specific builtin fields diff --git a/kverrors/kverrors_test.go b/kverrors/kverrors_test.go index eceac05..aded923 100644 --- a/kverrors/kverrors_test.go +++ b/kverrors/kverrors_test.go @@ -6,8 +6,8 @@ import ( "io" "testing" - "github.com/ViaQ/logerr/internal/kv" - "github.com/ViaQ/logerr/kverrors" + "github.com/ViaQ/logerr/v2/internal/kv" + "github.com/ViaQ/logerr/v2/kverrors" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) diff --git a/log/fake_test.go b/log/fake_test.go deleted file mode 100644 index e09a0d6..0000000 --- a/log/fake_test.go +++ /dev/null @@ -1,17 +0,0 @@ -package log_test - -import ( - "io" -) - -// fakeEncoder is an encoder that you can use for testing -type fakeEncoder struct { - EncodeFunc func(w io.Writer, entry interface{}) error -} - -func (f fakeEncoder) Encode(w io.Writer, entry interface{}) error { - if f.EncodeFunc != nil { - return f.EncodeFunc(w, entry) - } - return nil -} diff --git a/log/fakes_test.go b/log/fakes_test.go deleted file mode 100644 index 12fbf45..0000000 --- a/log/fakes_test.go +++ /dev/null @@ -1,28 +0,0 @@ -package log_test - -import ( - "github.com/go-logr/logr" -) - -type nopLogSink struct{} - -func (nopLogSink) Init(logr.RuntimeInfo) { -} - -func (nopLogSink) Enabled(int) bool { - return false -} - -func (nopLogSink) Info(int, string, ...interface{}) { -} - -func (nopLogSink) Error(error, string, ...interface{}) { -} - -func (nopLogSink) WithValues(...interface{}) logr.LogSink { - return nil -} - -func (nopLogSink) WithName(string) logr.LogSink { - return nil -} diff --git a/log/log.go b/log/log.go index 308ea67..6a2e225 100644 --- a/log/log.go +++ b/log/log.go @@ -1,63 +1,19 @@ package log import ( - "fmt" "os" - "github.com/ViaQ/logerr/kverrors" + "github.com/ViaQ/logerr/v2/internal/sink" "github.com/go-logr/logr" ) -var ( - // ErrUnknownSinkType is returned when trying to perform a *Logger only function - // that is incompatible with logr.Logger interface - ErrUnknownSinkType = kverrors.New("unknown log sink type") - - defaultOutput = os.Stdout - - defaultLogger = logr.New(NewLogSink("", defaultOutput, 0, JSONEncoder{})) -) - -// DefaultLogger creates a logger without any key value pairs -func DefaultLogger() logr.Logger { - return defaultLogger -} - -// NewLogger creates a logger with the provided key value pairs -func NewLogger(component string, keyValuePairs ...interface{}) logr.Logger { - return NewLoggerWithOptions(component, nil, keyValuePairs...) -} - -// NewLoggerWithOptions creates a logger with the provided opts and key value pairs -func NewLoggerWithOptions(component string, opts []Option, keyValuePairs ...interface{}) logr.Logger { - s := NewLogSink(component, defaultOutput, 0, JSONEncoder{}, keyValuePairs...) +// NewLogger creates a logger with the provided opts and key value pairs +func NewLogger(component string, opts ...Option) logr.Logger { + sink := sink.NewLogSink(component, os.Stdout, 0, sink.JSONEncoder{}, nil) for _, opt := range opts { - opt(s) + opt(sink) } - return logr.New(s) -} - -// GetSink return the LogSink converted as a Sink object. It returns an -// error if it cannot convert it. -func GetSink(l logr.Logger) (*Sink, error) { - s, ok := l.GetSink().(*Sink) - - if !ok { - return nil, kverrors.Add(ErrUnknownSinkType, - "sink_type", fmt.Sprintf("%T", s), - "expected_type", fmt.Sprintf("%T", &Sink{}), - ) - } - return s, nil -} - -// MustGetSink retrieves the Sink and panics if it gets an error from GetSink -func MustGetSink(l logr.Logger) *Sink { - s, err := GetSink(l) - if err != nil { - panic(err) - } - return s + return logr.New(sink) } diff --git a/log/log_test.go b/log/log_test.go index ee98790..d81cab2 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -2,181 +2,34 @@ package log_test import ( "bytes" - "errors" "fmt" - "github.com/ViaQ/logerr/internal/kv" - "io/ioutil" "testing" - "github.com/ViaQ/logerr/kverrors" - "github.com/ViaQ/logerr/log" - "github.com/go-logr/logr" - "github.com/stretchr/testify/assert" + "github.com/ViaQ/logerr/v2/internal/sink" + "github.com/ViaQ/logerr/v2/log" "github.com/stretchr/testify/require" ) -// This test exists to confirm that the output actually works. There was a previous bug that broke the real logger -// because DefaultConfig specified a sampling which caused a panic. This uses a real logger and logs just to verify -// that it _can_ log successfully. There are no assertions because the content of the logs are irrelevant. See -// TestLogger_V above for a more comprehensive test. -func TestLogger_V_Integration(t *testing.T) { - for i := 1; i < 5; i++ { - verbosity := i - testName := fmt.Sprintf("verbosity-%d", verbosity) - l := log.NewLoggerWithOptions(testName, []log.Option{ - log.WithOutput(ioutil.Discard), - log.WithLogLevel(verbosity), - }) - t.Run(testName, func(t *testing.T) { - for logLevel := 1; logLevel < 5; logLevel++ { - l.V(logLevel).Info("hello, world") - } - }) - } -} - func TestNewLogger(t *testing.T) { + level := 1 component := "mycomponent" - buf := bytes.NewBuffer(nil) - - l := log.NewLogger(component) - s, err := log.GetSink(l) - - require.NoError(t, err) - - s.SetOutput(buf) - l.Info("laskdjfhiausdc") - - expected := fmt.Sprintf(`%q:%q`, log.ComponentKey, component) - actual := string(buf.Bytes()) - - require.Contains(t, actual, expected) -} - -func TestInfo(t *testing.T) { - obs, l := NewObservedLogger() - - msg := t.Name() - l.Info(msg) - - logs := obs.Logs() - require.Len(t, logs, 1) - require.EqualValues(t, msg, logs[0].Message) -} - -func TestError(t *testing.T) { - obs, l := NewObservedLogger() - - msg := t.Name() - err := errors.New("fail boat") - - l.Error(err, msg) - - logs := obs.Logs() - require.Len(t, logs, 1) - require.EqualValues(t, msg, logs[0].Message) - require.NotNil(t, logs[0].Error) - require.EqualValues(t, err.Error(), logs[0].Error.Error()) -} - -func TestWithValues(t *testing.T) { - obs, l := NewObservedLogger() - - msg := t.Name() - ll := l.WithValues("hello", "world") - - t.Run("Error", func(t *testing.T) { - ll.Error(errors.New("fail boat"), msg) - logs := obs.TakeAll() - require.Len(t, logs, 1) - assert.EqualValues(t, msg, logs[0].Message) - assert.EqualValues(t, kv.ToMap("hello", "world"), logs[0].Context) - }) - - t.Run("Info", func(t *testing.T) { - ll.Info(msg, "a", "b") - ll.Info(msg, "c", "d") - logs := obs.TakeAll() - require.Len(t, logs, 2) - assert.EqualValues(t, msg, logs[0].Message) - assert.EqualValues(t, kv.ToMap("a", "b", "hello", "world"), logs[0].Context) - assert.EqualValues(t, kv.ToMap("c", "d", "hello", "world"), logs[1].Context) - }) -} - -func TestSetLogLevel(t *testing.T) { - obs, l := NewObservedLogger() - s, err := log.GetSink(l) - - require.NoError(t, err) - - const logLevel = 4 - msg := t.Name() - - s.SetVerbosity(logLevel) - l.V(logLevel).Info(msg) - - logs := obs.TakeAll() - require.NotEmpty(t, logs) - - require.EqualValues(t, msg, logs[0].Message) -} - -func TestSetOutput(t *testing.T) { - obs, l := NewObservedLogger() - s, err := log.GetSink(l) - - require.NoError(t, err) - - msg := t.Name() - buf := bytes.NewBuffer(nil) - - s.SetOutput(buf) - - l.Info(msg) - logs := obs.TakeAll() - - require.NotEmpty(t, logs) - require.Contains(t, logs[0].Message, msg) -} - -func TestGetSink_WithUnknownLogSink_Errors(t *testing.T) { - l := logr.New(nopLogSink{}) - _, err := log.GetSink(l) - - actual := kverrors.Root(err) - require.Equal(t, log.ErrUnknownSinkType, actual) -} - -func TestWithName(t *testing.T) { - obs, _ := NewObservedLogger() - - l := logr.New(log.NewLogSink("", ioutil.Discard, 0, obs)).WithName("mycomponent") - ll := l.WithName("mynameis") - - msg := t.Name() - ll.Info(msg) - - logs := obs.TakeAll() - require.NotEmpty(t, logs) - - require.Contains(t, logs[0].Component, "mycomponent") - require.Contains(t, logs[0].Component, "mynameis") -} + componentValue := fmt.Sprintf(`%q:%q`, sink.ComponentKey, component) -func TestV(t *testing.T) { - obs, l := NewObservedLogger() - s, err := log.GetSink(l) + b := bytes.NewBuffer(nil) + bb := bytes.NewBuffer(nil) - require.NoError(t, err) + l := log.NewLogger(component, log.WithOutput(b)) + l.Info("Default configuration. Though still need to override the stdout writer to test.") + msg := string(b.Bytes()) - msg := t.Name() + require.Contains(t, msg, componentValue) + require.Contains(t, msg,fmt.Sprintf(`%q:"%d"`, sink.LevelKey, 0)) - s.SetVerbosity(1) - l.V(1).Info(msg) + ll := log.NewLogger(component, log.WithOutput(bb), log.WithVerbosity(level)) + ll.Info("Non-default configuration.") + msg = string(bb.Bytes()) - logs := obs.TakeAll() - require.NotEmpty(t, logs) - require.Equal(t, msg, logs[0].Message) + require.Contains(t, msg, componentValue) + require.Contains(t, msg,fmt.Sprintf(`%q:"%d"`, sink.LevelKey, level)) } diff --git a/log/logsink_test.go b/log/logsink_test.go deleted file mode 100644 index f6c4869..0000000 --- a/log/logsink_test.go +++ /dev/null @@ -1,380 +0,0 @@ -package log_test - -import ( - "bytes" - "encoding/json" - "fmt" - "io" - "io/ioutil" - "math" - "reflect" - "testing" - - "github.com/ViaQ/logerr/kverrors" - "github.com/ViaQ/logerr/log" - "github.com/go-logr/logr" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" -) - -func TestLogger_Info_WithKeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Info("hello, world", "city", "Athens") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - "city": "Athens", - }, - ) -} - -func TestLogger_Error_noKeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := kverrors.New("an error") - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - require.Len(t, logs, 1) - require.EqualValues(t, "hello, world", logs[0].Message) - require.EqualValues(t, err, logs[0].Error) -} - -var unsupportedValues = []float64{ - math.NaN(), - math.Inf(-1), - math.Inf(1), -} - -func TestLogger_Info_UnsupportedValues(t *testing.T) { - for _, unsupportedValue := range unsupportedValues { - buf := bytes.NewBuffer(nil) - logger := logr.New(log.NewLogSink("", buf, 0, log.JSONEncoder{})) - logger.Info("Test unsupported value", "value", unsupportedValue) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), "failed to encode message") - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) - } -} - -func TestLogger_Error_UnsupportedValues(t *testing.T) { - for _, unsupportedValue := range unsupportedValues { - buf := bytes.NewBuffer(nil) - logger := log.NewLogSink("", buf, 0, log.JSONEncoder{}) - err := kverrors.New("an error") - logger.Error(err, "Test unsupported value", "key", unsupportedValue) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - println(string(buf.Bytes())) - assert.Contains(t, string(buf.Bytes()), "failed to encode message") - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf("json: unsupported value: %f", unsupportedValue)) - } -} - -func TestLogger_Error_KeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := kverrors.New("an error") - logger.Error(err, "hello, world", "key", "value") - - logs := obs.TakeAll() - require.Len(t, logs, 1) - require.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - "key": "value", - }, - ) -} - -func TestLogger_Error_pkg_error_KeysAndValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := kverrors.New("an error", "key", "value") - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - require.EqualValues(t, err, logs[0].Error) - - assertLoggedFields(t, - logs[0], - Fields{ - log.MessageKey: "hello, world", - log.ErrorKey: map[string]interface{}{ - "msg": "an error", - "key": "value", - }, - }, - ) -} - -func TestLogger_Error_nested_error(t *testing.T) { - obs, logger := NewObservedLogger() - - err1 := kverrors.New("error1", "order", 1) - err := kverrors.Wrap(err1, "main error", "key", "value") - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - log.ErrorKey: map[string]interface{}{ - "key": "value", - "msg": kverrors.Message(err), - kverrors.CauseKey: map[string]interface{}{ - "order": 1, - "msg": kverrors.Message(err1), - }, - }, - }, - ) -} - -func TestLogger__PlainErrors_ConvertedToStructured(t *testing.T) { - obs, logger := NewObservedLogger() - - err := io.ErrClosedPipe - logger.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - log.ErrorKey: map[string]interface{}{ - "msg": err.Error(), - }, - }, - ) -} - -func TestLogger_WithValues_AddsValues(t *testing.T) { - obs, logger := NewObservedLogger() - - err := io.ErrClosedPipe - ll := logger.WithValues("key", "value") - - ll.Error(err, "hello, world") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - "key": "value", - }, - ) -} - -func TestLogger_Error_MakesUnstructuredErrorsStructured(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Error(io.ErrClosedPipe, t.Name()) - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - - assertLoggedFields(t, - logs[0], - Fields{ - log.ErrorKey: map[string]interface{}{ - "msg": io.ErrClosedPipe.Error(), - }, - }, - ) -} - -func TestLogger_Error_WorksWithNilError(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Error(nil, t.Name()) - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.Nil(t, logs[0].Error) -} - -func TestLogger_V_Info(t *testing.T) { - // loop through log levels 1-5 and log all of them to verify that they either - // are or are not logged according to verbosity above - for verbosity := 1; verbosity < 5; verbosity++ { - for logLevel := 1; logLevel < 5; logLevel++ { - obs, logger := NewObservedLogger() - logger.GetSink().(*log.Sink).SetVerbosity(verbosity) - - logger.V(logLevel).Info("hello, world") - - logs := obs.TakeAll() - - if verbosity >= logLevel { - assert.Len(t, logs, 1, "expected log to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) - assert.EqualValues(t, "hello, world", logs[0].Message) - } else { - assert.Empty(t, logs, "expected NO logs to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) - } - } - } -} - -func TestLogger_V_Error(t *testing.T) { - // Error messages should always be logged regardless of level - for verbosity := 1; verbosity < 5; verbosity++ { - for logLevel := 1; logLevel < 5; logLevel++ { - obs, logger := NewObservedLogger() - logger.GetSink().(*log.Sink).SetVerbosity(verbosity) - - logger.V(logLevel).Error(io.ErrUnexpectedEOF, "hello, world") - - logs := obs.TakeAll() - - assert.Len(t, logs, 1, "expected log to be present for verbosity:%d, logLevel:%d", verbosity, logLevel) - assert.EqualValues(t, "hello, world", logs[0].Message) - } - } -} - -func TestLogger_SetsVerbosity(t *testing.T) { - obs, logger := NewObservedLogger() - - logger.Info(t.Name()) - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, 0, logs[0].Verbosity) -} - -func TestLogger_TestSetOutput(t *testing.T) { - buf := bytes.NewBuffer(nil) - - s := log.NewLogSink("", ioutil.Discard, 0, log.JSONEncoder{}) - s.SetOutput(buf) - - logger := logr.New(s) - - msg := "hello, world" - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) -} - -func TestLogger_Info_PrintsError_WhenEncoderErrors(t *testing.T) { - err := io.ErrShortBuffer - fenc := fakeEncoder{ - EncodeFunc: func(_ io.Writer, _ interface{}) error { - return &json.MarshalerError{ - Type: reflect.TypeOf(&json.MarshalerError{}), - Err: err, - } - }, - } - - buf := bytes.NewBuffer(nil) - logger := logr.New(log.NewLogSink("", buf, 0, fenc)) - - msg := "hello, world" - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected buffer output, but buffer was empty") - } - - output := string(buf.Bytes()) - assert.Contains(t, output, msg, "has the original message") - assert.Contains(t, output, err.Error(), "shows the original error") - assert.Contains(t, output, reflect.TypeOf(fenc).String(), "explains the encoder that failed") -} - -func TestLogger_LogsLevel(t *testing.T) { - const v = 2 - - obs, logger := NewObservedLogger() - logger.GetSink().(*log.Sink).SetVerbosity(v) - - logger.V(v).Info("hello, world", "city", "Athens") - - logs := obs.TakeAll() - assert.Len(t, logs, 1) - assert.EqualValues(t, "hello, world", logs[0].Message) - - assertLoggedFields(t, - logs[0], - Fields{ - log.LevelKey: v, - }, - ) -} - -func TestLogger_ProductionLogsLevel(t *testing.T) { - const v = 0 - - buf := bytes.NewBuffer(nil) - s := log.NewLogSink("", ioutil.Discard, v, log.JSONEncoder{}) - s.SetOutput(buf) - - msg := "hello, world" - logger := logr.New(s) - - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) - assert.NotContains(t, string(buf.Bytes()), fmt.Sprintf(`%q`, log.FileLineKey)) -} - -func TestLogger_DeveloperLogsLevel(t *testing.T) { - const v = 2 - - buf := bytes.NewBuffer(nil) - s := log.NewLogSink("", ioutil.Discard, v, log.JSONEncoder{}) - s.SetOutput(buf) - - msg := "hello, world" - logger := logr.New(s) - - logger.Info(msg) - - if buf.Len() == 0 { - t.Fatal("expected log output, but buffer was empty") - } - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) - assert.Contains(t, string(buf.Bytes()), fmt.Sprintf(`%q`, log.FileLineKey)) -} - -func TestLogger_LogLineWithNoContext(t *testing.T) { - msg := "hello, world" - l := log.Line{ - Message: msg, - } - - buf, err := l.MarshalJSON() - assert.Nil(t, err) - assert.Contains(t, string(buf), fmt.Sprintf(`%q:%q`, log.MessageKey, msg)) -} diff --git a/log/observer_test.go b/log/observer_test.go deleted file mode 100644 index 1233050..0000000 --- a/log/observer_test.go +++ /dev/null @@ -1,164 +0,0 @@ -package log_test - -import ( - "bytes" - "encoding/json" - "fmt" - "io" - "io/ioutil" - "os" - "strconv" - "testing" - "time" - - "github.com/ViaQ/logerr/kverrors" - "github.com/ViaQ/logerr/log" - "github.com/go-logr/logr" - "github.com/stretchr/testify/require" -) - -type Fields map[string]interface{} - -// assertLoggedFields checks that all of fields exists in the entry. -func assertLoggedFields(t *testing.T, entry *observedEntry, fields Fields) { - var f []string - for k := range fields { - f = append(f, k) - } - - ctx := entry.Fields(f...) - - for k, v := range fields { - value, ok := ctx[k] - require.True(t, ok, "expected key '%s:%v' to exist in logged entry %+v", k, v, entry) - actual, e := json.Marshal(value) - require.NoError(t, e) - expected, e := json.Marshal(v) - require.NoError(t, e) - require.JSONEq(t, string(expected), string(actual), "key: %q", k) - } -} - -type observedEntry struct { - Component string - Message string - Timestamp string - Context map[string]interface{} - Error error - Verbosity log.Verbosity - FileLine string -} - -// Fields filters the entry to the specified fields and returns the result as a map. -// This will include all known/parsed fields (such as Message, Timestamp) as well as -// all Context items. -func (o *observedEntry) Fields(fields ...string) Fields { - entry := o.ToMap() - filtered := Fields{} - - for _, f := range fields { - filtered[f] = entry[f] - } - return filtered -} - -// RawFields drops all but the specified from the entry and returns the encoded result -func (o *observedEntry) RawFields(fields ...string) ([]byte, error) { - filtered := o.Fields(fields...) - b := bytes.NewBuffer(nil) - err := log.JSONEncoder{}.Encode(b, filtered) - return b.Bytes(), err -} - -func (o *observedEntry) ToMap() map[string]interface{} { - m := make(map[string]interface{}, len(o.Context)) - for k, v := range o.Context { - m[k] = v - } - m[log.ErrorKey] = o.Error - m[log.MessageKey] = o.Message - m[log.TimeStampKey] = o.Timestamp - m[log.ComponentKey] = o.Component - m[log.LevelKey] = o.Verbosity - m[log.FileLineKey] = o.FileLine - return m -} - -func (o *observedEntry) Raw() ([]byte, error) { - entry := o.ToMap() - - b := bytes.NewBuffer(nil) - err := log.JSONEncoder{}.Encode(b, entry) - return b.Bytes(), err -} - -// observableEncoder stores all entries in a buffer rather than encoding them to an output -type observableEncoder struct { - entries []*observedEntry -} - -// Encode stores all entries in a buffer rather than encoding them to an output -func (o *observableEncoder) Encode(_ io.Writer, m interface{}) error { - o.entries = append(o.entries, parseEntry(m)) - return nil -} - -// Logs returns all logs in the buffer -func (o *observableEncoder) Logs() []*observedEntry { - return o.entries -} - -// TakeAll returns all logs and clears the buffer -func (o *observableEncoder) TakeAll() []*observedEntry { - defer o.Reset() - return o.Logs() -} - -// Reset empties the buffer -func (o *observableEncoder) Reset() { - o.entries = make([]*observedEntry, 0) -} - -// parseEntry parses all known fields into the observedEntry struct and places -// everything else in the Context field -func parseEntry(entry interface{}) *observedEntry { - // Make a copy, don't alter the argument as a side effect. - m := entry.(log.Line) - verbosity, err := strconv.Atoi(m.Verbosity) - if err != nil { - log.DefaultLogger().Error(err, "failed to parse string as verbosity") - } - - var resultErr error = nil - if errVal, ok := m.Context[log.ErrorKey]; ok { - if resultErr, ok = errVal.(error); !ok { - fmt.Fprintf(os.Stderr, "failed to parse error from message: %v\n", kverrors.New("malformed/missing key", "key", log.ErrorKey)) - } - } - delete(m.Context, log.ErrorKey) - - result := &observedEntry{ - Timestamp: m.Timestamp, - FileLine: m.FileLine, - Verbosity: log.Verbosity(verbosity), - Component: m.Component, - Message: m.Message, - Context: m.Context, - Error: resultErr, - } - - return result -} - -// NewObservedLogger creates a new observableEncoder and a logger that uses the encoder. -func NewObservedLogger() (*observableEncoder, logr.Logger) { - now := time.Now().UTC().Format(time.RFC3339) - log.TimestampFunc = func() string { - return now - } - - te := &observableEncoder{} - s := log.NewLogSink("", ioutil.Discard, 0, te) - - return te, logr.New(s) -} diff --git a/log/options.go b/log/options.go index 66a28e6..5523aee 100644 --- a/log/options.go +++ b/log/options.go @@ -2,21 +2,23 @@ package log import ( "io" + + "github.com/ViaQ/logerr/v2/internal/sink" ) // Option is a configuration option -type Option func(*Sink) +type Option func(*sink.Sink) -// WithOutput sets the output to w +// WithOutput sets the output of the internal sink of the logger func WithOutput(w io.Writer) Option { - return func(s *Sink) { + return func(s *sink.Sink) { s.SetOutput(w) } } -// WithLogLevel sets the output log level and controls which verbosity logs are printed -func WithLogLevel(v int) Option { - return func(s *Sink) { +// WithVerbosity sets the verbosity of the internal sink of the logger +func WithVerbosity(v int) Option { + return func(s *sink.Sink) { s.SetVerbosity(v) } }