[MM-56757] Expand NotificationsLog to include websocket and email, adding much more varied logging across the entire process (#26273)

* [MM-56757] Expand NotificationsLog to include websocket and email, adding much more varied logging across the entire process

* Rework the status/notify prop calls

* Avoid some repetition in the logging calls

* Fix one log

* Wrap error

---------

Co-authored-by: Mattermost Build <build@mattermost.com>

server/channels/app/app_iface.go

@@ -1120,6 +1120,7 @@ type AppIface interface {
 	SetTeamIconFromFile(team *model.Team, file io.Reader) *model.AppError
 	SetTeamIconFromMultiPartFile(teamID string, file multipart.File) *model.AppError
 	ShareChannel(c request.CTX, sc *model.SharedChannel) (*model.SharedChannel, error)
+	ShouldSendPushNotification(user *model.User, channelNotifyProps model.StringMap, wasMentioned bool, status *model.Status, post *model.Post, isGM bool) bool
 	SlackImport(c request.CTX, fileData multipart.File, fileSize int64, teamID string) (*model.AppError, *bytes.Buffer)
 	SoftDeleteTeam(teamID string) *model.AppError
 	Srv() *Server

server/channels/app/expirynotify.go

@@ -24,6 +24,12 @@ func (a *App) NotifySessionsExpired() error {
 	// Get all mobile sessions that expired within the last hour.
 	sessions, err := a.ch.srv.Store().Session().GetSessionsExpired(OneHourMillis, true, true)
 	if err != nil {
+		a.NotificationsLog().Error("Cannot get sessions expired",
+			mlog.String("type", model.TypePush),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonFetchError),
+			mlog.Err(err),
+		)
 		return model.NewAppError("NotifySessionsExpired", "app.session.analytics_session_count.app_error", nil, "", http.StatusInternalServerError).Wrap(err)
 	}
 
@@ -40,21 +46,25 @@ func (a *App) NotifySessionsExpired() error {
 
 		errPush := a.sendToPushProxy(tmpMessage, session)
 		if errPush != nil {
-			a.NotificationsLog().Error("Notification error",
-				mlog.String("ackId", tmpMessage.AckId),
-				mlog.String("type", tmpMessage.Type),
-				mlog.String("userId", session.UserId),
-				mlog.String("deviceId", tmpMessage.DeviceId),
-				mlog.String("status", errPush.Error()),
+			a.NotificationsLog().Error("Failed to send to push proxy",
+				mlog.String("type", model.TypePush),
+				mlog.String("status", model.StatusNotSent),
+				mlog.String("reason", model.ReasonPushProxyError),
+				mlog.String("ack_id", tmpMessage.AckId),
+				mlog.String("push_type", tmpMessage.Type),
+				mlog.String("user_id", session.UserId),
+				mlog.String("device_id", tmpMessage.DeviceId),
+				mlog.Err(errPush),
 			)
 			continue
 		}
 
-		a.NotificationsLog().Info("Notification sent",
-			mlog.String("ackId", tmpMessage.AckId),
-			mlog.String("type", tmpMessage.Type),
-			mlog.String("userId", session.UserId),
-			mlog.String("deviceId", tmpMessage.DeviceId),
+		a.NotificationsLog().Trace("Notification sent to push proxy",
+			mlog.String("type", model.TypePush),
+			mlog.String("ack_id", tmpMessage.AckId),
+			mlog.String("push_type", tmpMessage.Type),
+			mlog.String("user_id", session.UserId),
+			mlog.String("device_id", tmpMessage.DeviceId),
 			mlog.String("status", model.PushSendSuccess),
 		)
 

server/channels/app/notification.go

@@ -23,11 +23,19 @@ import (
 
 func (a *App) canSendPushNotifications() bool {
 	if !*a.Config().EmailSettings.SendPushNotifications {
+		a.NotificationsLog().Debug("Push notifications are disabled - server config",
+			mlog.String("status", model.StatusBlocked),
+			mlog.String("reason", model.ReasonServerConfig),
+		)
 		return false
 	}
 
 	pushServer := *a.Config().EmailSettings.PushNotificationServer
 	if license := a.Srv().License(); pushServer == model.MHPNS && (license == nil || !*license.Features.MHPNS) {
+		a.NotificationsLog().Info("Push notifications are disabled - license missing",
+			mlog.String("status", model.StatusBlocked),
+			mlog.String("reason", model.ReasonServerConfig),
+		)
 		mlog.Warn("Push notifications have been disabled. Update your license or go to System Console > Environment > Push Notification Server to use a different server")
 		return false
 	}
@@ -89,12 +97,26 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 
 	pResult := <-pchan
 	if pResult.NErr != nil {
+		a.NotificationsLog().Error("Error fetching profiles",
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonFetchError),
+			mlog.Err(pResult.NErr),
+		)
 		return nil, pResult.NErr
 	}
 	profileMap := pResult.Data
 
 	cmnResult := <-cmnchan
 	if cmnResult.NErr != nil {
+		a.NotificationsLog().Error("Error fetching notify props",
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonFetchError),
+			mlog.Err(cmnResult.NErr),
+		)
 		return nil, cmnResult.NErr
 	}
 	channelMemberNotifyPropsMap := cmnResult.Data
@@ -103,6 +125,13 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 	if tchan != nil {
 		tResult := <-tchan
 		if tResult.NErr != nil {
+			a.NotificationsLog().Error("Error fetching thread followers",
+				mlog.String("sender_id", sender.Id),
+				mlog.String("post_id", post.Id),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonFetchError),
+				mlog.Err(tResult.NErr),
+			)
 			return nil, tResult.NErr
 		}
 		for _, v := range tResult.Data {
@@ -114,11 +143,23 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 	if gchan != nil {
 		gResult := <-gchan
 		if gResult.NErr != nil {
+			a.NotificationsLog().Error("Error fetching group mentions",
+				mlog.String("sender_id", sender.Id),
+				mlog.String("post_id", post.Id),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonFetchError),
+				mlog.Err(gResult.NErr),
+			)
 			return nil, gResult.NErr
 		}
 		groups = gResult.Data
 	}
 
+	a.NotificationsLog().Trace("Successfully fetched all profiles",
+		mlog.String("sender_id", sender.Id),
+		mlog.String("post_id", post.Id),
+	)
+
 	mentions, keywords := a.getExplicitMentionsAndKeywords(c, post, channel, profileMap, groups, channelMemberNotifyPropsMap, parentPostList)
 
 	var allActivityPushUserIds []string
@@ -128,6 +169,13 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 			group := groups[groupID]
 			anyUsersMentionedByGroup, err := a.insertGroupMentions(sender.Id, group, channel, profileMap, mentions)
 			if err != nil {
+				a.NotificationsLog().Error("Failed to populate group mentions",
+					mlog.String("sender_id", sender.Id),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusServerError),
+					mlog.String("reason", model.ReasonFetchError),
+					mlog.Err(err),
+				)
 				return nil, err
 			}
 
@@ -139,6 +187,13 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 		go func() {
 			_, err := a.sendOutOfChannelMentions(c, sender, post, channel, mentions.OtherPotentialMentions)
 			if err != nil {
+				a.NotificationsLog().Warn("Failed to send warning for out of channel mentions",
+					mlog.String("sender_id", sender.Id),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusServerError),
+					mlog.String("reason", model.ReasonServerError),
+					mlog.Err(err),
+				)
 				c.Logger().Error("Failed to send warning for out of channel mentions", mlog.String("user_id", sender.Id), mlog.String("post_id", post.Id), mlog.Err(err))
 			}
 		}()
@@ -270,6 +325,11 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 		)
 	}
 
+	a.NotificationsLog().Trace("Finished processing mentions",
+		mlog.String("sender_id", sender.Id),
+		mlog.String("post_id", post.Id),
+	)
+
 	// Log the problems that might have occurred while auto following the thread
 	for _, mac := range mentionAutofollowChans {
 		if err := <-mac; err != nil {
@@ -307,16 +367,37 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 	}
 
 	if *a.Config().EmailSettings.SendEmailNotifications {
+		a.NotificationsLog().Trace("Begin sending email notifications",
+			mlog.String("type", model.TypeEmail),
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+		)
 		emailRecipients := append(mentionedUsersList, notificationsForCRT.Email...)
 		emailRecipients = model.RemoveDuplicateStrings(emailRecipients)
 
 		for _, id := range emailRecipients {
 			if profileMap[id] == nil {
+				a.NotificationsLog().Warn("Missing profile",
+					mlog.String("type", model.TypeEmail),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonMissingProfile),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", id),
+				)
 				continue
 			}
 
 			//If email verification is required and user email is not verified don't send email.
 			if *a.Config().EmailSettings.RequireEmailVerification && !profileMap[id].EmailVerified {
+				a.NotificationsLog().Debug("Email not verified",
+					mlog.String("type", model.TypeEmail),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonUserConfig),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", id),
+				)
 				c.Logger().Debug("Skipped sending notification email, address not verified.", mlog.String("user_email", profileMap[id].Email), mlog.String("user_id", id))
 				continue
 			}
@@ -327,14 +408,45 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 					a.Log().Warn("Unable to get the sender user profile image.", mlog.String("user_id", sender.Id), mlog.Err(err))
 				}
 				if err := a.sendNotificationEmail(c, notification, profileMap[id], team, senderProfileImage); err != nil {
+					a.NotificationsLog().Warn("Error sending email notification",
+						mlog.String("type", model.TypeEmail),
+						mlog.String("post_id", post.Id),
+						mlog.String("status", model.StatusNotSent),
+						mlog.String("reason", model.ReasonServerError),
+						mlog.String("sender_id", sender.Id),
+						mlog.String("receiver_id", id),
+						mlog.Err(err),
+					)
 					c.Logger().Warn("Unable to send notification email.", mlog.Err(err))
 				}
+			} else {
+				a.NotificationsLog().Debug("Email disallowed by user",
+					mlog.String("type", model.TypeEmail),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonUserConfig),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", id),
+				)
 			}
 		}
