Tracking Push Notifications in a structured logger (notifications.log) (#10823)

* Remove NotificationRegistry table and use structured logging

* Fix ackId for notification sent

* Notification logger at server level

* Remove unused i18n strings

app/app.go

@@ -23,7 +23,8 @@ import (
 type App struct {
 	Srv *Server
 
-	Log *mlog.Logger
+	Log              *mlog.Logger
+	NotificationsLog *mlog.Logger
 
 	T              goi18n.TranslateFunc
 	Session        model.Session

app/notification.go

@@ -308,16 +308,13 @@ func (a *App) SendNotifications(post *model.Post, team *model.Team, channel *mod
 				)
 			} else {
 				// register that a notification was not sent
-				notificationRegistry := model.NotificationRegistry{
-					UserId:     id,
-					PostId:     post.Id,
-					SendStatus: model.PUSH_NOT_SENT,
-					Type:       model.PUSH_TYPE_MESSAGE,
-				}
-				_, appErr := a.Srv.Store.NotificationRegistry().Save(&notificationRegistry)
-				if appErr != nil {
-					mlog.Debug(appErr.Error())
-				}
+				a.NotificationsLog.Warn("Notification not sent",
+					mlog.String("ackId", ""),
+					mlog.String("type", model.PUSH_TYPE_MESSAGE),
+					mlog.String("userId", id),
+					mlog.String("postId", post.Id),
+					mlog.String("status", model.PUSH_NOT_SENT),
+				)
 			}
 		}
 
@@ -343,16 +340,13 @@ func (a *App) SendNotifications(post *model.Post, team *model.Team, channel *mod
 					)
 				} else {
 					// register that a notification was not sent
-					notificationRegistry := model.NotificationRegistry{
-						UserId:     id,
-						PostId:     post.Id,
-						SendStatus: model.PUSH_NOT_SENT,
-						Type:       model.PUSH_TYPE_MESSAGE,
-					}
-					_, appErr := a.Srv.Store.NotificationRegistry().Save(&notificationRegistry)
-					if appErr != nil {
-						mlog.Debug(appErr.Error())
-					}
+					a.NotificationsLog.Warn("Notification not sent",
+						mlog.String("ackId", ""),
+						mlog.String("type", model.PUSH_TYPE_MESSAGE),
+						mlog.String("userId", id),
+						mlog.String("postId", post.Id),
+						mlog.String("status", model.PUSH_NOT_SENT),
+					)
 				}
 			}
 		}

app/notification_push.go

