Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Improved logging #480

Merged
merged 15 commits into from
Feb 1, 2024
Merged

Improved logging #480

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
15 commits
Select commit Hold shift + click to select a range
3733de7
remove .Times(x) on various mock apis
lieut-data Jan 11, 2024
10df322
stop trying to mock logs
lieut-data Jan 12, 2024
1f89177
s/"Error"/"error"/g
lieut-data Jan 9, 2024
15aaa2c
fix spurious mutex_cron_monitoring_system failures
lieut-data Jan 11, 2024
ff35d04
error -> warn when not actionable
lieut-data Jan 9, 2024
864b836
warn -> error when actionable
lieut-data Jan 19, 2024
b4ac6ad
debug -> error when actionable
lieut-data Jan 10, 2024
338ebd1
debug -> warn when error involved
lieut-data Jan 9, 2024
160abcf
debug -> info when not high volume
lieut-data Jan 10, 2024
014103c
remove high-volume debug logs
lieut-data Jan 11, 2024
f2e176c
remove logs of minimal value
lieut-data Jan 10, 2024
2e47855
improved monitoring job logging
lieut-data Jan 10, 2024
98add74
snake_case for log parameters
lieut-data Jan 30, 2024
0f714f7
skip logging cipheredText in log
lieut-data Jan 30, 2024
51334cd
wrap vs redundant log
lieut-data Jan 30, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
112 changes: 51 additions & 61 deletions server/api.go
View file
Open in desktop

Large diffs are not rendered by default.

10 changes: 5 additions & 5 deletions server/api_mock.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,13 +29,13 @@ func (a *API) registerClientMock() {
func (a *API) resetMSTeamsClientMocks(w http.ResponseWriter, r *http.Request) {
userID := r.Header.Get("Mattermost-User-Id")
if userID == "" {
a.p.API.LogError("Not authorized")
a.p.API.LogWarn("Not authorized")
http.Error(w, "not authorized", http.StatusUnauthorized)
return
}

if !a.p.API.HasPermissionTo(userID, model.PermissionManageSystem) {
a.p.API.LogError("Insufficient permissions", "UserID", userID)
a.p.API.LogWarn("Insufficient permissions", "user_id", userID)
http.Error(w, "not able to authorize the user", http.StatusForbidden)
return
}
Expand All @@ -50,13 +50,13 @@ func (a *API) resetMSTeamsClientMocks(w http.ResponseWriter, r *http.Request) {
func (a *API) addMSTeamsClientMock(w http.ResponseWriter, r *http.Request) {
userID := r.Header.Get("Mattermost-User-Id")
if userID == "" {
a.p.API.LogError("Not authorized")
a.p.API.LogWarn("Not authorized")
http.Error(w, "not authorized", http.StatusUnauthorized)
return
}

if !a.p.API.HasPermissionTo(userID, model.PermissionManageSystem) {
a.p.API.LogError("Insufficient permissions", "UserID", userID)
a.p.API.LogWarn("Insufficient permissions", "user_id", userID)
http.Error(w, "not able to authorize the user", http.StatusForbidden)
return
}
Expand Down Expand Up @@ -162,7 +162,7 @@ func (a *API) addMSTeamsClientMock(w http.ResponseWriter, r *http.Request) {
}

func getClientMock(p *Plugin) *mocks.Client {
p.API.LogDebug("Using mock client")
p.API.LogInfo("Using mock client")

if clientMock != nil {
return clientMock
Expand Down
22 changes: 4 additions & 18 deletions server/api_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -169,7 +169,6 @@ func TestSubscriptionNewMesage(t *testing.T) {
},
func() {
plugin.store.(*storemocks.Store).On("GetTokenForMattermostUser", "bot-user-id").Return(&fakeToken, nil).Times(1)
plugin.API.(*plugintest.API).On("LogError", "Unable to process created activity", "activity", mock.Anything, "error", "Invalid webhook secret").Return(nil).Times(1)
},
http.StatusBadRequest,
"Invalid webhook secret\n",
Expand All @@ -190,10 +189,9 @@ func TestSubscriptionNewMesage(t *testing.T) {
func() {
plugin.configuration.CertificateKey = "test"
plugin.store.(*storemocks.Store).On("GetTokenForMattermostUser", "bot-user-id").Return(&fakeToken, nil)
plugin.API.(*plugintest.API).On("LogError", "Invalid encrypted content", "error", "invalid certificate key").Return(nil)
},
http.StatusBadRequest,
"invalid certificate key\n\n",
"Unable to get private key: invalid certificate key\n\n",
},
{
"Non encrypted message on encrypted subscription",
Expand Down Expand Up @@ -294,7 +292,6 @@ func TestGetAvatarNotFound(t *testing.T) {

plugin.store.(*storemocks.Store).On("GetAvatarCache", "user-id").Return(nil, &model.AppError{Message: "not-found"}).Times(1)
plugin.msteamsAppClient.(*clientmocks.Client).On("GetUserAvatar", "user-id").Return(nil, errors.New("not-found")).Times(1)
plugin.API.(*plugintest.API).On("LogError", "Unable to get user avatar", "msteamsUserID", "user-id", "error", "not-found").Return(nil)
plugin.metricsService.(*metricsmocks.Metrics).On("IncrementHTTPErrors").Times(1)

w := httptest.NewRecorder()
Expand Down Expand Up @@ -346,7 +343,6 @@ func TestProcessActivity(t *testing.T) {
{
Name: "ProcessActivity: Valid body with invalid webhook secret",
SetupAPI: func(api *plugintest.API) {
api.On("LogError", "Unable to process created activity", "activity", mock.Anything, "error", mock.Anything).Times(1)
},
SetupClient: func(client *clientmocks.Client, uclient *clientmocks.Client) {},
SetupStore: func(store *storemocks.Store) {},
Expand Down Expand Up @@ -463,7 +459,6 @@ func TestProcessLifecycle(t *testing.T) {
{
Name: "ProcessLifecycle: Valid body with invalid webhook secret",
SetupAPI: func(api *plugintest.API) {
api.On("LogError", "Invalid webhook secret received in lifecycle event").Times(1)
},
SetupClient: func(client *clientmocks.Client, uclient *clientmocks.Client) {},
SetupStore: func(store *storemocks.Store) {},
Expand Down Expand Up @@ -575,7 +570,6 @@ func TestAutocompleteTeams(t *testing.T) {
{
Name: "AutocompleteTeams: Unable to get client for the user",
SetupAPI: func(api *plugintest.API) {
api.On("LogError", "Unable to get the client for user", "MMUserID", testutils.GetID(), "Error", "not connected user").Once()
},
SetupStore: func(store *storemocks.Store) {
store.On("GetTokenForMattermostUser", testutils.GetID()).Return(nil, nil).Times(1)
Expand All @@ -587,7 +581,6 @@ func TestAutocompleteTeams(t *testing.T) {
{
Name: "AutocompleteTeams: Unable to get the teams list",
SetupAPI: func(api *plugintest.API) {
api.On("LogError", "Unable to get the MS Teams teams", "Error", "unable to get the teams list").Once()
},
SetupStore: func(store *storemocks.Store) {
store.On("GetTokenForMattermostUser", testutils.GetID()).Return(&fakeToken, nil).Times(1)
Expand All @@ -603,7 +596,6 @@ func TestAutocompleteTeams(t *testing.T) {
{
Name: "AutocompleteTeams: Valid",
SetupAPI: func(api *plugintest.API) {
api.On("LogDebug", "Successfully fetched the list of teams", "Count", 2).Once()
},
SetupStore: func(store *storemocks.Store) {
store.On("GetTokenForMattermostUser", testutils.GetID()).Return(&fakeToken, nil).Times(1)
Expand Down Expand Up @@ -684,7 +676,6 @@ func TestAutocompleteChannels(t *testing.T) {
{
Name: "AutocompleteChannels: Unable to get client for the user",
SetupAPI: func(api *plugintest.API) {
api.On("LogError", "Unable to get the client for user", "MMUserID", testutils.GetID(), "Error", "not connected user").Once()
},
QueryParams: "mockData-1 mockData-2 mockData-3",
SetupStore: func(store *storemocks.Store) {
Expand All @@ -697,7 +688,6 @@ func TestAutocompleteChannels(t *testing.T) {
{
Name: "AutocompleteChannels: Unable to get the channels list",
SetupAPI: func(api *plugintest.API) {
api.On("LogError", "Unable to get the channels for MS Teams team", "TeamID", "mockData-3", "Error", "unable to get the channels list").Once()
},
QueryParams: "mockData-1 mockData-2 mockData-3",
SetupStore: func(store *storemocks.Store) {
Expand All @@ -714,7 +704,6 @@ func TestAutocompleteChannels(t *testing.T) {
{
Name: "AutocompleteChannels: Valid",
SetupAPI: func(api *plugintest.API) {
api.On("LogDebug", "Successfully fetched the list of channels for MS Teams team", "TeamID", "mockData-3", "Count", 2).Once()
},
QueryParams: "mockData-1 mockData-2 mockData-3",
SetupStore: func(store *storemocks.Store) {
Expand Down Expand Up @@ -883,7 +872,6 @@ func TestConnect(t *testing.T) {
{
Name: "connect: Error in storing the OAuth state",
SetupPlugin: func(api *plugintest.API) {
api.On("LogError", "Error in storing the OAuth state", "error", "error in storing the oauth state").Return(nil).Times(1)
},
SetupStore: func(store *storemocks.Store) {
store.On("StoreOAuth2State", mock.AnythingOfType("string")).Return(errors.New("error in storing the oauth state")).Times(1)
Expand All @@ -894,7 +882,6 @@ func TestConnect(t *testing.T) {
{
Name: "connect: Error in storing the code verifier",
SetupPlugin: func(api *plugintest.API) {
api.On("LogError", "Error in storing the code verifier", "error", "error in storing the code verifier").Return(nil).Times(1)
api.On("KVSet", mock.AnythingOfType("string"), mock.AnythingOfType("[]uint8")).Return(&model.AppError{
Message: "error in storing the code verifier",
}).Times(1)
Expand All @@ -914,6 +901,7 @@ func TestConnect(t *testing.T) {
}

mockAPI := &plugintest.API{}
testutils.MockLogs(mockAPI)
plugin.SetAPI(mockAPI)

defer mockAPI.AssertExpectations(t)
Expand Down Expand Up @@ -953,7 +941,6 @@ func TestGetConnectedUsers(t *testing.T) {
Name: "getConnectedUsers: Insufficient permissions for the user",
SetupPlugin: func(api *plugintest.API) {
api.On("HasPermissionTo", testutils.GetUserID(), model.PermissionManageSystem).Return(false).Times(1)
api.On("LogError", "Insufficient permissions", "UserID", testutils.GetUserID()).Return(nil).Times(1)
},
SetupStore: func(store *storemocks.Store) {},
ExpectedStatusCode: http.StatusForbidden,
Expand All @@ -963,7 +950,6 @@ func TestGetConnectedUsers(t *testing.T) {
Name: "getConnectedUsers: Unable to get the list of connected users from the store",
SetupPlugin: func(api *plugintest.API) {
api.On("HasPermissionTo", testutils.GetUserID(), model.PermissionManageSystem).Return(true).Times(1)
api.On("LogError", "Unable to get connected users list", "Error", ("unable to get the list of connected users from the store")).Return(nil).Times(1)
},
SetupStore: func(store *storemocks.Store) {
store.On("GetConnectedUsers", 0, 100).Return(nil, errors.New("unable to get the list of connected users from the store")).Times(1)
Expand Down Expand Up @@ -1006,6 +992,7 @@ func TestGetConnectedUsers(t *testing.T) {
}

mockAPI := &plugintest.API{}
testutils.MockLogs(mockAPI)

plugin.SetAPI(mockAPI)
defer mockAPI.AssertExpectations(t)
Expand Down Expand Up @@ -1045,7 +1032,6 @@ func TestGetConnectedUsersFile(t *testing.T) {
Name: "getConnectedUsers: Insufficient permissions for the user",
SetupPlugin: func(api *plugintest.API) {
api.On("HasPermissionTo", testutils.GetUserID(), model.PermissionManageSystem).Return(false).Times(1)
api.On("LogError", "Insufficient permissions", "UserID", testutils.GetUserID()).Return(nil).Times(1)
},
SetupStore: func(store *storemocks.Store) {},
ExpectedStatusCode: http.StatusForbidden,
Expand All @@ -1055,7 +1041,6 @@ func TestGetConnectedUsersFile(t *testing.T) {
Name: "getConnectedUsers: Unable to get the list of connected users from the store",
SetupPlugin: func(api *plugintest.API) {
api.On("HasPermissionTo", testutils.GetUserID(), model.PermissionManageSystem).Return(true).Times(1)
api.On("LogError", "Unable to get connected users list", "Error", ("unable to get the list of connected users from the store")).Return(nil).Times(1)
},
SetupStore: func(store *storemocks.Store) {
store.On("GetConnectedUsers", 0, 100).Return(nil, errors.New("unable to get the list of connected users from the store")).Times(1)
Expand Down Expand Up @@ -1099,6 +1084,7 @@ func TestGetConnectedUsersFile(t *testing.T) {

mockAPI := &plugintest.API{}
plugin.SetAPI(mockAPI)
testutils.MockLogs(mockAPI)

defer mockAPI.AssertExpectations(t)

Expand Down
38 changes: 19 additions & 19 deletions server/command.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ const commandWaitingMessage = "Please wait while your request is being processed
func (p *Plugin) createMsteamsSyncCommand() *model.Command {
iconData, err := command.GetIconData(p.API, "assets/msteams-sync-icon.svg")
if err != nil {
p.API.LogError("Unable to get the MS Teams icon for the slash command")
p.API.LogWarn("Unable to get the MS Teams icon for the slash command")
}

return &model.Command{
Expand Down Expand Up @@ -200,13 +200,13 @@ func (p *Plugin) executeLinkCommand(args *model.CommandArgs, parameters []string
p.sendBotEphemeralPost(args.UserId, args.ChannelId, commandWaitingMessage)
channelsSubscription, err := p.GetClientForApp().SubscribeToChannel(channelLink.MSTeamsTeam, channelLink.MSTeamsChannel, p.GetURL()+"/", p.getConfiguration().WebhookSecret, p.getBase64Certificate())
if err != nil {
p.API.LogDebug("Unable to subscribe to the channel", "channelID", channelLink.MattermostChannelID, "error", err.Error())
p.API.LogWarn("Unable to subscribe to the channel", "channel_id", channelLink.MattermostChannelID, "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, "Unable to subscribe to the channel")
}

p.GetMetrics().ObserveSubscription(metrics.SubscriptionConnected)
if err = p.store.StoreChannelLink(&channelLink); err != nil {
p.API.LogDebug("Unable to create the new link", "error", err.Error())
p.API.LogWarn("Unable to create the new link", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, "Unable to create new link.")
}

Expand Down Expand Up @@ -242,30 +242,30 @@ func (p *Plugin) executeUnlinkCommand(args *model.CommandArgs) (*model.CommandRe

link, err := p.store.GetLinkByChannelID(channel.Id)
if err != nil {
p.API.LogDebug("Unable to get the link by channel ID", "error", err.Error())
p.API.LogWarn("Unable to get the link by channel ID", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, "This Mattermost channel is not linked to any MS Teams channel.")
}

if err = p.store.DeleteLinkByChannelID(channel.Id); err != nil {
p.API.LogDebug("Unable to delete the link by channel ID", "error", err.Error())
p.API.LogWarn("Unable to delete the link by channel ID", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, "Unable to delete link.")
}

p.sendBotEphemeralPost(args.UserId, args.ChannelId, "The MS Teams channel is no longer linked to this Mattermost channel.")

subscription, err := p.store.GetChannelSubscriptionByTeamsChannelID(link.MSTeamsChannel)
if err != nil {
p.API.LogDebug("Unable to get the subscription by MS Teams channel ID", "error", err.Error())
p.API.LogWarn("Unable to get the subscription by MS Teams channel ID", "error", err.Error())
return &model.CommandResponse{}, nil
}

if err = p.store.DeleteSubscription(subscription.SubscriptionID); err != nil {
p.API.LogDebug("Unable to delete the subscription from the DB", "subscriptionID", subscription.SubscriptionID, "error", err.Error())
p.API.LogWarn("Unable to delete the subscription from the DB", "subscription_id", subscription.SubscriptionID, "error", err.Error())
return &model.CommandResponse{}, nil
}

if err = p.GetClientForApp().DeleteSubscription(subscription.SubscriptionID); err != nil {
p.API.LogDebug("Unable to delete the subscription on MS Teams", "subscriptionID", subscription.SubscriptionID, "error", err.Error())
p.API.LogWarn("Unable to delete the subscription on MS Teams", "subscription_id", subscription.SubscriptionID, "error", err.Error())
}

return &model.CommandResponse{}, nil
Expand Down Expand Up @@ -304,7 +304,7 @@ func (p *Plugin) executeShowLinksCommand(args *model.CommandArgs) (*model.Comman

links, err := p.store.ListChannelLinksWithNames()
if err != nil {
p.API.LogDebug("Unable to get links from store", "Error", err.Error())
p.API.LogWarn("Unable to get links from store", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, "Something went wrong.")
}

Expand Down Expand Up @@ -386,7 +386,7 @@ func (p *Plugin) GetMSTeamsTeamDetails(msTeamsTeamIDsVsNames map[string]string)
teamsQuery = strings.TrimSuffix(teamsQuery, ", ") + ")"
msTeamsTeams, err := p.GetClientForApp().GetTeams(teamsQuery)
if err != nil {
p.API.LogDebug("Unable to get the MS Teams teams information", "Error", err.Error())
p.API.LogWarn("Unable to get the MS Teams teams information", "error", err.Error())
return true
}

Expand All @@ -402,7 +402,7 @@ func (p *Plugin) GetMSTeamsChannelDetailsForAllTeams(msTeamsTeamIDsVsChannelsQue
for teamID, channelsQuery := range msTeamsTeamIDsVsChannelsQuery {
channels, err := p.GetClientForApp().GetChannelsInTeam(teamID, channelsQuery+")")
if err != nil {
p.API.LogDebug("Unable to get the MS Teams channel information for the team", "TeamID", teamID, "Error", err.Error())
p.API.LogWarn("Unable to get the MS Teams channel information for the team", "team_id", teamID, "error", err.Error())
errorsFound = true
}

Expand All @@ -422,14 +422,14 @@ func (p *Plugin) executeConnectCommand(args *model.CommandArgs) (*model.CommandR
genericErrorMessage := "Error in trying to connect the account, please try again."
presentInWhitelist, err := p.store.IsUserPresentInWhitelist(args.UserId)
if err != nil {
p.API.LogError("Error in checking if a user is present in whitelist", "UserID", args.UserId, "Error", err.Error())
p.API.LogWarn("Error in checking if a user is present in whitelist", "user_id", args.UserId, "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

if !presentInWhitelist {
whitelistSize, err := p.store.GetSizeOfWhitelist()
if err != nil {
p.API.LogError("Error in getting the size of whitelist", "Error", err.Error())
p.API.LogWarn("Error in getting the size of whitelist", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

Expand All @@ -440,13 +440,13 @@ func (p *Plugin) executeConnectCommand(args *model.CommandArgs) (*model.CommandR

state := fmt.Sprintf("%s_%s", model.NewId(), args.UserId)
if err := p.store.StoreOAuth2State(state); err != nil {
p.API.LogError("Error in storing the OAuth state", "error", err.Error())
p.API.LogWarn("Error in storing the OAuth state", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

codeVerifier := model.NewId()
if appErr := p.API.KVSet("_code_verifier_"+args.UserId, []byte(codeVerifier)); appErr != nil {
p.API.LogError("Error in storing the code verifier", "error", appErr.Error())
p.API.LogWarn("Error in storing the code verifier", "error", appErr.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

Expand All @@ -467,14 +467,14 @@ func (p *Plugin) executeConnectBotCommand(args *model.CommandArgs) (*model.Comma
genericErrorMessage := "Error in trying to connect the bot account, please try again."
presentInWhitelist, err := p.store.IsUserPresentInWhitelist(p.userID)
if err != nil {
p.API.LogError("Error in checking if the bot user is present in whitelist", "BotUserID", p.userID, "Error", err.Error())
p.API.LogWarn("Error in checking if the bot user is present in whitelist", "bot_user_id", p.userID, "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

if !presentInWhitelist {
whitelistSize, err := p.store.GetSizeOfWhitelist()
if err != nil {
p.API.LogError("Error in getting the size of whitelist", "Error", err.Error())
p.API.LogWarn("Error in getting the size of whitelist", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

Expand All @@ -485,7 +485,7 @@ func (p *Plugin) executeConnectBotCommand(args *model.CommandArgs) (*model.Comma

state := fmt.Sprintf("%s_%s", model.NewId(), p.userID)
if err := p.store.StoreOAuth2State(state); err != nil {
p.API.LogError("Error in storing the OAuth state", "error", err.Error())
p.API.LogWarn("Error in storing the OAuth state", "error", err.Error())
return p.cmdError(args.UserId, args.ChannelId, genericErrorMessage)
}

Expand Down Expand Up @@ -521,7 +521,7 @@ func (p *Plugin) executeDisconnectCommand(args *model.CommandArgs) (*model.Comma

p.sendBotEphemeralPost(args.UserId, args.ChannelId, "Your account has been disconnected.")
if err := p.store.DeleteDMAndGMChannelPromptTime(args.UserId); err != nil {
p.API.LogDebug("Unable to delete the last prompt timestamp for the user", "MMUserID", args.UserId, "Error", err.Error())
p.API.LogWarn("Unable to delete the last prompt timestamp for the user", "user_id", args.UserId, "error", err.Error())
}

return &model.CommandResponse{}, nil
Expand Down
Loading
Loading