Can't update from 7.1.5 to 7.2.1

[ricrui3 (Ricardo Ruiz)]

For feature requests, please see: Contributing Feature Proposals - Mattermost.

For troubleshooting questions, please post in the following format:

Summary
I’m trying to update my mattermost from 5.36.1 to the latest version in small increments but when trying to update to 7.2.1 the application doesn’t start.

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

I updated in small batches, this is the path I followed:

• 5.36.1
• 5.37.10
• 5.39.3
• 6.3.10
• 7.1.5
  Up to here, I didn’t have any problem following the steps from Upgrade Mattermost Server but then I tried to update to 7.5.2 and everything went downhill. I couldn’t access the web application and even if I reverted to a previous version it wouldn’t start. I needed to restore my DB backup and then install 7.1.5 again to make it work.

Expected behavior
Describe your issue in detail

Observed behavior
What did you see happen? Please include relevant error messages and/or screenshots.
These are the logs from mattermost.log with debug enabled

{"timestamp":"2023-01-13 13:07:51.935 Z","level":"info","msg":"Server is initializing...","caller":"app/server.go:271","go_version":"go1.18.1"}
{"timestamp":"2023-01-13 13:07:51.935 Z","level":"info","msg":"Pinging SQL","caller":"sqlstore/store.go:228","database":"master"}
{"timestamp":"2023-01-13 13:07:51.975 Z","level":"info","msg":"Pinging SQL","caller":"sqlstore/store.go:228","database":"master"}
{"timestamp":"2023-01-13 13:07:51.983 Z","level":"debug","msg":"morph.go:175: ==  create_enums: migrating  =======================================================================\n","caller":"sqlstore/utils.go:159"}
{"timestamp":"2023-01-13 13:07:52.367 Z","level":"debug","msg":"morph.go:182: ==  create_enums: migrated (0.3842s)  ==============================================================\n","caller":"sqlstore/utils.go:159"}
{"timestamp":"2023-01-13 13:07:52.371 Z","level":"debug","msg":"Deleting any unused pre-release features","caller":"sqlstore/preference_store.go:25"}
{"timestamp":"2023-01-13 13:07:52.386 Z","level":"debug","msg":"We could not find the license key in the database or on disk at","caller":"utils/license.go:114","filename":"/opt/mattermost/bin/config/mattermost.mattermost-license"}
{"timestamp":"2023-01-13 13:07:52.395 Z","level":"error","msg":"License key from https://mattermost.com required to unlock enterprise features.","caller":"app/license.go:151","error":"resource: License id: "}
{"timestamp":"2023-01-13 13:07:52.395 Z","level":"info","msg":"Starting websocket hubs","caller":"app/web_hub.go:93","number_of_hubs":2}
{"timestamp":"2023-01-13 13:07:52.396 Z","level":"info","msg":"Loaded system translations","caller":"i18n/i18n.go:93","for locale":"en","from locale":"/opt/mattermost/i18n/en.json"}
{"timestamp":"2023-01-13 13:07:52.406 Z","level":"debug","msg":"Hub is starting","caller":"app/web_hub.go:415","index":0}
{"timestamp":"2023-01-13 13:07:52.406 Z","level":"debug","msg":"Hub is starting","caller":"app/web_hub.go:415","index":1}
{"timestamp":"2023-01-13 13:07:52.451 Z","level":"info","msg":"Current version is 7.2.1 (7.2.1/Tue Oct 11 15:35:48 UTC 2022/64021bf5c4810546cd9a8aa22d263b0365e98d54/bf26b0fa15446e3e9d9683982aa5601a04aeb0a3)","caller":"app/server.go:581","current_version":"7.2.1","build_number":"7.2.1","build_date":"Tue Oct 11 15:35:48 UTC 2022","build_hash":"64021bf5c4810546cd9a8aa22d263b0365e98d54","build_hash_enterprise":"bf26b0fa15446e3e9d9683982aa5601a04aeb0a3"}
{"timestamp":"2023-01-13 13:07:52.451 Z","level":"info","msg":"Enterprise Build","caller":"app/server.go:590","enterprise_build":true}
{"timestamp":"2023-01-13 13:07:52.451 Z","level":"info","msg":"Printing current working","caller":"app/server.go:596","directory":"/opt/mattermost/bin"}
{"timestamp":"2023-01-13 13:07:52.451 Z","level":"info","msg":"Loaded config","caller":"app/server.go:597","source":"file:///opt/mattermost/config/config.json"}
{"timestamp":"2023-01-13 13:07:52.453 Z","level":"debug","msg":"Logging metrics enabled","caller":"app/server.go:965"}
{"timestamp":"2023-01-13 13:07:52.455 Z","level":"debug","msg":"Will fetch notices from","caller":"app/product_notices.go:344","url":"https://notices.mattermost.com/","skip_cache":false}
{"timestamp":"2023-01-13 13:07:52.456 Z","level":"info","msg":"Starting workers","caller":"jobs/workers.go:48"}
{"timestamp":"2023-01-13 13:07:52.457 Z","level":"debug","msg":"Cleaning up session store.","caller":"app/server.go:1600"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Cleaning up token store.","caller":"app/server.go:1585"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Cleaning up command webhook store.","caller":"sqlstore/command_webhook_store.go:93"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"jobs/base_workers.go:37","worker":"ExtractContent"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"jobs/base_workers.go:37","worker":"ExportProcess"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"jobs/base_workers.go:37","worker":"ProductNotices"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"jobs/base_workers.go:37","worker":"ImportProcess"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"jobs/base_workers.go:37","worker":"ImportDelete"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"jobs/base_workers.go:37","worker":"ExportDelete"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"migrations/worker.go:50","worker":"Migrations"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"scheduler/worker.go:39","worker":"Plugins"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker Started","caller":"indexer/indexing_job.go:100","workername":"BleveIndexer"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Worker started","caller":"resend_invitation_email/worker.go:54","worker":"resend_invitation_email"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"debug","msg":"Watcher Started","caller":"jobs/jobs_watcher.go:38"}
{"timestamp":"2023-01-13 13:07:52.458 Z","level":"info","msg":"Starting schedulers.","caller":"jobs/schedulers.go:47"}
{"timestamp":"2023-01-13 13:07:52.478 Z","level":"debug","msg":"We could not find the license key in the database or on disk at","caller":"utils/license.go:114","filename":"/opt/mattermost/bin/config/mattermost.mattermost-license"}
{"timestamp":"2023-01-13 13:07:52.482 Z","level":"debug","msg":"Logging metrics enabled","caller":"app/server.go:965"}
{"timestamp":"2023-01-13 13:07:52.482 Z","level":"debug","msg":"License cannot be found.","caller":"app/server.go:1791"}
{"timestamp":"2023-01-13 13:07:52.591 Z","level":"debug","msg":"EXPERIMENTAL: Initializing plugin api","caller":"api4/plugin.go:28"}
{"timestamp":"2023-01-13 13:07:52.598 Z","level":"debug","msg":"Initializing web routes","caller":"web/web.go:26"}
{"timestamp":"2023-01-13 13:07:52.605 Z","level":"debug","msg":"Rewriting static assets","caller":"utils/subpath.go:84","from_subpath":"/","to_subpath":"/"}
{"timestamp":"2023-01-13 13:07:52.668 Z","level":"debug","msg":"Using client directory","caller":"web/static.go:30","clientDir":"/opt/mattermost/client"}
{"timestamp":"2023-01-13 13:07:52.668 Z","level":"info","msg":"Starting up plugins","caller":"app/plugin.go:213"}
{"timestamp":"2023-01-13 13:07:52.668 Z","level":"error","msg":"Failed to start up plugins","caller":"app/plugin.go:221","error":"mkdir ./client/plugins: no such file or directory"}
{"timestamp":"2023-01-13 13:07:52.675 Z","level":"debug","msg":"Able to write files to local storage.","caller":"filestore/localstore.go:78"}
{"timestamp":"2023-01-13 13:07:52.677 Z","level":"info","msg":"Starting Server...","caller":"app/server.go:1245"}
{"timestamp":"2023-01-13 13:07:52.677 Z","level":"info","msg":"Server is listening on [::]:443","caller":"app/server.go:1318","address":"[::]:443"}
{"timestamp":"2023-01-13 13:07:52.677 Z","level":"debug","msg":"No license provided; Remote Cluster services disabled","caller":"app/server.go:888"}
{"timestamp":"2023-01-13 13:07:52.765 Z","level":"debug","msg":"Next run time for scheduler","caller":"jobs/schedulers.go:147","scheduler_name":"product_notices","next_runtime":"2023-01-13 14:07:52.765546096 +0000 UTC m=+3601.206106071"}
{"timestamp":"2023-01-13 13:07:52.771 Z","level":"debug","msg":"Next run time for scheduler","caller":"jobs/schedulers.go:147","scheduler_name":"import_delete","next_runtime":"2023-01-14 13:07:52.771432142 +0000 UTC m=+86401.211992089"}
{"timestamp":"2023-01-13 13:07:52.771 Z","level":"debug","msg":"Scheduler: isEnabled: false","caller":"last_accessible_post/scheduler.go:20","scheduler":"last_accessible_post"}
{"timestamp":"2023-01-13 13:07:52.781 Z","level":"debug","msg":"Next run time for scheduler","caller":"jobs/schedulers.go:147","scheduler_name":"migrations","next_runtime":"2023-01-13 13:08:52.781389497 +0000 UTC m=+61.221949436"}
{"timestamp":"2023-01-13 13:07:52.784 Z","level":"debug","msg":"Next run time for scheduler","caller":"jobs/schedulers.go:147","scheduler_name":"export_delete","next_runtime":"2023-01-14 13:07:52.784450962 +0000 UTC m=+86401.225010908"}
{"timestamp":"2023-01-13 13:07:52.794 Z","level":"debug","msg":"Next run time for scheduler","caller":"jobs/schedulers.go:147","scheduler_name":"plugins","next_runtime":"2023-01-14 13:07:52.794272378 +0000 UTC m=+86401.234832322"}
{"timestamp":"2023-01-13 13:08:52.795 Z","level":"debug","msg":"Scheduling Job","caller":"migrations/scheduler.go:45","scheduler":"migrations"}
{"timestamp":"2023-01-13 13:08:52.796 Z","level":"debug","msg":"All migrations are complete.","caller":"migrations/scheduler.go:84","scheduler":"migrations"}
{"timestamp":"2023-01-13 13:08:52.797 Z","level":"debug","msg":"Next run time for scheduler","caller":"jobs/schedulers.go:147","scheduler_name":"migrations","next_runtime":"<nil>"}
{"timestamp":"2023-01-13 13:17:23.767 Z","level":"error","msg":"http: TLS handshake error from 133.32.131.63:1618: 429 urn:ietf:params:acme:error:rateLimited: Error creating new order :: too many certificates (5) already issued for this exact set of domains in the last 168 hours: rondhuit.chat, retry after 2023-01-14T21:28:54Z: see https://letsencrypt.org/docs/duplicate-certificate-limit/","caller":"log/log.go:195","source":"httpserver"}
{"timestamp":"2023-01-13 13:17:23.767 Z","level":"error","msg":"http: TLS handshake error from 133.32.131.63:1612: acme/autocert: missing certificate","caller":"log/log.go:195","source":"httpserver"}

