[ZODB-Dev] RE: Re: "Time travel" conflict errors in Zope

[Malcolm Cleaton]

On Mon, 20 Dec 2004 10:21:35 -0500, Tim Peters wrote:
> [Malcolm Cleaton]
>> ConflictError: database conflict error (oid 0x10fd16,
>> serial this txn started with 0x0359debd2d2ababb
>>                                      2004-12-14 14:53:10.585995,
>> seria> currently committed   0x0359defb79b34a88
>>                                      2004-12-14 15:55:28.523521)
... 
>> This traceback was seen late in the afternoon
> 
> Which time zone are you in?  IIRC, ZODB timestamps are given in UTC.

I'm in London, so in the winter UTC == Local Time.

> Which of the two timestamps displayed do you mean by "the timestamp on the
> committed transaction"?  They're actually *both* timestamps on committed
> transactions.  It says that, for oid 0x10fd16, the revision current when the
> transaction began was committed at
> 
>     2004-12-14 14:53:10
> 
> but that another revision was committed since then, at
> 
>     2004-12-14 15:55:28

Ah! Ok, that helps my understanding, that the earlier time is the time of
the commit of the revision which was current at the start of the
transaction. Although now I think about it, it couldn't be anything else,
really.

>> and the mystery is why the "serial this txn started with" is many hours
>> in the past.
> 
> Those timestamps are an hour apart, so it's unclear how one of them
> could be seen as "reasonable" but the other one "many hours in the past".
> 
> What we can't guess here is when the failing transaction began.  For
> example, perhaps it began at 15:55:00, oid 0x10fd16 hadn't been changed for
> about an hour (14:53:10), another transaction committed a change to oid
> 0x10fd16 28 seconds later (15:55:28), and then the current transaction tried
> to commit at 15:55:29.  IOW, there's no way to deduce from the timestamps
> displayed when the current transaction started, or how long it was in
> progress.  It could all have occurred in less than a second.  The only
> deductions I can make from this info are that the failing transaction:
> 
> 1) Began sometime (any time) between 14:53:10 and 15:55:28.
> 2) And failed to commit sometime (any time) after 15:55:28.
> 
>> Although I've never come across the errors when turning a clock back, I'd
>> expect them to be in the opposite direction - a committed transaction
>> which thinks it was in the future, rather than an open transaction which
>> thinks it was opened ages ago.
> 
> I agree the system clock shouldn't be relevant here.

This is all in the context of a regular Zope request, so the transaction
was begun something less than a second before it was committed. Apologies
for not including this vital information in the original question!

So, the question becomes, why was the version of the object committed at
14:53 being repeatedly loaded into transactions begun after 16:00, when a
later version was available? Given the known issue with the hard drive
filling up, it's starting to sound like this is a symptom of a broken ZEO
client cache file...?

Thanks,
Malcolm.

-- 

    [] j a m k i t
      web solutions for charities

         malcolm cleaton
T:  020 7549 0520
F:  020 7490 1152
M:  07986 563852
W: www.jamkit.com