Mailing List Archive: Bricolage: devel

Story version corruption

1 2

View All

Index | Next | Previous | View Threaded

rolfm at denison

Jan 21, 2009, 9:15 AM

Post #1 of 27 (7061 views)
Permalink

Story version corruption

Well, we've got the first error message from a story version being
corrupted thanks to our new unique key index on story instance. The
scenerio:

A person checked in a story. The check in failed in some manner, as it
is still on their workflow. If you go to the desk, there is a button
that claims it can be checked out. Attempting to check it out results
in this error in the logs

Unable to execute SQL statement: DBD::Pg::st execute failed: ERROR:
duplicate key violates unique constraint "udx_story__story_instance"\n
[.for Statement "INSERT INTO story_instance (id, name, description,
story__id, version, usr__id, primary_oc__id, slug, cover_date, note,
checked_out)VALUES
(NEXTVAL('seq_story_instance'), ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)" with
ParamValues: 6='1', 3='7616', 7='Overview', 9=undef, 2='',
8='2007-06-20 19:15:00', 1='Overview', 4='11', 10='1', 5='1029'] at /
usr/local/bricolage/lib/Bric/Util/DBI.pm line 1087, <GEN1620> line 68.\n
[/usr/local/bricolage/lib/Bric/Util/DBI.pm:1088]

Which makes sense. Go to the story instance table, though, and we see
this:

id | name | description | story__id | version | usr__id |
slug | primary_oc__id | cover_date | note | checked_out
...
73198 | Overview | | 7616 | 7 | 1366 |
Overview | 1 | 2007-06-20 19:15:00 | | f
73304 | Overview | | 7616 | 8 | 1366 |
Overview | 1 | 2007-06-20 19:15:00 | | f
90836 | Overview | | 7616 | 9 | 1312 |
Overview | 1 | 2007-06-20 19:15:00 | | f
101200 | Overview | | 7616 | 10 | 1312 |
Overview | 1 | 2007-06-20 19:15:00 | | f
101212 | Overview | | 7616 | 11 | 1312 |
Overview | 1 | 2007-06-20 19:15:00 | | f
101799 | Overview | | 7616 | 11 | 1312 |
Overview | 1 | 2007-06-20 19:15:00 | | t

Now we actually have lots of stories that look like this - 435 to be
exact. Most of the time it means that the latest version is being
worked on, and hasn't been checked in yet. But you've got the
database creating a new record with the same version when a story is
checked out, and then incrementing that on checkin. Maybe that is
part of the problem here, and it would be better to increment the
version number on the initial check out - maybe it would help prevent
this sort of thing. But I'm not sure why the checkin partially works,
but leaves a version on her workspace and doesn't increment the
version number.

What do other people think?

-Matt

david at kineticode

Jan 21, 2009, 9:24 AM

Post #2 of 27 (6938 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 21, 2009, at 9:15 AM, Matt Rolf wrote:

> Now we actually have lots of stories that look like this - 435 to be
> exact. Most of the time it means that the latest version is being
> worked on, and hasn't been checked in yet. But you've got the
> database creating a new record with the same version when a story is
> checked out, and then incrementing that on checkin. Maybe that is
> part of the problem here, and it would be better to increment the
> version number on the initial check out - maybe it would help
> prevent this sort of thing. But I'm not sure why the checkin
> partially works, but leaves a version on her workspace and doesn't
> increment the version number.
>
> What do other people think?

I think that a new version should not be created until new content is
checked in.

I added that UNIQUE index to prevent duplicate records from being
created, in the full knowledge that an error would show up elsewhere,
namely in application space. What we need to do is figure out what's
causing the error and fix it.

Are you able to reproduce it?

Best,

David

rolfm at denison

Jan 21, 2009, 9:52 AM

Post #3 of 27 (6963 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 21, 2009, at 12:24 PM, David E. Wheeler wrote:

> I think that a new version should not be created until new content
> is checked in.

Maybe you've explained this before, but what's your rational?

> I added that UNIQUE index to prevent duplicate records from being
> created, in the full knowledge that an error would show up
> elsewhere, namely in application space.

Yep, and it's great that we're now getting that.

> What we need to do is figure out what's causing the error and fix it.
>
> Are you able to reproduce it?

