Closed yahonda closed 11 years ago
Could you run bundle show
in the directory where rake test_oracle
was executed and post the output?
Here is the bundle show
output when this error happens. You will see this test case is different one but always happens some of SchemaDumperTest
.
$ rake test_oracle
/home/yahonda/.rvm/rubies/ruby-2.0.0-p0/bin/ruby -w -I"lib:test" -I"/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/rake-10.0.3/lib" "/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/rake-10.0.3/lib/rake/rake_test_loader.rb" "test/cases/adapter_test.rb" "test/cases/adapters/oracle/synonym_test.rb" "test/cases/aggregations_test.rb" "test/cases/ar_schema_test.rb" "test/cases/associations/association_scope_test.rb" "test/cases/associations/belongs_to_associations_test.rb" "test/cases/associations/callbacks_test.rb" "test/cases/associations/cascaded_eager_loading_test.rb" "test/cases/associations/eager_load_includes_full_sti_class_test.rb" "test/cases/associations/eager_load_nested_include_test.rb" "test/cases/associations/eager_singularization_test.rb" "test/cases/associations/eager_test.rb" "test/cases/associations/extension_test.rb" "test/cases/associations/has_and_belongs_to_many_associations_test.rb" "test/cases/associations/has_many_associations_test.rb" "test/cases/associations/has_many_through_associations_test.rb" "test/cases/associations/has_one_associations_test.rb" "test/cases/associations/has_one_through_associations_test.rb" "test/cases/associations/inner_join_association_test.rb" "test/cases/associations/inverse_associations_test.rb" "test/cases/associations/join_dependency_test.rb" "test/cases/associations/join_model_test.rb" "test/cases/associations/nested_through_associations_test.rb" "test/cases/associations_test.rb" "test/cases/attribute_methods/read_test.rb" "test/cases/attribute_methods_test.rb" "test/cases/autosave_association_test.rb" "test/cases/base_test.rb" "test/cases/batches_test.rb" "test/cases/binary_test.rb" "test/cases/bind_parameter_test.rb" "test/cases/calculations_test.rb" "test/cases/callbacks_test.rb" "test/cases/clone_test.rb" "test/cases/coders/yaml_column_test.rb" "test/cases/column_alias_test.rb" "test/cases/column_definition_test.rb" "test/cases/column_test.rb" "test/cases/connection_adapters/abstract_adapter_test.rb" "test/cases/connection_adapters/connection_handler_test.rb" "test/cases/connection_adapters/connection_specification_test.rb" "test/cases/connection_adapters/quoting_test.rb" "test/cases/connection_adapters/schema_cache_test.rb" "test/cases/connection_management_test.rb" "test/cases/connection_pool_test.rb" "test/cases/connection_specification/resolver_test.rb" "test/cases/counter_cache_test.rb" "test/cases/custom_locking_test.rb" "test/cases/database_statements_test.rb" "test/cases/date_time_test.rb" "test/cases/defaults_test.rb" "test/cases/deprecated_dynamic_methods_test.rb" "test/cases/dirty_test.rb" "test/cases/dup_test.rb" "test/cases/explain_subscriber_test.rb" "test/cases/explain_test.rb" "test/cases/finder_respond_to_test.rb" "test/cases/finder_test.rb" "test/cases/fixture_set/file_test.rb" "test/cases/fixtures_test.rb" "test/cases/forbidden_attributes_protection_test.rb" "test/cases/habtm_destroy_order_test.rb" "test/cases/hot_compatibility_test.rb" "test/cases/i18n_test.rb" "test/cases/inheritance_test.rb" "test/cases/invalid_date_test.rb" "test/cases/invertible_migration_test.rb" "test/cases/json_serialization_test.rb" "test/cases/locking_test.rb" "test/cases/log_subscriber_test.rb" "test/cases/migration/change_schema_test.rb" "test/cases/migration/change_table_test.rb" "test/cases/migration/column_attributes_test.rb" "test/cases/migration/column_positioning_test.rb" "test/cases/migration/columns_test.rb" "test/cases/migration/command_recorder_test.rb" "test/cases/migration/create_join_table_test.rb" "test/cases/migration/index_test.rb" "test/cases/migration/logger_test.rb" "test/cases/migration/references_index_test.rb" "test/cases/migration/references_statements_test.rb" "test/cases/migration/rename_table_test.rb" "test/cases/migration/table_and_index_test.rb" "test/cases/migration_test.rb" "test/cases/migrator_test.rb" "test/cases/mixin_test.rb" "test/cases/modules_test.rb" "test/cases/multiparameter_attributes_test.rb" "test/cases/multiple_db_test.rb" "test/cases/named_scope_test.rb" "test/cases/nested_attributes_test.rb" "test/cases/persistence_test.rb" "test/cases/pooled_connections_test.rb" "test/cases/primary_keys_test.rb" "test/cases/query_cache_test.rb" "test/cases/quoting_test.rb" "test/cases/readonly_test.rb" "test/cases/reaper_test.rb" "test/cases/reflection_test.rb" "test/cases/relation/where_chain_test.rb" "test/cases/relation/where_test.rb" "test/cases/relation_scoping_test.rb" "test/cases/relation_test.rb" "test/cases/relations_test.rb" "test/cases/reload_models_test.rb" "test/cases/sanitize_test.rb" "test/cases/schema_dumper_test.rb" "test/cases/serialization_test.rb" "test/cases/serialized_attribute_test.rb" "test/cases/store_test.rb" "test/cases/tasks/database_tasks_test.rb" "test/cases/tasks/mysql_rake_test.rb" "test/cases/tasks/postgresql_rake_test.rb" "test/cases/tasks/sqlite_rake_test.rb" "test/cases/timestamp_test.rb" "test/cases/transaction_callbacks_test.rb" "test/cases/transaction_isolation_test.rb" "test/cases/transactions_test.rb" "test/cases/unconnected_test.rb" "test/cases/validations/association_validation_test.rb" "test/cases/validations/i18n_generate_message_validation_test.rb" "test/cases/validations/i18n_validation_test.rb" "test/cases/validations/presence_validation_test.rb" "test/cases/validations/uniqueness_validation_test.rb" "test/cases/validations_test.rb" "test/cases/xml_serialization_test.rb" "test/cases/yaml_serialization_test.rb"
Using oracle
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb:1091: warning: assigned but unused variable - owner
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb:1091: warning: assigned but unused variable - db_link
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_oci_connection.rb:211: warning: assigned but unused variable - e
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_schema_statements.rb:71: warning: assigned but unused variable - result
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_schema_dumper.rb:52: warning: assigned but unused variable - pk_seq
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_schema_dumper.rb:152: warning: assigned but unused variable - pk_seq
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_structure_dump.rb:152: warning: assigned but unused variable - lines
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_structure_dump.rb:262: warning: assigned but unused variable - e
Run options: --seed 29826
# Running tests:
......................................................................................................................................................................................................................................................S..SSSSSSS..............................................................................S...............SS.....................S...................................................................SSSSSS...................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................SS.S.............................................S..................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................E..................................................................................................................................................................................................................................................................................................................................................................................................................SS...S..........................................S..........................................
Finished tests in 287.928596s, 12.3503 tests/s, 33.9494 assertions/s.
1) Error:
SchemaDumperTest#test_arguments_line_up:
ActiveRecord::StatementInvalid: RuntimeError: executing in another thread: SELECT r.table_name to_table
,rc.column_name references_column
,cc.column_name
,c.constraint_name name
,c.delete_rule
FROM user_constraints c, user_cons_columns cc,
user_constraints r, user_cons_columns rc
WHERE c.owner = 'ARUNIT'
AND c.table_name = 'ACCOUNTS'
AND c.constraint_type = 'R'
AND cc.owner = c.owner
AND cc.constraint_name = c.constraint_name
AND r.constraint_name = c.r_constraint_name
AND r.owner = c.owner
AND rc.owner = r.owner
AND rc.constraint_name = r.constraint_name
AND rc.position = cc.position
ORDER BY name, to_table, column_name, references_column
/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/ruby-oci8-2.1.5/lib/oci8/cursor.rb:536:in `__fetch'
/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/ruby-oci8-2.1.5/lib/oci8/cursor.rb:536:in `fetch_one_row_as_array'
/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/ruby-oci8-2.1.5/lib/oci8/cursor.rb:149:in `fetch'
/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/ruby-oci8-2.1.5/lib/oci8/oci8.rb:282:in `exec_internal'
/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/ruby-oci8-2.1.5/lib/oci8/oci8.rb:269:in `exec'
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_oci_connection.rb:438:in `ping'
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_oci_connection.rb:72:in `ping'
/home/yahonda/git/oracle-enhanced/lib/active_record/connection_adapters/oracle_enhanced_adapter.rb:697:in `active?'
/home/yahonda/git/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:409:in `block (2 levels) in reap'
/home/yahonda/git/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:408:in `each'
/home/yahonda/git/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:408:in `block in reap'
/home/yahonda/.rvm/rubies/ruby-2.0.0-p0/lib/ruby/2.0.0/monitor.rb:211:in `mon_synchronize'
/home/yahonda/git/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:406:in `reap'
/home/yahonda/git/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:217:in `block in run'
3556 tests, 9775 assertions, 0 failures, 1 errors, 26 skips
rake aborted!
Command failed with status (1): [ruby -w -I"lib:test" -I"/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/rake-10.0.3/lib" "/home/yahonda/.rvm/gems/ruby-2.0.0-p0@railsmaster/gems/rake-10.0.3/lib/rake/rake_test_loader.rb" "test/cases/adapter_test.rb" "test/cases/adapters/oracle/synonym_test.rb" "test/cases/aggregations_test.rb" "test/cases/ar_schema_test.rb" "test/cases/associations/association_scope_test.rb" "test/cases/associations/belongs_to_associations_test.rb" "test/cases/associations/callbacks_test.rb" "test/cases/associations/cascaded_eager_loading_test.rb" "test/cases/associations/eager_load_includes_full_sti_class_test.rb" "test/cases/associations/eager_load_nested_include_test.rb" "test/cases/associations/eager_singularization_test.rb" "test/cases/associations/eager_test.rb" "test/cases/associations/extension_test.rb" "test/cases/associations/has_and_belongs_to_many_associations_test.rb" "test/cases/associations/has_many_associations_test.rb" "test/cases/associations/has_many_through_associations_test.rb" "test/cases/associations/has_one_associations_test.rb" "test/cases/associations/has_one_through_associations_test.rb" "test/cases/associations/inner_join_association_test.rb" "test/cases/associations/inverse_associations_test.rb" "test/cases/associations/join_dependency_test.rb" "test/cases/associations/join_model_test.rb" "test/cases/associations/nested_through_associations_test.rb" "test/cases/associations_test.rb" "test/cases/attribute_methods/read_test.rb" "test/cases/attribute_methods_test.rb" "test/cases/autosave_association_test.rb" "test/cases/base_test.rb" "test/cases/batches_test.rb" "test/cases/binary_test.rb" "test/cases/bind_parameter_test.rb" "test/cases/calculations_test.rb" "test/cases/callbacks_test.rb" "test/cases/clone_test.rb" "test/cases/coders/yaml_column_test.rb" "test/cases/column_alias_test.rb" "test/cases/column_definition_test.rb" "test/cases/column_test.rb" "test/cases/connection_adapters/abstract_adapter_test.rb" "test/cases/connection_adapters/connection_handler_test.rb" "test/cases/connection_adapters/connection_specification_test.rb" "test/cases/connection_adapters/quoting_test.rb" "test/cases/connection_adapters/schema_cache_test.rb" "test/cases/connection_management_test.rb" "test/cases/connection_pool_test.rb" "test/cases/connection_specification/resolver_test.rb" "test/cases/counter_cache_test.rb" "test/cases/custom_locking_test.rb" "test/cases/database_statements_test.rb" "test/cases/date_time_test.rb" "test/cases/defaults_test.rb" "test/cases/deprecated_dynamic_methods_test.rb" "test/cases/dirty_test.rb" "test/cases/dup_test.rb" "test/cases/explain_subscriber_test.rb" "test/cases/explain_test.rb" "test/cases/finder_respond_to_test.rb" "test/cases/finder_test.rb" "test/cases/fixture_set/file_test.rb" "test/cases/fixtures_test.rb" "test/cases/forbidden_attributes_protection_test.rb" "test/cases/habtm_destroy_order_test.rb" "test/cases/hot_compatibility_test.rb" "test/cases/i18n_test.rb" "test/cases/inheritance_test.rb" "test/cases/invalid_date_test.rb" "test/cases/invertible_migration_test.rb" "test/cases/json_serialization_test.rb" "test/cases/locking_test.rb" "test/cases/log_subscriber_test.rb" "test/cases/migration/change_schema_test.rb" "test/cases/migration/change_table_test.rb" "test/cases/migration/column_attributes_test.rb" "test/cases/migration/column_positioning_test.rb" "test/cases/migration/columns_test.rb" "test/cases/migration/command_recorder_test.rb" "test/cases/migration/create_join_table_test.rb" "test/cases/migration/index_test.rb" "test/cases/migration/logger_test.rb" "test/cases/migration/references_index_test.rb" "test/cases/migration/references_statements_test.rb" "test/cases/migration/rename_table_test.rb" "test/cases/migration/table_and_index_test.rb" "test/cases/migration_test.rb" "test/cases/migrator_test.rb" "test/cases/mixin_test.rb" "test/cases/modules_test.rb" "test/cases/multiparameter_attributes_test.rb" "test/cases/multiple_db_test.rb" "test/cases/named_scope_test.rb" "test/cases/nested_attributes_test.rb" "test/cases/persistence_test.rb" "test/cases/pooled_connections_test.rb" "test/cases/primary_keys_test.rb" "test/cases/query_cache_test.rb" "test/cases/quoting_test.rb" "test/cases/readonly_test.rb" "test/cases/reaper_test.rb" "test/cases/reflection_test.rb" "test/cases/relation/where_chain_test.rb" "test/cases/relation/where_test.rb" "test/cases/relation_scoping_test.rb" "test/cases/relation_test.rb" "test/cases/relations_test.rb" "test/cases/reload_models_test.rb" "test/cases/sanitize_test.rb" "test/cases/schema_dumper_test.rb" "test/cases/serialization_test.rb" "test/cases/serialized_attribute_test.rb" "test/cases/store_test.rb" "test/cases/tasks/database_tasks_test.rb" "test/cases/tasks/mysql_rake_test.rb" "test/cases/tasks/postgresql_rake_test.rb" "test/cases/tasks/sqlite_rake_test.rb" "test/cases/timestamp_test.rb" "test/cases/transaction_callbacks_test.rb" "test/cases/transaction_isolation_test.rb" "test/cases/transactions_test.rb" "test/cases/unconnected_test.rb" "test/cases/validations/association_validation_test.rb" "test/cases/validations/i18n_generate_message_validation_test.rb" "test/cases/validations/i18n_validation_test.rb" "test/cases/validations/presence_validation_test.rb" "test/cases/validations/uniqueness_validation_test.rb" "test/cases/validations_test.rb" "test/cases/xml_serialization_test.rb" "test/cases/yaml_serialization_test.rb" ]
Tasks: TOP => test_oracle
(See full trace by running task with --trace)
$ bundle show
Resolving dependencies...
Gems included by the bundle:
* actionmailer (4.0.0.beta1)
* actionpack (4.0.0.beta1)
* activemodel (4.0.0.beta1)
* activerecord (4.0.0.beta1)
* activerecord-deprecated_finders (0.0.3)
* activerecord-oracle_enhanced-adapter (1.4.2.rc1 8d98858)
* activesupport (4.0.0.beta1)
* arel (4.0.0.beta2)
* atomic (1.0.1)
* bcrypt-ruby (3.0.1)
* benchmark-ips (1.2.0)
* builder (3.1.4)
* bundler (1.3.0)
* coffee-rails (4.0.0.beta1)
* coffee-script (2.2.0)
* coffee-script-source (1.6.1)
* columnize (0.3.6)
* dalli (2.6.2)
* debugger (1.5.0)
* debugger-linecache (1.2.0)
* debugger-ruby_core_source (1.2.0)
* erubis (2.7.0)
* execjs (1.4.0)
* hike (1.2.1)
* i18n (0.6.4)
* jquery-rails (2.2.1)
* json (1.7.7)
* kindlerb (0.1.1)
* mail (2.5.3)
* metaclass (0.0.1)
* mime-types (1.21)
* minitest (4.6.2)
* mocha (0.13.3)
* multi_json (1.6.1)
* mustache (0.99.4)
* mysql (2.9.1)
* mysql2 (0.3.11)
* nokogiri (1.5.6)
* pg (0.14.1)
* polyglot (0.3.3)
* racc (1.4.9)
* rack (1.5.2)
* rack-cache (1.2)
* rack-test (0.6.2)
* rails (4.0.0.beta1 aa07318)
* railties (4.0.0.beta1)
* rake (10.0.3)
* rdoc (3.12.2)
* redcarpet (2.2.2)
* ruby-oci8 (2.1.5)
* sdoc (0.3.20 87ad100)
* sprockets (2.9.0)
* sprockets-rails (2.0.0.rc3)
* sqlite3 (1.3.7)
* thor (0.17.0)
* thread_safe (0.1.0)
* tilt (1.3.5)
* treetop (1.4.12)
* turbolinks (1.0.0)
* tzinfo (0.3.37)
* uglifier (1.3.0)
* w3c_validators (1.2)
* yajl-ruby (1.1.0)
$
Thanks. I reproduced the issue owing to the bundle show
output,
Good news. Please update whatever I can do.
I found the reason. It is caused by rails/rails@7cc588b684f6d1af3e7fab1edfa6715e269e41a2.
A connection pool reaper checks connections every 10 seconds and executes OracleEnhancedAdapter#active?
when it finds an in-use connection running more than 5 seconds.
Thanks for finding cause of this issue.
If my understanding is correct this error is easy to reproduce if this default value(self, spec.config[:reaping_frequency] || 10)
changed to 5 or lower value?
(This comment is confusable. Look at my next comment.) I found a bug and fixed it. See e9dfda6f7f2ee0a95c6ea33b96d32e7115f64612. This issue is reproduced easily due to the fix.
Thank you for making a fix. I tried to verity my error but it looks it still reproduces. https://gist.github.com/yahonda/5177671
Sorry, my previous comment it too short to confuse you. It doesn't fix this issue: "executing in another thread." It fixes another bug that OCI8#parse and OCI8#exec, which calls OCI8#parse internally, stop the ruby interpreter while the OCI8 connection is used by another thread.
The "executing in another thread" issue happen in delicate timing due to the bug because OCI8#parse doesn't raise "executing in another thread" but blocks the ruby interpreter. Fixing the bug increases the timing to raise "executing in another thread" and reproduces the issue more easily.
Thanks for the update. You said This issue is reproduced easily due to the fix.
I just misunderstood.
Your commit makes OCI8#parse not to block ruby raising this "executing in another thread" error. Then my issue should be easy to reproduce.
To address the "executing in another thread" error itself, some change needs in ActiveRecord.
I made a patch. https://gist.github.com/kubo/5181580
When a connection is used by another thread, it waits maximum 10 seconds until the connection become free.
Otherwise it raises an "executing in another thread" error.
This issue will be suppressed if OracleEnhancedAdapter#active?
always finishes in 10 seconds.
I'm not sure whether it is best or not because, IMO, 10 seconds is too long but setting 5 seconds reproduced this issue in my environment.
Applied this patch and tested rake test_oracle
30 times. No failures or errors found.
OracleEnhancedAdapter#active?
executes select 1 from dual
at the connected database, I think it should not 5 seconds.
I have no strong idea this patch should be merged to ruby-oci8 or default :reaping_frequency
value changed at rails.
Tested rake test_oracle
with ruby-oci8 master branch, e9dfda6f7f2ee0a95c6ea33b96d32e7115f64612 included, no errors/failures found. I can say no need to commit your patch https://gist.github.com/kubo/5181580 to ruby-oci8 master.
I think I can close this issue. Thanks for providing info and patches, really helpful.
Recently Rails ActiveRecord unit tests with oracle database
rake test_oracle
sometimes gets this error.You can see the whole output from here
As I write 'sometimes', this error is not a 100% reproduce one.
rake test_oracle
RuntimeError: executing in another thread
has been happening quite recently, within a week. I do not remember the exact date it happens first.Because of this it's quite difficult to find which commit causes this error using
git bisect
. Therefore I'm opening this issue to ask for help to resolve this error. Anyone has any hints, please have some comments.