classification
Title: Unintuitive error handling in wsgiref when a crash happens in write() or close()
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: berker.peksag, chris.jerdonek, jleclanche, martin.panter
Priority: normal Keywords: 3.2regression, patch

Created on 2017-01-06 19:41 by jleclanche, last changed 2019-05-19 16:29 by berker.peksag. This issue is now closed.

Files
File name Uploaded Description Edit
test_server.py jleclanche, 2017-01-06 19:41 Reproduction test case (visit localhost:8080)
Pull Requests
URL Status Linked Edit
PR 12914 merged berker.peksag, 2019-04-22 20:00
PR 13424 merged miss-islington, 2019-05-19 15:56
Messages (6)
msg284844 - (view) Author: Jerome Leclanche (jleclanche) Date: 2017-01-06 19:41
TLDR: When an error happens in the wsgiref's write() or close(), stack traces get inundated with irrelevant yet legitimate errors which make it hard to track down the real issue.

Couple of examples of this happening in practice:
https://stackoverflow.com/questions/28124461/how-do-i-solve-nonetype-object-is-not-callable-with-beautifulsoup-and-bottle

https://stackoverflow.com/questions/27518844/error-when-serving-html-with-wsgi

----

How to reproduce: The file I've attached reproduces the error on python 3.4, 3.5 and 3.6. The handler returns a string instead of bytes, which fails an early assert in handlers.py: write(data).

BaseHandler.run() triggers, gets as far as finish_response(), which triggers the above AssertionError. It falls into the except: block which attempts to handle_error(). But before doing that, it triggers self.close(), which sets result/headers/status/environ to None, bytes_sent to 0 and headers_sent to False.

Now when handle_error() triggers, `self.headers_sent` is False because of that, which attempts to trigger finish_response() *again*. This triggers a write() which attempts sending the headers, which checks client_is_modern(), subscripting `self.environ` which at that point has already been set to None. New error, which is caught in run()'s except block and re-raised after closing the connection (again).

I probably skipped some steps because the traceback is truly a mess. I think this could be improved, if only so that it doesn't get so confusing anymore.
msg329223 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2018-11-04 11:20
Looks like the error handling is broken by Issue 16220, which calls the “BaseHandler.close” method before the exception is caught for the error handler. Perhaps it is better to just close the iterator without messing with the other attributes in the exception case.

I tried various cases in Python 2.6 (without the Issue 16220 change) and the error handling seems better (not masked by double exceptions, no sending a 500 response after the start of the app’s response).

The same problem exists in Python 2, except only the later exception is reported, and the original exception is forgotten.
msg329277 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2018-11-05 03:10
This may or may not be the same as what you're suggesting, Martin. But is another option to make close() a no-op if it is called a second time? Otherwise, it seems we'd need to make sure that no code path can result in close() being called twice (even during exception handling, etc).
msg329890 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2018-11-14 08:03
There are actually two “close” methods in the WSGI package: ServerHandler’s implementation extends the BaseHandler implementation. Making the “close” methods do nothing if called a second time would avoid the error about “self.status” being None, but won’t help very much with other problems, such as:

* If no response has been sent when the exception happens, the first call to “ServerHandler.close” still won’t have a HTTP status code or response size to log. It is more useful in this case to log the 500 code in the second “close” call after the error page is generated, which is what happens in 2.6.

* If the response was started when the exception happens, the first call to “BaseHandler.close” will still reset “self.headers_sent”, which fools “handle_error” into trying to generate a 500 response despite already having started the application response.

To be clear, what I had in mind last week was to adjust “finish_response” to look something like:

class BaseHandler:
    ...
    def finish_response(self):
        try:
            ...
        except:
            # Limited version of “close” method on exception
            if hasattr(self.result, 'close'):
                self.result.close()
            raise
        self.close()  # Full “close” method when no exception

For the record: This is related to Issue 27682, specifically about handling ConnectionAbortedError and other network errors.
msg342861 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2019-05-19 15:56
New changeset 7c59362a15dfce538512ff1fce4e07d33a925cfb by Berker Peksag in branch 'master':
bpo-29183: Fix double exceptions in wsgiref.handlers.BaseHandler (GH-12914)
https://github.com/python/cpython/commit/7c59362a15dfce538512ff1fce4e07d33a925cfb
msg342863 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2019-05-19 16:28
New changeset f393e8eb463d60ce559982613429568c518ab8d9 by Berker Peksag (Miss Islington (bot)) in branch '3.7':
bpo-29183: Fix double exceptions in wsgiref.handlers.BaseHandler (GH-12914)
https://github.com/python/cpython/commit/f393e8eb463d60ce559982613429568c518ab8d9
History
Date User Action Args
2019-05-19 16:29:18berker.peksagsetstatus: open -> closed
stage: patch review -> resolved
resolution: fixed
components: + Library (Lib)
versions: + Python 3.7, Python 3.8, - Python 2.7, Python 3.4, Python 3.5, Python 3.6
2019-05-19 16:28:41berker.peksagsetmessages: + msg342863
2019-05-19 15:56:32berker.peksagsetnosy: + berker.peksag
messages: + msg342861
2019-05-19 15:56:27miss-islingtonsetpull_requests: + pull_request13334
2019-04-22 20:00:37berker.peksagsetkeywords: + patch
stage: patch review
pull_requests: + pull_request12840
2018-11-14 08:03:16martin.pantersetmessages: + msg329890
2018-11-05 03:10:56chris.jerdoneksetnosy: + chris.jerdonek
messages: + msg329277
2018-11-04 11:20:48martin.pantersetversions: + Python 2.7
nosy: + martin.panter

messages: + msg329223

keywords: + 3.2regression
type: behavior
2017-01-06 19:41:41jleclanchecreate