plugin crash when add reminder

[tgly307]

I install the plugin and enable it, then test it with command /remind list, plugin return the message No reminders correctly.
When I use /remind command, the dialog can trigger correctly, but when I set the reminder with this way, plugin throw an error unexpected EOF and crash.

{"level":"error","ts":1556708299.7545977,"caller":"mlog/log.go:172","msg":"Plugin failed to ServeHTTP, RPC call failed","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"unexpected EOF"}
{"level":"error","ts":1556708299.7554028,"caller":"mlog/log.go:172","msg":"Action integration error","path":"/api/v4/actions/dialogs/submit","request_id":"tikderdazjy1jrkbr9fiaepu3h","ip_addr":"x.x.x.x","user_id":"rc35qwg4f3napjkk1wbngh8p6c","method":"POST","err_where":"DoActionRequest","http_code":400,"err_details":"status=500"}

Then I tried to restart the plugin, it can't accept any command even /remind list, the error is also unexpected EOF

Only after disable & enable and execute command /remind __clear, the plugin return right message with command /remind list

Then I tried add reminder with command /remind me Do the dishes in 1 day, it failed with same error unexpected EOF, the log is below

{"level":"error","ts":1556710033.9267929,"caller":"mlog/log.go:172","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"unexpected EOF"}

Env:
Plugin version 0.2.0
Mattermost server version 5.10.0 run by docker-compose, the siteURL is set with "https://demo.com".

my mattermost server runs after nginx, the container port is 8000, mapping to 8086 of host machine, then nginx forwarding requests to host's port 8086.
Do I set something wrong?

[scottleedavis]

@tgly307 I setup a docker server 5.10 (without nginx) to replicate a simple setup. I set my sitURL to localhost:8065 (for the docker container internal). I was able to schedule and interact with reminders both with typed and dialog commands without issue.

From your debugging, I suspect API calls are not working correctly, and I am curious if your siteURL demo.com is valid for the container? (i get forbidden at the url) . Can you try using localhost, or perhaps another site url (if there is one you are using different that demo.com)?

[scottleedavis]

If siteURL is not to blame, I will try more so to replicate.

[tgly307]

@scottleedavis hi, sorry for the late reply.
I have set siteURL to http://localhost:8000 ( the image expose port 8000 in docker-compose ), the problem still exists. And if I set siteURL to localhost, other plugin function will fail, such as supply image to user, the link of image will forward to http://localhost/xxxx.png incorrectly.

[scottleedavis]

@tgly307 do other plugins work? (E.g. https://github.com/scottleedavis/mattermost-plugin-spybot or any others...)

I will do my best to replicate if so.

[tgly307]

Yes, all other plugins work fine. Including spybot and analysis bot

[scottleedavis]

I have not been able to replicate the error but added a half dozen new npe protection checks. please give this a try:
v0.2.1

Also, if it doesn't work, could you share /remind __user?

[tgly307]

I install v0.2.1, but the problem still exists.
When I use command /remind __user, the response is

locale: en
location: UTC

[tgly307]

There is something strange.
When I restart the plugin, I use command /remind list, it works ( to check if the plugin is working ). And I use command /remind me eat in 2 seconds, the system return "Command with a trigger of '/remind' not found", but I still can receive message from remindbot like this below:

The button can't response click event.
Then I restart the plugin again, and click the button from remindbot message, it worked.
The log shows below:

{"level":"error","ts":1556972490.452481,"caller":"mlog/log.go:172","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"unexpected EOF"}
{"level":"error","ts":1556972495.5485833,"caller":"mlog/log.go:172","msg":"Plugin failed to ServeHTTP, RPC call failed","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
{"level":"error","ts":1556972495.5492582,"caller":"mlog/log.go:172","msg":"Action integration error","path":"/api/v4/posts/s48974zecbdwurf4pjtbi5swjc/actions/drps58nanpfspmeg895efspuxo","request_id":"sobkb3d4rire3x3igzoiw8d1za","ip_addr":"218.x.x.14","user_id":"rc35qwg4f3napjkk1wbngh8p6c","method":"POST","err_where":"DoActionRequest","http_code":400,"err_details":"status=500"}
{"level":"error","ts":1556972500.5488896,"caller":"mlog/log.go:172","msg":"Plugin failed to ServeHTTP, muxBroker couldn't accept connection","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","serve_http_stream_id":2,"error":"timeout waiting for accept"}
{"level":"error","ts":1556972500.548999,"caller":"mlog/log.go:172","msg":"Plugin failed to ServeHTTP, muxBroker couldn't Accept request body connection","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"timeout waiting for accept"}

[scottleedavis]

Ok! I was able to replicate some of the behavior using mattermost-docker.

Could you please try v0.2.2 ? Please disable/enable before usage too. Also, existing reminders/buttons will not work, but new ones should. hopefully.. . :)

If that does't work, would you please share the docker-compose.yml and app Dockerfile configuration with me: scottleedavis at gmail ?

[tgly307]

Unfortunately, the issue still exists. T^T
The plugin still crashes when I add task to it, but I also can recieve message from the remindbot, but button can't work until plugin restart.
My docker-compose.yml and app Dockerfile are exactly the same as the official version except password of DB.
The image is based on alpine, so I guess the problem may come from the setting of the time zone.

[scottleedavis]

Thank you for letting me know your setup, I was able to reproduce 100% of the time.

Running the log level at DEBUG level output, I noticed your guess about alpine & timezone was correct.

{"level":"debug","ts":1557067004.1418078,"caller":"mlog/sugar.go:15","msg":"new occurrence 2019-05-05 14:36:46 +0000 UTC","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.1660306,"caller":"mlog/sugar.go:15","msg":"location for occurrence UTC","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.1696134,"caller":"plugin/hclog_adapter.go:34","msg":"panic: time: missing Location in call to Time.In","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.171683,"caller":"plugin/hclog_adapter.go:34","msg":"","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.1726882,"caller":"plugin/hclog_adapter.go:34","msg":"goroutine 83 [running]:","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"error","ts":1557067004.1716583,"caller":"mlog/log.go:172","msg":"RPC call ExecuteCommand to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"unexpected EOF"}
{"level":"debug","ts":1557067004.1733131,"caller":"plugin/hclog_adapter.go:34","msg":"time.Time.In(...)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.1749027,"caller":"plugin/hclog_adapter.go:34","msg":"\t/usr/local/Cellar/go/1.12.4/libexec/src/time/time.go:1120","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.175589,"caller":"plugin/hclog_adapter.go:34","msg":"main.(*Plugin).ScheduleReminder(0xc0001c68c0, 0xc0003e3400, 0xc00039df60, 0x1a, 0x0, 0xc00030b760, 0x2)","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"debug","ts":1557067004.1761258,"caller":"plugin/hclog_adapter.go:34","msg":"\t/Users/scottd/go/src/github.com/scottleedavis/mattermost-plugin-remind/server/scheduler.go:59 +0x180a","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}

Looks like another has had this same issue on alpine, and solved it adding the tzdata apk to alpine.

From there, I changed mattermost-docker/app/Dockerfile , and added the tzdata apk to the install

# Install some needed packages
RUN apk add --no-cache \
	ca-certificates \
	curl \
	jq \
	libc6-compat \
	libffi-dev \
	linux-headers \
	mailcap \
	netcat-openbsd \
	xmlsec-dev \
	tzdata \
	&& rm -rf /tmp/*

This solved the problem in my tests, and I added a PR to add tzdata to the main docker repo. mattermost/mattermost-docker#390

Does this work as a solution for you @tgly307?

[tgly307]

It's a good solution to avoid other time zone issues.
In another plugin, I found a related issue. Does it possible to set the plugin's time zone local to avoid changing Dockerfile? To set time zone to local or UTC is accepted by mattermost server.

[scottleedavis]

Thank you for that link... It helps the case that mattermost-docker app can provide tzdata.

While the plugin could only support local or UTC, this will not work well for teams that span timezones, for example community.mattermost.com.

[scottleedavis]

mattermost-docker accepted the PR! Update to that and verify solution?

[tgly307]

wow, that's great!

[tgly307]

I update the Dockerfile and it works as expected! Thanks for working on it. The issue can be closed if you want. :)

[scottleedavis]

👍