[ZODB-Dev] time-stamp reduction

[Tim Peters]

[Thomas Guettler]
> Unfortunaltly the clock was set back on one server. Now I get this during
> pack:
>
> Traceback (most recent call last):
>   File "/home/user/app/scripts/cron/pack.py", line 77, in ?
>     main()
>   File "/home/user/app/scripts/cron/pack.py", line 67, in main
>     storage.pack()
>   File
"/home/user/app/python/lib64/python2.3/site-packages/ZEO/ClientStorage.py",
line 815, in pack
>     return self._server.pack(t, wait)
>   File
"/home/user/app/python/lib64/python2.3/site-packages/ZEO/ServerStub.py",
line 79, in pack
>     self.rpc.call('pack', t, wait)
>   File
"/home/user/app/python/lib64/python2.3/site-packages/ZEO/zrpc/connection.py"
, line 372, in call
>     raise inst # error raised by server
> ZODB.fspack.CorruptedError:
> /home/user/app/var/data.fs:299901427:time-stamp reduction:
> 035c9d4907706f44 <= 037cf4863546e018
>
> Version is ZODB 3.2.1.

You're missing a lot of bugfixes (3.2.8 is current), and some of them are
even relevant <wink>.  Here's from 3.2.3 news:

    Collector #1327: FileStorage init confused by time travel

    If the system clock "went backwards" a long time between the times a
    FileStorage was closed and reopened, new transaction ids could be
    smaller than transaction ids already in the storage, violating a
    key invariant.  Now transaction ids are guaranteed to be increasing
    even when this happens.  If time appears to have run backwards at all
    when a FileStorage is opened, a new message saying so is logged at
    warning level; if time appears to have run backwards at least 30
    minutes, the message is logged at panic level (and you should
    investigate to find and repair the true cause).

The timestamps in your error message work out to

    2005-04-15 12:25:01.743562
and
    2009-03-30 09:10:12.486763

so it looks more like time got set _forward_ on your box by about 4 years,
and then got set back to reality.  In any case, that's more than 30 minutes,
so fits the collector 1327 scenario.

> A search with google for "zodb timestamp reduction" reveals this thread:
> http://mail.zope.org/pipermail/zodb-dev/2004-August/007826.html
>
> Now I know that using fsrecover is a bad idea, since it drops transaction
> with smaller timestamps.

I didn't know that.  Are you sure?

> Is "copyTransactionsFrom()" the right thing?

Yes, it's an "undocumented feature" of copyTransactionsFrom() that it
repairs timestamp reductions during the copy.

> Should I use the latest 3.2.x or 3.3. release to try to fix this?

You should upgrade to 3.2.8 regardless.  You can use any version of ZODB to
repair this, but if you use a version earlier than 3.2.6, it's critical that
you delete the .fs.index file created for the new FileStorage, after the
copyTransactionsFrom() dance is done, but before you use the .fs file for
anything.  See ZODB 3.2.6 news for the relevant .fs.index bugs (specifically
triggered by cloning a FileStorage via copyTransactionsFrom()).

> There are backups. The application seems healthy since the daily
> unittest does not fail.

To be brutally honest here, I'm not clear on why tids need to be strictly
increasing.  Someday I'd like to break that part on purpose, and see what
(if anything) fails as a result.  It's certainly _nice_ that tids normally
have a clear relationship to wall-clock time, and "strictly increasing" is
one way to satisfy the obviously necessary "no two tids are the same"
requirement.

>  Thomas
>
> PS: I tried to get timestamps from the tids (035c9d4907706f44), but did
> not find a suitable method in ZODB.utils. How long is the clock screw?

Oops!  If I had known you were going to ask this <wink>, I would have done
the computation above using a 3.2 ZODB.  Here's what I did in ZODB 3.4; in
3.2 you have to do by hand what 3.4's readable_tid_repr() does (see the
source code):

>>> from ZODB.utils import p64, readable_tid_repr as rtr
>>> print rtr(p64(0x035c9d4907706f44))
0x035c9d4907706f44 2005-04-15 12:25:01.743562
>>> print rtr(p64(0x037cf4863546e018))
0x037cf4863546e018 2009-03-30 09:10:12.486763

Internally, tids are always 8-byte strings (which display as gibberish), so
there are no utilities in any ZODB for creating a readable timestamp from an
integer.  p64 there is used to reconstruct an 8-byte tid string from the hex
integer output in the traceback.