Failed to migrate from 1.2.0 to 2.1.0 with Ruby 1.9.2 (Bug #554)

I assume problem is because 1.x branch was not supposed to run with Ruby 1.9.2, so probably we need no fix for this issue, but a notice about migration process.

Admittedly I am trying to upgrade from Redmine (1.2.0) to Chiliproject, but I am seeing a similar problem on Ruby 1.8.7:

Change(#-617066458) expected, got Array(#-607918318)
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations/association_proxy.rb:259:in `raise_on_type_mismatch'
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations/association_collection.rb:321:in `replace'
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations/association_collection.rb:321:in `each'
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations/association_collection.rb:321:in `replace'
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations.rb:1331:in `changes='
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations/association_proxy.rb:149:in `send'
/var/lib/gems/1.8/gems/activerecord-2.3.12/lib/active_record/associations/association_proxy.rb:149:in `send'
....

[root@projects2]# ruby --version
ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-linux]
[root@projects2]# /var/lib/gems/1.8/bin/rake --version
rake, version 0.9.2

For what it's worth I experienced the same problem. We upgrade from Redmine 1.1.2 to ChiliProject 1.5.2 (We did this because the DB migration failed for the later versions.) Trying to upgrade ChiliProject from 1.5.2 to 2.X.X caused the db migration to fail with an output as seen in issue #554. This is preventing us from using ChiliProject.

I think I've hit a similar problem. I'm coming from Redmine v 0.9.3.stable (mysql) and trying to upgrade to latest Chiliproject using instructions here: https://www.chiliproject.org/projects/chiliproject/wiki/Upgrade

I am running ruby 1.8.7:

$/usr/bin/ruby -v
ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

I first restored the mysql db from backup, replaced the redmine directory w/ the latest Chiliproject, copied over database.yml, created configuration.yml from the example, did bundle install, generated session store and then...

Here is a stack trace when trying to migrate the db:

$ rake db:migrate RAILS_ENV=production --trace
** Invoke db:migrate (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute db:migrate
==  BuildInitialJournalsForActsAsJournalized: migrating =======================
-- Building initial journals for Message
   -> 0.8706s
-- Building initial journals for Attachment
   -> 61.4480s
-- Building initial journals for Document
   -> 8.1766s
-- Building initial journals for Changeset
rake aborted!
An error has occurred, all later migrations canceled:

Change(#70002589826020) expected, got Array(#70002672113180)
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:259:in `raise_on_type_mismatch'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `replace'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `each'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `replace'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations.rb:1331:in `changes='
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:149:in `send'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:149:in `send'
/usr/share/chiliproject/app/models/journal.rb:111:in `method_missing'
/usr/share/chiliproject/vendor/plugins/acts_as_journalized/lib/redmine/acts/journalized/creation.rb:91:in `recreate_initial_journal!'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:44:in `up_without_benchmarks'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:40:in `each'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:40:in `up_without_benchmarks'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:328:in `say_with_time'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:328:in `say_with_time'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:29:in `up_without_benchmarks'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:28:in `each'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:28:in `up_without_benchmarks'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `send'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `migrate'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:365:in `__send__'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:365:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:491
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:567:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:567:in `ddl_transaction'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:490:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:477:in `each'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:477:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:401:in `up'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:383:in `migrate'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.14/lib/tasks/databases.rake:112
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:205:in `call'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:205:in `execute'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:200:in `each'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:200:in `execute'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:158:in `invoke_with_call_chain'
/usr/lib/ruby/1.8/monitor.rb:242:in `synchronize'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:151:in `invoke_with_call_chain'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/task.rb:144:in `invoke'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:112:in `invoke_task'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:90:in `top_level'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:90:in `each'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:90:in `top_level'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:129:in `standard_exception_handling'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:84:in `top_level'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:62:in `run'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:129:in `standard_exception_handling'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/lib/rake/application.rb:59:in `run'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2/bin/rake:32
/usr/bin/rake:19:in `load'
/usr/bin/rake:19
Tasks: TOP => db:migrate

By far not a ruby expert, and thus this error is also preventing us from using Chiliproject at the moment.

I think the title of this issue is misleading. This seems to be an issue with moving from Redmine to ChiliProject 2.X.0. After further investigation we still get basically the same error when using Ruby 1.8.7 when attempting to migrate from Redmine 1.1.1, Redmine 1.2.1, or Redmine 1.1.1 -> ChiliProject 1.5.X, to any version of ChiliProject 2.X.X. If desired I can open a different issue but it will contain no new information. Any assistance from those who more deeply understand ChiliProject would be appreciated, by several potential users. Thanks.

Another stack trace:

rake db:migrate --trace
** Invoke db:migrate (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute db:migrate
==  BuildInitialJournalsForActsAsJournalized: migrating =======================
-- Building initial journals for Message
   -> 0.0030s
-- Building initial journals for Attachment
   -> 0.2310s
-- Building initial journals for Document
   -> 0.0030s
-- Building initial journals for Changeset
rake aborted!
An error has occurred, all later migrations canceled:

Change(#3882) expected, got Array(#3884)
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:259:in `raise_on_type_mismatch'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `replace'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `replace'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations.rb:1331:in `changes='
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:149:in `send'
../chiliproject-2.2.0/app/models/journal.rb:111:in `method_missing'
../chiliproject-2.2.0/vendor/plugins/acts_as_journalized/lib/redmine/acts/journalized/creation.rb:91:in `recreate_initial_journal!'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:44:in `up'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:40:in `up'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:328:in `say_with_time'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:328:in `say_with_time'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:29:in `up'
./db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:28:in `up'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `migrate'
/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:365:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:491:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:567:in `ddl_transaction'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:490:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:477:in `migrate'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:401:in `up'
/usr/lib/ruby/gems/1.8/gems/activerecord-2.3.14/lib/active_record/migration.rb:383:in `migrate'
/usr/lib/ruby/gems/1.8/gems/rails-2.3.14/lib/tasks/databases.rake:112:in `(root)'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/task.rb:205:in `execute'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `execute'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/task.rb:158:in `invoke_with_call_chain'
/usr/lib/ruby/1.8/monitor.rb:191:in `mon_synchronize'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/task.rb:151:in `invoke_with_call_chain'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/task.rb:144:in `invoke'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:116:in `invoke_task'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `top_level'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `top_level'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:133:in `standard_exception_handling'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:88:in `top_level'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:66:in `run'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:133:in `standard_exception_handling'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/lib/rake/application.rb:63:in `run'
/usr/lib/ruby/gems/1.8/gems/rake-0.9.2.2/bin/rake:33:in `(root)'
/usr/bin/rake:19:in `(root)'
Tasks: TOP => db:migrate

When I was putting the title - I was describing MINE problem :)) More than 100% sure that you have same problem, so probably title should be renamed though...

