Skip to content

Commit

Permalink
Updating library to v2; Reorganizing files; Cleaning up test cases
Browse files Browse the repository at this point in the history
  • Loading branch information
Red-GV committed Apr 14, 2022
1 parent c53ff49 commit e6aeabc
Show file tree
Hide file tree
Showing 20 changed files with 580 additions and 1,144 deletions.
2 changes: 1 addition & 1 deletion .github/workflows/ci.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
41 changes: 15 additions & 26 deletions MIGRATION.md
Original file line number Diff line number Diff line change
@@ -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.
263 changes: 66 additions & 197 deletions README.md
Original file line number Diff line number Diff line change
@@ -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": "<timestamp>",
// "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": "<timestamp>",
// "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).
4 changes: 1 addition & 3 deletions go.mod
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
module github.com/ViaQ/logerr
module github.com/ViaQ/logerr/v2

go 1.17

Expand All @@ -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
20 changes: 12 additions & 8 deletions internal/kv/kv.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand Down
2 changes: 1 addition & 1 deletion log/encoding.go → internal/sink/encoding.go
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
package log
package sink

import (
"encoding/json"
Expand Down

0 comments on commit e6aeabc

Please sign in to comment.