Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New API for package log (post-GopherCon) #76

Merged
merged 11 commits into from
Jul 15, 2015
2 changes: 1 addition & 1 deletion addsvc/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ func main() {
// `package log` domain
var logger kitlog.Logger
logger = kitlog.NewLogfmtLogger(os.Stderr)
logger = kitlog.With(logger, "ts", kitlog.DefaultTimestampUTC)
logger = kitlog.NewContext(logger).With("ts", kitlog.DefaultTimestampUTC)
stdlog.SetOutput(kitlog.NewStdlibAdapter(logger)) // redirect stdlib logging to us
stdlog.SetFlags(0) // flags are handled in our logger

Expand Down
6 changes: 3 additions & 3 deletions log/benchmark_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -7,15 +7,15 @@ import (
)

func benchmarkRunner(b *testing.B, logger log.Logger, f func(log.Logger)) {
logger = log.With(logger, "common_key", "common_value")
lc := log.NewContext(logger).With("common_key", "common_value")
b.ReportAllocs()
b.ResetTimer()
for i := 0; i < b.N; i++ {
f(logger)
f(lc)
}
}

var (
baseMessage = func(logger log.Logger) { logger.Log("foo_key", "foo_value") }
withMessage = func(logger log.Logger) { log.With(logger, "a", "b").Log("c", "d") }
withMessage = func(logger log.Logger) { log.NewContext(logger).With("a", "b").Log("c", "d") }
)
23 changes: 23 additions & 0 deletions log/example_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
package log_test

import (
"os"

"github.com/go-kit/kit/log"
)

func ExampleContext() {
logger := log.NewLogfmtLogger(os.Stdout)
logger.Log("foo", 123)
ctx := log.NewContext(logger).With("level", "info")
ctx.Log()
ctx = ctx.With("msg", "hello")
ctx.Log()
ctx.With("a", 1).Log("b", 2)

// Output:
// foo=123
// level=info
// level=info msg=hello
// level=info msg=hello a=1 b=2
}
60 changes: 0 additions & 60 deletions log/levels.go

This file was deleted.

113 changes: 113 additions & 0 deletions log/levels/levels.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,113 @@
package levels

import "github.com/go-kit/kit/log"

// Levels provides a leveled logging wrapper around a logger. It has five
// levels: debug, info, warning (warn), error, and critical (crit). If you
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The way log levels are usually (in my practice) used:

  • there is a way to suppress levels up to a minimum severity
  • there is a way to configure a log sink for each log level (so that critical ones a teed to some alerting mechanism for example)

How does it work with levels.Levels?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This Levels type is very basic and doesn't support any of those use cases directly. To get them, you'd need to implement a new Levels type, which I think would be straightforward. If you think your usage generalizes to a lot of other organizations, I'd be happy to review a PR to add it as an additional type in package levels!

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was expecting we would add support for something along those lines in the future. Before we cram it all into levels.Levels though, consider if it can be achieved with a level aware log.Logger.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not sure how to do it with the current implementation of log levels.
I would need to extract current log level from the context so I can switch on it etc.
Also, what is the semantics for setting log level multiple times?
(in case of JSON sink the last one wins, if it is a regular loggger they are all printed).

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I understand you correctly, you wouldn't introspect the keyvals for a level key. Rather, you'd construct each leveled logger so that it's connected to the appropriate sink, and enabled/disabled according to the configured minimum severity.

If you supply multiple level keys, they will stack. Keyvals deliberately preserve order and don't dedupe.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sasha-s Since this PR has already been merged I recommend that you write up the features you want as separate issues and we'll iterate on them.

// want a different set of levels, you can create your own levels type very
// easily, and you can elide the configuration.
type Levels struct {
ctx log.Context
cfg *config
}

// New creates a new leveled logger, wrapping the passed logger.
func New(logger log.Logger, options ...Option) Levels {
cfg := &config{
levelKey: "level",
debugValue: "debug",
infoValue: "info",
warnValue: "warn",
errorValue: "error",
critValue: "crit",
}
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we already have a Levels struct, can we put these config params directly in it, and have the Option type take a Levels struct (pointer)? One less type to worry about.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I have combined them.

for _, option := range options {
option(cfg)
}
return Levels{
ctx: log.NewContext(logger),
cfg: cfg,
}
}

// With returns a new leveled logger that includes keyvals in all log events.
func (l Levels) With(keyvals ...interface{}) Levels {
return Levels{
ctx: l.ctx.With(keyvals...),
cfg: l.cfg,
}
}

// Debug logs a debug event along with keyvals.
func (l Levels) Debug(keyvals ...interface{}) error {
return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.debugValue).Log(keyvals...)
}

// Info logs an info event along with keyvals.
func (l Levels) Info(keyvals ...interface{}) error {
return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.infoValue).Log(keyvals...)
}

// Warn logs a warn event along with keyvals.
func (l Levels) Warn(keyvals ...interface{}) error {
return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.warnValue).Log(keyvals...)
}