Not reliably but you know that already. But I think this instance
provides more evidence that there's something in the checkin/check out
mechanism that's failing. Maybe the checkin transaction wasn't
complete before the story got checked out again. Maybe it was never
checked in properly.

Going back to Scott's response in this thread

http://www.gossamer-threads.com/lists/bricolage/devel/35284#35284

it looks like work on hardening checkin/checkout could be done. I'm
still not ready to totally rule out session issues myself, but I'll
wait for more evidence to ride that hobby horse.

-Matt

phillip at communitybandwidth

Jan 21, 2009, 10:47 AM

Post #4 of 27 (6952 views)
Permalink

Re: Story version corruption [In reply to]

On 21-Jan-09, at 12:52 PM, Matt Rolf wrote:

>> Are you able to reproduce it?
>>

Whenever I see that error (from time to time) it's usually because:

* Story A is checked out for a while
* Someone publishes Story B and Story B triggers a publish_another for
Story A, which is still checked out
* A new version of Story A is created by the publish_another, but it's
out of sync with the Story A that is one a user's workspace
* When that user tries to check in Story A, the check in fails,
because it's already been incremented one version by the publish_another

I described the problem once here:
http://www.gossamer-threads.com/lists/bricolage/users/35029?#35029

I do find that having checked_in => 1 prevents the state-related
problems, and -- because someone's got the story in question checked
out -- it usually means they're going to republish it anyway, which
achieves the desired result.

HTH,

Phillip.

--
Phillip Smith // Simplifier of Technology // COMMUNITY BANDWIDTH
www.communitybandwidth.ca // www.communitybandwidth.ca/phillipadsmith

rolfm at denison

Jan 21, 2009, 10:50 AM

Post #5 of 27 (6943 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 21, 2009, at 1:47 PM, Phillip Smith wrote:

>
> On 21-Jan-09, at 12:52 PM, Matt Rolf wrote:
>
>>> Are you able to reproduce it?
>>>
>
> Whenever I see that error (from time to time) it's usually because:
>
> * Story A is checked out for a while

In our case, the story was checked out for a week.

phillip at communitybandwidth

Jan 21, 2009, 10:58 AM

Post #6 of 27 (6948 views)
Permalink

Re: Story version corruption [In reply to]

On 21-Jan-09, at 1:50 PM, Matt Rolf wrote:

>
> On Jan 21, 2009, at 1:47 PM, Phillip Smith wrote:
>
>>
>> On 21-Jan-09, at 12:52 PM, Matt Rolf wrote:
>>
>>>> Are you able to reproduce it?
>>>>
>>
>> Whenever I see that error (from time to time) it's usually because:
>>
>> * Story A is checked out for a while
>
> In our case, the story was checked out for a week.

Did another story republish it while it was checked out? If so, that
would seem consistent with my experiences...

--
Phillip Smith // Simplifier of Technology // COMMUNITY BANDWIDTH
www.communitybandwidth.ca // www.communitybandwidth.ca/phillipadsmith

david at kineticode

Jan 21, 2009, 11:01 AM

Post #7 of 27 (6942 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 21, 2009, at 9:52 AM, Matt Rolf wrote:

> On Jan 21, 2009, at 12:24 PM, David E. Wheeler wrote:
>
>> I think that a new version should not be created until new content
>> is checked in.
>
> Maybe you've explained this before, but what's your rational?

See CVS, Subversion, and git.

>> What we need to do is figure out what's causing the error and fix it.
>>
>> Are you able to reproduce it?
>
> Not reliably but you know that already. But I think this instance
> provides more evidence that there's something in the checkin/check
> out mechanism that's failing. Maybe the checkin transaction wasn't
> complete before the story got checked out again. Maybe it was
> never checked in properly.
>
> Going back to Scott's response in this thread
>
> http://www.gossamer-threads.com/lists/bricolage/devel/35284#35284
>
> it looks like work on hardening checkin/checkout could be done. I'm
> still not ready to totally rule out session issues myself, but I'll
> wait for more evidence to ride that hobby horse.

Yeah. One way or another we need to solve this problem. I'm glad at
least we're getting some valuable symptoms!

Best,

David

lannings at who

Jan 22, 2009, 2:11 AM

Post #8 of 27 (6947 views)
Permalink

Re: Story version corruption [In reply to]