@@ -112,34 +112,30 @@ func (a *App) sendPushNotificationSync(post *model.Post, user *model.User, chann
 		tmpMessage.SetDeviceIdAndPlatform(session.DeviceId)
 		tmpMessage.AckId = model.NewId()
 
-		mlog.Debug(
-			"Sending push notification",
-			mlog.String("ackId", tmpMessage.AckId),
-			mlog.String("deviceId", tmpMessage.DeviceId),
-			mlog.String("userId", user.Id),
-		)
-
 		err := a.sendToPushProxy(*tmpMessage, session)
 		if err != nil {
-			mlog.Error(
-				"Failed to send Push Notification:",
-				mlog.String("error", err.Error()),
+			a.NotificationsLog.Error("Notification error",
+				mlog.String("ackId", tmpMessage.AckId),
+				mlog.String("type", tmpMessage.Type),
 				mlog.String("userId", session.UserId),
-				mlog.String("sessionId", session.Id),
-				mlog.String("deviceId", msg.DeviceId),
-				mlog.String("ackId", msg.AckId),
+				mlog.String("postId", tmpMessage.PostId),
+				mlog.String("channelId", tmpMessage.ChannelId),
+				mlog.String("deviceId", tmpMessage.DeviceId),
+				mlog.String("status", err.Error()),
 			)
-			appErr := a.Srv.Store.NotificationRegistry().UpdateSendStatus(tmpMessage.AckId, model.PUSH_SEND_ERROR+": "+err.Error())
-			if appErr != nil {
-				mlog.Debug(appErr.Error())
-			}
+
 			continue
 		}
 
-		appErr := a.Srv.Store.NotificationRegistry().UpdateSendStatus(tmpMessage.AckId, model.PUSH_SEND_SUCCESS)
-		if appErr != nil {
-			mlog.Debug(appErr.Error())
-		}
+		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),
+			mlog.String("status", model.PUSH_SEND_SUCCESS),
+		)
 
 		if a.Metrics != nil {
 			a.Metrics.IncrementPostSentPush()
@@ -248,35 +244,30 @@ func (a *App) ClearPushNotificationSync(currentSessionId, userId, channelId stri
 			tmpMessage.SetDeviceIdAndPlatform(session.DeviceId)
 			tmpMessage.AckId = model.NewId()
 
-			mlog.Debug(
-				"Sending clear push notification",
-				mlog.String("ackId", tmpMessage.AckId),
-				mlog.String("deviceId", tmpMessage.DeviceId),
-				mlog.String("userId", session.UserId),
-				mlog.String("channelId", channelId), //should we remove the message from the logs?
-			)
-
 			err := a.sendToPushProxy(*tmpMessage, session)
 			if err != nil {
-				mlog.Error(
-					"Failed to send Push Notification:",
-					mlog.String("error", err.Error()),
+				a.NotificationsLog.Error("Notification error",
+					mlog.String("ackId", tmpMessage.AckId),
+					mlog.String("type", tmpMessage.Type),
 					mlog.String("userId", session.UserId),
-					mlog.String("sessionId", session.Id),
-					mlog.String("deviceId", msg.DeviceId),
-					mlog.String("ackId", msg.AckId),
+					mlog.String("postId", tmpMessage.PostId),
+					mlog.String("channelId", tmpMessage.ChannelId),
+					mlog.String("deviceId", tmpMessage.DeviceId),
+					mlog.String("status", err.Error()),
 				)
-				appErr := a.Srv.Store.NotificationRegistry().UpdateSendStatus(tmpMessage.AckId, model.PUSH_SEND_ERROR+": "+err.Error())
-				if appErr != nil {
-					mlog.Debug(appErr.Error())
-				}
+
 				continue
 			}
 
-			appErr := a.Srv.Store.NotificationRegistry().UpdateSendStatus(tmpMessage.AckId, model.PUSH_SEND_SUCCESS)
-			if appErr != nil {
-				mlog.Debug(appErr.Error())
-			}
+			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),
+				mlog.String("status", model.PUSH_SEND_SUCCESS),
+			)
 
 			if a.Metrics != nil {
 				a.Metrics.IncrementPostSentPush()
@@ -343,18 +334,13 @@ func (a *App) StopPushNotificationsHubWorkers() {
 func (a *App) sendToPushProxy(msg model.PushNotification, session *model.Session) error {
 	msg.ServerId = a.DiagnosticId()
 
-	notificationRegistry := model.NotificationRegistry{
-		AckId:    msg.AckId,
-		DeviceId: msg.DeviceId,
-		UserId:   session.UserId,
-		PostId:   msg.PostId,
-		Type:     msg.Type,
-	}
-
-	_, appErr := a.Srv.Store.NotificationRegistry().Save(&notificationRegistry)
-	if appErr != nil {
-		return appErr
-	}
+	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),
+		mlog.String("status", model.PUSH_SEND_PREPARE),
+	)
 
 	request, err := http.NewRequest("POST", strings.TrimRight(*a.Config().EmailSettings.PushNotificationServer, "/")+model.API_URL_SUFFIX_V1+"/send_push", strings.NewReader(msg.ToJson()))
 	if err != nil {
@@ -388,10 +374,13 @@ func (a *App) SendAckToPushProxy(ack *model.PushNotificationAck) error {
 		return nil
 	}
 
-	appErr := a.Srv.Store.NotificationRegistry().MarkAsReceived(ack.Id, ack.ClientReceivedAt)
-	if appErr != nil {
-		return appErr
-	}
+	a.NotificationsLog.Info("Notification received",
+		mlog.String("ackId", ack.Id),
+		mlog.String("type", ack.NotificationType),
+		mlog.String("deviceType", ack.ClientPlatform),
+		mlog.Int64("receivedAt", ack.ClientReceivedAt),
+		mlog.String("status", model.PUSH_RECEIVED),
+	)
 
 	request, err := http.NewRequest(
 		"POST",

app/options.go

@@ -99,6 +99,7 @@ func ServerConnector(s *Server) AppOption {
 		a.Srv = s
 
 		a.Log = s.Log
+		a.NotificationsLog = s.NotificationsLog
 
 		a.AccountMigration = s.AccountMigration
 		a.Cluster = s.Cluster

app/server.go

@@ -108,7 +108,8 @@ type Server struct {
 
 	ImageProxy *imageproxy.ImageProxy
 
-	Log *mlog.Logger
+	Log              *mlog.Logger
+	NotificationsLog *mlog.Logger
 
 	joinCluster        bool
 	startMetrics       bool
@@ -152,7 +153,13 @@ func NewServer(options ...Option) (*Server, error) {
 	}
 
 	if s.Log == nil {
-		s.Log = mlog.NewLogger(utils.MloggerConfigFromLoggerConfig(&s.Config().LogSettings))
+		s.Log = mlog.NewLogger(utils.MloggerConfigFromLoggerConfig(&s.Config().LogSettings, utils.GetLogFileLocation))
+	}
+
+	if s.NotificationsLog == nil {
+		notificationLogSettings := utils.GetLogSettingsFromNotificationsLogSettings(&s.Config().NotificationLogSettings)
+		s.NotificationsLog = mlog.NewLogger(utils.MloggerConfigFromLoggerConfig(notificationLogSettings, utils.GetNotificationsLogFileLocation)).
+			WithCallerSkip(1).With(mlog.String("logSource", "notifications"))
 	}
 
 	// Redirect default golang logger to this logger
@@ -162,7 +169,10 @@ func NewServer(options ...Option) (*Server, error) {
 	mlog.InitGlobalLogger(s.Log)
 
 	s.logListenerId = s.AddConfigListener(func(_, after *model.Config) {
-		s.Log.ChangeLevels(utils.MloggerConfigFromLoggerConfig(&after.LogSettings))
+		s.Log.ChangeLevels(utils.MloggerConfigFromLoggerConfig(&after.LogSettings, utils.GetLogFileLocation))
+
+		notificationLogSettings := utils.GetLogSettingsFromNotificationsLogSettings(&after.NotificationLogSettings)
+		s.NotificationsLog.ChangeLevels(utils.MloggerConfigFromLoggerConfig(notificationLogSettings, utils.GetNotificationsLogFileLocation))
 	})
 
 	s.HTTPService = httpservice.MakeHTTPService(s.FakeApp())