closing task generates 'Version has already been taken' error

[KevinJW]

a new issue but relates to #467.

dragging a task to the done column, or updating from the chiliproject issue page, generate the above error, useful(?) bit out of the log below. What I'm personally assuming is that second select query has an invalid journaled_id of 0 as who knows what that id is for it is not for issue 459 that is for sure :-) The version of 4 looks correct if the journaled_id was set to the correct issue.

Backlogs code in question is from:

.../vendor/plugins/redmine_backlogs/lib/backlogs_issue_patch.rb:147:in backlogs_after_save' .../vendor/plugins/redmine_backlogs/lib/backlogs_issue_patch.rb:123:ineach' .../vendor/plugins/redmine_backlogs/lib/backlogs_issue_patch.rb:123:in `backlogs_after_save'

The second SQL call appears to be made during the save! call when the validations are run

Completed in 47ms (View: 1, DB: 5) | 200 OK [http://help/rb/updated_items/4?only=tasks,impediments&since=May+15%2C+2012+11%3A00%3A52.016571117401123] ^[[4;35;1mSQL (0.5ms)^[[0m ^[[0mSELECT max("journals".version) AS max_version FROM "journals" WHERE (journaled_id = 459 and type = 'IssueJournal') ^[[0m ^[[4;36;1mJournal Load (0.4ms)^[[0m ^[[0;1mSELECT "journals".id FROM "journals" WHERE ("journals"."version" = 4 AND "journals"."journaled_id" = 0 AND "journals"."type" = 'IssueJournal') LIMIT 1^[[0m ^[[4;35;1mSQL (0.4ms)^[[0m ^[[0mROLLBACK^[[0m

ActiveRecord::RecordInvalid (Validation failed: Version has already been taken): app/models/issue.rb:805:in recalculate_attributes_for' app/models/issue.rb:769:inupdate_parent_attributes' app/models/issue.rb:596:in save_issue_with_child_records' app/models/issue.rb:579:insave_issue_with_child_records'

[KevinJW]

Creating a task for the same feature also gives the same error and 351 lines of log output for a single create I'll ensure it is sanitized enough to post...

[KevinJW]

https://gist.github.com/2711852 has the full 'create task 509 for story 50' the id 120 is a closed task also associated to 50 if that helps at all.

[KevinJW]

I'm wondering why you have the explicit version number selection code circa line 145 in vendor/plugins/redmine_backlogs/lib/backlogs_issue_patch.rb, when it appears that the version should be automatically assigned. I know you are suggesting earlier on about recursive calls being triggered which makes sense but I can't see why you need to explicitly set it...

If I disable that line I get two records added to the journal when closing a task changing status_id and setting remaining_hours in the first, then a second journal entry changing estimated_hours. On and of course the task is closed :-)

[retorquere]

Sorry, line number have changed in the interim, so I can't match them against the current code. If you disable the line that says

j.version = (Journal.maximum('version', :conditions => ['journaled_id = ? and type = ?', task.id, 'IssueJournal']) || 0) + 1

you say that stuff just works?

[KevinJW]

Yes, which is why I was wondering if there were some edge cases related to something I may have missed...

[retorquere]

No, it could well have been something I've missed. I added that because I couldn't get it to save the journal record otherwise. I'll run the tests without it.

[retorquere]

Seems to work, closing

[KevinJW]

now, I have a different variant of the problem.

If I move a task 520 attached to a story 421 in a sprint to a different story 521 in another sprint I get the same validation error, but an 800 + line log output for my debugging delight :-)

[retorquere]

Could you post that log output somewhere?

[KevinJW]

http://temp-share.com/show/HKdPfyiyA

[retorquere]

Which version of redmine do you use? The log complains about "app/models/issue.rb:805:in `recalculate_attributes_for'", but line 805 of issues.rb from 1.4.2 does not contain code for recalculate_attributes_for.

[KevinJW]

Chiliproject v3.1.0 was that particular log

[retorquere]

Could you try latest master?

[KevinJW]

