mostlymatter/server/enterprise/message_export/worker.go

// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved.
// See LICENSE.enterprise for license information.

package message_export

import (
	"context"
	"errors"
	"fmt"
	"net/http"
	"path"
	"strconv"
	"sync"
	"time"

	"github.com/mattermost/mattermost/server/public/model"
	"github.com/mattermost/mattermost/server/public/shared/mlog"
	"github.com/mattermost/mattermost/server/public/shared/request"
	"github.com/mattermost/mattermost/server/v8/channels/jobs"
	"github.com/mattermost/mattermost/server/v8/channels/utils/fileutils"
	"github.com/mattermost/mattermost/server/v8/enterprise/message_export/shared"
	"github.com/mattermost/mattermost/server/v8/platform/shared/templates"
)

const TimeBetweenBatchesMs = 100

// testEndOfBatchCb is only used for testing
var testEndOfBatchCb func(worker *MessageExportWorker)

type MessageExportWorker struct {
	name string
	// stateMut protects stopCh, cancel, and stopped and helps enforce
	// ordering in case subsequent Run or Stop calls are made.
	stateMut            sync.Mutex
	stopCh              chan struct{}
	stopped             bool
	stoppedCh           chan struct{}
	jobs                chan model.Job
	jobServer           *jobs.JobServer
	logger              mlog.LoggerIFace
	htmlTemplateWatcher *templates.Container
	license             func() *model.License

	context context.Context
	cancel  func()
}

func (dr *MessageExportJobInterfaceImpl) MakeWorker() model.Worker {
	const workerName = "MessageExportWorker"
	logger := dr.Server.Jobs.Logger().With(mlog.String("worker_name", workerName))

	templatesDir, ok := fileutils.FindDir("templates")
	if !ok {
		logger.Error("Failed to initialize HTMLTemplateWatcher, templates directory not found")
		return nil
	}
	htmlTemplateWatcher, err := templates.New(templatesDir)
	if err != nil {
		logger.Error("Failed to initialize HTMLTemplateWatcher", mlog.Err(err))
		return nil
	}

	ctx, cancel := context.WithCancel(context.Background())

	return &MessageExportWorker{
		name:                workerName,
		stoppedCh:           make(chan struct{}, 1),
		jobs:                make(chan model.Job),
		jobServer:           dr.Server.Jobs,
		logger:              logger,
		htmlTemplateWatcher: htmlTemplateWatcher,
		// It is not a best practice to store context inside a struct,
		// however we need to cancel a SQL query during a job execution.
		// There is no other good way.
		context: ctx,
		cancel:  cancel,
		license: dr.Server.License,
		stopped: true,
	}
}

func (w *MessageExportWorker) IsEnabled(cfg *model.Config) bool {
	return w.license() != nil && *w.license().Features.MessageExport && *cfg.MessageExportSettings.EnableExport
}

func (w *MessageExportWorker) Run() {
	w.stateMut.Lock()
	// We have to re-assign the stop channel again, because
	// it might happen that the job was restarted due to a config change.
	if w.stopped {
		w.stopped = false
		w.stopCh = make(chan struct{})
		w.context, w.cancel = context.WithCancel(context.Background())
	} else {
		w.stateMut.Unlock()
		return
	}
	// Run is called from a separate goroutine and doesn't return.
	// So we cannot Unlock in a defer clause.
	w.stateMut.Unlock()

	w.logger.Debug("Worker Started")

	defer func() {
		w.logger.Debug("Worker finished")
		w.stoppedCh <- struct{}{}
	}()

	for {
		select {
		case <-w.stopCh:
			w.logger.Debug("Worker: Received stop signal")
			return
		case job := <-w.jobs:
			w.DoJob(&job)
		}
	}
}

func (w *MessageExportWorker) Stop() {
	w.stateMut.Lock()
	defer w.stateMut.Unlock()

	// Set to close, and if already closed before, then return.
	if w.stopped {
		return
	}
	w.stopped = true

	w.logger.Debug("Worker: Stopping")
	w.cancel()
	close(w.stopCh)
	<-w.stoppedCh
}

func (w *MessageExportWorker) JobChannel() chan<- model.Job {
	return w.jobs
}

