Intermittent errors (thread tried to join itself) #9

Closed
AMHOL opened this Issue Sep 10, 2013 · 12 comments

Projects

None yet

3 participants

@AMHOL

I am consuming an API and have made use of the 'promise' library to make concurrent API calls with a lower impact on the code than a roll-my-own solution, however, intermittently I get the following error:

"thread 0x94fb000 tried to join itself"

From what I have read about it (https://www.ruby-forum.com/topic/209491) it seems that it will not be a problem once config.cache_classes is set to true, however, that would give me a hard time developing the application, of course I can test a development environment with cache_classes enabled, but ideally it would be good to get this problem resolved, I can't get to the bottom of what's causing it.

I'm using Ruby 1.8.7 (don't ask), Rails 3.2.13 and future mostly wraps responses from Savon (2.2.0)

@bhuga
Owner

I would need a full stack trace to have a shot at figuring this out. I could imagine this happening if a future referenced itself while resolving.

@AMHOL

promise (0.3.0) lib/future.rb:34:in join'
promise (0.3.0) lib/future.rb:34:in
join'
promise (0.3.0) lib/future.rb:34:in __force__'
promise (0.3.0) lib/promise.rb:89:in
method_missing'
app/views/layouts/_job_tree.html.slim:2:in _app_views_layouts__job_tree_html_slim__486827935_77537136'
actionpack (3.2.13) lib/action_view/template.rb:145:in
send'
actionpack (3.2.13) lib/action_view/template.rb:145:in render'
activesupport (3.2.13) lib/active_support/notifications.rb:125:in
instrument'
actionpack (3.2.13) lib/action_view/template.rb:143:in render'
actionpack (3.2.13) lib/action_view/renderer/partial_renderer.rb:265:in
render_partial'
actionpack (3.2.13) lib/action_view/renderer/partial_renderer.rb:238:in render'
actionpack (3.2.13) lib/action_view/renderer/abstract_renderer.rb:38:in
instrument'
activesupport (3.2.13) lib/active_support/notifications.rb:123:in instrument'
activesupport (3.2.13) lib/active_support/notifications/instrumenter.rb:20:in
instrument'
activesupport (3.2.13) lib/active_support/notifications.rb:123:in instrument'
actionpack (3.2.13) lib/action_view/renderer/abstract_renderer.rb:38:in
instrument'
actionpack (3.2.13) lib/action_view/renderer/partial_renderer.rb:237:in render'
actionpack (3.2.13) lib/action_view/renderer/renderer.rb:41:in
render_partial'
actionpack (3.2.13) lib/action_view/helpers/rendering_helper.rb:27:in render'
app/views/layouts/_two-column.slim:19:in
_app_views_layouts__two_column_slim__540420294_77735592'
actionpack (3.2.13) lib/action_view/template.rb:145:in send'
actionpack (3.2.13) lib/action_view/template.rb:145:in
render'
activesupport (3.2.13) lib/active_support/notifications.rb:125:in instrument'
actionpack (3.2.13) lib/action_view/template.rb:143:in
render'
actionpack (3.2.13) lib/action_view/renderer/partial_renderer.rb:265:in render_partial'
actionpack (3.2.13) lib/action_view/renderer/partial_renderer.rb:238:in
render'
actionpack (3.2.13) lib/action_view/renderer/abstract_renderer.rb:38:in instrument'
activesupport (3.2.13) lib/active_support/notifications.rb:123:in
instrument'
activesupport (3.2.13) lib/active_support/notifications/instrumenter.rb:20:in instrument'
activesupport (3.2.13) lib/active_support/notifications.rb:123:in
instrument'
actionpack (3.2.13) lib/action_view/renderer/abstract_renderer.rb:38:in instrument'
actionpack (3.2.13) lib/action_view/renderer/partial_renderer.rb:237:in
render'
actionpack (3.2.13) lib/action_view/renderer/renderer.rb:41:in render_partial'
actionpack (3.2.13) lib/action_view/helpers/rendering_helper.rb:27:in
render'
app/views/layouts/application.html.slim:12:in _app_views_layouts_application_html_slim__188727106_76743816'
actionpack (3.2.13) lib/action_view/template.rb:145:in
send'
actionpack (3.2.13) lib/action_view/template.rb:145:in render'
activesupport (3.2.13) lib/active_support/notifications.rb:125:in
instrument'
actionpack (3.2.13) lib/action_view/template.rb:143:in render'
actionpack (3.2.13) lib/action_view/renderer/template_renderer.rb:59:in
render_with_layout'
actionpack (3.2.13) lib/action_view/renderer/template_renderer.rb:45:in render_template'
actionpack (3.2.13) lib/action_view/renderer/template_renderer.rb:18:in
render'
actionpack (3.2.13) lib/action_view/renderer/renderer.rb:36:in render_template'
actionpack (3.2.13) lib/action_view/renderer/renderer.rb:17:in
render'
actionpack (3.2.13) lib/abstract_controller/rendering.rb:110:in _render_template'
actionpack (3.2.13) lib/action_controller/metal/streaming.rb:225:in
_render_template'
actionpack (3.2.13) lib/abstract_controller/rendering.rb:103:in render_to_body'
actionpack (3.2.13) lib/action_controller/metal/renderers.rb:28:in
render_to_body'
actionpack (3.2.13) lib/action_controller/metal/compatibility.rb:50:in render_to_body'
actionpack (3.2.13) lib/abstract_controller/rendering.rb:88:in
render'
actionpack (3.2.13) lib/action_controller/metal/rendering.rb:16:in render'
actionpack (3.2.13) lib/action_controller/metal/instrumentation.rb:40:in
render'
activesupport (3.2.13) lib/active_support/core_ext/benchmark.rb:5:in ms'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/benchmark.rb:308:in
realtime'
activesupport (3.2.13) lib/active_support/core_ext/benchmark.rb:5:in ms'
actionpack (3.2.13) lib/action_controller/metal/instrumentation.rb:40:in
render'
actionpack (3.2.13) lib/action_controller/metal/instrumentation.rb:83:in cleanup_view_runtime'
actionpack (3.2.13) lib/action_controller/metal/instrumentation.rb:39:in
render'
actionpack (3.2.13) lib/action_controller/metal/implicit_render.rb:10:in default_render'
actionpack (3.2.13) lib/action_controller/metal/implicit_render.rb:5:in
send_action'
actionpack (3.2.13) lib/abstract_controller/base.rb:167:in process_action'
actionpack (3.2.13) lib/action_controller/metal/rendering.rb:10:in
process_action'
actionpack (3.2.13) lib/abstract_controller/callbacks.rb:18:in process_action'
activesupport (3.2.13) lib/active_support/callbacks.rb:469:in
_run__718587544__process_action__155074602__callbacks'
activesupport (3.2.13) lib/active_support/callbacks.rb:405:in send'
activesupport (3.2.13) lib/active_support/callbacks.rb:405:in
__run_callback'
activesupport (3.2.13) lib/active_support/callbacks.rb:385:in _run_process_action_callbacks'
activesupport (3.2.13) lib/active_support/callbacks.rb:81:in
send'
activesupport (3.2.13) lib/active_support/callbacks.rb:81:in run_callbacks'
actionpack (3.2.13) lib/abstract_controller/callbacks.rb:17:in
process_action'
actionpack (3.2.13) lib/action_controller/metal/rescue.rb:29:in process_action'
actionpack (3.2.13) lib/action_controller/metal/instrumentation.rb:30:in
process_action'
activesupport (3.2.13) lib/active_support/notifications.rb:123:in instrument'
activesupport (3.2.13) lib/active_support/notifications/instrumenter.rb:20:in
instrument'
activesupport (3.2.13) lib/active_support/notifications.rb:123:in instrument'
actionpack (3.2.13) lib/action_controller/metal/instrumentation.rb:29:in
process_action'
actionpack (3.2.13) lib/action_controller/metal/params_wrapper.rb:207:in process_action'
actionpack (3.2.13) lib/abstract_controller/base.rb:121:in
process'
actionpack (3.2.13) lib/abstract_controller/rendering.rb:45:in process'
actionpack (3.2.13) lib/action_controller/metal.rb:203:in
dispatch'
actionpack (3.2.13) lib/action_controller/metal/rack_delegation.rb:14:in dispatch'
actionpack (3.2.13) lib/action_controller/metal.rb:246:in
action'
actionpack (3.2.13) lib/action_dispatch/routing/route_set.rb:73:in call'
actionpack (3.2.13) lib/action_dispatch/routing/route_set.rb:73:in
dispatch'
actionpack (3.2.13) lib/action_dispatch/routing/route_set.rb:36:in call'
journey (1.0.4) lib/journey/router.rb:68:in
call'
journey (1.0.4) lib/journey/router.rb:56:in each'
journey (1.0.4) lib/journey/router.rb:56:in
call'
actionpack (3.2.13) lib/action_dispatch/routing/route_set.rb:612:in call'
actionpack (3.2.13) lib/action_dispatch/middleware/best_standards_support.rb:17:in
call'
rack (1.4.5) lib/rack/etag.rb:23:in call'
rack (1.4.5) lib/rack/conditionalget.rb:25:in
call'
actionpack (3.2.13) lib/action_dispatch/middleware/head.rb:14:in call'
actionpack (3.2.13) lib/action_dispatch/middleware/params_parser.rb:21:in
call'
actionpack (3.2.13) lib/action_dispatch/middleware/flash.rb:242:in call'
rack (1.4.5) lib/rack/session/abstract/id.rb:210:in
context'
rack (1.4.5) lib/rack/session/abstract/id.rb:205:in call'
actionpack (3.2.13) lib/action_dispatch/middleware/cookies.rb:341:in
call'
actionpack (3.2.13) lib/action_dispatch/middleware/callbacks.rb:28:in call'
activesupport (3.2.13) lib/active_support/callbacks.rb:405:in
_run__397314981__call__4__callbacks'
activesupport (3.2.13) lib/active_support/callbacks.rb:405:in send'
activesupport (3.2.13) lib/active_support/callbacks.rb:405:in
__run_callback'
activesupport (3.2.13) lib/active_support/callbacks.rb:385:in _run_call_callbacks'
activesupport (3.2.13) lib/active_support/callbacks.rb:81:in
send'
activesupport (3.2.13) lib/active_support/callbacks.rb:81:in run_callbacks'
actionpack (3.2.13) lib/action_dispatch/middleware/callbacks.rb:27:in
call'
actionpack (3.2.13) lib/action_dispatch/middleware/reloader.rb:65:in call'
actionpack (3.2.13) lib/action_dispatch/middleware/remote_ip.rb:31:in
call'
actionpack (3.2.13) lib/action_dispatch/middleware/debug_exceptions.rb:16:in call'
actionpack (3.2.13) lib/action_dispatch/middleware/show_exceptions.rb:56:in
call'
railties (3.2.13) lib/rails/rack/logger.rb:32:in call_app'
railties (3.2.13) lib/rails/rack/logger.rb:16:in
call'
activesupport (3.2.13) lib/active_support/tagged_logging.rb:22:in tagged'
railties (3.2.13) lib/rails/rack/logger.rb:16:in
call'
actionpack (3.2.13) lib/action_dispatch/middleware/request_id.rb:22:in call'
rack (1.4.5) lib/rack/methodoverride.rb:21:in
call'
rack (1.4.5) lib/rack/runtime.rb:17:in call'
activesupport (3.2.13) lib/active_support/cache/strategy/local_cache.rb:72:in
call'
rack (1.4.5) lib/rack/lock.rb:15:in call'
actionpack (3.2.13) lib/action_dispatch/middleware/static.rb:63:in
call'
railties (3.2.13) lib/rails/engine.rb:479:in call'
railties (3.2.13) lib/rails/application.rb:223:in
call'
rack (1.4.5) lib/rack/content_length.rb:14:in call'
railties (3.2.13) lib/rails/rack/log_tailer.rb:17:in
call'
rack (1.4.5) lib/rack/handler/webrick.rb:59:in service'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/httpserver.rb:104:in
service'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/httpserver.rb:65:in run'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:173:in
start_thread'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:162:in start'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:162:in
start_thread'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:95:in start'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:92:in
each'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:92:in start'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:23:in
start'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:82:in start'
rack (1.4.5) lib/rack/handler/webrick.rb:13:in
run'
rack (1.4.5) lib/rack/server.rb:268:in start'
railties (3.2.13) lib/rails/commands/server.rb:70:in
start'
railties (3.2.13) lib/rails/commands.rb:55
railties (3.2.13) lib/rails/commands.rb:50:in tap'
railties (3.2.13) lib/rails/commands.rb:50
script/rails:6:in
require'
script/rails:6