I can, but this particular aspect of the problem occurred previously even with the version being set, not setting the version fixes the more common cases of just moving tasks on the task board... I'll work out when I can update and let you know.

Kevin

[retorquere]

Damn, I forgot that one. How can that version be a duplicate anyway that way? Can you get me the steps to reproduce the problem given the current master? I've been looking to find where journal.version gets set anyway.

[retorquere]

Would it be possible to get a "starter database" from you so I can reproduce this locally?

[retorquere]

Could you try the code in the 544 branch?

[KevinJW]

Sure :-)

Dunno, my only thought is that something is setting the journaled_id to 0, I suspect this is to do with when things actually get written to the database and for some reason there are two journal entries being generated, but the second one doesn't pick up the first one's change as it has not yet hit the database so they both try to write the same version number. At this point I'm suspecting something to do with the way the status of parent tasks and their children get automagically updated. If you look at the very bottom of that log, I pasted a more complete stack trace which shows multiple traces through the active record stack ( which I now know far more about that I used to :-)

re my previous comment, I've now also seen your change to remove the hard coding of the journal type, that would be a new situation I suppose if the other change was of the wrong type they could collide.

I'll work on duplicating a small test db on a separate machine, that should be easier to play with different branches.

Thanks

Kevin

[retorquere]

If there are no privacy issues I don't care how large the DB is.

[KevinJW]

Unfortunately there are privacy issues, I've also been involved with some other things the last day so I did no get a chance to try the other version, I'll see if I can schedule it today/tomorrow morning

I'll start with the 'easy' bumping the running install up to the latest release, then I'll look at my test environment machine and bring that onto the branch version.

Thanks

Kevin

[retorquere]

Not latest release, but the 554 branch please. On May 30, 2012 4:49 PM, "Kevin Wheatley" < reply@reply.github.com> wrote:

Unfortunately there are privacy issues, I've also been involved with some other things the last day so I did no get a chance to try the other version, I'll see if I can schedule it today/tomorrow morning

I'll start with the 'easy' bumping the running install up to the latest release, then I'll look at my test environment machine and bring that onto the branch version.

Thanks

Kevin

---

Reply to this email directly or view it on GitHub:

https://github.com/backlogs/redmine_backlogs/issues/544#issuecomment-6011758

[KevinJW]

OK running with mysql, CP v3.1.0 backlogs branch 554 via webrick...

from the backlog view: create sprint 1 create sprint 2 create story 1 under sprint 1 create story 2 under sprint 2

go to task board for sprint 1 create a task under story 1

click through the task id to view the issue update the issue parent id to be the one for story 2 and hit save...

Cache hit: chiliproject/setting/1338466557/plugin_redmine_backlogs ({}) CACHE (0.0ms) SELECT * FROM trackers WHERE (trackers.id IN ('2','3')) Issue Load (0.4ms) SELECT * FROM issues WHERE (root_id=15 and lft>3 and rgt<6 and ( (9 is NULL and not fixed_version_id is NULL) or (not 9 is NULL and fixed_version_id is NULL) or (not 9 is NULL and not fixed_version_id is NULL and 9<>fixed_version_id) )) SQL (0.3ms) SELECT max(journals.version) AS max_version FROM journals WHERE (journals.journaled_id = 15) AND ( (journals.type = 'IssueJournal' ) ) Journal Load (7.4ms) SELECT journals.id FROM journals WHERE (journals.version = 2 AND journals.journaled_id = 0 AND journals.type = 'IssueJournal') LIMIT 1 Journal Create (0.3ms) INSERT INTO journals (type, journaled_id, created_at, activity_type, changes, user_id, version, notes) VALUES('IssueJournal', 0, '2012-05-31 13:12:39', 'issues', NULL, 1, 2, NULL) Journal Load (0.3ms) SELECT * FROM journals WHERE (journals.id = 0) SQL (31.4ms) ROLLBACK