func (w *MessageExportWorker) DoJob(job *model.Job) {
	logger := w.logger.With(jobs.JobLoggerFields(job)...)
	logger.Debug("Worker: Received a new candidate job.")
	defer w.jobServer.HandleJobPanic(logger, job)

	claimed, appErr := w.jobServer.ClaimJob(job)
	if appErr != nil {
		logger.Info("Worker: Error occurred while trying to claim job", mlog.Err(appErr))
		return
	}

	if !claimed {
		return
	}

	var cancelContext request.CTX = request.EmptyContext(w.logger)
	cancelCtx, cancelCancelWatcher := context.WithCancel(context.Background())
	cancelWatcherChan := make(chan struct{}, 1)
	cancelContext = cancelContext.WithContext(cancelCtx)
	go w.jobServer.CancellationWatcher(cancelContext, job.Id, cancelWatcherChan)
	defer cancelCancelWatcher()

	// if job data is missing, we'll do our best to recover
	w.initJobData(logger, job, time.Now())
	data, err := extractJobData(logger, job.Data)
	if err != nil {
		// Error in conversion. Not much we can do about that. But it shouldn't happen, unless someone edited the db.
		w.setJobError(logger, job, model.NewAppError("Job.DoJob", "ent.message_export.job_data_conversion.app_error", nil, "", http.StatusBadRequest).Wrap(err))
		return
	}

	rctx := request.EmptyContext(logger).WithContext(w.context)
	reportProgress := func(message string) {
		logger.Debug(message)
		// Don't fail because we couldn't update progress.
		w.setJobProgressMessage(0, message, rctx.Logger(), job)
	}

	jobParams := shared.BackendParams{
		Config:        w.jobServer.Config(),
		Store:         shared.NewMessageExportStore(w.jobServer.Store),
		HtmlTemplates: w.htmlTemplateWatcher,
	}
	jobParams.FileAttachmentBackend, err = shared.GetFileAttachmentBackend(rctx, w.jobServer.Config())
	if err != nil {
		w.setJobError(logger, job, model.NewAppError("GetFileAttachmentBackend", "api.file.no_driver.app_error", nil, "", http.StatusInternalServerError).Wrap(err))
		return
	}
	jobParams.ExportBackend, err = shared.GetExportBackend(rctx, w.jobServer.Config())
	if err != nil {
		w.setJobError(logger, job, model.NewAppError("GetExportBackend", "api.file.no_driver.app_error", nil, "", http.StatusInternalServerError).Wrap(err))
		return
	}

	data, err = shared.GetInitialExportPeriodData(rctx, jobParams.Store, data, reportProgress)
	if err != nil {
		w.setJobError(logger, job, model.NewAppError("DoJob", "ent.message_export.calculate_channel_exports.app_error", nil, "", http.StatusInternalServerError).Wrap(err))
		return
	}
	job.Data[shared.JobDataTotalPostsExpected] = strconv.Itoa(data.TotalPostsExpected)

	for {
		select {
		case <-cancelWatcherChan:
			logger.Debug("Worker: Job has been canceled via CancellationWatcher")
			w.setJobCanceled(logger, job)
			return

		case <-w.stopCh:
			logger.Debug("Worker: Job has been canceled via Worker Stop. Setting the job back to pending")
			w.SetJobPending(logger, job)
			return

		case <-time.After(TimeBetweenBatchesMs * time.Millisecond):
			logger.Debug("Starting batch export", mlog.Int("last_post_update_at", data.Cursor.LastPostUpdateAt))

			_, data, err = RunBatch(rctx, data, jobParams)
			if err != nil {
				// We ignore error if the job was explicitly cancelled
				if errors.Is(w.context.Err(), context.Canceled) {
					logger.Debug("Worker: Job has been canceled via worker's context. Setting the job back to pending")
					w.SetJobPending(logger, job)
				} else {
					w.setJobError(logger, job, model.NewAppError("DoJob", "ent.message_export.run_export.app_error", nil, "", http.StatusInternalServerError).Wrap(err))
				}
				return
			}

			setJobDataEndOfBatch(job, data)

			if data.Finished {
				w.finishExport(rctx, logger, job, data.WarningCount)
				return
			}

			// also saves job.Data
			if err := w.setJobProgress(logger, job, getJobProgress(data.MessagesExported, data.TotalPostsExpected)); err != nil {
				// TODO: MM-59093 handle job errors (robust, recoverable)
				return
			}

			// testEndOfBatchCb is only used by tests.
			if testEndOfBatchCb != nil {
				testEndOfBatchCb(w)
			}
		}
	}
}

