Audit logging - new schema (#20447)

* Audit logging - new schema added, old schema removed. * fix linter error by running goimports * Address review comments * Address review comments * Example usage of new audit logging API for the updateUserAuth call * fixed unit test on auditing updating user record * Changed the `TestUpdateConfigDiffInAuditRecord` testcase---it failed, because this PR changes how the `meta` field is serialized into the audit log records. * fix linter error
2022-07-14 12:19:33 +03:00
--- a/api4/config_test.go
+++ b/api4/config_test.go
@@ -572,8 +572,9 @@ func TestUpdateConfigDiffInAuditRecord(t *testing.T) {
 	data, err := ioutil.ReadAll(logFile)
 	require.NoError(t, err)
 	require.NotEmpty(t, data)
+
 	require.Contains(t, string(data),
-		fmt.Sprintf(`"diff":"[{Path:ServiceSettings.ReadTimeout BaseVal:%d ActualVal:%d}]"`,
+		fmt.Sprintf(`"diff":[{"path":"ServiceSettings.ReadTimeout","base_val":%d,"actual_val":%d}]`,
 			timeoutVal, timeoutVal+1))
 }

--- a/api4/user.go
+++ b/api4/user.go
@@ -1508,13 +1508,15 @@ func updateUserAuth(c *Context, w http.ResponseWriter, r *http.Request) {
 		return
 	}

+	auditRec.AddEventParameter("user_auth", userAuth.Auditable())
+
 	if userAuth.AuthData == nil || *userAuth.AuthData == "" || userAuth.AuthService == "" {
 		c.Err = model.NewAppError("updateUserAuth", "api.user.update_user_auth.invalid_request", nil, "", http.StatusBadRequest)
 		return
 	}

 	if user, err := c.App.GetUser(c.Params.UserId); err == nil {
-		auditRec.AddMeta("user", user)
+		auditRec.AddEventPriorState(user)
 	}

 	user, err := c.App.UpdateUserAuth(c.Params.UserId, &userAuth)
@@ -1522,6 +1524,7 @@ func updateUserAuth(c *Context, w http.ResponseWriter, r *http.Request) {
 		c.Err = err
 		return
 	}
+	auditRec.AddEventResultState(user)

 	auditRec.Success()
 	auditRec.AddMeta("auth_service", user.AuthService)
--- a/app/audit.go
+++ b/app/audit.go
@@ -16,13 +16,6 @@ import (
 	"github.com/mattermost/mattermost-server/v6/store"
 )

-const (
-	RestLevelID        = 240
-	RestContentLevelID = 241
-	RestPermsLevelID   = 242
-	CLILevelID         = 243
-)
-
 var (
 	LevelAPI     = mlog.LvlAuditAPI
 	LevelContent = mlog.LvlAuditContent
@@ -69,12 +62,11 @@ func (a *App) LogAuditRecWithLevel(rec *audit.Record, level mlog.Level, err erro
 		return
 	}
 	if err != nil {
-		if appErr, ok := err.(*model.AppError); ok {
-			rec.AddMeta("err", appErr.Error())
-			rec.AddMeta("code", appErr.StatusCode)
-		} else {
-			rec.AddMeta("err", err)
+		appErr, ok := err.(*model.AppError)
+		if ok {
+			rec.AddErrorCode(appErr.StatusCode)
 		}
+		rec.AddErrorDesc(appErr.Error())
 		rec.Fail()
 	}
 	a.Srv().Audit.LogRecord(level, *rec)
@@ -89,16 +81,25 @@ func (a *App) MakeAuditRecord(event string, initialStatus string) *audit.Record
 	}

 	rec := &audit.Record{
-		APIPath:   "",
-		Event:     event,
+		EventName: event,
 		Status:    initialStatus,
-		UserID:    userID,
-		SessionID: "",
-		Client:    fmt.Sprintf("server %s-%s", model.BuildNumber, model.BuildHash),
-		IPAddress: "",
-		Meta:      audit.Meta{audit.KeyClusterID: a.GetClusterId()},
+		Meta: map[string]interface{}{
+			audit.KeyAPIPath:   "",
+			audit.KeyClusterID: a.GetClusterId(),
+		},
+		Actor: audit.EventActor{
+			UserId:    userID,
+			SessionId: "",
+			Client:    fmt.Sprintf("server %s-%s", model.BuildNumber, model.BuildHash),
+			IpAddress: "",
+		},
+		EventData: audit.EventData{
+			Parameters:  map[string]interface{}{},
+			PriorState:  map[string]interface{}{},
+			ResultState: map[string]interface{}{},
+			ObjectType:  "",
+		},
 	}
-	rec.AddMetaTypeConverter(model.AuditModelTypeConv)

 	return rec
 }
--- a/audit/audit.go
+++ b/audit/audit.go
@@ -32,33 +32,17 @@ func (a *Audit) Init(maxQueueSize int) {
 // LogRecord emits an audit record with complete info.
 func (a *Audit) LogRecord(level mlog.Level, rec Record) {
 	flds := []mlog.Field{
-		mlog.String(KeyAPIPath, rec.APIPath),
-		mlog.String(KeyEvent, rec.Event),
+		mlog.String("event_name", rec.EventName),
 		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),
+		mlog.Any("actor", rec.Actor),
+		mlog.Any("event", rec.EventData),
+		mlog.Any("meta", rec.Meta),
+		mlog.Any("error", rec.Error),
 	}

-	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.Level, path string, evt string, status string, userID string, sessionID string, meta Meta) {
-	a.LogRecord(level, Record{
-		APIPath:   path,
-		Event:     evt,
-		Status:    status,
-		UserID:    userID,
-		SessionID: sessionID,
-		Meta:      meta,
-	})
-}
-
 // Configure sets zero or more target to output audit logs to.
 func (a *Audit) Configure(cfg mlog.LoggerConfiguration) error {
 	return a.logger.ConfigureTargets(cfg, nil)
--- a/audit/audit_test.go
+++ b/audit/audit_test.go
@@ -0,0 +1,103 @@
+// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
+// See LICENSE.txt for license information.
+
+package audit
+
+import (
+	"encoding/json"
+	"fmt"
+	"io/ioutil"
+	"os"
+	"path/filepath"
+	"regexp"
+	"strings"
+	"testing"
+
+	"github.com/mattermost/mattermost-server/v6/model"
+	"github.com/mattermost/mattermost-server/v6/shared/mlog"
+	"github.com/stretchr/testify/require"
+)
+
+func TestAudit_LogRecord(t *testing.T) {
+	userId := model.NewId()
+	testCases := []struct {
+		description  string
+		auditLogFunc func(audit Audit)
+		expectedLogs []string
+	}{
+		{
+			"empty record",
+			func(audit Audit) {
+				rec := Record{}
+				audit.LogRecord(mlog.LvlAuditAPI, rec)
+			},
+			[]string{
+				`{"timestamp":0,"level":"audit-api","msg":"","event_name":"","status":"","actor":{"user_id":"","session_id":"","client":"","ip_address":""},"event":{"parameters":null,"prior_state":null,"resulting_state":null,"object_type":""},"meta":null,"error":{}}`,
+			},
+		},
+		{
+			"update user record, no error",
+			func(audit Audit) {
+
+				usr := &model.User{}
+				usr.Id = userId //"fasd21321sdasd12"
+				usr.Username = "TestABC"
+				usr.Password = "hello_world"
+
+				rec := Record{}
+				rec.AddEventObjectType("user")
+				rec.EventName = "User.Update"
+				rec.AddEventPriorState(usr)
+
+				usr.Username = "TestDEF"
+				rec.AddEventResultState(usr)
+				rec.Success()
+
+				audit.LogRecord(mlog.LvlAuditAPI, rec)
+			},
+			[]string{
+				strings.Replace(`{"timestamp":0,"level":"audit-api","msg":"","event_name":"User.Update","status":"success","actor":{"user_id":"","session_id":"","client":"","ip_address":""},"event":{"parameters":null,"prior_state":{"id":"_____USERID_____","username":"TestABC"},"resulting_state":{"id":"_____USERID_____","username":"TestDEF"},"object_type":"user"},"meta":null,"error":{}}`, "_____USERID_____", userId, -1),
+			},
+		},
+	}
+
+	cfg := mlog.TargetCfg{
+		Type:          "file",
+		Format:        "json",
+		FormatOptions: nil,
+		Levels:        []mlog.Level{mlog.LvlAuditCLI, mlog.LvlAuditAPI, mlog.LvlAuditPerms, mlog.LvlAuditContent},
+	}
+
+	reTs := regexp.MustCompile(`"timestamp":"[0-9\.\-\+\:\sZ]+"`)
+
+	for _, testCase := range testCases {
+		t.Run(testCase.description, func(t *testing.T) {
+			tempDir, err := ioutil.TempDir(os.TempDir(), "TestAudit_LogRecord")
+			require.NoError(t, err)
+			defer os.Remove(tempDir)
+
+			filePath := filepath.Join(tempDir, "audit.log")
+			cfg.Options = json.RawMessage(fmt.Sprintf(`{"filename": "%s"}`, filePath))
+			logger, err := mlog.NewLogger()
+			require.NoError(t, err)
+
+			err = logger.ConfigureTargets(map[string]mlog.TargetCfg{testCase.description: cfg}, nil)
+			require.NoError(t, err)
+			mlog.InitGlobalLogger(logger)
+
+			audit := Audit{}
+			audit.logger = logger
+			testCase.auditLogFunc(audit)
+
+			err = logger.Shutdown()
+			require.NoError(t, err)
+
+			logs, err := ioutil.ReadFile(filePath)
+			require.NoError(t, err)
+
+			actual := strings.TrimSpace(string(logs))
+			actual = reTs.ReplaceAllString(actual, `"timestamp":0`)
+			require.ElementsMatch(t, testCase.expectedLogs, strings.Split(actual, "\n"))
+		})
+	}
+}
--- a/audit/const.go
+++ b/audit/const.go
@@ -8,6 +8,7 @@ const (

 	KeyAPIPath   = "api_path"
 	KeyEvent     = "event"
+	KeyEventData = "event_data"
 	KeyStatus    = "status"
 	KeyUserID    = "user_id"
 	KeySessionID = "session_id"
--- a/audit/record.go
+++ b/audit/record.go
@@ -3,24 +3,49 @@

 package audit

-// Meta represents metadata that can be added to a audit record as name/value pairs.
-type Meta map[string]any
-
-// FuncMetaTypeConv defines a function that can convert meta data types into something
-// that serializes well for audit records.
-type FuncMetaTypeConv func(val any) (newVal any, converted bool)
-
 // Record provides a consistent set of fields used for all audit logging.
 type Record struct {
-	APIPath   string
-	Event     string
-	Status    string
-	UserID    string
-	SessionID string
-	Client    string
-	IPAddress string
-	Meta      Meta
-	metaConv  []FuncMetaTypeConv
+	EventName string                 `json:"event_name"`
+	Status    string                 `json:"status"`
+	EventData EventData              `json:"event"`
+	Actor     EventActor             `json:"actor"`
+	Meta      map[string]interface{} `json:"meta"`
+	Error     EventError             `json:"error,omitempty"`
+}
+
+// EventData contains all event specific data about the modified entity
+type EventData struct {
+	Parameters  map[string]interface{} `json:"parameters"`      // Payload and parameters being processed as part of the request
+	PriorState  map[string]interface{} `json:"prior_state"`     // Prior state of the object being modified, nil if no prior state
+	ResultState map[string]interface{} `json:"resulting_state"` // Resulting object after creating or modifying it
+	ObjectType  string                 `json:"object_type"`     // String representation of the object type. eg. "post"
+}
+
+// EventActor is the subject triggering the event
+type EventActor struct {
+	UserId    string `json:"user_id"`
+	SessionId string `json:"session_id"`
+	Client    string `json:"client"`
+	IpAddress string `json:"ip_address"`
+}
+
+// EventMeta is a key-value store to store related information to the event that is not directly related to the modified entity
+type EventMeta struct {
+	ApiPath   string `json:"api_path"`
+	ClusterId string `json:"cluster_id"`
+}
+
+// EventError contains error information in case of failure of the event
+type EventError struct {
+	Description string `json:"description,omitempty"`
+	Code        int    `json:"status_code,omitempty"`
+}
+
+// Auditable for sensitive object classes, consider implementing Auditable and include whatever the
+// AuditableObject returns. For example: it's likely OK to write a user object to the
+// audit logs, but not the user password in cleartext or hashed form
+type Auditable interface {
+	Auditable() map[string]interface{}
 }

 // Success marks the audit record status as successful.
@@ -28,32 +53,43 @@ func (rec *Record) Success() {
 	rec.Status = Success
 }

-// Success marks the audit record status as failed.
+// Fail marks the audit record status as failed.
 func (rec *Record) Fail() {
 	rec.Status = Fail
 }

-// AddMeta adds a single name/value pair to this audit record's metadata.
-func (rec *Record) AddMeta(name string, val any) {
-	if rec.Meta == nil {
-		rec.Meta = Meta{}
-	}
+// AddEventParameter adds a parameter, e.g. query or post body, to the event
+func (rec *Record) AddEventParameter(key string, val interface{}) {
+	rec.EventData.Parameters[key] = val
+}

-	// possibly convert val to something better suited for serializing
-	// via zero or more conversion functions.
-	var converted bool
-	for _, conv := range rec.metaConv {
-		val, converted = conv(val)
-		if converted {
-			break
-		}
-	}
+// AddEventPriorState adds the prior state of the modified object to the audit record
+func (rec *Record) AddEventPriorState(object Auditable) {
+	rec.EventData.PriorState = object.Auditable()
+}

+// AddEventResultState adds the result state of the modified object to the audit record
+func (rec *Record) AddEventResultState(object Auditable) {
+	rec.EventData.ResultState = object.Auditable()
+}
+
+// AddEventObjectType adds the object type of the modified object to the audit record
+func (rec *Record) AddEventObjectType(objectType string) {
+	rec.EventData.ObjectType = objectType
+}
+
+// AddMeta adds a key/value entry to the audit record that can be used for related information not directly related to
+// the modified object, e.g. authentication method
+func (rec *Record) AddMeta(name string, val interface{}) {
 	rec.Meta[name] = val
 }

-// AddMetaTypeConverter adds a function capable of converting meta field types
-// into something more suitable for serialization.
-func (rec *Record) AddMetaTypeConverter(f FuncMetaTypeConv) {
-	rec.metaConv = append(rec.metaConv, f)
+// AddErrorCode adds the error code for a failed event to the audit record
+func (rec *Record) AddErrorCode(code int) {
+	rec.Error.Code = code
+}
+
+// AddErrorDesc adds the error description for a failed event to the audit record
+func (rec *Record) AddErrorDesc(description string) {
+	rec.Error.Description = description
 }
--- a/audit/record_test.go
+++ b/audit/record_test.go
@@ -1,76 +0,0 @@
-// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
-// See LICENSE.txt for license information.
-
-package audit
-
-import (
-	"testing"
-
-	"github.com/stretchr/testify/require"
-)
-
-type bloated struct {
-	fld1 string
-	fld2 string
-	fld3 string
-	fld4 string
-}
-
-type wilted struct {
-	wilt1 string
-}
-
-func conv(val any) (any, bool) {
-	switch v := val.(type) {
-	case *bloated:
-		return &wilted{wilt1: v.fld1}, true
-	}
-	return val, false
-}
-
-func TestRecord_AddMeta(t *testing.T) {
-	type fields struct {
-		metaConv []FuncMetaTypeConv
-	}
-	type args struct {
-		name string
-		val  any
-	}
-	tests := []struct {
-		name     string
-		fields   fields
-		args     args
-		wantWilt bool
-		wantVal  string
-	}{
-		{name: "no converter", wantWilt: false, wantVal: "ok", fields: fields{}, args: args{name: "prop", val: "ok"}},
-		{name: "don't convert", wantWilt: false, wantVal: "ok", fields: fields{metaConv: []FuncMetaTypeConv{conv}}, args: args{name: "prop", val: "ok"}},
-		{name: "convert", wantWilt: true, wantVal: "1", fields: fields{metaConv: []FuncMetaTypeConv{conv}}, args: args{name: "prop", val: &bloated{
-			fld1: "1", fld2: "2", fld3: "3", fld4: "4"}},
-		},
-	}
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			rec := &Record{
-				metaConv: tt.fields.metaConv,
-			}
-			rec.AddMeta(tt.args.name, tt.args.val)
-
-			// fetch the prop store in auditRecord meta data
-			got, ok := rec.Meta["prop"]
-			require.True(t, ok)
-
-			// check if conversion was expected
-			val, ok := got.(*wilted)
-			require.Equal(t, tt.wantWilt, ok)
-
-			if ok {
-				// if converted to wilt then make sure field was copied
-				require.Equal(t, tt.wantVal, val.wilt1)
-			} else {
-				// if not converted, make sure val is unchanged
-				require.Equal(t, tt.wantVal, got)
-			}
-		})
-	}
-}
--- a/model/user.go
+++ b/model/user.go
@@ -140,6 +140,12 @@ type UserAuth struct {
 	AuthService string  `json:"auth_service,omitempty"`
 }

+func (u *UserAuth) Auditable() map[string]interface{} {
+	return map[string]interface{}{
+		"auth_service": u.AuthService,
+	}
+}
+
 //msgp:ignore UserForIndexing
 type UserForIndexing struct {
 	Id          string   `json:"id"`
@@ -829,6 +835,13 @@ func (u *User) ToPatch() *UserPatch {
 	}
 }

+func (u *User) Auditable() map[string]interface{} {
+	return map[string]interface{}{
+		"id":       u.Id,
+		"username": u.Username,
+	}
+}
+
 func (u *UserPatch) SetField(fieldName string, fieldValue string) {
 	switch fieldName {
 	case "FirstName":
--- a/web/context.go
+++ b/web/context.go
@@ -43,8 +43,8 @@ func (c *Context) LogAuditRecWithLevel(rec *audit.Record, level mlog.Level) {
 		return
 	}
 	if c.Err != nil {
-		rec.AddMeta("err", c.Err.Id)
-		rec.AddMeta("code", c.Err.StatusCode)
+		rec.AddErrorCode(c.Err.StatusCode)
+		rec.AddErrorDesc(c.Err.Error())
 		if c.Err.Id == "api.context.permissions.app_error" {
 			level = app.LevelPerms
 		}
@@ -56,16 +56,25 @@ func (c *Context) LogAuditRecWithLevel(rec *audit.Record, level mlog.Level) {
 // MakeAuditRecord creates a audit record pre-populated with data from this context.
 func (c *Context) MakeAuditRecord(event string, initialStatus string) *audit.Record {
 	rec := &audit.Record{
-		APIPath:   c.AppContext.Path(),
-		Event:     event,
+		EventName: event,
 		Status:    initialStatus,
-		UserID:    c.AppContext.Session().UserId,
-		SessionID: c.AppContext.Session().Id,
-		Client:    c.AppContext.UserAgent(),
-		IPAddress: c.AppContext.IPAddress(),
-		Meta:      audit.Meta{audit.KeyClusterID: c.App.GetClusterId()},
+		Actor: audit.EventActor{
+			UserId:    c.AppContext.Session().UserId,
+			SessionId: c.AppContext.Session().Id,
+			Client:    c.AppContext.UserAgent(),
+			IpAddress: c.AppContext.IPAddress(),
+		},
+		Meta: map[string]interface{}{
+			audit.KeyAPIPath:   c.AppContext.Path(),
+			audit.KeyClusterID: c.App.GetClusterId(),
+		},
+		EventData: audit.EventData{
+			Parameters:  map[string]interface{}{},
+			PriorState:  map[string]interface{}{},
+			ResultState: map[string]interface{}{},
+			ObjectType:  "",
+		},
 	}
-	rec.AddMetaTypeConverter(model.AuditModelTypeConv)

 	return rec
 }