Redmine, awesome_nested_set, Issue.rebuild!, lock_version and ActiveRecord::StaleObjectError

Today I got a task to restructure about 400 issues in our Redmine instance. I should create a hierarchy and reparent existing issues under new ones. All the issues have a lot of related ones. But when I tried to modify parent issue field I got “Parent task is invalid” message after saving. I found pages about this problem and the only solution: remove relations, reparent the issue and recreate relations… 400 issues with a lot of relations… No.

I was updating the database instead: set the issues.parent_id to the appropriate new value. Naturally after that two things went wrong: some aggregated values e.g. estimated_hours and the hierarchy view, because of awesome_nested_set gem was used which stores hierarchy speedup values in rgt and lft fields of that table. First of all I fired out these fields in database (11840 was my main root issue):

UPDATE issues 
SET 
  rgt=null, 
  lft=null 
WHERE parent_id=11840

Than the following command needs to run in redmine root dir:

RAILS_ENV=production ruby script/rails runner Issue.rebuild!

After a long run, error occured:

ActiveRecord::StaleObjectError: ActiveRecord::StaleObjectError
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/locking/optimistic.rb:90:in `update'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/attribute_methods/dirty.rb:74:in `update'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/timestamp.rb:71:in `update'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/callbacks.rb:272:in `update'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:403:in `_run__1446014408__update__4__callbacks'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:405:in `send'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:405:in `__run_callback'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:385:in `_run_update_callbacks'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:81:in `send'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:81:in `run_callbacks'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/callbacks.rb:272:in `update'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/persistence.rb:348:in `create_or_update'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/callbacks.rb:264:in `create_or_update'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:590:in `_run__1446014408__save__4__callbacks'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:405:in `send'
from /var/lib/gems/1.8/gems/activesupport-3.2.19/lib/active_support/callbacks.rb:405:in `__run_callback'
... 18 levels...
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation/delegation.rb:6:in `__send__'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation/delegation.rb:6:in `each'
from /var/lib/gems/1.8/gems/awesome_nested_set-2.1.6/lib/awesome_nested_set/awesome_nested_set.rb:203:in `rebuild!'
from /var/lib/gems/1.8/gems/awesome_nested_set-2.1.6/lib/awesome_nested_set/awesome_nested_set.rb:213:in `call'
from /var/lib/gems/1.8/gems/awesome_nested_set-2.1.6/lib/awesome_nested_set/awesome_nested_set.rb:213:in `rebuild!'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation/delegation.rb:6:in `each'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation/delegation.rb:6:in `__send__'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation/delegation.rb:6:in `each'
from /var/lib/gems/1.8/gems/awesome_nested_set-2.1.6/lib/awesome_nested_set/awesome_nested_set.rb:210:in `rebuild!'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/scoping/default.rb:41:in `unscoped'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation.rb:241:in `scoping'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/scoping.rb:98:in `with_scope'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/relation.rb:241:in `scoping'
from /var/lib/gems/1.8/gems/activerecord-3.2.19/lib/active_record/scoping/default.rb:41:in `unscoped'
from /var/lib/gems/1.8/gems/awesome_nested_set-2.1.6/lib/awesome_nested_set/awesome_nested_set.rb:185:in `rebuild!'

After some googling I modified my command:

RAILS_ENV=production ruby script/rails console
irb(main):003:0> Issue.rebuild!

Same error, but instead of long nothinghappens block a lot of SQL statements were scrolling on my screen which indicate what is happening. Here are the interesting last ones:

   ...
   (0.2ms)  UPDATE `issues` SET `lock_version` = 53, `estimated_hours` = NULL, `updated_on` = '2014-11-25 12:29:00' WHERE (`issues`.`id` = 12751 AND `issues`.`lock_version` = 52)
   ...
   (0.1ms)  UPDATE `issues` SET `lock_version` = 53, `lft` = 388, `updated_on` = '2014-11-25 12:29:02', `rgt` = 419 WHERE (`issues`.`id` = 12751 AND `issues`.`lock_version` = 52)
   (0.1ms)  ROLLBACK

So it seems that the ActiveRecord contexts used by Redmine and nested set’s rebuilder differ: Redmine collects info about aggregated values and updates the record and the other one wants to update the hierarchy fields. Optimistic concurrency fails here.

My solution: stop Redmine and run this command in ruby console before Issure.rebuild!:

irb(main):003:0> ActiveRecord::Base.lock_optimistically = false

This will turn off concurrency locking in Your process so script will run. It seems the fields updated are not overlapped so running without locking is not a problem.

Leave a Reply