+
+		a.NotificationsLog().Trace("Finished sending email notifications",
+			mlog.String("type", model.TypeEmail),
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+		)
 	}
 
 	// Check for channel-wide mentions in channels that have too many members for those to work
 	if int64(len(profileMap)) > *a.Config().TeamSettings.MaxNotificationsPerChannel {
+		a.NotificationsLog().Debug("Too many users to notify - will send ephemeral message",
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusNotSent),
+			mlog.String("reason", model.ReasonServerConfig),
+		)
+
 		T := i18n.GetUserTranslations(sender.Locale)
 
 		if mentions.HereMentioned {
@@ -375,8 +487,32 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 	}
 
 	if a.canSendPushNotifications() {
+		a.NotificationsLog().Trace("Begin sending push notifications",
+			mlog.String("type", model.TypePush),
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+		)
+
 		for _, id := range mentionedUsersList {
-			if profileMap[id] == nil || notificationsForCRT.Push.Contains(id) {
+			if profileMap[id] == nil {
+				a.NotificationsLog().Warn("Missing profile",
+					mlog.String("type", model.TypePush),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonMissingProfile),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", id),
+				)
+				continue
+			}
+
+			if notificationsForCRT.Push.Contains(id) {
+				a.NotificationsLog().Trace("Skipped direct push notification - will send as CRT notification",
+					mlog.String("type", model.TypePush),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("sender_id", sender.Id),
+				)
 				continue
 			}
 
@@ -388,7 +524,7 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 
 			isExplicitlyMentioned := mentions.Mentions[id] > GMMention
 			isGM := channel.Type == model.ChannelTypeGroup
-			if ShouldSendPushNotification(profileMap[id], channelMemberNotifyPropsMap[id], isExplicitlyMentioned, status, post, isGM) {
+			if a.ShouldSendPushNotification(profileMap[id], channelMemberNotifyPropsMap[id], isExplicitlyMentioned, status, post, isGM) {
 				mentionType := mentions.Mentions[id]
 
 				replyToThreadType := ""
@@ -405,20 +541,29 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 					mentionType == ChannelMention,
 					replyToThreadType,
 				)
-			} else {
-				// register that a notification was not sent
-				a.NotificationsLog().Debug("Notification not sent",
-					mlog.String("ackId", ""),
-					mlog.String("type", model.PushTypeMessage),
-					mlog.String("userId", id),
-					mlog.String("postId", post.Id),
-					mlog.String("status", model.PushNotSent),
-				)
 			}
 		}
 
 		for _, id := range allActivityPushUserIds {
-			if profileMap[id] == nil || notificationsForCRT.Push.Contains(id) {
+			if profileMap[id] == nil {
+				a.NotificationsLog().Warn("Missing profile",
+					mlog.String("type", model.TypePush),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonMissingProfile),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", id),
+				)
+				continue
+			}
+
+			if notificationsForCRT.Push.Contains(id) {
+				a.NotificationsLog().Trace("Skipped direct push notification - will send as CRT notification",
+					mlog.String("type", model.TypePush),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("sender_id", sender.Id),
+				)
 				continue
 			}
 
@@ -430,7 +575,7 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 				}
 
 				isGM := channel.Type == model.ChannelTypeGroup
-				if ShouldSendPushNotification(profileMap[id], channelMemberNotifyPropsMap[id], false, status, post, isGM) {
+				if a.ShouldSendPushNotification(profileMap[id], channelMemberNotifyPropsMap[id], false, status, post, isGM) {
 					a.sendPushNotification(
 						notification,
 						profileMap[id],
@@ -438,21 +583,20 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 						false,
 						"",
 					)
-				} else {
-					// register that a notification was not sent
-					a.NotificationsLog().Debug("Notification not sent",
-						mlog.String("ackId", ""),
-						mlog.String("type", model.PushTypeMessage),
-						mlog.String("userId", id),
-						mlog.String("postId", post.Id),
-						mlog.String("status", model.PushNotSent),
-					)
 				}
 			}
 		}
 
 		for _, id := range notificationsForCRT.Push {
 			if profileMap[id] == nil {
+				a.NotificationsLog().Warn("Missing profile",
+					mlog.String("type", model.TypePush),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonMissingProfile),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", id),
+				)
 				continue
 			}
 
