Users become inactive daily

[itwasonlyabug]

Summary

Certain users become inactive every night, even though during the day they are logged-in and actively using the Desktop client or Mobile client.

Steps to reproduce

• Login through GitLab (CE 13.5.3)
• Mattermost Version: 5.25.4
• Database Schema Version: 5.25.0
• Database: postgres
• Session lengths are the default 30 days

Expected behavior

Users should remain logged in as long as the session length is configured. Direct messages should not become archived just because the users has not logged-in recently.

Observed behavior (that appears unintentional)

A small subset of users become marked as inactive every day and all direct messages with them become archived. They can send messages but cannot receive any until they logout and login again. Once they re-login, their status changes to active.

Note - the users do not have issues with their GitLab session length.
Note - this affects only people with names starting with A, B, C or D, so it looks like some user filtering going wrong.

[amyblais]

@itwasonlyabug Can you help share any Mattermost server logs or developer console errors from the time the issue occurs?

[itwasonlyabug]

Hi @amyblais , thanks for the quick response!

From the developer console I'm having a hard time getting useful information, but from the mattermost.log file I see the following:

I have redacted IPs and tokens.

• Errors that happen very frequently:

{"level":"info","ts":1542810141.8993478,"caller":"web/handlers.go:95","msg":"Invalid` session","error":"GetSession: Invalid session token=<REDACTED>, err=<no value>, "}

• Errors that happen frequently:

{"level":"error","ts":1543319912.519615,"caller":"web/context.go:60","msg":"We encountered an error finding the session","path":"/error","request_id":"<REDACTED>","ip_addr":"<REDACTED>","user_id":"","method":"GET","err_where":"SqlSessionStore.Get","http_code":500,"err_details":"sessionIdOrToken=<REDACTED>, dial tcp <REDACTED_DB_IP>: connect: connection refused"}

This is interesting, as I tested the DB connection and there is no connectivity problem and I think a DB connection issue should affect all users.

{"level":"warn","ts":1558818026.8144588,"caller":"app/web_hub.go:125","msg":"We appear to have already sent the stop checking for deadlocks command"}

• Sequence that I managed to catch today after a user went inactive:

I am not sure how I can get the user ID so I can filter for a specific users, so this sequence is mostly luck.

