Errors after systemctl stop

Chi · March 8, 2023, 10:52pm

Summary

After systemctl stop, there are some error messages written to the log. Sorry to bother you, if possible I would like to confirm those errors does not indicate any potential security problem.
I think before I upgraded my Mattermost server, there was already Jira plugin installed. After upgrade, there is an error message saying new Jira plugin cannot be installed. I am not using Jira, however I would like to confirm that is there any security concern if I don’t install the newest Jira plugin?

Steps to reproduce
Those errors are being triggered after each “systemctl restart”.

Expected behavior
I don’t know.

Observed behavior
The error messages are the following:

{"timestamp":"2023-03-07 22:00:30.204 -05:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.nps","wrapped_extras":"pathplugins/com.mattermost.nps/server/dist/plugin-linux-amd64pid5026errorsignal: terminated"}
{"timestamp":"2023-03-07 22:00:30.205 -05:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"playbooks","wrapped_extras":"pathplugins/playbooks/server/dist/plugin-linux-amd64pid5042errorsignal: terminated"}
{"timestamp":"2023-03-07 22:00:30.206 -05:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.apps","wrapped_extras":"pathplugins/com.mattermost.apps/server/dist/plugin-linux-amd64pid5035errorsignal: terminated"}
{"timestamp":"2023-03-07 22:00:30.206 -05:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.calls","wrapped_extras":"pathplugins/com.mattermost.calls/server/dist/plugin-linux-amd64pid5050errorsignal: terminated"}
{"timestamp":"2023-03-07 22:00:30.207 -05:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid5057errorsignal: terminated"}
{"timestamp":"2023-03-07 22:00:30.213 -05:00","level":"info","msg":"Stopping Server...","caller":"app/server.go:654"}
{"timestamp":"2023-03-07 22:00:30.235 -05:00","level":"info","msg":"Stopped workers","caller":"jobs/workers.go:90"}
{"timestamp":"2023-03-07 22:00:30.235 -05:00","level":"info","msg":"Stopping schedulers.","caller":"jobs/schedulers.go:118"}
{"timestamp":"2023-03-07 22:00:30.235 -05:00","level":"info","msg":"Schedulers stopped.","caller":"jobs/schedulers.go:50"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"info","msg":"Shutting down plugins","caller":"app/plugin.go:384"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"focalboard","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.nps","error":"connection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.nps","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.nps"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.apps","error":"connection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.apps","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.apps"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"playbooks","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"playbooks"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.calls","error":"connection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.calls","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.calls"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"info","msg":"stopping websocket hub connections","caller":"platform/web_hub.go:115"}

Sorry if the above error messages has any data that I should hide to in order to protect my server’s security please tell me to remove them.

agriesser · March 10, 2023, 4:18am

Hi @Chi ,

the first few lines just tell you that the plugins have been termindated, which is expected since you’re shutting down the server. In my opinion, the shutdown should be handled more gracefully and the log should reflect that, right now it’s being logged in the error level, but maybe that’s because the system tried to shut them down gracefully before and failed to do so? Are there any shutdown related info level events before the first line in the output you shared?

Starting with this line, the mattermost server tries to shut down the plugins again which is causing errors then, because they’ve already been terminated:

{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"info","msg":"Shutting down plugins","caller":"app/plugin.go:384"}
{"timestamp":"2023-03-07 22:00:30.238 -05:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"focalboard","error":"connection is shut down"}

Can you reproduce that on every restart of your Mattermost server or does this only happen if the server is running for some time?

Chi · March 15, 2023, 2:14am

Hi @agriesser ,

Thank you very much for helping again. And sorry for replying late.

Sorry, I don’t have a certain answer, I am not knowledgeable enough. Is there a preferred way to restart Mattermost server?

That set of log messages no, the first error line is the very first log message of the set from the restart. I observed the latest 4 sets of similar messages. Out of the 4 sets, 3 of them I get the line "level":"info","msg":"Stopping Server...","caller":"app/server.go:654" before the first error level message; the other time the set begins with the "level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.calls" line.

It seems like each restart produce similar result; sometimes I have a few more lines of log messages; I will spend more time to compare them. The very last time of restart was about 10 minutes away from its previous restart, I can at least see the "level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.calls" doesn’t exist in the very last time.

I found this message:

github.com/mattermost/docs

Comment by adsche to Update docs regarding Illegal mix of collations

mattermost:master ← mukul-kr:sql-collation

This change somewhat disconnects the paragraph about the "Reactions" table from …the code to update that same table. It seems this has nothing to do with Reactions, as this only really breaks due to focalboard or playbook upgrades from my experience? Additionally, should this maybe come with code on how to check that the the collations are correctly setup for the upgrade - since this is the "prepare for upgrade" page? I still don't know what was wrong in the database, my collations are all set to the same value, yet most updates of mattermost result in broken collations. I checked with `SHOW VARIABLES LIKE 'collation%';` in MySQL to confirm connection and server values - but apparently that's not good enough, every update since 7.1 (IIRC) broke some tables. Additionally, it would be great to provide (on the Troubleshooting page?) code to fix the broken tables after the update. Here's what I did in MySQL: `SELECT CONCAT("ALTER TABLE ", TABLE_SCHEMA, '.', TABLE_NAME," COLLATE utf8mb4_0900_ai_ci;") AS Command FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_SCHEMA="mattermost" AND TABLE_TYPE="BASE TABLE";` This generates commands that I had to copy to another file (e.g., `collation.sql`) and then execute via `mysql`. I am sure there are better ways to do it, maybe you could document one. (NB This takes forever on a <50 user/ <6mio posts instance, especially on the 'Posts' table.)

while I am trying to figure out some MySQL table collation mismatch messages that I have within each set of log messages from restart. I will try to solve the collation mismatch issue, maybe it will make some of the error messages disappear.

agriesser · March 15, 2023, 4:30am

systemctl restart is just fine, not sure why it did that on you.

Let me know if you need help with the collation issue.

Chi · March 15, 2023, 10:52pm

Sorry I may need more help with the collation. I tried to SET PERSIST ... to collation_connection, collation_database, and collation_server to match mattermost database’s tables’ collation, I restarted both MySQL and Mattermost service, I logged in to new MySQL session and confirmed that new collation value is being applied to all three of the MySQL variables, but when I do restart there are still warn level messages:

... "level":"warn","msg":"Table collation mismatch","caller":"sqlstore/store.go:1235","table_name":"incomingwebhooks","connection_collation":"utf8mb4_0900_ai_ci","table_collation":"utf8mb4_general_ci" ...
... "level":"warn","msg":"Table collation mismatch","caller":"sqlstore/store.go:1235","table_name":"preferences","connection_collation":"utf8mb4_0900_ai_ci","table_collation":"utf8mb4_general_ci" ...
... "level":"warn","msg":"Table collation mismatch","caller":"sqlstore/store.go:1235","table_name":"users","connection_collation":"utf8mb4_0900_ai_ci","table_collation":"utf8mb4_general_ci" ...
... "level":"warn","msg":"Table collation mismatch","caller":"sqlstore/store.go:1235","table_name":"uploadsessions","connection_collation":"utf8mb4_0900_ai_ci","table_collation":"utf8mb4_general_ci" ...
... "level":"warn","msg":"Table collation mismatch","caller":"sqlstore/store.go:1235","table_name":"channels","connection_collation":"utf8mb4_0900_ai_ci","table_collation":"utf8mb4_general_ci" ...
... "level":"warn","msg":"Table collation mismatch","caller":"sqlstore/store.go:1235","table_name":"publicchannels","connection_collation":"utf8mb4_0900_ai_ci","table_collation":"utf8mb4_general_ci" ...

Sorry could you teach me how I may correct them? Or do I need to correct them?

agriesser · March 16, 2023, 6:05am

Your database and all the tables in it are utf8mb4_general_ci, but you’re attempting the connection with utf8mb4_0900_ai_ci, so there’s a mismatch and that’s what the system is telling you.

Most likely this is caused by an upgrade on your end, MySQL has changed the default collation from utf8mb4_general_ci to utf8mb4_0900_ai_ci in 8.0.1 I think, see this post for more details behind the reasoning:

https://dev.mysql.com/blog-archive/new-collations-in-mysql-8-0-0/

When yonnected to your MySQL server, you can check the default collations using this command:

mysql> show variables like "%coll%";
+-------------------------------+--------------------+
| Variable_name                 | Value              |
+-------------------------------+--------------------+
| collation_connection          | utf8mb4_0900_ai_ci |
| collation_database            | utf8mb4_0900_ai_ci |
| collation_server              | utf8mb4_0900_ai_ci |
| default_collation_for_utf8mb4 | utf8mb4_0900_ai_ci |
+-------------------------------+--------------------+
4 rows in set (0.02 sec)

As you can see, on a 8.0+ MySQL server, everything defaults to the new collation, but your database is still using the old one.

First of all, make sure you have a full database backup before proceeding here.
Next please check the tables in your Mattermost database and note down the ones with the old collation.
This command will output more rows on your system, I did convert one table on my end so I can show you the process here:

# echo "show table status;" | mysql yourdatabasename | awk "-F " '$16=="utf8mb4_general_ci" { print $1 }'
Bots

In my example, only the table Bots has the collation utf8mb4_general_ci.
You can now use a slightly modified version of the command to automatically fix all the tables:

echo "show table status;" | mysql yourdatabasename | awk "-F " '$16=="utf8mb4_general_ci" { print "ALTER TABLE `"$1"` CONVERT TO CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci;" }' | mysql yourdatabasename

Afterwards, the first command should not show any tables anymore, as they should have all been converted to the new collation.
If that worked out, change the default collation of the database also to make sure new tables are being created correctly:

mysql> ALTER DATABASE yourdatabasename CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci;
Query OK, 1 row affected (0.03 sec)

This should fix the collation issue.

Chi · March 17, 2023, 12:24am

Thank you very much.

I did not change default_collation_for_utf8mb4 last time; after changing default_collation_for_utf8mb4’s value to utf8mb4_general_ci, the collation warn messages are gone; the bad news is the error messages doesn’t disappear, so I guess they are not caused by MySQL collation problem.
I don’t know if I should change all tables’ collation to utf8mb4_0900_ai_ci, because my database’s data were in utf8mb4_general_ci, so I am afraid that changing to utf8mb4_0900_ai_ci will cause existing data’s damage.

agriesser · March 17, 2023, 5:31am

It should not cause damage, because the newer collation supports more characters, so from what I read, converting in this direction is OK. But, as always, make sure you have a backup just in case and after the conversion, watch out for posts with special characters (unicode emojis, umlauts, accented characters, non-latin text in general). If they look good, you’re safe.

I did not expect the error messages to go away when fixing the collation, so can you post updated error from a restart? Ideally, open two terminal sessions to your Mattermost server and in one, you run tail -f mattermost.log to get a live view on the log. Press a few times, so you can see where to start at later on. Then in the second terminal session, restart mattermost using systemctl and watch the logout. As soon as the restart is done, copy all the log lines generated by the restart over here so we can have another look.

Chi · March 17, 2023, 11:45pm

Thank you very much.

I copied and paste the log messages that a restart triggers now. I hide some ID like string, just in case if any of them should be hidden for my server’s security:

{"timestamp":"2023-03-17 19:30:41.344 -04:00","level":"info","msg":"Stopping Server...","caller":"app/server.go:654"}
{"timestamp":"2023-03-17 19:30:41.343 -04:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.apps","wrapped_extras":"pathplugins/com.mattermost.apps/server/dist/plugin-linux-amd64pid5371errorsignal: terminated"}
{"timestamp":"2023-03-17 19:30:41.344 -04:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.calls","wrapped_extras":"pathplugins/com.mattermost.calls/server/dist/plugin-linux-amd64pid5391errorsignal: terminated"}
{"timestamp":"2023-03-17 19:30:41.345 -04:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.nps","wrapped_extras":"pathplugins/com.mattermost.nps/server/dist/plugin-linux-amd64pid5351errorsignal: terminated"}
{"timestamp":"2023-03-17 19:30:41.345 -04:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"playbooks","wrapped_extras":"pathplugins/playbooks/server/dist/plugin-linux-amd64pid5378errorsignal: terminated"}
{"timestamp":"2023-03-17 19:30:41.345 -04:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid5398errorsignal: terminated"}
{"timestamp":"2023-03-17 19:30:41.369 -04:00","level":"info","msg":"Stopped workers","caller":"jobs/workers.go:90"}
{"timestamp":"2023-03-17 19:30:41.369 -04:00","level":"info","msg":"Stopping schedulers.","caller":"jobs/schedulers.go:118"}
{"timestamp":"2023-03-17 19:30:41.369 -04:00","level":"info","msg":"Schedulers stopped.","caller":"jobs/schedulers.go:50"}
{"timestamp":"2023-03-17 19:30:41.369 -04:00","level":"info","msg":"Shutting down plugins","caller":"app/plugin.go:384"}
{"timestamp":"2023-03-17 19:30:41.369 -04:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.calls","error":"connection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"playbooks","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"playbooks"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.nps","error":"connection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.nps","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.nps"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.apps","error":"connection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.apps","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.apps"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"focalboard","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-17 19:30:41.370 -04:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-17 19:30:41.371 -04:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.calls","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-17 19:30:41.371 -04:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.calls"}
{"timestamp":"2023-03-17 19:30:41.371 -04:00","level":"info","msg":"stopping websocket hub connections","caller":"platform/web_hub.go:115"}
{"timestamp":"2023-03-17 19:30:41.372 -04:00","level":"info","msg":"Server stopped","caller":"app/server.go:736"}
{"timestamp":"2023-03-17 19:30:41.743 -04:00","level":"info","msg":"Server is initializing...","caller":"platform/service.go:165","go_version":"go1.18.1"}
{"timestamp":"2023-03-17 19:30:41.743 -04:00","level":"info","msg":"Pinging SQL","caller":"sqlstore/store.go:240","database":"master"}
{"timestamp":"2023-03-17 19:30:41.774 -04:00","level":"info","msg":"Pinging SQL","caller":"sqlstore/store.go:240","database":"master"}
{"timestamp":"2023-03-17 19:30:41.930 -04:00","level":"info","msg":"Starting websocket hubs","caller":"platform/web_hub.go:95","number_of_hubs":4}
{"timestamp":"2023-03-17 19:30:41.931 -04:00","level":"info","msg":"Loaded system translations","caller":"i18n/i18n.go:93","for locale":"en","from locale":"/opt/mattermost/i18n/en.json"}
{"timestamp":"2023-03-17 19:30:41.953 -04:00","level":"info","msg":"Current version is 7.8.0 (7.8.0/Tue Feb 14 14:16:41 UTC 2023/[A long string, I don't know what it is but I hide it just in case.]/none)","caller":"app/server.go:397","current_version":"7.8.0","build_number":"7.8.0","build_date":"Tue Feb 14 14:16:41 UTC 2023","build_hash":"[A long string, I don't know whhat it is but I hide it just in case.]","build_hash_enterprise":"none"}
{"timestamp":"2023-03-17 19:30:41.953 -04:00","level":"info","msg":"Team Edition Build","caller":"app/server.go:408","enterprise_build":false}
{"timestamp":"2023-03-17 19:30:41.953 -04:00","level":"info","msg":"Printing current working","caller":"app/server.go:412","directory":"/opt/mattermost"}
{"timestamp":"2023-03-17 19:30:41.953 -04:00","level":"info","msg":"Loaded config","caller":"app/server.go:413","source":"file:///opt/mattermost/config/config.json"}
{"timestamp":"2023-03-17 19:30:41.962 -04:00","level":"info","msg":"Starting workers","caller":"jobs/workers.go:48"}
{"timestamp":"2023-03-17 19:30:41.963 -04:00","level":"info","msg":"Starting schedulers.","caller":"jobs/schedulers.go:47"}
{"timestamp":"2023-03-17 19:30:41.969 -04:00","level":"error","msg":"License key from https://mattermost.com required to unlock enterprise features.","caller":"platform/license.go:106","error":"resource: License id: "}
{"timestamp":"2023-03-17 19:30:42.167 -04:00","level":"info","msg":"Starting up plugins","caller":"app/plugin.go:213"}
{"timestamp":"2023-03-17 19:30:42.167 -04:00","level":"info","msg":"Syncing plugins from the file store","caller":"app/plugin.go:294"}
{"timestamp":"2023-03-17 19:30:42.167 -04:00","level":"warn","msg":"Skipping sync for unmanaged plugin","caller":"app/plugin.go:324","plugin_id":"zoom"}
{"timestamp":"2023-03-17 19:30:44.597 -04:00","level":"error","msg":"Failed to install prepackaged plugin","caller":"app/plugin.go:967","path":"/opt/mattermost/prepackaged_plugins/mattermost-plugin-jira-v3.2.2-linux-amd64.tar.gz","error":"Failed to install extracted prepackaged plugin /opt/mattermost/prepackaged_plugins/mattermost-plugin-jira-v3.2.2-linux-amd64.tar.gz: installExtractedPlugin: Unable to move plugin from temporary directory to final destination. Another plugin may be using the same directory name., destination already exists"}
{"timestamp":"2023-03-17 19:30:45.743 -04:00","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.nps"}
{"timestamp":"2023-03-17 19:30:45.963 -04:00","level":"info","msg":"Ensuring Feedbackbot exists","caller":"app/plugin_api.go:973","plugin_id":"com.mattermost.nps"}
{"timestamp":"2023-03-17 19:30:46.952 -04:00","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.apps"}
{"timestamp":"2023-03-17 19:30:47.118 -04:00","level":"info","msg":"activated","caller":"app/plugin_api.go:973","plugin_id":"com.mattermost.apps","plugin_caller":"server/plugin.go:135"}
{"timestamp":"2023-03-17 19:30:47.951 -04:00","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"playbooks"}
{"timestamp":"2023-03-17 19:30:48.571 -04:00","level":"info","msg":"registered collection and topic type","caller":"app/collection.go:33","plugin_id":"playbooks","collection_type":"run","topic_type":"status"}
{"timestamp":"2023-03-17 19:30:48.577 -04:00","level":"info","msg":"registered collection and topic type","caller":"app/collection.go:33","plugin_id":"playbooks","collection_type":"run","topic_type":"task"}
{"timestamp":"2023-03-17 19:30:48.888 -04:00","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.calls"}
{"timestamp":"2023-03-17 19:30:49.117 -04:00","level":"info","msg":"got public IP address","caller":"app/plugin_api.go:973","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:95","addr":"[An IP.]"}
{"timestamp":"2023-03-17 19:30:49.118 -04:00","level":"info","msg":"rtc: server is listening on udp :8443","caller":"app/plugin_api.go:973","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:95"}
{"timestamp":"2023-03-17 19:30:49.118 -04:00","level":"info","msg":"rtc: server is listening on udp :8443","caller":"app/plugin_api.go:973","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:95"}
{"timestamp":"2023-03-17 19:30:49.237 -04:00","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-17 19:30:49.267 -04:00","level":"info","msg":"connectDatabase","caller":"app/plugin_api.go:973","plugin_id":"focalboard","dbType":"mysql"}
{"timestamp":"2023-03-17 19:30:49.287 -04:00","level":"info","msg":"{\"level\":\"info\",\"msg\":\"Pinging SQL\",\"fields\":{\"database\":\"master\"}}\n","caller":"io/io.go:428","plugin_id":"focalboard","source":"plugin_stderr"}
{"timestamp":"2023-03-17 19:30:49.490 -04:00","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyMentions"}
{"timestamp":"2023-03-17 19:30:49.491 -04:00","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifySubscriptions"}
{"timestamp":"2023-03-17 19:30:49.491 -04:00","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyLogger"}
{"timestamp":"2023-03-17 19:30:49.501 -04:00","level":"info","msg":"Focalboard server","caller":"app/plugin_api.go:973","plugin_id":"focalboard","version":"7.8.2","edition":"plugin","build_number":"[A number.]","build_date":"\"Mon Feb 13 15:23:12 UTC 2023\"","build_hash":"[A long string.]"}
{"timestamp":"2023-03-17 19:30:49.501 -04:00","level":"info","msg":"Server.Start","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-03-17 19:30:49.515 -04:00","level":"info","msg":"Boards product successfully started.","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-03-17 19:30:50.500 -04:00","level":"error","msg":"Mail server connection test failed","caller":"app/server.go:862","error":"unable to connect: authentication failed: x509: certificate signed by unknown authority"}
{"timestamp":"2023-03-17 19:30:50.503 -04:00","level":"warn","msg":"Your push notification server is configured with HTTP. For improved security, update to HTTPS in your configuration.","caller":"app/server.go:1135"}
{"timestamp":"2023-03-17 19:30:50.515 -04:00","level":"info","msg":"Starting Server...","caller":"app/server.go:880"}
{"timestamp":"2023-03-17 19:30:50.517 -04:00","level":"info","msg":"Server is listening on [::]:8065","caller":"app/server.go:952","address":"[::]:8065"}

agriesser · March 18, 2023, 6:06am

Thanks, this looks good but the ordering is still wrong (but that’s nothing you can fix).
Seeing the same on my server here:

{"timestamp":"2023-03-18 06:20:11.552 +01:00","level":"info","msg":"Stopping Server...","caller":"app/server.go:654"}
[... and here the first plugins start writing errors being terminated ...]
{"timestamp":"2023-03-18 06:20:11.593 +01:00","level":"info","msg":"Metrics and profiling server is stopped","caller":"platform/metrics.go:83"}
[...]
{"timestamp":"2023-03-18 06:20:11.614 +01:00","level":"info","msg":"Stopped workers","caller":"jobs/workers.go:90"}
{"timestamp":"2023-03-18 06:20:11.616 +01:00","level":"info","msg":"Stopping schedulers.","caller":"jobs/schedulers.go:118"}
{"timestamp":"2023-03-18 06:20:11.616 +01:00","level":"info","msg":"Schedulers stopped.","caller":"jobs/schedulers.go:50"}
{"timestamp":"2023-03-18 06:20:11.617 +01:00","level":"info","msg":"Shutting down plugins","caller":"app/plugin.go:384"}
[... and now we get a lot of error messages, because the plugins are not reachable via RPC ...]
{"timestamp":"2023-03-18 06:20:11.624 +01:00","level":"info","msg":"stopping websocket hub connections","caller":"platform/web_hub.go:115"}
{"timestamp":"2023-03-18 06:20:11.709 +01:00","level":"info","msg":"Server stopped","caller":"app/server.go:736"}

So in my opinion, the plugins should be stopped gracefully first before everything else is being stopped, which does not seem to be the case here. @agnivade any ideas about that?

Chi · March 20, 2023, 1:48am

Thank you @agriesser for keep helping me. I did not expect I got so much help. I am an old man, I experience how bad government workers are as well as a lot other private organization workers, if they can have half of your patient and the will to help, I believe I can have a lot less stress in life. I can only wish you good luck in your life, good people deserve fortune and happiness.

agnivade · March 20, 2023, 7:14am

The server should be stopped first, and then the plugins. The reason being if server is still running, and the plugins are stopped before, then there might be some requests reaching the server which would not be served by a plugin.

Can you clarify what is the issue here?

agriesser · March 20, 2023, 11:16am

The “issue” is, that the logs are full of errors which indicate that something is wrong, when in fact this is a normal shutdown procedure. Also the system is unable to shut down the plugins properly, I removed these lines from the output above, but after it says “Shutting down plugins…” the following messages are being logged:

{"timestamp":"2023-03-09 06:11:49.621 +01:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-09 06:11:49.621 +01:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"focalboard","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-09 06:11:49.621 +01:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-09 06:11:49.621 +01:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"channel-notes","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-03-09 06:11:49.621 +01:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"channel-notes"}

Please disregard the timestamps, just took some from a different day.

agnivade · March 20, 2023, 6:51pm

Ah yes understood. Yes this has been a longstanding problem. I thought there was an ordering issue somewhere.

agriesser · March 21, 2023, 4:11am

Alright, thanks for confirming. @Chi there’s nothing we can do about these messages for the time being, so you don’t need to worry about them, just ignore them for now.

Chi · March 23, 2023, 1:18am

Understood. Thank you very much.