func (w *MessageExportWorker) finishExport(rctx request.CTX, logger *mlog.Logger, job *model.Job, totalWarningCount int) {
	job.Data[shared.JobDataWarningCount] = strconv.Itoa(totalWarningCount)
	// we've exported everything up to the current time
	logger.Debug("FormatExport complete")

	job.Data[shared.JobDataIsDownloadable] = "false"

	if totalWarningCount > 0 {
		w.setJobWarning(logger, job)
	} else {
		w.setJobSuccess(logger, job)
	}
}

// initializes job data if it's missing, allows us to recover from failed or improperly configured jobs
func (w *MessageExportWorker) initJobData(logger mlog.LoggerIFace, job *model.Job, now time.Time) {
	if job.Data == nil {
		job.Data = make(map[string]string)
	}
	if _, exists := job.Data[shared.JobDataMessagesExported]; !exists {
		logger.Info("Worker: JobDataMessagesExported does not exist, starting at 0")
		job.Data[shared.JobDataMessagesExported] = "0"
	}
	if _, exists := job.Data[shared.JobDataExportType]; !exists {
		exportFormat := *w.jobServer.Config().MessageExportSettings.ExportFormat
		logger.Info("Worker: Defaulting to configured export format", mlog.String("export_format", exportFormat))
		job.Data[shared.JobDataExportType] = exportFormat
	}
	if _, exists := job.Data[shared.JobDataBatchSize]; !exists {
		batchSize := strconv.Itoa(*w.jobServer.Config().MessageExportSettings.BatchSize)
		logger.Info("Worker: Defaulting to configured batch size", mlog.String("batch_size", batchSize))
		job.Data[shared.JobDataBatchSize] = batchSize
	}
	if _, exists := job.Data[shared.JobDataChannelBatchSize]; !exists {
		channelBatchSize := strconv.Itoa(*w.jobServer.Config().MessageExportSettings.ChannelBatchSize)
		logger.Info("Worker: Defaulting to configured channel batch size", mlog.String("channel_batch_size", channelBatchSize))
		job.Data[shared.JobDataChannelBatchSize] = channelBatchSize
	}
	if _, exists := job.Data[shared.JobDataChannelHistoryBatchSize]; !exists {
		channelHistoryBatchSize := strconv.Itoa(*w.jobServer.Config().MessageExportSettings.ChannelHistoryBatchSize)
		logger.Info("Worker: Defaulting to configured channel history batch size", mlog.String("channel_history_batch_size", channelHistoryBatchSize))
		job.Data[shared.JobDataChannelHistoryBatchSize] = channelHistoryBatchSize
	}
	if _, exists := job.Data[shared.JobDataBatchNumber]; !exists {
		logger.Info("Worker: JobDataBatchNumber does not exist, starting at 0")
		job.Data[shared.JobDataBatchNumber] = "0"
	}

	// If this is a new job (JobEndTime doesn't exist), set it to now, because this is when the job has first started.
	// The logic is that a job exports messages up to the moment the job was started. If the job was picked up after
	// gracefully stopping, then run it until that original initial endTime.
	// However, if the job was cancelled or errored out, that job will not be picked up again, so this will be a new job
	// starting from the last successful batchStartTimestamp up until now. This is intentional (for now) because failed
	// jobs do not get rescheduled properly yet, and when they are run again it means that new day's worth of messages
	// need to be exported.
	if _, exists := job.Data[shared.JobDataJobEndTime]; !exists {
		millis := strconv.FormatInt(model.GetMillisForTime(now), 10)
		logger.Info("Worker: JobDataJobEndTime not found in previous job, using now", mlog.String("job_data_job_end_time", millis))
		job.Data[shared.JobDataJobEndTime] = millis
	}

	if _, exists := job.Data[shared.JobDataBatchStartTime]; !exists {
		previousJob, err := w.jobServer.Store.Job().GetNewestJobByStatusesAndType([]string{model.JobStatusWarning, model.JobStatusSuccess}, model.JobTypeMessageExport)
		if err != nil {
			exportFromTimestamp := strconv.FormatInt(*w.jobServer.Config().MessageExportSettings.ExportFromTimestamp, 10)
			logger.Info("Worker: No previously successful job found, falling back to configured MessageExportSettings.ExportFromTimestamp", mlog.String("export_from_timestamp", exportFromTimestamp))
			job.Data[shared.JobDataBatchStartTime] = exportFromTimestamp
			job.Data[shared.JobDataJobStartTime] = exportFromTimestamp
			job.Data[shared.JobDataBatchStartId] = ""
			job.Data[shared.JobDataJobStartId] = job.Data[shared.JobDataBatchStartId]
			job.Data[shared.JobDataExportDir] = getJobExportDir(logger, job.Data, exportFromTimestamp, job.Data[shared.JobDataJobEndTime])
			return
		}

		logger.Info("Worker: Implicitly resuming export from where previously successful job left off")
		if previousJob == nil {
			previousJob = &model.Job{}
		}
		if previousJob.Data == nil {
			previousJob.Data = make(map[string]string)
		}
		if _, prevExists := previousJob.Data[shared.JobDataBatchStartTime]; !prevExists {
			exportFromTimestamp := strconv.FormatInt(*w.jobServer.Config().MessageExportSettings.ExportFromTimestamp, 10)
			logger.Info("Worker: Previously successful job lacks job data, falling back to configured MessageExportSettings.ExportFromTimestamp", mlog.String("export_from_timestamp", exportFromTimestamp))
			job.Data[shared.JobDataBatchStartTime] = exportFromTimestamp
			job.Data[shared.JobDataJobStartTime] = exportFromTimestamp
		} else {
			job.Data[shared.JobDataBatchStartTime] = previousJob.Data[shared.JobDataBatchStartTime]
		}
		if _, prevExists := previousJob.Data[shared.JobDataBatchStartId]; !prevExists {
			logger.Info("Worker: Previously successful job lacks post ID, falling back to empty string")
			job.Data[shared.JobDataBatchStartId] = ""
		} else {
			job.Data[shared.JobDataBatchStartId] = previousJob.Data[shared.JobDataBatchStartId]
		}
		job.Data[shared.JobDataJobStartId] = job.Data[shared.JobDataBatchStartId]
	} else {
		logger.Info("Worker: JobDataBatchStartTime start time was already set",
			mlog.String(shared.JobDataBatchStartTime, job.Data[shared.JobDataBatchStartTime]))
	}

	if _, exists := job.Data[shared.JobDataJobStartTime]; !exists {
		// Just in case, if we don't have this (JobDataBatchStartTime was already set, but this wasn't) set it:
		job.Data[shared.JobDataJobStartTime] = job.Data[shared.JobDataBatchStartTime]
		logger.Info("Worker: JobDataJobStartTime start time was not set, using batch startTimestamp",
			mlog.String(shared.JobDataJobStartTime, job.Data[shared.JobDataJobStartTime]))
	}

	job.Data[shared.JobDataExportDir] = getJobExportDir(logger, job.Data, job.Data[shared.JobDataJobStartTime], job.Data[shared.JobDataJobEndTime])
}

