Mattermost 4.4.1 loses session and users disappear

Troubleshooting
1

Summary

Users get logged out after a period of time

Steps to reproduce

Mattermost 4.4.1, deployed on CentOS behind a NGINX reverse proxy. Auth is done through LDAP/AD. We did not see this on 3.8.x.

Expected behavior

Users to stay logged in and not disappear from the team

Observed behavior

Users who are logged in eventually get kicked out and when you log back in, you cannot @ any team members or anything until said team member logs back in. In the logs we see this,

  [2017/11/17 11:23:12 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:12 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:12 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:12 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:30 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:30 PST] [EROR] /api/v4/users/status/ids:ServeHTTP code=401 rid=5g4by3dy47nwt8o3n9kdw51k9c uid= ip=10.100.141.230 Invalid or expired session, please login again. [details: token=x4cj9q8ir3r13pp8p859kqxenh]
[2017/11/17 11:23:30 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:50 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:50 PST] [EROR] /api/v4/users/status/ids:ServeHTTP code=401 rid=wthjggihkfyjxedtiskx481q6h uid= ip=10.100.111.62 Invalid or expired session, please login again. [details: token=mhrenpxmmjyubc3zrekrsnix3a]
[2017/11/17 11:23:50 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:52 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:52 PST] [EROR] /api/v4/users/status/ids:ServeHTTP code=401 rid=5bhu3xg5epr73mqg6ese654cxw uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: token=u41i3ska5idsiywftxbkfem1jh]
[2017/11/17 11:23:53 PST] [EROR] /api/v4/users/me: code=401 rid=8ugkxjow6idzzrbncaqxqhfy3c uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: UserRequired]
[2017/11/17 11:23:53 PST] [EROR] /api/v4/users/me/preferences: code=401 rid=znwwmmjrfi8cmye56n76cs6nko uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: UserRequired]
[2017/11/17 11:23:53 PST] [EROR] /api/v4/users/me/teams: code=401 rid=o6sxdi5ad7ye9p8xord1nnyocr uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: UserRequired]
[2017/11/17 11:23:53 PST] [EROR] /api/v4/users/me/teams/unread: code=401 rid=7p85p9bcp7ne9pkdhnc58h98pr uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: UserRequired]
[2017/11/17 11:23:53 PST] [EROR] /api/v4/users/me/teams/members: code=401 rid=99cmkgjsijfwf8ucb4w6eikqer uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: UserRequired]
[2017/11/17 11:23:53 PST] [EROR] /api/v4/emoji: code=401 rid=wme67j8dn3rp9yycjcub8okq9w uid= ip=10.100.142.109 Invalid or expired session, please login again. [details: UserRequired]
[2017/11/17 11:23:55 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:23:55 PST] [EROR] /api/v4/users/status/ids:ServeHTTP code=401 rid=fmdfc6ko93b9xbzfy68fhu5cjc uid= ip=10.100.142.88 Invalid or expired session, please login again. [details: token=pj11i7co4ifxpncr9xz4wgjeme]
[2017/11/17 11:23:55 PST] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, SqlUserAccessTokenStore.GetByToken: store.sql_user_access_token.get_by_token.app_error, sql: no rows in result set
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/5w4myyxrui8n3pn4xunn5rq93c/thumbnail:ReadFile code=404 rid=gr7u1mycxigj9py3ub3p6remoa uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/ie5wdwtqpjfmpc4fmnrshh48jc/t9s6e4xcsbgimjan6srhcbkqpo/Screenshot 2016-05-26 11.03.23_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/cjtme4i4jby7xj8c3wewjkxxfa/thumbnail:ReadFile code=404 rid=5dihms43kbyzb84zri7fy478xa uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/7jpogf7e5pn57mddj6g6sqrsde/p13ebfsihibxdgtbbtnnu7e7wh/Screen Shot 2016-06-23 at 3.24.43 PM_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/4emmcg8qzjdpud4mdaqtfiebae/thumbnail:ReadFile code=404 rid=pm3ibyzqjfy9i8zz8ta83ohgra uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/7jpogf7e5pn57mddj6g6sqrsde/cz791mhxxpg3pdiqqa8c5q7guw/real_programmers_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/u4aopnqfh7ncikd6kj8wkx4u6y/thumbnail:ReadFile code=404 rid=6cxqxfnmmfgn3yassuhg9us6uw uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/7jpogf7e5pn57mddj6g6sqrsde/71sq7pwoob8rucdaxigxrdr6ze/Screen Shot 2016-10-05 at 12.30.19 PM_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/4emmcg8qzjdpud4mdaqtfiebae/thumbnail:ReadFile code=404 rid=z6j6gtsx1tbf8kj9o13ert4d8a uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/7jpogf7e5pn57mddj6g6sqrsde/cz791mhxxpg3pdiqqa8c5q7guw/real_programmers_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/5w4myyxrui8n3pn4xunn5rq93c/thumbnail:ReadFile code=404 rid=eeo683u1fby8ierchwq8jaczbo uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/ie5wdwtqpjfmpc4fmnrshh48jc/t9s6e4xcsbgimjan6srhcbkqpo/Screenshot 2016-05-26 11.03.23_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/cjtme4i4jby7xj8c3wewjkxxfa/thumbnail:ReadFile code=404 rid=o5hw1zakubg68xdd3udzxt5wjr uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/7jpogf7e5pn57mddj6g6sqrsde/p13ebfsihibxdgtbbtnnu7e7wh/Screen Shot 2016-06-23 at 3.24.43 PM_thumb.jpg: no such file or directory]
[2017/11/17 11:24:11 PST] [EROR] /api/v4/files/u4aopnqfh7ncikd6kj8wkx4u6y/thumbnail:ReadFile code=404 rid=7cjeqkutw38kufuocrtf7icfsy uid=jsjohhd3m3bcmdrwna8t9g3our ip=10.100.141.230 Encountered an error reading from local server storage [details: open /home/mattermost/data/teams/6dkqxaychbbujphxjm3jyw6c3a/channels/x6mk39k61pdmxezkyenqniyp6c/users/7jpogf7e5pn57mddj6g6sqrsde/71sq7pwoob8rucdaxigxrdr6ze/Screen Shot 2016-10-05 at 12.30.19 PM_thumb.jpg: no such file or directory]
2

Thanks @congalong,

  1. Can you let me know the values of the following settings in config.json, under ServiceSettings 
        "SessionLengthWebInDays"
        "SessionLengthMobileInDays"
        "SessionLengthSSOInDays"
        "SessionCacheInMinutes"
        "SessionIdleTimeoutInMinutes"
  1. Similarly, can you let me know the values for these config.json settings:
    "LocalizationSettings": {
        "DefaultServerLocale": "en",
        "DefaultClientLocale": "en",
        "AvailableLocales": ""
    },
  1. Did you update directly from v3.8.X to v4.4.1, and followed our upgrade guide and review important upgrade notes?
  2. Has this reproduced on the following:
    4a) Browsers (if so, which ones)?
    4b) Desktop app (if so, Mac, Windows and/or Linux)?
    4c) Mobile app (if so, iOS and/or Android)?
  3. What languages do the users experiencing issues have set in Mattermost, do you know?
3

Hey @jasonblais

  1.  "SessionLengthWebInDays": 30,
 "SessionLengthMobileInDays": 30,
 "SessionLengthSSOInDays": 30,
 "SessionCacheInMinutes": 10,
 "SessionIdleTimeoutInMinutes": 0,

  2. "LocalizationSettings": {
 "DefaultServerLocale": "en",
 "DefaultClientLocale": "en",
 "AvailableLocales": "en"
},

  3. Upgraded directly, did follow the guide and applied the upgrade notes.

4a. Firefox, Chrome
4b. Not tested on Desktop App, I will test
4c. No mobile users
5. English

4

Thanks @congalong, very helpful. I’ll touch base with our engineers to get their thoughts on this.

Couple more questions that come to mind, given there was an update to LDAP sync in v4.4:
6. What is your LDAP synchronization interval set to? Any chance these timeouts occur after the sync runs?
7. Have most recent LDAP sync jobs run successfully? (there is a table of LDAP sync runs at the bottom of the System Console > AD/LDAP page)

5

We’re seeing the same problem. 4.2.0 worked fine for us.
AD Sync as well. Only a few users get deactivated though with a message like this:
platform[22109]: [2017/11/20 10:08:23 UTC] [EROR] Invalid session err=GetSession: api.context.invalid_token.error, createSessionForUserAccessToken: app.user_access_token.invalid_or_missing, EnableUserAccessTokens=false
platform[22109]: [2017/11/20 10:08:23 UTC] [INFO] Mattermost user was updated by AD/LDAP server. deactivated username=myuser email=myemail

i can actually reproduce the behaviour with my own account every time i click on AD Sync now it will get deactivated with that log message.

6

Mostly a me too post to say I’m having the same issue

LDAP synchronization was set to 60 minutes, and it’s definitely throwing that error at/after a sync. The sync otherwise runs fine. And again, it seems to be a random subset of users each time.

For what it’s worth, my desktop app hasn’t been logged out, and I’m on a Linux machine whereas everyone else here will be on Windows.

7

@pauljones @fstelzer @congalong

Thank you all. I have escalated this issue and created a ticket. Our engineers will investigate this as high priority.

https://mattermost.atlassian.net/browse/PLT-8196

I might follow up with you guys with more questions if needed, and keep you updated on the ticket status.

8

Just want to add that in my case I am also able to reproduce it consistently with forcing an AD/LDAP sync in the system console.

9

@congalong @pauljones @fstelzer

