Bug (MM Boards Plugin): deleting specific property breaks boards

[jakobkilian]

Summary

Deleting a specific property from a board breaks the boards plugin of my instance I know, this is very inaccurate, but the issue happens on an important instance, because of that I can't narrow down the error or tinker around a lot. I would be happy if smn can assist in finding the actual problem / logs.

Steps to reproduce

Deleting a specific property (I don't no yet which ones cause the problem) breaks boards plugin a few seconds/mins later. Error page (screenshot) or blank screen in the boards tab, broken icons and nor linked boards in the sidebar of the MM channels, no more card previews in the chat.

Screenshots (optional)

Edition and Platform

• Edition: Mattermost Boards (plugin)
• Version: Mattermost 7.8.1
• Server: running MM via Yunohost on a VPS
• Browser and OS: tested on multiple browsers and the Mac os app. Seems to be a server-sided issue.

Observed behavior

• After first occurrence I repeated the deletion of the same property multiple times after restoring from the backup every time → always resulting in a crash. Deletion seems to work fine for a moment.
• I rebooted the system
• I checked the logs (see and excerpt below). There are many similar messages about the plugin not working. Is there any plugin specific log?
• I also had a look into the database (postgres) and nothing "looked" wrong. However I noticed that there are many instances of card_properties share the same ID (due to templates?). Is this expected behaviour?

{"timestamp":"2023-03-25 11:21:37.672 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid27173errorexit status 2"}
{"timestamp":"2023-03-25 11:21:42.751 Z","level":"error","msg":"Plugin failed to ServeHTTP, RPC call failed","caller":"plugin/client_rpc.go:423","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-25 11:21:43.201 Z","level":"error","msg":"RPC call WebSocketMessageHasBeenPosted to plugin failed.","caller":"plugin/client_rpc_generated.go:655","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-25 11:21:47.752 Z","level":"error","msg":"Plugin failed to ServeHTTP, muxBroker couldn't accept connection","caller":"plugin/client_rpc.go:378","plugin_id":"focalboard","serve_http_stream_id":4721,"error":"timeout waiting for accept"}
{"timestamp":"2023-03-25 11:21:47.752 Z","level":"error","msg":"Plugin failed to ServeHTTP, muxBroker couldn't Accept request body connection","caller":"plugin/client_rpc.go:397","plugin_id":"focalboard","error":"timeout waiting for accept"}{"timestamp":"2023-03-25 11:21:59.949 Z","level":"warn","msg":"Health check failed for plugin","caller":"plugin/health_check.go:59","id":"focalboard","error":"plugin RPC connection is not responding"}
{"timestamp":"2023-03-25 11:21:59.949 Z","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-25 11:21:59.949 Z","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-25 11:21:59.949 Z","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-25 11:22:00.043 Z","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-25 11:22:00.119 Z","level":"info","msg":"connectDatabase","caller":"app/plugin_api.go:973","plugin_id":"focalboard","dbType":"postgres"}
{"timestamp":"2023-03-25 11:22:00.135 Z","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-25 11:22:00.204 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyMentions"}
{"timestamp":"2023-03-25 11:22:00.204 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifySubscriptions"}
{"timestamp":"2023-03-25 11:22:00.208 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyLogger"}
{"timestamp":"2023-03-25 11:22:00.241 Z","level":"info","msg":"Focalboard server","caller":"app/plugin_api.go:973","plugin_id":"focalboard","version":"7.8.2","edition":"plugin","build_number":"4164951632","build_date":"\"Mon Feb 13 15:23:12 UTC 2023\"","build_hash":"1e358783>
{"timestamp":"2023-03-25 11:22:00.242 Z","level":"info","msg":"Server.Start","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-03-25 11:22:00.242 Z","level":"info","msg":"Boards product successfully started.","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-03-25 11:22:30.212 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid232016errorexit status 2"}
{"timestamp":"2023-03-25 11:22:52.230 Z","level":"error","msg":"RPC call WebSocketMessageHasBeenPosted to plugin failed.","caller":"plugin/client_rpc_generated.go:655","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-25 11:22:52.231 Z","level":"error","msg":"RPC call WebSocketMessageHasBeenPosted to plugin failed.","caller":"plugin/client_rpc_generated.go:655","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-25 11:22:59.950 Z","level":"warn","msg":"Health check failed for plugin","caller":"plugin/health_check.go:59","id":"focalboard","error":"plugin RPC connection is not responding"}
{"timestamp":"2023-03-25 11:22:59.950 Z","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-25 11:22:59.951 Z","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-25 11:22:59.951 Z","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}

I am happy to help, thy for all your effort

[sbishel]

@jakobkilian - Is that your only "select" property on the board? There are some issues if the property being deleted is being used as either a Group By or Filter.

Could you check the browser errors? This would be able to confirm that.

[jakobkilian]

Unfortunately, it is neither one nor the other (one of 10 properties, no "filter" or "group by" used on it, it is a "multi-select").

I crashed MM Boards again on purpose and noticed something interesting: the plugin seems to crash and then deactivates itself after several failed calls. But if you manually deactivate it in the settings and reactivate it, everything works again. At least until now.

I have saved logs of failed calls (before deactivating and re-activating...):

MACOS-MM-App-Log.log MACOS-CHROME-Log.log

[sbishel]

it is a "multi-select" Are there other select or multi-select properties?

Those logs look like they were after the plugin crashed and restarted. At least, that appears to be what happened. Can you get logs right before the plugin crashed? May-be just before the logs in your original post. Look for errors before this line, which appears to be the plugin crashing.

{"timestamp":"2023-03-25 11:21:37.672 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid27173errorexit status 2"}

Can you create a similar type board and duplicate? What if you export and import the board does it still happen to the new board?

[jakobkilian]

Hi again, thanks for taking the time and pointing out the proper logs. This is everything that happens in the /var/log/mattermost/mattermost.log before the"plugin process exited" you pointed out.

{"timestamp":"2023-03-28 16:15:42.331 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid54375errorexit status 2"}
{"timestamp":"2023-03-28 16:15:49.393 Z","level":"warn","msg":"Health check failed for plugin","caller":"plugin/health_check.go:59","id":"focalboard","error":"plugin RPC connection is not responding"}
{"timestamp":"2023-03-28 16:15:49.393 Z","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-28 16:15:49.393 Z","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-28 16:15:49.393 Z","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-28 16:15:49.513 Z","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-03-28 16:15:49.585 Z","level":"info","msg":"connectDatabase","caller":"app/plugin_api.go:973","plugin_id":"focalboard","dbType":"postgres"}
{"timestamp":"2023-03-28 16:15:49.606 Z","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-28 16:15:49.659 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyMentions"}
{"timestamp":"2023-03-28 16:15:49.660 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifySubscriptions"}
{"timestamp":"2023-03-28 16:15:49.660 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyLogger"}
{"timestamp":"2023-03-28 16:15:49.677 Z","level":"info","msg":"Focalboard server","caller":"app/plugin_api.go:973","plugin_id":"focalboard","version":"7.8.2","edition":"plugin","build_number":"4164951632","build_date":"\"Mon Feb 13 15:23:12 UTC 2023\"","build_hash":"1e35878351f9ab75fe6fd9c7562fb4cfdc566027"}
{"timestamp":"2023-03-28 16:15:49.677 Z","level":"info","msg":"Server.Start","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-03-28 16:15:49.677 Z","level":"info","msg":"Boards product successfully started.","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-03-28 16:15:49.686 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid770341errorexit status 2"}
{"timestamp":"2023-03-28 16:15:57.862 Z","level":"error","msg":"RPC call OnWebSocketDisconnect to plugin failed.","caller":"plugin/client_rpc_generated.go:620","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-03-28 16:15:58.400 Z","level":"error","msg":"Plugin failed to ServeHTTP, RPC call failed","caller":"plugin/client_rpc.go:423","plugin_id":"focalboard","error":"connection is shut down"}
--- repeat a dozen of times --- 

---

Are there other select or multi-select properties?

• yes, the board has multiple select and multi-select properties. In total there are about 10 properties
• I actually exported the master board and imported it again about 40x as every channel in this MM instance should have this board-design. So I am basically always referring to imported (cloned) boards of the same type.
• I tried to duplicate and get the server to crash again, but unfortunately (or fortunate for me) it won't happen again with new properties. I already deleted the troublemaker now 🙆 I can tinker a bit more tonight
• is my last bullet of the 1st post relevant? Is it intended that card_properties (also the troublemaker) share the same ID across several different boards?

[sbishel]

Well, I'm glad it's fixed, but wish we could have figured out the issue.

Is it intended that card_properties (also the troublemaker) share the same ID across several different boards?

Not really intended, but left over from the original database design which was all JSON. We've gradually migrated into a relation database structure. We have plans to migrate properties to their own tables in the next few months.

[jakobkilian]

k, thx for the explanation of the database structure, makes sense to me. Didn't have issues since then, let me know if I can test anything else. At the moment it seems that the deletion has somehow terminated the plugin, but after manual reactivation it works again.

[jakobkilian]

Had the issue again: someone moved cards "fast" and created a new one. Then boards broke. I somehow had the feeling that also in my cases it was related to the speed of successive actions... The logs look pretty identical.

Tell me if I can help in any way, I am happy to do so!

{"timestamp":"2023-04-25 10:18:56.335 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid2033errorexit status 2"}
{"timestamp":"2023-04-25 10:19:10.055 Z","level":"error","msg":"Plugin failed to ServeHTTP, RPC call failed","caller":"plugin/client_rpc.go:423","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-04-25 10:19:15.056 Z","level":"error","msg":"Plugin failed to ServeHTTP, muxBroker couldn't Accept request body connection","caller":"plugin/client_rpc.go:397","plugin_id":"focalboard","error":"timeout waiting for accept"}
{"timestamp":"2023-04-25 10:19:15.056 Z","level":"error","msg":"Plugin failed to ServeHTTP, muxBroker couldn't accept connection","caller":"plugin/client_rpc.go:378","plugin_id":"focalboard","serve_http_stream_id":4883,"error":"timeout waiting for accept"}
{"timestamp":"2023-04-25 10:19:15.833 Z","level":"warn","msg":"Health check failed for plugin","caller":"plugin/health_check.go:59","id":"focalboard","error":"plugin RPC connection is not responding"}
{"timestamp":"2023-04-25 10:19:15.834 Z","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-04-25 10:19:15.834 Z","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-04-25 10:19:15.834 Z","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-04-25 10:19:15.966 Z","level":"warn","msg":"plugin configured with a nil SecureConfig","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-04-25 10:19:16.057 Z","level":"info","msg":"connectDatabase","caller":"app/plugin_api.go:973","plugin_id":"focalboard","dbType":"postgres"}
{"timestamp":"2023-04-25 10:19:16.075 Z","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-04-25 10:19:16.127 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyMentions"}
{"timestamp":"2023-04-25 10:19:16.127 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifySubscriptions"}
{"timestamp":"2023-04-25 10:19:16.127 Z","level":"info","msg":"Initialized notification backend","caller":"app/plugin_api.go:973","plugin_id":"focalboard","name":"notifyLogger"}
{"timestamp":"2023-04-25 10:19:16.138 Z","level":"info","msg":"Focalboard server","caller":"app/plugin_api.go:973","plugin_id":"focalboard","version":"7.8.2","edition":"plugin","build_number":"4164951632","build_date":"\"Mon Feb 13 15:23:12 UTC 2023\"","build_hash":"1e35878351f9ab75fe6fd9c7562fb4cfdc566027"}
{"timestamp":"2023-04-25 10:19:16.139 Z","level":"info","msg":"Server.Start","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-04-25 10:19:16.139 Z","level":"info","msg":"Boards product successfully started.","caller":"app/plugin_api.go:973","plugin_id":"focalboard"}
{"timestamp":"2023-04-25 10:19:16.156 Z","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid1268406errorexit status 2"}
{"timestamp":"2023-04-25 10:19:16.777 Z","level":"error","msg":"Plugin failed to ServeHTTP, RPC call failed","caller":"plugin/client_rpc.go:423","plugin_id":"focalboard","error":"connection is shut down"}

Workaround this time: deactivate and activate twice then it worked again...