log: add log context (#766)

* add log context & valuer

log/README.md

@@ -5,11 +5,13 @@
 ### Structured logging
 
 ```
-logger := stdlog.NewLogger(stdlog.Writer(os.Stdout))
-log := log.NewHelper("module_name", logger)
+logger := log.NewLogger(os.Stdout)
+logger = With(logger, "key", "value")
+
+log := log.NewHelper("github.com/project/foo", logger)
 // Levels
-log.Info("some log")
-log.Infof("format %s", "some log")
-log.Infow("field_name", "some log")
+log.Info("hello")
+log.Infof("hello %s", "kratos")
+log.Infow("key", "value")
 ```
 

log/helper.go

@@ -34,8 +34,8 @@ func (h *Helper) Debugf(format string, a ...interface{}) {
 }
 
 // Debugw logs a message at debug level.
-func (h *Helper) Debugw(kvpair ...interface{}) {
-	h.debug.Print(kvpair...)
+func (h *Helper) Debugw(pairs ...interface{}) {
+	h.debug.Print(pairs...)
 }
 
 // Info logs a message at info level.
@@ -49,8 +49,8 @@ func (h *Helper) Infof(format string, a ...interface{}) {
 }
 
 // Infow logs a message at info level.
-func (h *Helper) Infow(kvpair ...interface{}) {
-	h.info.Print(kvpair...)
+func (h *Helper) Infow(pairs ...interface{}) {
+	h.info.Print(pairs...)
 }
 
 // Warn logs a message at warn level.
@@ -64,8 +64,8 @@ func (h *Helper) Warnf(format string, a ...interface{}) {
 }
 
 // Warnw logs a message at warnf level.
-func (h *Helper) Warnw(kvpair ...interface{}) {
-	h.warn.Print(kvpair...)
+func (h *Helper) Warnw(pairs ...interface{}) {
+	h.warn.Print(pairs...)
 }
 
 // Error logs a message at error level.
@@ -79,6 +79,6 @@ func (h *Helper) Errorf(format string, a ...interface{}) {
 }
 
 // Errorw logs a message at error level.
-func (h *Helper) Errorw(kvpair ...interface{}) {
-	h.err.Print(kvpair...)
+func (h *Helper) Errorw(pairs ...interface{}) {
+	h.err.Print(pairs...)
 }

log/helper_test.go

@@ -1,11 +1,14 @@
 package log
 
 import (
+	"io/ioutil"
 	"testing"
 )
 
 func TestHelper(t *testing.T) {
-	log := NewHelper("test", DefaultLogger)
+	logger := With(DefaultLogger, "caller", Caller(5))
+	log := NewHelper("test", logger)
+
 	log.Debug("test debug")
 	log.Debugf("test %s", "debug")
 	log.Debugw("log", "test debug")
@@ -18,3 +21,24 @@ func TestHelperLevel(t *testing.T) {
 	log.Warn("test warn")
 	log.Error("test error")
 }
+
+func BenchmarkHelperPrint(b *testing.B) {
+	log := NewHelper("test", NewStdLogger(ioutil.Discard))
+	for i := 0; i < b.N; i++ {
+		log.Debug("test")
+	}
+}
+
+func BenchmarkHelperPrintf(b *testing.B) {
+	log := NewHelper("test", NewStdLogger(ioutil.Discard))
+	for i := 0; i < b.N; i++ {
+		log.Debugf("%s", "test")
+	}
+}
+
+func BenchmarkHelperPrintw(b *testing.B) {
+	log := NewHelper("test", NewStdLogger(ioutil.Discard))
+	for i := 0; i < b.N; i++ {
+		log.Debugw("key", "value")
+	}
+}

log/level.go

@@ -3,6 +3,9 @@ package log
 // Level is a logger level.
 type Level int8
 
+// LevelKey is logger level key.
+const LevelKey = "level"
+
 const (
 	// LevelDebug is logger debug level.
 	LevelDebug Level = iota
@@ -14,11 +17,6 @@ const (
 	LevelError
 )
 
-const (
-	// LevelKey is logger level key.
-	LevelKey = "level"
-)
-
 // Enabled compare whether the logging level is enabled.
 func (l Level) Enabled(lv Level) bool {
 	return lv >= l

log/log.go

@@ -1,10 +1,12 @@
 package log
 
-import "os"
+import (
+	"log"
+)
 
 var (
 	// DefaultLogger is default logger.
-	DefaultLogger Logger = NewStdLogger(os.Stderr)
+	DefaultLogger Logger = NewStdLogger(log.Writer())
 )
 
 // Logger is a logger interface.
@@ -12,21 +14,37 @@ type Logger interface {
 	Print(pairs ...interface{})
 }
 
-type logger struct {
-	log   Logger
-	pairs []interface{}
+type context struct {
+	logs   []Logger
+	prefix []interface{}
 }
 
-func (l *logger) Print(pairs ...interface{}) {
-	l.log.Print(append(pairs, l.pairs...)...)
-}
-
-// With with logger kv pairs.
-func With(log Logger, pairs ...interface{}) Logger {
-	if len(pairs) == 0 {
-		return log
+func (c *context) Print(a ...interface{}) {
+	kvs := make([]interface{}, 0, len(c.prefix)+len(a))
+	kvs = append(kvs, c.prefix...)
+	kvs = append(kvs, a...)
+	for _, log := range c.logs {
+		log.Print(kvs...)
 	}
-	return &logger{log: log, pairs: pairs}
+}
+
+// With with logger fields.
+func With(l Logger, a ...interface{}) Logger {
+	if c, ok := l.(*context); ok {
+		kvs := make([]interface{}, 0, len(c.prefix)+len(a))
+		kvs = append(kvs, a...)
+		kvs = append(kvs, c.prefix...)
+		return &context{
+			logs:   c.logs,
+			prefix: kvs,
+		}
+	}
+	return &context{logs: []Logger{l}, prefix: a}
+}
+
+// Wrap wraps multi logger.
+func Wrap(logs ...Logger) Logger {
+	return &context{logs: logs}
 }
 
 // Debug returns a debug logger.

log/log_test.go

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"os"
 	"testing"
 )
 
@@ -11,3 +12,11 @@ func TestLogger(t *testing.T) {
 	Warn(logger).Print("log", "test warn")
 	Error(logger).Print("log", "test error")
 }
+
+func TestWrapper(t *testing.T) {
+	out := NewStdLogger(os.Stdout)
+	err := NewStdLogger(os.Stderr)
+
+	l := Wrap(out, err)
+	l.Print("message", "test")
+}

log/std.go

@@ -28,18 +28,18 @@ func NewStdLogger(w io.Writer) Logger {
 }
 
 // Print print the kv pairs log.
-func (s *stdLogger) Print(kvpair ...interface{}) {
-	if len(kvpair) == 0 {
+func (l *stdLogger) Print(pairs ...interface{}) {
+	if len(pairs) == 0 {
 		return
 	}
-	if len(kvpair)%2 != 0 {
-		kvpair = append(kvpair, "")
+	if len(pairs)%2 != 0 {
+		pairs = append(pairs, "")
 	}
-	buf := s.pool.Get().(*bytes.Buffer)
-	for i := 0; i < len(kvpair); i += 2 {
-		fmt.Fprintf(buf, "%s=%v ", kvpair[i], kvpair[i+1])
+	buf := l.pool.Get().(*bytes.Buffer)
+	for i := 0; i < len(pairs); i += 2 {
+		fmt.Fprintf(buf, "%s=%v ", pairs[i], Value(pairs[i+1]))
 	}
-	s.log.Println(buf.String())
+	l.log.Output(4, buf.String())
 	buf.Reset()
-	s.pool.Put(buf)
+	l.pool.Put(buf)
 }

log/std_test.go

@@ -2,7 +2,7 @@ package log
 
 import "testing"
 
-func TestFmtLogger(t *testing.T) {
+func TestStdLogger(t *testing.T) {
 	logger := DefaultLogger
 
 	Debug(logger).Print("log", "test debug")

log/value.go

@@ -0,0 +1,30 @@
+package log
+
+import (
+	"runtime"
+	"strconv"
+	"strings"
+)
+
+// Valuer is returns a log value.
+type Valuer func() interface{}
+
+// Value return the function value.
+func Value(v interface{}) interface{} {
+	if v, ok := v.(Valuer); ok {
+		return v()
+	}
+	return v
+}
+
+// Caller returns returns a Valuer that returns a pkg/file:line description of the caller.
+func Caller(depth int) Valuer {
+	return func() interface{} {
+		_, file, line, ok := runtime.Caller(depth)
+		if !ok {
+			return nil
+		}
+		idx := strings.LastIndexByte(file, '/')
+		return file[idx+1:] + ":" + strconv.Itoa(line)
+	}
+}

log/value_test.go

@@ -0,0 +1,8 @@
+package log
+
+import "testing"
+
+func TestValue(t *testing.T) {
+	logger := With(DefaultLogger, "caller", Caller(4))
+	logger.Print("message", "helloworld")
+}

log/wrapper.go

@@ -1,14 +0,0 @@
-package log
-
-type wrapper []Logger
-
-func (w wrapper) Print(pairs ...interface{}) {
-	for _, p := range w {
-		p.Print(pairs...)
-	}
-}
-
-// Wrap wraps multi logger.
-func Wrap(l ...Logger) Logger {
-	return wrapper(l)
-}

log/wrapper_test.go

@@ -1,14 +0,0 @@
-package log
-
-import (
-	"os"
-	"testing"
-)
-
-func TestWrapper(t *testing.T) {
-	out := NewStdLogger(os.Stdout)
-	err := NewStdLogger(os.Stderr)
-
-	l := Wrap(out, err)
-	l.Print("message", "test")
-}