On Wed, 21 Jan 2009, Phillip Smith wrote:
> Whenever I see that error (from time to time) it's usually because:
>
> * Story A is checked out for a while
> * Someone publishes Story B and Story B triggers a publish_another for Story
> A, which is still checked out
> * A new version of Story A is created by the publish_another, but it's out of
> sync with the Story A that is one a user's workspace
> * When that user tries to check in Story A, the check in fails, because it's
> already been incremented one version by the publish_another

I've seen something along these lines for the last half year,
since we upgraded to 1.10.x), though I only recently figured
out how to reproduce it (and I didn't try reproducing it in
a vanilla Bricolage). What seems to happen is:
1) you schedule a story to publish, so it gets put in the job queue
2) before the publish job actually runs, you check the story out
3) when the job runs, the publish fails with an error like
"Can't call method "get_id" on an undefined value....".
It seems to be due to sorting of the rows in story_instance when there
are both checked_in and not checked_in versions.
I'll make a bug report, though I'm not sure yet if it
happens in "real" Bricolage.

rolfm at denison

Jan 22, 2009, 5:12 AM

Post #9 of 27 (6923 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 22, 2009, at 5:11 AM, Scott Lanning wrote:

> It seems to be due to sorting of the rows in story_instance when there
> are both checked_in and not checked_in versions.
> I'll make a bug report, though I'm not sure yet if it
> happens in "real" Bricolage.

Sounds to me like it does.

david at kineticode

Jan 22, 2009, 8:20 AM

Post #10 of 27 (6944 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 22, 2009, at 2:11 AM, Scott Lanning wrote:

> It seems to be due to sorting of the rows in story_instance when there
> are both checked_in and not checked_in versions.
> I'll make a bug report, though I'm not sure yet if it
> happens in "real" Bricolage.

That sounds right. We need to make sure that the job uses `checked_out
=> 1` when it selects the story.

Best,

David

lannings at who

Jan 23, 2009, 1:29 AM

Post #11 of 27 (6934 views)
Permalink

Re: Story version corruption [In reply to]

On Thu, 22 Jan 2009, David E. Wheeler wrote:
> On Jan 22, 2009, at 2:11 AM, Scott Lanning wrote:
>> It seems to be due to sorting of the rows in story_instance when there
>> are both checked_in and not checked_in versions.
>> I'll make a bug report, though I'm not sure yet if it
>> happens in "real" Bricolage.
>
> That sounds right. We need to make sure that the job uses `checked_out => 1`
> when it selects the story.

Shouldn't it publish the checked_in version, though?

david at kineticode

Jan 23, 2009, 9:05 AM

Post #12 of 27 (6936 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 23, 2009, at 1:29 AM, Scott Lanning wrote:

>> That sounds right. We need to make sure that the job uses
>> `checked_out => 1` when it selects the story.
>
> Shouldn't it publish the checked_in version, though?

Sorry, yes, that should have been `checked_in => 1`.

Best,

David

rolfm at denison

Feb 3, 2009, 11:47 AM

Post #13 of 27 (6844 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 21, 2009, at 11:58 AM, Phillip Smith wrote:

> Did another story republish it while it was checked out? If so, that
> would seem consistent with my experiences...