func extractJobData(logger *mlog.Logger, strmap map[string]string) (shared.JobData, error) {
	data, err := shared.StringMapToJobDataWithZeroValues(strmap)
	if err != nil {
		return data, err
	}

	// ExportPeriodStartTime is initialized to BatchStartTime because this is where we will start exporting. But unlike
	// BatchStartTime, it won't change as we process the batches.
	// If this is the first time this job has run, BatchStartTime will be the start of the entire job. If this job has
	// been resumed, then BatchStartTime will be the start of the newest batch. This is expected--the channel activity
	// and total posts will be calculated from ExportPeriodStartTime (anything earlier has already been exported in
	// previous batches).
	// Note: ExportPeriodStartTime is different from JobStartTime because JobStartTime won't change
	//	     if the job processes some batches, is stopped, and picked up again.
	data.ExportPeriodStartTime = data.BatchStartTime

	logger.Info("Worker: initial job variables set",
		mlog.String("export_type", data.ExportType),
		mlog.String("export_dir", data.ExportDir),
		mlog.Int("job_start_time", data.JobStartTime),
		mlog.Int("batch_start_time", data.BatchStartTime),
		mlog.Int("export_period_start_time", data.ExportPeriodStartTime),
		mlog.Int("job_end_time", data.JobEndTime),
		mlog.String("job_start_id", data.JobStartId),
		mlog.Int("batch_size", data.BatchSize),
		mlog.Int("channel_batch_size", data.ChannelBatchSize),
		mlog.Int("channel_history_batch_size", data.ChannelHistoryBatchSize),
		mlog.Int("batch_number", data.BatchNumber),
		mlog.Int("total_posts_exported", data.MessagesExported))

	return data, err
}

func setJobDataEndOfBatch(job *model.Job, data shared.JobData) {
	job.Data[shared.JobDataBatchStartTime] = strconv.FormatInt(data.BatchStartTime, 10)
	job.Data[shared.JobDataBatchStartId] = data.Cursor.LastPostId
	job.Data[shared.JobDataMessagesExported] = strconv.Itoa(data.MessagesExported)
	job.Data[shared.JobDataBatchNumber] = strconv.Itoa(data.BatchNumber)
}

