search

kubo / ruby-oci8

Ruby-oci8 - Oracle interface for ruby
Other
169 stars 78 forks source link

'executing in another thread' randomly occurs when running feature tests #216

Closed morszczuk closed 5 years ago

morszczuk commented 5 years ago

Dear Kubo,

In our project, we are experiencing randomly occurring 'executing in another thread' error. It shows up in the feature tests (run with the usage of Capybara) and is more likely to happen when there are many interactions with the database at the same time. I know we are using older version of the gem - we are working on moving to the newer versions of rails and oci8 gem. But before that happens, do you think you can give some tips what can cause our problems?

The stackrace of error ends at the execution of the native extension functions. I tried to debug C code and apparently 'executing in another thread' error comes from oci8_call_without_gvl function (in ext/oci8lib.c file). What can be the reason of this error?

Ruby version: 2.3.1p112 (2016-04-26 revision 54768) [x86_64-linux]

Rails version: 4.2.11.1

ruby-oci8lib gem version: 2.1.7

Database version: Oracle 12c

Error:

bundle exec m ./test/features/feature_landing_page_test.rb

Minitest::Result#test_save_maximal_with_js:
ActiveRecord::StatementInvalid: RuntimeError: executing in another thread 2: ROLLBACK TO active_record_1
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/cursor.rb:28:in `__initialize'
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/cursor.rb:28:in `initialize'
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/oci8.rb:177:in `new'
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/oci8.rb:177:in `parse_internal'
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/oci8.rb:170:in `parse'
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/oci8.rb:277:in `exec_internal'
/home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/ruby-oci8-2.1.7/lib/oci8/oci8.rb:269:in `exec'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-oracle_enhanced-adapter-1.6.9/lib/active_record/connection_adapters/oracle_enhanced/oci_connection.rb:437:in `exec'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-oracle_enhanced-adapter-1.6.9/lib/active_record/connection_adapters/oracle_enhanced/oci_connection.rb:92:in `exec'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-oracle_enhanced-adapter-1.6.9/lib/active_record/connection_adapters/oracle_enhanced/database_statements.rb:11:in `block in execute'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract_adapter.rb:484:in `block in log'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-4.2.11.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract_adapter.rb:478:in `log'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/rack-mini-profiler-0.9.3/lib/patches/db/activerecord.rb:17:in `log_with_miniprofiler'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-oracle_enhanced-adapter-1.6.9/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb:1353:in `log'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-oracle_enhanced-adapter-1.6.9/lib/active_record/connection_adapters/oracle_enhanced/database_statements.rb:11:in `execute'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-oracle_enhanced-adapter-1.6.9/lib/active_record/connection_adapters/oracle_enhanced/database_statements.rb:222:in `exec_rollback_to_savepoint'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/database_statements.rb:272:in `rollback_to_savepoint'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/query_cache.rb:14:in `rollback_to_savepoint'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/transaction.rb:118:in `rollback'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/transaction.rb:179:in `rollback_transaction'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/transaction.rb:186:in `rescue in within_new_transaction'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/transaction.rb:201:in `within_new_transaction'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/test_after_commit-0.4.1/lib/test_after_commit.rb:9:in `transaction_with_transactional_fixtures'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/transactions.rb:220:in `transaction'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activerecord-4.2.11.1/lib/active_record/transactions.rb:291:in `save!'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/evaluation.rb:18:in `create'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy/create.rb:12:in `block in result'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy/create.rb:9:in `tap'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy/create.rb:9:in `result'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/factory.rb:43:in `run'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/factory_runner.rb:29:in `block in run'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/activesupport-4.2.11.1/lib/active_support/notifications.rb:166:in `instrument'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/factory_runner.rb:28:in `run'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy_syntax_method_registrar.rb:20:in `block in define_singular_strategy_method'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy_syntax_method_registrar.rb:32:in `block (2 levels) in define_list_strategy_method'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy_syntax_method_registrar.rb:32:in `initialize'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy_syntax_method_registrar.rb:32:in `new'
    /home/vagrant/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/factory_bot-5.0.2/lib/factory_bot/strategy_syntax_method_registrar.rb:32:in `block in define_list_strategy_method'
    /opt/www/apps/cms-editor/test/support/factory_builder_helper.rb:10:in `create_published_content_items'
    /opt/www/apps/cms-editor/test/features/feature_landing_page_test.rb:431:in `prepare_published_content_items'
    /opt/www/apps/cms-editor/test/features/feature_landing_page_test.rb:109:in `test_save_maximal_with_js'

Gem versions:

bundle show:
  * aasm (4.11.1)
  * actionmailer (4.2.11.1)
  * actionpack (4.2.11.1)
  * actionview (4.2.11.1)
  * active_model-errors_details (1.3.1)
  * activejob (4.2.11.1)
  * activemodel (4.2.11.1)
  * activerecord (4.2.11.1)
  * activerecord-oracle_enhanced-adapter (1.6.9)
  * activesupport (4.2.11.1)
  * addressable (2.5.0)
  * ansi (1.5.0)
  * arel (6.0.4)
  * ast (2.0.0)
  * astrolabe (1.3.0)
  * awesome_print (1.6.1)
  * brakeman (3.0.1)
  * builder (3.2.3)
  * bundler (2.0.1)
  * byebug (3.5.1)
  * capybara (2.13.0)
  * capybara-webkit (1.14.0)
  * carrierwave (0.10.0)
  * childprocess (0.5.5)
  * coderay (1.1.2)
  * coffee-rails (4.1.0)
  * coffee-script (2.3.0)
  * coffee-script-source (1.9.1)
  * columnize (0.9.0)
  * concurrent-ruby (1.1.5)
  * crass (1.0.4)
  * daemons (1.2.4)
  * date_validator (0.8.0)
  * debugger-linecache (1.2.0)
  * delayed_job (4.1.3)
  * delayed_job_active_record (4.1.2)
  * delayed_job_web (1.4)
  * docile (1.1.5)
  * erubis (2.7.0)
  * execjs (2.6.0)
  * factory_bot (5.0.2)
  * factory_bot_rails (5.0.2)
  * faker (1.9.3)
  * fast_stack (0.1.0)
  * fastercsv (1.5.5)
  * ffi (1.9.8)
  * flamegraph (0.1.0)
  * globalid (0.4.2)
  * haml (4.0.6)
  * highline (1.6.21)
  * i18n (0.9.5)
  * jbuilder (2.2.8)
  * jquery-rails (4.0.5)
  * json (1.8.6)
  * kaminari (0.16.3)
  * kgio (2.9.3)
  * lograge (0.3.3)
  * loofah (2.2.3)
  * m (1.5.1)
  * mail (2.7.1)
  * method_source (0.9.0)
  * mime-types (3.2.2)
  * mime-types-data (3.2018.0812)
  * mina (0.3.1)
  * mina-unicorn (0.0.3)
  * mini_mime (1.0.1)
  * mini_portile2 (2.4.0)
  * minitest (5.11.3)
  * minitest-capybara (0.7.1)
  * minitest-metadata (0.5.3)
  * minitest-rails (2.1.1)
  * minitest-rails-capybara (2.1.1)
  * minitest-reporters (1.0.11)
  * minitest-stub_any_instance (1.0.1)
  * monetize (1.9.0)
  * money (6.13.1)
  * money-rails (1.13.0)
  * multi_json (1.11.2)
  * net-ldap (0.9.0)
  * nokogiri (1.10.1)
  * open4 (1.3.4)
  * paper_trail (4.2.0)
  * parser (2.2.0.3)
  * powerpack (0.1.0)
  * pry (0.12.2)
  * pry-byebug (3.0.1)
  * pry-doc (1.0.0)
  * public_suffix (2.0.5)
  * quiet_assets (1.1.0)
  * rack (1.6.11)
  * rack-cas (0.15.0)
  * rack-mini-profiler (0.9.3)
  * rack-protection (1.5.3)
  * rack-test (0.6.3)
  * rack_session_access (0.1.1)
  * rails (4.2.11.1)
  * rails-deprecated_sanitizer (1.0.3)
  * rails-dom-testing (1.0.9)
  * rails-html-sanitizer (1.0.4)
  * rails_config (0.4.2)
  * railties (4.2.11.1)
  * rainbow (2.0.0)
  * raindrops (0.13.0)
  * rake (12.3.2)
  * rake-compiler (0.9.5)
  * rdoc (4.2.0)
  * redis (3.2.1)
  * request_store (1.3.1)
  * rubocop (0.29.1)
  * ruby-oci8 (2.1.7)
  * ruby-progressbar (1.7.1)
  * ruby2ruby (2.1.3)
  * ruby_parser (3.5.0)
  * rubyzip (1.1.7)
  * sass (3.4.15)
  * sdoc (0.4.1)
  * secure_headers (2.0.0)
  * selenium-webdriver (2.45.0)
  * sexp_processor (4.4.5)
  * simplecov (0.9.2)
  * simplecov-html (0.9.0)
  * sinatra (1.4.8)
  * slop (3.6.0)
  * spring (2.0.2)
  * spring-commands-m (1.0.1)
  * sprockets (3.7.2)
  * sprockets-rails (3.2.1)
  * terminal-table (1.4.5)
  * test_after_commit (0.4.1)
  * thor (0.20.3)
  * thread_safe (0.3.6)
  * tilt (1.4.1)
  * transactional_capybara (0.2.0)
  * turbolinks (2.5.3)
  * tzinfo (1.2.5)
  * uglifier (2.7.2)
  * unicorn (4.8.3)
  * uniofbath_deploy (0.0.11 5a29db4)
  * websocket (1.2.1)
  * xpath (2.1.0)
  * yard (0.9.19)
kubo commented 5 years ago

The stackrace of error ends at the execution of the native extension functions. I tried to debug C code and apparently 'executing in another thread' error comes from oci8_call_without_gvl function (in ext/oci8lib.c file). What can be the reason of this error?

I don't know the reason. One database connection cannot be used from more than one thread at the same time. So when a connection is used while it is used in another thread, ruby-oc8 raises the error. The behavior has not been changed since ruby-oci8 2.0.0 until now. Therefore what I could say is that the caller should not use one connection simultaneously. However rails supports connection pooling and uses one connection from only one thread. So the error won't occur.

morszczuk commented 5 years ago

@kubo Thank you very much for your response. Although we haven't found what causes our problem yet, we now know the place to investigate - our issue is probably related to how feature tests are being run. Thanks!

cbenger commented 2 years ago

Hey @morszczuk! Was wondering if you found out what was causing the error? We are getting this same error after upgrading to Rails 6 (6.0.4.6) using ruby-oci8 (2.2.9) & activerecord-oracle_enhanced-adapter (= 6.0.4)

We have been able to re-created the issue by executing queries in the same number of threads as our connection pool is configured for.

kubo commented 2 years ago

@cbenger

Could you try ruby-oci8 2.2.10 or later? @poblouin found that https://github.com/kubo/ruby-oci8/commit/031cab52f95e9d3ea5229ed0e465c95a7e94dcaa, which is in ruby-oci8 2.2.10 or later, solved the issue. See https://github.com/kubo/ruby-oci8/issues/244.

cbenger commented 2 years ago

Hi @kubo! Yeah, upgrading to 2.2.10 did fix the issue. Poblouin and I are actually co-workers haha. Wanted to ask here incase the OP on this ticket ever found what was causing this error for them.

EdwinRozario commented 4 months ago

Hi Team

I am getting similar error while running ApplicationSystemTestCase. The changes made to the app before getting these errors are.

  1. Rails upgraded from 6 to 7.0.8.1
  2. Ruby from 3.0 to 3.1
  3. activerecord-oracle_enhanced-adapter from 6.1.0 to 7.0.3

ruby-oci8 seems to be 2.2.11

Error output

Minitest::UnexpectedError:         RuntimeError: executing in another thread
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/ruby-oci8-2.2.11/lib/oci8/cursor.rb:131:in `__execute'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/ruby-oci8-2.2.11/lib/oci8/cursor.rb:131:in `exec'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/ruby-oci8-2.2.11/lib/oci8/oci8.rb:271:in `exec_internal'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/ruby-oci8-2.2.11/lib/oci8/oci8.rb:262:in `exec'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-oracle_enhanced-adapter-7.0.3/lib/active_record/connection_adapters/oracle_enhanced/oci_connection.rb:401:in `ping'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-oracle_enhanced-adapter-7.0.3/lib/active_record/connection_adapters/oracle_enhanced/oci_connection.rb:81:in `ping'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-oracle_enhanced-adapter-7.0.3/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb:443:in `active?'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/abstract_adapter.rb:579:in `verify!'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:705:in `block in checkout_and_verify'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-7.0.8.1/lib/active_support/callbacks.rb:107:in `run_callbacks'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-7.0.8.1/lib/active_support/callbacks.rb:929:in `_run_checkout_callbacks'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:704:in `checkout_and_verify'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:341:in `checkout'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `connection'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/test_fixtures.rb:192:in `map'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/test_fixtures.rb:192:in `enlist_fixture_connections'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/test_fixtures.rb:130:in `setup_fixtures'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activerecord-7.0.8.1/lib/active_record/test_fixtures.rb:10:in `before_setup'
            /Users/eroza001/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-7.0.8.1/lib/active_support/testing/setup_and_teardown.rb:40:in `before_setup'

This is not a show stopper. I thought it will be helpful to let you guys know.

Thank you