I just noticed the last log that happened after 9 minutes since it started? could this be the reason?

[agriesser (Alexander Griesser)]

Hi ricrui3!

You would not have needed so many steps, you can upgrade directly from 5.37.10 to 7.5.2, the only important intermediate step is to go to 5.37.10 as outlined in the Important Upgrade Notes since this is the release that switches to a new database migration scheme and all previous migrations would have been lost otherwise.

The only errors I can see in your logs are:

{"timestamp":"2023-01-13 13:07:52.668 Z","level":"error","msg":"Failed to start up plugins","caller":"app/plugin.go:221","error":"mkdir ./client/plugins: no such file or directory"}

Can you verify that all files and folders below the /opt/mattermost directory belong to the mattermost user? You can ensure that by running:

chown -R mattermost: /opt/mattermost

Also please verify that the directory it’s complaining about really exists (maybe it got deleted during the upgrade).

ls -l /opt/mattermost/client/plugins

The second error message is this one, which indicates that you reached the Let’s encrypt renewal limit for the certificate on your deployment:

{"timestamp":"2023-01-13 13:17:23.767 Z","level":"error","msg":"http: TLS handshake error from 133.32.131.63:1618: 429 urn:ietf:params:acme:error:rateLimited: Error creating new order :: too many certificates (5) already issued for this exact set of domains in the last 168 hours: rondhuit.chat, retry after 2023-01-14T21:28:54Z: see https://letsencrypt.org/docs/duplicate-certificate-limit/","caller":"log/log.go:195","source":"httpserver"}
{"timestamp":"2023-01-13 13:17:23.767 Z","level":"error","msg":"http: TLS handshake error from 133.32.131.63:1612: acme/autocert: missing certificate","caller":"log/log.go:195","source":"httpserver"}

