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
Этот коммит содержится в:
Agniva De Sarker
2020-08-19 23:27:48 +05:30
коммит произвёл GitHub
родитель 4791aca112
Коммит 4e154756bd
2 изменённых файлов: 99 добавлений и 1 удалений

Просмотреть файл

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

Просмотреть файл

@@ -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()