Mattermost unstable after server update 4.7.3

Ju_St · March 29, 2018, 7:42am

Summary

Mattermost is unstable after update to 4.7.3 (smtp TLS connection isn’t working, but this might be a coincidence) - keeps on restarting every 15-30 minutes.

Steps to reproduce

Debian 9, Nginx, Mattermost Enterprise Version 4.7.2 (upgraded to 4.7.3)
follow standard procedures to update as indicated in the guide

Expected behavior

Same steps worked flawless to upgrade to 4.7.2

Observed behavior

systemctl status mattermost shows that the server is running, but is stuck on ‘pinging sql master database’ (edit). Nginx shows 502 Bad Gateway, then after aun unusally long time mattermost starts running, but keeps on shutting down 1-2 times an hour.

paulrothrock · March 15, 2018, 7:59pm

Happy to help but first I have a couple questions:

What version of MySQL and Nginx are you using?
Is the MySQL server functioning normally?

Ju_St · March 16, 2018, 2:51am

Hello Paul,

we’re using postgresql 9.6 and nginx 1.10.3 (both seem to work fine)

my mistake it should say: pinging sql master database in the original post

edit: we tried again this morning and the update worked now!

The strange thing is that the whole server seems very unstable since we tried to update yesterday. The logs are full of this:

[2018/03/16 08:47:41 +07] [INFO] Server is initializing…
[2018/03/16 08:47:41 +07] [INFO] Pinging SQL master database
[2018/03/16 08:47:41 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 08:48:00 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 08:48:01 +07] [INFO] Server is initializing…
[2018/03/16 08:48:01 +07] [INFO] Pinging SQL master database
[2018/03/16 08:48:01 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 08:48:27 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 08:48:27 +07] [INFO] Server is initializing…
[2018/03/16 08:48:27 +07] [INFO] Pinging SQL master database
[2018/03/16 08:48:27 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 08:48:55 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 08:48:55 +07] [INFO] Server is initializing…
[2018/03/16 08:48:55 +07] [INFO] Pinging SQL master database
[2018/03/16 08:48:55 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 08:49:11 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 08:49:11 +07] [INFO] Server is initializing…
[2018/03/16 08:49:11 +07] [INFO] Pinging SQL master database

[2018/03/16 09:37:47 +07] [INFO] Pinging SQL master database
[2018/03/16 09:37:47 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:37:55 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:37:55 +07] [INFO] Server is initializing…
[2018/03/16 09:37:55 +07] [INFO] Pinging SQL master database
[2018/03/16 09:37:55 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:38:06 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:38:06 +07] [INFO] Server is initializing…
[2018/03/16 09:38:06 +07] [INFO] Pinging SQL master database
[2018/03/16 09:38:06 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:38:40 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:38:40 +07] [INFO] Server is initializing…
[2018/03/16 09:38:40 +07] [INFO] Pinging SQL master database
[2018/03/16 09:38:40 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:38:45 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:38:45 +07] [INFO] Server is initializing…
[2018/03/16 09:38:45 +07] [INFO] Pinging SQL master database
[2018/03/16 09:38:45 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:39:16 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:39:16 +07] [INFO] Server is initializing…
[2018/03/16 09:39:16 +07] [INFO] Pinging SQL master database
[2018/03/16 09:39:16 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:39:20 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:39:20 +07] [INFO] Server is initializing…
[2018/03/16 09:39:20 +07] [INFO] Pinging SQL master database
[2018/03/16 09:39:20 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:39:50 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:39:50 +07] [INFO] Server is initializing…
[2018/03/16 09:39:50 +07] [INFO] Pinging SQL master database
[2018/03/16 09:39:50 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:39:55 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:39:55 +07] [INFO] Server is initializing…
[2018/03/16 09:39:55 +07] [INFO] Pinging SQL master database
[2018/03/16 09:39:55 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:40:32 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:40:32 +07] [INFO] Server is initializing…
[2018/03/16 09:40:32 +07] [INFO] Pinging SQL master database
[2018/03/16 09:40:32 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:40:36 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:40:36 +07] [INFO] Server is initializing…
[2018/03/16 09:40:36 +07] [INFO] Pinging SQL master database
[2018/03/16 09:40:36 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:41:15 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:41:15 +07] [INFO] Server is initializing…
[2018/03/16 09:41:15 +07] [INFO] Pinging SQL master database
[2018/03/16 09:41:16 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:41:20 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:41:20 +07] [INFO] Server is initializing…
[2018/03/16 09:41:20 +07] [INFO] Pinging SQL master database
[2018/03/16 09:41:20 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:41:50 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:41:50 +07] [INFO] Server is initializing…
[2018/03/16 09:41:50 +07] [INFO] Pinging SQL master database
[2018/03/16 09:41:50 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:41:54 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:41:54 +07] [INFO] Server is initializing…
[2018/03/16 09:41:54 +07] [INFO] Pinging SQL master database
[2018/03/16 09:41:54 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:42:27 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:42:27 +07] [INFO] Server is initializing…
[2018/03/16 09:42:27 +07] [INFO] Pinging SQL master database
[2018/03/16 09:42:27 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:42:32 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:42:32 +07] [INFO] Server is initializing…
[2018/03/16 09:42:32 +07] [INFO] Pinging SQL master database
[2018/03/16 09:42:32 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/16 09:42:54 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/16 09:42:54 +07] [INFO] Server is initializing…
[2018/03/16 09:42:54 +07] [INFO] Pinging SQL master database

