From 442c34c1eeca672cade26f92fe1fc81e89e6c25f Mon Sep 17 00:00:00 2001 From: mickmister <6913320+mickmister@users.noreply.github.com> Date: Thu, 14 Dec 2023 18:01:20 -0500 Subject: [PATCH 1/5] add verbose logging for lhs data code path --- server/api.go | 23 ++++- server/command_test.go | 58 ++++++++++++ server/gitlab/api.go | 66 ++++++++++++- server/gitlab/gitlab.go | 2 +- server/gitlab/mocks/mock_gitlab.go | 8 +- server/mocks/mock_gitlab.go | 8 +- server/plugin.go | 146 +++++++++++++++++++++++++++-- 7 files changed, 292 insertions(+), 19 deletions(-) diff --git a/server/api.go b/server/api.go index 0f5cb8a1d..2d9558ddf 100644 --- a/server/api.go +++ b/server/api.go @@ -554,10 +554,29 @@ func (p *Plugin) getPrDetails(c *UserContext, w http.ResponseWriter, r *http.Req } func (p *Plugin) getLHSData(c *UserContext, w http.ResponseWriter, r *http.Request) { + log := c.Log.With(logger.LogContext{ + "original_token": nil, + "token": nil, + "func": "getLHSData", + }) + var result *gitlab.LHSContent err := p.useGitlabClient(c.GitlabInfo, func(info *gitlab.UserInfo, token *oauth2.Token) error { - resp, err := p.GitlabClient.GetLHSData(c.Ctx, info, token) + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) + + localLog := log.With(logger.LogContext{"func": "getLHSData/useGitlabClient callback"}) + + localLog.Debugf("calling p.GitlabClient.GetLHSData") + resp, err := p.GitlabClient.GetLHSData(c.Ctx, info, token, log) + + // update outer-scope log variable with potentially new token + log = log.With(gitlab.MakeSanitizedTokenLogContext(token)) + localLog = log.With(logger.LogContext{"func": "getLHSData/useGitlabClient callback"}) + + localLog.Debugf("called p.GitlabClient.GetLHSData") + if err != nil { + localLog.WithError(err).Debugf("error calling p.GitlabClient.GetLHSData") return err } result = resp @@ -570,6 +589,8 @@ func (p *Plugin) getLHSData(c *UserContext, w http.ResponseWriter, r *http.Reque return } + log.Debugf("end of getLHSData") + p.writeAPIResponse(w, result) } diff --git a/server/command_test.go b/server/command_test.go index 15a94b557..b5c599d96 100644 --- a/server/command_test.go +++ b/server/command_test.go @@ -76,6 +76,7 @@ func TestSubscribeCommand(t *testing.T) { for _, test := range subscribeCommandTests { t.Run(test.testName, func(t *testing.T) { mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() channelID := "12345" userInfo := &gitlab.UserInfo{} @@ -195,6 +196,8 @@ func TestListWebhookCommand(t *testing.T) { p := new(Plugin) mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + mockedClient := mocks.NewMockGitlab(mockCtrl) encryptedToken, _ := encrypt([]byte(testEncryptionKey), testGitlabToken) @@ -205,6 +208,24 @@ func TestListWebhookCommand(t *testing.T) { api := &plugintest.API{} api.On("KVGet", "_usertoken").Return([]byte(encryptedToken), nil) + api.On("LogDebug", + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + ).Maybe().Return(nil) + p.SetAPI(api) p.client = pluginapi.NewClient(api, p.Driver) @@ -256,6 +277,23 @@ func getTestPlugin(t *testing.T, mockCtrl *gomock.Controller, hooks []*gitlab.We api.On("KVSet", mock.Anything, mock.Anything).Return(nil) api.On("KVSetWithOptions", mock.AnythingOfType("string"), mock.Anything, mock.AnythingOfType("model.PluginKVSetOptions")).Return(true, nil) api.On("PublishWebSocketEvent", mock.Anything, mock.Anything, mock.Anything).Return(nil) + api.On("LogDebug", + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + ).Maybe().Return(nil) p.SetAPI(api) p.client = pluginapi.NewClient(api, p.Driver) @@ -366,6 +404,8 @@ func TestAddWebhookCommand(t *testing.T) { p := new(Plugin) mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + mockedClient := mocks.NewMockGitlab(mockCtrl) if test.scope == "group" { @@ -391,6 +431,24 @@ func TestAddWebhookCommand(t *testing.T) { api := &plugintest.API{} api.On("GetConfig", mock.Anything).Return(conf) api.On("KVGet", "_usertoken").Return([]byte(encryptedToken), nil) + api.On("LogDebug", + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + mock.Anything, + ).Maybe().Return(nil) + p.SetAPI(api) p.client = pluginapi.NewClient(api, p.Driver) diff --git a/server/gitlab/api.go b/server/gitlab/api.go index 63b357c47..cfd3119a0 100644 --- a/server/gitlab/api.go +++ b/server/gitlab/api.go @@ -289,35 +289,99 @@ func (g *gitlab) GetProject(ctx context.Context, user *UserInfo, token *oauth2.T return project, nil } -func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.Token) (*LHSContent, error) { +func sanitizeTokenString(token string) string { + suffixLength := 8 + endIndex := len(token) - suffixLength + return strings.Repeat("*", endIndex) + token[endIndex:] +} + +func MakeSanitizedTokenLogContext(token *oauth2.Token) logger.LogContext { + if token == nil { + return nil + } + + return logger.LogContext{ + "access_token": sanitizeTokenString(token.AccessToken), + "refresh_token": sanitizeTokenString(token.RefreshToken), + "expiry": token.Expiry, + } +} + +func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.Token, log logger.Logger) (*LHSContent, error) { + log = log.With(logger.LogContext{ + "func": "gitlab.getLHSData", + "original_token": MakeSanitizedTokenLogContext(token), + "token": MakeSanitizedTokenLogContext(token), + }) + + log.Debugf("beginning of gitlab.GetLHSData") + + log.Debugf("calling g.GitlabConnect") client, err := g.GitlabConnect(*token) + log = log.With(logger.LogContext{"token": MakeSanitizedTokenLogContext(token)}) + if err != nil { + log.WithError(err).Debugf("error calling g.GitlabConnect") return nil, err } + log.Debugf("called g.GitlabConnect") + grp, ctx := errgroup.WithContext(ctx) var reviews []*MergeRequest grp.Go(func() error { + log.Debugf("calling g.GetReviews") reviews, err = g.GetReviews(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetReviews") + return err + } + + log.Debugf("called g.GetReviews") + return err }) var assignments []*Issue grp.Go(func() error { + log.Debugf("calling g.GetYourAssignments") assignments, err = g.GetYourAssignments(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetYourAssignments") + return err + } + + log.Debugf("called g.GetYourAssignments") + return err }) var mergeRequests []*MergeRequest grp.Go(func() error { + log.Debugf("calling g.GetYourPrs") mergeRequests, err = g.GetYourPrs(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetYourPrs") + return err + } + + log.Debugf("called g.GetYourPrs") + return err }) var unreads []*internGitlab.Todo grp.Go(func() error { + log.Debugf("calling g.GetUnreads") unreads, err = g.GetUnreads(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetUnreads") + return err + } + + log.Debugf("called g.GetUnreads") + return err }) diff --git a/server/gitlab/gitlab.go b/server/gitlab/gitlab.go index fbdc446bc..4464a72c3 100644 --- a/server/gitlab/gitlab.go +++ b/server/gitlab/gitlab.go @@ -32,7 +32,7 @@ type Gitlab interface { GetYourPrDetails(ctx context.Context, log logger.Logger, user *UserInfo, token *oauth2.Token, prList []*PRDetails) ([]*PRDetails, error) GetReviews(ctx context.Context, user *UserInfo, client *internGitlab.Client) ([]*MergeRequest, error) GetYourPrs(ctx context.Context, user *UserInfo, client *internGitlab.Client) ([]*MergeRequest, error) - GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.Token) (*LHSContent, error) + GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.Token, log logger.Logger) (*LHSContent, error) GetYourAssignments(ctx context.Context, user *UserInfo, client *internGitlab.Client) ([]*Issue, error) GetUnreads(ctx context.Context, user *UserInfo, client *internGitlab.Client) ([]*internGitlab.Todo, error) GetProjectHooks(ctx context.Context, user *UserInfo, token *oauth2.Token, owner string, repo string) ([]*WebhookInfo, error) diff --git a/server/gitlab/mocks/mock_gitlab.go b/server/gitlab/mocks/mock_gitlab.go index d5a23f358..21d30c3bc 100644 --- a/server/gitlab/mocks/mock_gitlab.go +++ b/server/gitlab/mocks/mock_gitlab.go @@ -84,18 +84,18 @@ func (mr *MockGitlabMockRecorder) GetIssueByID(arg0, arg1, arg2, arg3, arg4, arg } // GetLHSData mocks base method. -func (m *MockGitlab) GetLHSData(arg0 context.Context, arg1 *gitlab.UserInfo, arg2 *oauth2.Token) (*gitlab.LHSContent, error) { +func (m *MockGitlab) GetLHSData(arg0 context.Context, arg1 *gitlab.UserInfo, arg2 *oauth2.Token, arg3 logger.Logger) (*gitlab.LHSContent, error) { m.ctrl.T.Helper() - ret := m.ctrl.Call(m, "GetLHSData", arg0, arg1, arg2) + ret := m.ctrl.Call(m, "GetLHSData", arg0, arg1, arg2, arg3) ret0, _ := ret[0].(*gitlab.LHSContent) ret1, _ := ret[1].(error) return ret0, ret1 } // GetLHSData indicates an expected call of GetLHSData. -func (mr *MockGitlabMockRecorder) GetLHSData(arg0, arg1, arg2 interface{}) *gomock.Call { +func (mr *MockGitlabMockRecorder) GetLHSData(arg0, arg1, arg2, arg3 interface{}) *gomock.Call { mr.mock.ctrl.T.Helper() - return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetLHSData", reflect.TypeOf((*MockGitlab)(nil).GetLHSData), arg0, arg1, arg2) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetLHSData", reflect.TypeOf((*MockGitlab)(nil).GetLHSData), arg0, arg1, arg2, arg3) } // GetMergeRequestByID mocks base method. diff --git a/server/mocks/mock_gitlab.go b/server/mocks/mock_gitlab.go index d5a23f358..21d30c3bc 100644 --- a/server/mocks/mock_gitlab.go +++ b/server/mocks/mock_gitlab.go @@ -84,18 +84,18 @@ func (mr *MockGitlabMockRecorder) GetIssueByID(arg0, arg1, arg2, arg3, arg4, arg } // GetLHSData mocks base method. -func (m *MockGitlab) GetLHSData(arg0 context.Context, arg1 *gitlab.UserInfo, arg2 *oauth2.Token) (*gitlab.LHSContent, error) { +func (m *MockGitlab) GetLHSData(arg0 context.Context, arg1 *gitlab.UserInfo, arg2 *oauth2.Token, arg3 logger.Logger) (*gitlab.LHSContent, error) { m.ctrl.T.Helper() - ret := m.ctrl.Call(m, "GetLHSData", arg0, arg1, arg2) + ret := m.ctrl.Call(m, "GetLHSData", arg0, arg1, arg2, arg3) ret0, _ := ret[0].(*gitlab.LHSContent) ret1, _ := ret[1].(error) return ret0, ret1 } // GetLHSData indicates an expected call of GetLHSData. -func (mr *MockGitlabMockRecorder) GetLHSData(arg0, arg1, arg2 interface{}) *gomock.Call { +func (mr *MockGitlabMockRecorder) GetLHSData(arg0, arg1, arg2, arg3 interface{}) *gomock.Call { mr.mock.ctrl.T.Helper() - return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetLHSData", reflect.TypeOf((*MockGitlab)(nil).GetLHSData), arg0, arg1, arg2) + return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetLHSData", reflect.TypeOf((*MockGitlab)(nil).GetLHSData), arg0, arg1, arg2, arg3) } // GetMergeRequestByID mocks base method. diff --git a/server/plugin.go b/server/plugin.go index b980f3dd6..5f38f0cff 100644 --- a/server/plugin.go +++ b/server/plugin.go @@ -19,6 +19,7 @@ import ( "github.com/mattermost/mattermost/server/public/plugin" "github.com/mattermost/mattermost/server/public/pluginapi" "github.com/mattermost/mattermost/server/public/pluginapi/cluster" + "github.com/mattermost/mattermost/server/public/pluginapi/experimental/bot/logger" "github.com/mattermost/mattermost/server/public/pluginapi/experimental/bot/poster" "github.com/mattermost/mattermost/server/public/pluginapi/experimental/telemetry" "github.com/pkg/errors" @@ -366,7 +367,11 @@ func (p *Plugin) getGitlabUserInfoByMattermostID(userID string) (*gitlab.UserInf return &userInfo, nil } -func (p *Plugin) migrateGitlabToken(userID string) (*oauth2.Token, *APIErrorResponse) { +func (p *Plugin) migrateGitlabToken(userID string, log logger.Logger) (*oauth2.Token, *APIErrorResponse) { + log = log.With(logger.LogContext{ + "func": "migrateGitlabToken", + }) + config := p.getConfiguration() var userInfo struct { @@ -374,17 +379,43 @@ func (p *Plugin) migrateGitlabToken(userID string) (*oauth2.Token, *APIErrorResp Token *oauth2.Token } + log.Debugf("getting mutex for " + userID + TokenMutexKey) mutex, err := cluster.NewMutex(p.API, userID+TokenMutexKey) if err != nil { + log.WithError(err).Debugf("error getting mutex") return nil, &APIErrorResponse{ID: "", Message: "Unable to obtain mutex for KV migration.", StatusCode: http.StatusInternalServerError} } + + log.Debugf("got mutex. locking mutex") + mutex.Lock() + + log.Debugf("locked mutex") + defer mutex.Unlock() var gitlabTokenBytes []byte + + log.Debugf("calling p.client.KV.Get " + userID + GitlabMigrationTokenKey) err = p.client.KV.Get(userID+GitlabMigrationTokenKey, &gitlabTokenBytes) if err != nil || gitlabTokenBytes == nil { - return p.getGitlabUserTokenByMattermostID(userID) + if err != nil { + log.WithError(err).Debugf("error calling p.client.KV.Get " + userID + GitlabMigrationTokenKey) + } else { + log.Debugf("no bytes returned when calling p.client.KV.Get " + userID + GitlabMigrationTokenKey) + } + + log.Debugf("calling p.getGitlabUserTokenByMattermostID") + storedToken, errRes := p.getGitlabUserTokenByMattermostID(userID) + log.With(logger.LogContext{"storedToken": gitlab.MakeSanitizedTokenLogContext(storedToken)}) + + if errRes != nil { + log.WithError(errRes).Debugf("error calling getGitlabUserTokenByMattermostID") + } else { + log.Debugf("called p.getGitlabUserTokenByMattermostID") + } + + return storedToken, errRes } if err = json.Unmarshal(gitlabTokenBytes, &userInfo); err != nil { @@ -397,6 +428,9 @@ func (p *Plugin) migrateGitlabToken(userID string) (*oauth2.Token, *APIErrorResp } userInfo.Token.AccessToken = unencryptedToken + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(userInfo.Token)}) + + log.Debugf("decrypted access token") var userInfoWithoutToken = &gitlab.UserInfo{ UserID: userInfo.UserID, @@ -406,17 +440,31 @@ func (p *Plugin) migrateGitlabToken(userID string) (*oauth2.Token, *APIErrorResp Settings: userInfo.Settings, } + log.Debugf("calling p.storeGitlabUserInfo") if err = p.storeGitlabUserInfo(userInfoWithoutToken); err != nil { + log.WithError(err).Debugf("error calling p.storeGitlabUserInfo") return nil, &APIErrorResponse{ID: "", Message: "Unable to store user info for KV migration.", StatusCode: http.StatusInternalServerError} } + log.Debugf("called p.storeGitlabUserInfo") + + log.Debugf("calling p.storeGitlabUserToken") if err = p.storeGitlabUserToken(userInfo.UserID, userInfo.Token); err != nil { + log.WithError(err).Debugf("error calling p.storeGitlabUserToken") return nil, &APIErrorResponse{ID: "", Message: "Unable to store token for KV migration.", StatusCode: http.StatusInternalServerError} } + log.Debugf("called p.storeGitlabUserToken") + + log.Debugf("calling p.client.KV.Delete " + userInfo.UserID + GitlabMigrationTokenKey) + if err = p.client.KV.Delete(userInfo.UserID + GitlabMigrationTokenKey); err != nil { + log.WithError(err).Debugf("error calling p.client.KV.Delete " + userInfo.UserID + GitlabMigrationTokenKey) return nil, &APIErrorResponse{ID: "", Message: "Unable to delete KV entry for migration.", StatusCode: http.StatusInternalServerError} } + log.Debugf("called p.client.KV.Delete " + userInfo.UserID + GitlabMigrationTokenKey) + + log.Debugf("end of migrateGitlabToken") return userInfo.Token, nil } @@ -581,11 +629,20 @@ func (p *Plugin) GetToDo(ctx context.Context, user *gitlab.UserInfo) (bool, stri var notificationText, reviewText, assignmentText, mergeRequestText string err := p.useGitlabClient(user, func(info *gitlab.UserInfo, token *oauth2.Token) error { - resp, err := p.GitlabClient.GetLHSData(ctx, info, token) + log := logger.New(p.API).With(logger.LogContext{ + "userid": user.UserID, + "func": "GetToDo/useGitlabClient", + }) + + log.Debugf("calling p.GitlabClient.GetLHSData") + resp, err := p.GitlabClient.GetLHSData(ctx, info, token, log) if err != nil { + log.WithError(err).Debugf("error calling p.GitlabClient.GetLHSData") return err } + log.Debugf("called p.GitlabClient.GetLHSData") + unreads := resp.Unreads notificationCount := 0 notificationContent := "" @@ -821,56 +878,129 @@ func (p *Plugin) handleRevokedToken(info *gitlab.UserInfo) { } } -func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo) (*oauth2.Token, error) { +func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Logger) (*oauth2.Token, error) { + log = log.With(logger.LogContext{ + "func": "getOrFreshTokenWithMutex", + }) + + log.Debugf("beginning of getOrRefreshTokenWithMutex") + + log.Debugf("calling p.getGitlabUserTokenByMattermostID") token, apiErr := p.getGitlabUserTokenByMattermostID(info.UserID) + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) + log.Debugf("called p.getGitlabUserTokenByMattermostID") + if apiErr != nil { - token, apiErr = p.migrateGitlabToken(info.UserID) + log.WithError(apiErr).Debugf("error calling p.getGitlabUserTokenByMattermostID") + + log.Debugf("calling migrateGitlabToken") + token, apiErr = p.migrateGitlabToken(info.UserID, log) + + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) + if apiErr != nil { + log.WithError(apiErr).Debugf("error calling p.migrateGitlabToken") return nil, apiErr } + + log.Debugf("called p.migrateGitlabToken") } if time.Until(token.Expiry) > 1*time.Minute { + log.Debugf("time until expiry is more than one minute. not getting mutex for " + info.UserID + TokenMutexKey) return token, nil } + log.Debugf("time until expiry is less than one minute. getting mutex for " + info.UserID + TokenMutexKey) + mutex, err := cluster.NewMutex(p.API, info.UserID+TokenMutexKey) if err != nil { + log.WithError(err).Debugf("error getting mutex") return nil, err } + log.Debugf("got mutex. locking mutex") + mutex.Lock() + + log.Debugf("mutex locked") + defer mutex.Unlock() + log.Debugf("calling p.getGitlabUserTokenByMattermostID") + lockedToken, apiErr := p.getGitlabUserTokenByMattermostID(info.UserID) + log = log.With(logger.LogContext{"lockedToken": gitlab.MakeSanitizedTokenLogContext(lockedToken)}) + if apiErr != nil { + log.WithError(apiErr).Debugf("error calling p.getGitlabUserTokenByMattermostID") return nil, apiErr } + log.Debugf("called p.getGitlabUserTokenByMattermostID") + if time.Until(lockedToken.Expiry) > 1*time.Minute { + log.Debugf("time until expiry for lockedToken is more than one minute. returning lockedToken") return lockedToken, nil } + log.Debugf("time until expiry for lockedToken is less than one minute. refreshing token") + + log.Debugf("calling p.refreshToken") newToken, err := p.refreshToken(info, lockedToken) + log.With(logger.LogContext{"newToken": gitlab.MakeSanitizedTokenLogContext(newToken)}) + if err != nil { + log.WithError(err).Debugf("error calling p.refreshToken") return nil, err } + log.Debugf("called p.refreshToken") + + log.Debugf("end of getOrRefreshTokenWithMutex") + return newToken, nil } func (p *Plugin) useGitlabClient(info *gitlab.UserInfo, toRun func(info *gitlab.UserInfo, token *oauth2.Token) error) error { - token, err := p.getOrRefreshTokenWithMutex(info) + log := logger.New(p.API).With(logger.LogContext{ + "func": "useGitlabClient", + "func_id": model.NewId(), + "original_token": nil, + "token": nil, + "userid": info.UserID, + }) + + log.Debugf("calling getOrRefreshTokenWithMutex") + token, err := p.getOrRefreshTokenWithMutex(info, log) + + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) + log.Debugf("called getOrRefreshTokenWithMutex") + if err != nil { + log.WithError(err).Debugf("error calling getOrRefreshTokenWithMutex") return err } + log.Debugf("calling toRun") err = toRun(info, token) - if err != nil && strings.Contains(err.Error(), invalidTokenError) { - p.handleRevokedToken(info) + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) + log.Debugf("called toRun") + + if err != nil { + if strings.Contains(err.Error(), invalidTokenError) { + log.WithError(err).Debugf("error calling toRun. contains invalidTokenError message") + log.Debugf("calling p.handleRevokedToken") + p.handleRevokedToken(info) + log.Debugf("called p.handleRevokedToken") + } else { + log.WithError(err).Debugf("error calling toRun. does not contain invalidTokenError message") + } } + log.Debugf("end of useGitlabClient") + return err } From 6f7fe3f1c6f45f0ff88d3b3f47d003070dced359 Mon Sep 17 00:00:00 2001 From: mickmister <6913320+mickmister@users.noreply.github.com> Date: Fri, 15 Dec 2023 06:07:59 -0500 Subject: [PATCH 2/5] more logging --- server/api.go | 23 +++++++++++++++++++++++ server/gitlab/api.go | 10 ++++++---- server/plugin.go | 13 +++++++++++-- 3 files changed, 40 insertions(+), 6 deletions(-) diff --git a/server/api.go b/server/api.go index 2d9558ddf..f35839052 100644 --- a/server/api.go +++ b/server/api.go @@ -34,6 +34,29 @@ const ( func (p *Plugin) ServeHTTP(c *plugin.Context, w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") + if r.URL.Path == "/set-expiry" { + expiry := r.URL.Query().Get("expiry") + userId := r.Header.Get("Mattermost-User-Id") + token, err := p.getGitlabUserTokenByMattermostID(userId) + oldExpiry := token.Expiry + if err != nil { + http.Error(w, err.Error(), 500) + return + } + + expiryMinutes, _ := strconv.ParseInt(expiry, 10, 32) + newExpiry := time.Now().Add(time.Duration(expiryMinutes) * time.Minute) + token.Expiry = newExpiry + p.storeGitlabUserToken(userId, token) + + json.NewEncoder(w).Encode(map[string]string{ + "old_expiry": oldExpiry.String(), + "new_expiry": newExpiry.String(), + }) + + return + } + p.router.ServeHTTP(w, r) } diff --git a/server/gitlab/api.go b/server/gitlab/api.go index cfd3119a0..264d869e8 100644 --- a/server/gitlab/api.go +++ b/server/gitlab/api.go @@ -6,6 +6,7 @@ import ( "net/http" "strings" "sync" + "time" "github.com/mattermost/mattermost/server/public/pluginapi/experimental/bot/logger" @@ -301,9 +302,10 @@ func MakeSanitizedTokenLogContext(token *oauth2.Token) logger.LogContext { } return logger.LogContext{ - "access_token": sanitizeTokenString(token.AccessToken), - "refresh_token": sanitizeTokenString(token.RefreshToken), - "expiry": token.Expiry, + "access_token": sanitizeTokenString(token.AccessToken), + "refresh_token": sanitizeTokenString(token.RefreshToken), + "expiry": token.Expiry, + "expiry_minutes": time.Until(token.Expiry) / time.Minute, } } @@ -654,7 +656,7 @@ func (g *gitlab) GetYourAssignments(ctx context.Context, user *UserInfo, client } } - var result []*Issue + result := []*Issue{} for _, issue := range issues { if issue.Labels != nil { labelsWithDetails, err := g.GetLabelDetails(client, issue.ProjectID, issue.Labels) diff --git a/server/plugin.go b/server/plugin.go index 5f38f0cff..b7e56d41e 100644 --- a/server/plugin.go +++ b/server/plugin.go @@ -843,11 +843,20 @@ func (p *Plugin) HasGroupHook(ctx context.Context, user *gitlab.UserInfo, namesp return found, err } -func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token) (*oauth2.Token, error) { +func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token, log logger.Logger) (*oauth2.Token, error) { + log = log.With(logger.LogContext{ + "func": "refreshToken", + }) + + log.Debugf("beginning of refreshToken") + conf := p.getOAuthConfig() + src := conf.TokenSource(context.Background(), token) + log.Debugf("calling src.Token()") newToken, err := src.Token() // this actually goes and renews the tokens + log = log.With(logger.LogContext{"newToken": gitlab.MakeSanitizedTokenLogContext(newToken)}) if err != nil { if strings.Contains(err.Error(), "\"error\":\"invalid_grant\"") { @@ -948,7 +957,7 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo log.Debugf("time until expiry for lockedToken is less than one minute. refreshing token") log.Debugf("calling p.refreshToken") - newToken, err := p.refreshToken(info, lockedToken) + newToken, err := p.refreshToken(info, lockedToken, log) log.With(logger.LogContext{"newToken": gitlab.MakeSanitizedTokenLogContext(newToken)}) if err != nil { From f10c8fbe530240e5e6853599156de05f0d61e3df Mon Sep 17 00:00:00 2001 From: raghavaggarwal2308 Date: Thu, 18 Jan 2024 15:56:26 +0530 Subject: [PATCH 3/5] [MM-147] Updated log statements --- server/api.go | 20 ++++++++++---------- server/gitlab/api.go | 40 ++++++++++++++++++++++++++-------------- server/plugin.go | 27 +++++++++++---------------- 3 files changed, 47 insertions(+), 40 deletions(-) diff --git a/server/api.go b/server/api.go index daaed8429..05ec35303 100644 --- a/server/api.go +++ b/server/api.go @@ -36,8 +36,8 @@ func (p *Plugin) ServeHTTP(c *plugin.Context, w http.ResponseWriter, r *http.Req if r.URL.Path == "/set-expiry" { expiry := r.URL.Query().Get("expiry") - userId := r.Header.Get("Mattermost-User-Id") - token, err := p.getGitlabUserTokenByMattermostID(userId) + userID := r.Header.Get("Mattermost-User-Id") + token, err := p.getGitlabUserTokenByMattermostID(userID) oldExpiry := token.Expiry if err != nil { http.Error(w, err.Error(), 500) @@ -47,9 +47,9 @@ func (p *Plugin) ServeHTTP(c *plugin.Context, w http.ResponseWriter, r *http.Req expiryMinutes, _ := strconv.ParseInt(expiry, 10, 32) newExpiry := time.Now().Add(time.Duration(expiryMinutes) * time.Minute) token.Expiry = newExpiry - p.storeGitlabUserToken(userId, token) + _ = p.storeGitlabUserToken(userID, token) - json.NewEncoder(w).Encode(map[string]string{ + _ = json.NewEncoder(w).Encode(map[string]string{ "old_expiry": oldExpiry.String(), "new_expiry": newExpiry.String(), }) @@ -578,9 +578,8 @@ func (p *Plugin) getPrDetails(c *UserContext, w http.ResponseWriter, r *http.Req func (p *Plugin) getLHSData(c *UserContext, w http.ResponseWriter, r *http.Request) { log := c.Log.With(logger.LogContext{ - "original_token": nil, - "token": nil, - "func": "getLHSData", + "token": nil, + "func": "getLHSData", }) var result *gitlab.LHSContent @@ -593,15 +592,16 @@ func (p *Plugin) getLHSData(c *UserContext, w http.ResponseWriter, r *http.Reque resp, err := p.GitlabClient.GetLHSData(c.Ctx, info, token, log) // update outer-scope log variable with potentially new token - log = log.With(gitlab.MakeSanitizedTokenLogContext(token)) + log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) localLog = log.With(logger.LogContext{"func": "getLHSData/useGitlabClient callback"}) - localLog.Debugf("called p.GitlabClient.GetLHSData") - if err != nil { localLog.WithError(err).Debugf("error calling p.GitlabClient.GetLHSData") return err } + + localLog.Debugf("called p.GitlabClient.GetLHSData") + result = resp return nil }) diff --git a/server/gitlab/api.go b/server/gitlab/api.go index 369f2069f..428bdf2df 100644 --- a/server/gitlab/api.go +++ b/server/gitlab/api.go @@ -293,7 +293,7 @@ func (g *gitlab) GetProject(ctx context.Context, user *UserInfo, token *oauth2.T func sanitizeTokenString(token string) string { suffixLength := 8 endIndex := len(token) - suffixLength - return strings.Repeat("*", endIndex) + token[endIndex:] + return token[endIndex:] } func MakeSanitizedTokenLogContext(token *oauth2.Token) logger.LogContext { @@ -311,13 +311,10 @@ func MakeSanitizedTokenLogContext(token *oauth2.Token) logger.LogContext { func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.Token, log logger.Logger) (*LHSContent, error) { log = log.With(logger.LogContext{ - "func": "gitlab.getLHSData", - "original_token": MakeSanitizedTokenLogContext(token), - "token": MakeSanitizedTokenLogContext(token), + "func": "gitlab.GetLHSData", + "token": MakeSanitizedTokenLogContext(token), }) - log.Debugf("beginning of gitlab.GetLHSData") - log.Debugf("calling g.GitlabConnect") client, err := g.GitlabConnect(*token) log = log.With(logger.LogContext{"token": MakeSanitizedTokenLogContext(token)}) @@ -347,28 +344,43 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T var issues []*Issue grp.Go(func() error { - log.Debugf("calling g.GetYourAssignments") - log.Debugf("called g.GetYourAssignments") - + log.Debugf("calling g.GetYourAssignedIssues") issues, err = g.GetYourAssignedIssues(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetYourAssignedIssues") + return err + } + + log.Debugf("called g.GetYourAssignedIssues") + return err }) var mergeRequests []*MergeRequest grp.Go(func() error { - log.Debugf("calling g.GetYourPrs") - log.Debugf("called g.GetYourPrs") - + log.Debugf("calling g.GetYourAssignedPrs") mergeRequests, err = g.GetYourAssignedPrs(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetYourAssignedPrs") + return err + } + + log.Debugf("called g.GetYourAssignedPrs") return err }) var todos []*internGitlab.Todo grp.Go(func() error { - log.Debugf("calling g.GetUnreads") - log.Debugf("called g.GetUnreads") + log.Debugf("calling g.GetToDoList") todos, err = g.GetToDoList(ctx, user, client) + if err != nil { + log.WithError(err).Debugf("error calling g.GetToDoList") + return err + } + + log.Debugf("called g.GetToDoList") + return err }) diff --git a/server/plugin.go b/server/plugin.go index 4763c3df7..31f432b70 100644 --- a/server/plugin.go +++ b/server/plugin.go @@ -858,6 +858,8 @@ func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token, lo log = log.With(logger.LogContext{"newToken": gitlab.MakeSanitizedTokenLogContext(newToken)}) if err != nil { + log.WithError(err).Debugf("error calling src.Token()") + if strings.Contains(err.Error(), "\"error\":\"invalid_grant\"") { p.handleRevokedToken(userInfo) } @@ -868,12 +870,16 @@ func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token, lo p.client.Log.Debug("Gitlab token refreshed.", "UserID", userInfo.UserID) if err := p.storeGitlabUserToken(userInfo.UserID, newToken); err != nil { + log.WithError(err).Debugf("Error occurred while storing refreshed token.") + return nil, errors.Wrap(err, "unable to store user info with refreshed token") } return newToken, nil } + log.Debugf("end of refreshToken") + return token, nil } @@ -891,8 +897,6 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo "func": "getOrFreshTokenWithMutex", }) - log.Debugf("beginning of getOrRefreshTokenWithMutex") - log.Debugf("calling p.getGitlabUserTokenByMattermostID") token, apiErr := p.getGitlabUserTokenByMattermostID(info.UserID) @@ -902,7 +906,6 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo if apiErr != nil { log.WithError(apiErr).Debugf("error calling p.getGitlabUserTokenByMattermostID") - log.Debugf("calling migrateGitlabToken") token, apiErr = p.migrateGitlabToken(info.UserID, log) log = log.With(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) @@ -928,16 +931,12 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo return nil, err } - log.Debugf("got mutex. locking mutex") - mutex.Lock() log.Debugf("mutex locked") defer mutex.Unlock() - log.Debugf("calling p.getGitlabUserTokenByMattermostID") - lockedToken, apiErr := p.getGitlabUserTokenByMattermostID(info.UserID) log = log.With(logger.LogContext{"lockedToken": gitlab.MakeSanitizedTokenLogContext(lockedToken)}) @@ -953,9 +952,8 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo return lockedToken, nil } - log.Debugf("time until expiry for lockedToken is less than one minute. refreshing token") + log.Debugf("time until expiry for lockedToken is less than one minute. calling refreshToken") - log.Debugf("calling p.refreshToken") newToken, err := p.refreshToken(info, lockedToken, log) log.With(logger.LogContext{"newToken": gitlab.MakeSanitizedTokenLogContext(newToken)}) @@ -966,18 +964,15 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo log.Debugf("called p.refreshToken") - log.Debugf("end of getOrRefreshTokenWithMutex") - return newToken, nil } func (p *Plugin) useGitlabClient(info *gitlab.UserInfo, toRun func(info *gitlab.UserInfo, token *oauth2.Token) error) error { log := logger.New(p.API).With(logger.LogContext{ - "func": "useGitlabClient", - "func_id": model.NewId(), - "original_token": nil, - "token": nil, - "userid": info.UserID, + "func": "useGitlabClient", + "func_id": model.NewId(), + "token": nil, + "userid": info.UserID, }) log.Debugf("calling getOrRefreshTokenWithMutex") From 666fae464fd23b127f42f9c2d554a98147750fd9 Mon Sep 17 00:00:00 2001 From: raghavaggarwal2308 Date: Thu, 18 Jan 2024 16:09:01 +0530 Subject: [PATCH 4/5] [MM-147] Removed few extra logs --- server/gitlab/api.go | 13 ------------- server/plugin.go | 8 ++------ 2 files changed, 2 insertions(+), 19 deletions(-) diff --git a/server/gitlab/api.go b/server/gitlab/api.go index 428bdf2df..1ca4fb8db 100644 --- a/server/gitlab/api.go +++ b/server/gitlab/api.go @@ -324,8 +324,6 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T return nil, err } - log.Debugf("called g.GitlabConnect") - grp, ctx := errgroup.WithContext(ctx) var reviews []*MergeRequest @@ -336,9 +334,6 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T log.WithError(err).Debugf("error calling g.GetReviews") return err } - - log.Debugf("called g.GetReviews") - return err }) @@ -350,9 +345,6 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T log.WithError(err).Debugf("error calling g.GetYourAssignedIssues") return err } - - log.Debugf("called g.GetYourAssignedIssues") - return err }) @@ -364,8 +356,6 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T log.WithError(err).Debugf("error calling g.GetYourAssignedPrs") return err } - - log.Debugf("called g.GetYourAssignedPrs") return err }) @@ -378,9 +368,6 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T log.WithError(err).Debugf("error calling g.GetToDoList") return err } - - log.Debugf("called g.GetToDoList") - return err }) diff --git a/server/plugin.go b/server/plugin.go index 31f432b70..587edb330 100644 --- a/server/plugin.go +++ b/server/plugin.go @@ -853,7 +853,6 @@ func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token, lo src := conf.TokenSource(context.Background(), token) - log.Debugf("calling src.Token()") newToken, err := src.Token() // this actually goes and renews the tokens log = log.With(logger.LogContext{"newToken": gitlab.MakeSanitizedTokenLogContext(newToken)}) @@ -867,6 +866,8 @@ func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token, lo } if newToken.AccessToken != token.AccessToken { + log.Debugf("token is refreshed") + p.client.Log.Debug("Gitlab token refreshed.", "UserID", userInfo.UserID) if err := p.storeGitlabUserToken(userInfo.UserID, newToken); err != nil { @@ -932,9 +933,6 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo, log logger.Lo } mutex.Lock() - - log.Debugf("mutex locked") - defer mutex.Unlock() lockedToken, apiErr := p.getGitlabUserTokenByMattermostID(info.UserID) @@ -995,9 +993,7 @@ func (p *Plugin) useGitlabClient(info *gitlab.UserInfo, toRun func(info *gitlab. if err != nil { if strings.Contains(err.Error(), invalidTokenError) { log.WithError(err).Debugf("error calling toRun. contains invalidTokenError message") - log.Debugf("calling p.handleRevokedToken") p.handleRevokedToken(info) - log.Debugf("called p.handleRevokedToken") } else { log.WithError(err).Debugf("error calling toRun. does not contain invalidTokenError message") } From 9afee46dcc0f667608dd6264807a3143cadfd3bf Mon Sep 17 00:00:00 2001 From: raghavaggarwal2308 Date: Thu, 18 Jan 2024 16:22:09 +0530 Subject: [PATCH 5/5] [MM-147] Fix the log value of expiry_minutes --- server/gitlab/api.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/gitlab/api.go b/server/gitlab/api.go index 1ca4fb8db..dbf9e2552 100644 --- a/server/gitlab/api.go +++ b/server/gitlab/api.go @@ -305,7 +305,7 @@ func MakeSanitizedTokenLogContext(token *oauth2.Token) logger.LogContext { "access_token": sanitizeTokenString(token.AccessToken), "refresh_token": sanitizeTokenString(token.RefreshToken), "expiry": token.Expiry, - "expiry_minutes": time.Until(token.Expiry) / time.Minute, + "expiry_minutes": time.Until(token.Expiry).Minutes(), } }