You can see that the last application file in the stack trace is app/views/layouts/_job_tree.html.slim(2), which is called from app/views/layouts/_two-column.html.slim(19), the code is as follows:

app/views/layouts/_two-column.html.slim(19)

  = render 'layouts/job_tree', :developments => @user.developments

app/views/layouts/_job_tree.html.slim(2)

  - developments.each do |development|

@user.developments contains the future instance, wrapping a collection of instances from a parsed Savon response.

@bhuga
Owner

Does this happen on master, or just the released version?

@AMHOL

Sorry, forgot to mention, I'm using version 0.3.0 (http://rubygems.org/gems/promise/versions/0.3.0)

@AMHOL

I have updated my local gem code to the master branch, I haven't had the error so far, if it continues successfully I will have to pull the gem from the master branch in my Gemfile.

Thanks for the help.

@philipmw
Collaborator

Hi, @AMHOL. Thanks for reporting this problem; my team ran into the same thing, and your bug report was helpful.

Ben just made a new release (0.3.1) which should fix your problem. My team and I traced this problem to a race condition in the Future class, between its constructor and its force method. That code was changed in 0.3.1 and, at least from visual inspection, shouldn't have that problem anymore.

@philipmw philipmw closed this Dec 23, 2014
@AMHOL

Thanks @philipmw, don't suppose you have a link to the relevant commit? Would be interested in seeing the fix