Ju_St · March 19, 2018, 4:17am

We’ve upgraded to 4.8.0 today, which also attempted (and succeeded) in upgrading the database server. Seems to be stable again now. Will report back if problems persist.

lindy65 · March 22, 2018, 8:38am

Thanks @Ju_St,

Let us know how it goes and whether you need any help troubleshooting further…

Ju_St · March 28, 2018, 3:20am

Hello lindy,

the server runs stable most of the time, but weirdly some random actions cause a restart. Most recent example is uploading a certain image (8.4 MB), which causes a restart with the logs not showing any details on why it restarted. It just shows this:

[2018/03/28 10:15:39 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/03/28 10:15:39 +07] [INFO] Server is initializing…
[2018/03/28 10:15:39 +07] [INFO] Pinging SQL master database
[2018/03/28 10:15:40 +07] [INFO] Current version is 4.8.0 (4.8.0/Thu Mar 15 23:11:12 UTC 2018/d1ed79a66c7930020b7fda046a11050f5890c84e/6f563c1fa497d123134fd499eb37674eb2511325)
[2018/03/28 10:15:40 +07] [INFO] Enterprise Enabled: true
[2018/03/28 10:15:40 +07] [INFO] Current working directory is /opt/mattermost
[2018/03/28 10:15:40 +07] [INFO] Loaded config file from /opt/mattermost/config/config.json
[2018/03/28 10:15:40 +07] [INFO] Connection to S3 or minio is good. Bucket exists.
[2018/03/28 10:15:40 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/03/28 10:15:40 +07] [INFO] Starting up plugins
[2018/03/28 10:15:40 +07] [WARN] unable to create user namespace: fork/exec /proc/self/exe: permission denied
[2018/03/28 10:15:40 +07] [WARN] plugin sandboxing is not supported. plugins will run with the same access level as the server
[2018/03/28 10:15:41 +07] [INFO] Starting Server…
[2018/03/28 10:15:41 +07] [INFO] Server is listening on XXX.XXX.XXX.XXX:8065
[2018/03/28 10:15:41 +07] [INFO] API version 3 is scheduled for deprecation. Please see https://api.mattermost.com for details.
[2018/03/28 10:15:41 +07] [INFO] Starting 2 websocket hubs
[2018/03/28 10:15:41 +07] [INFO] Starting workers
[2018/03/28 10:15:41 +07] [INFO] Starting schedulers.

Adding new users with the platform command also seems to cause a restart (although the users are successfully created, while the file upload is stuck indefinitely)

lindy65 · March 29, 2018, 7:45am

Thanks for the feedback @Ju_St,

I’ve asked our engineers to help troubleshoot this issue…

jwilander · March 29, 2018, 3:15pm

@Ju_St couple questions to help troubleshoot:

How large of a deployment do you have? Some good numbers would be number of user and channel rows in your database
Are you able to capture the stderr output of the Mattermost process? Sometimes that has more information about the issue

Ju_St · March 30, 2018, 2:48am

Hello jwilander,
we currently have 192 channel rows and 113 user rows. Let me check to see if I can get the stderr output.

jwilander · April 2, 2018, 12:10pm

Ok with that low of row counts that rules out it being related to a performance issue we were having. Let me know if you’re able to grab the stderr

Ju_St · April 5, 2018, 2:09am

Sorry, no luck so far with the stderr output. Any other things I could try to get more information about the issue?

Ju_St · April 9, 2018, 2:11am

Another thing I noticed, not sure if this is supposed to happen:

Whenever I create user accounts through the platform commands it re-initiates the server

For example these two commands:
sudo ./platform user create --email xxxxx@xxxx.com --username xxxxx --password xxxx
sudo ./platform user verify xxxxx@xxxx.com

