two inverse associations test got failed with Oracle enhanced adapter #7334

Closed
yahonda opened this Issue Aug 12, 2012 · 23 comments

5 participants

@yahonda

Tested rails master branch with Oracle enhanced adapter rails4, two inverse associations test got failed as follows.

$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb 
Using oracle
Run options: --seed 25611

# Running tests:

.......................FF............

Finished tests in 1.242921s, 29.7686 tests/s, 117.4652 assertions/s.

  1) Failure:
test_parent_instance_should_be_shared_with_newly_created_child(InverseHasOneTests) [test/cases/associations/inverse_associations_test.rb:133]:
Name of man should be the same after changes to parent instance.
Expected: "Bongo"
  Actual: "Steve"

  2) Failure:
test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method(InverseHasOneTests) [test/cases/associations/inverse_associations_test.rb:144]:
Name of man should be the same after changes to parent instance.
Expected: "Bongo"
  Actual: "Steve"

37 tests, 146 assertions, 2 failures, 0 errors, 0 skips
$ 

According to the git bisect output, 42dd5d9 made in #7191 is the first commit which cause these failures.

@rafaelfranca
Ruby on Rails member

Any clue about what can be causing this issue?

@drogus
Ruby on Rails member

@yahonda could you run git bisect to check which commit causes the issue?

@rafaelfranca
Ruby on Rails member

According to the git bisect output, 42dd5d9 made in #7191 is the first commit which cause these failures.

@yahonda

Well, I have not find the exact cause of these failures then opened this issue without any pull request yet to get someone's help.

@yahonda

Reverted the commit 42dd5d9 and test_has_one_transaction test failed as expected.

Then test_parent_instance_should_be_shared_with_newly_created_child and test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method successfully finished.

$ ARCONN=oracle ruby -Itest test/cases/associations/has_one_associations_test.rb
Using oracle
Run options: --seed 12585

# Running tests:

....................................F...................

Finished tests in 3.087005s, 18.1406 tests/s, 39.5205 assertions/s.

  1) Failure:
test_has_one_transaction(HasOneAssociationsTest) [test/cases/associations/has_one_associations_test.rb:514]:
1 instead of 0 queries were executed.
Queries:
SAVEPOINT active_record_1.
Expected: 0
  Actual: 1

56 tests, 122 assertions, 1 failures, 0 errors, 0 skips
$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb
Using oracle
Run options: --seed 17896

# Running tests:

.....................................

Finished tests in 1.214541s, 30.4642 tests/s, 121.8567 assertions/s.

37 tests, 148 assertions, 0 failures, 0 errors, 0 skips
$

You can see this branch here.

@kennyj

I investigated this issue in last night. And I found strange behavior.

In oracle, target.id is equal to record.id. And target.object_id isn't equal to record.object_id.
In MySQL, all of them are another value.

Thus, in oracle, some codes inside if statement are not executed.
If I remove target != record, it's work fine. But it's not properly solution.

I guess the core of this issue is this behavior that existed before my commit.

@kennyj

Btw, I used oracle_enhanced rails4 branch and rails master.

@yahonda

Tested with Oracle enhanced adapter both target.id and record.id return 10000.

The 10000 would come from the default sequence start value of Oracle enhanced.
See here for detail.

1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ git diff
diff --git a/activerecord/lib/active_record/associations/has_one_association.rb b/activerecord/lib/active_record/associations/has_one
index dd7da59..86b37fc 100644
--- a/activerecord/lib/active_record/associations/has_one_association.rb
+++ b/activerecord/lib/active_record/associations/has_one_association.rb
@@ -27,6 +27,10 @@ module ActiveRecord

         # If target and record are nil, or target is equal to record,
         # we don't need to have transaction.
+        puts target.id
+        puts record.id
+        puts target.object_id
+        puts record.object_id
         if (target || record) && target != record
           reflection.klass.transaction do
             remove_target!(options[:dependent]) if target && !target.destroyed?
1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ 

Here are test results.

1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ ARCONN=postgresql ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child
Using postgresql
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child --seed 47346

# Running tests:

703156990
976688383
10937780
17591320
.

Finished tests in 0.252748s, 3.9565 tests/s, 15.8260 assertions/s.

