Conflict errors since update to Zope 4

Zope
1

While on Zope 2.13, I regularly had Conflict errors, but they always got resolved.

Since I am on Zope 4 it looks like they do not get resolved any more.

Zope 2 (some older example)

2017-04-13T11:03:20 INFO ZPublisher.Conflict ConflictError at /VirtualHostBase/https/xxx.de:443/bliss/VirtualHostRoot//Calendar/importHyAppointments: database conflict error (oid 0x0191db, class Products.Entities.User.User) (1 conflicts (0 unresolved) since startup at Thu Apr 13 11:00:08 2017)

Zope 4

2020-01-29 11:43:12,924 ERROR   [Zope.SiteErrorLog:251][waitress] 1580294592.920.296257209085 https://xxx.de/Calendar/importHyAppointments
Traceback (innermost last):
  Module ZPublisher.WSGIPublisher, line 162, in transaction_pubevents
  Module transaction._manager, line 252, in commit
  Module transaction._manager, line 131, in commit
  Module transaction._transaction, line 311, in commit
  Module transaction._transaction, line 302, in commit
  Module transaction._transaction, line 447, in _commitResources
  Module transaction._transaction, line 424, in _commitResources
  Module ZODB.Connection, line 692, in tpc_vote
  Module ZEO.ClientStorage, line 752, in tpc_vote
  Module ZEO.asyncio.client, line 764, in call
  Module ZEO.asyncio.client, line 743, in call
  Module ZEO.asyncio.client, line 756, in wait_for_result
  Module concurrent.futures._base, line 462, in result
  Module concurrent.futures._base, line 414, in __get_result
ConflictError: database conflict error (oid 0x7618c7, class BTrees.OOBTree.OOBucket, serial this txn started with 0x03d57bfef976ef00 2020-01-29 10:38:58.468262, serial currently committed 0x03d57c0326ec5688 2020-01-29 10:43:09.122624)

Is this really a serious error?

I have not set a special retry value for waitress, ie it should be 3 retries when having a conflict.

Any advice on what I could do?

Thanks

1 Like
2

What you see in your logfile is written by Products.SiteErrorLog. This gets activated via a ZPublisher.interfaces.IPubFailure handler. The corresponding event is notified before any retry handling. Thus, log entries like the above may not need to signal an error (seen by the user/client).

I fear the WSGI publisher has a weakness with respect to the handling of transient errors (such as ConflictError). There seems to be no (easy) way to distinguish between resolvable and unresolvable transient errors: all produce the same log entries (both in SiteErrorLog and the logfile). You no longer get any indication whether the transient error could or could not get resolved. You would need to know the request's retry_count in order to determine from the number of (mostly) consecutive temporary error log entries to estimate whether retrial was likely successful.

The event notified by the WSGIPublisher contains the information whether a retry will be tried or not. This allows you to register your own IPubFailure handler to recognize unresolved temporary errors (and create appropriate log entries).

1 Like
3

@dieter Thank you very much for your detailed answer.

What I do not understand yet, when there is a ConflictError, and on the retry there would be another ConflictError, would I see two errors in my logfile?

While I could create a custom logging (thanks to your description), don't you think we should report the current behavior as a Zope bug?

4

From my experience with my Sentry logs there are now ConflictErrors logged for each conflict, even if a retry happens. I had not unresolved conflict until now, so I can not tell, if there will be a different entry for unresolved ones.

5

Each request aborted by ConfictError (or more general TransientError) exception will be reported: this applies both to the initial request as well as to a retried request.

My first reaction, too, has been that this was a bug. Looking at the code (--> ZPublisher.WSGIPublisher.transaction_pubevents), however, gave me the impression that this is not a Zope bug: Zope itself does nothing with respect to the logging of exceptions; it simply notifies an IPubFailure event AND provides relevant information (among this whether a retry is expected). Thus, SiteErrorLog should be extended to show this information in its exception presentation (e.g. in the log entries written to the logfile).

1 Like
6

@dieter, thank you very much for your answer.

I was also looking at both the WSGIPublisher and the SiteErrorLog code, and did not come to clear decision where to fix this problem.

