[MM-54132] Use annotated logger for log messages from jobs (#24275)

server/public/model/job.go

@@ -6,6 +6,8 @@ package model
 import (
 	"net/http"
 	"time"
+
+	"github.com/mattermost/mattermost/server/public/shared/mlog"
 )
 
 const (
@@ -80,6 +82,8 @@ type Job struct {
 	Status         string    `json:"status"`
 	Progress       int64     `json:"progress"`
 	Data           StringMap `json:"data"`
+
+	Logger *mlog.Logger `json:"-"`
 }
 
 func (j *Job) Auditable() map[string]interface{} {
@@ -120,15 +124,19 @@ func (j *Job) IsValid() *AppError {
 	return nil
 }
 
+// InitLogger attaches an annotated logger to a Job.
+// It should always be called after creating a new Job to ensure `Job.Logger` it set.
+func (j *Job) InitLogger(logger mlog.LoggerIFace) {
+	j.Logger = logger.With(
+		mlog.String("job_id", j.Id),
+		mlog.String("job_type", j.Type),
+		mlog.String("create_at", time.UnixMilli(j.CreateAt).String()),
+	)
+}
+
 type Worker interface {
 	Run()
 	Stop()
 	JobChannel() chan<- Job
 	IsEnabled(cfg *Config) bool
 }
-
-type Scheduler interface {
-	Enabled(cfg *Config) bool
-	NextScheduleTime(cfg *Config, now time.Time, pendingJobs bool, lastSuccessfulJob *Job) *time.Time
-	ScheduleJob(cfg *Config, pendingJobs bool, lastSuccessfulJob *Job) (*Job, *AppError)
-}

server/public/plugin/health_check_test.go

@@ -51,10 +51,8 @@ func testPluginHealthCheckSuccess(t *testing.T) {
 	require.NoError(t, err)
 
 	bundle := model.BundleInfoForPath(dir)
-	log := mlog.CreateConsoleTestLogger(true, mlog.LvlError)
-	defer log.Shutdown()
-
-	supervisor, err := newSupervisor(bundle, nil, nil, log, nil)
+	logger := mlog.CreateConsoleTestLogger(t)
+	supervisor, err := newSupervisor(bundle, nil, nil, logger, nil)
 	require.NoError(t, err)
 	require.NotNil(t, supervisor)
 	defer supervisor.Shutdown()
@@ -94,10 +92,8 @@ func testPluginHealthCheckPanic(t *testing.T) {
 	require.NoError(t, err)
 
 	bundle := model.BundleInfoForPath(dir)
-	log := mlog.CreateConsoleTestLogger(true, mlog.LvlError)
-	defer log.Shutdown()
-
-	supervisor, err := newSupervisor(bundle, nil, nil, log, nil)
+	logger := mlog.CreateConsoleTestLogger(t)
+	supervisor, err := newSupervisor(bundle, nil, nil, logger, nil)
 	require.NoError(t, err)
 	require.NotNil(t, supervisor)
 	defer supervisor.Shutdown()

server/public/plugin/supervisor_test.go

@@ -34,9 +34,8 @@ func testSupervisorInvalidExecutablePath(t *testing.T) {
 	os.WriteFile(filepath.Join(dir, "plugin.json"), []byte(`{"id": "foo", "server": {"executable": "/foo/../../backend.exe"}}`), 0600)
 
 	bundle := model.BundleInfoForPath(dir)
-	log := mlog.CreateConsoleTestLogger(true, mlog.LvlError)
-	defer log.Shutdown()
-	supervisor, err := newSupervisor(bundle, nil, nil, log, nil)
+	logger := mlog.CreateConsoleTestLogger(t)
+	supervisor, err := newSupervisor(bundle, nil, nil, logger, nil)
 	assert.Nil(t, supervisor)
 	assert.Error(t, err)
 }
@@ -49,9 +48,8 @@ func testSupervisorNonExistentExecutablePath(t *testing.T) {
 	os.WriteFile(filepath.Join(dir, "plugin.json"), []byte(`{"id": "foo", "server": {"executable": "thisfileshouldnotexist"}}`), 0600)
 
 	bundle := model.BundleInfoForPath(dir)
-	log := mlog.CreateConsoleTestLogger(true, mlog.LvlError)
-	defer log.Shutdown()
-	supervisor, err := newSupervisor(bundle, nil, nil, log, nil)
+	logger := mlog.CreateConsoleTestLogger(t)
+	supervisor, err := newSupervisor(bundle, nil, nil, logger, nil)
 	require.Error(t, err)
 	require.Nil(t, supervisor)
 }
@@ -75,9 +73,8 @@ func testSupervisorStartTimeout(t *testing.T) {
 	os.WriteFile(filepath.Join(dir, "plugin.json"), []byte(`{"id": "foo", "server": {"executable": "backend.exe"}}`), 0600)
 
 	bundle := model.BundleInfoForPath(dir)
-	log := mlog.CreateConsoleTestLogger(true, mlog.LvlError)
-	defer log.Shutdown()
-	supervisor, err := newSupervisor(bundle, nil, nil, log, nil)
+	logger := mlog.CreateConsoleTestLogger(t)
+	supervisor, err := newSupervisor(bundle, nil, nil, logger, nil)
 	require.Error(t, err)
 	require.Nil(t, supervisor)
 }

server/public/shared/mlog/mlog.go

@@ -40,6 +40,7 @@ type LoggerIFace interface {
 	LogM([]Level, string, ...Field)
 	With(fields ...Field) *Logger
 	Flush() error
+	Sugar(fields ...Field) Sugar
 	StdLogger(level Level) *log.Logger
 }
 

server/public/shared/mlog/tlog.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"os"
 	"sync"
+	"testing"
 
 	"github.com/mattermost/logr/v2"
 	"github.com/mattermost/logr/v2/formatters"
@@ -33,26 +34,66 @@ func AddWriterTarget(logger *Logger, w io.Writer, useJSON bool, levels ...Level)
 }
 
 // CreateConsoleTestLogger creates a logger for unit tests. Log records are output to `os.Stdout`.
-// Logs can also be mirrored to the optional `io.Writer`.
-func CreateConsoleTestLogger(useJSON bool, level Level) *Logger {
-	logger, _ := NewLogger()
+// All log messages with level trace or lower are logged.
+// The returned logger get Shutdown() when the tests completes. The caller should not shut it down.
+func CreateConsoleTestLogger(tb testing.TB) *Logger {
+	tb.Helper()
+
+	logger, err := NewLogger()
+	if err != nil {
+		tb.Fatalf("failed create logger %v", err)
+	}
 
 	filter := logr.StdFilter{
-		Lvl:        level,
+		Lvl:        LvlTrace,
 		Stacktrace: LvlPanic,
 	}
-
-	var formatter logr.Formatter
-	if useJSON {
-		formatter = &formatters.JSON{EnableCaller: true}
-	} else {
-		formatter = &formatters.Plain{EnableCaller: true}
-	}
+	formatter := &formatters.Plain{EnableCaller: true}
 
 	target := targets.NewWriterTarget(os.Stdout)
 	if err := logger.log.Logr().AddTarget(target, "_testcon", filter, formatter, 1000); err != nil {
-		panic(err)
+		tb.Fatalf("failed to add target %v", err)
 	}
+
+	tb.Cleanup(func() {
+		err := logger.Shutdown()
+		if err != nil {
+			tb.Fatalf("failed to shut down test logger %v", err)
+		}
+	})
+
+	return logger
+}
+
+// CreateTestLogger creates a logger for unit tests. Log records are output via `t.Log`.
+// All log messages with level trace or lower are logged.
+// The returned logger get Shutdown() when the tests completes. The caller should not shut it down.
+func CreateTestLogger(t *testing.T) *Logger {
+	t.Helper()
+
+	logger, err := NewLogger()
+	if err != nil {
+		t.Fatalf("failed create logger %v", err)
+	}
+
+	filter := logr.StdFilter{
+		Lvl:        LvlTrace,
+		Stacktrace: LvlPanic,
+	}
+	formatter := &formatters.Plain{EnableCaller: true}
+	target := targets.NewTestingTarget(t)
+
+	if err := logger.log.Logr().AddTarget(target, "test", filter, formatter, 1000); err != nil {
+		t.Fatalf("failed to add target %v", err)
+	}
+
+	t.Cleanup(func() {
+		err := logger.Shutdown()
+		if err != nil {
+			t.Errorf("failed to shut down test logger %v", err)
+		}
+	})
+
 	return logger
 }
 

server/public/shared/request/context.go

@@ -26,12 +26,12 @@ type Context struct {
 	context context.Context
 }
 
-func NewContext(ctx context.Context, requestId, ipAddress, path, userAgent, acceptLanguage string, session model.Session, t i18n.TranslateFunc) *Context {
+func NewContext(ctx context.Context, requestId, ipAddress, xForwardedFor, path, userAgent, acceptLanguage string, t i18n.TranslateFunc) *Context {
 	return &Context{
 		t:              t,
-		session:        session,
 		requestId:      requestId,
 		ipAddress:      ipAddress,
+		xForwardedFor:  xForwardedFor,
 		path:           path,
 		userAgent:      userAgent,
 		acceptLanguage: acceptLanguage,