// Error logs an error event along with keyvals.
func (l Levels) Error(keyvals ...interface{}) error {
return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.errorValue).Log(keyvals...)
}

// Crit logs a crit event along with keyvals.
func (l Levels) Crit(keyvals ...interface{}) error {
return l.ctx.WithPrefix(l.cfg.levelKey, l.cfg.critValue).Log(keyvals...)
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perhaps, DRYer?

type Levels struct {
    Debug, Info, Warn, Error, Crit Logger
    ctx log.Context
    cfg *config
}

func New(logger log.Logger, options ...Option) Levels {
    // ...
    ctx := log.NewContext(logger)
    return Levels{
        Debug: ctx.WithPrefix(cfg.key, cfg.values["debug"]),
        Info:  ctx.WithPrefix(cfg.key, cfg.values["info"]),
        Warn:  ctx.WithPrefix(cfg.key, cfg.values["warn"]),
        Error: ctx.WithPrefix(cfg.key, cfg.values["error"]),
        Crit:  ctx.WithPrefix(cfg.key, cfg.values["crit"]),
        ctx:   ctx,
        cfg:   cfg,   
    }
}

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems to be heading back toward what we have in the master branch with a separate logger/context for each level. The downside to this approach is that each call to Levels.With must update all the leveled contexts. It seems difficult to justify the overhead of calling With on this many contexts because to break even the application must create more than five subsequent log events in the scope of the context.


type config struct {
levelKey string

debugValue string
infoValue string
warnValue string
errorValue string
critValue string
}

// Option sets a parameter for leveled loggers.
type Option func(*config)

// Key sets the key for the field used to indicate log level. By default,
// the key is "level".
func Key(key string) Option {
return func(c *config) { c.levelKey = key }
}

// DebugValue sets the value for the field used to indicate the debug log
// level. By default, the value is "debug".
func DebugValue(value string) Option {
return func(c *config) { c.debugValue = value }
}

// InfoValue sets the value for the field used to indicate the info log level.
// By default, the value is "info".
func InfoValue(value string) Option {
return func(c *config) { c.infoValue = value }
}

// WarnValue sets the value for the field used to indicate the warning log
// level. By default, the value is "warn".
func WarnValue(value string) Option {
return func(c *config) { c.warnValue = value }
}

// ErrorValue sets the value for the field used to indicate the error log
// level. By default, the value is "error".
func ErrorValue(value string) Option {
return func(c *config) { c.errorValue = value }
}

// CritValue sets the value for the field used to indicate the critical log
// level. By default, the value is "crit".
func CritValue(value string) Option {
return func(c *config) { c.critValue = value }
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My DRY spidey sense is triggering here. I appreciate the performance implications of the following suggestion, and I'd love to see a benchmark to see if we could take the hit.

type config struct {
    key string
    values map[string]string
}

var (
    DebugValue = Level("debug")
    InfoValue  = Level("info")
    WarnValue  = Level("warn")
    ErrorValue = Level("error")
    CritValue  = Level("crit")
)

func Level(level string) func(string) Option {
    return func(value string) Option {
        return func(c *config) { c.values[level] = value }
    }
}

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Clever, but I feel too clever. For better or worse, godoc currently displays functions in the package index but not variables of function type. So the function version makes the available options much easier to discover for the casual user.

55 changes: 55 additions & 0 deletions log/levels/levels_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,55 @@
package levels_test

import (
"bytes"
"os"
"testing"

"github.com/go-kit/kit/log"
"github.com/go-kit/kit/log/levels"
)

func TestDefaultLevels(t *testing.T) {
buf := bytes.Buffer{}
logger := levels.New(log.NewLogfmtLogger(&buf))

logger.Debug("msg", "résumé") // of course you'd want to do this
if want, have := "level=debug msg=résumé\n", buf.String(); want != have {
t.Errorf("want %#v, have %#v", want, have)
}

buf.Reset()
logger.Info("msg", "Åhus")
if want, have := "level=info msg=Åhus\n", buf.String(); want != have {
t.Errorf("want %#v, have %#v", want, have)
}

buf.Reset()
logger.Error("msg", "© violation")
if want, have := "level=error msg=\"© violation\"\n", buf.String(); want != have {
t.Errorf("want %#v, have %#v", want, have)
}
}

func TestModifiedLevels(t *testing.T) {
buf := bytes.Buffer{}
logger := levels.New(
log.NewJSONLogger(&buf),
levels.Key("l"),
levels.DebugValue("dbg"),
)
logger.With("easter_island", "176°").Debug("msg", "moai")
if want, have := `{"easter_island":"176°","l":"dbg","msg":"moai"}`+"\n", buf.String(); want != have {
t.Errorf("want %#v, have %#v", want, have)
}
}

func ExampleLevels() {
logger := levels.New(log.NewLogfmtLogger(os.Stdout))
logger.Debug("msg", "hello")
logger.With("context", "foo").Warn("err", "error")

// Output:
// level=debug msg=hello
// level=warn context=foo err=error
}
45 changes: 0 additions & 45 deletions log/levels_test.go

This file was deleted.

Loading