mattermost-plugin-remind
mattermost-plugin-remind copied to clipboard
scottleedavis
RPC call ExecuteCommand
Summary
Sometime the plugin crashs
Steps to reproduce
I don't know
Expected behavior
No crashs
Observed behavior (that appears unintentional)
Output: Command with a trigger of '/remind' not found.
Server configuration
Operating system: CentOs
Mattermost version: 5.19.1
Remind version: 0.4.4
Updated from an older Remind bot version or fresh install: Updated I think
Mattermost server logs
{"level":"error","ts":1589289600.7570996,"caller":"mlog/log.go:174","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
{"level":"error","ts":1589289611.2719955,"caller":"mlog/log.go:174","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
{"level":"error","ts":1589289626.7770824,"caller":"mlog/log.go:174","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
{"level":"error","ts":1589289688.7921574,"caller":"mlog/log.go:174","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
{"level":"error","ts":1589289738.3685138,"caller":"mlog/log.go:174","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
not sure where to start yet in triaging this... @hanzei do you have pointers?
@tschlue Could you post your full server log with Debug logging on please? I strongly suspect that the remind plugin crashed at some point, which is only visible in debug logs.
I switched the logging to debug and will post the log as soon as it occures.
{"level":"debug","ts":1589457084.2072966,"caller":"plugin/hclog_adapter.go:35","msg":"panic: runtime error: index out of range","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073348,"caller":"plugin/hclog_adapter.go:35","msg":"","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073424,"caller":"plugin/hclog_adapter.go:35","msg":"goroutine 1574 [running]:","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073522,"caller":"plugin/hclog_adapter.go:35","msg":"main.(*Plugin).onEN(0xc0001d9680, 0xc0001ad42c, 0xb, 0xc0000b3600, 0x2, 0x2, 0x0, 0x2, 0xc0002e6dc4)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.207359,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:890 +0x1d51","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073677,"caller":"plugin/hclog_adapter.go:35","msg":"main.(*Plugin).on(0xc0001d9680, 0xc0001ad42c, 0xb, 0xc0000b3600, 0x0, 0xc0002e6dc4, 0x2, 0x0, 0x8000101)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073739,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:774 +0xed","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073834,"caller":"plugin/hclog_adapter.go:35","msg":"main.(*Plugin).createOccurrencesEN(0xc0001d9680, 0xc0002b1520, 0xc000424a50, 0xc00047206a)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2073922,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:162 +0x322","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2074018,"caller":"plugin/hclog_adapter.go:35","msg":"main.(*Plugin).CreateOccurrences(0xc0001d9680, 0xc0002b1520, 0x2, 0x0)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2074096,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:130 +0xd9","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2074373,"caller":"plugin/hclog_adapter.go:35","msg":"main.(*Plugin).ScheduleReminder(0xc0001d9680, 0xc0002b1520, 0xc000447360, 0x1a, 0xc0001ad411, 0x26, 0x1)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.207467,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/scheduler.go:39 +0x218","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2074804,"caller":"plugin/hclog_adapter.go:35","msg":"main.(*Plugin).ExecuteCommand(0xc0001d9680, 0xc000445d60, 0xc0002ba360, 0x7fafc969e0d0, 0xc0001d9680)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2074947,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/command.go:101 +0x7b8","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2075067,"caller":"plugin/hclog_adapter.go:35","msg":"github.com/mattermost/mattermost-server/plugin.(*hooksRPCServer).ExecuteCommand(0xc0001b2a60, 0xc0004309f0, 0xc000430d80, 0x0, 0x0)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2075148,"caller":"plugin/hclog_adapter.go:35","msg":"\t/Users/scottd/go/pkg/mod/github.com/mattermost/[email protected]+incompatible/plugin/client_rpc_generated.go:114 +0x78","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2075608,"caller":"plugin/hclog_adapter.go:35","msg":"reflect.Value.call(0xc0001a9620, 0xc0001b4420, 0x13, 0xb9ec07, 0x4, 0xc00007bf18, 0x3, 0x3, 0xc000293a80, 0x40a374, ...)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2075694,"caller":"plugin/hclog_adapter.go:35","msg":"\t/usr/local/Cellar/go/1.12.5/libexec/src/reflect/value.go:447 +0x461","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2076027,"caller":"plugin/hclog_adapter.go:35","msg":"reflect.Value.Call(0xc0001a9620, 0xc0001b4420, 0x13, 0xc00003ef18, 0x3, 0x3, 0x405e87, 0xc00027dda0, 0xc0004501d8)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2076104,"caller":"plugin/hclog_adapter.go:35","msg":"\t/usr/local/Cellar/go/1.12.5/libexec/src/reflect/value.go:308 +0xa4","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2078173,"caller":"plugin/hclog_adapter.go:35","msg":"net/rpc.(*service).call(0xc0001b0d40, 0xc0001c2410, 0xc0001b8790, 0xc0001b87a0, 0xc0001ba800, 0xc0001b31e0, 0xa63980, 0xc0004309f0, 0x16, 0xa639c0, ...)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2078435,"caller":"plugin/hclog_adapter.go:35","msg":"\t/usr/local/Cellar/go/1.12.5/libexec/src/net/rpc/server.go:384 +0x14e","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2078495,"caller":"plugin/hclog_adapter.go:35","msg":"created by net/rpc.(*Server).ServeCodec","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1589457084.2078664,"caller":"plugin/hclog_adapter.go:35","msg":"\t/usr/local/Cellar/go/1.12.5/libexec/src/net/rpc/server.go:481 +0x42b","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"error","ts":1589457084.2089639,"caller":"mlog/log.go:174","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"unexpected EOF"}
{"level":"debug","ts":1589457084.2092795,"caller":"plugin/hclog_adapter.go:33","msg":"plugin process exited","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","wrapped_extras":"pathplugins/com.github.scottleedavis.mattermost-plugin-remind/server/dist/plugin-linux-amd64pid89966errorexit status 2"}
{"level":"debug","ts":1589457084.2107751,"caller":"mlog/log.go:162","msg":"Command with a trigger of 'remind' not found. To send a message beginning with \"/\", try adding an empty space at the beginning of the message.","path":"/mattermost/api/v4/commands/execute","request_id":"bcj4fordi7ro7p8chb9ipnwykh","ip_addr":"xxx.xxx.xxx.xxx","user_id":"7rehqjww43r4tyo5mrmewj7tfc","method":"POST","err_where":"command","http_code":404,"err_details":""}
{"level":"debug","ts":1589457085.9719062,"caller":"app/email_batching.go:110","msg":"Email batching job ran. 0 user(s) still have notifications pending."}
{"level":"debug","ts":1589457087.2322237,"caller":"web/handlers.go:77","msg":"Received HTTP request","method":"POST","url":"/mattermost/api/v4/users/status/ids","request_id":"dfqjahcatjf6jg13z39bk937oo"}
Doesn't "msg":"panic: runtime error: index out of range" look suspicious?
At the moment I have to reenable the plugin every day.
Doesn't "msg":"panic: runtime error: index out of range" look suspicious?
Indeed. If you unpack the subsequent messages, the exception seems to happen around line 890 in server/occurrence.go, in the onEN() function:
panic: runtime error: index out of range
goroutine 1574 [running]:
main.(*Plugin).onEN(0xc0001d9680, 0xc0001ad42c, 0xb, 0xc0000b3600, 0x2, 0x2, 0x0, 0x2, 0xc0002e6dc4)
/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:890 +0x1d51
main.(*Plugin).on(0xc0001d9680, 0xc0001ad42c, 0xb, 0xc0000b3600, 0x0, 0xc0002e6dc4, 0x2, 0x0, 0x8000101)
/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:774 +0xed
main.(*Plugin).createOccurrencesEN(0xc0001d9680, 0xc0002b1520, 0xc000424a50, 0xc00047206a)
/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:162 +0x322
main.(*Plugin).CreateOccurrences(0xc0001d9680, 0xc0002b1520, 0x2, 0x0)
/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/occurrence.go:130 +0xd9
main.(*Plugin).ScheduleReminder(0xc0001d9680, 0xc0002b1520, 0xc000447360, 0x1a, 0xc0001ad411, 0x26, 0x1)
/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/scheduler.go:39 +0x218
main.(*Plugin).ExecuteCommand(0xc0001d9680, 0xc000445d60, 0xc0002ba360, 0x7fafc969e0d0, 0xc0001d9680)
/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/command.go:101 +0x7b8
github.com/mattermost/mattermost-server/plugin.(*hooksRPCServer).ExecuteCommand(0xc0001b2a60, 0xc0004309f0, 0xc000430d80, 0x0, 0x0)
/Users/scottd/go/pkg/mod/github.com/mattermost/[email protected]+incompatible/plugin/client_rpc_generated.go:114 +0x78
reflect.Value.call(0xc0001a9620, 0xc0001b4420, 0x13, 0xb9ec07, 0x4, 0xc00007bf18, 0x3, 0x3, 0xc000293a80, 0x40a374, ...)
/usr/local/Cellar/go/1.12.5/libexec/src/reflect/value.go:447 +0x461
reflect.Value.Call(0xc0001a9620, 0xc0001b4420, 0x13, 0xc00003ef18, 0x3, 0x3, 0x405e87, 0xc00027dda0, 0xc0004501d8)
/usr/local/Cellar/go/1.12.5/libexec/src/reflect/value.go:308 +0xa4
net/rpc.(*service).call(0xc0001b0d40, 0xc0001c2410, 0xc0001b8790, 0xc0001b87a0, 0xc0001ba800, 0xc0001b31e0, 0xa63980, 0xc0004309f0, 0x16, 0xa639c0, ...)
/usr/local/Cellar/go/1.12.5/libexec/src/net/rpc/server.go:384 +0x14e
created by net/rpc.(*Server).ServeCodec
/usr/local/Cellar/go/1.12.5/libexec/src/net/rpc/server.go:481 +0x42b
Note that this part of the code was changed after the 0.4.4 release, by commit 2ca387850f340381cb20b3b2cc3dea48e387c2c5 (5 May). So maybe this problem has already been fixed?
I just built and installed the latest version of this plugin locally. And indeed this problem has already been fixed in the latest version from master.
However this version has not been released yet, which makes it cumbersome to install.
@scottleedavis would you consider releasing the current state of master as a 0.4.5 version?
@scottleedavis I'd still be very much interested in releasing a new compiled version.
I've seen there's not much activity on this plugin recently–which is fine :) Do you have some time for publishing a release currently? Or maybe would you consider additionnal maintainers to help keep this plugin up-to-date?
@scottleedavis I'd still be very much interested in releasing a new compiled version.
I've seen there's not much activity on this plugin recently–which is fine :) Do you have some time for publishing a release currently? Or maybe would you consider additionnal maintainers to help keep this plugin up-to-date?
@kemenaran do you have recommendations for maintainers? You would be?
@kemenaran do you have recommendations for maintainers? You would be?
I'd be interested in stepping in, yes. I could at least do some grunt work on publishing releases, managing the CI, writing some tests, or reviewing PRs.
That said, although I know some Mattermost internals (I maintain the Mattermost Yunohost package and some build scripts, I don't know much about Mattermost plugins. Oh, and I'll be on holidays for a few weeks soon.
But I guess I could at least help – and maybe broadcast a message about this plugin looking for additional help in the Mattermost developer communities I know.
(I've also seen repos pinning an issue about "maintainers wanted" on top of the issues list, maybe that could also be an option?)