log: rename Print to Log (#886)

* rename Print to Log

log/README.md

@@ -4,14 +4,42 @@
 
 ### Structured logging
 
-```
-logger := log.NewLogger(os.Stdout)
-logger = With(logger, "key", "value")
+```go
+logger := log.NewStdLogger(os.Stdout)
+logger = log.With(logger, "caller", log.DefaultCaller, "ts", log.DefaultTimestamp)
 
-log := log.NewHelper("github.com/project/foo", logger)
 // Levels
-log.Info("hello")
-log.Infof("hello %s", "kratos")
-log.Infow("key", "value")
+log.Debug(logger).Log("msg", "foo bar")
+log.Info(logger).Log("msg", "foo bar")
+log.Warn(logger).Log("msg", "foo bar")
+log.Error(logger).Log("msg", "foo bar")
+
+errLogger := log.Error(logger)
+errLogger.Log("msg", "xxx")
+errLogger.Log("msg", "yyy")
+errLogger.Log("msg", "zzz")
+
+errLogger.Log(
+    "http.scheme", "https",
+    "http.host", "translate.googleapis.com",
+    "http.target", "/language/translate",
+    "http.method", "post",
+    "http.status_code", 500,
+    "http.flavor", "1.1.",
+    "http.user_agent", "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.149 Safari/537.36",
+)
+
+// Helper
+logger := log.NewHelper("github.com/project/foo", log.DefaultLogger)
+logger.Info("hello")
+logger.Infof("foo %s", "bar")
+logger.Infow("key", "value")
+
+// Verbose
+v := NewVerbose(log.DefaultLogger, 20)
+
+v.V(10).Log("foo", "bar1")
+v.V(20).Log("foo", "bar2")
+v.V(30).Log("foo", "bar3")
 ```
 

log/helper.go

@@ -14,71 +14,71 @@ type Helper struct {
 
 // NewHelper new a logger helper.
 func NewHelper(name string, logger Logger) *Helper {
-	log := With(logger, "module", name)
+	logger = With(logger, "module", name)
 	return &Helper{
-		debug: Debug(log),
-		info:  Info(log),
-		warn:  Warn(log),
-		err:   Error(log),
+		debug: Debug(logger),
+		info:  Info(logger),
+		warn:  Warn(logger),
+		err:   Error(logger),
 	}
 }
 
 // Debug logs a message at debug level.
 func (h *Helper) Debug(a ...interface{}) {
-	h.debug.Print("message", fmt.Sprint(a...))
+	h.debug.Log("msg", fmt.Sprint(a...))
 }
 
 // Debugf logs a message at debug level.
 func (h *Helper) Debugf(format string, a ...interface{}) {
-	h.debug.Print("message", fmt.Sprintf(format, a...))
+	h.debug.Log("msg", fmt.Sprintf(format, a...))
 }
 
 // Debugw logs a message at debug level.
-func (h *Helper) Debugw(pairs ...interface{}) {
-	h.debug.Print(pairs...)
+func (h *Helper) Debugw(kv ...interface{}) {
+	h.debug.Log(kv...)
 }
 
 // Info logs a message at info level.
 func (h *Helper) Info(a ...interface{}) {
-	h.info.Print("message", fmt.Sprint(a...))
+	h.info.Log("msg", fmt.Sprint(a...))
 }
 
 // Infof logs a message at info level.
 func (h *Helper) Infof(format string, a ...interface{}) {
-	h.info.Print("message", fmt.Sprintf(format, a...))
+	h.info.Log("msg", fmt.Sprintf(format, a...))
 }
 
 // Infow logs a message at info level.
-func (h *Helper) Infow(pairs ...interface{}) {
-	h.info.Print(pairs...)
+func (h *Helper) Infow(kv ...interface{}) {
+	h.info.Log(kv...)
 }
 
 // Warn logs a message at warn level.
 func (h *Helper) Warn(a ...interface{}) {
-	h.warn.Print("message", fmt.Sprint(a...))
+	h.warn.Log("msg", fmt.Sprint(a...))
 }
 
 // Warnf logs a message at warnf level.
 func (h *Helper) Warnf(format string, a ...interface{}) {
-	h.warn.Print("message", fmt.Sprintf(format, a...))
+	h.warn.Log("msg", fmt.Sprintf(format, a...))
 }
 
 // Warnw logs a message at warnf level.
-func (h *Helper) Warnw(pairs ...interface{}) {
-	h.warn.Print(pairs...)
+func (h *Helper) Warnw(kv ...interface{}) {
+	h.warn.Log(kv...)
 }
 
 // Error logs a message at error level.
 func (h *Helper) Error(a ...interface{}) {
-	h.err.Print("message", fmt.Sprint(a...))
+	h.err.Log("msg", fmt.Sprint(a...))
 }
 
 // Errorf logs a message at error level.
 func (h *Helper) Errorf(format string, a ...interface{}) {
-	h.err.Print("message", fmt.Sprintf(format, a...))
+	h.err.Log("msg", fmt.Sprintf(format, a...))
 }
 
 // Errorw logs a message at error level.
-func (h *Helper) Errorw(pairs ...interface{}) {
-	h.err.Print(pairs...)
+func (h *Helper) Errorw(kv ...interface{}) {
+	h.err.Log(kv...)
 }

log/helper_test.go

@@ -6,7 +6,7 @@ import (
 )
 
 func TestHelper(t *testing.T) {
-	logger := With(DefaultLogger, "caller", Caller(5))
+	logger := With(DefaultLogger, "caller", DefaultCaller, "ts", DefaultTimestamp)
 	log := NewHelper("test", logger)
 
 	log.Debug("test debug")

log/level.go

@@ -1,5 +1,7 @@
 package log
 
+import "strings"
+
 // Level is a logger level.
 type Level int8
 
@@ -31,3 +33,18 @@ func (l Level) String() string {
 		return ""
 	}
 }
+
+// ParseLevel parses a level string into a logger Level value.
+func ParseLevel(s string) Level {
+	switch strings.ToUpper(s) {
+	case "DEBUG":
+		return LevelDebug
+	case "INFO":
+		return LevelInfo
+	case "WARN":
+		return LevelWarn
+	case "ERROR":
+		return LevelError
+	}
+	return LevelInfo
+}

log/log.go

@@ -11,39 +11,47 @@ var (
 
 // Logger is a logger interface.
 type Logger interface {
-	Print(pairs ...interface{})
+	Log(kv ...interface{}) error
 }
 
 type context struct {
-	logs   []Logger
-	prefix []interface{}
+	logs      []Logger
+	prefix    []interface{}
+	hasValuer bool
 }
 
-func (c *context) Print(a ...interface{}) {
-	kvs := make([]interface{}, 0, len(c.prefix)+len(a))
+func (c *context) Log(kv ...interface{}) error {
+	kvs := make([]interface{}, 0, len(c.prefix)+len(kv))
 	kvs = append(kvs, c.prefix...)
-	kvs = append(kvs, a...)
-	for _, log := range c.logs {
-		log.Print(kvs...)
+	if c.hasValuer {
+		bindValues(kvs)
 	}
+	kvs = append(kvs, kv...)
+	for _, l := range c.logs {
+		if err := l.Log(kvs...); err != nil {
+			return err
+		}
+	}
+	return nil
 }
 
 // With with logger fields.
-func With(l Logger, a ...interface{}) Logger {
+func With(l Logger, kv ...interface{}) Logger {
 	if c, ok := l.(*context); ok {
-		kvs := make([]interface{}, 0, len(c.prefix)+len(a))
-		kvs = append(kvs, a...)
+		kvs := make([]interface{}, 0, len(c.prefix)+len(kv))
+		kvs = append(kvs, kv...)
 		kvs = append(kvs, c.prefix...)
 		return &context{
-			logs:   c.logs,
-			prefix: kvs,
+			logs:      c.logs,
+			prefix:    kvs,
+			hasValuer: containsValuer(kvs),
 		}
 	}
-	return &context{logs: []Logger{l}, prefix: a}
+	return &context{logs: []Logger{l}, prefix: kv, hasValuer: containsValuer(kv)}
 }
 
-// Wrap wraps multi logger.
-func Wrap(logs ...Logger) Logger {
+// MultiLogger wraps multi logger.
+func MultiLogger(logs ...Logger) Logger {
 	return &context{logs: logs}
 }
 

log/log_test.go

@@ -7,16 +7,25 @@ import (
 
 func TestLogger(t *testing.T) {
 	logger := DefaultLogger
-	Debug(logger).Print("log", "test debug")
-	Info(logger).Print("log", "test info")
-	Warn(logger).Print("log", "test warn")
-	Error(logger).Print("log", "test error")
+	Debug(logger).Log("msg", "test debug")
+	Info(logger).Log("msg", "test info")
+	Warn(logger).Log("msg", "test warn")
+	Error(logger).Log("msg", "test error")
+}
+
+func TestInfo(t *testing.T) {
+	logger := DefaultLogger
+	logger = With(logger, "caller", DefaultCaller, "ts", DefaultTimestamp)
+	infoLogger := Info(logger)
+	infoLogger.Log("key1", "value1")
+	infoLogger.Log("key2", "value2")
+	infoLogger.Log("key3", "value3")
 }
 
 func TestWrapper(t *testing.T) {
 	out := NewStdLogger(os.Stdout)
 	err := NewStdLogger(os.Stderr)
 
-	l := Wrap(out, err)
-	l.Print("message", "test")
+	l := With(MultiLogger(out, err), "caller", DefaultCaller, "ts", DefaultTimestamp)
+	l.Log("msg", "test")
 }

log/std.go

@@ -18,7 +18,7 @@ type stdLogger struct {
 // NewStdLogger new a std logger with options.
 func NewStdLogger(w io.Writer) Logger {
 	return &stdLogger{
-		log: log.New(w, "", log.LstdFlags),
+		log: log.New(w, "", 0),
 		pool: &sync.Pool{
 			New: func() interface{} {
 				return new(bytes.Buffer)
@@ -27,19 +27,20 @@ func NewStdLogger(w io.Writer) Logger {
 	}
 }
 
-// Print print the kv pairs log.
-func (l *stdLogger) Print(pairs ...interface{}) {
-	if len(pairs) == 0 {
-		return
+// Log print the kv pairs log.
+func (l *stdLogger) Log(kv ...interface{}) error {
+	if len(kv) == 0 {
+		return nil
 	}
-	if len(pairs)%2 != 0 {
-		pairs = append(pairs, "")
+	if len(kv)%2 != 0 {
+		kv = append(kv, "")
 	}
 	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]))
+	for i := 0; i < len(kv); i += 2 {
+		fmt.Fprintf(buf, "%s=%v ", kv[i], kv[i+1])
 	}
 	l.log.Output(4, buf.String())
 	buf.Reset()
 	l.pool.Put(buf)
+	return nil
 }

log/std_test.go

@@ -4,9 +4,10 @@ import "testing"
 
 func TestStdLogger(t *testing.T) {
 	logger := DefaultLogger
+	logger = With(logger, "caller", DefaultCaller, "ts", DefaultTimestamp)
 
-	Debug(logger).Print("log", "test debug")
-	Info(logger).Print("log", "test info")
-	Warn(logger).Print("log", "test warn")
-	Error(logger).Print("log", "test error")
+	Debug(logger).Log("msg", "test debug")
+	Info(logger).Log("msg", "test info")
+	Warn(logger).Log("msg", "test warn")
+	Error(logger).Log("msg", "test error")
 }

log/value.go

@@ -4,6 +4,15 @@ import (
 	"runtime"
 	"strconv"
 	"strings"
+	"time"
+)
+
+var (
+	// DefaultCaller is a Valuer that returns the file and line.
+	DefaultCaller = Caller(3)
+
+	// DefaultTimestamp is a Valuer that returns the current wallclock time.
+	DefaultTimestamp = Timestamp(time.RFC3339)
 )
 
 // Valuer is returns a log value.
@@ -20,11 +29,35 @@ func Value(v interface{}) interface{} {
 // 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
+		_, file, line, _ := runtime.Caller(depth)
+		if strings.LastIndex(file, "github.com/go-kratos/kratos/log") > 0 {
+			_, file, line, _ = runtime.Caller(depth + 1)
 		}
 		idx := strings.LastIndexByte(file, '/')
 		return file[idx+1:] + ":" + strconv.Itoa(line)
 	}
 }
+
+// Timestamp returns a timestamp Valuer with a custom time format.
+func Timestamp(layout string) Valuer {
+	return func() interface{} {
+		return time.Now().Format(layout)
+	}
+}
+
+func bindValues(keyvals []interface{}) {
+	for i := 1; i < len(keyvals); i += 2 {
+		if v, ok := keyvals[i].(Valuer); ok {
+			keyvals[i] = v()
+		}
+	}
+}
+
+func containsValuer(keyvals []interface{}) bool {
+	for i := 1; i < len(keyvals); i += 2 {
+		if _, ok := keyvals[i].(Valuer); ok {
+			return true
+		}
+	}
+	return false
+}

log/value_test.go

@@ -3,6 +3,12 @@ package log
 import "testing"
 
 func TestValue(t *testing.T) {
-	logger := With(DefaultLogger, "caller", Caller(4))
-	logger.Print("message", "helloworld")
+	logger := DefaultLogger
+	logger = With(logger, "caller", DefaultCaller, "ts", DefaultTimestamp)
+	logger.Log("msg", "helloworld")
+
+	Debug(logger).Log("msg", "debug value")
+	Info(logger).Log("msg", "info value")
+	Warn(logger).Log("msg", "warn value")
+	Error(logger).Log("msg", "error value")
 }

log/verbose.go

@@ -22,9 +22,10 @@ func (v Verbose) V(level Level) Verbose {
 	return Verbose{log: v.log, enabled: v.Enabled(level)}
 }
 
-// Print is equivalent to the Print function, guarded by the value of v.
-func (v Verbose) Print(a ...interface{}) {
+// Log is equivalent to the Print function, guarded by the value of v.
+func (v Verbose) Log(a ...interface{}) error {
 	if v.enabled {
-		v.log.Print(a...)
+		return v.log.Log(a...)
 	}
+	return nil
 }

log/verbose_test.go

@@ -3,9 +3,10 @@ package log
 import "testing"
 
 func TestVerbose(t *testing.T) {
-	v := NewVerbose(DefaultLogger, 20)
+	logger := With(DefaultLogger, "caller", DefaultCaller, "ts", DefaultTimestamp)
+	v := NewVerbose(logger, 20)
 
-	v.V(10).Print("foo", "bar1")
-	v.V(20).Print("foo", "bar2")
-	v.V(30).Print("foo", "bar3")
+	v.V(10).Log("foo", "bar1")
+	v.V(20).Log("foo", "bar2")
+	v.V(30).Log("foo", "bar3")
 }