Well, not always. Here's the story log for good example from today
(we've had two this week).

Story Checked In 2008-04-07 20:51:11 Version: 5
Story Checked Out 2008-04-07 20:50:21
Story Checked In 2008-04-07 20:50:19 Version: 6
Story Checked Out 2008-04-07 20:46:30
Story Checked In 2008-04-07 20:46:27 Version: 5
Story Moved to Desk 2008-04-07 20:39:17 Desk: Recreation Edit Alerts
Story Checked Out 2008-04-07 20:39:17
Story Moved into Workflow 2008-04-07 20:39:16 Workflow: Recreation
Pages
Story Republished Maintainance, Bricolage 2008-01-11 14:10:27
Story Republished Maintainance, Bricolage 2007-12-20 16:47:37
Story Republished Maintainance, Bricolage 2007-12-20 16:47:06
Story Expired Maintainance, Bricolage 2007-11-11 15:41:36
Story Republished Maintainance, Bricolage 2007-11-11 15:41:29
Story Changes Saved 2007-11-11 15:41:25
Story Removed from Workflow 2007-11-11 15:41:25
Story Checked In 2007-11-11 15:41:25 Version: 4

Now, this story was republished by the system, before the error
occured, but it was checked in when that happened. The important
bit, I think, is from April 7, 2008. This is from the story instance
table before I fixed it:

64244 | Intramural Spring Golf League | | 14703
| 5 | 1101 | sgolf | 1
| 2007-07-25 13:37:00 | | f
102717 | Intramural Spring Golf League | | 14703
| 5 | 1101 | sgolf | 1
| 2007-07-25 13:37:00 | | t
64245 | Intramural Spring Golf League | | 14703
| 6 | 1101 | sgolf | 1
| 2007-07-25 13:37:00 | | f
64246 | Intramural Spring Golf League | | 14703
| 6 | 1101 | sgolf | 1
| 2007-07-25 13:37:00 | | t

It looks like when the story was checked in, not only was version 6
created, but a *new* version 6 for editing was created when the user
checked out the story two seconds later. That behavior looks proper.
But, when the story gets checked in, it's listed in the log as version
5, and there's nothing new to be seen in the story_instance table.
Perhaps it checked in with id 64244, because it had already been
incremented prior. Then when the user checked out the story this
week, they got a new version 5 in the story instance table.

-Matt

lannings at who

Feb 4, 2009, 2:17 AM

Post #14 of 27 (6855 views)
Permalink

Re: Story version corruption [In reply to]

On Fri, 23 Jan 2009, David E. Wheeler wrote:
> On Jan 23, 2009, at 1:29 AM, Scott Lanning wrote:
>>> That sounds right. We need to make sure that the job uses `checked_out =>
>>> 1` when it selects the story.
>>
>> Shouldn't it publish the checked_in version, though?
>
> Sorry, yes, that should have been `checked_in => 1`.

Doesn't seem to be working. :/

david at kineticode

Feb 4, 2009, 9:30 AM

Post #15 of 27 (6838 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 3, 2009, at 11:47 AM, Matthew Rolf wrote:

> Now, this story was republished by the system, before the error
> occured, but it was checked in when that happened.

NO, it wasn't:

> Story Checked Out 2008-04-07 20:39:17
> Story Moved into Workflow 2008-04-07 20:39:16 Workflow: Recreation
> Pages
> Story Republished Maintainance, Bricolage 2008-01-11 14:10:27

It's clearly checked out when the maintenance republish happened.
Furthermore, it was expired before it was checked in!

> Story Expired Maintainance, Bricolage 2007-11-11 15:41:36
> Story Republished Maintainance, Bricolage 2007-11-11 15:41:29
> Story Changes Saved 2007-11-11 15:41:25
> Story Removed from Workflow 2007-11-11 15:41:25
> Story Checked In 2007-11-11 15:41:25 Version: 4

I have to admit I never expected that.

> The important bit, I think, is from April 7, 2008. This is from the
> story instance table before I fixed it:
>
> 64244 | Intramural Spring Golf League | | 14703
> | 5 | 1101 | sgolf |
> 1 | 2007-07-25 13:37:00 | | f
> 102717 | Intramural Spring Golf League | | 14703
> | 5 | 1101 | sgolf |
> 1 | 2007-07-25 13:37:00 | | t
> 64245 | Intramural Spring Golf League | | 14703
> | 6 | 1101 | sgolf |
> 1 | 2007-07-25 13:37:00 | | f
> 64246 | Intramural Spring Golf League | | 14703
> | 6 | 1101 | sgolf |
> 1 | 2007-07-25 13:37:00 | | t
>
> It looks like when the story was checked in, not only was version 6
> created, but a *new* version 6 for editing was created when the user
> checked out the story two seconds later.

Your pasting of the log for the story only goes to version 4. But, I
ask you, what user is capable of checking a story in and, within two
seconds, finding it on a desk and checking it out again? Or, better,
how likely is it that some other user checked it out exactly two
seconds after it was checked in? Seems kind of weird, though not out
of the question.

> That behavior looks proper. But, when the story gets checked in,
> it's listed in the log as version 5, and there's nothing new to be
> seen in the story_instance table. Perhaps it checked in with id
> 64244, because it had already been incremented prior. Then when the
> user checked out the story this week, they got a new version 5 in
> the story instance table.

When you check in a story, it checks in the instance you've been
using. All it does is set checked_out to false and increment the
version number. Somehow, though, you've got two checked-out versions
at the same time, 5 and 6, which is just wrong. Also, where did that
crazy, out-of-sequence id come from, 102717? That doesn't look right
at all. There's some code somewhere that's doing something funky. I
sure would like to know where it is. :-(

Best,

David

rolfm at denison

Feb 4, 2009, 10:09 AM

Post #16 of 27 (6825 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 4, 2009, at 10:30 AM, David E. Wheeler wrote:

> On Feb 3, 2009, at 11:47 AM, Matthew Rolf wrote:
>
>> Now, this story was republished by the system, before the error
>> occured, but it was checked in when that happened.
>
> NO, it wasn't:
>
>> Story Checked Out 2008-04-07 20:39:17
>> Story Moved into Workflow 2008-04-07 20:39:16 Workflow: Recreation
>> Pages
>> Story Republished Maintainance, Bricolage 2008-01-11 14:10:27

What? It was republished in january, and checked out in April.

> It's clearly checked out when the maintenance republish happened.
> Furthermore, it was expired before it was checked in!
>
>> Story Expired Maintainance, Bricolage 2007-11-11 15:41:36
>> Story Republished Maintainance, Bricolage 2007-11-11 15:41:29
>> Story Changes Saved 2007-11-11 15:41:25
>> Story Removed from Workflow 2007-11-11 15:41:25
>> Story Checked In 2007-11-11 15:41:25 Version: 4

That's not the way I read it. I read that that it was checked in, and
then republished and expired at the same time. This log is in
chronological order from the bottom up - just like the log screen
displays. My apologies if that caused confusion.

>> Your pasting of the log for the story only goes to version 4.

No, it doesn't.

>> But, I ask you, what user is capable of checking a story in and,
>> within two seconds, finding it on a desk and checking it out again?

They can check it in on a desk and check it out very rapidly. The
Check In/Out button changes with the page refresh. It is entirely
possible.

>> Or, better, how likely is it that some other user checked it out
>> exactly two seconds after it was checked in? Seems kind of weird,
>> though not out of the question.

The log shows it being checked out by the same user. I omitted their
name, because I didn't want to past it on the list.

> When you check in a story, it checks in the instance you've been
> using. All it does is set checked_out to false and increment the
> version number. Somehow, though, you've got two checked-out versions
> at the same time, 5 and 6, which is just wrong. Also, where did that
> crazy, out-of-sequence id come from, 102717? That doesn't look right
> at all. There's some code somewhere that's doing something funky. I
> sure would like to know where it is. :-(

Right, so what I'm saying is that looking at the log, the first check
in from 5 to 6 looks like it worked. But when the user checked it out
and in again, it went to version 5, and didn't increment, and didn't
create a new db entry. Then when they came back months later and
checked it out, it stayed at version 5, which is the out of sequence
id. They then could not check it in, because there was already a
version 6, and the unique key index wouldn't let them duplicate it.

-Matt

david at kineticode

Feb 4, 2009, 10:50 AM

Post #17 of 27 (6828 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 4, 2009, at 10:09 AM, Matthew Rolf wrote:

>> NO, it wasn't:
>>
>>> Story Checked Out 2008-04-07 20:39:17
>>> Story Moved into Workflow 2008-04-07 20:39:16 Workflow:
>>> Recreation Pages
>>> Story Republished Maintainance, Bricolage 2008-01-11 14:10:27
>
> What? It was republished in january, and checked out in April.

Oh, sorry, was reading it backward. I forgot that the log was reverse
cron. Duh. Let me start over.

> That's not the way I read it. I read that that it was checked in,
> and then republished and expired at the same time. This log is in
> chronological order from the bottom up - just like the log screen
> displays. My apologies if that caused confusion.

It's not your fault that I'm a moron.

>> But, I ask you, what user is capable of checking a story in and,
>> within two seconds, finding it on a desk and checking it out again?
>
> They can check it in on a desk and check it out very rapidly. The
> Check In/Out button changes with the page refresh. It is entirely
> possible.

That's crazy. Is this 1.11? That would help to explain it�

>> Or, better, how likely is it that some other user checked it out
>> exactly two seconds after it was checked in? Seems kind of weird,
>> though not out of the question.
>
> The log shows it being checked out by the same user. I omitted
> their name, because I didn't want to past it on the list.

Of course.

> Right, so what I'm saying is that looking at the log, the first
> check in from 5 to 6 looks like it worked. But when the user checked
> it out and in again, it went to version 5, and didn't increment, and
> didn't create a new db entry. Then when they came back months later
> and checked it out, it stayed at version 5, which is the out of
> sequence id. They then could not check it in, because there was
> already a version 6, and the unique key index wouldn't let them
> duplicate it.

Okay, let me reverse the log and look at it again:

> Story Checked In 2007-11-11 15:41:25 Version: 4
> Story Removed from Workflow 2007-11-11 15:41:25
> Story Changes Saved 2007-11-11 15:41:25

Okay, fine. I should probably update the logging to use real time
instead of transaction start time so that these are properly ordered,
but that's a minor issue.

> Story Republished Maintainance, Bricolage 2007-11-11 15:41:29
> Story Expired Maintainance, Bricolage 2007-11-11 15:41:36
> Story Republished Maintainance, Bricolage 2007-12-20 16:47:06
> Story Republished Maintainance, Bricolage 2007-12-20 16:47:37
> Story Republished Maintainance, Bricolage 2008-01-11 14:10:27

That all looks fine.

> Story Moved into Workflow 2008-04-07 20:39:16 Workflow: Recreation
> Pages
> Story Checked Out 2008-04-07 20:39:17
> Story Moved to Desk 2008-04-07 20:39:17 Desk: Recreation Edit Alerts

Fine. So this would be version 4, checked_out true, a new row.

> Story Checked In 2008-04-07 20:46:27 Version: 5

That changes v4/true to v5/false. Fine.

> Story Checked Out 2008-04-07 20:46:30

This should create v5/true as a new row.

> Story Checked In 2008-04-07 20:50:19 Version: 6

That changes v5/true to v6/false. Fine.

> Story Checked Out 2008-04-07 20:50:21

This should create v6/true as a new row.

> Story Checked In 2008-04-07 20:51:11 Version: 5

Clearly wrong. So I wonder if that last checkout copied v4 instead of
v6? Let's have a look at your table results now (sorry if you've done
all this already, I'm just thinking it through here�). I've
reformatted to get just the columns that interest us (plus type) and
ordered by ID, so it's chronological:

id | version | type | checked_out
--------+---------+-------+-------------
64244 | 5 | sgolf | f
64245 | 6 | sgolf | f
64246 | 6 | sgolf | t
102717 | 5 | sgolf | t

So first, we have version 5 not checked out. That was created when
version 4 was checked in.

Then we have version 6/false, which was created when version 5 was
checked in.

Then we have version 6/true, which was created when version 6 was
checked out.

Then, a long time later, the story was checked in�and the version was
set to 5 instead of 7. WTF?

So, what we've figured out is that this tends to happen when a user
has a story checked out for a long time, and, maybe, that there were
publishes while it was checked out. Yes?

Is there a bug report for this? I don't really have time to fiddle
with it right now, but we should add this info to a bug report.

Thanks,

David

rolfm at denison

Feb 4, 2009, 1:42 PM

Post #18 of 27 (6820 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 4, 2009, at 11:50 AM, David E. Wheeler wrote:

>> They can check it in on a desk and check it out very rapidly. The
>> Check In/Out button changes with the page refresh. It is entirely
>> possible.
>
> That's crazy. Is this 1.11? That would help to explain it�

Nope, it's in 1.10.x, if not before. Take a look at the desk interface.

>>> Okay, let me reverse the log and look at it again:

>> Story Checked In 2008-04-07 20:51:11 Version: 5
>
> Clearly wrong. So I wonder if that last checkout copied v4 instead
> of v6?

FWIW, the id of v4 is 52324, which puts it appropriately before v.5.

> Then, a long time later, the story was checked in�and the version
> was set to 5 instead of 7. WTF?
>
> So, what we've figured out is that this tends to happen when a user
> has a story checked out for a long time, and, maybe, that there were
> publishes while it was checked out. Yes?

That's definitely Philip and Scott's experience, and I don't discount
it, but I can't say that's been ours. Look at the log again - the
entire bit of going to v5-v6-v5 takes place within a half hour. So
this story didn't sit for a while.

I have 2 theories - 1) the session data regarding versions got borked
(or was cached?) and failed to be aware of the fact that it had v6,
checking it in as something else, or 2) The check in hadn't completed
before the checkout occurred, resulting in corruption.

> Is there a bug report for this? I don't really have time to fiddle
> with it right now, but we should add this info to a bug report.

I'll be happy to make a bug report. I was poking around

http://svn.bricolage.cc/bricolage/trunk/lib/Bric/Biz/Asset/Business/Story.pm

And saw the somewhat cryptic checkout subroutine, but didn't see
anything for check in. Where would I look for that code?

-Matt

lannings at who

Feb 5, 2009, 1:10 AM

Post #19 of 27 (6819 views)
Permalink

Re: Story version corruption [In reply to]

On Wed, 4 Feb 2009, Matthew Rolf wrote:
> http://svn.bricolage.cc/bricolage/trunk/lib/Bric/Biz/Asset/Business/Story.pm
>
> And saw the somewhat cryptic checkout subroutine, but didn't see anything for
> check in. Where would I look for that code?

In base classes, in this case Bric::Biz::Asset

david at kineticode

Feb 5, 2009, 10:18 AM

Post #20 of 27 (6821 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 4, 2009, at 1:42 PM, Matthew Rolf wrote:

>> That's crazy. Is this 1.11? That would help to explain it�
>
> Nope, it's in 1.10.x, if not before. Take a look at the desk
> interface.

Okay.

>>> Story Checked In 2008-04-07 20:51:11 Version: 5
>>
>> Clearly wrong. So I wonder if that last checkout copied v4 instead
>> of v6?
>
> FWIW, the id of v4 is 52324, which puts it appropriately before v.5.

Yeah, but the query doesn't sort by log dates when it looks for a
story to check out (or check in).

>> Then, a long time later, the story was checked in�and the version
>> was set to 5 instead of 7. WTF?
>>
>> So, what we've figured out is that this tends to happen when a user
>> has a story checked out for a long time, and, maybe, that there
>> were publishes while it was checked out. Yes?
>
> That's definitely Philip and Scott's experience, and I don't
> discount it, but I can't say that's been ours. Look at the log
> again - the entire bit of going to v5-v6-v5 takes place within a
> half hour. So this story didn't sit for a while.

Okay. Scratch that idea, then. Good to have one less variable to worry
about.

> I have 2 theories - 1) the session data regarding versions got
> borked (or was cached?) and failed to be aware of the fact that it
> had v6, checking it in as something else, or 2) The check in hadn't
> completed before the checkout occurred, resulting in corruption.

