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

[Tim Peters]

[Malcolm Cleaton]
>>> One of our servers, after the disk filled up, started showing some
>>> "time travel" conflict errors.

[Thomas Guettler]
>> ZODB does not like it, if your system clock goes backward.

ZODB always intended to protect itself against that, but until recent ZODB
there was a bug that could get it in trouble if the system clock went
backward "a lot" between restarts.  Current ZODB will log a problem if it
detects that, but shouldn't be hurt by it.  Malcolm didn't say which version
of ZODB he's using, but I can deduce from the "wordy" ConflictError message
below that it's recent enough that it shouldn't have that problem.

[Malcolm]
> Thanks Thomas. That's interesting and useful, but I'm not sure it's the
> problem in this case.
>
> One of my colleagues has managed to find a copy of the traceback (which
> seemed to only be displayed, and not show up in the log):
>
> An error was encountered while publishing this resource.
>
> *ZODB.POSException.ConflictError*
>
> Sorry, a site error occurred.
>
> Traceback (innermost last):
>
>     * Module ZPublisher.Publish, line 175, in publish_module_standard
>     * Module ZPublisher.Publish, line 149, in publish
>     * Module ZPublisher.Publish, line 149, in publish
>     * Module ZPublisher.Publish, line 149, in publish
>     * Module ZPublisher.Publish, line 139, in publish
>     * Module Zope.App.startup, line 163, in zpublisher_exception_hook
>     * Module ZPublisher.Publish, line 107, in publish
>     * Module Zope.App.startup, line 222, in commit
>     * Module ZODB.Transaction, line 252, in commit
>     * Module ZODB.Connection, line 737, in tpc_vote
>     * Module ZEO.ClientStorage, line 841, in tpc_vote
>     * Module ZEO.ClientStorage, line 825, in _check_serials
>
> 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)

I'm unclear about what's odd here.  ConflictErrors are expected when using
ZODB.  Zope retries a transaction some number of times if it sees a conflict
error, but if it keeps seeing conflict errors it eventually gives up.

> This traceback was seen late in the afternoon

Which time zone are you in?  IIRC, ZODB timestamps are given in UTC.

> - after 16:00 - and the server clock was correct (enough) at the time.
> So, it looks like the timestamp on the committed transaction is
> reasonable,

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

> 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.