Logging after ConflictError Retries
After a ConflictError causes a request to be retried, a few things go a bit wrong with error handling and logging in the Zope server. 1. If the request is abandoned after repeated ConflictErrors, no error at all appears in the error log. The following change to Zope/App/startup.py appears to fix this, although I'm not sufficiently experienced in the depths of Zope to be sure there are no downsides: 162,163c162 < if REQUEST.supports_retry(): < raise ZPublisher.Retry(t, v, traceback) ---
raise ZPublisher.Retry(t, v, traceback)
If a Retry error is raised again here even though we don't support any more retries, the ZServer calls the exception hook again with the Retry error, we throw it again and the error logging is missed. Simply not raising the Retry error again once we don't support any more retries means we fall through to the rest of the exception handling hook, and the ConflictError itself is logged, which I think is right. 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. I can think of a few things which might fix this, but they all feel like they might also break many other subtle things, and I've got The Fear; can somebody more experienced in the core comment on the Right Way? I've submitted this to the Collector: http://www.zope.org/Collectors/Zope/1805 Thanks, Malcolm. -- [] j a m k i t web solutions for charities malcolm cleaton T: 020 7549 0520 F: 020 7490 1152 M: 07986 563852 W: www.jamkit.com
On Thu, 09 Jun 2005 10:13:05 +0100, Malcolm Cleaton wrote:
162,163c162 < if REQUEST.supports_retry(): < raise ZPublisher.Retry(t, v, traceback) ---
raise ZPublisher.Retry(t, v, traceback)
I just noticed I've generated this patch backwards, ie. the above is how to remove the change! I wonder if my subconscious is trying to say something there about staying out of the publishing code... :) Thanks, Malcolm. -- [] j a m k i t web solutions for charities malcolm cleaton T: 020 7549 0520 F: 020 7490 1152 M: 07986 563852 W: www.jamkit.com
Malcolm Cleaton wrote at 2005-6-9 10:13 +0100:
After a ConflictError causes a request to be retried, a few things go a bit wrong with error handling and logging in the Zope server.
1. If the request is abandoned after repeated ConflictErrors, no error at all appears in the error log.
Right: please file a bug report. The fix is (almost surely) to replace in ".../Zope/App/startup.py": if t is ZPublisher.Retry: v.reraise() by if t is ZPublisher.Retry: t, v, traceback = v._args
... 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). Nevertheless, the mixed use of "response" and "request.response" in "publish_module_standard" looks wrong. Almost surely, "request.response" should get the value of "response" when "publish" succeeds and both are different. Thus I expect, we should have: response = publish(...) request.response = response except ... Please file two bug reports for the problems you discovered... -- Dieter
On Thu, 09 Jun 2005 20:50:22 +0200, Dieter Maurer wrote:
The fix is (almost surely) to replace in ".../Zope/App/startup.py":
if t is ZPublisher.Retry: v.reraise()
by
if t is ZPublisher.Retry: t, v, traceback = v._args
Yes, that's better than my fix.
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.
Nevertheless, the mixed use of "response" and "request.response" in "publish_module_standard" looks wrong. Almost surely, "request.response" should get the value of "response" when "publish" succeeds and both are different. Thus I expect, we should have:
response = publish(...) request.response = response except ...
I don't know if this is right or not, but due to the way exceptions are propagating here it won't have any impact on this specific problem; the extra code won't be executed in this case.
Please file two bug reports for the problems you discovered...
I've filed one bug report; I'll scope it down to the first bug and add your better fix, and file another for the second bug. Thanks, Malcolm. -- [] j a m k i t web solutions for charities malcolm cleaton T: 020 7549 0520 F: 020 7490 1152 M: 07986 563852 W: www.jamkit.com
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... Apparently, "Retry" must be carefully rethought. Please file a critical bug report... -- Dieter
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
participants (2)
-
Dieter Maurer -
Malcolm Cleaton