Show this in the logs for each user created this way:
[2018/04/09 09:04:00 +07] [INFO] Server is initializing…
[2018/04/09 09:04:00 +07] [INFO] Pinging SQL master database
[2018/04/09 09:04:00 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.

And then a bit later:
[2018/04/09 09:09:07 +07] [INFO] Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’
[2018/04/09 09:09:07 +07] [INFO] Server is initializing…
[2018/04/09 09:09:07 +07] [INFO] Pinging SQL master database
[2018/04/09 09:09:09 +07] [INFO] Current version is 4.8.0 (4.8.0/Thu Mar 15 23:11:12 UTC 2018/d1ed79a66c7930020b7fda046a11050f5890c84e/6f563c1fa497d123134fd499eb37674eb2511325)
[2018/04/09 09:09:09 +07] [INFO] Enterprise Enabled: true
[2018/04/09 09:09:09 +07] [INFO] Current working directory is /opt/mattermost
[2018/04/09 09:09:09 +07] [INFO] Loaded config file from /opt/mattermost/config/config.json
[2018/04/09 09:09:09 +07] [INFO] Connection to S3 or minio is good. Bucket exists.
[2018/04/09 09:09:09 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.
[2018/04/09 09:09:09 +07] [INFO] Starting up plugins
[2018/04/09 09:09:09 +07] [WARN] unable to create user namespace: fork/exec /proc/self/exe: permission denied
[2018/04/09 09:09:09 +07] [WARN] plugin sandboxing is not supported. plugins will run with the same access level as the server
[2018/04/09 09:09:10 +07] [INFO] Starting Server…
[2018/04/09 09:09:10 +07] [INFO] Server is listening on XXX.XXX.XXX.XXX:8065
[2018/04/09 09:09:10 +07] [INFO] API version 3 is scheduled for deprecation. Please see https://api.mattermost.com for details.
[2018/04/09 09:09:10 +07] [INFO] Starting 2 websocket hubs
[2018/04/09 09:09:10 +07] [INFO] Starting workers
[2018/04/09 09:09:10 +07] [INFO] Starting schedulers.

The users are created and work, but should the server initialize again each time?

jwilander · April 13, 2018, 12:20pm

Seeing:

[2018/04/09 09:04:00 +07] [INFO] Server is initializing…
[2018/04/09 09:04:00 +07] [INFO] Pinging SQL master database
[2018/04/09 09:04:00 +07] [INFO] License key from https://mattermost.com required to unlock enterprise features.

after running a platform command is normal but it shouldn’t cause an entire server restart a few minutes later. One thing you might be able to try is manually running the server attached at the command line with ./bin/platform. If you can catch a server restart that way it should also print out the stderr if it’s being caused a by a crash

Ju_St · April 20, 2018, 8:51am

It seems like updating to 4.9 has resolved the issue. I just tried to upload files when starting the server from the platform command and from the normal systemctl start command. In both cases uploading the files worked without a server crash/restart.

One thing I saw when starting the server from the platform command was this (over and over again) though:

[2018/04/20 15:41:09 +07] [EROR] /api/v4/plugins/webapp:GetActivePluginManifests code=501 rid=m5i7o7nhbfguzenwg1bcrnuyyo uid=8oyg7kc89tfjbrbpmb7hos173y ip=removed.ip.address Plugins have been disabled. Please check your logs for details. [details: ]
[2018/04/20 15:41:47 +07] [EROR] /api/v4/plugins/webapp:GetActivePluginManifests code=501 rid=n1ezh7bciirztpxuhntp5eit6w uid=ej6n4ptsc7no5jkthdhaxqeufr ip=removed.ip.address Plugins have been disabled. Please check your logs for details. [details: ]
[2018/04/20 15:41:47 +07] [EROR] /api/v4/plugins/webapp:GetActivePluginManifests code=501 rid=zk55okuehtrydcdqtex3oe9fdr uid=8ugq1t7363fhfq5hkijumfrp3a ip=removed.ip.address Plugins have been disabled. Please check your logs for details. [details: ]
[2018/04/20 15:42:42 +07] [EROR] /api/v4/plugins/webapp:GetActivePluginManifests code=501 rid=ra3p1o4ccjyf8nygd3d4hiueze uid=4xa5eyw3pt83zch8hw6ba5dhzo ip=removed.ip.address Plugins have been disabled. Please check your logs for details. [details: ]
[2018/04/20 15:42:55 +07] [EROR] /api/v4/plugins/webapp:GetActivePluginManifests code=501 rid=8ww3e1anijdo9dw77qdequtj1w uid=zywk4d55wtgzmkmjrm4ny1mcao ip=removed.ip.address Plugins have been disabled. Please check your logs for details. [details: ]
[2018/04/20 15:43:02 +07] [EROR] /api/v4/plugins/webapp:GetActivePluginManifests code=501 rid=bdcgehanb7rs3jefnrhxthjauh uid=uq1dehr39tbkig51dd38jzqe8r ip=removed.ip.address Plugins have been disabled. Please check your logs for details. [details: ]