diff --git a/pkg/infra/log/log.go b/pkg/infra/log/log.go index bd393178a26..ba531ca633f 100644 --- a/pkg/infra/log/log.go +++ b/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 { diff --git a/pkg/infra/log/term/terminal_logger.go b/pkg/infra/log/term/terminal_logger.go new file mode 100644 index 00000000000..21fa02b0a9c --- /dev/null +++ b/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 +}