It seems you’re directly using the Let’s encrypt feature of the Mattermost application server instead of using a reverse proxy in front of it, but I’m not sure if this error would really result in the application server not starting. There should be a cache file, though, which defaults to ./config/letsencrypt.cache relative to the Mattermost base directory and should contain a valid certificate and as long as it’s valid, it should not try to generate a new one and run into this limit.

[ricrui3 (Ricardo Ruiz)]

Hi agriesser!

Thank you for your help.

Can you verify that all files and folders below the /opt/mattermost directory belong to the mattermost user?

I ran the command you provided and there were no results so It’s good I think.

Also please verify that the directory it’s complaining about really exists (maybe it got deleted during the upgrade).

I confirmed that the directory exists. This is the first time I give maintenance to this server and one thing that I noticed is that the directory for the files is on /opt/mattermost/bin/data instead of /opt/mattermost/data so I guess these two things are related but I don’t know how to config them correctly.

About the last point, I can see the ./config/letsencrypt.cache folder with 3 files in both my current folder and the backup of my failed update. I’ll try to update once again today to see if this was the reason.

[agriesser (Alexander Griesser)]

@ricrui3

I ran the command you provided and there were no results so It’s good I think.

The command will only output something if there are errors, but it will not tell you if it changed something, so by just running this command, we do not know if there were missing permissions earlier, but we made sure that they are now correct.

