Skip to content
This repository has been archived by the owner on Apr 11, 2020. It is now read-only.

Bot keeps disconnecting and reconnecting twice #33

Open
mirko314 opened this issue Aug 14, 2019 · 4 comments
Open

Bot keeps disconnecting and reconnecting twice #33

mirko314 opened this issue Aug 14, 2019 · 4 comments

Comments

@mirko314
Copy link

Hey,
First, thank you for implementing this awesome library 👍

Somehow my Slackserver is quite unstable. I keep getting disconnects (which is fine by itself), but after that, TWO Bots connect. So every incoming message is getting processed twice by my system. And this effect keeps stacking, so I ended up with 7 connections sometimes, that then lead to the Too Many requests� API error.
I stumbled upon slack-ruby/slack-ruby-client@9934f02 but not sure if related.

Do you have an idea how to fix this?

Thank you,
Mirko

Versions

Using slack-ruby-client 0.14.2
Using slack-bot-server 0.4.7

Log


2019-08-14T03:43:12.653171823Z app[slack.1]: New Slack Message: channel=CL3TXJTLL, event_ts=1565753962.001800, hidden=true, message=attachments=[#<Slack::Messages::Message fallback="Paweł U. | Ruby on Rails Web Development Consultant Full Stack Blog: Migrate a Rails App from Heroku to Dokku [Step by Step Tutorial]" from_url="https://pawelurbanek.com/rails-heroku-dokku-migration" id=1 image_bytes=123721 image_height=250 image_url="https://pawelurbanek.com/assets/dokku-containers-543a4920f96e8686f14f330c9c37b2d4fce2ce571f34774894f75ba594c00078.jpg" image_width=400 original_url="https://pawelurbanek.com/rails-heroku-dokku-migration" service_icon="https://pawelurbanek.com/apple-touch-icon-57x57.png" service_name="Paweł U. | Ruby on Rails Web Development Consultant Full Stack Blog" text="Dokku is dev ops for dummies and a cheaper alternative to Heroku. Recently I've migrated a couple of my projects to it. In this blog post, I will describe how to setup and migrate a Rails app to Dokku with PostgreSQL, Sidekiq, Redis and Let's Encrypt or Cloudflare for free SSL." title="Migrate a Rails App from Heroku to Dokku [Step by Step Tutorial]" title_link="https://pawelurbanek.com/rails-heroku-dokku-migration" ts=1523250037>], client_msg_id=b95cb068-a4f2-4719-b222-ba9fddd0e9e0, team=TL3K7E8CV, text=<https://pawelurbanek.com/rails-heroku-dokku-migration>, ts=1565753961.001700, type=message, user=UL351D6CC, previous_message=client_msg_id=b95cb068-a4f2-4719-b222-ba9fddd0e9e0, team=TL3K7E8CV, text=<https://pawelurbanek.com/rails-heroku-dokku-migration>, ts=1565753961.001700, type=message, user=UL351D6CC, subtype=message_changed, ts=1565753962.001800, type=message
2019-08-14T03:43:12.653638862Z app[slack.1]: D, [2019-08-14T03:39:22.514390 #8] DEBUG -- :   Team Load (0.7ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
2019-08-14T03:43:12.654250091Z app[slack.1]: I, [2019-08-14T03:41:21.460777 #8]  INFO -- : [BOT/postwave] disconnected
2019-08-14T03:43:12.654293758Z app[slack.1]: I, [2019-08-14T03:41:22.026071 #8]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-14T03:43:12.654393675Z app[slack.1]: I, [2019-08-14T03:41:22.029442 #8]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-14T03:43:12.654420730Z app[slack.1]: D, [2019-08-14T03:43:09.629051 #8] DEBUG -- : [BOT/postwave] {:message=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">}
2019-08-14T03:43:12.654529240Z app[slack.1]: D, [2019-08-14T03:43:09.630379 #8] DEBUG -- : [BOT/postwave] {:on_message=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">, :bot_message=>false}
2019-08-14T03:43:12.654556563Z app[slack.1]: D, [2019-08-14T03:43:09.630933 #8] DEBUG -- : [BOT/postwave] {:on_im=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">, :bot_message=>false, :is_im_channel=>false}
2019-08-14T03:43:12.654669684Z app[slack.1]: New Slack Message: channel=CL3TXJTLL, client_msg_id=de06f3fa-091f-488d-a735-3563098e157b, event_ts=1565754189.002000, source_team=TL3K7E8CV, suppress_notification=false, team=TL3K7E8CV, text=<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>, ts=1565754189.002000, type=message, user=UL351D6CC, user_team=TL3K7E8CV
2019-08-14T03:43:12.654693050Z app[slack.1]: D, [2019-08-14T03:43:09.637072 #8] DEBUG -- :   Team Load (2.0ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
2019-08-14T03:43:12.654816945Z app[slack.1]: D, [2019-08-14T03:43:09.647878 #8] DEBUG -- :    (0.7ms)  BEGIN
2019-08-14T03:43:12.654843112Z app[slack.1]: D, [2019-08-14T03:43:09.650059 #8] DEBUG -- :   Post Create (1.2ms)  INSERT INTO "posts" ("team_id", "text", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["team_id", 5], ["text", "<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>"], ["created_at", "2019-08-14 03:43:09.644393"], ["updated_at", "2019-08-14 03:43:09.644393"]]
2019-08-14T03:43:12.655271364Z app[slack.1]: D, [2019-08-14T03:43:09.655344 #8] DEBUG -- :   Post Update (1.0ms)  UPDATE "posts" SET "text" = $1, "updated_at" = $2 WHERE "posts"."id" = $3  [["text", "https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise"], ["updated_at", "2019-08-14 03:43:09.652506"], ["id", 82]]
2019-08-14T03:43:12.655315846Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:43:12.655431561Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:43:12.655450769Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:43:12.655518890Z app[slack.1]: D, [2019-08-14T03:43:11.126618 #8] DEBUG -- :    (1.1ms)  COMMIT
2019-08-14T03:43:12.655538406Z app[slack.1]: D, [2019-08-14T03:43:11.127923 #8] DEBUG -- : [BOT/postwave] {:message=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">}
2019-08-14T03:43:12.655634580Z app[slack.1]: D, [2019-08-14T03:43:11.128120 #8] DEBUG -- : [BOT/postwave] {:on_message=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">, :bot_message=>false}
2019-08-14T03:43:12.655678017Z app[slack.1]: D, [2019-08-14T03:43:11.128274 #8] DEBUG -- : [BOT/postwave] {:on_im=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">, :bot_message=>false, :is_im_channel=>false}
2019-08-14T03:43:12.655770742Z app[slack.1]: New Slack Message: channel=CL3TXJTLL, client_msg_id=de06f3fa-091f-488d-a735-3563098e157b, event_ts=1565754189.002000, source_team=TL3K7E8CV, suppress_notification=false, team=TL3K7E8CV, text=<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>, ts=1565754189.002000, type=message, user=UL351D6CC, user_team=TL3K7E8CV
2019-08-14T03:43:12.655809798Z app[slack.1]: D, [2019-08-14T03:43:11.129350 #8] DEBUG -- :   Team Load (0.5ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
2019-08-14T03:43:12.655928518Z app[slack.1]: D, [2019-08-14T03:43:11.131802 #8] DEBUG -- :    (0.3ms)  BEGIN
2019-08-14T03:43:12.655949959Z app[slack.1]: D, [2019-08-14T03:43:11.133176 #8] DEBUG -- :   Post Create (0.7ms)  INSERT INTO "posts" ("team_id", "text", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["team_id", 5], ["text", "<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>"], ["created_at", "2019-08-14 03:43:11.130764"], ["updated_at", "2019-08-14 03:43:11.130764"]]
2019-08-14T03:43:12.656115486Z app[slack.1]: D, [2019-08-14T03:43:11.136710 #8] DEBUG -- :   Post Update (0.9ms)  UPDATE "posts" SET "text" = $1, "updated_at" = $2 WHERE "posts"."id" = $3  [["text", "https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise"], ["updated_at", "2019-08-14 03:43:11.134542"], ["id", 83]]
2019-08-14T03:43:12.656144042Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:43:12.656250467Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:43:12.656271819Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:43:12.658477600Z app[slack.1]: D, [2019-08-14T03:43:12.652145 #8] DEBUG -- :    (1.4ms)  COMMIT
2019-08-14T03:46:36.836281450Z app[slack.1]: D, [2019-08-14T03:43:12.657131 #8] DEBUG -- : [BOT/postwave] {:message=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">}
2019-08-14T03:46:36.836679355Z app[slack.1]: D, [2019-08-14T03:43:12.657510 #8] DEBUG -- : [BOT/postwave] {:on_message=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">, :bot_message=>false}
2019-08-14T03:46:36.837129398Z app[slack.1]: D, [2019-08-14T03:43:12.657762 #8] DEBUG -- : [BOT/postwave] {:on_im=>#<Slack::Messages::Message channel="CL3TXJTLL" client_msg_id="de06f3fa-091f-488d-a735-3563098e157b" event_ts="1565754189.002000" source_team="TL3K7E8CV" suppress_notification=false team="TL3K7E8CV" text="<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>" ts="1565754189.002000" type="message" user="UL351D6CC" user_team="TL3K7E8CV">, :bot_message=>false, :is_im_channel=>false}
2019-08-14T03:46:36.837155693Z app[slack.1]: New Slack Message: channel=CL3TXJTLL, client_msg_id=de06f3fa-091f-488d-a735-3563098e157b, event_ts=1565754189.002000, source_team=TL3K7E8CV, suppress_notification=false, team=TL3K7E8CV, text=<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>, ts=1565754189.002000, type=message, user=UL351D6CC, user_team=TL3K7E8CV
2019-08-14T03:46:36.837317031Z app[slack.1]: D, [2019-08-14T03:43:12.664536 #8] DEBUG -- :   Team Load (6.1ms)  SELECT "teams".* FROM "teams" WHERE "teams"."id" = $1 LIMIT $2  [["id", 5], ["LIMIT", 1]]
2019-08-14T03:46:36.837340619Z app[slack.1]: D, [2019-08-14T03:43:12.670642 #8] DEBUG -- :    (3.6ms)  BEGIN
2019-08-14T03:46:36.837457378Z app[slack.1]: D, [2019-08-14T03:43:12.673575 #8] DEBUG -- :   Post Create (2.0ms)  INSERT INTO "posts" ("team_id", "text", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["team_id", 5], ["text", "<https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise>"], ["created_at", "2019-08-14 03:43:12.666167"], ["updated_at", "2019-08-14 03:43:12.666167"]]
2019-08-14T03:46:36.837479718Z app[slack.1]: D, [2019-08-14T03:43:12.683010 #8] DEBUG -- :   Post Update (7.0ms)  UPDATE "posts" SET "text" = $1, "updated_at" = $2 WHERE "posts"."id" = $3  [["text", "https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise"], ["updated_at", "2019-08-14 03:43:12.674755"], ["id", 84]]
2019-08-14T03:46:36.837582825Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:46:36.837601546Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:46:36.837667127Z app[slack.1]: https://www.quora.com/What-is-Phoenixs-alternative-for-Rails-devise is missing attributes, could not create preview
2019-08-14T03:46:36.837814487Z app[slack.1]: D, [2019-08-14T03:43:14.110840 #8] DEBUG -- :    (1.7ms)  COMMIT
2019-08-14T03:46:36.837946942Z app[slack.1]: I, [2019-08-14T03:44:21.776431 #8]  INFO -- : [BOT/postwave] disconnected
2019-08-14T03:46:36.837970444Z app[slack.1]: E, [2019-08-14T03:46:36.834779 #8] ERROR -- : Failed to open TCP connection to slack.com:443 (Connection timed out - connect(2) for "slack.com" port 443) (Faraday::TimeoutError)
2019-08-14T03:46:36.838045944Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/net/http.rb:939:in `rescue in block in connect'
2019-08-14T03:46:36.838066691Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/net/http.rb:936:in `block in connect'
2019-08-14T03:46:36.838156227Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
2019-08-14T03:46:36.838191581Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/timeout.rb:103:in `timeout'
2019-08-14T03:46:36.838246403Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/net/http.rb:935:in `connect'
2019-08-14T03:46:36.838279073Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/net/http.rb:920:in `do_start'
2019-08-14T03:46:36.838329403Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/net/http.rb:909:in `start'
2019-08-14T03:46:36.838360707Z app[slack.1]: /app/vendor/ruby-2.5.1/lib/ruby/2.5.0/net/http.rb:1455:in `request'
2019-08-14T03:46:36.838436203Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:87:in `perform_request'
2019-08-14T03:46:36.838473179Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:43:in `block in call'
2019-08-14T03:46:36.838543076Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:92:in `with_net_http_connection'
2019-08-14T03:46:36.838561328Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/adapter/net_http.rb:38:in `call'
2019-08-14T03:46:36.838627798Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/response.rb:8:in `call'
2019-08-14T03:46:36.838646437Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/response/logger.rb:26:in `call'
2019-08-14T03:46:36.838860996Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday_middleware-0.13.1/lib/faraday_middleware/response_middleware.rb:31:in `call'
2019-08-14T03:46:36.838914094Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/response.rb:8:in `call'
2019-08-14T03:46:36.838964186Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/response.rb:8:in `call'
2019-08-14T03:46:36.838994477Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/response.rb:8:in `call'
2019-08-14T03:46:36.839047903Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/request/url_encoded.rb:15:in `call'
2019-08-14T03:46:36.839080133Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/request/multipart.rb:15:in `call'
2019-08-14T03:46:36.839133195Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/rack_builder.rb:143:in `build_response'
2019-08-14T03:46:36.839164354Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/connection.rb:387:in `run_request'
2019-08-14T03:46:36.839301197Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faraday-0.15.4/lib/faraday/connection.rb:175:in `post'
2019-08-14T03:46:36.839322060Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/web/faraday/request.rb:25:in `request'
2019-08-14T03:46:36.839431655Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/web/faraday/request.rb:10:in `post'
2019-08-14T03:46:36.839449920Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/web/api/endpoints/rtm.rb:41:in `rtm_start'
2019-08-14T03:46:36.839517214Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:153:in `build_socket'
2019-08-14T03:46:36.839535167Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:58:in `start_async'
2019-08-14T03:46:36.839601287Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:179:in `start'
2019-08-14T03:46:36.839624221Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:348:in `block in <class:Bot>'
2019-08-14T03:46:36.839717603Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:368:in `instance_exec'
2019-08-14T03:46:36.839736303Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:368:in `block in run_callbacks'
2019-08-14T03:46:36.841382706Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:367:in `each'
2019-08-14T03:46:36.841442072Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:367:in `run_callbacks'
2019-08-14T03:46:36.841532035Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:174:in `block in start'
2019-08-14T03:46:36.841540632Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:203:in `block in callback'
2019-08-14T03:46:36.841546836Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:202:in `each'
2019-08-14T03:46:36.841552625Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:202:in `callback'
2019-08-14T03:46:36.841581804Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:97:in `block (2 levels) in run_loop'
2019-08-14T03:46:36.841681334Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:39:in `block in emit'
2019-08-14T03:46:36.841689375Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `each'
2019-08-14T03:46:36.841695148Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `emit'
2019-08-14T03:46:36.841701065Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/socket.rb:82:in `close'
2019-08-14T03:46:36.841706745Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:141:in `restart_async'
2019-08-14T03:46:36.841712513Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:130:in `run_ping!'
2019-08-14T03:46:36.841766447Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/concurrency/eventmachine.rb:34:in `block in start_async'
2019-08-14T03:46:36.841773954Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/em/timers.rb:56:in `fire'
2019-08-14T03:46:36.841780005Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `call'
2019-08-14T03:46:36.841788185Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `run_machine'
2019-08-14T03:46:36.841794096Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `run'
2019-08-14T03:46:36.841799920Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/server.rb:80:in `start'
2019-08-14T03:46:36.841805813Z app[slack.1]: /app/bin/slack_server:36:in `<top (required)>'
2019-08-14T03:46:36.841812187Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2019-08-14T03:46:36.841818228Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2019-08-14T03:46:36.841857406Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/commands/runner/runner_command.rb:42:in `perform'
2019-08-14T03:46:36.841864514Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
2019-08-14T03:46:36.841887895Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
2019-08-14T03:46:36.841894016Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
2019-08-14T03:46:36.841899694Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/command/base.rb:65:in `perform'
2019-08-14T03:46:36.841919932Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/command.rb:46:in `invoke'
2019-08-14T03:46:36.841925923Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/commands.rb:18:in `<top (required)>'
2019-08-14T03:46:36.841932011Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require'
2019-08-14T03:46:36.841937914Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `block in require_with_bootsnap_lfi'
2019-08-14T03:46:36.841944000Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
2019-08-14T03:46:36.841949942Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:21:in `require_with_bootsnap_lfi'
2019-08-14T03:46:36.841956005Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
2019-08-14T03:46:36.841961909Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:302:in `block in require'
2019-08-14T03:46:36.841967811Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:268:in `load_dependency'
2019-08-14T03:46:36.841976259Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:302:in `require'
2019-08-14T03:46:36.841982143Z app[slack.1]: bin/rails:9:in `<main>'
2019-08-14T03:47:11.070684239Z app[slack.1]: E, [2019-08-14T03:47:10.831162 #8] ERROR -- : undefined method `name' for nil:NilClass (NoMethodError)
2019-08-14T03:47:11.070873580Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:64:in `bot_user_name'
2019-08-14T03:47:11.070884754Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/logging.rb:22:in `log_string'
2019-08-14T03:47:11.070889545Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/logging.rb:3:in `log'
2019-08-14T03:47:11.070893747Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:172:in `block in start'
2019-08-14T03:47:11.070897963Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:203:in `block in callback'
2019-08-14T03:47:11.070902187Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:202:in `each'
2019-08-14T03:47:11.070906323Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:202:in `callback'
2019-08-14T03:47:11.070910452Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:97:in `block (2 levels) in run_loop'
2019-08-14T03:47:11.070935287Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:39:in `block in emit'
2019-08-14T03:47:11.070939574Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `each'
2019-08-14T03:47:11.070943252Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `emit'
2019-08-14T03:47:11.070946937Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/socket.rb:82:in `close'
2019-08-14T03:47:11.070950696Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:141:in `restart_async'
2019-08-14T03:47:11.070954352Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:130:in `run_ping!'
2019-08-14T03:47:11.070959689Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/concurrency/eventmachine.rb:34:in `block in start_async'
2019-08-14T03:47:11.070965377Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/em/timers.rb:56:in `fire'
2019-08-14T03:47:11.070970876Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `call'
2019-08-14T03:47:11.070978499Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `run_machine'
2019-08-14T03:47:11.070984712Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `run'
2019-08-14T03:47:11.070990380Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/server.rb:80:in `start'
2019-08-14T03:47:11.070995483Z app[slack.1]: /app/bin/slack_server:36:in `<top (required)>'
2019-08-14T03:47:11.071003508Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2019-08-14T03:47:11.071007318Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2019-08-14T03:47:11.071011524Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/commands/runner/runner_command.rb:42:in `perform'
2019-08-14T03:47:11.071015190Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
2019-08-14T03:47:11.071018897Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
2019-08-14T03:47:11.071022481Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
2019-08-14T03:47:11.071026139Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/command/base.rb:65:in `perform'
2019-08-14T03:47:11.071029729Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/command.rb:46:in `invoke'
2019-08-14T03:47:11.071033337Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/commands.rb:18:in `<top (required)>'
2019-08-14T03:47:11.071037197Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require'
2019-08-14T03:47:11.071041084Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `block in require_with_bootsnap_lfi'
2019-08-14T03:47:11.071050703Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
2019-08-14T03:47:11.071054552Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:21:in `require_with_bootsnap_lfi'
2019-08-14T03:47:11.071058218Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
2019-08-14T03:47:11.071061888Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:302:in `block in require'
2019-08-14T03:47:11.071065535Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:268:in `load_dependency'
2019-08-14T03:47:11.071069696Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:302:in `require'
2019-08-14T03:47:11.071073418Z app[slack.1]: bin/rails:9:in `<main>'
2019-08-14T03:47:11.071077029Z app[slack.1]: E, [2019-08-14T03:47:11.069553 #8] ERROR -- : undefined method `name' for nil:NilClass (NoMethodError)
2019-08-14T03:47:11.071080700Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:74:in `team_name'
2019-08-14T03:47:11.071084408Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/bot.rb:157:in `block in start'
2019-08-14T03:47:11.071088001Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:203:in `block in callback'
2019-08-14T03:47:11.071091758Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:202:in `each'
2019-08-14T03:47:11.071095371Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:202:in `callback'
2019-08-14T03:47:11.071099007Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/client.rb:87:in `block (2 levels) in run_loop'
2019-08-14T03:47:11.071102743Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:39:in `block in emit'
2019-08-14T03:47:11.071106391Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `each'
2019-08-14T03:47:11.071110075Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `emit'
2019-08-14T03:47:11.071113783Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faye-websocket-0.10.9/lib/faye/websocket/api/event_target.rb:44:in `dispatch_event'
2019-08-14T03:47:11.071117437Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faye-websocket-0.10.9/lib/faye/websocket/api.rb:106:in `open'
2019-08-14T03:47:11.071121012Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faye-websocket-0.10.9/lib/faye/websocket/api.rb:44:in `block in initialize'
2019-08-14T03:47:11.071124641Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:39:in `block in emit'
2019-08-14T03:47:11.071128408Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `each'
2019-08-14T03:47:11.071135915Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/event_emitter.rb:38:in `emit'
2019-08-14T03:47:11.071140042Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver.rb:168:in `open'
2019-08-14T03:47:11.071144711Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/websocket-driver-0.7.1/lib/websocket/driver/client.rb:72:in `parse'
2019-08-14T03:47:11.071148403Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faye-websocket-0.10.9/lib/faye/websocket/api.rb:157:in `parse'
2019-08-14T03:47:11.071152074Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-ruby-client-0.14.2/lib/slack/real_time/concurrency/eventmachine.rb:19:in `parse'
2019-08-14T03:47:11.071155749Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/faye-websocket-0.10.9/lib/faye/websocket/client.rb:82:in `receive_data'
2019-08-14T03:47:11.071159380Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `run_machine'
2019-08-14T03:47:11.071185750Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/eventmachine-1.2.7/lib/eventmachine.rb:195:in `run'
2019-08-14T03:47:11.071191387Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/slack-bot-server-0.4.7/lib/slack_bot_server/server.rb:80:in `start'
2019-08-14T03:47:11.071196995Z app[slack.1]: /app/bin/slack_server:36:in `<top (required)>'
2019-08-14T03:47:11.071202841Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2019-08-14T03:47:11.071208271Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2019-08-14T03:47:11.071213737Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/commands/runner/runner_command.rb:42:in `perform'
2019-08-14T03:47:11.071217566Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
2019-08-14T03:47:11.071221248Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
2019-08-14T03:47:11.071224844Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
2019-08-14T03:47:11.071228541Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/command/base.rb:65:in `perform'
2019-08-14T03:47:11.071232149Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/command.rb:46:in `invoke'
2019-08-14T03:47:11.071235845Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/railties-6.0.0.rc1/lib/rails/commands.rb:18:in `<top (required)>'
2019-08-14T03:47:11.071239510Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require'
2019-08-14T03:47:11.071243377Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `block in require_with_bootsnap_lfi'
2019-08-14T03:47:11.071247203Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
2019-08-14T03:47:11.071252054Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:21:in `require_with_bootsnap_lfi'
2019-08-14T03:47:11.071257513Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/bootsnap-1.4.4/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
2019-08-14T03:47:11.071269088Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:302:in `block in require'
2019-08-14T03:47:11.071274726Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:268:in `load_dependency'
2019-08-14T03:47:11.071278513Z app[slack.1]: /app/vendor/bundle/ruby/2.5.0/gems/activesupport-6.0.0.rc1/lib/active_support/dependencies.rb:302:in `require'
2019-08-14T03:47:11.071282187Z app[slack.1]: bin/rails:9:in `<main>'

Full bundle:

Using rake 12.3.2
Using concurrent-ruby 1.1.5
Using i18n 1.6.0
Using minitest 5.11.3
Using thread_safe 0.3.6
Using tzinfo 1.2.5
Using zeitwerk 2.1.8
Using activesupport 6.0.0.rc1
Using builder 3.2.3
Using erubi 1.8.0
Using mini_portile2 2.4.0
Using nokogiri 1.10.3
Using rails-dom-testing 2.0.3
Using crass 1.0.4
Using loofah 2.2.3
Using rails-html-sanitizer 1.0.4
Using actionview 6.0.0.rc1
Using rack 2.0.7
Using rack-test 1.1.0
Using actionpack 6.0.0.rc1
Using nio4r 2.4.0
Using websocket-extensions 0.1.4
Using websocket-driver 0.7.1
Using actioncable 6.0.0.rc1
Using globalid 0.4.2
Using activejob 6.0.0.rc1
Using activemodel 6.0.0.rc1
Using activerecord 6.0.0.rc1
Using mimemagic 0.3.3
Using marcel 0.3.3
Using activestorage 6.0.0.rc1
Using mini_mime 1.0.2
Using mail 2.7.1
Using actionmailbox 6.0.0.rc1
Using actionmailer 6.0.0.rc1
Using actiontext 6.0.0.rc1
Using public_suffix 3.1.1
Using addressable 2.6.0
Using ansi 1.5.0
Using ast 2.4.0
Using bcrypt 3.1.13
Using msgpack 1.3.0
Using bootsnap 1.4.4
Using environs 1.1.0
Using multipart-post 2.1.1
Using faraday 0.15.4
Using faraday_middleware 0.13.1
Using hashie 3.6.0
Using multi_json 1.13.1
Using yajl-ruby 1.4.1
Using buffer 0.1.3 from https://github.com/bufferapp/buffer-ruby.git (at master@eb88e48)
Using bundler 2.0.1
Using orm_adapter 0.5.0
Using method_source 0.9.2
Using thor 0.20.3
Using railties 6.0.0.rc1
Using responders 3.0.0
Using warden 1.2.8
Using devise 4.6.2
Using devise_invitable 2.0.1
Using erubis 2.7.0
Using eventmachine 1.2.7
Using faye-websocket 0.10.9
Using gli 2.18.1
Using temple 0.8.1
Using tilt 2.0.9
Using haml 5.1.1
Using sexp_processor 4.12.1
Using ruby_parser 3.13.1
Using html2haml 2.2.0
Using haml-rails 2.0.1
Using jbuilder 2.9.1
Using jwt 2.2.1
Using multi_xml 0.6.0
Using oauth2 1.4.1
Using ruby-ll 2.1.2
Using oga 2.15
Using ogp 0.3.0
Using omniauth 1.9.0
Using omniauth-oauth2 1.6.0
Using omniauth-buffer2 0.0.1
Using pg 1.1.4
Using puma 3.12.1
Using rack-proxy 0.6.5
Using sprockets 3.7.2
Using sprockets-rails 3.2.1
Using rails 6.0.0.rc1
Using redis 4.1.2
Using slack-ruby-client 0.14.2
Using slack-bot-server 0.4.7
Using turbolinks-source 5.2.0
Using turbolinks 5.2.0
Using webpacker 4.0.7
@lazyatom
Copy link
Contributor

Hi there,

Thanks for the detailed bug report. Are you able to get some of the logs where it reconnects and has the two bot instances connected?

Also if possible, can you share the contents of your bin/slack_server script?

Thanks

@mirko314
Copy link
Author

Before that I, I get data via HTTP. It might be related.

The only thing that appears is in the logs the following:

2019-08-14T03:43:12.654250091Z app[slack.1]: I, [2019-08-14T03:41:21.460777 #8]  INFO -- : [BOT/postwave] disconnected
2019-08-14T03:43:12.654293758Z app[slack.1]: I, [2019-08-14T03:41:22.026071 #8]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-14T03:43:12.654393675Z app[slack.1]: I, [2019-08-14T03:41:22.029442 #8]  INFO -- : [BOT/postwave] connected to 'Postwave'

bin/slack_server

#!/usr/bin/env ruby

require 'slack_bot_server'
require 'slack_bot_server/redis_queue'

# Use a Redis-based queue to add/remove bots and to trigger
# bot messages to be sent
queue = SlackBotServer::RedisQueue.new

# Create a new server using that queue
SlackBotServer.logger.level = Logger::DEBUG
server = SlackBotServer::Server.new(queue: queue)

# How your application-specific should be created when the server
# is told about a new slack api token to connect with
server.on_add do |token, team_id|
  # Return a new bot instance to the server. `SimpleBot` is a provided
  # example bot with some very simple behaviour.
  puts "Added Slack for Team #{Team.find(team_id).name} with #{token}"
  PostwaveBot.new(token: token, team_id: team_id)
end

# When the server starts we need to find all the teams which have already
# set up integrations and ensure their bots are launched immediately
Team.all.each do |team|
  # Any arguments can be passed to the `add_bot` method; they are passed
  # on to the proc supplied to `on_add` for the server.
  next if team.slack_integration.nil?
  server.add_bot(team.slack_integration.bot_access_token, team.id)
end

# Actually start the server. This line is blocking; code after
# it won't be executed.
server.start

@lazyatom
Copy link
Contributor

Given you're seeing two connected to <XXX> messages, that means we know that PostwaveBot#start is being called twice. This method is only called in two places:

  • SlackBotServer#start, which runs once when the server itself starts up
  • SlackBotServer#add_bot, which runs when the server starts up (in your Team.all loop), and then whenever the add_bot method is called.

When the server is running (and I'm assuming that nothing is restarting your server), the only way this gets called is when someone in your app sends the add_bot message via the queue; it does't sound like this is what is happening with you though.

So, more questions:

  • Do you have a custom PostwaveBot#key method implementation, or is it just using the default behaviour from SlackBotServer::Bot? Normally the server will prevent more than one bot with the same matching key from being started.
  • Do you see any logging containing adding bot <XXX>? At the log level debug (as your server has set), it should be displayed
  • In the log messages in your second message, between the disconnected and connected messages, was there any other logging?

@mirko314
Copy link
Author

  1. No my PostwaveBot is simple:
require 'slack_bot_server/bot'

class PostwaveBot < SlackBotServer::Bot
  POSTING_CHANNEL_NAME = '---'
  POSTING_CHANNEL_ID = '---'

  # Set the friendly username displayed in Slack
  username 'myBot'
  # Set the image to use as an avatar icon in Slack
  icon_url 'http://my.server.example.com/assets/icon.png'

  def initialize(options)
    @team_id = options.extract!(:team_id)[:team_id]
    raise 'ERROR: no Team found' if @team_id.nil?
    puts "Added Slack for Team #{Team.find(@team_id).name} with #{options.inspect}"
    super(options)
  end
  
  # Respond to mentions in the connected chat room (defaults to #general).
  # As well as the normal data provided by Slack's API, we add the `message`,
  # which is the `text` parameter with the username stripped out. For example,
  # When a user sends 'simple_bot: how are you?', the `message` data contains
  # only 'how are you'.
  on_mention do |data|
    if data['message'] == 'who are you'
      reply text: "I am #{bot_user_name} (user id: #{bot_user_id}, connected to team #{team_name} with team id #{team_id}"
    else
      reply text: "You said '#{data.message}', and I'm frankly fascinated."
    end
  end

  # Respond to messages sent via IM communication directly with the bot.
  on_im do
    reply text: "Hmm, OK, let me get back to you about that."
  end

  on :message do |data|
    puts "New Slack Message: #{data}"
    Team.find(@team_id).process_slack_message(data.to_hash, POSTING_CHANNEL_ID)
  end
end

  1. Yeah it is called only once after startup, how it should be I guess:
    2019-08-15T07:33:56.654781443Z app[slack.1]:�[0m I, [2019-08-15T07:32:24.576356 #9] INFO -- : adding bot <PostwaveBot ...

  2. No nothing in between:


2019-08-15T07:36:25.394253157Z app[slack.1]:�[0m I, [2019-08-15T07:36:24.887227 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:36:25.394259914Z app[slack.1]:�[0m I, [2019-08-15T07:36:25.385644 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:36:25.394266599Z app[slack.1]:�[0m I, [2019-08-15T07:36:25.390688 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.227799842Z app[slack.1]:�[0m I, [2019-08-15T07:38:25.154071 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228022154Z app[slack.1]:�[0m I, [2019-08-15T07:38:25.630857 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228031465Z app[slack.1]:�[0m I, [2019-08-15T07:38:26.124187 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228038286Z app[slack.1]:�[0m I, [2019-08-15T07:38:26.124691 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228044557Z app[slack.1]:�[0m I, [2019-08-15T07:38:26.127463 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228050836Z app[slack.1]:�[0m I, [2019-08-15T07:38:26.132543 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228057071Z app[slack.1]:�[0m I, [2019-08-15T07:40:25.643221 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228063083Z app[slack.1]:�[0m I, [2019-08-15T07:40:26.149574 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228069175Z app[slack.1]:�[0m I, [2019-08-15T07:40:26.595459 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228075169Z app[slack.1]:�[0m I, [2019-08-15T07:40:27.062996 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228081342Z app[slack.1]:�[0m I, [2019-08-15T07:40:27.067159 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228087476Z app[slack.1]:�[0m I, [2019-08-15T07:40:27.067645 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228093529Z app[slack.1]:�[0m I, [2019-08-15T07:40:27.067951 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228111797Z app[slack.1]:�[0m I, [2019-08-15T07:40:27.068180 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228117238Z app[slack.1]:�[0m I, [2019-08-15T07:40:27.068388 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228122710Z app[slack.1]:�[0m I, [2019-08-15T07:42:25.428016 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228128299Z app[slack.1]:�[0m I, [2019-08-15T07:42:25.966758 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228133807Z app[slack.1]:�[0m I, [2019-08-15T07:42:25.980015 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228139397Z app[slack.1]:�[0m I, [2019-08-15T07:42:26.160883 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228144861Z app[slack.1]:�[0m I, [2019-08-15T07:42:26.617190 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228150279Z app[slack.1]:�[0m I, [2019-08-15T07:42:27.069454 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228155638Z app[slack.1]:�[0m I, [2019-08-15T07:42:27.532714 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228161042Z app[slack.1]:�[0m I, [2019-08-15T07:42:27.997823 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228166486Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.461824 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228171984Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.462757 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228178983Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.463137 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228184589Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.464231 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228190006Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.466597 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228195409Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.466969 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228200745Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.467495 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228206110Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.467907 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228211481Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.468418 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228216801Z app[slack.1]:�[0m I, [2019-08-15T07:42:28.591838 #9]  INFO -- : [BOT/postwave] connected to 'Postwave'
2019-08-15T07:44:29.228222078Z app[slack.1]:�[0m I, [2019-08-15T07:44:25.955252 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228227387Z app[slack.1]:�[0m I, [2019-08-15T07:44:26.437212 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228232714Z app[slack.1]:�[0m I, [2019-08-15T07:44:26.886457 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228238084Z app[slack.1]:�[0m I, [2019-08-15T07:44:27.372160 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228243380Z app[slack.1]:�[0m I, [2019-08-15T07:44:27.831963 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228248728Z app[slack.1]:�[0m I, [2019-08-15T07:44:28.269355 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228254150Z app[slack.1]:�[0m I, [2019-08-15T07:44:28.736988 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228259491Z app[slack.1]:�[0m I, [2019-08-15T07:44:29.097806 #9]  INFO -- : [BOT/postwave] disconnected
2019-08-15T07:44:29.228270666Z app[slack.1]:�[0m E, [2019-08-15T07:44:29.225836 #9] ERROR -- : Retry after 57 seconds (Slack::Web::Api::Errors::TooManyRequestsError)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@lazyatom @mirko314