Reduced unnecessary debug logs from scheduled post job (#29560)

* Reduced unnecessery debug logs from scheduled post job

* Improved log

server/channels/app/scheduled_post_job.go

@@ -25,15 +25,12 @@ const (
 
 func (a *App) ProcessScheduledPosts(rctx request.CTX) {
 	rctx = rctx.WithLogger(rctx.Logger().With(mlog.String("component", "scheduled_post_job")))
-	rctx.Logger().Debug("ProcessScheduledPosts called...")
 
 	if !*a.Config().ServiceSettings.ScheduledPosts {
-		rctx.Logger().Debug("ProcessScheduledPosts exiting as the feature is turned off via ServiceSettings.ScheduledPosts setting...")
 		return
 	}
 
 	if a.License() == nil {
-		rctx.Logger().Debug("ProcessScheduledPosts exiting as no license is available")
 		return
 	}
 
@@ -44,7 +41,6 @@ func (a *App) ProcessScheduledPosts(rctx request.CTX) {
 	for {
 		// we wait some time before processing each batch to avoid hammering the database with too many requests.
 		time.Sleep(scheduledPostBatchWaitTime)
-		rctx.Logger().Debug("ProcessScheduledPosts: fetching page of pending scheduled posts...")
 
 		scheduledPostsBatch, err := a.Srv().Store().ScheduledPost().GetPendingScheduledPosts(beforeTime, afterTime, lastScheduledPostId, getPendingScheduledPostsPageSize)
 		if err != nil {
@@ -63,9 +59,7 @@ func (a *App) ProcessScheduledPosts(rctx request.CTX) {
 			break
 		}
 
-		rctx.Logger().Debug("ProcessScheduledPosts: entries found in page of pending scheduled posts", mlog.Int("entries", len(scheduledPostsBatch)))
 		if len(scheduledPostsBatch) == 0 {
-			rctx.Logger().Debug("ProcessScheduledPosts: skipping as there are no pending scheduled")
 			// break loop if there are no more scheduled posts
 			break
 		}
@@ -89,8 +83,6 @@ func (a *App) ProcessScheduledPosts(rctx request.CTX) {
 			continue
 		}
 
-		rctx.Logger().Debug("ProcessScheduledPosts: finished processing a page of pending scheduled posts.")
-
 		if len(scheduledPostsBatch) < getPendingScheduledPostsPageSize {
 			// if we got less than page size worth of scheduled posts, it indicates
 			// that we have no more pending scheduled posts. So, we can break instead of making
@@ -112,46 +104,37 @@ func (a *App) ProcessScheduledPosts(rctx request.CTX) {
 
 // processScheduledPostBatch processes one batch
 func (a *App) processScheduledPostBatch(rctx request.CTX, scheduledPosts []*model.ScheduledPost) error {
-	rctx.Logger().Debug("processScheduledPostBatch called...")
 	var failedScheduledPosts []*model.ScheduledPost
 	var successfulScheduledPostIDs []string
 
 	for i := range scheduledPosts {
-		rctx.Logger().Trace("processScheduledPostBatch processing scheduled post", mlog.String("scheduled_post_id", scheduledPosts[i].Id))
 		scheduledPost, err := a.postScheduledPost(rctx, scheduledPosts[i])
 		if err != nil {
-			rctx.Logger().Debug("processScheduledPostBatch scheduled post processing failed", mlog.String("scheduled_post_id", scheduledPosts[i].Id), mlog.Err(err))
+			rctx.Logger().Error("processScheduledPostBatch scheduled post processing failed", mlog.String("scheduled_post_id", scheduledPosts[i].Id), mlog.Err(err))
 			failedScheduledPosts = append(failedScheduledPosts, scheduledPost)
 			continue
 		}
 
-		rctx.Logger().Trace("processScheduledPostBatch scheduled post processing successful", mlog.String("scheduled_post_id", scheduledPosts[i].Id))
 		successfulScheduledPostIDs = append(successfulScheduledPostIDs, scheduledPost.Id)
 	}
 
-	rctx.Logger().Trace("processScheduledPostBatch handling successful scheduled posts...", mlog.Int("count", len(successfulScheduledPostIDs)))
 	if err := a.handleSuccessfulScheduledPosts(rctx, successfulScheduledPostIDs); err != nil {
 		return errors.Wrap(err, "App.processScheduledPostBatch: failed to handle successfully posted scheduled posts")
 	}
 
-	rctx.Logger().Trace("processScheduledPostBatch handling failed scheduled posts...", mlog.Int("count", len(failedScheduledPosts)))
 	a.handleFailedScheduledPosts(rctx, failedScheduledPosts)
-	rctx.Logger().Debug("processScheduledPostBatch finished...")
 	return nil
 }
 
 // postScheduledPost processes an individual scheduled post
 func (a *App) postScheduledPost(rctx request.CTX, scheduledPost *model.ScheduledPost) (*model.ScheduledPost, error) {
-	rctx.Logger().Debug("postScheduledPost called...", mlog.String("scheduled_post_id", scheduledPost.Id))
-
 	// we'll process scheduled posts one by one.
 	// If an error occurs, we'll log it and move onto the next scheduled post
 
-	rctx.Logger().Trace("postScheduledPost fetching channel for scheduled post", mlog.String("scheduled_post_id", scheduledPost.Id), mlog.String("channel_id", scheduledPost.ChannelId))
 	channel, appErr := a.GetChannel(rctx, scheduledPost.ChannelId)
 	if appErr != nil {
 		if appErr.StatusCode == http.StatusNotFound {
-			rctx.Logger().Debug("postScheduledPost channel for scheduled post not found, setting error code", mlog.String("scheduled_post_id", scheduledPost.Id), mlog.String("channel_id", scheduledPost.ChannelId), mlog.String("error_code", model.ScheduledPostErrorCodeChannelNotFound))
+			rctx.Logger().Warn("channel for scheduled post not found, setting error code", mlog.String("scheduled_post_id", scheduledPost.Id), mlog.String("channel_id", scheduledPost.ChannelId), mlog.String("error_code", model.ScheduledPostErrorCodeChannelNotFound), mlog.Err(appErr))
 
 			scheduledPost.ErrorCode = model.ScheduledPostErrorCodeChannelNotFound
 			return scheduledPost, nil
@@ -169,7 +152,6 @@ func (a *App) postScheduledPost(rctx request.CTX, scheduledPost *model.Scheduled
 		return scheduledPost, appErr
 	}
 
-	rctx.Logger().Trace("postScheduledPost checking if scheduled post can be posted", mlog.String("scheduled_post_id", scheduledPost.Id))
 	errorCode, err := a.canPostScheduledPost(rctx, scheduledPost, channel)
 	scheduledPost.ErrorCode = errorCode
 	if err != nil {
@@ -196,7 +178,6 @@ func (a *App) postScheduledPost(rctx request.CTX, scheduledPost *model.Scheduled
 		return scheduledPost, fmt.Errorf("App.processScheduledPostBatch: skipping posting a scheduled post as `can post` check failed, error_code: %s", scheduledPost.ErrorCode)
 	}
 
-	rctx.Logger().Trace("postScheduledPost converting scheduled post to post", mlog.String("scheduled_post_id", scheduledPost.Id))
 	post, err := scheduledPost.ToPost()
 	if err != nil {
 		rctx.Logger().Error(
@@ -210,7 +191,6 @@ func (a *App) postScheduledPost(rctx request.CTX, scheduledPost *model.Scheduled
 		return scheduledPost, err
 	}
 
-	rctx.Logger().Trace("postScheduledPost posting the scheduled post", mlog.String("scheduled_post_id", scheduledPost.Id))
 	createPostFlags := model.CreatePostFlags{
 		TriggerWebhooks: true,
 		SetOnline:       false,
@@ -237,8 +217,6 @@ func (a *App) postScheduledPost(rctx request.CTX, scheduledPost *model.Scheduled
 
 // canPostScheduledPost checks whether the scheduled post be created based on permissions and other checks.
 func (a *App) canPostScheduledPost(rctx request.CTX, scheduledPost *model.ScheduledPost, channel *model.Channel) (string, error) {
-	rctx.Logger().Trace("canPostScheduledPost called...", mlog.String("scheduled_post_id", scheduledPost.Id))
-
 	user, appErr := a.GetUser(scheduledPost.UserId)
 	if appErr != nil {
 		if appErr.Id == MissingAccountError {
@@ -327,7 +305,6 @@ func (a *App) canPostScheduledPost(rctx request.CTX, scheduledPost *model.Schedu
 		return model.ScheduledPostErrorInvalidPost, nil
 	}
 
-	rctx.Logger().Debug("canPostScheduledPost scheduled post can be posted", mlog.String("scheduled_post_id", scheduledPost.Id))
 	return "", nil
 }