1 tests, 4 assertions, 0 failures, 0 errors, 0 skips
1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child
Using oracle
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child --seed 32113

# Running tests:

10000
10000
30823720
29877660
F

Finished tests in 0.263092s, 3.8010 tests/s, 11.4029 assertions/s.

  1) Failure:
test_parent_instance_should_be_shared_with_newly_created_child(InverseHasOneTests) [test/cases/associations/inverse_associations_test.rb:133]:
Name of man should be the same after changes to parent instance.
Expected: "Bongo"
  Actual: "Steve"

1 tests, 3 assertions, 1 failures, 0 errors, 0 skips

There must be some difference in id.

@kennyj

@yahonda I got same result.

If we add m.face for force loading before m.create_face in the testcase, target.id is not 10000.

@yahonda

Thanks for the investigation. It's very interesting.

1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ git diff
diff --git a/activerecord/lib/active_record/associations/has_one_association.rb b/activerecord/lib/active_record/associations/has_one
index dd7da59..86b37fc 100644
--- a/activerecord/lib/active_record/associations/has_one_association.rb
+++ b/activerecord/lib/active_record/associations/has_one_association.rb
@@ -27,6 +27,10 @@ module ActiveRecord

         # If target and record are nil, or target is equal to record,
         # we don't need to have transaction.
+        puts target.id
+        puts record.id
+        puts target.object_id
+        puts record.object_id
         if (target || record) && target != record
           reflection.klass.transaction do
             remove_target!(options[:dependent]) if target && !target.destroyed?
diff --git a/activerecord/test/cases/associations/inverse_associations_test.rb b/activerecord/test/cases/associations/inverse_associa
index 8cb8a5a..b820c57 100644
--- a/activerecord/test/cases/associations/inverse_associations_test.rb
+++ b/activerecord/test/cases/associations/inverse_associations_test.rb
@@ -126,6 +126,7 @@ class InverseHasOneTests < ActiveRecord::TestCase

   def test_parent_instance_should_be_shared_with_newly_created_child
     m = Man.first
+    m.face
     f = m.create_face(:description => 'haunted')
     assert_not_nil f.man
     assert_equal m.name, f.man.name, "Name of man should be the same before changes to parent instance"
1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child
Using oracle
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child --seed 6819

# Running tests:

703156990
10000
24741380
32688300
.

Finished tests in 0.255904s, 3.9077 tests/s, 15.6309 assertions/s.

1 tests, 4 assertions, 0 failures, 0 errors, 0 skips
1.9.3-p194@railsmaster [ address_7334 ~/git/rails/activerecord]$ 

I do not get what is the expected behavior yet, there may be some difference at the initial id generated by Oracle enhanced adapter.

@yahonda

By executing m.face, target.id becomes 703156990 then target != record becomes true, which makes these failed tests passed. Here is the branch with this fix.

There are several reasons I hesitate to open a pull request.

  • record.id is still 10000, 976688383 should be the expected value for record.id.
  • Executing m.face is a workaround, It would be better not to execute this.
@yahonda

Cc Oracle enhanced adapter developers. @rsim @ebeigarts

@yahonda

@kennyj Thanks for your investigation, It helps a lot always.

@rsim @ebeigarts
Just added cc you guys without any explanation.

This issue just reproduces with Oracle enhanced adapter. Tested with Oracle enhanced adapter(rails4 branch), target.id and record.id are 10000 based on the default_sequence_start_value specified in Oracle enhanced adapter.

On the other hand, tested with postgresql, target.id is 703156990, and record.id is 976688383. These values come from Fixture hash value, Here it is important these id values are different initially.

As @kennyj said 42dd5d9 does not cause regression itself. As 42dd5d9 reverted, target.id and record.id are still 10000. Commit 42dd5d9 implements target != record condition to fix issue #7191. Tested with Oracle enhanced adapter, this condition becomes false as other database it is true.

I've been trying to find the cause of this, but I do not get any useful information yet. It would be helpful if you have some idea.

@yahonda

Tested with Rails 3-2-stable which has the commit 2e00074 to address #7191 ,these tests have passed.

$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child
Using oracle with Identity Map off
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child

