Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Failure/Error: raise ThreadError, 'queue empty' if @queue.empty? #198

Closed
dblock opened this issue Jan 23, 2018 · 14 comments
Closed

Failure/Error: raise ThreadError, 'queue empty' if @queue.empty? #198

dblock opened this issue Jan 23, 2018 · 14 comments
Labels
confirmed bug

Comments

@dblock
Copy link
Collaborator

dblock commented Jan 23, 2018 •
edited
Loading

Seems like a reproducible, but inconsistent failure in Travis.

Failures:
  1) integration test client connected sends message
     Failure/Error: raise ThreadError, 'queue empty' if @queue.empty?
     ThreadError:
       queue empty
     # ./spec/support/queue_with_timeout.rb:29:in `block in pop_with_timeout'
     # ./spec/support/queue_with_timeout.rb:25:in `synchronize'
     # ./spec/support/queue_with_timeout.rb:25:in `pop_with_timeout'
     # ./spec/integration/integration_spec.rb:65:in `wait_for_server'
     # ./spec/integration/integration_spec.rb:76:in `block (2 levels) in <top (required)>'
     # ./spec/integration/integration_spec.rb:6:in `block (3 levels) in <top (required)>'
     # ./vendor/bundle/ruby/2.4.0/gems/vcr-4.0.0/lib/vcr.rb:261:in `turned_off'
     # ./spec/integration/integration_spec.rb:6:in `block (2 levels) in <top (required)>'

https://travis-ci.org/slack-ruby/slack-ruby-client/jobs/332488852
@dblock dblock mentioned this issue Jan 23, 2018
Closed
@ioquatix
Copy link
Contributor

I feel like there are race conditions but I couldn't reproduce them. That being said, here is what I got in at least one case:

client connected
D, [2018-08-28T12:07:30.399298 #74308] DEBUG -- : #start_server, waiting 25 second(s) to prevent Slack rate limiting
D, [2018-08-28T12:07:30.398346 #74308] DEBUG -- : client.on :close, data=#<struct WebSocket::Driver::CloseEvent code=1000, reason="">
#<Thread:0x00007febf822a560@/Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:16 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
25: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/async-1.10.3/lib/async/task.rb:74:in `block in initialize'
24: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:18:in `block (2 levels) in start_async'
23: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:82:in `run_loop'
22: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:26:in `connect!'
21: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:36:in `run_loop'
20: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/async-websocket-0.6.1/lib/async/websocket/connection.rb:63:in `next_event'
19: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/client.rb:63:in `parse'
18: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/hybi.rb:123:in `parse'
17: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/hybi.rb:367:in `emit_frame'
16: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/hybi.rb:255:in `shutdown'
15: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/event_emitter.rb:38:in `emit'
14: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/event_emitter.rb:38:in `each'
13: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/event_emitter.rb:39:in `block in emit'
12: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:100:in `block (2 levels) in run_loop'
11: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:162:in `callback'
10: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:162:in `each'
 9: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:163:in `block in callback'
 8: from /Users/samuel/Documents/socketry/slack-ruby-client/spec/integration/integration_spec.rb:128:in `block (3 levels) in <top (required)>'
 7: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/expectation_target.rb:65:in `to'
 6: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:48:in `handle_matcher'
 5: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:27:in `with_matcher'
 4: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'
 3: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:40:in `handle_failure'
 2: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/fail_with.rb:35:in `fail_with'
 1: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-support-3.8.0/lib/rspec/support.rb:106:in `notify_failure'
/Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-support-3.8.0/lib/rspec/support.rb:97:in `block in <module:Support>':  (RSpec::Expectations::ExpectationNotMetError)
expected true
	 got nil
D, [2018-08-28T12:07:30.419683 #74308] DEBUG -- : #wait_for_server

Compared to a successful run:

integration test
D, [2018-08-28T14:21:29.180907 #75196] DEBUG -- : #start_server, waiting 63 second(s) to prevent Slack rate limiting
I, [2018-08-28T14:22:32.191749 #75196]  INFO -- request: POST https://slack.com/api/rtm.start
D, [2018-08-28T14:22:32.191816 #75196] DEBUG -- request: Accept: "application/json; charset=utf-8"
User-Agent: "Slack Ruby Client/0.12.1"
Content-Type: "application/x-www-form-urlencoded"
I, [2018-08-28T14:22:32.609004 #75196]  INFO -- response: Status 200
D, [2018-08-28T14:22:32.609192 #75196] DEBUG -- response: content-type: "application/json; charset=utf-8"
content-length: "5609"
connection: "keep-alive"
date: "Tue, 28 Aug 2018 05:23:03 GMT"
server: "Apache"
x-slack-router: "p"
x-slack-req-id: "661b0c22-3db2-4b39-b109-c79e866477c3"
x-oauth-scopes: "identify,read,post,client,apps,admin"
x-accepted-oauth-scopes: "rtm:stream,client"
expires: "Mon, 26 Jul 1997 05:00:00 GMT"
cache-control: "private, no-cache, no-store, must-revalidate"
pragma: "no-cache"
x-xss-protection: "0"
x-content-type-options: "nosniff"
x-slack-exp: "1"
x-slack-backend: "h"
referrer-policy: "no-referrer"
strict-transport-security: "max-age=31536000; includeSubDomains; preload"
vary: "Accept-Encoding"
access-control-allow-origin: "*"
x-via: "haproxy-www-8f7k"
x-cache: "Miss from cloudfront"
via: "1.1 3ed49104d7c94fa12d28825f6707b029.cloudfront.net (CloudFront)"
x-amz-cf-id: "2vpdlrby71mH5xPqfbbteAS0J5TzGvg74MBLupieTLDIkDx0Y5H1LA=="
connect: connecting...
D, [2018-08-28T14:22:32.617832 #75196] DEBUG -- : connection is #<Thread:0x00007ffbc0123810@/Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:16 run>
connect: connected @driver = #<Slack::RealTime::Concurrency::Async::Client:0x00007ffbc0104460>
D, [2018-08-28T14:22:32.776020 #75196] DEBUG -- Slack::RealTime::Concurrency::Async::Socket#connect!: Slack::RealTime::Concurrency::Async::Client
run_loop: registering callbacks on #<Slack::RealTime::Concurrency::Async::Client:0x00007ffbc0104460>
run_loop: @driver = #<Slack::RealTime::Concurrency::Async::Client:0x00007ffbc0104460>
D, [2018-08-28T14:22:32.801861 #75196] DEBUG -- : connection.on :open, data=#<struct WebSocket::Driver::OpenEvent>
D, [2018-08-28T14:22:32.801941 #75196] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::OpenEvent
D, [2018-08-28T14:22:32.802076 #75196] DEBUG -- : #wait_for_server
run_loop: event = #<struct WebSocket::Driver::OpenEvent>
D, [2018-08-28T14:22:33.218941 #75196] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::MessageEvent, {"type": "hello"}
D, [2018-08-28T14:22:33.219091 #75196] DEBUG -- Slack::RealTime::Client#dispatch: type=hello
I, [2018-08-28T14:22:33.219207 #75196]  INFO -- : Successfully connected, welcome 'samuel' to the 'Orion Transfer' team at https://oriontransfer.slack.com.
D, [2018-08-28T14:22:33.219290 #75196] DEBUG -- : client.on :hello, data=type=hello
run_loop: event = #<struct WebSocket::Driver::MessageEvent data="{\"type\": \"hello\"}">
D, [2018-08-28T14:22:33.238432 #75196] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::CloseEvent
D, [2018-08-28T14:22:33.238550 #75196] DEBUG -- : client.on :close, data=#<struct WebSocket::Driver::CloseEvent code=1000, reason="">
D, [2018-08-28T14:22:33.238634 #75196] DEBUG -- : #wait_for_server, joined
  gets close, followed by closed

My initial assessment is that the web request to get the rtm endpoint is silently failing. Could it be rate limiting?

@ioquatix
Copy link
Contributor

Another odd thing, I've run a single integration test using repeat and I couldn't reproduce the issue... I'm trying again running all 4 integration tests. I feel like perhaps there is a race condition caused by running multiple specs. I don't know what it would be yet though.

@ioquatix
Copy link
Contributor

Hmmm. So, I could only reproduce this issue when bumping up against rate limits.

I feel like the rtm.start method is probably failing, and this is causing the spec to fail... e.g.

  client connected
D, [2018-08-28T15:09:02.058264 #76075] DEBUG -- : #start_server, waiting 20 second(s) to prevent Slack rate limiting
D, [2018-08-28T15:09:02.057295 #76075] DEBUG -- : client.on :close, data=#<struct WebSocket::Driver::CloseEvent code=1000, reason="">
#<Thread:0x00007fe5dc19f2c0@/Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:16 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
	25: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/async-1.10.3/lib/async/task.rb:74:in `block in initialize'
	24: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:18:in `block (2 levels) in start_async'
	23: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:82:in `run_loop'
	22: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:28:in `connect!'
	21: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:38:in `run_loop'
	20: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/async-websocket-0.6.1/lib/async/websocket/connection.rb:63:in `next_event'
	19: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/client.rb:63:in `parse'
	18: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/hybi.rb:123:in `parse'
	17: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/hybi.rb:367:in `emit_frame'
	16: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/hybi.rb:255:in `shutdown'
	15: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/event_emitter.rb:38:in `emit'
	14: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/event_emitter.rb:38:in `each'
	13: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/websocket-driver-0.7.0/lib/websocket/driver/event_emitter.rb:39:in `block in emit'
	12: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:100:in `block (2 levels) in run_loop'
	11: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:162:in `callback'
	10: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:162:in `each'
	 9: from /Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/client.rb:163:in `block in callback'
	 8: from /Users/samuel/Documents/socketry/slack-ruby-client/spec/integration/integration_spec.rb:129:in `block (3 levels) in <top (required)>'
	 7: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/expectation_target.rb:65:in `to'
	 6: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:48:in `handle_matcher'
	 5: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:27:in `with_matcher'
	 4: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:50:in `block in handle_matcher'
	 3: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/handler.rb:40:in `handle_failure'
	 2: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-expectations-3.8.1/lib/rspec/expectations/fail_with.rb:35:in `fail_with'
	 1: from /Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-support-3.8.0/lib/rspec/support.rb:106:in `notify_failure'
/Users/samuel/.rvm/gems/ruby-2.5.1/gems/rspec-support-3.8.0/lib/rspec/support.rb:97:in `block in <module:Support>':  (RSpec::Expectations::ExpectationNotMetError)
expected true
     got nil
D, [2018-08-28T15:09:02.073210 #76075] DEBUG -- : #wait_for_server
    responds to message (FAILED - 2)

Here is the same spec, earlier, which was successful:

  client connected
D, [2018-08-28T14:41:39.113257 #75641] DEBUG -- : #start_server, waiting 10 second(s) to prevent Slack rate limiting
D, [2018-08-28T14:41:39.113425 #75641] DEBUG -- : client.on :closed, data=#<struct WebSocket::Driver::CloseEvent code=1000, reason="">
run_loop: event = #<struct WebSocket::Driver::CloseEvent code=1000, reason="">
I, [2018-08-28T14:41:49.115228 #75641]  INFO -- request: POST https://slack.com/api/rtm.start
D, [2018-08-28T14:41:49.115320 #75641] DEBUG -- request: Accept: "application/json; charset=utf-8"
User-Agent: "Slack Ruby Client/0.12.1"
Content-Type: "application/x-www-form-urlencoded"
I, [2018-08-28T14:41:49.541899 #75641]  INFO -- response: Status 200
D, [2018-08-28T14:41:49.542030 #75641] DEBUG -- response: content-type: "application/json; charset=utf-8"
content-length: "5611"
connection: "keep-alive"
date: "Tue, 28 Aug 2018 05:42:20 GMT"
server: "Apache"
x-slack-router: "p"
x-slack-req-id: "4b248fe4-f415-4b75-b1bf-b497ecc3ed8a"
x-oauth-scopes: "identify,read,post,client,apps,admin"
x-accepted-oauth-scopes: "rtm:stream,client"
expires: "Mon, 26 Jul 1997 05:00:00 GMT"
cache-control: "private, no-cache, no-store, must-revalidate"
pragma: "no-cache"
x-xss-protection: "0"
x-content-type-options: "nosniff"
x-slack-exp: "1"
x-slack-backend: "h"
referrer-policy: "no-referrer"
strict-transport-security: "max-age=31536000; includeSubDomains; preload"
vary: "Accept-Encoding"
access-control-allow-origin: "*"
x-via: "haproxy-www-zuny"
x-cache: "Miss from cloudfront"
via: "1.1 dc121c00d1bcafe610f6ef30199f8977.cloudfront.net (CloudFront)"
x-amz-cf-id: "-IUbo4qYLim6TFnbEQ5og48voG24aDYtsoPGai0tXwtNiUueYFqwQw=="
connect: connecting...
D, [2018-08-28T14:41:49.551256 #75641] DEBUG -- : connection is #<Thread:0x00007fcd8b998a30@/Users/samuel/Documents/socketry/slack-ruby-client/lib/slack/real_time/concurrency/async.rb:16 run>
connect: connected @driver = #<Slack::RealTime::Concurrency::Async::Client:0x00007fcd8b97d8c0>
D, [2018-08-28T14:41:49.587436 #75641] DEBUG -- Slack::RealTime::Concurrency::Async::Socket#connect!: Slack::RealTime::Concurrency::Async::Client
run_loop: registering callbacks on #<Slack::RealTime::Concurrency::Async::Client:0x00007fcd8b97d8c0>
run_loop: @driver = #<Slack::RealTime::Concurrency::Async::Client:0x00007fcd8b97d8c0>
D, [2018-08-28T14:41:49.597001 #75641] DEBUG -- : connection.on :open, data=#<struct WebSocket::Driver::OpenEvent>
D, [2018-08-28T14:41:49.597049 #75641] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::OpenEvent
run_loop: event = #<struct WebSocket::Driver::OpenEvent>
D, [2018-08-28T14:41:49.597209 #75641] DEBUG -- : chat_postMessage, channel=@samuel, message=0fba65e12b8d2b5a8ab548b624ba9bc4
I, [2018-08-28T14:41:49.600407 #75641]  INFO -- request: POST https://slack.com/api/chat.postMessage
D, [2018-08-28T14:41:49.600451 #75641] DEBUG -- request: Accept: "application/json; charset=utf-8"
User-Agent: "Slack Ruby Client/0.12.1"
Content-Type: "application/x-www-form-urlencoded"
I, [2018-08-28T14:41:49.858900 #75641]  INFO -- response: Status 200
D, [2018-08-28T14:41:49.859032 #75641] DEBUG -- response: content-type: "application/json; charset=utf-8"
content-length: "187"
connection: "keep-alive"
date: "Tue, 28 Aug 2018 05:42:21 GMT"
server: "Apache"
x-slack-router: "p"
x-slack-req-id: "38e04d4e-9e47-47f8-9c2e-0e38a0ccb47f"
x-oauth-scopes: "identify,read,post,client,apps,admin"
x-accepted-oauth-scopes: "chat:write:bot,post"
expires: "Mon, 26 Jul 1997 05:00:00 GMT"
cache-control: "private, no-cache, no-store, must-revalidate"
pragma: "no-cache"
x-xss-protection: "0"
x-content-type-options: "nosniff"
x-slack-exp: "1"
x-slack-backend: "h"
referrer-policy: "no-referrer"
strict-transport-security: "max-age=31536000; includeSubDomains; preload"
vary: "Accept-Encoding"
access-control-allow-origin: "*"
x-via: "haproxy-www-yntl"
x-cache: "Miss from cloudfront"
via: "1.1 c998ab49515e1eaeddaacbd7ea8013d0.cloudfront.net (CloudFront)"
x-amz-cf-id: "3jYjm70JcRHOoV9h1iRUJPxcIIVhZZc7f1r7UdJ-_HooPUJJPOteXg=="
D, [2018-08-28T14:41:49.859328 #75641] DEBUG -- : #wait_for_server
D, [2018-08-28T14:41:49.956828 #75641] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::MessageEvent, {"type": "hello"}
D, [2018-08-28T14:41:49.956975 #75641] DEBUG -- Slack::RealTime::Client#dispatch: type=hello
I, [2018-08-28T14:41:49.957047 #75641]  INFO -- : Successfully connected, welcome 'samuel' to the 'Orion Transfer' team at https://oriontransfer.slack.com.
run_loop: event = #<struct WebSocket::Driver::MessageEvent data="{\"type\": \"hello\"}">
D, [2018-08-28T14:41:49.957227 #75641] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::MessageEvent, {"text":"0fba65e12b8d2b5a8ab548b624ba9bc4","username":"Slack API Tester","bot_id":"BCFE5QREG","type":"message","subtype":"bot_message","team":"T6PMWBA74","channel":"D6PKQGYTV","event_ts":"1535434941.000100","ts":"1535434941.000100"}
D, [2018-08-28T14:41:49.957384 #75641] DEBUG -- Slack::RealTime::Client#dispatch: bot_id=BCFE5QREG, channel=D6PKQGYTV, event_ts=1535434941.000100, subtype=bot_message, team=T6PMWBA74, text=0fba65e12b8d2b5a8ab548b624ba9bc4, ts=1535434941.000100, type=message, username=Slack API Tester
D, [2018-08-28T14:41:49.957523 #75641] DEBUG -- : #<Slack::Messages::Message bot_id="BCFE5QREG" channel="D6PKQGYTV" event_ts="1535434941.000100" subtype="bot_message" team="T6PMWBA74" text="0fba65e12b8d2b5a8ab548b624ba9bc4" ts="1535434941.000100" type="message" username="Slack API Tester">
D, [2018-08-28T14:41:49.959263 #75641] DEBUG -- : client.stop!
run_loop: event = #<struct WebSocket::Driver::MessageEvent data="{\"text\":\"0fba65e12b8d2b5a8ab548b624ba9bc4\",\"username\":\"Slack API Tester\",\"bot_id\":\"BCFE5QREG\",\"type\":\"message\",\"subtype\":\"bot_message\",\"team\":\"T6PMWBA74\",\"channel\":\"D6PKQGYTV\",\"event_ts\":\"1535434941.000100\",\"ts\":\"1535434941.000100\"}">
D, [2018-08-28T14:41:49.970359 #75641] DEBUG -- Slack::RealTime::Client#run_loop: WebSocket::Driver::CloseEvent
run_loop: event = #<struct WebSocket::Driver::CloseEvent code=1000, reason="">
D, [2018-08-28T14:41:49.970531 #75641] DEBUG -- : #wait_for_server, joined
    responds to message

@ioquatix
Copy link
Contributor

I noticed the first event is different:

Failed

D, [2018-08-28T15:09:02.057295 #76075] DEBUG -- : client.on :close, data=#<struct WebSocket::Driver::CloseEvent code=1000, reason="">

Succeeded

D, [2018-08-28T14:41:39.113425 #75641] DEBUG -- : client.on :closed, data=#<struct WebSocket::Driver::CloseEvent code=1000, reason="">
run_loop: event = #<struct WebSocket::Driver::CloseEvent code=1000, reason="">
I, [2018-08-28T14:41:49.115228 #75641]  INFO -- request: POST https://slack.com/api/rtm.start
D, [2018-08-28T14:41:49.115320 #75641] DEBUG -- request: Accept: "application/json; charset=utf-8"

How can we get a closed event before the connection even started? Is there a race condition with previous spec? (it passed in both cases above).

@ioquatix
Copy link
Contributor

I think I see what's happening. The spec is flakey, but in a very odd way caused by threads.

  it 'gets close, followed by closed' do
    client.on :hello do |data|
      logger.debug "client.on :hello, data=#{data}"
      expect(client.started?).to be true
      client.stop!
    end

    client.on :close do |data|
      logger.debug "client.on :close, data=#{data}"
      expect(client.started?).to be true
      @close_called = true
    end

    client.on :closed do |data|
      logger.debug "client.on :closed, data=#{data}"
      expect(@close_called).to be true
    end

    start_server
  end

Here is my theory:

  • The spec gets close, followed by closed runs, but for whatever reason the thread is never terminated.

  • Another spec runs, e.g. in the case above, responds to message.

  • The original thread exits/terminates, and fails on expect(client.started?).to be true.

  • We can confirm this because the expectation that fails is not actually part of the spec that's being executed.

What do you think?

@ioquatix
Copy link
Contributor

I don't think this is a bug in the actual code, but a problem with how the spec is executing.

This class of bugs is avoided entirely by async, so perhaps the solution is to accept the buggy spec for 0.12.x, and the problem would be resolved in 0.13.x because threads wouldn't be used.

ioquatix referenced this issue in dblock/slack-ruby-client Aug 28, 2018
@ioquatix
Fix async implementation.
58c2980
@ioquatix
Copy link
Contributor

@dblock ping :)

dblock added a commit to dblock/slack-ruby-client that referenced this issue Aug 28, 2018
@dblock
Attempt at fixing slack-ruby#198, potential race condition.
b1b681a
@dblock
Copy link
Collaborator Author

dblock commented Aug 28, 2018

If this is a race condition we should be able to wait for the thread in wait_for_server, like so?

@ioquatix
Copy link
Contributor

I think that's the right fix. You should definitely call thread.join somewhere.

@ioquatix
Copy link
Contributor

Just FYI, that's why Async::Reactor.run(&block) works the way it does - the default is to ensure that tasks/resources don't escape the block.

dblock added a commit that referenced this issue Sep 8, 2018
@dblock
Undo fix for #198, doesn't work with faye-websocket.
5effe17
@dblock
Copy link
Collaborator Author

dblock commented Sep 8, 2018 •
edited
Loading

Had to revert the fix in 5effe17, needs changes for faye-websocket and celluloid.

  • ignore Celluloid::TaskTerminated
  • change how the reactor thread is managed in faye-websocket to return a thread from start_async; doesn't look trivial because it's blocking during at least one of the integration tests

@ioquatix
Copy link
Contributor

ioquatix commented Sep 8, 2018

I know it’s tricky but you definitely shouldn’t just leave threads hanging around.

@dblock
Copy link
Collaborator Author

dblock commented Sep 8, 2018

Yes @ioquatix, I'll fix it later.

@ioquatix
Copy link
Contributor

ioquatix commented Sep 8, 2018

I am travelling for the next week but will be happy to review the code after that.

@dblock dblock closed this as completed in c1fc8d7 Sep 8, 2018
dblock added a commit that referenced this issue Sep 8, 2018
@dblock
Merge pull request #224 from dblock/fix-198
1bfa20f 
Fix #198: Use a thread for Celluloid, shutdown EM.
@dblock dblock mentioned this issue Oct 31, 2018
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
confirmed bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ioquatix @dblock