[Zope-dev] Re: Logging after ConflictError Retries

[Dieter Maurer]

Dieter Maurer wrote at 2005-6-10 20:43 +0200:
>Malcolm Cleaton wrote at 2005-6-10 11:00 +0100:
>> ...
>>>>2. If there is at least one ConflictError and then the request finishes
>>>>with an error (either more ConflictErrors or something else), the Z2 log
>>>>shows the request as having been answered with status 200, although
>>>>actually a status 500 error response has been served.
>>>>
>>>>I've managed to work out what's causing this, but fixing may be more
>>>>fiddly. What happens is, once the request is abandoned because of the
>>>>error, when control comes back to publish_module_standard in Publish.py,
>>>>response.exception() is called on the original response, not on the latest
>>>>retry. Then, when HTTPResponse _finish() is called, it traces down to the
>>>>latest retry to find the status code for the logging, which is now the
>>>>wrong one.
>>> 
>>> This should only happen when "publish" itself raises an exception.
>>> Usually, "publish" should *NOT* raise an exception, when
>>> the request fails (although exceeding the maximal number
>>> of retries may cause this).
>>
>>My debugger indicates that publish in fact does raise an exception,
>>whether or not retries are in play. zpublisher_exception_hook calls 
>>raise_standardErrorMessage, which raises, and this exception propagates
>>all the way to the catch in publish_module_standard.
>
>You and your debugger are right!
>
>I do not understand why "raise_standardErrorMessage"
>needs to raise an exception rather than just set up
>the response -- but it indeed raise an exception...

Reanalysing the code, I now understand why "raise" is used
in "raise_standardErrorMessage":

  It should pass the information from the repeated request
  up to "publish_module_standard".

  There, "response.exception()" is called for the original
  response which should set its status based on the
  exception raised in the repeated request.

Unfortunately, "ZServer.HTTPRequest.HTTPRequest"
does not look at the original request but at the final
repeated request...

A nasty workaround may be, to call "response.exception"
for the repeated request as well.
In order not to make implementations assumptions,
this should be done in "Zope.App.startup.zpublisher_exception_hook":

  The complete block starting with

        try:
            log = aq_acquire(published, '__error_log__', containment=1)
  
  and ending just before the "finally:"

  may be wrapped into a

      try:
        <block>
      except:
        response = getattr(REQUEST, 'response', None)
	if response is not None:
	    response.exception()
	raise


Of course, the complete handling is so complex that is cries
out for simplification rather than further nasty workarounds...


-- 
Dieter