User get logged out on every refresh

Troubleshooting
1

Hello,

Summary

User get logged out everytime the page is refreshed (F5)

Steps to reproduce

Mattermost 5.23 behind an Apache 2.4.41 proxy

Vhost config

 <VirtualHost *:80>
        ServerAdmin email@example.com
        ServerName mattermost.xxxxx.xxx

        ServerSignature Off

    # Enforce HTTPS:
        RewriteEngine On
        RewriteCond %{HTTPS} !=on
        RewriteRule ^/?(.*) https://%{SERVER_NAME}/$1 [R,L]
</VirtualHost>

<VirtualHost *:443>

    SSLEngine On

    ServerAdmin email@example.com
    ServerName mattermost.xxxxx.xxx

    SSLProxyEngine on

    Header always set Strict-Transport-Security "max-age=31536000" env=HTTPS

    RewriteEngine On
    RewriteCond %{REQUEST_URI} ^/api/v[0-9]+/(users/)?websocket [NC,OR]
    RewriteCond %{HTTP:UPGRADE} ^WebSocket$ [NC,OR]
    RewriteCond %{HTTP:CONNECTION} ^Upgrade$ [NC]
    RewriteRule .* ws://127.0.0.1:8065%{REQUEST_URI} [P,QSA,L]
    RewriteCond %{DOCUMENT_ROOT}/%{REQUEST_FILENAME} !-f
    RewriteRule .* http://127.0.0.1:8065%{REQUEST_URI} [P,QSA,L]
    RequestHeader set X-Forwarded-Proto "https"

    RequestHeader unset If-Modified-Since
    RequestHeader unset If-None-Match

    # setup the proxy
    <Proxy *>
        Require all granted
    </Proxy>

    <LocationMatch "/api/(?<version>v[0-9]+)/(?<users>users/)?websocket$">
    Require all granted
        ProxyPassReverse ws://localhost:8065/api/v%{env:MATCH_VERSION}/%{env:MATCH_USERS}websocket
        ProxyPassReverseCookieDomain localhost mattermost.xxxxx.xxx
    </LocationMatch>
    <Location />
        Require all granted
        ProxyPass http://localhost:8065/
        ProxyPassReverse http://localhost:8065/
        ProxyPassReverseCookieDomain localhost mattermost.xxxxx.xxx
    </Location>

    LogLevel warn
    ErrorLog ${APACHE_LOG_DIR}/mattermost_error.log
    CustomLog ${APACHE_LOG_DIR}/mattermost_access.log combined

    ProxyPreserveHost On
    ProxyRequests Off

    SSLCertificateFile    /etc/letsencrypt/live/mattermost.xxxxx.xxx/fullchain.pem
    SSLCertificateKeyFile /etc/letsencrypt/live/mattermost.xxxxx.xxx/privkey.pem
    Include /etc/letsencrypt/options-ssl-apache.conf
</VirtualHost>

Expected behavior

The users stay logged

Observed behavior

The following appears on the log :

{"level":"info","ts":1589568876.1257844,"caller":"mlog/log.go:167","msg":"Invalid session","error":"GetSession: Invalid session token=the_token_gibberish, err=<no value>, "}

Of course I saw this post but it doesn’t seem the provide any solution (and the cookies seems to be set in the browser)

Thank you,

2

Hi Jehan,

Does this reproduce for you reliably ?

Would you be open to share the logs at a DEBUG level, from the time you hit refresh till you get logged out in the web app ?

3

Hi,

Thanks for answering !
Here are the logs at the debug level from the moment I hit the refresh button, as requested :