Yeah, good working hypotheses. If the session had the story with
version 4 instead of 6, then it would try to check it in as version 5.
That'd be my first guess. The "checkin hadn't completed" bit shouldn't
be the case, thanks to transactions, but it's possible that there
could be a couple of transactions on checkin. Still, the bit that
determines the new version number should not be confused. I think the
session issue is much more likely the culprit.

>> Is there a bug report for this? I don't really have time to fiddle
>> with it right now, but we should add this info to a bug report.
>
> I'll be happy to make a bug report. I was poking around
>
> http://svn.bricolage.cc/bricolage/trunk/lib/Bric/Biz/Asset/Business/Story.pm
>
> And saw the somewhat cryptic checkout subroutine, but didn't see
> anything for check in. Where would I look for that code?

Like Scott said. :-) Try sticking in this code and watching your log
the next time this happens:

Index: Asset.pm
===================================================================
--- Asset.pm (revision 8400)
+++ Asset.pm (working copy)
@@ -1723,6 +1723,8 @@

my $version = $self->_get('version');
$version++;
+ print STDERR 'Story ID ', $self->get_id, ' going from version ',
+ $self->get_version, " to $version\n";
$self->_set({ user__id => undef,
version => $version,
current_version => $version,

Best,

David

david at kineticode

Feb 16, 2009, 4:41 PM

Post #21 of 27 (6663 views)
Permalink

Re: Story version corruption [In reply to]

On Jan 22, 2009, at 8:20 AM, David E. Wheeler wrote:

>> It seems to be due to sorting of the rows in story_instance when
>> there
>> are both checked_in and not checked_in versions.
>> I'll make a bug report, though I'm not sure yet if it
>> happens in "real" Bricolage.
>
> That sounds right. We need to make sure that the job uses
> `checked_out => 1` when it selects the story.

I think I've fixed this bit, at least, in r8408, just by adding
`checked_in => 1` to the story and media lookups in jobs. Still
looking at the other stuff in this thread, though�

Best,

David

david at kineticode

Feb 16, 2009, 8:24 PM

Post #22 of 27 (6676 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 5, 2009, at 10:18 AM, David E. Wheeler wrote:

>> I have 2 theories - 1) the session data regarding versions got
>> borked (or was cached?) and failed to be aware of the fact that it
>> had v6, checking it in as something else, or 2) The check in hadn't
>> completed before the checkout occurred, resulting in corruption.
>
> Yeah, good working hypotheses. If the session had the story with
> version 4 instead of 6, then it would try to check it in as version
> 5. That'd be my first guess. The "checkin hadn't completed" bit
> shouldn't be the case, thanks to transactions, but it's possible
> that there could be a couple of transactions on checkin. Still, the
> bit that determines the new version number should not be confused. I
> think the session issue is much more likely the culprit.