# Running tests:

413266651
10000
12766580
12628040
.

Finished tests in 0.393172s, 2.5434 tests/s, 10.1737 assertions/s.

1 tests, 4 assertions, 0 failures, 0 errors, 0 skips
1.9.3-p194@32stable [ 3-2-stable ~/git/rails/activerecord]$ git diff
diff --git a/activerecord/lib/active_record/associations/has_one_association.rb b/activerecord/lib/active_record/associations/has_one_association.rb
index 501ebe7..9fa4db8 100644
--- a/activerecord/lib/active_record/associations/has_one_association.rb
+++ b/activerecord/lib/active_record/associations/has_one_association.rb
@@ -10,6 +10,10 @@ module ActiveRecord

         # If target and record are nil, or target is equal to record,
         # we don't need to have transaction.
+        puts target.id
+        puts record.id
+        puts target.object_id
+        puts record.object_id
         if (target || record) && target != record
           reflection.klass.transaction do
             remove_target!(options[:dependent]) if target && !target.destroyed?
$

At least the target.id has the expected value.

I think this issue should be removed from the Milestone 3.2.9 as I tested. It just exists with Rails master branch and Oracle enhanced rails4 branch.

I'm wondering if there might be something wrong with returning values of DML(Insert/Update) statement.

@rafaelfranca
Ruby on Rails member

Changed the milestone.

@yahonda

Thanks for the milestone change. It still reproduces and temporary fix is available, but not getting to the bottom.

@yahonda

Still investigating this issue. Made a debug commit yahonda@0a6100f which shows several puts caller.first for postgresql, one of the databases these test finishes successfully. However, these methods have not called when tested with oracle database.

$ cd activerecord
$ for i in postgresql oracle; do echo $i; ARCONN=$i ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method; done
postgresql
Using postgresql
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method --seed 43144

# Running tests:

