#3689 Observer callback ordering with touched associations is unexpected - Ruby on Rails

Type	To find
responsible:me	tickets assigned to you
tagged:"@high"	tickets tagged @high
milestone:next	tickets in the upcoming milestone
state:invalid	tickets with the state invalid
created:"last week"	tickets created last week
sort:number, importance, updated	tickets sorted by #, importance or updated
Combine keywords for powerful searching.
Use advanced searching »

This project is archived and is in readonly mode.

#3689 ✓stale

Observer callback ordering with touched associations is unexpected

Reported by Geoff Garside | January 13th, 2010 @ 05:30 PM

I've got a situation where I have a model which has an observer, I'm using the accepts_nested_attributes_for method to allow the model to save its associated children in the form. When the observer runs I'm not getting the after_create callback fired but rather the after_update callback, which explodes fantastically.

I've written a test case to demonstrate this behaviour and it looks like the update is being done before the create. The test result is the following

  1) Failure:
test_observer_callbacks_called_on_create_with_touched_association(BunnyObserversTest)
    [./test/cases/touch_association_callbacks_observers_test.rb:48:in `test_observer_callbacks_called_on_create_with_touched_association'
     ./test/cases/../../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `__send__'
     ./test/cases/../../../activesupport/lib/active_support/testing/setup_and_teardown.rb:62:in `run']:
After callbacks for create not fired in expected order.
<[:after_create, :after_save]> expected but was
<[:after_update, :after_save, :after_create, :after_save]>.

I might have expected :after_create, :after_save, :after_update, :after_save to have been run, but the demonstrated ordering seems incorrect to me.

0001-add-tests-for-ordering-of-observer-callbacks-when-an.patch 3.3 KB

Comments and changes to this ticket

You flagged this item as spam.
Geoff Garside January 14th, 2010 @ 02:25 PM
I believe I've managed to determine the cause for this. Using the classes from the provided test as an example when we do the following
```
bunny = Bunny.new({:name => "foo", carrot_attributes => [{:rating => 0.2}]})
bunny.save
```
what happens is the following
1. The Bunny instance is persisted to the database
2. The Carrot instance on bunny is persisted to the database, either as part of the create or an early after_save callback
3. The belongs_to_touch_after_save_or_destroy_for_bunny Carrot after_save callback is run
4. belongs_to_touch_after_save_or_destroy_for_bunny calls save! on the bunny object
5. bunny.save! as the object has been persisted to the database performs an UPDATE of the database
6. The BunnyObserver is notified of an UPDATE having occurred and runs its after_update and after_save callbacks
7. The adding of the Carrot instance to the Bunny returns
8. The Bunny instance save method which is creating the object runs its after_* callbacks
9. The BunnyObserver is notified of an INSERT having occurred and runs its after_create and after_save callbacks
So the call sequence is logical with this understanding, however my expectation for the observer call sequence is different from the resulting sequence.
You flagged this item as spam.
Geoff Garside January 14th, 2010 @ 02:46 PM
I'm not sure at the moment how to fix this within rails itself, for now though I've got the following to work in my observer
```
class BunnyObserver < ActiveRecord::Observer
  def after_create(record)
    # .. do something with record ..
  end
  def after_update(record)
    return if in_create_stack?
    # .. do something with record ..
  end
  private
    def in_create_stack?
      caller.any? {|c| c =~ /`create'/ }
    end
end
```
its a bit of a hack with an aroma of roquefort but it is at the very least working and would seem to function in both Ruby 1.8 and Ruby 1.9.

If any better solutions or fixes can be offered then I'd be happy to add a better aroma to my code.
Rohit Arondekar October 8th, 2010 @ 02:51 AM
- State changed from “new” to “stale”
- Importance changed from “” to “Low”
Marking ticket as stale. If this is still an issue please leave a comment with suggested changes, creating a patch with tests, rebasing an existing patch or just confirming the issue on a latest release or master/branches.
Ryan Bigg October 9th, 2010 @ 10:01 PM
- Tag cleared.
Automatic cleanup of spam.