MatterMost won't start after rebooting EC2 instance

Troubleshooting
1

For troubleshooting questions, please post in the following format:

Summary

After restarting EC2 instance, Mattermost fails to start with the message

{“level”:“error”,“ts”:1539454659.400191,“caller”:“app/server.go:219”,“msg”:“Error starting server, err:open : no such file or directory”}

Steps to reproduce

How can we reproduce the issue (what version are you using?)

  1. Install 5.3.1 following the installation instructions, using Postgres on Amazon Linux
  2. Run it for two days without issue
  3. Shutdown EC2 instance at end of night
  4. Start EC2 instance the next morning. Mattermost hangs on start with an error about a missing file:

{“level”:“info”,“ts”:1539455002.8930788,“caller”:“utils/i18n.go:83”,“msg”:“Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’”}
{“level”:“info”,“ts”:1539455002.8931653,“caller”:“app/app.go:195”,“msg”:“Server is initializing…”}
{“level”:“info”,“ts”:1539455002.89509,“caller”:“sqlstore/supplier.go:200”,“msg”:“Pinging SQL master database”}
{“level”:“info”,“ts”:1539455002.9436934,“caller”:“commands/server.go:81”,“msg”:“Current version is 5.3.0 (5.3.1/Wed Sep 19 07:42:34 UTC 2018/fd21e53365d504155ab87f9bef60b1ab4faeb38d/c87ad1eeda18455c22a42ede7276194412e3a25f)”}
{“level”:“info”,“ts”:1539455002.9437466,“caller”:“commands/server.go:82”,“msg”:“Enterprise Enabled: true”}
{“level”:“info”,“ts”:1539455002.9437597,“caller”:“commands/server.go:83”,“msg”:“Current working directory is /opt/mattermost”}
{“level”:“info”,“ts”:1539455002.9437919,“caller”:“commands/server.go:84”,“msg”:“Loaded config file from /opt/mattermost/config/config.json”}
{“level”:“info”,“ts”:1539455002.9439156,“caller”:“utils/file_backend_local.go:32”,“msg”:“Able to write files to local storage.”}
{“level”:“info”,“ts”:1539455002.9449074,“caller”:“app/license.go:44”,“msg”:“License key from https://mattermost.com required to unlock enterprise features.”}
{“level”:“info”,“ts”:1539455002.9455242,“caller”:“app/plugin.go:100”,“msg”:“Starting up plugins”}
{“level”:“info”,“ts”:1539455003.4513152,“caller”:“app/server.go:88”,“msg”:“Starting Server…”}
{“level”:“info”,“ts”:1539455003.451441,“caller”:“app/server.go:148”,“msg”:“Server is listening on [::]:8065”}
{“level”:“error”,“ts”:1539455003.4516575,“caller”:“app/server.go:219”,“msg”:“Error starting server, err:open : no such file or directory”}
{“level”:“info”,“ts”:1539455003.4580114,“caller”:“app/web_hub.go:75”,“msg”:“Starting 4 websocket hubs”}
{“level”:“info”,“ts”:1539455003.4661472,“caller”:“sqlstore/post_store.go:1297”,“msg”:“Post.Message supports at most 16383 characters (65535 bytes)”}
{“level”:“info”,“ts”:1539455003.4952223,“caller”:“jobs/workers.go:62”,“msg”:“Starting workers”}
{“level”:“info”,“ts”:1539455003.4960074,“caller”:“jobs/schedulers.go:68”,“msg”:“Starting schedulers.”}

  1. kill -9 the process

  2. ps aux | grep mattermost
    root 7654 0.0 0.0 119468 976 pts/0 S+ 14:40 0:00 grep --color=auto mattermost

  3. Enable debug logging in config/config.json

  4. service mattermost start. Service hangs at scheduler with errors in logs (previous error as well as errors about plugin directories being in use)

Expected behavior

The server should start without error

Observed behavior

What did you see happen? Please include relevant error messages and/or screenshots.

[root@ip-172-16-5-141 mattermost]# tail -n 200 logs/mattermost.log
{“level”:“info”,“ts”:1539456396.79089,“caller”:“utils/i18n.go:83”,“msg”:“Loaded system translations for ‘en’ from ‘/opt/mattermost/i18n/en.json’”}
{“level”:“info”,“ts”:1539456396.7910206,“caller”:“app/app.go:195”,“msg”:“Server is initializing…”}
{“level”:“debug”,“ts”:1539456396.7915618,“caller”:“utils/html.go:30”,“msg”:“Parsing server templates at /opt/mattermost/templates”}
{“level”:“info”,“ts”:1539456396.7929425,“caller”:“sqlstore/supplier.go:200”,“msg”:“Pinging SQL master database”}
{“level”:“debug”,“ts”:1539456396.8319116,“caller”:“sqlstore/preference_store.go:41”,“msg”:“Deleting any unused pre-release features”}
{“level”:“debug”,“ts”:1539456396.834403,“caller”:“jobs/schedulers.go:29”,“msg”:“Initialising schedulers.”}
{“level”:“info”,“ts”:1539456396.83456,“caller”:“commands/server.go:81”,“msg”:“Current version is 5.3.0 (5.3.1/Wed Sep 19 07:42:34 UTC 2018/fd21e53365d504155ab87f9bef60b1ab4faeb38d/c87ad1eeda18455c22a42ede7276194412e3a25f)”}
{“level”:“info”,“ts”:1539456396.8345916,“caller”:“commands/server.go:82”,“msg”:“Enterprise Enabled: true”}
{“level”:“info”,“ts”:1539456396.8346014,“caller”:“commands/server.go:83”,“msg”:“Current working directory is /opt/mattermost”}
{“level”:“info”,“ts”:1539456396.8346443,“caller”:“commands/server.go:84”,“msg”:“Loaded config file from /opt/mattermost/config/config.json”}
{“level”:“info”,“ts”:1539456396.8347473,“caller”:“utils/file_backend_local.go:32”,“msg”:“Able to write files to local storage.”}
{“level”:“debug”,“ts”:1539456396.834961,“caller”:“jobs/schedulers.go:29”,“msg”:“Initialising schedulers.”}
{“level”:“debug”,“ts”:1539456396.835594,“caller”:“utils/license.go:83”,“msg”:“We could not find the license key in the database or on disk at /opt/mattermost/config/mattermost.mattermost-license”}
{“level”:“info”,“ts”:1539456396.8360565,“caller”:“app/license.go:44”,“msg”:“License key from https://mattermost.com required to unlock enterprise features.”}
{“level”:“info”,“ts”:1539456396.8367288,“caller”:“app/plugin.go:100”,“msg”:“Starting up plugins”}
{“level”:“error”,“ts”:1539456397.0310977,“caller”:“app/plugin.go:129”,“msg”:“Failed to unpack prepackaged plugin”,“error”:“installPlugin: Unable to move plugin from temporary directory to final destination. Another plugin may be using the same directory name., destination already exists”,“path”:“/opt/mattermost/prepackaged_plugins/mattermost-jira-plugin-linux-amd64.tar.gz”}
{“level”:“error”,“ts”:1539456397.2281704,“caller”:“app/plugin.go:129”,“msg”:“Failed to unpack prepackaged plugin”,“error”:“installPlugin: Unable to move plugin from temporary directory to final destination. Another plugin may be using the same directory name., destination already exists”,“path”:“/opt/mattermost/prepackaged_plugins/mattermost-zoom-plugin-linux-amd64.tar.gz”}
{“level”:“error”,“ts”:1539456397.228276,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/jira”,“error”:“open plugins/jira/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2283008,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/zoom”,“error”:“open plugins/zoom/plugin.yml: permission denied”}
{“level”:“info”,“ts”:1539456397.2285974,“caller”:“app/server.go:88”,“msg”:“Starting Server…”}
{“level”:“info”,“ts”:1539456397.228812,“caller”:“app/server.go:148”,“msg”:“Server is listening on [::]:8065”}
{“level”:“error”,“ts”:1539456397.229114,“caller”:“app/server.go:219”,“msg”:“Error starting server, err:open : no such file or directory”}
{“level”:“debug”,“ts”:1539456397.235222,“caller”:“api4/plugin.go:20”,“msg”:“EXPERIMENTAL: Initializing plugin api”}
{“level”:“info”,“ts”:1539456397.2356615,“caller”:“app/web_hub.go:75”,“msg”:“Starting 4 websocket hubs”}
{“level”:“debug”,“ts”:1539456397.2357197,“caller”:“web/web.go:27”,“msg”:“Initializing web routes”}
{“level”:“debug”,“ts”:1539456397.2358732,“caller”:“utils/subpath.go:59”,“msg”:“No rewrite required for static assets”,“path”:“/static/”}
{“level”:“debug”,“ts”:1539456397.235861,“caller”:“app/web_hub.go:400”,“msg”:“Hub for index 1 is starting with goroutine 2468”}
{“level”:“debug”,“ts”:1539456397.2359037,“caller”:“web/static.go:26”,“msg”:“Using client directory at /opt/mattermost/client”}
{“level”:“debug”,“ts”:1539456397.2359598,“caller”:“app/web_hub.go:400”,“msg”:“Hub for index 0 is starting with goroutine 2467”}
{“level”:“debug”,“ts”:1539456397.236125,“caller”:“app/web_hub.go:400”,“msg”:“Hub for index 2 is starting with goroutine 2469”}
{“level”:“debug”,“ts”:1539456397.2362182,“caller”:“app/web_hub.go:400”,“msg”:“Hub for index 3 is starting with goroutine 2470”}
{“level”:“info”,“ts”:1539456397.2430675,“caller”:“sqlstore/post_store.go:1297”,“msg”:“Post.Message supports at most 16383 characters (65535 bytes)”}
{“level”:“error”,“ts”:1539456397.2434707,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/jira”,“error”:“open plugins/jira/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2435052,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/zoom”,“error”:“open plugins/zoom/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2435777,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/jira”,“error”:“open plugins/jira/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2435951,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/zoom”,“error”:“open plugins/zoom/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2675183,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/jira”,“error”:“open plugins/jira/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2675717,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/zoom”,“error”:“open plugins/zoom/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2686849,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/jira”,“error”:“open plugins/jira/plugin.yml: permission denied”}
{“level”:“error”,“ts”:1539456397.2687209,“caller”:“app/plugin.go:55”,“msg”:“Plugin manifest could not be loaded”,“plugin_path”:“plugins/zoom”,“error”:“open plugins/zoom/plugin.yml: permission denied”}
{“level”:“info”,“ts”:1539456397.2705193,“caller”:“jobs/workers.go:62”,“msg”:“Starting workers”}
{“level”:“info”,“ts”:1539456397.270818,“caller”:“commands/server.go:265”,“msg”:“Sending systemd READY notification.”}
{“level”:“debug”,“ts”:1539456397.272278,“caller”:“sqlstore/session_store.go:227”,“msg”:“Cleaning up session store.”}
{“level”:“debug”,“ts”:1539456397.2724757,“caller”:“sqlstore/tokens_store.go:72”,“msg”:“Cleaning up token store.”}
{“level”:“debug”,“ts”:1539456397.2726328,“caller”:“sqlstore/command_webhook_store.go:88”,“msg”:“Cleaning up command webhook store.”}
{“level”:“debug”,“ts”:1539456397.2728262,“caller”:“migrations/worker.go:44”,“msg”:“Worker started”,“worker”:“Migrations”}
{“level”:“debug”,“ts”:1539456397.2728393,“caller”:“jobs/jobs_watcher.go:39”,“msg”:“Watcher Started”}
{“level”:“info”,“ts”:1539456397.27287,“caller”:“jobs/schedulers.go:68”,“msg”:“Starting schedulers.”}
{“level”:“debug”,“ts”:1539456397.279431,“caller”:“jobs/schedulers.go:163”,“msg”:“Next run time for scheduler MigrationsScheduler: 2018-10-13 14:47:37.279419437 -0400 EDT m=+60.639404180”}

2

Hi @Minnow, thank you for reaching out.

Can you also help share details on your general configuration settings: https://docs.mattermost.com/administration/config-settings.html#configuration.

3

Hi, Amy.

The configuration file has default values for everything, except (1) It’s using Postgresql instead of MySQL, and (2) it’s using /data/mattermost instead of /opt/mattermost/data for data. (And, yes, /data/mattermost exists, has the correct properties and is mounted before Mattermost inits.)

Any ideas?

Thanks!

4

Judging by

{“level”:“error”,“ts”:1539455003.4516575,“caller”:“app/server.go:219”,“msg”:“Error starting server, err:open : no such file or directory”}

it’s failing because the underlying HTTP server returned the error which it seems like it should only do if you have TLS enabled. Do you have that turned on?

5

That was it. Someone had switched it over to TLS prematurely. I set “ConnectionSecurity” : “” and we’re back in business.

Thanks!

6

Awesome. Glad I could help.