@@ -462,7 +606,7 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 				status = &model.Status{UserId: id, Status: model.StatusOffline, Manual: false, LastActivityAt: 0, ActiveChannel: ""}
 			}
 
-			if DoesStatusAllowPushNotification(profileMap[id].NotifyProps, status, post.ChannelId) {
+			if statusReason := DoesStatusAllowPushNotification(profileMap[id].NotifyProps, status, post.ChannelId); statusReason == "" {
 				a.sendPushNotification(
 					notification,
 					profileMap[id],
@@ -471,18 +615,32 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 					model.CommentsNotifyCRT,
 				)
 			} else {
-				// register that a notification was not sent
-				a.NotificationsLog().Debug("Notification not sent",
-					mlog.String("ackId", ""),
-					mlog.String("type", model.PushTypeMessage),
-					mlog.String("userId", id),
-					mlog.String("postId", post.Id),
-					mlog.String("status", model.PushNotSent),
+				a.NotificationsLog().Debug("Notification not sent - status",
+					mlog.String("type", model.TypePush),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonUserConfig),
+					mlog.String("status_reason", statusReason),
+					mlog.String("sender_id", post.UserId),
+					mlog.String("receiver_id", id),
+					mlog.String("receiver_status", status.Status),
 				)
 			}
 		}
+
+		a.NotificationsLog().Trace("Finished sending push notifications",
+			mlog.String("type", model.TypePush),
+			mlog.String("sender_id", sender.Id),
+			mlog.String("post_id", post.Id),
+		)
 	}
 
+	a.NotificationsLog().Trace("Begin sending websocket notifications",
+		mlog.String("type", model.TypeWebsocket),
+		mlog.String("sender_id", sender.Id),
+		mlog.String("post_id", post.Id),
+	)
+
 	message := model.NewWebSocketEvent(model.WebsocketEventPosted, "", post.ChannelId, "", nil, "")
 
 	message.Add("channel_type", channel.Type)
@@ -520,12 +678,28 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 
 	published, err := a.publishWebsocketEventForPermalinkPost(c, post, message)
 	if err != nil {
+		a.NotificationsLog().Error("Couldn't send websocket notification for permalink post",
+			mlog.String("type", model.TypeWebsocket),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonFetchError),
+			mlog.String("sender_id", sender.Id),
+			mlog.Err(err),
+		)
 		return nil, err
 	}
 	if !published {
 		removePermalinkMetadataFromPost(post)
 		postJSON, jsonErr := post.ToJSON()
 		if jsonErr != nil {
+			a.NotificationsLog().Error("JSON parse error",
+				mlog.String("type", model.TypeWebsocket),
+				mlog.String("post_id", post.Id),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonServerError),
+				mlog.String("sender_id", sender.Id),
+				mlog.Err(err),
+			)
 			return nil, errors.Wrapf(jsonErr, "failed to encode post to JSON")
 		}
 		message.Add("post", postJSON)