NoMethodError (undefined method touch' for nil:NilClass): app/models/journal.rb:46:intouch_journaled_after_creation' app/models/issue.rb:805:in recalculate_attributes_for' app/models/issue.rb:769:inupdate_parent_attributes' app/models/issue.rb:596:in save_issue_with_child_records' app/models/issue.rb:579:insave_issue_with_child_records' app/controllers/issues_controller.rb:158:in update' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/httpserver.rb:104:inservice' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/httpserver.rb:65:in run' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:173:instart_thread' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:162:in start' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:162:instart_thread' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:95:in start' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:92:ineach' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:92:in start' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:23:instart' /home/hxpro/.rvm/rubies/ruby-1.8.7-p358/lib/ruby/1.8/webrick/server.rb:82:in `start'

Undefined method clearly comes from the loss of the associated 'task' but prior to that the journaled_id is 15, then suddenly it gets reset to 0 and that is when things break.

[KevinJW]

FWIW the error still appears on the main server with the latest tag'd v0.9.9 but we expected that I guess.

[retorquere]

Could you try the freshly pushed 544 branch?

[KevinJW]

ActiveRecord::AssociationTypeMismatch (Journal(#70265426563520) expected, got Issue(#70265425553560)): app/models/issue.rb:805:in recalculate_attributes_for' app/models/issue.rb:769:inupdate_parent_attributes' app/models/issue.rb:596:in save_issue_with_child_records' app/models/issue.rb:579:insave_issue_with_child_records' app/controllers/issues_controller.rb:158:in `update'

[retorquere]

OK, and if you comment out line 213 in lib/backlogs_issue_patch.rb to read #j.type = 'IssueJournal' ?

[KevinJW]

same, although it looks like it is always set anyway in the logs...

[KevinJW]

There looks to be a depreciated method which does the j.journalized => j.journaled forwarding anyway.

[retorquere]

That's what I'm thinking, the "type" attribute is set by the polymorph method. So, this works then?

[KevinJW]

the type is always set to 'IssueJournal' even with the commented out line.

The ActiveRecord::AssociationTypeMismatch (Journal(#69864891095620) expected, got Issue(#69864890096060)):

still occurs.

[KevinJW]

I'm assuming you meant line 139 of 213 BTW

[retorquere]

Uh yeah, that. New version om 544.

[KevinJW]

Interesting... I notice that the journaled_id is now not zero, in this case Issue 15 is the story 1 and 16 is the destination story #2, so getting the max on the old one and using it on the other one some how??

SQL (0.3ms) SELECT max(journals.version) AS max_version FROM journals WHERE (journals.journaled_id = 15) AND ( (journals.type = 'IssueJournal' ) ) Journal Load (0.2ms) SELECT journals.id FROM journals WHERE (journals.version = 2 AND journals.journaled_id = 16 AND journals.type = 'IssueJournal') LIMIT 1 SQL (46.2ms) ROLLBACK

ActiveRecord::RecordInvalid (Validation failed: Version has already been taken): app/models/issue.rb:805:in recalculate_attributes_for' app/models/issue.rb:769:inupdate_parent_attributes' app/models/issue.rb:596:in save_issue_with_child_records' app/models/issue.rb:579:insave_issue_with_child_records' app/controllers/issues_controller.rb:158:in `update'

[KevinJW]

I got that wrong, sorry, issue 14 is the old story, 15 the new story, 16 is the Task Issue

[retorquere]

I really need a db I can reproduce this on. If you want I could refresh the anonimizer task so you could get me a copy of yours sans the privacy issues.

[KevinJW]

I checked the DB, each journal for each issue involved has only a single version prior to starting he transaction, so I guess it is still colliding as part of the updates made during the request. I guess it should use the updated task's version to get the next one.

[KevinJW]

in this case I've used a pretty empty database I'll run a dump and work out where we can host it.

[retorquere]

Dammit, of course it should. I'll get it fixed when I get home.

[retorquere]

New version on the 544 branch

[KevinJW]

I've just sent a pull request for the use of a private variable... this now appears to work, but would appreciate your looking at it.

Thanks

Kevin