Well, I did find a way in which version numbers can get mucked up, but
it'd be kind of hard for it to happen. It would basically require very
slow publishes. I'm not completely convinced that my recently-
committed fixes will address the issue, though I certainly hope so.
The attached patch has the relevant fixes, including for Scott's Bug
#1417. Please do apply this to your Bricolage instance, Matt, and let
me know if the problem of story version number corruption goes away or
continues.

Thanks!

David

--
David Wheeler
President, Kineticode, Inc.
http://www.kineticode.com/
Kineticode. Setting knowledge in motion.[sm]

rolfm at denison

Feb 17, 2009, 9:47 AM

Post #23 of 27 (6634 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 16, 2009, at 11:24 PM, David E. Wheeler wrote:

> Well, I did find a way in which version numbers can get mucked up,
> but it'd be kind of hard for it to happen. It would basically
> require very slow publishes. I'm not completely convinced that my
> recently-committed fixes will address the issue, though I certainly
> hope so. The attached patch has the relevant fixes, including for
> Scott's Bug #1417. Please do apply this to your Bricolage instance,
> Matt, and let me know if the problem of story version number
> corruption goes away or continues.

We will certainly apply that patch and let you know. I think there
are other instances though, like my last e-mail showed, that don't
involve publishes, so I suspect there will be more to do.