I can send you the dump on e-mail. It contains some confidetial information, but I'm OK to send it without any agreement unless you are going to "share" it ;))

Aleksey Zapparov wrote:

I can send you the dump on e-mail. It contains some confidetial information, but I'm OK to send it without any agreement unless you are going to "share" it ;))

I'll make sure to be careful. My address is on my user page. Thanks!

Hello,
I fiddled around with the problem. My last guess is, that the problem is related to the fact, that
in:

.../acts_as_journalized/lib/redmine/acts/journalized/creation.rb

recreate_initial_journal

new_journal.changes = creation_changes

My guess is now, that the order, how methods are evaluated, respective how the methods are mapped (do not know how to say properly) a difference may be between 1.8 and 1.9. Anyway, I think the reason for the problem is, that in Changesets a table changes is defined. Therefore also from Active Record a methode "changes" is defined. But for the table changes the creation_changes does not fit, because that fits to changesets. I have written a little more in the forum:
https://www.chiliproject.org/boards/1/topics/901?r=910

Hello,
first sorry for my bad english (I should read what I write before I send it).
I had a look into

app/models/journal.rb

def changes
  changed.inject({}) {|h, attr| h[attr] = attribute_change(attr); h}
end

Hello,
I have not tracked down the problem fully yet. But I assume a clean solution would be either to rename the table changes to something like changeitems or to
rename the method changes to something as journal_changes. I assume otherwise there needs somewhere somethings as a condition to check if the method was called on changesets or onother class to route
the method there properly. But as I wrote. Is only a assumption.

The problem is a bad case of method_missing magic somewhat sidestepping ActiveRecord's own method_missing magic at source:/app/models/journal.rb@9107023#L110.

The good news: I think that should be solvable.

The gory details: Journal#method_missing checks to see if the method is also the name of one of its attributes, calls the method on the journaled object if not and only then tries to call the method on itself if the call to the journaled object throws a NoMethodError, which then eventually triggers the ActiveRecord::Base#method_missing, which might do stuff with it. This works most of the times, the times it doesn't work is if AR provides a method_missing mechanism for the called method but the journaled object implements the same method. The method is then called on the journaled object instead of on the journal, and mayhem ensues.

In this particular case, journals have an attribute called changes, which the migration script tries to set by calling #changes=, which isn't explicitly implemented, so it bubbles up to method_missing, which checks the attributes, finds "changes=" isn't one of them, calls #changes= on the journaled object, which none of them but the Changesets implement, so it goes back to the journal which tries to call it on itself again, which bubbles up to AR's method_missing, which in turn knows the changes column and that a call to #changes= is an attempt to write stuff to it. For Changesets, this breaks though because Changeset#changes= exists (because of has_many :changes in changesets), the call tries to apply the array of changes the journal should receive to the journaled Changeset object.

(and sorry that this one took this long…)

Hello Felix,
Thank you very much for the fix. I tried it out. The migration worked smoothly with it.

Best regards,
Tammo

Felix Schäfer wrote:

The problem is a bad case of method_missing magic somewhat sidestepping ActiveRecord's own method_missing magic at source:/app/models/journal.rb@9107023#L110.

Ugh. I had a feeling that method was going to be a problem later on. I wonder if it's even used or if we could remove it.

Eric Davis wrote:

I had a feeling that method was going to be a problem later on. I wonder if it's even used or if we could remove it.

I think I've seen it used in at least one instance, I agree that we should work towards doing without it though.

I pulled the latest code and tried the migration again w/ similar results. I opened a new bug about it. Please let me know if I am missing something here.

https://www.chiliproject.org/issues/690