[GH-244]: Fixed issue "Status sync job exits if an error happens for a single user" by added additional logging #245

Kshitij-Katiyar · 2023-01-30T12:39:49Z

Summary

Users were getting the error in the server logs is an Error during user status sync job. err=not found during user status sync job. The status sync job was exiting if an error happened for a single user. So, I changed the logic to continue the process and log the error in server logs.
There will be at max 5 logs for a particular error/function.
Issue #244

… logging (#2) * [MI-2664]:Fixed issue mattermost#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

mattermost-build · 2023-01-30T12:39:52Z

Hello @Kshitij-Katiyar,

Thanks for your pull request! A Core Committer will review your pull request soon. For code contributions, you can learn more about the review process here.

mickmister

@Kshitij-Katiyar Thanks for the quick turnaround on this 👍 Mostly looks good, just a few requests

server/mscalendar/availability.go

… of mscalender plugin (#3) * [MI-2687]:Fixed review comments given by mattermost team on issue mattermost#244 of mscalender plugin * [MI-2687]:Fixed unit test cases * [MI-2687]:Fixed review fixes

mickmister

Awesome thanks @Kshitij-Katiyar!

DHaussermann · 2023-01-31T20:21:27Z

@Kshitij-Katiyar one suggestion to consider here would be - Once the sync job completes, can it write to the logs how many users where sync and how many errored out? This would provide visibility and confirm that the the job is now attempting to sync the entire user base.

Kshitij-Katiyar · 2023-02-01T07:08:37Z

@Kshitij-Katiyar one suggestion to consider here would be - Once the sync job completes, can it write to the logs how many users where sync and how many errored out? This would provide visibility and confirm that the the job is now attempting to sync the entire user base.

sure @DHaussermann @mickmister We can add a summary after the job ends. Can you please also give suggestions of what are the things I should include in that? Some examples could be

Can only show the number of users for each category like status synced-10 users and error-5 users.
Along with the number we can show the mattermost userId for each user. I don't think it would be better to show usernames as during the process we only have user Ids during this process and for each user, I have to call an additional API to fetch the usernames.

Please give your views on this.

mickmister · 2023-02-01T16:11:10Z

@Kshitij-Katiyar @DHaussermann I think we want to be cognizant of logging too much here. At the moment, we have a debug log before the job runs, and one after the job runs. These logs simply say that the job began and ended. There are some different levels of granularity we can add here:

Log how many users processed, and how many had errors
Include how many users had their status changed

The individual errors have the user ids in them, so no need to include the user ids in the aggregate log message at the end of the job. I think the first bullet point is appropriate here. If the second one is not a big hassle, then I think we should also include the "number of statuses changed".

spirosoik · 2023-02-03T12:20:20Z

/update-branch

mattermost-build · 2023-02-03T12:20:22Z

We don't have permissions to update this PR, please contact the submitter to apply the update.

* [MI-2705]:Added summary for status sync job * [MI-2705]:Fixed review comments * Fixed lint errors (mattermost#243) * [MI-2705]:Fixed review comments * [MI-2705]:Fixed review comments --------- Co-authored-by: Manoj Malik <manoj@brightscout.com>

Kshitij-Katiyar · 2023-02-06T10:20:26Z

@mickmister @DHaussermann Added the functionality of showing the summary for the status sync job

hanzei

There are a lot of unrelated changes in the PR. Could you please remove them?

server/config/config.go

hanzei · 2023-02-07T15:39:42Z

server/mscalendar/availability.go

+			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)
+			}


What is the value of posing a truncated message instead of the "real" one?

@hanzei Please read this comment #244 (comment).

@mickmister I don't understand your point in #244 (comment). If the goal is not to flood the logs, why are messages logged that only contain the information that the logs got trunkated? Isn't the number of log messages still the same?

@hanzei @mickmister I think the number of logs will not be the same. We will log the first 4 logs coming from a particular function/code snippet, then for the 5th one we will log the Truncate and after that, we will not be logging anything. So the max number of logs will be 5 in any case. If it is more than that we are truncating means not logging anything for a particular function.

…lendar into MM-244

mattermost-build · 2023-02-19T01:02:16Z

This PR has been automatically labelled "stale" because it hasn't had recent activity.
A core team member will check in on the status of the PR to help with questions.
Thank you for your contribution!

mattermost-build · 2023-03-07T01:02:13Z

This PR has been automatically labelled "stale" because it hasn't had recent activity.
A core team member will check in on the status of the PR to help with questions.
Thank you for your contribution!

m1lt0n · 2023-03-10T08:50:36Z

@mickmister @hanzei @DHaussermann what's the state of this related to a) code review, b) QA review? I see it is approved for (a), so is it a matter of finalising the QA review on that?

codecov-commenter · 2023-03-10T15:04:02Z

Codecov Report

Patch coverage: 43.90% and project coverage change: +0.37 🎉

Comparison is base (7c0c066) 23.31% compared to head (c25bd52) 23.68%.

Additional details and impacted files

@@            Coverage Diff             @@
##           master     #245      +/-   ##
==========================================
+ Coverage   23.31%   23.68%   +0.37%     
==========================================
  Files          62       62              
  Lines        3049     3090      +41     
==========================================
+ Hits          711      732      +21     
- Misses       2259     2277      +18     
- Partials       79       81       +2

Impacted Files	Coverage Δ
server/command/availability.go	`0.00% <0.00%> (ø)`
server/mscalendar/availability.go	`55.66% <45.00%> (-0.66%)`	⬇️

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report in Codecov by Sentry.
📢 Do you have feedback about the report comment? Let us know in this issue.

mickmister · 2023-03-10T15:04:59Z

@m1lt0n @DHaussermann Indeed it seems this is just awaiting QA review

DHaussermann · 2023-03-14T19:39:50Z

@Kshitij-Katiyar I can't test this. When I compile and deploy this to a cloud server (my local Darwin ARM seems to not be supported) The plugin starts up and then starts crashing until health-check eventually takes it down.

{
  "caller": "app/plugin_api.go:976",
  "level": "error",
  "msg": "Error during daily summary job. err=not found",
  "plugin_id": "com.mattermost.mscalendar",
  "timestamp": "2023-03-14 19:00:29.374 Z"
}

After this error it seems to crash

Steps:

Installed the plugin on a new cloud server where it's never run before
Configure the plugin and enable it
Nav to the user site and try running the connect command
Observed:
Plugin has crashed.

Can you please let me know if you can reproduce this?

Kshitij-Katiyar · 2023-03-16T10:35:04Z

@DHaussermann @mickmister I have fixed this. Actually in the code at one point I was accessing the attributes of a nil object, resulting in panic by mistake. This could only happen in an instance where there was no previous ms-calendar plugin installed. I have added a check now and also tested it on a new instance everything worked fine. Please test this again and let me know if you find any issues.

DHaussermann · 2023-03-21T02:39:43Z

Hi @Kshitij-Katiyar
I did some testing on this today.

The panic issue is fixed for new installs
I can see that the sync service starts and logs an output when it runs

The piece I'm struggling to test here is to see and error occur on 1 of the records and the job will still complete. from your summary "`err=not found during user status sync job..." How can I reproduce such an error?

I have this running locally with 2 users and have tried manually updating several values in KV store to invalidate them to try and cause such an error so I can see the sync complete. So far this has not worked. Updating oauth2_ values or user_ to try and invalidate them does cause the user to loose their connection but it still does not cause the job to error out on any of the records.

Are you able to offer any suggestions here?

Kshitij-Katiyar · 2023-03-21T07:42:35Z

Hi @Kshitij-Katiyar I did some testing on this today.

The panic issue is fixed for new installs

I can see that the sync service starts and logs an output when it runs

The piece I'm struggling to test here is to see and error occur on 1 of the records and the job will still complete. from your summary "`err=not found during user status sync job..." How can I reproduce such an error?

I have this running locally with 2 users and have tried manually updating several values in KV store to invalidate them to try and cause such an error so I can see the sync complete. So far this has not worked. Updating oauth2_ values or user_ to try and invalidate them does cause the user to loose their connection but it still does not cause the job to error out on any of the records.

Are you able to offer any suggestions here?

Hi @DHaussermann , I have done the changes for the part that even if we get an error from 1 user the job will still continue for other users. If you want to get or reproduce the above error user not found I can tell you what I have tried -

Connect the user using the slash command.
You can delete the key value for that user from the KV store either by going inside DB (if you can and I am using postgres) and run DELETE FROM pluginkeyvaluestore where pluginid ='com.mattermost.mscalendar' AND pkey = 'user_<key for your user>'; or using MM APIs to delete this KV pair.

{"timestamp":"2023-03-21 13:10:01.485 +05:30","level":"warn","msg":"Not able to load user 3p41xahsffbh9kqk1jcx9j1tpw from user index. err=not found","caller":"app/plugin_api.go:943","plugin_id":"com.mattermost.mscalendar"}

DHaussermann · 2023-03-21T14:20:38Z

Thanks @Kshitij-Katiyar taking another look and using your suggestion of deleting the records from the store - I can see the user not found errors

warn  [2023-03-21 10:10:00.389 -04:00] Not able to load user 6sbsdz3rgprs3f8s64nxft8s5a from user index. err=not found caller="app/plugin_api.go:979" plugin_id=com.mattermost.mscalendar
warn  [2023-03-21 10:10:00.399 -04:00] Not able to load user q6cs674637nguebthxp5r8m1rc from user index. err=not found caller="app/plugin_api.go:979" plugin_id=com.mattermost.mscalendar
debug [2023-03-21 10:10:00.399 -04:00] User status sync job finished.
Summary
Number of users processed:- 2
Number of users had their status changed:- 0
Number of users had errors:- 2 caller="app/plugin_api.go:970" plugin_id=com.mattermost.mscalendar

The issue yesterday was that Number of users had errors:- would continue showing as 0. I'm now not certain if Not able to load user <user ID> from user index was happening or not but even if it was, it would always show the error count as 0. Maybe your latest change may have affected this.

Also @mickmister does this last commit require code review?

Kshitij-Katiyar · 2023-03-21T14:48:09Z

Thanks @Kshitij-Katiyar taking another look and using your suggestion of deleting the records from the store - I can see the user not found errors
warn  [2023-03-21 10:10:00.389 -04:00] Not able to load user 6sbsdz3rgprs3f8s64nxft8s5a from user index. err=not found caller="app/plugin_api.go:979" plugin_id=com.mattermost.mscalendar
warn  [2023-03-21 10:10:00.399 -04:00] Not able to load user q6cs674637nguebthxp5r8m1rc from user index. err=not found caller="app/plugin_api.go:979" plugin_id=com.mattermost.mscalendar
debug [2023-03-21 10:10:00.399 -04:00] User status sync job finished.
Summary
Number of users processed:- 2
Number of users had their status changed:- 0
Number of users had errors:- 2 caller="app/plugin_api.go:970" plugin_id=com.mattermost.mscalendar
The issue yesterday was that Number of users had errors:- would continue showing as 0. I'm now not certain if Not able to load user <user ID> from user index was happening or not but even if it was, it would always show the error count as 0. Maybe your latest change may have affected this.

Also @mickmister does this last commit require code review?

@DHaussermann Ok yes I have fixed it. It was a very small change.

server/mscalendar/availability.go

hanzei · 2023-03-21T20:03:33Z

server/mscalendar/availability.go

 	err := m.Filter(withSuperuserClient)
 	if err != nil {
-		return "", err
+		return "", &StatusSyncJobSummary{}, errors.Wrap(err, "not able to filter the super user client")


Nit pick: In general, functions that return a non-nil error should have the other fields set to nil.

@hanzei Actually here I am not returning nil because, in its parent functions, I am using an attribute of this object, and if I return nil from here that could give panic.

DHaussermann

Tested and passed

When the sync fails for one or more users the job still completes
warn records are now shown is the server log for failed users
A count of processed and failed users is shown in the server logs after the job runs
Retested after last commit for any functional changes
LGTM!

DHaussermann · 2023-03-22T14:23:04Z

@mickmister or @hanzei please merge when you have a chance.
We also need a v1.1.1 versions bump PR.

mickmister · 2023-03-22T14:26:38Z

/update-branch

mattermost-build · 2023-03-22T14:26:40Z

We don't have permissions to update this PR, please contact the submitter to apply the update.

…lendar into MM-244

Kshitij-Katiyar · 2023-03-22T14:34:46Z

/update-branch

@mickmister @hanzei Synced with master

mattermost-build · 2023-03-22T14:34:48Z

We don't have permissions to update this PR, please contact the submitter to apply the update.

Kshitij-Katiyar requested a review from mickmister as a code owner January 30, 2023 12:39

mickmister suggested changes Jan 30, 2023

View reviewed changes

Kshitij-Katiyar mentioned this pull request Jan 31, 2023

[MI-2687]:Fixed review comments given by mattermost team on issue#244 of mscalender plugin Brightscout/mattermost-plugin-mscalendar#3

Merged

[MI-2687]:Fixed review comments given by mattermost team on issue#244…

72e88a4

… of mscalender plugin (#3) * [MI-2687]:Fixed review comments given by mattermost team on issue mattermost#244 of mscalender plugin * [MI-2687]:Fixed unit test cases * [MI-2687]:Fixed review fixes

Kshitij-Katiyar requested a review from mickmister January 31, 2023 09:55

mickmister approved these changes Jan 31, 2023

View reviewed changes

mickmister added the 3: QA Review Requires review by a QA tester label Jan 31, 2023

Kshitij-Katiyar mentioned this pull request Feb 2, 2023

[MI-2705]:Added summary for status sync job Brightscout/mattermost-plugin-mscalendar#4

Merged

Kshitij-Katiyar requested a review from mickmister February 7, 2023 13:08

mickmister approved these changes Feb 7, 2023

View reviewed changes

mickmister requested review from DHaussermann and hanzei February 7, 2023 15:17

hanzei added this to the 244 milestone Feb 7, 2023

hanzei linked an issue Feb 7, 2023 that may be closed by this pull request

Status sync job exits if an error happens for a single user #244

Closed

hanzei removed this from the 244 milestone Feb 7, 2023

hanzei requested changes Feb 7, 2023

View reviewed changes

Merge branch 'master' of github.com:mattermost/mattermost-plugin-msca…

4dbc8a5

…lendar into MM-244

Kshitij-Katiyar requested review from hanzei and removed request for DHaussermann February 8, 2023 06:16

mattermost-build added the Lifecycle/1:stale label Feb 19, 2023

m1lt0n removed the Lifecycle/1:stale label Mar 13, 2023

[MM-244]:Added a check for summary to be nill

9f341be

[MM-244]:Added addtional check for user error

45145da

[MM-244]:Fixed lint errors

e05b93b

hanzei reviewed Mar 21, 2023

View reviewed changes

server/mscalendar/availability.go Outdated Show resolved Hide resolved

[MM-244]:Fixed review comments

c25bd52

DHaussermann requested a review from hanzei March 21, 2023 19:24

hanzei approved these changes Mar 21, 2023

View reviewed changes

DHaussermann approved these changes Mar 22, 2023

View reviewed changes

DHaussermann added 4: Reviews Complete All reviewers have approved the pull request and removed 3: QA Review Requires review by a QA tester labels Mar 22, 2023

Merge branch 'master' of github.com:mattermost/mattermost-plugin-msca…

4acc5cf

…lendar into MM-244

mickmister merged commit 347546a into mattermost:master Mar 22, 2023

mickmister mentioned this pull request Mar 22, 2023

Release 1.1.1 #249

Closed

hanzei mentioned this pull request Mar 23, 2023

Release v1.2.0 #250

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[GH-244]: Fixed issue "Status sync job exits if an error happens for a single user" by added additional logging #245

[GH-244]: Fixed issue "Status sync job exits if an error happens for a single user" by added additional logging #245

Kshitij-Katiyar commented Jan 30, 2023 •

edited

Loading

mattermost-build commented Jan 30, 2023

mickmister left a comment

mickmister left a comment

DHaussermann commented Jan 31, 2023

Kshitij-Katiyar commented Feb 1, 2023 •

edited

Loading

mickmister commented Feb 1, 2023

spirosoik commented Feb 3, 2023

mattermost-build commented Feb 3, 2023

Kshitij-Katiyar commented Feb 6, 2023

hanzei left a comment

hanzei Feb 7, 2023

Kshitij-Katiyar Feb 8, 2023

hanzei Feb 19, 2023

Kshitij-Katiyar Feb 20, 2023 •

edited

Loading

mattermost-build commented Feb 19, 2023

mattermost-build commented Mar 7, 2023

m1lt0n commented Mar 10, 2023 •

edited

Loading

codecov-commenter commented Mar 10, 2023 •

edited

Loading

mickmister commented Mar 10, 2023

DHaussermann commented Mar 14, 2023

Kshitij-Katiyar commented Mar 16, 2023 •

edited

Loading

DHaussermann commented Mar 21, 2023

Kshitij-Katiyar commented Mar 21, 2023 •

edited

Loading

DHaussermann commented Mar 21, 2023

Kshitij-Katiyar commented Mar 21, 2023

hanzei Mar 21, 2023

Kshitij-Katiyar Mar 22, 2023

DHaussermann left a comment

DHaussermann commented Mar 22, 2023

mickmister commented Mar 22, 2023

mattermost-build commented Mar 22, 2023

Kshitij-Katiyar commented Mar 22, 2023

mattermost-build commented Mar 22, 2023

[GH-244]: Fixed issue "Status sync job exits if an error happens for a single user" by added additional logging #245

[GH-244]: Fixed issue "Status sync job exits if an error happens for a single user" by added additional logging #245

Conversation

Kshitij-Katiyar commented Jan 30, 2023 • edited Loading

mattermost-build commented Jan 30, 2023

mickmister left a comment

Choose a reason for hiding this comment

mickmister left a comment

Choose a reason for hiding this comment

DHaussermann commented Jan 31, 2023

Kshitij-Katiyar commented Feb 1, 2023 • edited Loading

mickmister commented Feb 1, 2023

spirosoik commented Feb 3, 2023

mattermost-build commented Feb 3, 2023

Kshitij-Katiyar commented Feb 6, 2023

hanzei left a comment

Choose a reason for hiding this comment

hanzei Feb 7, 2023

Choose a reason for hiding this comment

Kshitij-Katiyar Feb 8, 2023

Choose a reason for hiding this comment

hanzei Feb 19, 2023

Choose a reason for hiding this comment

Kshitij-Katiyar Feb 20, 2023 • edited Loading

Choose a reason for hiding this comment

mattermost-build commented Feb 19, 2023

mattermost-build commented Mar 7, 2023

m1lt0n commented Mar 10, 2023 • edited Loading

codecov-commenter commented Mar 10, 2023 • edited Loading

Codecov Report

mickmister commented Mar 10, 2023

DHaussermann commented Mar 14, 2023

Kshitij-Katiyar commented Mar 16, 2023 • edited Loading

DHaussermann commented Mar 21, 2023

Kshitij-Katiyar commented Mar 21, 2023 • edited Loading

DHaussermann commented Mar 21, 2023

Kshitij-Katiyar commented Mar 21, 2023

hanzei Mar 21, 2023

Choose a reason for hiding this comment

Kshitij-Katiyar Mar 22, 2023

Choose a reason for hiding this comment

DHaussermann left a comment

Choose a reason for hiding this comment

DHaussermann commented Mar 22, 2023

mickmister commented Mar 22, 2023

mattermost-build commented Mar 22, 2023

Kshitij-Katiyar commented Mar 22, 2023

mattermost-build commented Mar 22, 2023

Kshitij-Katiyar commented Jan 30, 2023 •

edited

Loading

Kshitij-Katiyar commented Feb 1, 2023 •

edited

Loading

Kshitij-Katiyar Feb 20, 2023 •

edited

Loading

m1lt0n commented Mar 10, 2023 •

edited

Loading

codecov-commenter commented Mar 10, 2023 •

edited

Loading

Kshitij-Katiyar commented Mar 16, 2023 •

edited

Loading

Kshitij-Katiyar commented Mar 21, 2023 •

edited

Loading