@@ -539,6 +713,14 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 			// A user following a thread but had left the channel won't get a notification
 			// https://mattermost.atlassian.net/browse/MM-36769
 			if profileMap[uid] == nil {
+				a.NotificationsLog().Warn("Missing profile",
+					mlog.String("type", model.TypeWebsocket),
+					mlog.String("post_id", post.Id),
+					mlog.String("status", model.StatusNotSent),
+					mlog.String("reason", model.ReasonMissingProfile),
+					mlog.String("sender_id", sender.Id),
+					mlog.String("receiver_id", uid),
+				)
 				continue
 			}
 			if a.IsCRTEnabledForUser(c, uid) {
@@ -547,15 +729,41 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 				if threadMembership == nil {
 					tm, err := a.Srv().Store().Thread().GetMembershipForUser(uid, post.RootId)
 					if err != nil {
+						a.NotificationsLog().Error("Missing thread membership",
+							mlog.String("type", model.TypeWebsocket),
+							mlog.String("post_id", post.Id),
+							mlog.String("status", model.StatusServerError),
+							mlog.String("reason", model.ReasonFetchError),
+							mlog.String("sender_id", sender.Id),
+							mlog.String("receiver_id", uid),
+							mlog.Err(err),
+						)
 						return nil, errors.Wrapf(err, "Missing thread membership for participant in notifications. user_id=%q thread_id=%q", uid, post.RootId)
 					}
 					if tm == nil {
+						a.NotificationsLog().Warn("Missing thread membership",
+							mlog.String("type", model.TypeWebsocket),
+							mlog.String("post_id", post.Id),
+							mlog.String("status", model.StatusNotSent),
+							mlog.String("reason", model.ReasonServerError),
+							mlog.String("sender_id", sender.Id),
+							mlog.String("receiver_id", uid),
+						)
 						continue
 					}
 					threadMembership = tm
 				}
 				userThread, err := a.Srv().Store().Thread().GetThreadForUser(threadMembership, true, a.IsPostPriorityEnabled())
 				if err != nil {
+					a.NotificationsLog().Error("Missing thread",
+						mlog.String("type", model.TypeWebsocket),
+						mlog.String("post_id", post.Id),
+						mlog.String("status", model.StatusServerError),
+						mlog.String("reason", model.ReasonFetchError),
+						mlog.String("sender_id", sender.Id),
+						mlog.String("receiver_id", uid),
+						mlog.Err(err),
+					)
 					return nil, errors.Wrapf(err, "cannot get thread %q for user %q", post.RootId, uid)
 				}
 				if userThread != nil {
@@ -580,6 +788,15 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 						// should set unread mentions, and unread replies to 0
 						_, err = a.Srv().Store().Thread().MaintainMembership(uid, post.RootId, opts)
 						if err != nil {
+							a.NotificationsLog().Error("Failed to update thread membership",
+								mlog.String("type", model.TypeWebsocket),
+								mlog.String("post_id", post.Id),
+								mlog.String("status", model.StatusServerError),
+								mlog.String("reason", model.ReasonServerError),
+								mlog.String("sender_id", sender.Id),
+								mlog.String("receiver_id", uid),
+								mlog.Err(err),
+							)
 							return nil, errors.Wrapf(err, "cannot maintain thread membership %q for user %q", post.RootId, uid)
 						}
 						userThread.UnreadMentions = 0
@@ -590,6 +807,15 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 
 					sanitizedPost, err := a.SanitizePostMetadataForUser(c, userThread.Post, uid)
 					if err != nil {
+						a.NotificationsLog().Error("Failed to sanitize metadata",
+							mlog.String("type", model.TypeWebsocket),
+							mlog.String("post_id", post.Id),
+							mlog.String("status", model.StatusServerError),
+							mlog.String("reason", model.ReasonServerError),
+							mlog.String("sender_id", sender.Id),
+							mlog.String("receiver_id", uid),
+							mlog.Err(err),
+						)
 						return nil, err
 					}
 					userThread.Post = sanitizedPost
@@ -607,6 +833,13 @@ func (a *App) SendNotifications(c request.CTX, post *model.Post, team *model.Tea
 			}
 		}
 	}
+
+	a.NotificationsLog().Trace("Finish sending websocket notifications",
+		mlog.String("type", model.TypeWebsocket),
+		mlog.String("sender_id", sender.Id),
+		mlog.String("post_id", post.Id),
+	)
+
 	return mentionedUsersList, nil
 }
 

server/channels/app/notification_push.go

@@ -24,12 +24,22 @@ import (
 )
 
 type notificationType string
