Chore: Implements log15 terminal logger (#44447)

Nicer development/terminal output based on log15 terminal logger.

pkg/infra/log/log.go

@@ -13,12 +13,12 @@ import (
 	"time"
 
 	gokitlog "github.com/go-kit/log"
-	"github.com/go-kit/log/term"
 	"github.com/go-stack/stack"
 	"github.com/mattn/go-isatty"
 	"gopkg.in/ini.v1"
 
 	"github.com/grafana/grafana/pkg/infra/log/level"
+	"github.com/grafana/grafana/pkg/infra/log/term"
 	"github.com/grafana/grafana/pkg/util"
 	"github.com/grafana/grafana/pkg/util/errutil"
 )
@@ -38,7 +38,10 @@ func init() {
 	loggersToClose = make([]DisposableHandler, 0)
 	loggersToReload = make([]ReloadableHandler, 0)
 	filters = map[string]level.Option{}
-	Root.AddLogger(gokitlog.NewLogfmtLogger(os.Stderr), "info", filters)
+
+	// Use console by default
+	format := getLogFormat("console")
+	Root.AddLogger(format(os.Stderr), "info", filters)
 }
 
 type LogWithFilters struct {
@@ -216,37 +219,12 @@ func Caller(depth int) gokitlog.Valuer {
 
 type Formatedlogger func(w io.Writer) gokitlog.Logger
 
-func terminalColorFn(keyvals ...interface{}) term.FgBgColor {
-	for i := 0; i < len(keyvals)-1; i += 2 {
-		if keyvals[i] != level.Key() {
-			continue
-		}
-		switch keyvals[i+1] {
-		case "trace":
-			return term.FgBgColor{Fg: term.Gray}
-		case level.DebugValue():
-			return term.FgBgColor{Fg: term.Gray}
-		case level.InfoValue():
-			return term.FgBgColor{Fg: term.Green}
-		case level.WarnValue():
-			return term.FgBgColor{Fg: term.Yellow}
-		case level.ErrorValue():
-			return term.FgBgColor{Fg: term.Red}
-		case "crit":
-			return term.FgBgColor{Fg: term.Gray, Bg: term.DarkRed}
-		default:
-			return term.FgBgColor{}
-		}
-	}
-	return term.FgBgColor{}
-}
-
 func getLogFormat(format string) Formatedlogger {
 	switch format {
 	case "console":
 		if isatty.IsTerminal(os.Stdout.Fd()) {
 			return func(w io.Writer) gokitlog.Logger {
-				return term.NewColorLogger(w, gokitlog.NewLogfmtLogger, terminalColorFn)
+				return term.NewTerminalLogger(w)
 			}
 		}
 		return func(w io.Writer) gokitlog.Logger {

pkg/infra/log/term/terminal_logger.go

@@ -0,0 +1,262 @@
+package term
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"reflect"
+	"strconv"
+	"strings"
+	"sync"
+	"time"
+
+	gokitlog "github.com/go-kit/log"
+	"github.com/grafana/grafana/pkg/infra/log/level"
+)
+
+const (
+	timeFormat     = "2006-01-02T15:04:05-0700"
+	termTimeFormat = "01-02|15:04:05"
+	floatFormat    = 'f'
+	termMsgJust    = 40
+	errorKey       = "LOG15_ERROR"
+)
+
+type terminalLogger struct {
+	w io.Writer
+}
+
+// NewTerminalLogger returns a logger that encodes keyvals to the Writer in
+// a format optimized for human readability on a terminal with color-coded
+// level output and terser human friendly timestamp.
+// This format should only be used for interactive programs or while developing.
+//
+//     [TIME] [LEVEL] MESSAGE key=value key=value ...
+//
+// Example:
+//
+//     [May 16 20:58:45] [DBUG] remove route ns=haproxy addr=127.0.0.1:50002
+//
+func NewTerminalLogger(w io.Writer) gokitlog.Logger {
+	return &terminalLogger{w}
+}
+
+func (l terminalLogger) Log(keyvals ...interface{}) error {
+	r := getRecord(keyvals)
+
+	b := &bytes.Buffer{}
+	lvl := strings.ToUpper(r.level.String())
+	if r.color > 0 {
+		fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", r.color, lvl, r.time.Format(termTimeFormat), r.msg)
+	} else {
+		fmt.Fprintf(b, "[%s] [%s] %s ", lvl, r.time.Format(termTimeFormat), r.msg)
+	}
+
+	// try to justify the log output for short messages
+	if len(r.keyvals) > 0 && len(r.msg) < termMsgJust {
+		b.Write(bytes.Repeat([]byte{' '}, termMsgJust-len(r.msg)))
+	}
+
+	// print the keys logfmt style
+	logfmt(b, r.keyvals, r.color)
+	_, err := l.w.Write(b.Bytes())
+	return err
+}
+
+type record struct {
+	msg     string
+	time    time.Time
+	level   level.Value
+	color   int
+	keyvals []interface{}
+}
+
+func getRecord(keyvals ...interface{}) *record {
+	r := &record{
+		color:   0,
+		level:   level.InfoValue(),
+		keyvals: []interface{}{},
+	}
+
+	keyvals = keyvals[0].([]interface{})
+
+	if len(keyvals) == 0 {
+		return nil
+	}
+	if len(keyvals)%2 == 1 {
+		keyvals = append(keyvals, nil)
+	}
+
+	for i := 0; i < len(keyvals); i += 2 {
+		k, v := keyvals[i], keyvals[i+1]
+
+		if k == "t" {
+			t := v.(fmt.Stringer)
+			time, err := time.Parse("2006-01-02T15:04:05.999999999-0700", t.String())
+			if err == nil {
+				r.time = time
+			}
+			continue
+		}
+
+		if keyvals[i] == "msg" {
+			r.msg = v.(string)
+			continue
+		}
+
+		if k == level.Key() {
+			switch v {
+			case "trace":
+			case level.DebugValue():
+				r.level = level.DebugValue()
+				r.color = 36
+			case level.InfoValue():
+				r.level = level.InfoValue()
+				r.color = 32
+			case level.WarnValue():
+				r.level = level.WarnValue()
+				r.color = 33
+			case level.ErrorValue():
+				r.level = level.ErrorValue()
+				r.color = 31
+			case "crit":
+				r.level = level.ErrorValue()
+				r.color = 35
+			}
+
+			continue
+		}
+
+		r.keyvals = append(r.keyvals, k)
+		r.keyvals = append(r.keyvals, v)
+	}
+
+	return r
+}
+
+func logfmt(buf *bytes.Buffer, ctx []interface{}, color int) {
+	for i := 0; i < len(ctx); i += 2 {
+		if i != 0 {
+			buf.WriteByte(' ')
+		}
+
+		k, ok := ctx[i].(string)
+		v := formatLogfmtValue(ctx[i+1])
+		if !ok {
+			k, v = errorKey, formatLogfmtValue(k)
+		}
+
+		// XXX: we should probably check that all of your key bytes aren't invalid
+		if color > 0 {
+			fmt.Fprintf(buf, "\x1b[%dm%s\x1b[0m=%s", color, k, v)
+		} else {
+			buf.WriteString(k)
+			buf.WriteByte('=')
+			buf.WriteString(v)
+		}
+	}
+
+	buf.WriteByte('\n')
+}
+
+func formatShared(value interface{}) (result interface{}) {
+	defer func() {
+		if err := recover(); err != nil {
+			if v := reflect.ValueOf(value); v.Kind() == reflect.Ptr && v.IsNil() {
+				result = "nil"
+			} else {
+				panic(err)
+			}
+		}
+	}()
+
+	switch v := value.(type) {
+	case time.Time:
+		return v.Format(timeFormat)
+
+	case error:
+		return v.Error()
+
+	case fmt.Stringer:
+		return v.String()
+
+	default:
+		return v
+	}
+}
+
+// formatValue formats a value for serialization
+func formatLogfmtValue(value interface{}) string {
+	if value == nil {
+		return "nil"
+	}
+
+	if t, ok := value.(time.Time); ok {
+		// Performance optimization: No need for escaping since the provided
+		// timeFormat doesn't have any escape characters, and escaping is
+		// expensive.
+		return t.Format(timeFormat)
+	}
+	value = formatShared(value)
+	switch v := value.(type) {
+	case bool:
+		return strconv.FormatBool(v)
+	case float32:
+		return strconv.FormatFloat(float64(v), floatFormat, 3, 64)
+	case float64:
+		return strconv.FormatFloat(v, floatFormat, 3, 64)
+	case int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64:
+		return fmt.Sprintf("%d", value)
+	case string:
+		return escapeString(v)
+	default:
+		return escapeString(fmt.Sprintf("%+v", value))
+	}
+}
+
+var stringBufPool = sync.Pool{
+	New: func() interface{} { return new(bytes.Buffer) },
+}
+
+func escapeString(s string) string {
+	needsQuotes := false
+	needsEscape := false
+	for _, r := range s {
+		if r <= ' ' || r == '=' || r == '"' {
+			needsQuotes = true
+		}
+		if r == '\\' || r == '"' || r == '\n' || r == '\r' || r == '\t' {
+			needsEscape = true
+		}
+	}
+	if !needsEscape && !needsQuotes {
+		return s
+	}
+	e := stringBufPool.Get().(*bytes.Buffer)
+	e.WriteByte('"')
+	for _, r := range s {
+		switch r {
+		case '\\', '"':
+			e.WriteByte('\\')
+			e.WriteByte(byte(r))
+		case '\n':
+			e.WriteString("\\n")
+		case '\r':
+			e.WriteString("\\r")
+		case '\t':
+			e.WriteString("\\t")
+		default:
+			e.WriteRune(r)
+		}
+	}
+	e.WriteByte('"')
+	var ret string
+	if needsQuotes {
+		ret = e.String()
+	} else {
+		ret = string(e.Bytes()[1 : e.Len()-1])
+	}
+	e.Reset()
+	stringBufPool.Put(e)
+	return ret
+}