Mattermost-server: Creating a bot accounts via the plugin API causes an error in server logs

[mattermod]

When a plugin creates a bot account using the plugin API, a server log message will be thrown stating e.g. for Matterpoll:

ERRO<2020-01-28T11:43:35.1281009+01:00> Unable to restart plugin on upgrade.          caller="mlog/log.go:175" err*details="SqlUserStore.Get: We encountered an error finding the account, SqlUserStore.Get: Unable to find the user., user_id=com.github.matterpoll.matterpoll" err_where=installExtractedPlugin http_code=500 ip_addr="::1" method=POST path=/api/v4/plugins request_id=6p6c4kdggpf4icb3ur5wgdzhpw user*id=7nbqcbb3f3fu58e6bxmxyhu1xo

Please not that there are no other issues besides this error message being shown.

This is a regression caused by https://github.com/mattermost/mattermost-server/pull/11062.

The root cause is that https://github.com/mattermost/mattermost-server/blob/master/app/bot.go#L33 doesn’t take into account that bot.OwnerId is the plugin ID for bot created by a plugin.

---

If you're interested please comment here and come join our "Contributors" community channel on our daily build server, where you can discuss questions with community members and the Mattermost core team. For technical advice or questions, please join our "Developers" community channel.

New contributors please see our Developer's Guide.

JIRA: https://mattermost.atlassian.net/browse/MM-22106

[frnkshin]

I can work on this if no one claimed it yet.

[hanzei]

Thanks for taking a shot @frnkshin. Let me know, if you have any questions.

[MatthewDorner]

I took a look at this and I'm not getting any error. The error in the example, "Unable to restart plugin on upgrade." doesn't appear in mattermost-server at all (was removed?) and when debugging, I get an error from a.Srv.Store.User().Get(bot.OwnerId) but since the error is store.MISSING_ACCOUNT_ERROR and ownerUser is nil, control passes through to the end of the CreateBot and returns normally with no error.

This was tested with the Matterpoll plugin.

edit: was looking at old code haha, anyway I'd like to follow along with this issue as I'm trying to learn about the server.

edit: still can't reproduce with the new code, installed via the mattermost plugin add command and got it to execute installExtractedPlugin where the error should be occurring but never got an error. @frnkshin, were you able to reproduce?

[frnkshin]

@MatthewDorner It only shows up for the very first time.
To reproduce, you will have to run make nuke and then install a bot plugin (I used welcomebot).

[MatthewDorner]

yeah, I can see it create the bot but no error. Tried installing plugins via make deploy, mattermost plugin cli command with tar.gz, uploading tar.gz via the webapp and installing from Marketplace. Installing welcomebot via Marketplace with added debug statements:

(install via Marketplace)
plugin_install.go::installExtractedPlugin exiting without error, manifest: 
&{com.mattermost.welcomebot Welcome Bot This plugin adds a WelcomeBot that helps add new users to channels.     1.1.1 5.12.0 0xc00023fce0 <nil> <nil> 0xc0015e2b00 map[] <nil>}

(activate via http://localhost:8065/admin_console/plugins/plugin_com.mattermost.welcomebot)
DEBU[2020-02-08T15:29:44.5326188-06:00] starting plugin                               caller="plugin/hclog_adapter.go:51" plugin_id=com.mattermost.welcomebot wrapped_extras="pathplugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64args[plugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64]"
DEBU[2020-02-08T15:29:44.5331905-06:00] plugin started                                caller="plugin/hclog_adapter.go:51" plugin_id=com.mattermost.welcomebot wrapped_extras=pathplugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64pid13785
DEBU[2020-02-08T15:29:44.5332344-06:00] waiting for RPC address                       caller="plugin/hclog_adapter.go:51" plugin_id=com.mattermost.welcomebot wrapped_extras=pathplugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64
DEBU[2020-02-08T15:29:44.5361462-06:00] Next run time for scheduler                   caller="jobs/schedulers.go:172" next_runtime="<nil>" scheduler_name=MigrationsScheduler
DEBU[2020-02-08T15:29:44.5385804-06:00] Next run time for scheduler                   caller="jobs/schedulers.go:172" next_runtime="2020-02-09 15:29:44.538565521 -0600 CST m=+86645.502035596" scheduler_name=PluginsScheduler
DEBU[2020-02-08T15:29:44.5443063-06:00] plugin address                                caller="plugin/hclog_adapter.go:51" plugin_id=com.mattermost.welcomebot wrapped_extras="address/tmp/plugin356383059networkunixtimestamp2020-02-08T15:29:44.544-0600"
DEBU[2020-02-08T15:29:44.5443797-06:00] using plugin                                  caller="plugin/hclog_adapter.go:51" plugin_id=com.mattermost.welcomebot wrapped_extras=version1
bot.go::CreateBot exiting without error, savedBot: 
&{cxikyfqwwigkb8akmftfjadnbe welcomebot Welcomebot A bot account created by the Welcomebot plugin. com.mattermost.welcomebot 0 1581197384601 1581197384601 0}
environment.go::Activate exiting without error, pluginInfo.Manifest: 
&{com.mattermost.welcomebot Welcome Bot This plugin adds a WelcomeBot that helps add new users to channels.     1.1.1 5.12.0 0xc001555a40 <nil> <nil> 0xc003b8f900 map[] <nil>}

anyway I will wait to see what you come up with if you're still working on it

[hanzei]

Hi @frnkshin,

Are you able to reproduce the problem? Do you have other questions?

[MojoAnfield]

Hey not sure if anyone is still working on this issue, I'm interested in taking a look.

[hanzei]

That would be great @MojoAnfield :+1: