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.

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

Issue with thread concurrency #515

Closed
catphish opened this issue Aug 15, 2017 · 6 comments
Closed

Issue with thread concurrency #515

catphish opened this issue Aug 15, 2017 · 6 comments

Comments

@catphish
Copy link

I am having an issue with thread concurrency resulting in the same types of errors that many people receive when using threads incorrectly and data gets out of order:

NoMethodError undefined method `queue' for #<AMQ::Protocol::Basic::ConsumeOk:0x007fe3d41efb08>
NoMethodError undefined method `consumer_tag' for #<AMQ::Protocol::Queue::DeleteOk:0x007fe3fa589068>

I see from previous issues that many others have had this issue when attempting to use the same channel across multiple threads, however my application only has a single thread, plus the threads that Bunny itself creates.

My specific issue seems to be that I am running subscribe in my main application thread at the same time as Bunny is running read_fully in its transport thread.

I don't know if I'm doing something I should not be from within a callback, or perhaps this is a bug. In either case any assistance would be appreciated. My complete code can be found at https://github.com/adamcooke/myxi/tree/master/lib/myxi

I hope the backtraces below provide the best possible information about this problem, but please let me know if there if anything else I can do to assist in debugging. Full backtrace of all threads at the time of the error:

I, [2017-08-15T15:28:44.613433 #13669]  INFO -- : NoMethodError undefined method `consumer_tag' for #<AMQ::Protocol::Queue::DeleteOk:0x007fe3fa589068>
I, [2017-08-15T15:28:44.613565 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/channel.rb:932:in `basic_consume_with'
I, [2017-08-15T15:28:44.613588 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/queue.rb:192:in `subscribe'
I, [2017-08-15T15:28:44.613617 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/session.rb:30:in `on_connect'
I, [2017-08-15T15:28:44.613639 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/session.rb:47:in `handle_r'
I, [2017-08-15T15:28:44.613658 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:70:in `block (2 levels) in run'
I, [2017-08-15T15:28:44.613678 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:68:in `select'
I, [2017-08-15T15:28:44.613699 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:68:in `block in run'
I, [2017-08-15T15:28:44.613722 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:60:in `loop'
I, [2017-08-15T15:28:44.613740 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:60:in `run'
I, [2017-08-15T15:28:44.613762 #13669]  INFO -- :   script/websocket_server.rb:23:in `<main>'

I, [2017-08-15T15:28:44.613878 #13669]  INFO -- :    =============== Begin Thread ===============
I, [2017-08-15T15:28:44.613915 #13669]  INFO -- : /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:50:in `sleep'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:50:in `block in run'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:47:in `loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:47:in `run'

I, [2017-08-15T15:28:44.613936 #13669]  INFO -- :    =============== Begin Thread ===============
I, [2017-08-15T15:28:44.613988 #13669]  INFO -- : /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/cruby/socket.rb:49:in `select'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/cruby/socket.rb:49:in `rescue in read_fully'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/cruby/socket.rb:40:in `read_fully'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/transport.rb:214:in `read_fully'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/transport.rb:236:in `read_next_frame'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:68:in `run_once'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:35:in `block in run_loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:32:in `loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:32:in `run_loop'

...and another one:

I, [2017-08-15T15:28:28.811947 #13669]  INFO -- : NoMethodError undefined method `queue' for #<AMQ::Protocol::Basic::ConsumeOk:0x007fe3d41efb08>
I, [2017-08-15T15:28:28.812017 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/queue.rb:371:in `declare!'
I, [2017-08-15T15:28:28.812037 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/queue.rb:51:in `initialize'
I, [2017-08-15T15:28:28.812054 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/channel.rb:410:in `new'
I, [2017-08-15T15:28:28.812071 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/channel.rb:410:in `queue'
I, [2017-08-15T15:28:28.812086 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/session.rb:29:in `on_connect'
I, [2017-08-15T15:28:28.812101 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/session.rb:47:in `handle_r'
I, [2017-08-15T15:28:28.812115 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:70:in `block (2 levels) in run'
I, [2017-08-15T15:28:28.812131 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:68:in `select'
I, [2017-08-15T15:28:28.812144 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:68:in `block in run'
I, [2017-08-15T15:28:28.812160 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:60:in `loop'
I, [2017-08-15T15:28:28.812251 #13669]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-3bf73acda157/lib/myxi/server.rb:60:in `run'
I, [2017-08-15T15:28:28.812271 #13669]  INFO -- :   script/websocket_server.rb:23:in `<main>'


I, [2017-08-15T15:28:28.812341 #13669]  INFO -- :    =============== Begin Thread ===============
I, [2017-08-15T15:28:28.812365 #13669]  INFO -- : /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:50:in `sleep'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:50:in `block in run'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:47:in `loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/heartbeat_sender.rb:47:in `run'

I, [2017-08-15T15:28:28.812380 #13669]  INFO -- :    =============== Begin Thread ===============
I, [2017-08-15T15:28:28.812410 #13669]  INFO -- : /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/cruby/socket.rb:49:in `select'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/cruby/socket.rb:49:in `rescue in read_fully'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/cruby/socket.rb:40:in `read_fully'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/transport.rb:214:in `read_fully'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/transport.rb:236:in `read_next_frame'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:68:in `run_once'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:35:in `block in run_loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:32:in `loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/reader_loop.rb:32:in `run_loop'

I, [2017-08-15T15:28:28.812427 #13669]  INFO -- :    =============== Begin Thread ===============
I, [2017-08-15T15:28:28.812453 #13669]  INFO -- : /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/consumer_work_pool.rb:94:in `pop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/consumer_work_pool.rb:94:in `block (2 levels) in run_loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/consumer_work_pool.rb:92:in `loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/consumer_work_pool.rb:92:in `block in run_loop'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/consumer_work_pool.rb:91:in `catch'
/opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/consumer_work_pool.rb:91:in `run_loop'

Thanks!

@michaelklishin
Copy link
Member

Please post questions to the mailing list in the future.

This seems to be a yet another case of #508, #386, #192, #188.

Each Bunny::Session runs an I/O loop in a separate thread. You can switch to the "single threaded mode" but a single digit % of users do. That thread continuously performs socket reads regardless of what your code does. That's entirely orthogonal to this issue.

If your code does not start threads that use Bunny channels per se, underlying servers, I/O libraries and so on can effectively create sharing. Channel continuations in Bunny are not that complicated and sequential for each channel.

In your specific case, Myxi.channel is shared mutable state. Should it ever be invoked from different threads by the underlying server or I/O library, you will run into "overlapping" continuations (method A is invoked, then before a response for A arrives B is invoked, then a response for A arrives and B's caller is confused and calls an unexpected method).

Either synchronise operations on Myxi.channel (it can be a group at a time, e.g. much of on_connect) or find a way to ensure it is never invoked concurrently, or each concurrent caller uses its own channel. One channel per operation is usually unnecessary and quite wasteful since it's a network round-trip but with some libraries there aren't many choices left.

@catphish
Copy link
Author

I believe this may be a duplicate of #462. Will ensure I am running latest version before reporting bugs next time 🙁

@michaelklishin
Copy link
Member

@catphish honestly I don't see how this is a duplicate of #462. You have shared mutable state which is a Bunny::Channel and your code seems to perform no synchronisation when setting up a queue/topology/consumer on said channel.

@catphish
Copy link
Author

catphish commented Aug 15, 2017

however my application only has a single thread, plus the threads that Bunny itself creates.

As I mentioned on my original post, my application is single threaded. Is it not correct that this this shared channel would only be an issue if multiple threads were to access it simultaneously? This should be impossible as I only have one thread.

I realise now that the title of this ticket is inappropriate and this may not be a thread related issue at all!

It is also worth noting that after further digging in my logs, I found this exception, which is what lead me to look at #462

I, [2017-08-15T09:31:21.467218 #20738]  INFO -- : Timeout::Error Timeout::Error
I, [2017-08-15T09:31:21.467303 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/concurrent/continuation_queue.rb:33:in `block in poll'
I, [2017-08-15T09:31:21.467323 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/concurrent/continuation_queue.rb:30:in `synchronize'
I, [2017-08-15T09:31:21.467337 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/concurrent/continuation_queue.rb:30:in `poll'
I, [2017-08-15T09:31:21.467350 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/channel.rb:1755:in `wait_on_continuations'
I, [2017-08-15T09:31:21.467364 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/channel.rb:1026:in `block in queue_delete'
I, [2017-08-15T09:31:21.467377 #20738]  INFO -- :   /usr/local/lib/ruby/2.3.0/timeout.rb:91:in `block in timeout'
I, [2017-08-15T09:31:21.467389 #20738]  INFO -- :   /usr/local/lib/ruby/2.3.0/timeout.rb:101:in `timeout'
I, [2017-08-15T09:31:21.467402 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/channel.rb:1025:in `queue_delete'
I, [2017-08-15T09:31:21.467415 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/gems/bunny-2.5.1/lib/bunny/queue.rb:295:in `delete'
I, [2017-08-15T09:31:21.467428 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/session.rb:183:in `close'
I, [2017-08-15T09:31:21.467441 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/session.rb:75:in `rescue in handle_r'
I, [2017-08-15T09:31:21.467454 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/session.rb:42:in `handle_r'
I, [2017-08-15T09:31:21.467467 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/server.rb:70:in `block (2 levels) in run'
I, [2017-08-15T09:31:21.467480 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/server.rb:68:in `select'
I, [2017-08-15T09:31:21.467492 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/server.rb:68:in `block in run'
I, [2017-08-15T09:31:21.467505 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/server.rb:60:in `loop'
I, [2017-08-15T09:31:21.467518 #20738]  INFO -- :   /opt/apps/deploy/shared/bundle/ruby/2.3.0/bundler/gems/myxi-ad48622a0ffa/lib/myxi/server.rb:60:in `run'
I, [2017-08-15T09:31:21.467531 #20738]  INFO -- :   script/websocket_server.rb:23:in `<main>'

@michaelklishin
Copy link
Member

I explained above that your code may or may not start threads but you rely on HTTP servers and I/O libraries that might. This kind of issues is usually reported by Puma users. I have been answering it for years now. Try printing current thread ID, for example.

Your other log does look like #462 but in a different place in your code (the line does not match what's in master but there's only one Bunny::Queue#delete call site in that method),
so quite likely it's a red herring.

@michaelklishin
Copy link
Member

I do not appreciate when GitHub issues are used for discussions and speculations plus I believe this is answered in enough detail for the OP to take it from here => locking.

@ruby-amqp ruby-amqp locked and limited conversation to collaborators Aug 16, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

2 participants