@ricrui3

I noticed is that the directory for the files is on /opt/mattermost/bin/data instead of /opt/mattermost/data

OK, this explains a lot. The default configuration for the setting FileSettings.Directory is ./data which means that a directory named data will be created in the current working directory of the application.
The only reason how this could happen in your scenario, is when you started mattermost directly from within the bin subfolder, when you should start it from the parent directory.
When following the setup recommendations, you should end up with a folder called /opt/mattermost which is the home of your Mattermost installation. In there, you will find all the relevant directories like data, bin, logs, config, etc.
What method do you use to start Mattermost? Did you create your own systemd unit or any other script to do that? If so, please show us either your systemd unit or the script you used.
Most likely the working directory is not set correctly, see here for some examples:

This invocation is wrong, since the current working directory (cwd) will be the /opt/mattermost/bin folder and when you start Mattermost in there, it will create a folder data in /opt/mattermost/bin because of the configuration value in your config.json. Also all other configuration variables, plugin directories, etc. cannot be found because they are also specified by relative values in your config/config.json which is probably what you’re seeing in your error logs now.

cd /opt/mattermost/bin
./mattermost

This is how it should be:

cd /opt/mattermost
bin/mattermost

You will probably have some data in the /opt/mattermost/data directory now and some in the /opt/mattermost/bin/data directory and it will be a bit tricky to merge these two now. In order to get an idea of what we’re dealing with, I’d need the output of the following command (which is probably quite large, so we’re dumping the output in a file called dir-listing.txt in the directory /tmp which you could then attach here or upload it anywhere for me to look at):

ls -lR /opt/mattermost > /tmp/dir-listing.txt

[ricrui3 (Ricardo Ruiz)]

I didn’t set up mattermost originally but it looks like we are using a systemd script, should I set WorkingDirectory=/opt/mattermost and ExecStart=bin/mattermost?

[Unit]
Description=Mattermost
After=syslog.target network.target mysql.service

[Service]
Type=simple
WorkingDirectory=/opt/mattermost/bin
User=mattermost
ExecStart=/opt/mattermost/bin/mattermost
PIDFile=/var/spool/mattermost/pid/master.pid

[Install]
WantedBy=multi-user.target mysql.service

you’re right, there are files in both directories but the most recent and relevant ones IMO are the ones on /opt/mattermost/bin/data
here’s the dump

[agriesser (Alexander Griesser)]

@ricrui3

should I set WorkingDirectory=/opt/mattermost and ExecStart=bin/mattermost?

The important part is the working directory, the execstart can be left untouched, here’s the contents of my service section for reference:

[Service]
Type=notify
ExecStart=/opt/mattermost/bin/mattermost
TimeoutStartSec=3600
Restart=always
RestartSec=10
WorkingDirectory=/opt/mattermost
User=mattermost
Group=mattermost
LimitNOFILE=49152

