diff --git a/server/api.go b/server/api.go index 8443fea8a..05ec35303 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) } @@ -554,12 +577,31 @@ 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{ + "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(logger.LogContext{"token": gitlab.MakeSanitizedTokenLogContext(token)}) + localLog = log.With(logger.LogContext{"func": "getLHSData/useGitlabClient callback"}) + if err != nil { + localLog.WithError(err).Debugf("error calling p.GitlabClient.GetLHSData") return err } + + localLog.Debugf("called p.GitlabClient.GetLHSData") + result = resp return nil }) @@ -570,6 +612,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 b6c7f0f81..a7616c1c6 100644 --- a/server/command_test.go +++ b/server/command_test.go @@ -99,6 +99,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{ @@ -220,6 +221,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) @@ -230,6 +233,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) @@ -311,6 +332,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) api.On("LogWarn", mock.AnythingOfTypeArgument("string"), mock.AnythingOfTypeArgument("string"), @@ -427,6 +465,8 @@ func TestAddWebhookCommand(t *testing.T) { p := new(Plugin) mockCtrl := gomock.NewController(t) + defer mockCtrl.Finish() + mockedClient := mocks.NewMockGitlab(mockCtrl) if test.scope == "group" { @@ -452,6 +492,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 2766da910..dbf88337f 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" @@ -289,9 +290,37 @@ 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 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, + "expiry_minutes": time.Until(token.Expiry).Minutes(), + } +} + +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", + "token": MakeSanitizedTokenLogContext(token), + }) + + 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 } @@ -299,25 +328,46 @@ func (g *gitlab) GetLHSData(ctx context.Context, user *UserInfo, token *oauth2.T 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 + } return err }) var issues []*Issue grp.Go(func() error { + 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 + } return err }) var mergeRequests []*MergeRequest grp.Go(func() error { + 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 + } return err }) var todos []*internGitlab.Todo grp.Go(func() error { + 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 + } return err }) @@ -590,7 +640,7 @@ func (g *gitlab) GetYourAssignedIssues(ctx context.Context, user *UserInfo, clie } } - 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/gitlab/gitlab.go b/server/gitlab/gitlab.go index 3fbfcc134..a17da1b7f 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) GetYourAssignedPrs(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) GetYourAssignedIssues(ctx context.Context, user *UserInfo, client *internGitlab.Client) ([]*Issue, error) GetToDoList(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 95eb59d33..21180fe7e 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 95eb59d33..21180fe7e 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 13cb0345b..2639c1dc3 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" @@ -363,7 +364,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 { @@ -371,17 +376,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 { @@ -394,6 +425,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, @@ -403,17 +437,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 } @@ -578,11 +626,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") + todos := resp.Todos notificationCount := 0 notificationContent := "" @@ -782,13 +839,23 @@ 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) newToken, err := src.Token() // this actually goes and renews the tokens + 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) } @@ -796,15 +863,21 @@ func (p *Plugin) refreshToken(userInfo *gitlab.UserInfo, token *oauth2.Token) (* } 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 { + 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 } @@ -817,22 +890,42 @@ 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("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") + + 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 } @@ -840,33 +933,70 @@ func (p *Plugin) getOrRefreshTokenWithMutex(info *gitlab.UserInfo) (*oauth2.Toke defer mutex.Unlock() 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 } - newToken, err := p.refreshToken(info, lockedToken) + log.Debugf("time until expiry for lockedToken is less than one minute. calling refreshToken") + + newToken, err := p.refreshToken(info, lockedToken, log) + 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") + 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(), + "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") + p.handleRevokedToken(info) + } else { + log.WithError(err).Debugf("error calling toRun. does not contain invalidTokenError message") + } } + log.Debugf("end of useGitlabClient") + return err }