MM-36764 mlog refactor (#18118)

Refactor mlog - simplify mlog by removing redundant code - remove Zap dependency - update unit test helpers - update logging config - update auditing
2021-08-17 16:08:04 -04:00
--- a/audit/audit.go
+++ b/audit/audit.go
@@ -5,17 +5,12 @@ package audit

 import (
 	"fmt"
-	"sort"
-
-	"github.com/mattermost/logr"
-	"github.com/mattermost/logr/format"

 	"github.com/mattermost/mattermost-server/v6/shared/mlog"
 )

 type Audit struct {
-	lgr    *logr.Logr
-	logger logr.Logger
+	logger *mlog.Logger

 	// OnQueueFull is called on an attempt to add an audit record to a full queue.
 	// Return true to drop record, or false to block until there is room in queue.
@@ -26,56 +21,34 @@ type Audit struct {
 }

 func (a *Audit) Init(maxQueueSize int) {
-	a.lgr = &logr.Logr{MaxQueueSize: maxQueueSize}
-	a.logger = a.lgr.NewLogger()
-
-	a.lgr.OnQueueFull = a.onQueueFull
-	a.lgr.OnTargetQueueFull = a.onTargetQueueFull
-	a.lgr.OnLoggerError = a.onLoggerError
-}
-
-// MakeFilter creates a filter which only allows the specified audit levels to be output.
-func (a *Audit) MakeFilter(level ...mlog.LogLevel) *logr.CustomFilter {
-	filter := &logr.CustomFilter{}
-	for _, l := range level {
-		filter.Add(logr.Level(l))
-	}
-	return filter
-}
-
-// MakeJSONFormatter creates a formatter that outputs JSON suitable for audit records.
-func (a *Audit) MakeJSONFormatter() *format.JSON {
-	f := &format.JSON{
-		DisableTimestamp:  true,
-		DisableMsg:        true,
-		DisableStacktrace: true,
-		DisableLevel:      true,
-		ContextSorter:     sortAuditFields,
-	}
-	return f
+	a.logger, _ = mlog.NewLogger(
+		mlog.MaxQueueSize(maxQueueSize),
+		mlog.OnLoggerError(a.onLoggerError),
+		mlog.OnQueueFull(a.onQueueFull),
+		mlog.OnTargetQueueFull(a.onTargetQueueFull),
+	)
 }

 // LogRecord emits an audit record with complete info.
-func (a *Audit) LogRecord(level mlog.LogLevel, rec Record) {
-	flds := logr.Fields{}
-	flds[KeyAPIPath] = rec.APIPath
-	flds[KeyEvent] = rec.Event
-	flds[KeyStatus] = rec.Status
-	flds[KeyUserID] = rec.UserID
-	flds[KeySessionID] = rec.SessionID
-	flds[KeyClient] = rec.Client
-	flds[KeyIPAddress] = rec.IPAddress
-
-	for k, v := range rec.Meta {
-		flds[k] = v
+func (a *Audit) LogRecord(level mlog.Level, rec Record) {
+	flds := []mlog.Field{
+		mlog.String(KeyAPIPath, rec.APIPath),
+		mlog.String(KeyEvent, rec.Event),
+		mlog.String(KeyStatus, rec.Status),
+		mlog.String(KeyUserID, rec.UserID),
+		mlog.String(KeySessionID, rec.SessionID),
+		mlog.String(KeyClient, rec.Client),
+		mlog.String(KeyIPAddress, rec.IPAddress),
 	}

-	l := a.logger.WithFields(flds)
-	l.Log(logr.Level(level))
+	for k, v := range rec.Meta {
+		flds = append(flds, mlog.Any(k, v))
+	}
+	a.logger.Log(level, "", flds...)
 }

 // Log emits an audit record based on minimum required info.
-func (a *Audit) Log(level mlog.LogLevel, path string, evt string, status string, userID string, sessionID string, meta Meta) {
+func (a *Audit) Log(level mlog.Level, path string, evt string, status string, userID string, sessionID string, meta Meta) {
 	a.LogRecord(level, Record{
 		APIPath:   path,
 		Event:     evt,
@@ -86,20 +59,30 @@ func (a *Audit) Log(level mlog.LogLevel, path string, evt string, status string,
 	})
 }

-// AddTarget adds a Logr target to the list of targets each audit record will be output to.
-func (a *Audit) AddTarget(target logr.Target) {
-	a.lgr.AddTarget(target)
+// Configure sets zero or more target to output audit logs to.
+func (a *Audit) Configure(cfg mlog.LoggerConfiguration) error {
+	return a.logger.ConfigureTargets(cfg)
 }

-// Shutdown cleanly stops the audit engine after making best efforts to flush all targets.
-func (a *Audit) Shutdown() {
-	err := a.lgr.Shutdown()
+// Flush attempts to write all queued audit records to all targets.
+func (a *Audit) Flush() error {
+	err := a.logger.Flush()
 	if err != nil {
 		a.onLoggerError(err)
 	}
+	return err
 }

-func (a *Audit) onQueueFull(rec *logr.LogRec, maxQueueSize int) bool {
+// Shutdown cleanly stops the audit engine after making best efforts to flush all targets.
+func (a *Audit) Shutdown() error {
+	err := a.logger.Shutdown()
+	if err != nil {
+		a.onLoggerError(err)
+	}
+	return err
+}
+
+func (a *Audit) onQueueFull(rec *mlog.LogRec, maxQueueSize int) bool {
 	if a.OnQueueFull != nil {
 		return a.OnQueueFull("main", maxQueueSize)
 	}
@@ -107,7 +90,7 @@ func (a *Audit) onQueueFull(rec *logr.LogRec, maxQueueSize int) bool {
 	return true
 }

-func (a *Audit) onTargetQueueFull(target logr.Target, rec *logr.LogRec, maxQueueSize int) bool {
+func (a *Audit) onTargetQueueFull(target mlog.Target, rec *mlog.LogRec, maxQueueSize int) bool {
 	if a.OnQueueFull != nil {
 		return a.OnQueueFull(fmt.Sprintf("%v", target), maxQueueSize)
 	}
@@ -118,58 +101,7 @@ func (a *Audit) onTargetQueueFull(target logr.Target, rec *logr.LogRec, maxQueue
 func (a *Audit) onLoggerError(err error) {
 	if a.OnError != nil {
 		a.OnError(err)
+		return
 	}
-}
-
-// sortAuditFields sorts the context fields of an audit record such that some fields
-// are prepended in order, some are appended in order, and the rest are sorted alphabetically.
-// This is done to make reading the records easier since common fields will appear in the same order.
-func sortAuditFields(fields logr.Fields) []format.ContextField {
-	prependKeys := []string{KeyEvent, KeyStatus, KeyUserID, KeySessionID, KeyIPAddress}
-	appendKeys := []string{KeyClusterID, KeyClient}
-
-	// sort alphabetically any fields not in the prepend/append lists.
-	keys := make([]string, 0, len(fields))
-	for k := range fields {
-		if !findIn(k, prependKeys, appendKeys) {
-			keys = append(keys, k)
-		}
-	}
-	sort.Strings(keys)
-
-	allKeys := make([]string, 0, len(fields))
-
-	// add any prepends that exist in fields
-	for _, k := range prependKeys {
-		if _, ok := fields[k]; ok {
-			allKeys = append(allKeys, k)
-		}
-	}
-
-	// sorted
-	allKeys = append(allKeys, keys...)
-
-	// add any appends that exist in fields
-	for _, k := range appendKeys {
-		if _, ok := fields[k]; ok {
-			allKeys = append(allKeys, k)
-		}
-	}
-
-	cfs := make([]format.ContextField, 0, len(allKeys))
-	for _, k := range allKeys {
-		cfs = append(cfs, format.ContextField{Key: k, Val: fields[k]})
-	}
-	return cfs
-}
-
-func findIn(s string, arrs ...[]string) bool {
-	for _, list := range arrs {
-		for _, key := range list {
-			if s == key {
-				return true
-			}
-		}
-	}
-	return false
+	mlog.Error("Auditing error", mlog.Err(err))
 }
--- a/audit/audit_test.go
+++ b/audit/audit_test.go
@@ -1,67 +0,0 @@
-// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
-// See LICENSE.txt for license information.
-
-package audit
-
-import (
-	"testing"
-
-	"github.com/mattermost/logr"
-	"github.com/mattermost/logr/format"
-	"github.com/stretchr/testify/require"
-)
-
-func Test_sortAuditFields(t *testing.T) {
-	type args struct {
-		fields logr.Fields
-	}
-	tests := []struct {
-		name string
-		args args
-		want []format.ContextField
-	}{
-		{name: "empty list",
-			args: args{fields: logr.Fields{}},
-			want: []format.ContextField{},
-		},
-		{name: "partial list",
-			args: args{fields: logr.Fields{"zProp": "x", "xProp": "x", "yProp": "x", KeyClusterID: "x", KeyEvent: "x"}},
-			want: []format.ContextField{
-				{Key: KeyEvent, Val: "x"},
-				{Key: "xProp", Val: "x"},
-				{Key: "yProp", Val: "x"},
-				{Key: "zProp", Val: "x"},
-				{Key: KeyClusterID, Val: "x"},
-			},
-		},
-		{name: "append/prepend only list",
-			args: args{fields: logr.Fields{KeyClusterID: "x", KeyEvent: "x", KeySessionID: "x", KeyIPAddress: "x", KeyClient: "x",
-				KeyUserID: "x", KeyStatus: "x"}},
-			want: []format.ContextField{
-				// prepend: KeyEvent, KeyStatus, KeyUserID, KeySessionID, KeyIPAddress
-				// append: KeyClusterID, KeyClient
-				{Key: KeyEvent, Val: "x"},
-				{Key: KeyStatus, Val: "x"},
-				{Key: KeyUserID, Val: "x"},
-				{Key: KeySessionID, Val: "x"},
-				{Key: KeyIPAddress, Val: "x"},
-				{Key: KeyClusterID, Val: "x"},
-				{Key: KeyClient, Val: "x"},
-			},
-		},
-		{name: "sortables only list",
-			args: args{fields: logr.Fields{"zProp": "x", "xProp": "x", "yProp": "x"}},
-			want: []format.ContextField{
-				{Key: "xProp", Val: "x"},
-				{Key: "yProp", Val: "x"},
-				{Key: "zProp", Val: "x"},
-			},
-		},
-	}
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			got := sortAuditFields(tt.args.fields)
-			require.Equal(t, tt.want, got)
-		})
-	}
-}
--- a/audit/file.go
+++ b/audit/file.go
@@ -1,34 +0,0 @@
-// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
-// See LICENSE.txt for license information.
-
-package audit
-
-import (
-	"os"
-
-	"github.com/mattermost/logr"
-	"github.com/mattermost/logr/target"
-)
-
-type FileOptions target.FileOptions
-
-// NewFileTarget creates a target capable of outputting log records to a rotated file.
-func NewFileTarget(filter logr.Filter, formatter logr.Formatter, opts FileOptions, maxQSize int) (*target.File, error) {
-	fopts := target.FileOptions(opts)
-	err := checkFileWritable(fopts.Filename)
-	if err != nil {
-		return nil, err
-	}
-	target := target.NewFileTarget(filter, formatter, fopts, maxQSize)
-	return target, nil
-}
-
-func checkFileWritable(filename string) error {
-	// try opening/creating the file for writing
-	file, err := os.OpenFile(filename, os.O_RDWR|os.O_APPEND|os.O_CREATE, 0600)
-	if err != nil {
-		return err
-	}
-	file.Close()
-	return nil
-}