/home/yahonda/git/rails/activerecord/lib/active_record/callbacks.rb:265:in `block in create_or_update'
/home/yahonda/git/rails/activerecord/lib/active_record/persistence.rb:373:in `create_or_update'
/home/yahonda/git/rails/activerecord/lib/active_record/timestamp.rb:74:in `update'
/home/yahonda/git/rails/activerecord/lib/active_record/callbacks.rb:274:in `block in update'
/home/yahonda/git/rails/activerecord/lib/active_record/attribute_methods/dirty.rb:68:in `update'
/home/yahonda/git/rails/activerecord/lib/active_record/locking/optimistic.rb:75:in `update'
/home/yahonda/git/rails/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:15:in `update'
.

Finished tests in 0.209598s, 4.7710 tests/s, 19.0841 assertions/s.

1 tests, 4 assertions, 0 failures, 0 errors, 0 skips
oracle
Using oracle
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method --seed 19965

# Running tests:

F

Finished tests in 0.236425s, 4.2297 tests/s, 12.6890 assertions/s.

  1) Failure:
test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method(InverseHasOneTests) [test/cases/associations/inverse_associations_test.rb:144]:
Name of man should be the same after changes to parent instance.
Expected: "Bongo"
  Actual: "Steve"

1 tests, 3 assertions, 1 failures, 0 errors, 0 skips
$
@mdespuits

Has this issue been resolved?

@yahonda

This issue still exists.

@yahonda

I've found the reason why it happens and a temporary workaround.

It is caused as Oracle enhanced adapter generates id starting with 10000 for Faces even if other rows' id values are higher than 10000.

  • Rails master branch with Oracle enhanced adapter

At ActiveRecord::Associations::SingularAssociation#find_target

$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method
Using oracle
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method --seed 5649

# Running tests:

[39, 48] in /home/yahonda/git/rails/activerecord/lib/active_record/associations/singular_association.rb
   39          end
   40
   41          def find_target
   42            require 'debugger'
   43            debugger
=> 44            scope.first.tap { |record| set_inverse_instance(record) }
   45          end
   46
   47          # Implemented by subclasses
   48          def replace(record)
/home/yahonda/git/rails/activerecord/lib/active_record/associations/singular_association.rb:44
scope.first.tap { |record| set_inverse_instance(record) }
(rdb:1) puts scope.first.inspect
#<Face id: 10000, description: "haunted", man_id: 380377255, polymorphic_man_id: nil, polymorphic_man_type: nil, horrible_polymorphic_man_id: nil, horrible_polymorphic_man_type: nil>
nil

As Oracle enhanced adapter takes 10000, which is lower than 703156990,
scope.first calls following sql statement, then this value is retrieved.

  Face Load (3.3ms)  SELECT * FROM (SELECT "FACES".* FROM "FACES" WHERE "FACES"."MAN_ID" = :a1 ORDER BY "FACES"."ID" ASC) WHERE ROWNUM <= 1  [["man_id", 380377255]]
  • Rails master branch with PostgreSQL adapter
$ ARCONN=postgresql ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method
Using postgresql
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method --seed 10599

# Running tests:

[39, 48] in /home/yahonda/git/rails/activerecord/lib/active_record/associations/singular_association.rb
   39          end
   40
   41          def find_target
   42            require 'debugger'
   43            debugger
=> 44            scope.first.tap { |record| set_inverse_instance(record) }
   45          end
   46
   47          # Implemented by subclasses
   48          def replace(record)
/home/yahonda/git/rails/activerecord/lib/active_record/associations/singular_association.rb:44
scope.first.tap { |record| set_inverse_instance(record) }
(rdb:1) puts scope.first.inspect
#<Face id: 703156990, description: "weather beaten", man_id: 380377255, polymorphic_man_id: nil, polymorphic_man_type: nil, horrible_polymorphic_man_id: nil, horrible_polymorphic_man_type: nil>
nil

Here, scope.first calls this sql statement, and id 703156990 retrieved. I think ( I do not have exact info yet ), PostgreSQL adapter or PostgreSQL database inserts id which is larger than other ids.

  Face Load (1.2ms)  SELECT "faces".* FROM "faces" WHERE "faces"."man_id" = $1 ORDER BY "faces"."id" ASC LIMIT 1  [["man_id", 380377255]]

I said this issue does not reproduce with 3-2-stable and here is the reason.

At ActiveRecord::Associations::SingularAssociation#find_target

$ ARCONN=oracle ruby -Itest test/cases/associations/inverse_associations_test.rb -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method
Using oracle with Identity Map off
Run options: -n test_parent_instance_should_be_shared_with_newly_created_child_via_bang_method

# Running tests:

[39, 48] in /home/yahonda/git/rails/activerecord/lib/active_record/associations/singular_association.rb
   39          end
   40
   41          def find_target
   42            require 'debugger'
   43            debugger
=> 44            scoped.first.tap { |record| set_inverse_instance(record) }
   45          end
   46
   47          # Implemented by subclasses
   48          def replace(record)
/home/yahonda/git/rails/activerecord/lib/active_record/associations/singular_association.rb:44
scoped.first.tap { |record| set_inverse_instance(record) }
(rdb:1) puts scoped.first.inspect
#<Face id: 413266651, description: "trusting", man_id: 970345986, polymorphic_man_id: nil, polymorphic_man_type: nil, horrible_polymorphic_man_id: nil, horrible_polymorphic_man_type: nil>
nil
(rdb:1)

Here, scoped.first calls following sql statement, which should not generate 'correct' results therefore fixed in master or maybe Arel.

D, [2013-02-14T07:07:39.437978 #3032] DEBUG -- :   Face Load (2.6ms)  SELECT "FACES".* FROM "FACES" WHERE "FACES"."MAN_ID" = 970345986 AND ROWNUM <= 1

Bottom line

  • This is not a showstopper for Rails master branch
  • It can workaround by setting higher initial sequence value (See yahonda/oracle-enhanced@7998bc9), which will not be merged.
  • It should be addressed by inserting higher value if other id values are higher than initial value at Oracle enhanced adapter.
@rafaelfranca
Ruby on Rails member

@yahonda thank you for the detailed report. Is there something that we can do in our side?

@yahonda

@rafaelfranca

I'm going to investigate at oracle enhanced adapter first. If I need some help / issues to address this at rails, I'm going to open a new one.

@yahonda yahonda closed this Feb 14, 2013
@rafaelfranca
Ruby on Rails member

OK. Thank you

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