grafana/pkg/infra/log/term/terminal_logger.go

package term

import (
	"bytes"
	"fmt"
	"io"
	"reflect"
	"strconv"
	"strings"
	"sync"
	"time"

	gokitlog "github.com/go-kit/log"
	"github.com/go-kit/log/level"
)

var (
	timeFormat     = time.RFC3339Nano
	termTimeFormat = "01-02|15:04:05"
)

const (
	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{}

	// To make the log output more readable, we make all log levels 5 characters long
	lvl := fmt.Sprintf("%-5s", 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) // lgtm[go/log-injection]
	} else {
		fmt.Fprintf(b, "[%s] [%s] %s ", lvl, r.time.Format(termTimeFormat), r.msg) // lgtm[go/log-injection]
	}

	// 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, ok := v.(fmt.Stringer)
			if ok {
				parsedTime, err := time.Parse("2006-01-02T15:04:05.999999999-0700", t.String())
				if err == nil {
					r.time = parsedTime
					continue
				} else {
					parsedTime, err := time.Parse(time.RFC3339Nano, t.String())
					if err == nil {
						r.time = parsedTime
						continue
					}
				}
			}

			t3, ok := v.(string)
			if ok {
				// from alerting:        2022-01-26T12:03:41.655107858-08:00
				time, err := time.Parse("2006-01-02T15:04:05.999999999-07:00", t3)
				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) // lgtm[go/log-injection]
		} 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
}