I enabled welcomebot but slash-command /welcomebot is not recognized?

Troubleshooting
1

I enabled welcomebot but slash-command /welcomebot is not recognized?

I followed the instructions and I think i got it right. Any idea what might be wrong?

root@mattermost-ubuntu-s01:/opt/mattermost/logs# cat mattermost.log | grep welcome
{"level":"error","ts":1592258061.4331543,"caller":"app/user.go:175","msg":"Failed to send welcome email on create user from signup","error":"SendWelcomeEmail: Failed to send welcome email successfully, SendMail: Failed to open connection, dial tcp 127.0.0.1:10025: connect: connection refused"}
{"level":"warn","ts":1592264538.905176,"caller":"plugin/hclog_adapter.go:51","msg":"error closing client during Kill","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1592264538.9054086,"caller":"plugin/hclog_adapter.go:53","msg":"plugin failed to exit gracefully","plugin_id":"com.mattermost.welcomebot"}
{"level":"error","ts":1592266790.84472,"caller":"app/user.go:175","msg":"Failed to send welcome email on create user from signup","error":"SendWelcomeEmail: Failed to send welcome email successfully, SendMail: Failed to open TLS connection, tls: first record does not look like a TLS handshake"}
{"level":"warn","ts":1592267438.4809303,"caller":"plugin/hclog_adapter.go:51","msg":"error closing client during Kill","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"errunexpected EOF"}
{"level":"warn","ts":1592267438.4812362,"caller":"plugin/hclog_adapter.go:53","msg":"plugin failed to exit gracefully","plugin_id":"com.mattermost.welcomebot"}
{"level":"warn","ts":1592612590.3872843,"caller":"plugin/hclog_adapter.go:51","msg":"error closing client during Kill","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1592612590.3874576,"caller":"plugin/hclog_adapter.go:53","msg":"plugin failed to exit gracefully","plugin_id":"com.mattermost.welcomebot"}
{"level":"error","ts":1592615145.5620985,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615249.6326952,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615431.0554059,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615544.6616657,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615619.1825342,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615653.8031876,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615687.568547,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615951.2700062,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592615974.505366,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"error","ts":1592616991.4715958,"caller":"mlog/log.go:174","msg":"RPC call OnConfigurationChange to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"warn","ts":1593144706.433013,"caller":"plugin/hclog_adapter.go:51","msg":"error closing client during Kill","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1593144706.4332168,"caller":"plugin/hclog_adapter.go:53","msg":"plugin failed to exit gracefully","plugin_id":"com.mattermost.welcomebot"}
2

I found this issue in the Github repo: https://github.com/mattermost/mattermost-plugin-welcomebot/issues/46

3

@djangofan Could you please set your log level to debbug and see if you see new messages? Could you also please grep for the word panic?

4

I tried again. I might give up on it.

I enabled debug and didn’t find the word “panic” in the log anywhere. This seems to be the most significant think in the log that I see.

{"level":"error","ts":1593277698.037531,"caller":"mlog/log.go:174","msg":"RPC call UserHasJoinedTeam to plugin failed.","plugin_id":"com.mattermost.welcomebot","error":"connection is shut down"}
{"level":"debug","ts":1593311940.6222744,"caller":"plugin/hclog_adapter.go:33","msg":"plugin process exited","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"pathplugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64pid27224errorsignal: terminated"}
{"level":"warn","ts":1593311940.6285026,"caller":"plugin/hclog_adapter.go:51","msg":"error closing client during Kill","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1593311940.6294734,"caller":"plugin/hclog_adapter.go:53","msg":"plugin failed to exit gracefully","plugin_id":"com.mattermost.welcomebot"}
5

Hello, @djangofan

Just giving a detailed log entry when the welcome bot is installed and enabled on my end:

Environment

  • Mattermost Server 5.24.1

  • Welcome Bot version 1.2.0

Installation

After downloading the .tar.gz from the link above, I uploaded the plugin and enabled it:

{"level":"debug","ts":1593403843.955797,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/plugins/com.mattermost.welcomebot/enable","request_id":"6ycacp3wobn89n1gqfepe4jg3c"}
{"level":"debug","ts":1593403844.0163794,"caller":"jobs/schedulers.go:190","msg":"Schedulers received config change."}
{"level":"info","ts":1593403844.0195749,"caller":"bleveengine/bleve.go:267","msg":"UpdateConf Bleve"}
{"level":"debug","ts":1593403844.0504105,"caller":"jobs/schedulers.go:190","msg":"Schedulers received config change."}
{"level":"debug","ts":1593403844.0672886,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"EnterpriseLdapSync","next_runtime":"2020-06-29 04:15:01 +0000 UTC"}
{"level":"debug","ts":1593403844.0696473,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"MigrationsScheduler","next_runtime":"<nil>"}
{"level":"debug","ts":1593403844.0717778,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"PluginsScheduler","next_runtime":"2020-06-30 04:10:44.071767736 +0000 UTC m=+86743.862136510"}
{"level":"debug","ts":1593403844.074071,"caller":"jobs/workers.go:117","msg":"Workers received config change."}
{"level":"debug","ts":1593403844.0748734,"caller":"jobs/workers.go:117","msg":"Workers received config change."}
{"level":"debug","ts":1593403844.0777774,"caller":"plugin/hclog_adapter.go:51","msg":"starting plugin","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]"}
{"level":"debug","ts":1593403844.0818527,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"EnterpriseLdapSync","next_runtime":"2020-06-29 04:15:01 +0000 UTC"}
{"level":"debug","ts":1593403844.0832036,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"MigrationsScheduler","next_runtime":"<nil>"}
{"level":"debug","ts":1593403844.0845537,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"PluginsScheduler","next_runtime":"2020-06-30 04:10:44.084543102 +0000 UTC m=+86743.874911889"}
{"level":"debug","ts":1593403844.085337,"caller":"plugin/hclog_adapter.go:51","msg":"plugin started","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"pathplugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64pid16858"}
{"level":"debug","ts":1593403844.0868704,"caller":"plugin/hclog_adapter.go:51","msg":"waiting for RPC address","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"pathplugins/com.mattermost.welcomebot/server/dist/plugin-linux-amd64"}
{"level":"debug","ts":1593403844.1401157,"caller":"plugin/hclog_adapter.go:51","msg":"plugin address","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"address/tmp/plugin937273276networkunixtimestamp2020-06-29T04:10:44.139Z"}
{"level":"debug","ts":1593403844.141108,"caller":"plugin/hclog_adapter.go:51","msg":"using plugin","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"version1"}
{"level":"debug","ts":1593403844.1911871,"caller":"jobs/workers.go:117","msg":"Workers received config change."}
{"level":"debug","ts":1593403844.1990023,"caller":"jobs/workers.go:117","msg":"Workers received config change."}
{"level":"debug","ts":1593403844.1995862,"caller":"jobs/workers.go:117","msg":"Workers received config change."}
{"level":"debug","ts":1593403844.2016785,"caller":"jobs/workers.go:117","msg":"Workers received config change."}
{"level":"debug","ts":1593403844.2024438,"caller":"jobs/schedulers.go:190","msg":"Schedulers received config change."}
{"level":"info","ts":1593403844.2031355,"caller":"bleveengine/bleve.go:267","msg":"UpdateConf Bleve"}
{"level":"debug","ts":1593403844.2048848,"caller":"jobs/schedulers.go:190","msg":"Schedulers received config change."}
{"level":"debug","ts":1593403844.2067904,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"EnterpriseLdapSync","next_runtime":"2020-06-29 04:15:01 +0000 UTC"}
{"level":"debug","ts":1593403844.2081404,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"MigrationsScheduler","next_runtime":"<nil>"}
{"level":"debug","ts":1593403844.2095845,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"PluginsScheduler","next_runtime":"2020-06-30 04:10:44.209577179 +0000 UTC m=+86743.999945926"}
{"level":"debug","ts":1593403844.2130845,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"EnterpriseLdapSync","next_runtime":"2020-06-29 04:15:01 +0000 UTC"}
{"level":"debug","ts":1593403844.2145522,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"MigrationsScheduler","next_runtime":"<nil>"}
{"level":"debug","ts":1593403844.215832,"caller":"jobs/schedulers.go:172","msg":"Next run time for scheduler","scheduler_name":"PluginsScheduler","next_runtime":"2020-06-30 04:10:44.215815153 +0000 UTC m=+86744.006183906"}

Once that was completed, I navigated to the Off-Topic channel and ran the /welcomebot command:

image
image2302Ă—954 192 KB

{"level":"debug","ts":1593403925.5090015,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/channels/members/me/view","request_id":"b4ne9ggip7bed87gt98r5phu3r"}
{"level":"debug","ts":1593403928.4940076,"caller":"wsapi/websocket_handler.go:25","msg":"Websocket request","action":"user_typing"}
{"level":"debug","ts":1593403928.5007493,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/commands/execute","request_id":"p8z4e51dxjyptnr7w9fkdf9auc"}
{"level":"debug","ts":1593403928.5260136,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/users/ids","request_id":"qdmiq4s4k7fi3bi5pb7usj45cy"}
{"level":"debug","ts":1593403928.5281062,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/users/status/ids","request_id":"c649wos6bpdp7pqqf8x96ztiko"}
{"level":"debug","ts":1593403928.5296288,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/channels/ujbqthqhytdzpcd1dbds43cgzh/members/me","request_id":"xobiggbpp3yh5gs88ok3kbkh5o"}
{"level":"debug","ts":1593403928.542537,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/channels/members/me/view","request_id":"1m8sp77c87rwbmzyqsmsa1jrfa"}
{"level":"debug","ts":1593403928.5695207,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/users/ids","request_id":"1zk9dcjkubbfbpheukdh5xs7nr"}
{"level":"debug","ts":1593403928.57079,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/users/status/ids","request_id":"niywgju6hbfoznbnw8tsgs5azr"}
{"level":"debug","ts":1593403928.6051855,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"GET","url":"/api/v4/users/t84k9m5w97f1tcoqpdt3zqdbqw/image","request_id":"anuigdk39inmj8rejnguudyi6y"}
{"level":"debug","ts":1593403929.1048503,"caller":"web/handlers.go:89","msg":"Received HTTP request","method":"POST","url":"/api/v4/channels/members/me/view","request_id":"7yhsaeyrxbg58x6skq8op1gssa"}

Finding

You can see from the second snippet of the log that the /welcomebot command does not show any entries in the mattermost.log even with the DEBUG File Log Level enabled. Hence, the reason why we were unable to trace for any specific errors there.

Moving Forward

  • Can you share which version of Mattermost Server and Welcome Bot did you have installed on your end?

  • Can you provide the screen shot of what you are seeing on the UI?

  • Since the error shows that the connection is shutdown, do you notice anything in the developer tools when you ran the command on the desktop / web app?

image
image2880Ă—1800 454 KB

  • Does it happen to other bots / when you run other slash commands too?
1 Like
6

Hi @djangofan. I am one of the codeowners for this plugin. Would you mind running through the feedback form @ahmaddanial?

Specifically, I am also interested in the version of the plugin and server versions!

1 Like