{"level":"error","ts":1605564092.4791138,"caller":"app/plugin.go:161","msg":"Failed to start up plugins","error":"mkdir ./client/plugins: no such file or directory"}
"level":"info","ts":1605564096.368415,"caller":"app/server.go:416","msg":"Stopping Server..."}
{"level":"info","ts":1605564096.368596,"caller":"app/web_hub.go:130","msg":"stopping websocket hub connections"}
{"level":"info","ts":1605564096.376344,"caller":"app/server.go:469","msg":"Server stopped"}
{"level":"error","ts":1605564209.4372847,"caller":"wsapi/websocket_handler.go:33","msg":"websocket session error","action":"user_update_active_status","seq":438,"user_id":"<REDACTED>","error_message":"Invalid session token=<REDACTED>, err=<no value>","error":"GetSession: Invalid session token=<REDACTED>, err=<no value>, "}
{"level":"info","ts":1605564244.4170148,"caller":"mlog/log.go:167","msg":"Invalid session","error":"GetSession: Invalid session token=<REDACTED>, err=<no value>, "}``` 

Afterwards we see the same errors as those in the very frequent and frequent lists shown above.

[ahmaddanialmohd]

Hello, @itwasonlyabug

The Invalid session token indicates that there is an issue with the existing token that was assigned to the user. If possible, can you please enable the DEBUG on the file log leve so get more details when the issue occurs again?

To clear off any potential issues with the session tokens first, can you also please ask the affected users to navigate to their Account Settings > View and Log Out of Active Sessions and log out from every session that they have listed there? Log in again and observe if the same daily deactivation of the same set of users happening. Since you mention that it is only happening on a specific subset of users, let us also drill down a bit more on that.

You can cross check the user ID by running the SQL statement on the Mattermost database:

SELECT * FROM Users WHERE Username = "<username>";

When you mentioned inactive, can I confirm that the user status was inactive when you view it from the System Console? For example:

I am trying to understand how logging in automatically reactivates their account again, which is strange.

[itwasonlyabug]

Hi @ahmaddanialmohd,
I confirm that the user status is inactive in the System Console. I will try your suggested fix with logging out of the sessions and with enabled DEBUG logging.

Don't know how I didn't see the ID there :( I'll parse the logs for specific errors with these users before and after their new sessions.

[itwasonlyabug]

So, after some testing:
After logging out the users out of all of their sessions the issue remains - every morning they are forced to login into Mattermost and after they do, they become active again.

As for the DEBUG logging, I enabled it but the file rotates at 100MB, and I found it next to impossible to get any useful information out of it. The only messages I see that might be useful are:

I have replaced to user IDs with USER 1, USER 2 and USER 3 - all of them have this issue.

• {"level":"debug","ts":1606159221.9542978,"caller":"app/web_conn.go:419","msg":"websocket.read: closing websocket","user_id":"USER 3","error":"websocket: close 1006 (abnormal closure): unexpected EOF"}

• {"level":"debug","ts":1606159325.375619,"caller":"app/web_conn.go:419","msg":"websocket.read: closing websocket","user_id":"USER 3","error":"read tcp <SERVER_IP> -> <PROXY_IP>: i/o timeout"} I checked with my network guys and it turns out that the connections to our Mattermost server pass through a reverse-proxy if coming from outside our local network, so I assume this is some mobile app trying to connect.

• {"level":"debug","ts":1606219178.197273,"caller":"app/email_batching.go:163","msg":"Deleted notifications for user","user_id":"USER 2"}

I couldn't find it in the docs, but how can I bump the log rotation to more than 100mb? I think we definitely need to provide more logs around the time the issue occurs.

[itwasonlyabug]

I sent the logs to ELK so I can provide better output. Here's an example of a USER4 that was inactive, logged in and is now shown as member:

In the console, i see USER4 as member. In my direct messages i see him as archived (box icon) , but If i click on the DM, in the chat window I cannot send him messages, but I see him as Active (green checkmark).

@timestamp	message
Dec 2, 2020 @ 13:50:00.226	{"level":"debug","ts":1606909796.403799,"caller":"app/web_conn.go:419","msg":"websocket.read: closing websocket","user_id":"USER4","error":"read tcp <MATTERMOST_IP>-><PROXY_IP>:59196: i/o timeout"}
Dec 2, 2020 @ 10:19:59.001	{"level":"debug","ts":1606897189.1549542,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/image","request_id":"7czs8rxtjtnqzb84od4qsi6t7a"}
Dec 2, 2020 @ 10:19:48.999	{"level":"debug","ts":1606897188.8030357,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/image","request_id":"tsnggniywtdzmc8wpodb91zb8c"}
Dec 2, 2020 @ 10:09:58.501	{"level":"debug","ts":1606896596.4525366,"caller":"app/web_conn.go:419","msg":"websocket.read: closing websocket","user_id":"USER4","error":"read tcp <MATTERMOST_IP>-><PROXY_IP>:47506: i/o timeout"}
Dec 2, 2020 @ 09:50:37.545	{"level":"debug","ts":1606895436.9001417,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/image","request_id":"7cunbeorofb6pmsze9wqwqzt5c"}
Dec 2, 2020 @ 08:57:24.559	{"level":"debug","ts":1606892236.4003074,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/status","request_id":"u7cbr9jo73fhjb6agf67onguor"}
Dec 2, 2020 @ 08:57:24.559	{"level":"debug","ts":1606892236.7074964,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/channels/t5b78sf4ofguixyuyjuinkpxoc/posts/unread","request_id":"y6j6g4p5ety95kp83mghcuhh8a"}
Dec 2, 2020 @ 08:57:24.559	{"level":"debug","ts":1606892241.7121525,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"pukawedxib81pqyy1t1dwprenh"}
Dec 1, 2020 @ 15:07:26.775	{"level":"debug","ts":1606828046.6427455,"caller":"app/web_conn.go:419","msg":"websocket.read: closing websocket","user_id":"USER4","error":"read tcp <MATTERMOST_IP>-><PROXY_IP>:47728: i/o timeout"}
Dec 1, 2020 @ 14:44:05.593	{"level":"debug","ts":1606826638.5572734,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"85tkcu5o4tfg5dgjn5uy6q9xja"}
Dec 1, 2020 @ 14:39:25.313	{"level":"debug","ts":1606826356.295858,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/image","request_id":"uwshxqi1p3dxfnh946rsqnxxpa"}
Dec 1, 2020 @ 10:54:53.392	{"level":"debug","ts":1606812886.7545898,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"6w16ypszx78rix4bwpam96gcww"}
Dec 1, 2020 @ 10:33:02.306	{"level":"debug","ts":1606811577.6780272,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"b8g6ucbasfrj7rrw5s4mgxbwwe"}
Dec 1, 2020 @ 10:31:22.237	{"level":"debug","ts":1606811475.3511448,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/image","request_id":"6pc436wxe7fnbpfdr3s49pg3mh"}
Dec 1, 2020 @ 10:20:41.736	{"level":"debug","ts":1606810838.5553246,"caller":"app/email_batching.go:163","msg":"Deleted notifications for user","user_id":"USER4"}
Dec 1, 2020 @ 10:20:41.736	{"level":"debug","ts":1606810837.6350498,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"ekr3booxtjg5b8bzei316bo4ec"}
Dec 1, 2020 @ 10:05:51.018	{"level":"debug","ts":1606809946.5840087,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/channels/t5b78sf4ofguixyuyjuinkpxoc/posts/unread","request_id":"o7qcodxbtpd8jd9d1dtkm5rc3h"}
Dec 1, 2020 @ 10:05:41.007	{"level":"debug","ts":1606809939.7415056,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/channels/fmgdtspf13nj3c7m8w45g7e15w/posts/unread","request_id":"4iqwz6w4kif47d7nbthn195hjc"}
Dec 1, 2020 @ 10:05:10.981	{"level":"debug","ts":1606809906.0019543,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"ab13bqgm17fbbbqxabcrpx8xdw"}
Dec 1, 2020 @ 10:02:50.854	{"level":"debug","ts":1606809766.591789,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/status","request_id":"pxzqhrpwzbbbmxdw3t6ah7hpne"}
Dec 1, 2020 @ 10:02:50.854	{"level":"debug","ts":1606809766.6384404,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/image","request_id":"xorssucwwjrrbguhw1y4r1jk7e"}
Dec 1, 2020 @ 10:02:50.854	{"level":"debug","ts":1606809766.9424837,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/channels/ke196fxndpnbifdycodo96d6jw/posts/unread","request_id":"5ankx4z8eidf5nfbmhrwoug1na"}
Dec 1, 2020 @ 10:02:50.854	{"level":"debug","ts":1606809768.4864087,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"PUT","url":"/api/v4/users/USER4/preferences","request_id":"m4gbx1o8efbmdjj3ufrt9cgzih"}
Dec 1, 2020 @ 10:02:50.854	{"level":"debug","ts":1606809768.5436654,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/USER4/channels/xqqn68qce3gaxgf9oj76zhr7fa/posts/unread","request_id":"n74g3womb3gf7be99sni6ir7hh"}

[amyblais]

Have you had a chance to take a look at our troubleshooting docs related to websockets https://docs.mattermost.com/install/troubleshooting.html#server-administration?

What are your settings set for https://docs.mattermost.com/administration/config-settings.html#enable-cross-origin-requests-from?

[itwasonlyabug]

Hi @amyblais, we reviewed the settings of our proxy and they are exactly as recommended here https://docs.mattermost.com/install/install-ubuntu-1604.html#installing-nginx-server

As for the websocket error, from a browser I'm seeing the same as the screenshot on that page - HTTP status 101 for the websocket connection.

For CORS, these are our settings:

        "AllowCorsFrom": "",
        "CorsExposedHeaders": "",
        "CorsAllowCredentials": false,
        "CorsDebug": false,

I would like to again emphasize, that this issue is happening only for a small subset of users (~10) - and all of them have names that start with A, B, C or D. So, if it was some general configuration issue I would expect it to be happening regardless of the name and for a much bigger pool of users.

[amyblais]

@itwasonlyabug Would you be open to posting this on our troubleshooting forum here forum.mattermost.org? I have asked our team to take a look at this issue but haven't received responses yet, and our community / support team is more active on the forum site.

[itwasonlyabug]

Hi @amyblais, sure thing. That was my initial idea as well, but then I read the rules and decided I should try here first :)

Link to the forum post