Merge pull request #147 from bilibili/update/log

update pkg/log from internal library

go.mod

@@ -25,7 +25,7 @@ require (
 	github.com/remyoudompheng/bigfft v0.0.0-20190321074620-2f0d2b0e0001 // indirect
 	github.com/samuel/go-zookeeper v0.0.0-20180130194729-c4fab1ac1bec // indirect
 	github.com/siddontang/go v0.0.0-20180604090527-bdc77568d726
-	github.com/sirupsen/logrus v1.4.1 // indirect
+	github.com/sirupsen/logrus v1.4.1
 	github.com/stretchr/testify v1.3.0
 	github.com/tsuna/gohbase v0.0.0-20190201102810-d3184c1526df
 	github.com/urfave/cli v1.20.0

pkg/log/doc.go

@@ -2,21 +2,23 @@
 
 一、主要功能：
 
-	1. 日志打印到本地
+	1. 日志打印到elk
-	2. 日志打印到标准输出
+	2. 日志打印到本地，内部使用log4go
-	3. verbose日志实现，参考glog实现，可通过设置不同verbose级别，默认不开启
+	3. 日志打印到标准输出
+	4. verbose日志实现，参考glog实现，可通过设置不同verbose级别，默认不开启
 
 二、日志配置
 
-1. 默认配置
+1. 默认agent配置
 
-	目前日志已经实现默认配置。可以直接使用以下方式：
+	目前日志已经实现默认配置，可以根据env自动切换远程日志。可以直接使用以下方式：
 	log.Init(nil)
 
 2. 启动参数 or 环境变量
 
 	启动参数		环境变量		说明
 	log.stdout	LOG_STDOUT	是否开启标准输出
+	log.agent	LOG_AGENT	远端日志地址：unixpacket:///var/run/lancer/collector_tcp.sock?timeout=100ms&chan=1024
 	log.dir		LOG_DIR		文件日志路径
 	log.v		LOG_V		verbose日志级别
 	log.module	LOG_MODULE	可单独配置每个文件的verbose级别：file=1,file2=2
@@ -33,6 +35,11 @@
 	[log.module]
 		"dao_user" = 2
 		"servic*" = 1
+	[log.agent]
+		taskID = "00000x"
+		proto = "unixpacket"
+		addr = "/var/run/lancer/collector_tcp.sock"
+		chanSize = 10240
 
 三、配置说明
 
@@ -47,5 +54,16 @@
 2. log.module
 
 	可单独配置每个文件的verbose级别
+
+3. log.agent
+远端日志配置项
+	taskID		lancer分配的taskID
+	proto		网络协议，常见：tcp, udp, unixgram
+	addr		网络地址，常见：ip:prot, sock
+	chanSize	日志队列长度
+
+四、最佳实践
+
+1. KVString 使用 KVString 代替 KV 可以减少对象分配, 避免给 golang GC 造成压力.
 */
 package log

pkg/log/dsn.go

@@ -0,0 +1,50 @@
+package log
+
+import (
+	"bytes"
+	"fmt"
+	"strconv"
+	"strings"
+)
+
+type verboseModule map[string]int32
+
+type logFilter []string
+
+func (f *logFilter) String() string {
+	return fmt.Sprint(*f)
+}
+
+// Set sets the value of the named command-line flag.
+// format: -log.filter key1,key2
+func (f *logFilter) Set(value string) error {
+	for _, i := range strings.Split(value, ",") {
+		*f = append(*f, strings.TrimSpace(i))
+	}
+	return nil
+}
+
+func (m verboseModule) String() string {
+	// FIXME strings.Builder
+	var buf bytes.Buffer
+	for k, v := range m {
+		buf.WriteString(k)
+		buf.WriteString(strconv.FormatInt(int64(v), 10))
+		buf.WriteString(",")
+	}
+	return buf.String()
+}
+
+// Set sets the value of the named command-line flag.
+// format: -log.module file=1,file2=2
+func (m verboseModule) Set(value string) error {
+	for _, i := range strings.Split(value, ",") {
+		kv := strings.Split(i, "=")
+		if len(kv) == 2 {
+			if v, err := strconv.ParseInt(kv[1], 10, 64); err == nil {
+				m[strings.TrimSpace(kv[0])] = int32(v)
+			}
+		}
+	}
+	return nil
+}

pkg/log/field.go

@@ -18,7 +18,7 @@ func KVString(key string, value string) D {
 
 // KVInt construct Field with int value.
 func KVInt(key string, value int) D {
-	return D{Key: key, Type: core.IntType, Int64Val: int64(value)}
+	return D{Key: key, Type: core.IntTpye, Int64Val: int64(value)}
 }
 
 // KVInt64 construct D with int64 value.

pkg/log/handler.go

@@ -16,6 +16,8 @@ const (
 	_level = "level"
 	// log time.
 	_time = "time"
+	// request path.
+	// _title = "title"
 	// log file.
 	_source = "source"
 	// common log filed.
@@ -27,7 +29,7 @@ const (
 	// uniq ID from trace.
 	_tid = "traceid"
 	// request time.
-	_ts = "ts"
+	// _ts = "ts"
 	// requester.
 	_caller = "caller"
 	// container environment: prod, pre, uat, fat.
@@ -38,6 +40,8 @@ const (
 	_mirror = "mirror"
 	// color.
 	_color = "color"
+	// env_color
+	_envColor = "env_color"
 	// cluster.
 	_cluster = "cluster"
 )
@@ -75,8 +79,8 @@ type Handlers struct {
 }
 
 // Log handlers logging.
-func (hs Handlers) Log(c context.Context, lv Level, d ...D) {
+func (hs Handlers) Log(ctx context.Context, lv Level, d ...D) {
-	var hasSource bool
+	hasSource := false
 	for i := range d {
 		if _, ok := hs.filters[d[i].Key]; ok {
 			d[i].Value = "***"
@@ -87,11 +91,12 @@ func (hs Handlers) Log(c context.Context, lv Level, d ...D) {
 	}
 	if !hasSource {
 		fn := funcName(3)
+		errIncr(lv, fn)
 		d = append(d, KVString(_source, fn))
 	}
 	d = append(d, KV(_time, time.Now()), KVInt64(_levelValue, int64(lv)), KVString(_level, lv.String()))
 	for _, h := range hs.handlers {
-		h.Log(c, lv, d...)
+		h.Log(ctx, lv, d...)
 	}
 }
 

pkg/log/internal/core/buffer_test.go

@@ -1,3 +1,23 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
 package core
 
 import (

pkg/log/internal/core/bufferpool.go

@@ -1,3 +1,25 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+// Package core houses zap's shared internal buffer pool. Third-party
+// packages can recreate the same functionality with buffers.NewPool.
 package core
 
 var (

pkg/log/internal/core/field.go

@@ -15,7 +15,7 @@ type FieldType int32
 const (
 	UnknownType FieldType = iota
 	StringType
-	IntType
+	IntTpye
 	Int64Type
 	UintType
 	Uint64Type
@@ -43,7 +43,7 @@ func (f Field) AddTo(enc ObjectEncoder) {
 	switch f.Type {
 	case StringType:
 		enc.AddString(f.Key, f.StringVal)
-	case IntType:
+	case IntTpye:
 		enc.AddInt(f.Key, int(f.Int64Val))
 	case Int64Type:
 		enc.AddInt64(f.Key, f.Int64Val)

pkg/log/internal/core/pool.go

@@ -1,3 +1,23 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
 package core
 
 import "sync"

pkg/log/internal/core/pool_test.go

@@ -1,3 +1,23 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
 package core
 
 import (

pkg/log/log.go

@@ -4,16 +4,17 @@ import (
 	"context"
 	"flag"
 	"fmt"
+	"io"
 	"os"
 	"strconv"
-	"strings"
 
 	"github.com/bilibili/kratos/pkg/conf/env"
+	"github.com/bilibili/kratos/pkg/stat/prom"
 )
 
 // Config log config.
 type Config struct {
-	AppID string
+	Family string
 	Host   string
 
 	// stdout
@@ -43,23 +44,39 @@ type Config struct {
 	Filter []string
 }
 
+// errProm prometheus error counter.
+var errProm = prom.BusinessErrCount
+
+// Render render log output
+type Render interface {
+	Render(io.Writer, map[string]interface{}) error
+	RenderString(map[string]interface{}) string
+}
+
 var (
 	h Handler
 	c *Config
 )
 
 func init() {
+	host, _ := os.Hostname()
+	c = &Config{
+		Family: env.AppID,
+		Host:   host,
+	}
+	h = newHandlers([]string{}, NewStdout())
+
 	addFlag(flag.CommandLine)
-	h = newHandlers(nil)
-	c = new(Config)
 }
 
 var (
 	_v        int
 	_stdout   bool
 	_dir      string
+	_agentDSN string
 	_filter   logFilter
 	_module   = verboseModule{}
+	_noagent  bool
 )
 
 // addFlag init log from dsn.
@@ -75,12 +92,15 @@ func addFlag(fs *flag.FlagSet) {
 	if tf := os.Getenv("LOG_FILTER"); len(tf) > 0 {
 		_filter.Set(tf)
 	}
+	_noagent, _ = strconv.ParseBool(os.Getenv("LOG_NO_AGENT"))
 	// get val from flag
 	fs.IntVar(&_v, "log.v", _v, "log verbose level, or use LOG_V env variable.")
 	fs.BoolVar(&_stdout, "log.stdout", _stdout, "log enable stdout or not, or use LOG_STDOUT env variable.")
 	fs.StringVar(&_dir, "log.dir", _dir, "log file `path, or use LOG_DIR env variable.")
+	fs.StringVar(&_agentDSN, "log.agent", _agentDSN, "log agent dsn, or use LOG_AGENT env variable.")
 	fs.Var(&_module, "log.module", "log verbose for specified module, or use LOG_MODULE env variable, format: file=1,file2=2.")
 	fs.Var(&_filter, "log.filter", "log field for sensitive message, or use LOG_FILTER env variable, format: field1,field2.")
+	fs.BoolVar(&_noagent, "log.noagent", _noagent, "force disable log agent print log to stderr,  or use LOG_NO_AGENT")
 }
 
 // Init create logger with context.
@@ -96,8 +116,8 @@ func Init(conf *Config) {
 			Filter: _filter,
 		}
 	}
-	if conf.AppID == "" && len(env.AppID) != 0 {
+	if len(env.AppID) != 0 {
-		conf.AppID = env.AppID
+		conf.Family = env.AppID // for caster
 	}
 	conf.Host = env.Hostname
 	if len(conf.Host) == 0 {
@@ -106,7 +126,7 @@ func Init(conf *Config) {
 	}
 	var hs []Handler
 	// when env is dev
-	if isNil || conf.Stdout {
+	if conf.Stdout || (isNil && (env.DeployEnv == "" || env.DeployEnv == env.DeployEnvDev)) || _noagent {
 		hs = append(hs, NewStdout())
 	}
 	if conf.Dir != "" {
@@ -116,21 +136,6 @@ func Init(conf *Config) {
 	c = conf
 }
 
-type logFilter []string
-
-func (f *logFilter) String() string {
-	return fmt.Sprint(*f)
-}
-
-// Set sets the value of the named command-line flag.
-// format: -log.filter key1,key2
-func (f *logFilter) Set(value string) error {
-	for _, i := range strings.Split(value, ",") {
-		*f = append(*f, strings.TrimSpace(i))
-	}
-	return nil
-}
-
 // Info logs a message at the info log level.
 func Info(format string, args ...interface{}) {
 	h.Log(context.Background(), _infoLevel, KVString(_log, fmt.Sprintf(format, args...)))
@@ -176,6 +181,36 @@ func Errorv(ctx context.Context, args ...D) {
 	h.Log(ctx, _errorLevel, args...)
 }
 
+func logw(args []interface{}) []D {
+	if len(args)%2 != 0 {
+		Warn("log: the variadic must be plural, the last one will ignored")
+	}
+	ds := make([]D, 0, len(args)/2)
+	for i := 0; i < len(args)-1; i = i + 2 {
+		if key, ok := args[i].(string); ok {
+			ds = append(ds, KV(key, args[i+1]))
+		} else {
+			Warn("log: key must be string, get %T, ignored", args[i])
+		}
+	}
+	return ds
+}
+
+// Infow logs a message with some additional context. The variadic key-value pairs are treated as they are in With.
+func Infow(ctx context.Context, args ...interface{}) {
+	h.Log(ctx, _infoLevel, logw(args)...)
+}
+
+// Warnw logs a message with some additional context. The variadic key-value pairs are treated as they are in With.
+func Warnw(ctx context.Context, args ...interface{}) {
+	h.Log(ctx, _warnLevel, logw(args)...)
+}
+
+// Errorw logs a message with some additional context. The variadic key-value pairs are treated as they are in With.
+func Errorw(ctx context.Context, args ...interface{}) {
+	h.Log(ctx, _errorLevel, logw(args)...)
+}
+
 // SetFormat only effective on stdout and file handler
 // %T time format at "15:04:05.999" on stdout handler, "15:04:05 MST" on file handler
 // %t time format at "15:04:05" on stdout handler, "15:04" on file on file handler
@@ -194,39 +229,15 @@ func SetFormat(format string) {
 	h.SetFormat(format)
 }
 
-// Infow logs a message with some additional context. The variadic key-value pairs are treated as they are in With.
-func Infow(ctx context.Context, args ...interface{}) {
-	h.Log(ctx, _infoLevel, logw(args)...)
-}
-
-// Warnw logs a message with some additional context. The variadic key-value pairs are treated as they are in With.
-func Warnw(ctx context.Context, args ...interface{}) {
-	h.Log(ctx, _warnLevel, logw(args)...)
-}
-
-// Errorw logs a message with some additional context. The variadic key-value pairs are treated as they are in With.
-func Errorw(ctx context.Context, args ...interface{}) {
-	h.Log(ctx, _errorLevel, logw(args)...)
-}
-
-func logw(args []interface{}) []D {
-	if len(args)%2 != 0 {
-		Warn("log: the variadic must be plural, the last one will ignored")
-	}
-	ds := make([]D, 0, len(args)/2)
-	for i := 0; i < len(args)-1; i = i + 2 {
-		if key, ok := args[i].(string); ok {
-			ds = append(ds, KV(key, args[i+1]))
-		} else {
-			Warn("log: key must be string, get %T, ignored", args[i])
-		}
-	}
-	return ds
-}
-
 // Close close resource.
 func Close() (err error) {
 	err = h.Close()
 	h = _defaultStdout
 	return
 }
+
+func errIncr(lv Level, source string) {
+	if lv == _errorLevel {
+		errProm.Incr(source)
+	}
+}

pkg/log/log_test.go

@@ -37,19 +37,16 @@ func testLog(t *testing.T) {
 		Error("hello %s", "world")
 		Errorv(context.Background(), KV("key", 2222222), KV("test2", "test"))
 		Errorc(context.Background(), "keys: %s %s...", "key1", "key2")
-		Errorw(context.Background(), "key1", "value1", "key2", "value2")
 	})
 	t.Run("Warn", func(t *testing.T) {
 		Warn("hello %s", "world")
 		Warnv(context.Background(), KV("key", 2222222), KV("test2", "test"))
 		Warnc(context.Background(), "keys: %s %s...", "key1", "key2")
-		Warnw(context.Background(), "key1", "value1", "key2", "value2")
 	})
 	t.Run("Info", func(t *testing.T) {
 		Info("hello %s", "world")
 		Infov(context.Background(), KV("key", 2222222), KV("test2", "test"))
 		Infoc(context.Background(), "keys: %s %s...", "key1", "key2")
-		Infow(context.Background(), "key1", "value1", "key2", "value2")
 	})
 }
 
@@ -87,3 +84,22 @@ func TestLogWithMirror(t *testing.T) {
 	Infov(context.Background(), KV("key1", "val1"), KV("key2", ""), KV("log", "log content"), KV("msg", "msg content"))
 
 }
+
+func TestOverwriteSouce(t *testing.T) {
+	ctx := context.Background()
+	t.Run("test source kv string", func(t *testing.T) {
+		Infov(ctx, KVString("source", "test"))
+	})
+	t.Run("test source kv string", func(t *testing.T) {
+		Infov(ctx, KV("source", "test"))
+	})
+}
+
+func BenchmarkLog(b *testing.B) {
+	ctx := context.Background()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			Infov(ctx, KVString("test", "hello"), KV("int", 34), KV("hhh", "hhhh"))
+		}
+	})
+}

pkg/log/logrus.go

@@ -0,0 +1,61 @@
+package log
+
+import (
+	"context"
+	"io/ioutil"
+	"os"
+
+	"github.com/sirupsen/logrus"
+)
+
+func init() {
+	redirectLogrus()
+}
+
+func redirectLogrus() {
+	// FIXME: because of different stack depth call runtime.Caller will get error function name.
+	logrus.AddHook(redirectHook{})
+	if os.Getenv("LOGRUS_STDOUT") == "" {
+		logrus.SetOutput(ioutil.Discard)
+	}
+}
+
+type redirectHook struct{}
+
+func (redirectHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+func (redirectHook) Fire(entry *logrus.Entry) error {
+	lv := _infoLevel
+	var logrusLv string
+	var verbose int32
+	switch entry.Level {
+	case logrus.FatalLevel, logrus.PanicLevel:
+		logrusLv = entry.Level.String()
+		fallthrough
+	case logrus.ErrorLevel:
+		lv = _errorLevel
+	case logrus.WarnLevel:
+		lv = _warnLevel
+	case logrus.InfoLevel:
+		lv = _infoLevel
+	case logrus.DebugLevel:
+		// use verbose log replace of debuglevel
+		verbose = 10
+	}
+	args := make([]D, 0, len(entry.Data)+1)
+	args = append(args, D{Key: _log, Value: entry.Message})
+	for k, v := range entry.Data {
+		args = append(args, D{Key: k, Value: v})
+	}
+	if logrusLv != "" {
+		args = append(args, D{Key: "logrus_lv", Value: logrusLv})
+	}
+	if verbose != 0 {
+		V(verbose).Infov(context.Background(), args...)
+	} else {
+		h.Log(context.Background(), lv, args...)
+	}
+	return nil
+}

pkg/log/pattern.go

@@ -4,17 +4,13 @@ import (
 	"bytes"
 	"fmt"
 	"io"
+	"path"
+	"runtime"
 	"strings"
 	"sync"
 	"time"
 )
 
-// Render render log output
-type Render interface {
-	Render(io.Writer, map[string]interface{}) error
-	RenderString(map[string]interface{}) string
-}
-
 var patternMap = map[string]func(map[string]interface{}) string{
 	"T": longTime,
 	"t": shortTime,
@@ -25,8 +21,8 @@ var patternMap = map[string]func(map[string]interface{}) string{
 	"i": keyFactory(_instanceID),
 	"e": keyFactory(_deplyEnv),
 	"z": keyFactory(_zone),
-	"S": keyFactory(_source),
+	"S": longSource,
-	"s": keyFactory(_source),
+	"s": shortSource,
 	"M": message,
 }
 
@@ -78,6 +74,7 @@ func (p *pattern) Render(w io.Writer, d map[string]interface{}) error {
 	for _, f := range p.funcs {
 		buf.WriteString(f(d))
 	}
+
 	_, err := buf.WriteTo(w)
 	return err
 }
@@ -114,6 +111,20 @@ func keyFactory(key string) func(map[string]interface{}) string {
 	}
 }
 
+func longSource(map[string]interface{}) string {
+	if _, file, lineNo, ok := runtime.Caller(6); ok {
+		return fmt.Sprintf("%s:%d", file, lineNo)
+	}
+	return "unknown:0"
+}
+
+func shortSource(map[string]interface{}) string {
+	if _, file, lineNo, ok := runtime.Caller(6); ok {
+		return fmt.Sprintf("%s:%d", path.Base(file), lineNo)
+	}
+	return "unknown:0"
+}
+
 func longTime(map[string]interface{}) string {
 	return time.Now().Format("15:04:05.000")
 }

pkg/log/stdout.go

@@ -2,27 +2,22 @@ package log
 
 import (
 	"context"
-	"io"
 	"os"
 	"time"
 )
 
+const defaultPattern = "%L %d-%T %f %M"
+
 var _defaultStdout = NewStdout()
 
 // StdoutHandler stdout log handler
 type StdoutHandler struct {
-	out    io.Writer
-	err    io.Writer
 	render Render
 }
 
 // NewStdout create a stdout log handler
 func NewStdout() *StdoutHandler {
-	return &StdoutHandler{
+	return &StdoutHandler{render: newPatternRender(defaultPattern)}
-		out:    os.Stdout,
-		err:    os.Stderr,
-		render: newPatternRender("[%D %T] [%s] %M"),
-	}
 }
 
 // Log stdout loging, only for developing env.
@@ -31,12 +26,8 @@ func (h *StdoutHandler) Log(ctx context.Context, lv Level, args ...D) {
 	// add extra fields
 	addExtraField(ctx, d)
 	d[_time] = time.Now().Format(_timeFormat)
-	if lv <= _infoLevel {
+	h.render.Render(os.Stderr, d)
-		h.render.Render(h.out, d)
+	os.Stderr.Write([]byte("\n"))
-	} else {
-		h.render.Render(h.err, d)
-	}
-	h.out.Write([]byte("\n"))
 }
 
 // Close stdout loging

pkg/log/util.go

@@ -2,7 +2,6 @@ package log
 
 import (
 	"context"
-	"fmt"
 	"math"
 	"runtime"
 	"strconv"
@@ -16,11 +15,7 @@ import (
 
 func addExtraField(ctx context.Context, fields map[string]interface{}) {
 	if t, ok := trace.FromContext(ctx); ok {
-		if s, ok := t.(fmt.Stringer); ok {
+		fields[_tid] = t.TraceID()
-			fields[_tid] = s.String()
-		} else {
-			fields[_tid] = fmt.Sprintf("%s", t)
-		}
 	}
 	if caller := metadata.String(ctx, metadata.Caller); caller != "" {
 		fields[_caller] = caller
@@ -28,24 +23,35 @@ func addExtraField(ctx context.Context, fields map[string]interface{}) {
 	if color := metadata.String(ctx, metadata.Color); color != "" {
 		fields[_color] = color
 	}
+	if env.Color != "" {
+		fields[_envColor] = env.Color
+	}
 	if cluster := metadata.String(ctx, metadata.Cluster); cluster != "" {
 		fields[_cluster] = cluster
 	}
 	fields[_deplyEnv] = env.DeployEnv
 	fields[_zone] = env.Zone
-	fields[_appID] = c.AppID
+	fields[_appID] = c.Family
 	fields[_instanceID] = c.Host
-	if metadata.Bool(ctx, metadata.Mirror) {
+	if metadata.String(ctx, metadata.Mirror) != "" {
 		fields[_mirror] = true
 	}
 }
 
+// funcName get func name.
+func funcName(skip int) (name string) {
+	if _, file, lineNo, ok := runtime.Caller(skip); ok {
+		return file + ":" + strconv.Itoa(lineNo)
+	}
+	return "unknown:0"
+}
+
 // toMap convert D slice to map[string]interface{} for legacy file and stdout.
 func toMap(args ...D) map[string]interface{} {
 	d := make(map[string]interface{}, 10+len(args))
 	for _, arg := range args {
 		switch arg.Type {
-		case core.UintType, core.Uint64Type, core.IntType, core.Int64Type:
+		case core.UintType, core.Uint64Type, core.IntTpye, core.Int64Type:
 			d[arg.Key] = arg.Int64Val
 		case core.StringType:
 			d[arg.Key] = arg.StringVal
@@ -61,11 +67,3 @@ func toMap(args ...D) map[string]interface{} {
 	}
 	return d
 }
-
-// funcName get func name.
-func funcName(skip int) (name string) {
-	if _, file, lineNo, ok := runtime.Caller(skip); ok {
-		return file + ":" + strconv.Itoa(lineNo)
-	}
-	return "unknown:0"
-}

pkg/log/util_test.go

@@ -0,0 +1,54 @@
+package log
+
+import (
+	"reflect"
+	"strings"
+	"testing"
+	"time"
+)
+
+func TestFuncName(t *testing.T) {
+	name := funcName(1)
+	if !strings.Contains(name, "util_test.go:11") {
+		t.Errorf("expect contains util_test.go:11 got %s", name)
+	}
+}
+
+func Test_toMap(t *testing.T) {
+	type args struct {
+		args []D
+	}
+	tests := []struct {
+		name string
+		args args
+		want map[string]interface{}
+	}{
+		{
+			args: args{[]D{KVString("test", "hello")}},
+			want: map[string]interface{}{"test": "hello"},
+		},
+		{
+			args: args{[]D{KVInt64("test", 123)}},
+			want: map[string]interface{}{"test": int64(123)},
+		},
+		{
+			args: args{[]D{KVFloat32("test", float32(1.01))}},
+			want: map[string]interface{}{"test": float32(1.01)},
+		},
+		{
+			args: args{[]D{KVFloat32("test", float32(1.01))}},
+			want: map[string]interface{}{"test": float32(1.01)},
+		},
+		{
+			args: args{[]D{KVDuration("test", time.Second)}},
+			want: map[string]interface{}{"test": time.Second},
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			if got := toMap(tt.args.args...); !reflect.DeepEqual(got, tt.want) {
+				t.Errorf("toMap() = %v, want %v", got, tt.want)
+			}
+		})
+	}
+}

pkg/log/verbose.go

@@ -1,42 +1,13 @@
 package log
 
 import (
-	"bytes"
 	"context"
 	"fmt"
 	"path/filepath"
 	"runtime"
-	"strconv"
 	"strings"
 )
 
-type verboseModule map[string]int32
-
-func (m verboseModule) String() string {
-	// FIXME strings.Builder
-	var buf bytes.Buffer
-	for k, v := range m {
-		buf.WriteString(k)
-		buf.WriteString(strconv.FormatInt(int64(v), 10))
-		buf.WriteString(",")
-	}
-	return buf.String()
-}
-
-// Set sets the value of the named command-line flag.
-// format: -log.module file=1,file2=2
-func (m verboseModule) Set(value string) error {
-	for _, i := range strings.Split(value, ",") {
-		kv := strings.Split(i, "=")
-		if len(kv) == 2 {
-			if v, err := strconv.ParseInt(kv[1], 10, 64); err == nil {
-				m[strings.TrimSpace(kv[0])] = int32(v)
-			}
-		}
-	}
-	return nil
-}
-
 // V reports whether verbosity at the call site is at least the requested level.
 // The returned value is a boolean of type Verbose, which implements Info, Infov etc.
 // These methods will write to the Info log if called.