Thanks to your suggestion I created an issue at the Products.SiteErrorLog project site:

If you can spare a minute, maybe you could add you opinion on how to resolve the issue.

7

The issue has been fixed in https://pypi.org/project/Products.SiteErrorLog/5.4/ ! :partying_face: :rocket:

1 Like
8

I encountered a similar behavior after changing the codebase to Zope 4 and Plone 5.2.1 on Python 2.7.16 with ZServer 4.0.2 (WSGI off).

I also tried to update to Products.SiteErrorLog=5.4 but it still happens apparently without clear reason so far, so that I cannot reproduce the issue.

I was also wondering why the same traceback was logged twice.

2020-07-06T23:03:10 INFO ZPublisher.Conflict ConflictError at /VirtualHostBase/https/senaite.ridingbytes.com/senaite/VirtualHostRoot//bika_setup: database conflict error (oid 0x0153, class Persistence.mapping.PersistentMapping, serial this txn started with 0x03d9133c30f9a066 2020-07-06 20:44:11.478540, serial currently committed 0x03d9134f2e49d577 2020-07-06 21:03:10.848847) (1 conflicts (0 unresolved) since startup at Mon Jul  6 22:57:47 2020)
------
2020-07-06T23:03:10 ERROR Zope.SiteErrorLog 1594069390.90.1788507017 https://senaite.ridingbytes.com/bika_setup/base_edit
Traceback (innermost last):
  Module ZServer.ZPublisher.exceptionhook, line 80, in __call__
  Module ZPublisher, line 43, in reraise
  Module ZServer.ZPublisher.Publish, line 151, in publish
  Module ZServer.ZPublisher.Publish, line 393, in commit
  Module transaction._manager, line 252, in commit
  Module transaction._manager, line 131, in commit
  Module transaction._transaction, line 311, in commit
  Module transaction._transaction, line 302, in commit
  Module transaction._transaction, line 447, in _commitResources
  Module transaction._transaction, line 424, in _commitResources
  Module ZODB.Connection, line 692, in tpc_vote
  Module ZEO.ClientStorage, line 752, in tpc_vote
  Module ZEO.asyncio.client, line 764, in call
  Module ZEO.asyncio.client, line 743, in call
  Module ZEO.asyncio.client, line 756, in wait_for_result
  Module concurrent.futures._base, line 462, in result
  Module concurrent.futures._base, line 414, in __get_result
ConflictError: database conflict error (oid 0x0153, class Persistence.mapping.PersistentMapping, serial this txn started with 0x03d9133c30f9a066 2020-07-06 20:44:11.478540, serial currently committed 0x03d9134f2e49d577 2020-07-06 21:03:10.848847)
------
2020-07-06T23:03:11 ERROR Zope.SiteErrorLog 1594069391.730.334596200752 https://senaite.ridingbytes.com/bika_setup/base_edit
Traceback (innermost last):
  Module ZServer.ZPublisher.Publish, line 151, in publish
  Module ZServer.ZPublisher.Publish, line 393, in commit
  Module transaction._manager, line 252, in commit
  Module transaction._manager, line 131, in commit
  Module transaction._transaction, line 311, in commit
  Module transaction._transaction, line 302, in commit
  Module transaction._transaction, line 447, in _commitResources
  Module transaction._transaction, line 424, in _commitResources
  Module ZODB.Connection, line 692, in tpc_vote
  Module ZEO.ClientStorage, line 752, in tpc_vote
  Module ZEO.asyncio.client, line 764, in call
  Module ZEO.asyncio.client, line 743, in call
  Module ZEO.asyncio.client, line 756, in wait_for_result
  Module concurrent.futures._base, line 462, in result
  Module concurrent.futures._base, line 414, in __get_result
ConflictError: database conflict error (oid 0x0153, class Persistence.mapping.PersistentMapping, serial this txn started with 0x03d9133c30f9a066 2020-07-06 20:44:11.478540, serial currently committed 0x03d9134f2e49d577 2020-07-06 21:03:10.848847)