+type notifyPropsReason string
+type statusReason string
 
 const (
 	notificationTypeClear       notificationType = "clear"
 	notificationTypeMessage     notificationType = "message"
 	notificationTypeUpdateBadge notificationType = "update_badge"
 	notificationTypeDummy       notificationType = "dummy"
+
+	NotifyPropsReasonChannelMuted  notifyPropsReason = "channel_muted"
+	NotifyPropsReasonSystemMessage notifyPropsReason = "system_message"
+	NotifyPropsReasonSetToNone     notifyPropsReason = "notify_props_set_to_note"
+	NotifyPropsReasonSetToMention  notifyPropsReason = "notify_props_set_to_mention_and_was_not_mentioned"
+
+	StatusReasonDNDOrOOO statusReason = "status_is_dnd_or_ooo"
+	StatusReasonIsActive statusReason = "user_is_active_on_channel"
 )
 
 type PushNotificationsHub struct {
@@ -97,15 +107,34 @@ func (a *App) sendPushNotificationToAllSessions(msg *model.PushNotification, use
 
 	if rejectionReason != "" {
 		// Notifications rejected by a plugin should not be considered errors
+		a.NotificationsLog().Info("Notification rejected by plugin",
+			mlog.String("type", model.TypePush),
+			mlog.String("status", model.StatusNotSent),
+			mlog.String("reason", rejectionReason),
+			mlog.String("user_id", userID),
+		)
 		return nil
 	}
 
 	sessions, err := a.getMobileAppSessions(userID)
 	if err != nil {
+		a.NotificationsLog().Error("Failed to send mobile app sessions",
+			mlog.String("type", model.TypePush),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonFetchError),
+			mlog.String("user_id", userID),
+			mlog.Err(err),
+		)
 		return err
 	}
 
 	if msg == nil {
+		a.NotificationsLog().Error("Failed to parse push notification",
+			mlog.String("type", model.TypePush),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonServerError),
+			mlog.String("user_id", userID),
+		)
 		return model.NewAppError(
 			"pushNotification",
 			"api.push_notifications.message.parse.app_error",
@@ -118,6 +147,13 @@ func (a *App) sendPushNotificationToAllSessions(msg *model.PushNotification, use
 	for _, session := range sessions {
 		// Don't send notifications to this session if it's expired or we want to skip it
 		if session.IsExpired() || (skipSessionId != "" && skipSessionId == session.Id) {
+			a.NotificationsLog().Debug("Session expired or skipped",
+				mlog.String("type", model.TypePush),
+				mlog.String("status", model.StatusNotSent),
+				mlog.String("reason", model.ReasonUserStatus),
+				mlog.String("user_id", session.UserId),
+				mlog.String("session_id", session.Id),
+			)
 			continue
 		}
 
@@ -128,25 +164,25 @@ func (a *App) sendPushNotificationToAllSessions(msg *model.PushNotification, use
 
 		err := a.sendToPushProxy(tmpMessage, session)
 		if err != nil {
-			a.NotificationsLog().Error("Notification error",
-				mlog.String("ackId", tmpMessage.AckId),
-				mlog.String("type", tmpMessage.Type),
-				mlog.String("userId", session.UserId),
-				mlog.String("postId", tmpMessage.PostId),
-				mlog.String("channelId", tmpMessage.ChannelId),
-				mlog.String("deviceId", tmpMessage.DeviceId),
-				mlog.String("status", err.Error()),
+			a.NotificationsLog().Error("Failed to send to push proxy",
+				mlog.String("type", model.TypePush),
+				mlog.String("status", model.StatusNotSent),
+				mlog.String("reason", model.ReasonPushProxyError),
+				mlog.String("ack_id", tmpMessage.AckId),
+				mlog.String("push_type", tmpMessage.Type),
+				mlog.String("user_id", session.UserId),
+				mlog.String("device_id", tmpMessage.DeviceId),
+				mlog.Err(err),
 			)
 			continue
 		}
 
-		a.NotificationsLog().Info("Notification sent",
-			mlog.String("ackId", tmpMessage.AckId),
-			mlog.String("type", tmpMessage.Type),
-			mlog.String("userId", session.UserId),
-			mlog.String("postId", tmpMessage.PostId),
-			mlog.String("channelId", tmpMessage.ChannelId),
-			mlog.String("deviceId", tmpMessage.DeviceId),
+		a.NotificationsLog().Trace("Notification sent to push proxy",
+			mlog.String("type", model.TypePush),
+			mlog.String("ack_id", tmpMessage.AckId),
+			mlog.String("push_type", tmpMessage.Type),
+			mlog.String("user_id", session.UserId),
+			mlog.String("device_id", tmpMessage.DeviceId),
 			mlog.String("status", model.PushSendSuccess),
 		)
 
@@ -440,11 +476,12 @@ func (a *App) rawSendToPushProxy(msg *model.PushNotification) (model.PushRespons
 func (a *App) sendToPushProxy(msg *model.PushNotification, session *model.Session) error {
 	msg.ServerId = a.TelemetryId()
 
-	a.NotificationsLog().Info("Notification will be sent",
-		mlog.String("ackId", msg.AckId),
-		mlog.String("type", msg.Type),
-		mlog.String("userId", session.UserId),
-		mlog.String("postId", msg.PostId),
+	a.NotificationsLog().Trace("Notification will be sent",
+		mlog.String("type", model.TypePush),
+		mlog.String("ack_id", msg.AckId),
+		mlog.String("push_type", msg.Type),
+		mlog.String("user_id", session.UserId),
+		mlog.String("post_id", msg.PostId),
 		mlog.String("status", model.PushSendPrepare),
 	)
 
@@ -469,11 +506,14 @@ func (a *App) SendAckToPushProxy(ack *model.PushNotificationAck) error {
 		return nil
 	}
 
-	a.NotificationsLog().Info("Notification received",
-		mlog.String("ackId", ack.Id),
-		mlog.String("type", ack.NotificationType),
-		mlog.String("deviceType", ack.ClientPlatform),
-		mlog.Int("receivedAt", ack.ClientReceivedAt),
+	a.NotificationsLog().Trace("Notification successfully received",
+		mlog.String("type", model.TypePush),
+		mlog.String("ack_id", ack.Id),
+		mlog.String("push_type", ack.NotificationType),
+		mlog.String("post_id", ack.PostId),
+		mlog.String("ack_type", ack.NotificationType),
+		mlog.String("device_type", ack.ClientPlatform),
+		mlog.Int("received_at", ack.ClientReceivedAt),
 		mlog.String("status", model.PushReceived),
 	)
 
@@ -488,12 +528,12 @@ func (a *App) SendAckToPushProxy(ack *model.PushNotificationAck) error {
 		bytes.NewReader(ackJSON),
 	)
 	if err != nil {
-		return err
+		return fmt.Errorf("failed to create request: %w", err)
 	}
 
 	resp, err := a.Srv().pushNotificationClient.Do(request)
 	if err != nil {
-		return err
+		return fmt.Errorf("failed to send: %w", err)
 	}
 	defer resp.Body.Close()
 
@@ -511,12 +551,38 @@ func (a *App) getMobileAppSessions(userID string) ([]*model.Session, *model.AppE
 	return sessions, nil
 }
 
-func ShouldSendPushNotification(user *model.User, channelNotifyProps model.StringMap, wasMentioned bool, status *model.Status, post *model.Post, isGM bool) bool {
-	return DoesNotifyPropsAllowPushNotification(user, channelNotifyProps, post, wasMentioned, isGM) &&
-		DoesStatusAllowPushNotification(user.NotifyProps, status, post.ChannelId)
+func (a *App) ShouldSendPushNotification(user *model.User, channelNotifyProps model.StringMap, wasMentioned bool, status *model.Status, post *model.Post, isGM bool) bool {
+	if notifyPropsAllowedReason := DoesNotifyPropsAllowPushNotification(user, channelNotifyProps, post, wasMentioned, isGM); notifyPropsAllowedReason != "" {
+		a.NotificationsLog().Debug("Notification not sent - notify props",
+			mlog.String("type", model.TypePush),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusNotSent),
+			mlog.String("reason", model.ReasonUserConfig),
+			mlog.String("notify_props_reason", notifyPropsAllowedReason),
+			mlog.String("sender_id", post.UserId),
+			mlog.String("receiver_id", user.Id),
+		)
+		return false
+	}
+
+	if statusAllowedReason := DoesStatusAllowPushNotification(user.NotifyProps, status, post.ChannelId); statusAllowedReason != "" {
+		a.NotificationsLog().Debug("Notification not sent - status",
+			mlog.String("type", model.TypePush),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusNotSent),
+			mlog.String("reason", model.ReasonUserConfig),
+			mlog.String("status_reason", statusAllowedReason),
+			mlog.String("sender_id", post.UserId),
+			mlog.String("receiver_id", user.Id),
+			mlog.String("receiver_status", status.Status),
+		)
+		return false
+	}
+
+	return true
 }
 
-func DoesNotifyPropsAllowPushNotification(user *model.User, channelNotifyProps model.StringMap, post *model.Post, wasMentioned, isGM bool) bool {
+func DoesNotifyPropsAllowPushNotification(user *model.User, channelNotifyProps model.StringMap, post *model.Post, wasMentioned, isGM bool) notifyPropsReason {
 	userNotifyProps := user.NotifyProps
 	userNotify := userNotifyProps[model.PushNotifyProp]
 	channelNotify, ok := channelNotifyProps[model.PushNotifyProp]
@@ -534,49 +600,49 @@ func DoesNotifyPropsAllowPushNotification(user *model.User, channelNotifyProps m
 
 	// If the channel is muted do not send push notifications
 	if channelNotifyProps[model.MarkUnreadNotifyProp] == model.ChannelMarkUnreadMention {
-		return false
+		return NotifyPropsReasonChannelMuted
 	}
 
 	if post.IsSystemMessage() {
-		return false
+		return NotifyPropsReasonSystemMessage
 	}
 
 	if notify == model.ChannelNotifyNone {
-		return false
+		return NotifyPropsReasonSetToNone
 	}
 
 	if notify == model.ChannelNotifyMention && !wasMentioned {
-		return false
+		return NotifyPropsReasonSetToMention
 	}
 
 	if (notify == model.ChannelNotifyAll) &&
 		(post.UserId != user.Id || post.GetProp("from_webhook") == "true") {
-		return true
+		return ""
 	}
 
-	return true
+	return ""
 }
 
-func DoesStatusAllowPushNotification(userNotifyProps model.StringMap, status *model.Status, channelID string) bool {
+func DoesStatusAllowPushNotification(userNotifyProps model.StringMap, status *model.Status, channelID string) statusReason {
 	// If User status is DND or OOO return false right away
 	if status.Status == model.StatusDnd || status.Status == model.StatusOutOfOffice {
-		return false
+		return StatusReasonDNDOrOOO
 	}
 
 	pushStatus, ok := userNotifyProps[model.PushStatusNotifyProp]
 	if (pushStatus == model.StatusOnline || !ok) && (status.ActiveChannel != channelID || model.GetMillis()-status.LastActivityAt > model.StatusChannelTimeout) {
-		return true
+		return ""
 	}
 
 	if pushStatus == model.StatusAway && (status.Status == model.StatusAway || status.Status == model.StatusOffline) {
-		return true
+		return ""
 	}
 
 	if pushStatus == model.StatusOffline && status.Status == model.StatusOffline {
-		return true
+		return ""
 	}
 
-	return false
+	return StatusReasonIsActive
 }
 
 func (a *App) BuildPushNotificationMessage(c request.CTX, contentsConfig string, post *model.Post, user *model.User, channel *model.Channel, channelName string, senderName string,
@@ -623,10 +689,13 @@ func (a *App) SendTestPushNotification(deviceID string) string {
 
 	pushResponse, err := a.rawSendToPushProxy(msg)
 	if err != nil {
-		a.NotificationsLog().Error("Notification error",
-			mlog.String("type", msg.Type),
-			mlog.String("deviceId", msg.DeviceId),
-			mlog.String("status", err.Error()),
+		a.NotificationsLog().Error("Failed to send test notification to push proxy",
+			mlog.String("type", model.TypePush),
+			mlog.String("push_type", msg.Type),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonPushProxyError),
+			mlog.String("device_id", msg.DeviceId),
+			mlog.Err(err),
 		)
 		return "unknown"
 	}
@@ -635,10 +704,13 @@ func (a *App) SendTestPushNotification(deviceID string) string {
 	case model.PushStatusRemove:
 		return "false"
 	case model.PushStatusFail:
-		a.NotificationsLog().Error("Notification error",
-			mlog.String("type", msg.Type),
-			mlog.String("deviceId", msg.DeviceId),
-			mlog.String("status", pushResponse[model.PushStatusErrorMsg]),
+		a.NotificationsLog().Error("Push proxy failed to send test notification",
+			mlog.String("type", model.TypePush),
+			mlog.String("push_type", msg.Type),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonPushProxyError),
+			mlog.String("device_id", msg.DeviceId),
+			mlog.Err(errors.New(pushResponse[model.PushStatusErrorMsg])),
 		)
 		return "unknown"
 	}

server/channels/app/notification_push_test.go

@@ -34,7 +34,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 		withSystemPost       bool
 		wasMentioned         bool
 		isMuted              bool
-		expected             bool
+		expected             notifyPropsReason
 		isGM                 bool
 	}{
 		{
@@ -44,7 +44,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       true,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSystemMessage,
 			isGM:                 false,
 		},
 		{
@@ -54,7 +54,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       true,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSystemMessage,
 			isGM:                 false,
 		},
 		{
@@ -64,7 +64,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -74,7 +74,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -84,7 +84,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToMention,
 			isGM:                 false,
 		},
 		{
@@ -94,7 +94,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -104,7 +104,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -114,7 +114,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -124,7 +124,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -134,7 +134,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -144,7 +144,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToMention,
 			isGM:                 false,
 		},
 		{
@@ -154,7 +154,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -164,7 +164,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -174,7 +174,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -184,7 +184,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -194,7 +194,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -204,7 +204,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -214,7 +214,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -224,7 +224,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -234,7 +234,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -244,7 +244,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToMention,
 			isGM:                 false,
 		},
 		{
@@ -254,7 +254,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -264,7 +264,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToMention,
 			isGM:                 false,
 		},
 		{
@@ -274,7 +274,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -284,7 +284,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToMention,
 			isGM:                 false,
 		},
 		{
@@ -294,7 +294,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 false,
 		},
 		{
@@ -304,7 +304,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -314,7 +314,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -324,7 +324,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -334,7 +334,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -344,7 +344,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -354,7 +354,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 false,
 		},
 		{
@@ -364,7 +364,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              true,
-			expected:             false,
+			expected:             NotifyPropsReasonChannelMuted,
 			isGM:                 false,
 		},
 		{
@@ -374,7 +374,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToNone,
 			isGM:                 true,
 		},
 		{
@@ -384,7 +384,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         true,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 true,
 		},
 		{
@@ -394,7 +394,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             true,
+			expected:             "",
 			isGM:                 true,
 		},
 		{
@@ -404,7 +404,7 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 			withSystemPost:       false,
 			wasMentioned:         false,
 			isMuted:              false,
-			expected:             false,
+			expected:             NotifyPropsReasonSetToMention,
 			isGM:                 true,
 		},
 	}
@@ -431,6 +431,9 @@ func TestDoesNotifyPropsAllowPushNotification(t *testing.T) {
 }
 
 func TestDoesStatusAllowPushNotification(t *testing.T) {
+	th := Setup(t).InitBasic()
+	defer th.TearDown()
+
 	userID := model.NewId()
 	channelID := model.NewId()
 
@@ -444,175 +447,175 @@ func TestDoesStatusAllowPushNotification(t *testing.T) {
 		userNotifySetting string
 		status            *model.Status
 		channelID         string
-		expected          bool
+		expected          statusReason
 	}{
 		{
 			name:              "WHEN props is ONLINE and user is offline with channel",
 			userNotifySetting: model.StatusOnline,
 			status:            offline,
 			channelID:         channelID,
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is ONLINE and user is offline without channel",
 			userNotifySetting: model.StatusOnline,
 			status:            offline,
 			channelID:         "",
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is ONLINE and user is away with channel",
 			userNotifySetting: model.StatusOnline,
 			status:            away,
 			channelID:         channelID,
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is ONLINE and user is away without channel",
 			userNotifySetting: model.StatusOnline,
 			status:            away,
 			channelID:         "",
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is ONLINE and user is online with channel",
 			userNotifySetting: model.StatusOnline,
 			status:            online,
 			channelID:         channelID,
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is ONLINE and user is online without channel",
 			userNotifySetting: model.StatusOnline,
 			status:            online,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is ONLINE and user is dnd with channel",
 			userNotifySetting: model.StatusOnline,
 			status:            dnd,
 			channelID:         channelID,
-			expected:          false,
+			expected:          StatusReasonDNDOrOOO,
 		},
 		{
 			name:              "WHEN props is ONLINE and user is dnd without channel",
 			userNotifySetting: model.StatusOnline,
 			status:            dnd,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonDNDOrOOO,
 		},
 		{
 			name:              "WHEN props is AWAY and user is offline with channel",
 			userNotifySetting: model.StatusAway,
 			status:            offline,
 			channelID:         channelID,
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is AWAY and user is offline without channel",
 			userNotifySetting: model.StatusAway,
 			status:            offline,
 			channelID:         "",
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is AWAY and user is away with channel",
 			userNotifySetting: model.StatusAway,
 			status:            away,
 			channelID:         channelID,
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is AWAY and user is away without channel",
 			userNotifySetting: model.StatusAway,
 			status:            away,
 			channelID:         "",
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is AWAY and user is online with channel",
 			userNotifySetting: model.StatusAway,
 			status:            online,
 			channelID:         channelID,
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is AWAY and user is online without channel",
 			userNotifySetting: model.StatusAway,
 			status:            online,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is AWAY and user is dnd with channel",
 			userNotifySetting: model.StatusAway,
 			status:            dnd,
 			channelID:         channelID,
-			expected:          false,
+			expected:          StatusReasonDNDOrOOO,
 		},
 		{
 			name:              "WHEN props is AWAY and user is dnd without channel",
 			userNotifySetting: model.StatusAway,
 			status:            dnd,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonDNDOrOOO,
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is offline with channel",
 			userNotifySetting: model.StatusOffline,
 			status:            offline,
 			channelID:         channelID,
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is offline without channel",
 			userNotifySetting: model.StatusOffline,
 			status:            offline,
 			channelID:         "",
-			expected:          true,
+			expected:          "",
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is away with channel",
 			userNotifySetting: model.StatusOffline,
 			status:            away,
 			channelID:         channelID,
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is away without channel",
 			userNotifySetting: model.StatusOffline,
 			status:            away,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is online with channel",
 			userNotifySetting: model.StatusOffline,
 			status:            online,
 			channelID:         channelID,
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is online without channel",
 			userNotifySetting: model.StatusOffline,
 			status:            online,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonIsActive,
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is dnd with channel",
 			userNotifySetting: model.StatusOffline,
 			status:            dnd,
 			channelID:         channelID,
-			expected:          false,
+			expected:          StatusReasonDNDOrOOO,
 		},
 		{
 			name:              "WHEN props is OFFLINE and user is dnd without channel",
 			userNotifySetting: model.StatusOffline,
 			status:            dnd,
 			channelID:         "",
-			expected:          false,
+			expected:          StatusReasonDNDOrOOO,
 		},
 	}
 

server/channels/app/opentracing/opentracing_layer.go

@@ -16835,6 +16835,23 @@ func (a *OpenTracingAppLayer) ShareChannel(c request.CTX, sc *model.SharedChanne
 	return resultVar0, resultVar1
 }
 
+func (a *OpenTracingAppLayer) ShouldSendPushNotification(user *model.User, channelNotifyProps model.StringMap, wasMentioned bool, status *model.Status, post *model.Post, isGM bool) bool {
+	origCtx := a.ctx
+	span, newCtx := tracing.StartSpanWithParentByContext(a.ctx, "app.ShouldSendPushNotification")
+
+	a.ctx = newCtx
+	a.app.Srv().Store().SetContext(newCtx)
+	defer func() {
+		a.app.Srv().Store().SetContext(origCtx)
+		a.ctx = origCtx
+	}()
+
+	defer span.Finish()
+	resultVar0 := a.app.ShouldSendPushNotification(user, channelNotifyProps, wasMentioned, status, post, isGM)
+
+	return resultVar0
+}
+
 func (a *OpenTracingAppLayer) SlackImport(c request.CTX, fileData multipart.File, fileSize int64, teamID string) (*model.AppError, *bytes.Buffer) {
 	origCtx := a.ctx
 	span, newCtx := tracing.StartSpanWithParentByContext(a.ctx, "app.SlackImport")

server/channels/app/post.go

@@ -357,6 +357,13 @@ func (a *App) CreatePost(c request.CTX, post *model.Post, channel *model.Channel
 
 	if rpost.RootId != "" {
 		if appErr := a.ResolvePersistentNotification(c, parentPostList.Posts[post.RootId], rpost.UserId); appErr != nil {
+			a.NotificationsLog().Error("Error resolving persistent notification",
+				mlog.String("sender_id", rpost.UserId),
+				mlog.String("post_id", post.RootId),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonFetchError),
+				mlog.Err(appErr),
+			)
 			return nil, appErr
 		}
 	}
@@ -480,6 +487,12 @@ func (a *App) handlePostEvents(c request.CTX, post *model.Post, user *model.User
 	if channel.TeamId != "" {
 		t, err := a.Srv().Store().Team().Get(channel.TeamId)
 		if err != nil {
+			a.NotificationsLog().Error("Missing team",
+				mlog.String("post_id", post.Id),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonFetchError),
+				mlog.Err(err),
+			)
 			return err
 		}
 		team = t
@@ -764,10 +777,23 @@ func (a *App) publishWebsocketEventForPermalinkPost(c request.CTX, post *model.P
 	if val, ok := post.GetProp(model.PostPropsPreviewedPost).(string); ok {
 		previewedPostID = val
 	} else {
+		a.NotificationsLog().Warn("Failed to get permalink post prop",
+			mlog.String("type", model.TypeWebsocket),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonServerError),
+		)
 		return false, nil
 	}
 
 	if !model.IsValidId(previewedPostID) {
+		a.NotificationsLog().Warn("Invalid post prop id for permalink post",
+			mlog.String("type", model.TypeWebsocket),
+			mlog.String("post_id", post.Id),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonServerError),
+			mlog.String("prop_value", previewedPostID),
+		)
 		c.Logger().Warn("invalid post prop value", mlog.String("prop_key", model.PostPropsPreviewedPost), mlog.String("prop_value", previewedPostID))
 		return false, nil
 	}
@@ -775,6 +801,13 @@ func (a *App) publishWebsocketEventForPermalinkPost(c request.CTX, post *model.P
 	previewedPost, err := a.GetSinglePost(previewedPostID, false)
 	if err != nil {
 		if err.StatusCode == http.StatusNotFound {
+			a.NotificationsLog().Warn("permalink post not found",
+				mlog.String("type", model.TypeWebsocket),
+				mlog.String("post_id", post.Id),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonServerError),
+				mlog.String("referenced_post_id", previewedPostID),
+			)
 			c.Logger().Warn("permalinked post not found", mlog.String("referenced_post_id", previewedPostID))
 			return false, nil
 		}

server/channels/app/post_acknowledgements.go

@@ -42,6 +42,13 @@ func (a *App) SaveAcknowledgementForPost(c request.CTX, postID, userID string) (
 	}
 
 	if appErr := a.ResolvePersistentNotification(c, post, userID); appErr != nil {
+		a.NotificationsLog().Error("Error resolving persistent notification",
+			mlog.String("sender_id", userID),
+			mlog.String("post_id", post.RootId),
+			mlog.String("status", model.StatusServerError),
+			mlog.String("reason", model.ReasonFetchError),
+			mlog.Err(appErr),
+		)
 		return nil, appErr
 	}
 

server/channels/app/post_persistent_notification.go

@@ -311,7 +311,7 @@ func (a *App) sendPersistentNotifications(post *model.Post, channel *model.Chann
 			}
 
 			isGM := channel.Type == model.ChannelTypeGroup
-			if ShouldSendPushNotification(profileMap[userID], channelNotifyProps[channel.Id][userID], true, status, post, isGM) {
+			if a.ShouldSendPushNotification(profileMap[userID], channelNotifyProps[channel.Id][userID], true, status, post, isGM) {
 				a.sendPushNotification(
 					notification,
 					user,
@@ -319,15 +319,6 @@ func (a *App) sendPersistentNotifications(post *model.Post, channel *model.Chann
 					false,
 					"",
 				)
-			} else {
-				// register that a notification was not sent
-				a.NotificationsLog().Debug("Persistent Notification not sent",
-					mlog.String("ackId", ""),
-					mlog.String("type", model.PushTypeMessage),
-					mlog.String("userId", userID),
-					mlog.String("postId", post.Id),
-					mlog.String("status", model.PushNotSent),
-				)
 			}
 		}
 	}

server/channels/app/reaction.go

@@ -67,6 +67,13 @@ func (a *App) SaveReactionForPost(c request.CTX, reaction *model.Reaction) (*mod
 
 	if post.RootId == "" {
 		if appErr := a.ResolvePersistentNotification(c, post, reaction.UserId); appErr != nil {
+			a.NotificationsLog().Error("Error resolving persistent notification",
+				mlog.String("sender_id", reaction.UserId),
+				mlog.String("post_id", post.RootId),
+				mlog.String("status", model.StatusServerError),
+				mlog.String("reason", model.ReasonFetchError),
+				mlog.Err(appErr),
+			)
 			return nil, appErr
 		}
 	}