Race condition fix #1032

deivid-rodriguez · 2019-09-15T12:53:30Z

While testing activeadmin, our parallel test suite run into the following error:

bin/rspec --color --tty -O .rspec_parallel spec/requests/stylesheets_spec.rb spec/unit/active_admin_spec.rb spec/unit/batch_actions/settings_spec.rb spec/unit/controller_filters_spec.rb spec/unit/devise_spec.rb spec/unit/helpers/scope_chain_spec.rb spec/unit/localizers/resource_localizer_spec.rb spec/unit/menu_spec.rb spec/unit/namespace_spec.rb spec/unit/page_controller_spec.rb spec/unit/page_spec.rb spec/unit/pundit_adapter_spec.rb spec/unit/resource/naming_spec.rb spec/unit/resource/page_presenters_spec.rb spec/unit/resource/routes_spec.rb spec/unit/resource_registration_spec.rb spec/unit/routing_spec.rb spec/unit/scope_spec.rb spec/unit/view_helpers/download_format_links_helper_spec.rb spec/unit/views/components/index_table_for_spec.rb spec/unit/views/components/menu_item_spec.rb spec/unit/views/components/paginated_collection_spec.rb spec/unit/views/components/panel_spec.rb spec/unit/views/components/table_for_spec.rb spec/unit/views/components/unsupported_browser_spec.rb spec/unit/views/pages/base_spec.rb 2>&1
Run options:
  include {:focus=>true}
  exclude {:changes_filesystem=>true}

All examples were filtered out; ignoring {:focus=>true}

Randomized with seed 28908
F..............................................................................................................................................................................................................................................................................................................................

Failures:

  1) Registering an object to administer when being registered multiple times should run the dsl in the same config object
     Failure/Error: Unable to find org/jruby/RubyDir.java to read failed line
     
     Errno::EEXIST:
       File exists - db
     # org/jruby/RubyDir.java:590:in `mkdir'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-jdbc-adapter-50.4-java/lib/arjdbc/sqlite3/connection_methods.rb:55:in `parse_sqlite3_config!'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-jdbc-adapter-50.4-java/lib/arjdbc/sqlite3/connection_methods.rb:17:in `sqlite3_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:729:in `new_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:773:in `checkout_new_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:752:in `try_to_checkout_new_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:713:in `acquire_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:490:in `checkout'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:364:in `connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:883:in `retrieve_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_handling.rb:128:in `retrieve_connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/connection_handling.rb:91:in `connection'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/fixtures.rb:516:in `create_fixtures'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/fixtures.rb:1015:in `load_fixtures'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/fixtures.rb:977:in `setup_fixtures'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/activerecord-5.0.7.2/lib/active_record/fixtures.rb:852:in `before_setup'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-rails-3.8.2/lib/rspec/rails/adapters.rb:126:in `block in MinitestLifecycleAdapter'
     # org/jruby/RubyBasicObject.java:2680:in `instance_exec'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example.rb:450:in `instance_exec'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/hooks.rb:373:in `execute_with'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/hooks.rb:606:in `block in run_around_example_hooks_for'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example.rb:345:in `call'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/hooks.rb:605:in `run_around_example_hooks_for'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/hooks.rb:464:in `run'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example.rb:460:in `with_around_example_hooks'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example.rb:503:in `with_around_and_singleton_context_hooks'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example.rb:254:in `run'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example_group.rb:633:in `block in run_examples'
     # org/jruby/RubyArray.java:2584:in `map'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example_group.rb:629:in `run_examples'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example_group.rb:595:in `run'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example_group.rb:596:in `block in run'
     # org/jruby/RubyArray.java:2584:in `map'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/example_group.rb:596:in `run'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:116:in `block in run_specs'
     # org/jruby/RubyArray.java:2584:in `map'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:116:in `block in run_specs'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/configuration.rb:2008:in `with_suite_hooks'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:111:in `block in run_specs'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/reporter.rb:74:in `report'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:110:in `run_specs'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:87:in `run'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:71:in `run'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/lib/rspec/core/runner.rb:45:in `invoke'
     # /root/project/vendor/bundle/jruby/2.5.0/gems/rspec-core-3.8.2/exe/rspec:4:in `<main>'
     # org/jruby/RubyKernel.java:1022:in `load'
     # bin/rspec:1:in `<main>'
     # 
     #   Showing full backtrace because every line was filtered out.
     #   See docs for RSpec::Configuration#backtrace_exclusion_patterns and
     #   RSpec::Configuration#backtrace_inclusion_patterns for more information.

Finished in 42.84 seconds (files took 11.27 seconds to load)
319 examples, 1 failure

Failed examples:

rspec ./spec/unit/resource_registration_spec.rb:53 # Registering an object to administer when being registered multiple times should run the dsl in the same config object

Randomized with seed 28908

Coverage report generated for regular specs 2, regular specs 3 to /root/project/coverage. 6758 / 7559 LOC (89.4%) covered.
SimpleCov failed with exit 1

As I understand it, this is a race condition where two threads would check File.directory?(dirname) and both get a negative answer because the directory does not yet exist, and then both try to create the directory, causing the last thread to crash.

This PR attempts to fix the error by rescuing the potential exception caused by the race condition.

kares · 2019-09-16T10:15:19Z

fine with this, since this isn't a hot path (in a production run) we'd like to avoid exception raising.
any objections @enebo ?

@deivid-rodriguez you might want to target 50-stable if you'd like this in next 50.x 51.x 52.x releases

enebo · 2019-09-16T15:25:28Z

@kares I don't have any objection in the sense this probably is not super common and will only pay a penalty in those particular circumstances. Otherwise we will need to lock access and I feel like that will be a higher per use penalty.

I guess if this is really common then perhaps we do something else? Is it though?

kares · 2019-09-16T15:36:02Z

I guess if this is really common then perhaps we do something else? Is it though?

pbly not - the reported use-case is pretty much artificial ... its a test-case run

enebo · 2019-09-16T15:52:46Z

@kares yeah then we won't sweat it until we see -Xlog.exceptions and notice it is happening too much :)

deivid-rodriguez · 2019-09-16T16:10:03Z

Yeah, if I understood the error correctly, this is happening when creating the db folder, so this code path should probably just be hit once for the whole life time of a production application.

deivid-rodriguez · 2019-09-16T16:11:24Z

@deivid-rodriguez you might want to target 50-stable if you'd like this in next 50.x 51.x 52.x releases

Sure, yeah. Activeadmin currently supports all of those, so ideally we would want the change backported to all stable branches. I just wanted to start with master to agree on what the best fix is for this, then I can open backports 👍.

deivid-rodriguez · 2019-09-16T16:54:44Z

Yeah, if I understood the error correctly, this is happening when creating the db folder, so this code path should probably just be hit once for the whole life time of a production application.

Actually, this is the connection method so I guess this happens once every time we connect to the DB? What I don't understand is that in our specs this folder should've already been created by the time the exception happened. So, I don't understand how this happened.

deivid-rodriguez · 2019-10-03T11:34:00Z

I got this error again and dug in a bit more but I'm still very confused.

The backtrace is now slightly different since now it shows an absolute path in the error message:

Errno::EEXIST:

  File exists - /root/project/db

  (...)

From reading the surrounding code, it sounds like Rails.root is not yet defined at that point, that's why it tries to read a configuration from the current directory instead of from the actual Rails root (the test application at /root/project/tmp/test_apps/rails_50).

But since RSpec first loads all tests files before trying to run them and I'm requiring rails_helper on top of all of them, and that initializes the test application, I don't understand how that would happen.

deivid-rodriguez · 2019-11-27T17:00:41Z

I never experienced this again, and I don't like this "solution" anyways, so closing!

deivid-rodriguez mentioned this pull request Sep 15, 2019

Try potential fix for jruby hangs activeadmin/activeadmin#5858

Merged

Race condition fix

1b54c53

deivid-rodriguez force-pushed the race_condition branch from 4a27286 to 1b54c53 Compare September 16, 2019 21:08

deivid-rodriguez closed this Nov 27, 2019

deivid-rodriguez deleted the race_condition branch November 27, 2019 17:00

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Race condition fix #1032

Race condition fix #1032

deivid-rodriguez commented Sep 15, 2019

kares commented Sep 16, 2019

enebo commented Sep 16, 2019

kares commented Sep 16, 2019 •

edited

Loading

enebo commented Sep 16, 2019

deivid-rodriguez commented Sep 16, 2019

deivid-rodriguez commented Sep 16, 2019

deivid-rodriguez commented Sep 16, 2019

deivid-rodriguez commented Oct 3, 2019

deivid-rodriguez commented Nov 27, 2019

Race condition fix #1032

Race condition fix #1032

Conversation

deivid-rodriguez commented Sep 15, 2019

kares commented Sep 16, 2019

enebo commented Sep 16, 2019

kares commented Sep 16, 2019 • edited Loading

enebo commented Sep 16, 2019

deivid-rodriguez commented Sep 16, 2019

deivid-rodriguez commented Sep 16, 2019

deivid-rodriguez commented Sep 16, 2019

deivid-rodriguez commented Oct 3, 2019

deivid-rodriguez commented Nov 27, 2019

kares commented Sep 16, 2019 •

edited

Loading