From 347546ab982ccd04ef495085ab5de6b0c24c5ce3 Mon Sep 17 00:00:00 2001 From: kshitij katiyar <90389917+Kshitij-Katiyar@users.noreply.github.com> Date: Thu, 23 Mar 2023 02:24:43 +0530 Subject: [PATCH] [GH-244]: Fixed issue "Status sync job exits if an error happens for a single user" by added additional logging (#245) * [MI-2664]:Fixed issue #244 on ms calender to add additional logging (#2) * [MI-2664]:Fixed issue #244 on ms calender to add additional logging * [MI-2664]:Added comment for skipping user * [MI-2664]:Fixed unit test cases * [MI-2664]:Fix lint errors * [MI-2664]:Added conditional logging * [MI-2664]:Added constants for limit * [MI-2664]:Fixed review comments * [MI-2664]:Fixed review comments * [MI-2687]:Fixed review comments given by mattermost team on issue#244 of mscalender plugin (#3) * [MI-2687]:Fixed review comments given by mattermost team on issue #244 of mscalender plugin * [MI-2687]:Fixed unit test cases * [MI-2687]:Fixed review fixes * [MI-2705]:Added summary for status sync job (#4) * [MI-2705]:Added summary for status sync job * [MI-2705]:Fixed review comments * Fixed lint errors (#243) * [MI-2705]:Fixed review comments * [MI-2705]:Fixed review comments --------- Co-authored-by: Manoj Malik * [MM-244]:Fixed lint errors * [MM-244]:Added a check for summary to be nill * [MM-244]:Added addtional check for user error * [MM-244]:Fixed lint errors * [MM-244]:Fixed review comments --------- Co-authored-by: Manoj Malik --- server/command/availability.go | 4 +- server/jobs/status_sync_job.go | 4 +- server/mscalendar/availability.go | 134 ++++++++++++------ server/mscalendar/availability_test.go | 10 +- .../mock_mscalendar/mock_mscalendar.go | 14 +- 5 files changed, 110 insertions(+), 56 deletions(-) diff --git a/server/command/availability.go b/server/command/availability.go index 2fab471c..5bca44d3 100644 --- a/server/command/availability.go +++ b/server/command/availability.go @@ -6,14 +6,14 @@ package command func (c *Command) debugAvailability(parameters ...string) (string, bool, error) { switch { case len(parameters) == 0: - resString, err := c.MSCalendar.Sync(c.Args.UserId) + resString, _, err := c.MSCalendar.Sync(c.Args.UserId) if err != nil { return "", false, err } return resString, false, nil case len(parameters) == 1 && parameters[0] == "all": - resString, err := c.MSCalendar.SyncAll() + resString, _, err := c.MSCalendar.SyncAll() if err != nil { return "", false, err } diff --git a/server/jobs/status_sync_job.go b/server/jobs/status_sync_job.go index 66e14c69..fff9040b 100644 --- a/server/jobs/status_sync_job.go +++ b/server/jobs/status_sync_job.go @@ -23,10 +23,10 @@ func NewStatusSyncJob() RegisteredJob { func runSyncJob(env mscalendar.Env) { env.Logger.Debugf("User status sync job beginning") - _, err := mscalendar.New(env, "").SyncAll() + _, syncJobSummary, err := mscalendar.New(env, "").SyncAll() if err != nil { env.Logger.Errorf("Error during user status sync job. err=%v", err) } - env.Logger.Debugf("User status sync job finished") + env.Logger.Debugf("User status sync job finished.\nSummary\nNumber of users processed:- %d\nNumber of users had their status changed:- %d\nNumber of users had errors:- %d", syncJobSummary.NumberOfUsersProcessed, syncJobSummary.NumberOfUsersStatusChanged, syncJobSummary.NumberOfUsersFailedStatusChanged) } diff --git a/server/mscalendar/availability.go b/server/mscalendar/availability.go index 4a7f9070..ef00cab9 100644 --- a/server/mscalendar/availability.go +++ b/server/mscalendar/availability.go @@ -8,6 +8,7 @@ import ( "time" "github.com/mattermost/mattermost-server/v5/model" + "github.com/pkg/errors" "github.com/mattermost/mattermost-plugin-mscalendar/server/config" "github.com/mattermost/mattermost-plugin-mscalendar/server/mscalendar/views" @@ -21,78 +22,102 @@ const ( StatusSyncJobInterval = 5 * time.Minute upcomingEventNotificationTime = 10 * time.Minute upcomingEventNotificationWindow = (StatusSyncJobInterval * 11) / 10 // 110% of the interval + logTruncateMsg = "We've truncated the logs due to too many messages" + logTruncateLimit = 5 ) +type StatusSyncJobSummary struct { + NumberOfUsersFailedStatusChanged int + NumberOfUsersStatusChanged int + NumberOfUsersProcessed int +} + type Availability interface { GetCalendarViews(users []*store.User) ([]*remote.ViewCalendarResponse, error) - Sync(mattermostUserID string) (string, error) - SyncAll() (string, error) + Sync(mattermostUserID string) (string, *StatusSyncJobSummary, error) + SyncAll() (string, *StatusSyncJobSummary, error) } -func (m *mscalendar) Sync(mattermostUserID string) (string, error) { +func (m *mscalendar) Sync(mattermostUserID string) (string, *StatusSyncJobSummary, error) { user, err := m.Store.LoadUserFromIndex(mattermostUserID) if err != nil { - return "", err + return "", nil, err } return m.syncUsers(store.UserIndex{user}) } -func (m *mscalendar) SyncAll() (string, error) { +func (m *mscalendar) SyncAll() (string, *StatusSyncJobSummary, error) { err := m.Filter(withSuperuserClient) if err != nil { - return "", err + return "", &StatusSyncJobSummary{}, errors.Wrap(err, "not able to filter the super user client") } userIndex, err := m.Store.LoadUserIndex() if err != nil { if err.Error() == "not found" { - return "No users found in user index", nil + return "No users found in user index", &StatusSyncJobSummary{}, nil } - return "", err + return "", &StatusSyncJobSummary{}, errors.Wrap(err, "not able to load the users from user index") } return m.syncUsers(userIndex) } -func (m *mscalendar) syncUsers(userIndex store.UserIndex) (string, error) { +func (m *mscalendar) syncUsers(userIndex store.UserIndex) (string, *StatusSyncJobSummary, error) { + syncJobSummary := &StatusSyncJobSummary{} if len(userIndex) == 0 { - return "No connected users found", nil + return "No connected users found", syncJobSummary, nil } + syncJobSummary.NumberOfUsersProcessed = len(userIndex) + numberOfLogs := 0 users := []*store.User{} for _, u := range userIndex { // TODO fetch users from kvstore in batches, and process in batches instead of all at once user, err := m.Store.LoadUser(u.MattermostUserID) if err != nil { - return "", err + syncJobSummary.NumberOfUsersFailedStatusChanged++ + if numberOfLogs < logTruncateLimit { + m.Logger.Warnf("Not able to load user %s from user index. err=%v", u.MattermostUserID, err) + } else if numberOfLogs == logTruncateLimit { + m.Logger.Warnf(logTruncateMsg) + } + numberOfLogs++ + + // In case of error in loading, skip this user and continue with the next user + continue } if user.Settings.UpdateStatus || user.Settings.ReceiveReminders { users = append(users, user) } } if len(users) == 0 { - return "No users need to be synced", nil + return "No users need to be synced", syncJobSummary, nil } calendarViews, err := m.GetCalendarViews(users) if err != nil { - return "", err + return "", syncJobSummary, errors.Wrap(err, "not able to get calendar views for connected users") } if len(calendarViews) == 0 { - return "No calendar views found", nil + return "No calendar views found", syncJobSummary, nil } m.deliverReminders(users, calendarViews) - out, err := m.setUserStatuses(users, calendarViews) + out, numberOfUsersStatusChanged, numberOfUsersFailedStatusChanged, err := m.setUserStatuses(users, calendarViews) if err != nil { - return "", err + return "", syncJobSummary, errors.Wrap(err, "error setting the user statuses") } - return out, nil + syncJobSummary.NumberOfUsersFailedStatusChanged += numberOfUsersFailedStatusChanged + syncJobSummary.NumberOfUsersStatusChanged = numberOfUsersStatusChanged + + return out, syncJobSummary, nil } func (m *mscalendar) deliverReminders(users []*store.User, calendarViews []*remote.ViewCalendarResponse) { + numberOfLogs := 0 toNotify := []*store.User{} for _, u := range users { if u.Settings.ReceiveReminders { @@ -114,7 +139,12 @@ func (m *mscalendar) deliverReminders(users []*store.User, calendarViews []*remo continue } if view.Error != nil { - m.Logger.Warnf("Error getting availability for %s. err=%s", user.Remote.Mail, view.Error.Message) + if numberOfLogs < logTruncateLimit { + m.Logger.Warnf("Error getting availability for %s. err=%s", user.MattermostUserID, view.Error.Message) + } else if numberOfLogs == logTruncateLimit { + m.Logger.Warnf(logTruncateMsg) + } + numberOfLogs++ continue } @@ -123,7 +153,8 @@ func (m *mscalendar) deliverReminders(users []*store.User, calendarViews []*remo } } -func (m *mscalendar) setUserStatuses(users []*store.User, calendarViews []*remote.ViewCalendarResponse) (string, error) { +func (m *mscalendar) setUserStatuses(users []*store.User, calendarViews []*remote.ViewCalendarResponse) (string, int, int, error) { + numberOfLogs, numberOfUserStatusChange, numberOfUserErrorInStatusChange := 0, 0, 0 toUpdate := []*store.User{} for _, u := range users { if u.Settings.UpdateStatus { @@ -131,7 +162,7 @@ func (m *mscalendar) setUserStatuses(users []*store.User, calendarViews []*remot } } if len(toUpdate) == 0 { - return "No users want their status updated", nil + return "No users want their status updated", numberOfUserStatusChange, numberOfUserErrorInStatusChange, nil } mattermostUserIDs := []string{} @@ -143,7 +174,7 @@ func (m *mscalendar) setUserStatuses(users []*store.User, calendarViews []*remot statuses, appErr := m.PluginAPI.GetMattermostUserStatusesByIds(mattermostUserIDs) if appErr != nil { - return "", appErr + return "", numberOfUserStatusChange, numberOfUserErrorInStatusChange, errors.Wrap(appErr, "error in getting Mattermost user statuses for connected users") } statusMap := map[string]*model.Status{} for _, s := range statuses { @@ -152,12 +183,19 @@ func (m *mscalendar) setUserStatuses(users []*store.User, calendarViews []*remot var res string for _, view := range calendarViews { + isStatusChanged := false user, ok := usersByRemoteID[view.RemoteUserID] if !ok { continue } if view.Error != nil { - m.Logger.Warnf("Error getting availability for %s. err=%s", user.Remote.Mail, view.Error.Message) + if numberOfLogs < logTruncateLimit { + m.Logger.Warnf("Error getting availability for %s. err=%s", user.MattermostUserID, view.Error.Message) + } else if numberOfLogs == logTruncateLimit { + m.Logger.Warnf(logTruncateMsg) + } + numberOfLogs++ + numberOfUserErrorInStatusChange++ continue } @@ -168,22 +206,32 @@ func (m *mscalendar) setUserStatuses(users []*store.User, calendarViews []*remot } var err error - res, err = m.setStatusFromCalendarView(user, status, view) + res, isStatusChanged, err = m.setStatusFromCalendarView(user, status, view) if err != nil { - m.Logger.Warnf("Error setting user %s status. err=%v", user.Remote.Mail, err) + if numberOfLogs < logTruncateLimit { + m.Logger.Warnf("Error setting user %s status. err=%v", user.MattermostUserID, err) + } else if numberOfLogs == logTruncateLimit { + m.Logger.Warnf(logTruncateMsg) + } + numberOfLogs++ + numberOfUserErrorInStatusChange++ + } + if isStatusChanged { + numberOfUserStatusChange++ } } if res != "" { - return res, nil + return res, numberOfUserStatusChange, numberOfUserErrorInStatusChange, nil } - return utils.JSONBlock(calendarViews), nil + return utils.JSONBlock(calendarViews), numberOfUserStatusChange, numberOfUserErrorInStatusChange, nil } -func (m *mscalendar) setStatusFromCalendarView(user *store.User, status *model.Status, res *remote.ViewCalendarResponse) (string, error) { +func (m *mscalendar) setStatusFromCalendarView(user *store.User, status *model.Status, res *remote.ViewCalendarResponse) (string, bool, error) { + isStatusChanged := false currentStatus := status.Status if currentStatus == model.STATUS_OFFLINE && !user.Settings.GetConfirmation { - return "User offline and does not want status change confirmations. No status change", nil + return "User offline and does not want status change confirmations. No status change", isStatusChanged, nil } events := filterBusyEvents(res.Events) @@ -193,7 +241,7 @@ func (m *mscalendar) setStatusFromCalendarView(user *store.User, status *model.S } if len(user.ActiveEvents) == 0 && len(events) == 0 { - return "No events in local or remote. No status change.", nil + return "No events in local or remote. No status change.", isStatusChanged, nil } if len(user.ActiveEvents) > 0 && len(events) == 0 { @@ -205,15 +253,16 @@ func (m *mscalendar) setStatusFromCalendarView(user *store.User, status *model.S } err := m.setStatusOrAskUser(user, status, events, true) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in setting user status for user %s", user.MattermostUserID) } + isStatusChanged = true } err := m.Store.StoreUserActiveEvents(user.MattermostUserID, []string{}) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in storing active events for user %s", user.MattermostUserID) } - return message, nil + return message, isStatusChanged, nil } remoteHashes := []string{} @@ -235,19 +284,20 @@ func (m *mscalendar) setStatusFromCalendarView(user *store.User, status *model.S m.Store.StoreUser(user) err = m.Store.StoreUserActiveEvents(user.MattermostUserID, remoteHashes) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in storing active events for user %s", user.MattermostUserID) } - return "User was already marked as busy. No status change.", nil + return "User was already marked as busy. No status change.", isStatusChanged, nil } err = m.setStatusOrAskUser(user, status, events, false) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in setting user status for user %s", user.MattermostUserID) } + isStatusChanged = true err = m.Store.StoreUserActiveEvents(user.MattermostUserID, remoteHashes) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in storing active events for user %s", user.MattermostUserID) } - return fmt.Sprintf("User was free, but is now busy (%s). Set status to busy.", busyStatus), nil + return fmt.Sprintf("User was free, but is now busy (%s). Set status to busy.", busyStatus), isStatusChanged, nil } newEventExists := false @@ -266,23 +316,25 @@ func (m *mscalendar) setStatusFromCalendarView(user *store.User, status *model.S } if !newEventExists { - return fmt.Sprintf("No change in active events. Total number of events: %d", len(events)), nil + return fmt.Sprintf("No change in active events. Total number of events: %d", len(events)), isStatusChanged, nil } message := "User is already busy. No status change." if currentStatus != busyStatus { err := m.setStatusOrAskUser(user, status, events, false) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in setting user status for user %s", user.MattermostUserID) } + isStatusChanged = true message = fmt.Sprintf("User was free, but is now busy. Set status to busy (%s).", busyStatus) } err := m.Store.StoreUserActiveEvents(user.MattermostUserID, remoteHashes) if err != nil { - return "", err + return "", isStatusChanged, errors.Wrapf(err, "error in storing active events for user %s", user.MattermostUserID) } - return message, nil + + return message, isStatusChanged, nil } // setStatusOrAskUser to which status change, and whether it should update the status automatically or ask the user. diff --git a/server/mscalendar/availability_test.go b/server/mscalendar/availability_test.go index 10e67d5f..831d6acf 100644 --- a/server/mscalendar/availability_test.go +++ b/server/mscalendar/availability_test.go @@ -155,13 +155,13 @@ func TestSyncStatusAll(t *testing.T) { } if tc.shouldLogError { - logger.EXPECT().Warnf("Error getting availability for %s. err=%s", "user_email@example.com", tc.apiError.Message).Times(1) + logger.EXPECT().Warnf("Error getting availability for %s. err=%s", "user_mm_id", tc.apiError.Message).Times(1) } else { logger.EXPECT().Warnf(gomock.Any()).Times(0) } m := New(env, "") - res, err := m.SyncAll() + res, _, err := m.SyncAll() require.Nil(t, err) require.NotEmpty(t, res) }) @@ -223,7 +223,7 @@ func TestSyncStatusUserConfig(t *testing.T) { tc.runAssertions(env.Dependencies, client) mscalendar := New(env, "") - _, err := mscalendar.SyncAll() + _, _, err := mscalendar.SyncAll() require.Nil(t, err) }) } @@ -315,13 +315,13 @@ func TestReminders(t *testing.T) { } if tc.shouldLogError { - logger.EXPECT().Warnf("Error getting availability for %s. err=%s", "user_email@example.com", tc.apiError.Message).Times(1) + logger.EXPECT().Warnf("Error getting availability for %s. err=%s", "user_mm_id", tc.apiError.Message).Times(1) } else { logger.EXPECT().Warnf(gomock.Any()).Times(0) } m := New(env, "") - res, err := m.SyncAll() + res, _, err := m.SyncAll() require.Nil(t, err) require.NotEmpty(t, res) }) diff --git a/server/mscalendar/mock_mscalendar/mock_mscalendar.go b/server/mscalendar/mock_mscalendar/mock_mscalendar.go index 8d6bc66c..05e380aa 100644 --- a/server/mscalendar/mock_mscalendar/mock_mscalendar.go +++ b/server/mscalendar/mock_mscalendar/mock_mscalendar.go @@ -471,12 +471,13 @@ func (mr *MockMSCalendarMockRecorder) SetDailySummaryPostTime(arg0, arg1 interfa } // Sync mocks base method. -func (m *MockMSCalendar) Sync(arg0 string) (string, error) { +func (m *MockMSCalendar) Sync(arg0 string) (string, *mscalendar.StatusSyncJobSummary, error) { m.ctrl.T.Helper() ret := m.ctrl.Call(m, "Sync", arg0) ret0, _ := ret[0].(string) - ret1, _ := ret[1].(error) - return ret0, ret1 + ret1, _ := ret[1].(*mscalendar.StatusSyncJobSummary) + ret2, _ := ret[2].(error) + return ret0, ret1, ret2 } // Sync indicates an expected call of Sync. @@ -486,12 +487,13 @@ func (mr *MockMSCalendarMockRecorder) Sync(arg0 interface{}) *gomock.Call { } // SyncAll mocks base method. -func (m *MockMSCalendar) SyncAll() (string, error) { +func (m *MockMSCalendar) SyncAll() (string, *mscalendar.StatusSyncJobSummary, error) { m.ctrl.T.Helper() ret := m.ctrl.Call(m, "SyncAll") ret0, _ := ret[0].(string) - ret1, _ := ret[1].(error) - return ret0, ret1 + ret1, _ := ret[1].(*mscalendar.StatusSyncJobSummary) + ret2, _ := ret[2].(error) + return ret0, ret1, ret2 } // SyncAll indicates an expected call of SyncAll.