But please do not change that right now, we need to first merge your data, now let me describe your situation.
Disclaimer: I have not tested any of the commands, they’re provided as-is without warranty out of my head If you encounter error messages, let me know.
I’m also available on the Mattermost community server with the same name if you want to talk about migration errors more quickly.

bin/config only contains the let’s encrypt cache for your recent try, but besides that, it does not contain any relevant information, so my suggestion here is to just delete it.

bin/data contains data back to July 2021 and up to Jan 2023, so this seems to be the recent data directory and we need to keep it (but it should be moved to a different location).
Additionally, I found a third one: bin/data/data which contains data up to 2023-01-13 to further complicate things…
/opt/mattermost/data does not contain any relevant data, but it has another subfolder called “data” (so /opt/mattermost/data/data) which contains data back to 2019-07 and ends in 2021-07 (so something happened in July 2021 which introduced a new directory).
Please note that you are currently not able to access attachments from before 2021-07, because they are not accessible by your Mattermost installation.

When you fix the systemd unit, please also check what the value for the FileSettings.Directory in your /opt/mattermost/config/config.json looks like. It needs to be either ./data (which will work once you change the working directory) or it needs to be the full path, that is /opt/mattermost/data.

Before you do any changes to the filesystem layout, please create a full backup of the /opt/mattermost folder so we can revert to it when anything breaks (or create a snapshot of your system, if it’s a virtual machine).

1. Stop your Mattermost server
2. Fix the systemd unit
3. Run systemctl daemon-reload to reload it
4. Delete the superfluous config directory rm -r /opt/mattermost/bin/config
5. Remove the superflous data directory

mv /opt/mattermost/data/data/* /opt/mattermost/data
rmdir /opt/mattermost/data/data

6. Merge the data from bin/data/data into the new data directory rsync -au /opt/mattermost/bin/data/data/ /opt/mattermost/data/
7. Move this directory out of our way mv /opt/mattermost/bin/data/data /opt/mattermost/bin-data-data
8. Merge the data from bin/data into the new data directory rsync -au /opt/mattermost/bin/data/ /opt/mattermost/data/
9. Move this directory out of our way mv /opt/mattermost/bin/data /opt/mattermost/bin-data

The above mentioned rsync command copies all data from the existing data directories into another data directory, but skips files that are newer on the destination, so you should end up with a merged data directory that contains all the files back to 2019. You can verify that when you run ls -l /opt/mattermost/data after step 9, it should contain all folders from 2019 to 2023. If this is the case, then you’re good to go and can start Mattermost again:

10. Start Mattermost

Once Mattermost is running, please send another ls -lR /opt/mattermost so I can see if it updated all the directories correct and please do some testing to see if you’re able to access your attachments (for newer and older posts).

[agriesser (Alexander Griesser)]

Hi again,

thanks for following up and for the new directory listing. It looks good now, you can now delete the empty folder /opt/mattermost/bin/plugins using the rmdir command (forgot about that one earlier, sorry) and you can also archive/move/delete the folders bin-data and bin-data-data in your /opt/mattermost/ folder. I would suggest to keep them for a few weeks to see if anyone is having issues with the move to the new data directory and if noone complains, you can get rid of them.

If you want to continue with your upgrade to 7.5.2 please be careful that the upgrade instructions will delete the bin-data and bin-data-data folders, so please move them out of the /opt/mattermost folder before you continue with the upgrade; the mattermost application folder is not a safe haven for additional folders you want to retain

[ricrui3 (Ricardo Ruiz)]

Thank you very much for your patience and clear instructions!

[ricrui3 (Ricardo Ruiz)]

I just finished updating to 7.5.2 and I didn’t have any problem! Thanks a million!

[agriesser (Alexander Griesser)]

Awesome, thanks for the confirmation

[urh82 (urh)]

Hi, i’m trying to set up mattermost on qnap via docker my self.
I got it running, but can not make it ssl accessibale… i got the same error as mentioned above (mattermost acme/autocert: missing server name",“caller”:“log/log.go:195”,“source”:“httpserver”})
i don’t use domain i just want it to be accessible over ip… now it is on port 8065
As i ran chown -R mattermost: /opt/mattermost i got msg operation not permited…

Thankyou for any suggestions
Regards, Urh