// getJobExportDir will use the existing JobDataExportDir if available. If it's not available, this is the first run
// for the job, so we use the startTime and endTime passed in.
func getJobExportDir(logger mlog.LoggerIFace, data model.StringMap, startTime string, endTime string) string {
	exportDir, exists := data[shared.JobDataExportDir]
	if !exists {
		// If we don't have a jobDataExportDir, this is the first run for the job, so we use the batch startTime
		exportDir = path.Join(model.ComplianceExportPath, fmt.Sprintf("%s-%s-%s", time.Now().Format(model.ComplianceExportDirectoryFormat), startTime, endTime))
		logger.Info("Worker: JobDataExportDir does not exist, using current datetime", mlog.String("job_data_export_dir", exportDir))
	}

	return exportDir
}

func getJobProgress(totalExportedPosts, totalPostsExpected int) int {
	return totalExportedPosts * 100 / totalPostsExpected
}

func (w *MessageExportWorker) setJobProgressMessage(progress int64, message string, logger mlog.LoggerIFace, job *model.Job) {
	job.Status = model.JobStatusInProgress
	job.Progress = progress
	if job.Data == nil {
		job.Data = make(map[string]string)
	}
	job.Data["progress_message"] = message

	if _, err := w.jobServer.Store.Job().UpdateOptimistically(job, model.JobStatusInProgress); err != nil {
		logger.Error("Worker: Failed to update progress for job", mlog.Err(err))
	}
}

func (w *MessageExportWorker) setJobProgress(logger mlog.LoggerIFace, job *model.Job, progress int) error {
	if job.Data != nil {
		job.Data["progress_message"] = ""
	}

	if err := w.jobServer.SetJobProgress(job, int64(progress)); err != nil {
		logger.Error("Worker: Failed to update progress for job", mlog.Err(err))
		w.setJobError(logger, job, err)
		return err
	}

	return nil
}

func (w *MessageExportWorker) setJobSuccess(logger mlog.LoggerIFace, job *model.Job) {
	// setting progress causes the job data to be saved, which is necessary if we want the next job to pick up where this one left off
	if job.Data != nil {
		job.Data["progress_message"] = ""
	}
	if err := w.jobServer.SetJobProgress(job, 100); err != nil {
		logger.Error("Worker: Failed to update progress for job", mlog.Err(err))
		w.setJobError(logger, job, err)
	}
	if err := w.jobServer.SetJobSuccess(job); err != nil {
		logger.Error("Worker: Failed to set success for job", mlog.Err(err))
		w.setJobError(logger, job, err)
	}
}

func (w *MessageExportWorker) setJobWarning(logger mlog.LoggerIFace, job *model.Job) {
	// setting progress causes the job data to be saved, which is necessary if we want the next job to pick up where this one left off
	if job.Data != nil {
		job.Data["progress_message"] = ""
	}
	if err := w.jobServer.SetJobProgress(job, 100); err != nil {
		logger.Error("Worker: Failed to update progress for job", mlog.Err(err))
		w.setJobError(logger, job, err)
	}
	if err := w.jobServer.SetJobWarning(job); err != nil {
		logger.Error("Worker: Failed to set warning for job", mlog.Err(err))
		w.setJobError(logger, job, err)
	}
}

func (w *MessageExportWorker) setJobError(logger mlog.LoggerIFace, job *model.Job, appError *model.AppError) {
	if job.Data != nil {
		job.Data["progress_message"] = ""
	}
	logger.Error("Worker: Job error", mlog.Err(appError))
	if err := w.jobServer.SetJobError(job, appError); err != nil {
		logger.Error("Worker: Failed to set job error", mlog.Err(err), mlog.NamedErr("set_error", appError))
	}
}

func (w *MessageExportWorker) setJobCanceled(logger mlog.LoggerIFace, job *model.Job) {
	if job.Data != nil {
		job.Data["progress_message"] = ""
	}
	if err := w.jobServer.SetJobCanceled(job); err != nil {
		logger.Error("Worker: Failed to mark job as canceled", mlog.Err(err))
	}
}

func (w *MessageExportWorker) SetJobPending(logger mlog.LoggerIFace, job *model.Job) {
	if job.Data != nil {
		job.Data["progress_message"] = ""
	}
	if err := w.jobServer.SetJobPending(job); err != nil {
		logger.Error("Worker: Failed to mark job as pending", mlog.Err(err))
	}
}