From 4e154756bd433ad230f930859f5d693889fdcb37 Mon Sep 17 00:00:00 2001 From: Agniva De Sarker Date: Wed, 19 Aug 2020 23:27:48 +0530 Subject: [PATCH] MM-27648: Fix a hub deadlock while revoking session (#15293) * MM-27648: Fix a hub deadlock while revoking session This is a bug which has always been there in the codebase. And it can only occur in the extreme of edge-cases. Following is the call trace due to which this happens: ``` 0 0x0000000001dfea68 in github.com/mattermost/mattermost-server/v5/app.(*Hub).InvalidateUser // deadlock at ./app/web_hub.go:369 1 0x0000000001dfc0bd in github.com/mattermost/mattermost-server/v5/app.(*App).InvalidateWebConnSessionCacheForUser at ./app/web_hub.go:109 2 0x0000000001db1be5 in github.com/mattermost/mattermost-server/v5/app.(*App).ClearSessionCacheForUserSkipClusterSend at ./app/session.go:209 3 0x0000000001db1763 in github.com/mattermost/mattermost-server/v5/app.(*App).ClearSessionCacheForUser at ./app/session.go:170 4 0x0000000001db2d2f in github.com/mattermost/mattermost-server/v5/app.(*App).RevokeSession at ./app/session.go:275 5 0x0000000001db2c09 in github.com/mattermost/mattermost-server/v5/app.(*App).RevokeSessionById at ./app/session.go:260 6 0x0000000001daf442 in github.com/mattermost/mattermost-server/v5/app.(*App).GetSession at ./app/session.go:93 7 0x0000000001df93f4 in github.com/mattermost/mattermost-server/v5/app.(*WebConn).IsAuthenticated at ./app/web_conn.go:271 8 0x0000000001dfa29b in github.com/mattermost/mattermost-server/v5/app.(*WebConn).shouldSendEvent at ./app/web_conn.go:323 9 0x0000000001e2667e in github.com/mattermost/mattermost-server/v5/app.(*Hub).Start.func1.3 // starting from hub at ./app/web_hub.go:491 10 0x0000000001e27c01 in github.com/mattermost/mattermost-server/v5/app.(*Hub).Start.func1 at ./app/web_hub.go:504 11 0x0000000001e27ee2 in github.com/mattermost/mattermost-server/v5/app.(*Hub).Start.func2 at ./app/web_hub.go:528 12 0x0000000000473811 in runtime.goexit at /usr/local/go/src/runtime/asm_amd64.s:1373 ``` The stars have to align in such a way that the session idle timeout _has_ to happen _exactly_ when a broadcast is happening for that user. Only then, this code path gets triggered. Since this is an extreme rabbit hole of calls, I have not attempted any big refactors and went with the most sensible approach which is to make the RevokeSessionById call asynchronous. There are 2 main reasons: - It was already treated as an asynchronous call because it happened during an error condition and we were not checking for the return value anyways. - Session idle timeout is a relatively infrequent event, so creating unbounded goroutines is not a concern. As a bonus, we also get to check the error return and log it. https://mattermost.atlassian.net/browse/MM-27648 * Add a test case * Fix an incorrect comment --- app/session.go | 14 +++++++- app/web_hub_test.go | 86 +++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 99 insertions(+), 1 deletion(-) diff --git a/app/session.go b/app/session.go index 6da7c61589..c9c8eff9a5 100644 --- a/app/session.go +++ b/app/session.go @@ -90,7 +90,19 @@ func (a *App) GetSession(token string) (*model.Session, *model.AppError) { timeout := int64(*a.Config().ServiceSettings.SessionIdleTimeoutInMinutes) * 1000 * 60 if (model.GetMillis() - session.LastActivityAt) > timeout { - a.RevokeSessionById(session.Id) + // Revoking the session is an asynchronous task anyways since we are not checking + // for the return value of the call before returning the error. + // So moving this to a goroutine has 2 advantages: + // 1. We are treating this as a proper asynchronous task. + // 2. This also fixes a race condition in the web hub, where GetSession + // gets called from (*WebConn).isMemberOfTeam and revoking a session involves + // clearing the webconn cache, which needs the hub again. + a.Srv().Go(func() { + err := a.RevokeSessionById(session.Id) + if err != nil { + mlog.Warn("Error while revoking session", mlog.Err(err)) + } + }) return nil, model.NewAppError("GetSession", "api.context.invalid_token.error", map[string]interface{}{"Token": token}, "idle timeout", http.StatusUnauthorized) } } diff --git a/app/web_hub_test.go b/app/web_hub_test.go index 567d2a4510..431d9599d4 100644 --- a/app/web_hub_test.go +++ b/app/web_hub_test.go @@ -13,9 +13,11 @@ import ( "github.com/gorilla/websocket" goi18n "github.com/mattermost/go-i18n/i18n" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/mock" "github.com/stretchr/testify/require" "github.com/mattermost/mattermost-server/v5/model" + "github.com/mattermost/mattermost-server/v5/store/storetest/mocks" ) func dummyWebsocketHandler(t *testing.T) http.HandlerFunc { @@ -108,6 +110,90 @@ func TestHubStopRaceCondition(t *testing.T) { } } +func TestHubSessionRevokeRace(t *testing.T) { + th := SetupWithStoreMock(t) + defer th.TearDown() + + sess1 := &model.Session{ + Id: "id1", + UserId: "user1", + DeviceId: "", + Token: "sesstoken", + ExpiresAt: model.GetMillis() + 300000, + LastActivityAt: 10000, + } + + mockStore := th.App.Srv().Store.(*mocks.Store) + + mockUserStore := mocks.UserStore{} + mockUserStore.On("Count", mock.Anything).Return(int64(10), nil) + mockUserStore.On("GetUnreadCount", mock.AnythingOfType("string")).Return(int64(1), nil) + mockPostStore := mocks.PostStore{} + mockPostStore.On("GetMaxPostSize").Return(65535, nil) + mockSystemStore := mocks.SystemStore{} + mockSystemStore.On("GetByName", "InstallationDate").Return(&model.System{Name: "InstallationDate", Value: "10"}, nil) + mockSystemStore.On("GetByName", "FirstServerRunTimestamp").Return(&model.System{Name: "FirstServerRunTimestamp", Value: "10"}, nil) + + mockSessionStore := mocks.SessionStore{} + mockSessionStore.On("UpdateLastActivityAt", "id1", mock.Anything).Return(nil) + mockSessionStore.On("Save", mock.AnythingOfType("*model.Session")).Return(sess1, nil) + mockSessionStore.On("Get", "id1").Return(sess1, nil) + mockSessionStore.On("Remove", "id1").Return(nil) + + mockStatusStore := mocks.StatusStore{} + mockStatusStore.On("Get", "user1").Return(&model.Status{UserId: "user1", Status: model.STATUS_ONLINE}, nil) + mockStatusStore.On("UpdateLastActivityAt", "user1", mock.Anything).Return(nil) + mockStatusStore.On("SaveOrUpdate", mock.AnythingOfType("*model.Status")).Return(nil) + + mockStore.On("Session").Return(&mockSessionStore) + mockStore.On("Status").Return(&mockStatusStore) + mockStore.On("User").Return(&mockUserStore) + mockStore.On("Post").Return(&mockPostStore) + mockStore.On("System").Return(&mockSystemStore) + + // This needs to be false for the condition to trigger + th.App.UpdateConfig(func(cfg *model.Config) { + *cfg.ServiceSettings.ExtendSessionLengthWithActivity = false + }) + + s := httptest.NewServer(dummyWebsocketHandler(t)) + defer s.Close() + + wc1 := registerDummyWebConn(t, th.App, s.Listener.Addr(), "testid") + hub := th.App.Srv().hubs[0] + hub.Register(wc1) + + done := make(chan bool) + + time.Sleep(time.Second) + // We override the LastActivityAt which happens in NewWebConn. + // This is needed to call RevokeSessionById which triggers the race. + th.App.AddSessionToCache(sess1) + + go func() { + for i := 0; i <= broadcastQueueSize; i++ { + hub.Broadcast(model.NewWebSocketEvent("", "teamId", "", "", nil)) + } + close(done) + }() + + // This call should happen _after_ !wc.IsAuthenticated() and _before_wc.isMemberOfTeam(). + // There's no guarantee this will happen. But that's out best bet to trigger this race. + wc1.InvalidateCache() + + for i := 0; i < 10; i++ { + // If broadcast buffer has not emptied, + // we sleep for a second and check again + if len(hub.broadcast) > 0 { + time.Sleep(time.Second) + continue + } + } + if len(hub.broadcast) > 0 { + require.Fail(t, "hub is deadlocked") + } +} + func TestHubConnIndex(t *testing.T) { th := Setup(t) defer th.TearDown()