-Matt

david at kineticode

Feb 17, 2009, 11:04 AM

Post #24 of 27 (6628 views)
Permalink

Re: Story version corruption [In reply to]

On Feb 16, 2009, at 8:24 PM, David E. Wheeler wrote:

> Well, I did find a way in which version numbers can get mucked up,
> but it'd be kind of hard for it to happen. It would basically
> require very slow publishes. I'm not completely convinced that my
> recently-committed fixes will address the issue, though I certainly
> hope so. The attached patch has the relevant fixes, including for
> Scott's Bug #1417. Please do apply this to your Bricolage instance,
> Matt, and let me know if the problem of story version number
> corruption goes away or continues.

Trying to attach the patch again, this time as a .txt file.

Best,

David

Attachments:

fixes.patch.txt (5.07 KB)

rolfm at denison

Mar 5, 2009, 8:36 AM

Post #25 of 27 (6376 views)
Permalink

Re: Story version corruption [In reply to]

Another example of story version corruption. Here's the log, again,
read it backwards.

I'll be hosest, I don't know what to make of it. There's no check
out after the second check in. It's weird.

Story Checked In user 2009-03-04 21:18:10 Version: 2
Story Changes Saved user 2009-03-04 21:15:56
Story Removed from Workflow user 2009-03-04 21:15:56
Story Checked In user 2009-03-04 21:15:56 Version: 3
Story Moved to Desk user 2009-03-04 21:15:25 Desk: Res Life Edit Alerts
Story Changes Saved user 2009-03-04 21:14:00
Story Moved to Desk user 2009-03-04 21:14:00 Desk: Res Life Approval
Alerts
Story Checked In user 2009-03-04 21:14:00 Version: 2
Story Changes Saved user 2009-03-04 21:13:44
Story Checked Out user 2009-03-04 20:52:48
Story Checked In user 2009-03-04 20:52:42 Version: 2
Story Checked Out user 2009-03-04 20:49:31

1 2

View All

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads