ValueError: new last tid (273179025317514649) must be greater than previous one (273179029162332364)

Hey all, in my ongoing struggle with an issue with Plone 5, we discovered another issue that honestly doesn't make sense to me.

When someone views the History of an item on the site, the site will take a long time to load, then this error comes up.

ValueError: new last tid (273179025317514649) must be greater than previous one (273179029162332364)

Thoughts? History used to work fine, but now, not so much.

Full traceback please.

My apologizies. Here is the traceback.

Traceback (innermost last):
Module ZPublisher.Publish, line 146, in publish
Module Zope2.App.startup, line 303, in commit
Module transaction._manager, line 131, in commit
Module transaction._transaction, line 310, in commit
Module transaction._transaction, line 301, in commit
Module transaction._transaction, line 446, in _commitResources
Module transaction._transaction, line 428, in _commitResources
Module ZODB.Connection, line 710, in tpc_finish
Module ZODB.mvccadapter, line 181, in tpc_finish
Module ZEO.ClientStorage, line 877, in tpc_finish
Module ZEO.asyncio.client, line 786, in tpc_finish
Module ZEO.asyncio.client, line 743, in call
Module ZEO.asyncio.client, line 756, in wait_for_result
Module concurrent.futures._base, line 422, in result
Module concurrent.futures._base, line 381, in __get_result
ValueError: new last tid (273190459948665446) must be greater than previous one (273190525494372881)

"tid" stands for "Transaction ID". Thery are essentially timestamps, representing the time, the transaction was committed. There is some mechanism which should ensure that the tids are increasing. The module ZODB.utils contains helper functions to work with tids (and oids), among them p64 and readable_tid_repr.

Applying those functions to your tids results in:

>>> readable_tid_repr(p64(273190459948665446))
'0x03ca9146a1440a66 2018-09-28 14:30:37.796668'
>>> readable_tid_repr(p64(273190525494372881))
'0x03ca9155e4182a11 2018-09-28 14:45:53.459623'

This means that the "new" tid is about 15 s older than the previous (old) tid.

Of course, this should not happen. I have no idea how this happened in your case. One possibilty could be a ZODB bug - but others should have seen such a bug as well. The mechanism mentioned above to ensure strongly increasing tids should even work when you play havoc with the local clock (i.e. you set arbitrary times).

Please file a ZODB bug