[MM-147] Updated log statements

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

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)
 

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,35 +290,84 @@ 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
 	}
 
 	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
+		}
 		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)

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)