From 893c44fe850c7092c4465e8f1af180d0c5c242e0 Mon Sep 17 00:00:00 2001 From: Devin Binnie <52460000+devinbinnie@users.noreply.github.com> Date: Thu, 29 Feb 2024 12:33:05 -0500 Subject: [PATCH] [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 --- server/channels/api4/system.go | 16 +- server/channels/app/app_iface.go | 1 + server/channels/app/expirynotify.go | 32 +- server/channels/app/notification.go | 293 ++++++++++++++++-- server/channels/app/notification_push.go | 174 ++++++++--- server/channels/app/notification_push_test.go | 129 ++++---- .../app/opentracing/opentracing_layer.go | 17 + server/channels/app/post.go | 33 ++ server/channels/app/post_acknowledgements.go | 7 + .../app/post_persistent_notification.go | 11 +- server/channels/app/reaction.go | 7 + server/public/model/notification.go | 22 ++ 12 files changed, 571 insertions(+), 171 deletions(-) create mode 100644 server/public/model/notification.go diff --git a/server/channels/api4/system.go b/server/channels/api4/system.go index bf234ccfeb..2a5886a6ec 100644 --- a/server/channels/api4/system.go +++ b/server/channels/api4/system.go @@ -631,15 +631,19 @@ func pushNotificationAck(c *Context, w http.ResponseWriter, r *http.Request) { err := c.App.SendAckToPushProxy(&ack) if ack.IsIdLoaded { if err != nil { - // Log the error only, then continue to fetch notification message c.App.NotificationsLog().Error("Notification ack not sent to push proxy", - mlog.String("ackId", ack.Id), - mlog.String("type", ack.NotificationType), - mlog.String("postId", ack.PostId), - mlog.String("status", err.Error()), + mlog.String("type", model.TypePush), + mlog.String("status", model.StatusServerError), + mlog.String("reason", model.ReasonServerError), + 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.Err(err), ) } - // Return post data only when PostId is passed. if ack.PostId != "" && ack.NotificationType == model.PushTypeMessage { if _, appErr := c.App.GetPostIfAuthorized(c.AppContext, ack.PostId, c.AppContext.Session(), false); appErr != nil { diff --git a/server/channels/app/app_iface.go b/server/channels/app/app_iface.go index 947cc23aba..c0ce94a936 100644 --- a/server/channels/app/app_iface.go +++ b/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 diff --git a/server/channels/app/expirynotify.go b/server/channels/app/expirynotify.go index 847fc99e03..a93b746882 100644 --- a/server/channels/app/expirynotify.go +++ b/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), ) diff --git a/server/channels/app/notification.go b/server/channels/app/notification.go index f9188c7cba..e444304145 100644 --- a/server/channels/app/notification.go +++ b/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 } diff --git a/server/channels/app/notification_push.go b/server/channels/app/notification_push.go index 1d0a79a7c2..9a4a8fb447 100644 --- a/server/channels/app/notification_push.go +++ b/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" } diff --git a/server/channels/app/notification_push_test.go b/server/channels/app/notification_push_test.go index 7874c3acfa..aa34c5e8e9 100644 --- a/server/channels/app/notification_push_test.go +++ b/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, }, } diff --git a/server/channels/app/opentracing/opentracing_layer.go b/server/channels/app/opentracing/opentracing_layer.go index df2673737a..a6e07582de 100644 --- a/server/channels/app/opentracing/opentracing_layer.go +++ b/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") diff --git a/server/channels/app/post.go b/server/channels/app/post.go index 3def93614a..c95c370622 100644 --- a/server/channels/app/post.go +++ b/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 } diff --git a/server/channels/app/post_acknowledgements.go b/server/channels/app/post_acknowledgements.go index d5c9f755f0..d03b1f9581 100644 --- a/server/channels/app/post_acknowledgements.go +++ b/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 } diff --git a/server/channels/app/post_persistent_notification.go b/server/channels/app/post_persistent_notification.go index 237ed3bbc7..da84bfa492 100644 --- a/server/channels/app/post_persistent_notification.go +++ b/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), - ) } } } diff --git a/server/channels/app/reaction.go b/server/channels/app/reaction.go index fd15140454..6239832b0a 100644 --- a/server/channels/app/reaction.go +++ b/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 } } diff --git a/server/public/model/notification.go b/server/public/model/notification.go new file mode 100644 index 0000000000..8a61b79670 --- /dev/null +++ b/server/public/model/notification.go @@ -0,0 +1,22 @@ +// Copyright (c) 2015-present Mattermost, Inc. All Rights Reserved. +// See LICENSE.txt for license information. + +package model + +const ( + StatusBlocked = "blocked" + StatusServerError = "server_error" + StatusNotSent = "not_sent" + + TypeEmail = "email" + TypeWebsocket = "websocket" + TypePush = "push" + + ReasonServerConfig = "server_config" + ReasonUserConfig = "user_config" + ReasonUserStatus = "user_status" + ReasonFetchError = "error_fetching" + ReasonServerError = "server_error" + ReasonMissingProfile = "missing_profile" + ReasonPushProxyError = "push_proxy_error" +)