@philipmw
Collaborator

@AMHOL:

I can't find the commit; for some reason Github's commit log does not show some commits. So let's look at the files themselves.
File from release 0.3.0: https://github.com/bhuga/promising-future/blob/0.3.0/lib/future.rb
File from release 0.3.1: https://github.com/bhuga/promising-future/blob/0.3.1/lib/future.rb

In 0.3.0 version, the Future constructor (#initialize) spins up a thread, so we have two timelines, as follows. Time flows downward.

Original thread Future worker thread
::Thread.new { __force__ } (doesn't exist yet)
(sleeping) check: (@thread == ::Thread.current) from line 34; it is false
assign thread to @thread (sleeping)
(sleeping) check: @thread.equal?(NOT_SET) from line 34; it is false
(sleeping) @thread.join (exception occurs)

This is a race condition made possible by the fact that one thread writes to @thread in parallel with the other thread reading the same variable. The symptom occurs only when the original thread assigns to @thread in-between the worker thread checking the two parts of the conditional on line 34.

Now compare the same file in 0.3.1 release. The worker thread no longer calls __force__ on itself; instead it calls that method on its @promise. The worker thread no longer shares data with the original thread, which should eliminate the potential for race conditions.

P.S. If you can figure out why Github's commit log doesn't show the relevant diff, and explain it to me, I'd appreciate it. It's disturbing that I couldn't find which commit changed this behavior.

@bhuga
Owner

P.S. If you can figure out why Github's commit log doesn't show the relevant diff, and explain it to me, I'd appreciate it. It's disturbing that I couldn't find which commit changed this behavior.

This is incredibly embarrassing, but the reason for it is that the commits simply aren't in master. You'll find them here:

https://github.com/bhuga/promising-future/commits/0.3.0

But not here:

https://github.com/bhuga/promising-future/commits/0.3.1

This is 4 and a half years ago and probably 3 computers for me, so I couldn't possibly recreate the working copy that led to this condition. But we should probably fix it or 3.1 will have been a regression.

@philipmw
Collaborator

Gotcha. Well, the commit that introduced the problem is only on 0.3.0: c95f40f
So, the regression did occur for 0.3.1, but it fixed the problem. :-)

The 0.3.0-only commits:

  1. c95f40f <- the one introducing the bug, but did change the interface.
  2. a9c9ec5 <- internal refactoring of #1
  3. d6b4dc5 <- commenting a change made in #1

So we went from a "Future owns-a Promise" design to "Future is-a Promise". Do you still feel that this needs to be done? Can you explain the benefit? (Maybe you'll re-submit this as a PR and we could move this discussion there?)

@bhuga
Owner

Do you still feel that this needs to be done? Can you explain the benefit?

No and no. Lost to the sands of time. 0.3.0 is dead, long live 0.3.1!

@AMHOL

Thanks for the explanation @philipmw

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment