jruby / activerecord-jdbc-adapter

JRuby's ActiveRecord adapter using JDBC.
BSD 2-Clause "Simplified" License
461 stars 385 forks source link

Race condition fix #1032

Closed deivid-rodriguez closed 5 years ago

deivid-rodriguez commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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 commented 5 years ago

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

deivid-rodriguez commented 5 years ago

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 commented 5 years ago

@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 :+1:.

deivid-rodriguez commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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