ChiliProject is not maintained anymore. Please be advised that there will be no more updates.

We do not recommend that you setup new ChiliProject instances and we urge all existing users to migrate their data to a maintained system, e.g. Redmine. We will provide a migration script later. In the meantime, you can use the instructions by Christian Daehn.

Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0

Added by Tammo Tjarks at 2011-11-02 03:40 pm

Hello,
when I run

rake db:migrate RAILS_ENV=production --trace

for migration from redmine 1.1.1 to chiliproject 2.4.0 I got the following stack trace:
** Invoke db:migrate (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute db:migrate
==  BuildInitialJournalsForActsAsJournalized: migrating =======================
-- Building initial journals for Message
   -> 0.0011s
-- Building initial journals for Attachment
   -> 1.8178s
-- Building initial journals for Document
   -> 0.0278s
-- Building initial journals for Changeset
rake aborted!
An error has occurred, all later migrations canceled:

Change(#39287780) expected, got Array(#3333340)
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:259:in `raise_on_type_mismatch'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `block in replace'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/associations/association_collection.rb:321:in `replace'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/associations.rb:1331:in `block in collection_accessor_methods'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/associations/association_proxy.rb:149:in `send'
/home/lib_tcqa/bugtracker/chiliproject-2.4.0/app/models/journal.rb:112:in `method_missing'
/home/lib_tcqa/bugtracker/chiliproject-2.4.0/vendor/plugins/acts_as_journalized/lib/redmine/acts/journalized/creation.rb:92:in `recreate_initial_journal!'
db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:45:in `block (3 levels) in up'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/batches.rb:26:in `block (2 levels) in find_each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/batches.rb:26:in `each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/batches.rb:26:in `block in find_each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/batches.rb:66:in `find_in_batches'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/batches.rb:25:in `find_each'
db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:41:in `block (2 levels) in up'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:328:in `block in say_with_time'
/opt/ruby/1.9.2/lib/ruby/1.9.1/benchmark.rb:295:in `measure'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/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:30:in `block in up'
db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:29:in `each'
db/migrate//20100714111653_build_initial_journals_for_acts_as_journalized.rb:29:in `up'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `block in migrate'
/opt/ruby/1.9.2/lib/ruby/1.9.1/benchmark.rb:295:in `measure'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:282:in `migrate'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:365:in `migrate'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:491:in `block (2 levels) in migrate'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:567:in `call'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:567:in `ddl_transaction'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:490:in `block in migrate'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:477:in `each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:477:in `migrate'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:401:in `up'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/activerecord-2.3.14/lib/active_record/migration.rb:383:in `migrate'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rails-2.3.14/lib/tasks/databases.rake:112:in `block (2 levels) in <top (required)>'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:205:in `call'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:205:in `block in execute'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:200:in `execute'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:158:in `block in invoke_with_call_chain'
/opt/ruby/1.9.2/lib/ruby/1.9.1/monitor.rb:201:in `mon_synchronize'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:151:in `invoke_with_call_chain'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/task.rb:144:in `invoke'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:116:in `invoke_task'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `block (2 levels) in top_level'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `each'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:94:in `block in top_level'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:133:in `standard_exception_handling'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:88:in `top_level'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:66:in `block in run'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:133:in `standard_exception_handling'
/opt/ruby/1.9.2/lib/ruby/gems/1.9.1/gems/rake-0.9.2.2/lib/rake/application.rb:63:in `run'
/opt/ruby/1.9.2/bin/rake:33:in `<main>'
Tasks: TOP => db:migrate

I do not have any clue where to search for the cause of the error. An Idea was, that the script has trouble when several files where modified with one commit. But I do not know how to debug this. Or should I remove/disable the act_as_journalized for the start?

Regards,
Tammo


Replies (9)

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Holger Just at 2011-11-02 03:56 pm

That exact issue is currently handled in #554. Unfortunately, we haven't been able to reproduce the issue yet so we don't know how to actually fix that. But we are working on it. You might want to follow #554 for updates on this issue.

--Holger

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 04:16 pm

Hello Holger,
thank you very much for your fast reply. Can the reason for the problem be, that there is already a table journals. Or can it be, that under one commit in changes are several files? Can it be, that some plugin in redmine caused the problem, because it already
created tables, which are assumed not to exist? Sorry for the questions. The problem is, that with this metaprogramming thing the code is hard to follow. I have seen where Change is defined. But not where record comes from. I have seen that there is
@reflection defined. I assume the type Change for that is OK right? Then the problem is, that I get an Array for the record. I assume the record comes from the database right? Where can I see from which table it is loaded?

Best regards,
Tammo

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Holger Just at 2011-11-02 04:33 pm

Yes it's true that we use some nifty meta-programming for the journals implementation. On the other hand this allows us to keep the implemented API rather clean and extensible.

However, from what I know until know the issues probably probably results from a difference between Ruby 1.8.7 and 1.9.2 as the issue was only observed on 1.9.2 yet. I highly doubt it has anything to do with your actual data in the database.

That said we have to take a deeper look on the actual data after we managed to reproduce the issue. I really can't say anything more than this at the moment, other than that we are working on it. Sorry for that. If you are in a hurry you might want to consider using Ruby 1.8.7 to run the migration. After that, Ruby 1.9.2 should work just fine with ChiliProject 2.4.

--Holger

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 05:52 pm

Hello Holger,
I had a look and have a suspicion. I first tried a clean debuger approach but ended in the messy puts statement approach.
In the record he complaints about are three entries. I think the problem could also be related to the fact if you use git or subversion.
There are several files/directories committed together. This entries of the table changes have the same
changeset_id. I think if you use the changeset_id to select the changes you get an array, maybe "id" should be used. There the number is unique.
The entries of the array itself are of the type "String". But I think it is strange, if that is the reason for the problem, because usually it should not be a problem, if a changeset has several changes?
I do not know, how the database structure would look like if it works.
When I use the puts Statements I get for the expected type (@reflection.inspect):
-----
#<ActiveRecord::Reflection::AssociationReflection:0x00000001e54510 @macro=:has_many, @name=:changes, @options={:dependent=>:delete_all, :extend=>[]}, @active_record=Changeset(id: integer, repository_id: integer, revision: string, committer: string, committed_on: datetime, comments: text, commit_date: date, scmid: string, user_id: integer), @collection=true, @class_name="Change", @primary_key_name="changeset_id", @klass=Change(id: integer, changeset_id: integer, action: string, path: string, from_path: string, from_revision: string, revision: string, branch: string), @quoted_table_name="`changes`">
------
I am not familiar with rails (I use more ruby standalone) anyway, the @macro=:has_many, looks to me as if the class should accept also a record array. The entries of the array would fit to the changes data structure. Is the
@primary_key_name="changeset_id" related to the Changeset or to Changes. I think for Changeset it is OK, but Changes should use ID.
I think it is misleading, that the Error gives with class_name "Change". I got with @reflection.class : ActiveRecord::Reflection::AssociationReflection and I think it should accept
arrays, because :has_many is set. The Change is only a entry. Maybe the problem raised earlier and it is only raised here. I think it is strange, that the class_name gives Change.

I will further look into it.

Regards,
Tammo

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 06:06 pm

Hello Holger,
sorry I had a closer look. When I started pry in the self context I have seent the three change entries, but the variable "record" seems to have different entries. In my case:

record[0] = "comments" 
record[1] = [nil, "first import of structure"]

Regards,
Tammo

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 06:09 pm

I had another look. It seems to come from the changeset table. "comments" is the row-name and "first import of structure" was the first entry for that row.

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 06:41 pm

Hello Holger,
I looked inside

....../activerecord-2.3.14/lib/active_record/associations/association_collection.rb

and have also added a debugging line to start pry there.
I modified it like that:
      def replace(other_array)
        gem 'pry'
        require 'pry'

        {:other_array => other_array, :self => self}.pry
        other_array.each { |val| raise_on_type_mismatch(val) }

Anyway. When I look into the self object it looks reasonable and the objects are of the kind Change.
Furthermore the informations seem to be taken from the "changes" database table:

[#<Change id: 1, changeset_id: 1, action: "A", path: "/bin", from_path: nil, from_revision: nil, revision: nil, branch: nil>,
 #<Change id: 2, changeset_id: 1, action: "A", path: "/drc", from_path: nil, from_revision: nil, revision: nil, branch: nil>,
 #<Change id: 3, changeset_id: 1, action: "A", path: "/lapo", from_path: nil, from_revision: nil, revision: nil, branch: nil>]

Contrary for the "other_array" I get something like:
[4] pry(#<Hash>)> self[:other_array]   
=> {"comments"=>[nil, "first import of structure"],
 "commit_date"=>[nil, Thu, 16 Oct 2008],
 "committed_on"=>[nil, 2008-10-16 09:47:31 +0200],
 "committer"=>[nil, "granigc"],
 "repository_id"=>[nil, 1],
 "revision"=>[nil, "1"],
 "scmid"=>[nil, nil],
 "user_id"=>[nil, nil]}

That data is from the "changesets" database table.

Maybe something I should add. I translated the database before from a sqlite3 database to a mysql database. But I am looking at the database table with knoda and it seems to be OK.

Regards,
Tammo

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 10:57 pm

Hello,
I looked further into it. It seems related to active record as far as I can see. Have found also :

https://github.com/rails/rails/issues/3434

but not sure if it is related. But it is also related to the method collection_accessor_methods.

It seems that Changeset.changes= is called (via method missing in app/models/journal.rb around line 112 . When I check the variables there I get the method

changes=

but the arguments are from changesets.

RE: Error message: Change(#39287780) expected, got Array(#3333340) occured while migrating from redmine 1.1.1 to chiliproject 2.4.0 - Added by Tammo Tjarks at 2011-11-02 11:10 pm

Hello,
me again. I have now the assumption that the problem comes from a name clash. There is in

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

in the method
recreate_initial_journal

(around line 95)
a line
new_journal.changes = creation_changes

I think the problem is, that for Changesets there is a Element changes, so that for Class Changesets the method
changes is already defined from class ActiveRecord for the table changes.

(1-9/9)