{"level":"debug","ts":1589782130.171263,"caller":"app/web_conn.go:147","msg":"websocket.read: client side closed socket","user_id":"na5za1fhu7yz8r74bzhwc6xw5a"} {"level":"debug","ts":1589782130.3567903,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/admin_console/reporting/server_logs","request_id":"tcbaz4z3npyzippkfehk85phmw"} {"level":"debug","ts":1589782132.8060565,"caller":"migrations/scheduler.go:50","msg":"Scheduling Job","scheduler":"MigrationsScheduler"} {"level":"debug","ts":1589782132.8089697,"caller":"migrations/scheduler.go:89","msg":"All migrations are complete.","scheduler":"MigrationsScheduler"} {"level":"debug","ts":1589782132.8106368,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"MigrationsScheduler","next_runtime":"<nil>"} {"level":"debug","ts":1589782134.244175,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/config/client","request_id":"o8qzshwewpno9gapa9yoo586ia"} {"level":"debug","ts":1589782134.2509835,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/license/client","request_id":"gzhohf8pff8edf1e4y6dek7jny"} {"level":"debug","ts":1589782134.3533456,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/plugins/webapp","request_id":"od8kpftm8tdpme8npgzo557u4y"} {"level":"debug","ts":1589782135.154131,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"POST","url":"/api/v4/users/logout","request_id":"ajw8cxa4ntbqxpw6s6dff3hx4h"} {"level":"debug","ts":1589782135.1543372,"caller":"mlog/log.go:163","msg":"CSRF Header check failed for request - Please upgrade your web application or custom app to set a CSRF Header","path":"/api/v4/users/logout","ip":"127.0.0.1:43804","session_id":"3ggikb9m4pfb9yw7m91ajy4dno","user_id":"na5za1fhu7yz8r74bzhwc6xw5a"} {"level":"debug","ts":1589782135.3728356,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/","request_id":"wbtgxzo9otgudqkkg7mypauooo"} {"level":"debug","ts":1589782135.3793545,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/websocket","request_id":"zbzkdy75et8g9k7uy8t3gb1ogc"} {"level":"info","ts":1589782135.3820646,"caller":"mlog/log.go:167","msg":"Invalid session","error":"GetSession: Invalid session token=6mfcp7afk7yy5qtkcnh5t7wjaw, err=<no value>, "} {"level":"debug","ts":1589782135.4692454,"caller":"app/web_conn.go:149","msg":"websocket.read: closing websocket","user_id":"","error":"websocket: close 1006 (abnormal closure): unexpected EOF"} {"level":"debug","ts":1589782139.035965,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/config/client","request_id":"7oyraryed3b1xmur4aehhmnmzy"} {"level":"debug","ts":1589782139.037683,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/license/client","request_id":"a4wxifsoh7bwtj9i8o11rzg5rc"} {"level":"debug","ts":1589782139.1552315,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/plugins/webapp","request_id":"kn63ry4dztr7ufa417rmz13cme"} {"level":"debug","ts":1589782146.7029998,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"POST","url":"/api/v4/users/login","request_id":"kjtrc95eqt883gae99cs7tzh9y"} {"level":"debug","ts":1589782147.0182939,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/me/teams/members","request_id":"zrc8jnmuppf9ibajop6sfzr85e"} {"level":"debug","ts":1589782147.019034,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/me/teams/unread","request_id":"3cauk6k1fprk8f4oz8ma3id7re"} {"level":"debug","ts":1589782147.173656,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/me/preferences","request_id":"iemojucojirb5egzs34k7677rw"} {"level":"debug","ts":1589782147.1766522,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/me/teams","request_id":"fsw49tk4c7fbmyornepuzd7ppy"} {"level":"debug","ts":1589782147.1767683,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/config/client","request_id":"kkzrufn7r7djumsqx8qo3f8sbh"} {"level":"debug","ts":1589782147.4358423,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"POST","url":"/api/v4/roles/names","request_id":"4oadw7dx17dhdq44ex98nehkiw"} {"level":"debug","ts":1589782147.9366693,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/websocket","request_id":"5799hwgd9pbk5c1dgczofnbdqc"} {"level":"debug","ts":1589782148.853896,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/config","request_id":"8ofnwkgpybn8tfupxwznr9bszr"} {"level":"debug","ts":1589782148.8593414,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/config/environment","request_id":"akodbnsbi38nmxk6mu8ykmddzo"} {"level":"debug","ts":1589782148.860178,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"POST","url":"/api/v4/roles/names","request_id":"aipjspo7nbrx588n87oe64qiyc"} {"level":"debug","ts":1589782149.0987196,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/analytics/old","request_id":"tc3obh5s37d3pynm9w5gp3jtwr"} {"level":"debug","ts":1589782149.0987082,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/plugins","request_id":"5b5cf93soffhmeaeizkaj63tqe"} {"level":"debug","ts":1589782149.1037238,"caller":"web/handlers.go:85","msg":"Received HTTP request","method":"GET","url":"/api/v4/logs","request_id":"tupyaxf3t78odbbf5q17wyn6ce"}

I notice something about a CSRF Header problem, but otherwise, nothing that seems super relevant.

Thanks !

4

Thanks ! Lastly, does it reproduce reliably for you every single time you refresh the page ? Or only sometimes ? Are all other users facing the same problem ?

5

So if I try to retrace the order of events,

  • The client closes the websocket connection on a page reload.
  • It slowly starts making all the GET calls needed to fill up the page.
  • After the /api/v4/plugins/webapp call, it suddenly makes a call to /api/v4/users/logout.
  • The server cannot do much except logout the user, which causes the invalid session error on the websocket connection.

This error is expected if a logout happens. But the question is why does the client send a logout request.

From your observations, all you did was hit just a refresh ?

EDIT:

I checked up internally with our dev team, and we were wondering if the call to /api/v4/plugins/webapp somehow returns a 401, due to which the client makes a logout request.

Would you be open to capturing a HAR dump of the entire flow from where you make a refresh to the point where you get logged out ?

Here are the steps for how to do that: https://confluence.atlassian.com/kb/generating-har-files-and-analysing-web-requests-720420612.html.

Please ensure to check the “Preserve logs” box so that the browser does not remove the old requests when you refresh the page.

Thanks !

6

I’ll try to be clear and answer point by point :

1. does it reproduce reliably for you every single time you refresh the page ? Or only sometimes ?
Everytime.

2. Are all other users facing the same problem ?
Yes.

3. From your observations, all you did was hit just a refresh ?
These are the steps I made : Logged in. Waiting for everything to load. Hit F5. Being logged out.

Here is a HAR dump as requested : https://defuse.ca/b/EuHBfMHy
It seems that the call to /api/v4/plugins/webapp returns a 200

Thanks !

7

Thanks for the HAR file. Now we know that the client is sending the logout event without any clear indication as to why.

We need a little more information to eliminate some other code paths in the client that can cause this. Would you be open to sharing your console logs for the entire duration of the page reload to the logout ? Do you see something like detected logout from a different tab ?

8

I wasn’t sure on how you wanted me to give you the console log, I took a screenshot (mostly because I don’t know how to export these in text format, never had to do that before tbh) :

mattermost-console
mattermost-console1308Ă—1818 566 KB

If you want it on another format, please tell me, I’d be happy to provide you the things you need.

9

@jehanf What browser are you using for replicating the issue?

10

@sudheerDev I’ve tested my setup on Safari, Chrome, Vivaldi, Firefox and Firefox Dev.
The result was always the same.

11

Hi, @jehanf

Perhaps you can check on the HAR Analyzer page for steps to export the HAR file according to the primary web browser that you are on.

One more thing. Is it possible for you to reproduce the issue when you are connecting directly yo Mattermost 5.23 without the Apache proxy on an incognito / private mode of the web browser? Just trying to narrow down if it is something specific to the configuration of the proxy that is causing the log out to happen whenever you refresh the page.

12

Hi @ahmaddanial

Indeed, if I connect directly to the IP:port address (which doesn’t use the proxy then) of my Mattermost install, everything seems to work perfectly.
I was assuming that it would be some kind of issue with my proxy, but now it seems almost certain it is. Why ? I don’t have a clue. I’m running other services with the same kind of proxy setup and never had any troubles like that.
I’m all ears about any suggestion, because it’s kind of a super weird problem I found no answer about anywhere (and so I’m aiming at finding one for the record, because I don’t think I’m the only one with a setup like this).

13

Hi Jehan,

I am not an Apache expert, but I do see that your Apache config is slightly different from what is documented here: https://docs.mattermost.com/install/config-apache2.html#configuring-apache2-with-ssl-and-http-2-unofficial

Perhaps adjusting your config to what is recommended might help ?

I do see that you have an additional location match for “/api/” and some other differences too.

I am not exactly sure what is the cause, but since the documented Apache config has been proved to work in the field, I am willing to think there is some difference in there that is causing this.

Please do let us know what was it, so that we can document this.

Thanks

1 Like
14

Hi,

Sorry for the delay of answer.
In fact, the link you pointed out was the very first one I used for the initial configuration, that’s why I searched and tried different results found on the web, after I saw this wasn’t working.

15

So just to confirm, the initial config was lifted from our docs, and that suffered from the same logout issue ?

After that, you changed the config, but that didn’t seem to help either ?

16

Yes, Exactly !
Nothing seems to work on my setup for this specific point.

17

Alright, that’s interesting. So given that atleast you have a working setup without the proxy, we can spend some time to get to the bottom of this.

Would you be able to run a tcpdump packet capture for the 2 different cases - one with the proxy, and one direct ?

sudo tcpdump -i eth0 -s0 -w test.pcap -host example.com

I am hoping this will shed some light on the difference between the proxy and direct.

18

Sure.

For further notice, there was a small mistake in the command you gave me : -host should be host (w/o the -)
It seems I have an issue with this. The file for the direct domain (with proxy) is only 24 bytes, which seems super low to me, and the one with ip + port (without proxy) give me this error : tcpdump: can't parse filter expression: syntax error
Here is what I used : sudo tcpdump -w test2.pcap -i en0 -s0 host xx.xx.xxx.xxx port 8065

Sorry, not really used to this.

19

No worries, you are missing an “and” predicate.

sudo tcpdump -w test2.pcap -i en0 -s0 host xx.xx.xxx.xxx and port 8065

Regarding why it’s too low, it would be very hard to say. I would suggest to try without -w and confirm you are getting the output correctly. If nothing is showing, then remove the host and check. Basically try eliminating variables one by one until you figure out the issue.

20

DNS resolution might also be a reason for the low file size. Try with with the -n flag. If that doesn’t work, just try doing sudo tcpdump -n -i en0. Or perhaps your interface name is not correct ? In that case try capturing from all interfaces to ensure whether the problem is with tcpdump or an incorrect interface.

Thanks.