Add library and command for human-readable logs (#9809)

* Update logrus to 1.2 and add as a direct dependency

* Create an mlog/human package for pretty-printing logs

This package can read JSON logs from mattermost.log, and output the data to
either logrus or a custom formatter, to make the logs more human readable.

* Create a command for outputting human-readable logs

This command will read JSON data from mattermost.log or stdin, and
output in a human readable format. An optional argument can be used
to activate logrus output (which includes color support).

* Reorganize code in mlog/human and improve logrus timestamp formatting

mlog/human/entry.go

@@ -0,0 +1,51 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package human
+
+import (
+	"fmt"
+	"github.com/mattermost/mattermost-server/mlog"
+	"strings"
+	"time"
+)
+
+type LogEntry struct {
+	Time    time.Time
+	Level   string
+	Message string
+	Caller  string
+	Fields  []mlog.Field
+}
+
+// Provide default string representation. Used by SimpleWriter
+func (f LogEntry) String() string {
+	var sb strings.Builder
+	if !f.Time.IsZero() {
+		sb.WriteString(f.Time.Format(time.RFC3339Nano))
+		sb.WriteRune(' ')
+	}
+	if f.Level != "" {
+		sb.WriteString(f.Level)
+		sb.WriteRune(' ')
+	}
+	if f.Caller != "" {
+		sb.WriteString(f.Caller)
+		sb.WriteRune(' ')
+	}
+	for _, field := range f.Fields {
+		sb.WriteString(field.Key)
+		sb.WriteRune('=')
+		sb.WriteString(fmt.Sprint(field.Interface))
+		sb.WriteRune(' ')
+	}
+	if f.Message != "" {
+		// If the message is multiple lines, start the whole message on a new line
+		if strings.ContainsRune(f.Message, '\n') {
+			sb.WriteRune('\n')
+		}
+		sb.WriteString(f.Message)
+	}
+
+	return sb.String()
+}

mlog/human/logrus_writer.go

@@ -0,0 +1,76 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package human
+
+import (
+	"fmt"
+	"github.com/sirupsen/logrus"
+	"io"
+	"time"
+)
+
+type LogrusWriter struct {
+	logger *logrus.Logger
+}
+
+func (w *LogrusWriter) Write(e LogEntry) {
+	if e.Level == "" {
+		fmt.Fprintln(w.logger.Out, e.Message)
+		return
+	}
+
+	lvl, err := logrus.ParseLevel(e.Level)
+	if err != nil {
+		fmt.Fprintln(w.logger.Out, err)
+		lvl = logrus.TraceLevel + 1 // will invoke Println
+	}
+
+	logger := w.logger.WithTime(e.Time)
+
+	if e.Caller != "" {
+		// logrus has a system of reporting the caller, but there's no easy way to override it
+		logger = logger.WithField("caller", e.Caller)
+	}
+
+	for _, field := range e.Fields {
+		logger = logger.WithField(field.Key, field.Interface)
+	}
+
+	switch lvl {
+	case logrus.PanicLevel:
+		// Prevent panic from causing us to exit
+		defer func() {
+			recover()
+		}()
+		logger.Panic(e.Message)
+	case logrus.FatalLevel:
+		logger.Fatal(e.Message)
+	case logrus.ErrorLevel:
+		logger.Error(e.Message)
+	case logrus.WarnLevel:
+		logger.Warn(e.Message)
+	case logrus.InfoLevel:
+		logger.Info(e.Message)
+	case logrus.DebugLevel:
+		logger.Debug(e.Message)
+	case logrus.TraceLevel:
+		logger.Trace(e.Message)
+	default:
+		logger.Println(e.Message)
+	}
+}
+
+func NewLogrusWriter(output io.Writer) *LogrusWriter {
+	w := new(LogrusWriter)
+	w.logger = logrus.New()
+	w.logger.SetLevel(logrus.TraceLevel) // don't filter any logs
+	w.logger.ExitFunc = func(int) {}     // prevent Fatal from causing us to exit
+	w.logger.SetReportCaller(false)
+	w.logger.SetOutput(output)
+	var tf logrus.TextFormatter
+	tf.FullTimestamp = true
+	tf.TimestampFormat = time.RFC3339Nano
+	w.logger.SetFormatter(&tf)
+	return w
+}

mlog/human/parser.go

@@ -0,0 +1,180 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package human
+
+import (
+	"encoding/json"
+	"errors"
+	"fmt"
+	"github.com/mattermost/mattermost-server/mlog"
+	"io"
+	"strconv"
+	"strings"
+	"time"
+)
+
+func ParseLogMessage(msg string) LogEntry {
+	result, err := parseLogMessage(msg)
+	if err != nil {
+		// If failed to parse, just output a LogEntry where all fields are blank, but Message is the original string
+		var result2 LogEntry
+		result2.Message = msg
+		return result2
+	}
+	return result
+}
+
+func parseLogMessage(msg string) (result LogEntry, err error) {
+
+	// Note: This implementation uses a custom json decoding loop.
+	// The primary advantage of this versus decoding directly into a map is to
+	// preserve the order of the fields. This can be simplified if we end up
+	// having the formatter sort fields alphabetically (logrus does by default)
+
+	dec := json.NewDecoder(strings.NewReader(msg))
+
+	// look for an initial "{"
+	if token, err := dec.Token(); err != nil {
+		return result, err
+	} else {
+		d, ok := token.(json.Delim)
+		if !ok || d != '{' {
+			return result, errors.New(fmt.Sprintf("input is not a JSON object, found: %v", token))
+		}
+	}
+
+	// read all key-value pairs
+	for dec.More() {
+		key, err := dec.Token()
+		if err != nil {
+			return result, err
+		}
+		if skey, ok := key.(string); !ok {
+			return result, errors.New("key is not a value string")
+		} else {
+			if !dec.More() {
+				return result, errors.New("missing value pair")
+			}
+
+			switch skey {
+			case "ts":
+				var ts json.Number
+				if err := dec.Decode(&ts); err != nil {
+					return result, err
+				}
+				if time, err := numberToTime(ts); err != nil {
+					return result, err
+				} else {
+					result.Time = time
+				}
+
+			case "level":
+				if s, err := decodeAsString(dec); err != nil {
+					return result, err
+				} else {
+					result.Level = s
+				}
+
+			case "msg":
+				if s, err := decodeAsString(dec); err != nil {
+					return result, err
+				} else {
+					result.Message = s
+				}
+
+			case "caller":
+				if s, err := decodeAsString(dec); err != nil {
+					return result, err
+				} else {
+					result.Caller = s
+				}
+
+			default:
+				var p interface{}
+				if err := dec.Decode(&p); err != nil {
+					return result, err
+				}
+				var f mlog.Field
+				f.Key = skey
+				f.Interface = p
+				result.Fields = append(result.Fields, f)
+			}
+		}
+	}
+
+	// read the "}"
+	if token, err := dec.Token(); err != nil {
+		return result, err
+	} else {
+		d, ok := token.(json.Delim)
+		if !ok || d != '}' {
+			return result, errors.New(fmt.Sprintf("failed to read '}', read: %v", token))
+		}
+	}
+
+	// make sure nothing else trailing
+	if token, err := dec.Token(); err != io.EOF {
+		return result, err
+	} else if token != nil {
+		return result, errors.New("found trailing data")
+	}
+
+	return result, nil
+}
+
+// Translate a number into a time
+func numberToTime(v json.Number) (time.Time, error) {
+	// Using floating point math to extract the nanoseconds leads to a time that doesn't exactly match the input
+	// Instead, parse out the components from the string representation
+
+	var t time.Time
+
+	// First make sure it is a number...
+	flt, err := v.Float64()
+	if err != nil {
+		return t, err
+	}
+
+	s := v.String()
+
+	if strings.ContainsAny(s, "eE") {
+		// input is in scientific notation. Convert to standard decimal notation
+		s = strconv.FormatFloat(flt, 'f', -1, 64)
+	}
+
+	// extract the seconds and nanoseconds separately
+	var nanos, sec int64
+
+	parts := strings.SplitN(s, ".", 2)
+	sec, err = strconv.ParseInt(parts[0], 10, 64)
+	if err != nil {
+		return t, err
+	}
+
+	if len(parts) == 2 {
+		nanosText := parts[1] + "000000000"
+		nanosText = nanosText[:9]
+		nanos, err = strconv.ParseInt(nanosText, 10, 64)
+		if err != nil {
+			return t, err
+		}
+	}
+
+	t = time.Unix(sec, nanos)
+	return t, nil
+}
+
+// Decodes a value from JSON, coercing it to a string value as necessary
+func decodeAsString(dec *json.Decoder) (s string, err error) {
+	var v interface{}
+	if err = dec.Decode(&v); err != nil {
+		return s, err
+	}
+	var ok bool
+	if s, ok = v.(string); ok {
+		return s, err
+	}
+	s = fmt.Sprint(v)
+	return s, err
+}

mlog/human/process.go

@@ -0,0 +1,23 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package human
+
+import (
+	"bufio"
+	"io"
+)
+
+type LogWriter interface {
+	Write(e LogEntry)
+}
+
+// Read JSON logs from input and write formatted logs to the output
+func ProcessLogs(reader io.Reader, writer LogWriter) {
+	scanner := bufio.NewScanner(reader)
+	for scanner.Scan() {
+		s := scanner.Text()
+		e := ParseLogMessage(s)
+		writer.Write(e)
+	}
+}

mlog/human/simple_writer.go

@@ -0,0 +1,23 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See License.txt for license information.
+
+package human
+
+import (
+	"fmt"
+	"io"
+)
+
+type SimpleWriter struct {
+	out io.Writer
+}
+
+func (w *SimpleWriter) Write(e LogEntry) {
+	fmt.Fprintln(w.out, e)
+}
+
+func NewSimpleWriter(out io.Writer) *SimpleWriter {
+	w := new(SimpleWriter)
+	w.out = out
+	return w
+}