Here are a few follow-up questions that will help us reproduce the issue.

  1. Can you help attach your LDAP settings from config.json? The username/password should be removed. If you don’t feel comfortable posting it here, totally understand. You can private message me instead.
  2. What AD/LDAP server and version are you using? For example, Active Directory on Windows Server 2016
  3. Are there any additional LDAP errors in the logs, apart from what you’ve already posted here?
  4. Is there a limit on the number of users the LDAP server can return in a single query? If so, have you set the Maximum Page Size in Mattermost?
  5. Can you send an example user from your system by using the ldapsearch command on your LDAP server. Again, if you don’t feel comfortable posting it here, you can private message me instead.
  6. Do you have SAML login enabled? If you do, have you set Enable Synchronizing SAML Accounts With AD/LDAP in System Console > SAML 2.0 to true or false?
10

Hi Jason,
here our settings. (I would send you a private message if you need more details, but i have no idea how…)

1:
“LdapSettings”: {
“Enable”: true,
“EnableSync”: true,
“LdapServer”: “LDAPSERVER”,
“LdapPort”: 636,
“ConnectionSecurity”: “TLS”,
“BaseDN”: “BASEDN”,
“BindUsername”: “BINDUSERNAME”,
“BindPassword”: “BINDPASSWORD”,
“UserFilter”: “USERFILTER”,
“FirstNameAttribute”: “givenName”,
“LastNameAttribute”: “sn”,
“EmailAttribute”: “mail”,
“UsernameAttribute”: “sAMAccountName”,
“NicknameAttribute”: “nickname”,
“IdAttribute”: “sAMAccountName”,
“PositionAttribute”: “”,
“SyncIntervalMinutes”: 60,
“SkipCertificateVerification”: true,
“QueryTimeout”: 60,
“MaxPageSize”: 0,
“LoginFieldName”: “LDAP Login”
},

2: Windows Server 2008 R2
3: No additional LDAP Messages
4: I don’t know. How can i check this?
5: I can provide this information if i can send a private message…
6: We have E10 edition. Therefore this option does not exist.

The problem seems to always affect my own user. So to check if the max page size is the problem i’ve set it to 10 and clicked Sync Now. It took some time but then i was logged out again with the same message in the log as before.

Thanks

11

Hi, here’s our LDAP setup with sensitive bits redacted:

"LdapSettings": {
    "Enable": true,
    "EnableSync": true,
    "LdapServer": "Server_IP",
    "LdapPort": 636,
    "ConnectionSecurity": "TLS",
    "BaseDN": "Base_DN",
    "BindUsername": "Bind_User",
    "BindPassword": "Bind_Password",
    "UserFilter": "",
    "FirstNameAttribute": "givenName",
    "LastNameAttribute": "sn",
    "EmailAttribute": "mail",
    "UsernameAttribute": "uid",
    "NicknameAttribute": "",
    "IdAttribute": "uid",
    "PositionAttribute": "",
    "SyncIntervalMinutes": 20160,
    "SkipCertificateVerification": true,
    "QueryTimeout": 60,
    "MaxPageSize": 0,
    "LoginFieldName": ""
}

NB - SyncInterval is usually 60 minutes but I’ve increased it for the moment to avoid the sync causing the logout problem

Server 2012 R2
No further LDAP messages in the logs
No limit on the number of LDAP users returned that I’m aware of. We’re talking <100 users here, so I can’t imagine it’s set lower than that if there is a limit
I’ll try the ldapsearch and PM across
E10, so no SAML

12

Thanks all! I’ve forwarded the information to our engineers and hopefully we’ll have this resolved soon.

Much appreciated.

@fstelzer To send a private message, you can click on my user profile (or username), then choose “Message”
image

13

31
as you can see i don’t have that button… although im logged in

14

@fstelzer Hm, not entirely sure why. I’ve sent you a PM, let me know if you’re able to respond?

If not, let me know and I’ll see if there is a permission issue or something.

15

@congalong @fstelzer @pauljones

We have cut 4.4.2-RC1, which fixes an issue where AD/LDAP accounts get deactivated following an AD/LDAP sync if their email address between the AD/LDAP server and Mattermost don’t match case.

It would be good to verify it fixes the issue you are experiencing. If you are open to it, you can download 4.4.2-RC1 here: https://releases.mattermost.com/4.4.2-rc1/mattermost-4.4.2-rc1-linux-amd64.tar.gz. If this fix doesn’t resolve it for you, let me know and we’ll continue investigating as a high priority.

For other fixes in v4.4.2, you can find a draft of the changelog here.

16

I’ve deployed that and left it to run a regular LDAP update after 60 minutes. All looks good, no errors and no-one reporting that they’ve been logged out.

Obviously if that changes I’ll let you know, but all seems fine now - thanks!

17

Just deployed. Did a simple LDAP sync and seems to look good. I’ll keep monitoring throughout the day and see how it goes. Thanks for the quick turn around!

18

Yay! That’s promising.

We’ve now officially cut 4.4.2, which should fix the AD/LDAP sync issue. You can download it below, or from our downloads page on 11/23:

https://releases.mattermost.com/4.4.2/mattermost-4.4.2-linux-amd64.tar.gz

Huge thanks for your help investigating this issue!