ModPythonHandler class should check for IOError when writing response

[Eric Woudenberg]

Apache was reporting occasional 500 errors of this form:

64.158.138.84 - - [15/Jan/2009:21:21:02 +0000] "GET /feeds/recordings/ HTTP/1.1" 500 17156 "-" "BlogPulseLive (support@blogpulse.com)" 256 20528 220012 

Although Django itself was not emailing any errors, the Apache error_log contained:

mod_python (pid=6859, interpreter='dharmaseed.org', phase='PythonHandler', handler='django.core.handlers.modpython'): Application error
ServerName: 'dharmaseed.org'
DocumentRoot: '/htdocs'
URI: '/feeds/teacher/175/'
Location: '/feeds'
Directory: None
Filename: '/htdocs'
PathInfo: '/feeds/teacher/175/'
Traceback (most recent call last):
  File "/usr/lib/python2.5/site-packages/mod_python/importer.py", line 1537, in HandlerDispatch\n    default=default_handler, arg=req, silent=hlist.silent)
  File "/usr/lib/python2.5/site-packages/mod_python/importer.py", line 1229, in _process_target\n    result = _execute_target(config, req, object, arg)
  File "/usr/lib/python2.5/site-packages/mod_python/importer.py", line 1128, in _execute_target\n    result = object(arg)
  File "/usr/lib/python2.5/site-packages/django/core/handlers/modpython.py", line 228, in handler\n    return ModPythonHandler()(req)
  File "/usr/lib/python2.5/site-packages/django/core/handlers/modpython.py", line 220, in __call__\n    req.write(chunk)
IOError: Write failed, client closed connection.
python_handler: Dispatch() returned non-integer.

It gets an error writing the socket. (Perhaps it was closed prematurely by the remote side?). The remedy is to explicitly check for error:

        try:
            for chunk in response:
                req.write(chunk)
        except IOError:          # Explicitly ignore IOError if it occurs.
            pass
        finally:
            response.close()

Which is done in the attached patch.

[Eric Woudenberg]

Check for IOError during HTTP socket write

[Graham Dumpleton]

This is possibly not addressing the real problem.

Why is 'python_handler: Dispatch() returned non-integer.' happening in the first place.

It would seem to be the case that the Django mod_python handler has a return path where it is not returning a proper HTTP status code but something else.

Same problem could arise if an exception other than IOError is generated.

It is also debatable whether IOError should be ignored in this situation as there are other reasons why an IOError could be raised and for other types of IOError it may be important that you know it happened.

Your patch also doesn't address what happens if IOError were raised for other hosting mechanisms such as WSGI, FASTCGI etc.

[Eric Woudenberg]

Graham, thank you for looking at this. To answer your questions:

Replying to grahamd:

This is possibly not addressing the real problem.

Why is 'python_handler: Dispatch() returned non-integer.' happening in the first place.

It's not -- it's happening in the 'second place', after modpython.py returns an exception object to the C mod_python code.

It would seem to be the case that the Django mod_python handler has a return path where it is not returning a proper HTTP status code but something else.

Yes, and this is the path -- it's returning an Exception object rather than an integer code.

Same problem could arise if an exception other than IOError is generated.

Yes, and in that case we should let the crash occur, it would be something we would want to know about.

It is also debatable whether IOError should be ignored in this situation as there are other reasons why an IOError could be raised and for other types of IOError it may be important that you know it happened.

Yes, we could be more strict and just check for "Write failed, client closed connection." -- which I am sure can be safely ignored.

Your patch also doesn't address what happens if IOError were raised for other hosting mechanisms such as WSGI, FASTCGI etc.

I think this change is more or less generic. It says, effectively "Do not crash on network write errors -- they're normal".

[Graham Dumpleton]

In regard to 'python_handler: Dispatch() returned non-integer.', you don't understand what I am saying.

If the exception had managed to propagate all the way to mod_python C code level, which it shouldn't as mod_python Python code layer catches it and returns 500 instead after logging details, then it actually generates 'python_handler: Dispatch() returned nothing.'.

The exception 'IOError: Write failed, client closed connection.' is normal. The abnormal thing is 'python_handler: Dispatch() returned non-integer.' and shouldn't be occuring.

Thus, somewhere above this code layer something is already catching that exception and rather than propagating the exception or generating a proper integer value for the HTTP status return code, it would appear to be returning something else which is a non integer.

Before making any change, you need to investigate where this is occurring. Noting that this is actually occurring right at the final point before returning to mod_python, you may have actually found some obscure problem in mod_python itself.

The change is also not generic as it only applies to 'django/core/handlers/modpython.py'. This file is only used by mod_python adapter. It would not be used for adapters for WSGI, FASTCGI etc. By changing this code, you are putting in place a different behaviour for mod_python. For other adapters it would continue to propagate equivalent errors.

[Eric Woudenberg]

Hi Graham -- thank you again for your comments. Briefly:

Replying to grahamd:

If the exception had managed to propagate all the way to mod_python C code level, which it shouldn't as mod_python Python code layer catches it and returns 500 instead after logging details, then it actually generates 'python_handler: Dispatch() returned nothing.'.

But modpython.py does not catch the exception or return 500. Rather it's python_handler() in mod_python.c that is returning 500 (HTTP_INTERNAL_SERVER_ERROR) because it receives an IOError exception object instead of the integer object it was expecting from the python code. See: python_handler() in ​mod_python.c

The exception 'IOError: Write failed, client closed connection.' is normal. The abnormal thing is 'python_handler: Dispatch() returned non-integer.' and shouldn't be occuring.

For this to not occur there would have to be code added to mod_python.c to understand Python exception objects.

Thus, somewhere above this code layer something is already catching that exception and rather than propagating the exception or generating a proper integer value for the HTTP status return code, it would appear to be returning something else which is a non integer.

Nothing is catching the exception. It's being returned all the way to mod_python.c, which complains that it's not an integer.

The change is also not generic as it only applies to 'django/core/handlers/modpython.py'. This file is only used by mod_python adapter. It would not be used for adapters for WSGI, FASTCGI etc. By changing this code, you are putting in place a different behaviour for mod_python. For other adapters it would continue to propagate equivalent errors.

Ah thank you, I hadn't realized that. In any case, adapter code must conform to its upper layer APIs. In this case, modpython.py is violating mod_python.c's API by incorrectly trying to return an exception, something mod_python.c does not understand.

[Eric Woudenberg]

Replying to grahamd:

If the exception had managed to propagate all the way to mod_python C code level, which it shouldn't as mod_python Python code layer catches it and returns 500 instead after logging details, then it actually generates 'python_handler: Dispatch() returned nothing.'.

Apologies Graham, you're right. If an exception occurs, !PyObject_CallMethod should return null, not a Python exception object.

[Graham Dumpleton]

The C code doesn't directly call Django code, it is calling 'HandlerDispatch()' in mod_python.importer (for 3.3.1).

Ultimately 'HandlerDispatch()' calls '_execute_target()' which then calls handler supplied by Django.

Any exceptions, except for certain special ones, are caught by fallback except clause which calls 'ReportError()'.

It is the 'ReportError()' return status which is actually getting returned to C code.

Looking at the code for 'ReportError()' there possibly is a problem with it. That is, if an exception occurs in formatting the traceback to be output to Apache error log, then it can fall through to returning None instead of a valid Apache status value. This would trigger the error 'python_handler: Dispatch() returned non-integer.' error message.

I don't quite understand how formatting could cause an exception half way through and still show at least some of the information though, as it formats into a StringIO instance before trying to display it.

Thus, there possibly could be something amiss in mod_python error reporting that is causing this.

Anyway, this is a separate issue to whether Django should ignore an exception which is generated out of trying to write back the response via the web server. Problem is that how it forces response content to be written may be different for different hosting mechanisms. In mod_python it calls write() on mod_python request object. In WSGI it probably returns an iterable and it is the lower level WSGI layers that write response and Django has no way of catching an error which occurs in writing the response. Thus, whether something is written to logs in that case depends on what WSGI adapter for web server does.

[Eric Woudenberg]

Replying to jacob:

On its behalf: Without this change we get several Apache 500 errors per day (on a 50K hit-per-day website). Since the change is added to handle an expected condition (remote client closing the socket prematurely) I think it is better to include it, even with the caveat that the upper layer (mis-)handling of this error, when uncaught, still needs to be understood. Graham?

[endi]

We recently moved to mod_wsgi, and the error keeps appearing in our logs like it used to do before.
So it's not a mod_python-only issue, and it is confirmed in 1.1.

Also, bump.

[André Cruz]

I also get these errors dozens of times per day. The problem lies not only when writing the response but when requesting POST parameters on a POST multipart request. If the request is not complete or the response cannot be written django should have an option to continue silently. Here is an example traceback from the CSRF middleware:

Traceback (most recent call last):

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/core/handlers/base.py", line 95, in get_response
   response = middleware_method(request, callback, callback_args, callback_kwargs)

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/middleware/csrf.py", line 158, in process_view
   request_csrf_token = request.POST.get('csrfmiddlewaretoken', None)

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/core/handlers/wsgi.py", line 171, in _get_post
   self._load_post_and_files()

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/core/handlers/wsgi.py", line 137, in _load_post_and_files
   self._post, self._files = self.parse_file_upload(self.META, self.environ['wsgi.input'])

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/__init__.py", line 124, in parse_file_upload
   return parser.parse()

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/multipartparser.py", line 192, in parse
   for chunk in field_stream:

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/multipartparser.py", line 314, in next
   output = self._producer.next()

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/multipartparser.py", line 468, in next
   for bytes in stream:

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/multipartparser.py", line 314, in next
   output = self._producer.next()

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/multipartparser.py", line 375, in next
   data = self.flo.read(self.chunk_size)

 File "/servers/python-2.6/lib/python2.6/site-packages/Django-1.2.1-py2.6.egg/django/http/multipartparser.py", line 405, in read
   return self._file.read(num_bytes)

IOError: request data read error


<WSGIRequest
GET:<QueryDict: {}>,
POST:<could not parse>,
COOKIES:{'_shibsession_49445349642e7361706f2e7074': '_f0',
'_swa_uv': '3346690041278958258',
'_swa_v': '4056487021281436498',
'csrftoken': 'abe42a7836f8c63796897ba2b487982c',
'sessionid': '7aef0bea88'},
META:{'AUTH_TYPE': 'shibboleth',
'CONTENT_LENGTH': '694660',
'CONTENT_TYPE': 'multipart/form-data; boundary=----WebKitFormBoundarysimXQBqzPfkcD9Mq',
'CSRF_COOKIE': 'abe42a7836f8c63796897ba2b487982c',
'DOCUMENT_ROOT': '/servers/profiles',
'GATEWAY_INTERFACE': 'CGI/1.1',
'HTTPS': '1',
'HTTP_ACCEPT': 'application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5',
'HTTP_ACCEPT_CHARSET': 'ISO-8859-1,utf-8;q=0.7,*;q=0.3',
'HTTP_ACCEPT_ENCODING': 'gzip,deflate,sdch',
'HTTP_ACCEPT_LANGUAGE': 'pt-PT,pt;q=0.8,en-US;q=0.6,en;q=0.4',
'HTTP_CACHE_CONTROL': 'max-age=0',
'HTTP_CONNECTION': 'keep-alive',
'HTTP_HOST': 'id.sapo.pt',
'HTTP_SHIB_APPLICATION_ID': 'IDSAPO',
'HTTP_SHIB_ASSERTION_COUNT': '',
'HTTP_SHIB_AUTHENTICATION_INSTANT': '2010-08-10T10:57:19.911Z',
'HTTP_SHIB_AUTHENTICATION_METHOD': 'urn:oasis:names:tc:SAML:1.0:am:unspecified',
'HTTP_SHIB_AUTHNCONTEXT_CLASS': 'urn:oasis:names:tc:SAML:1.0:am:unspecified',
'HTTP_SHIB_AUTHNCONTEXT_DECL': '',
'HTTP_USER_AGENT': 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/533.4 (KHTML, like Gecko) Chrome/5.0.375.125 Safari/533.4',
'PATH_INFO': u'/a/upload_avatar',
'QUERY_STRING': '',
'REQUEST_METHOD': 'POST',
'REQUEST_URI': '/a/upload_avatar',
'SCRIPT_NAME': u'',
'SCRIPT_URI': 'https://id.sapo.pt/a/upload_avatar',
'SCRIPT_URL': '/a/upload_avatar',
'SERVER_PROTOCOL': 'HTTP/1.1',
'SERVER_SIGNATURE': '',
'SERVER_SOFTWARE': 'Apache',
'SSL_CIPHER': 'RC4-MD5',
'SSL_CIPHER_ALGKEYSIZE': '128',
'SSL_CIPHER_EXPORT': 'false',
'SSL_CIPHER_USEKEYSIZE': '128',
'SSL_CLIENT_VERIFY': 'NONE',
'SSL_COMPRESS_METHOD': 'NULL',
'SSL_PROTOCOL': 'TLSv1',
'SSL_SECURE_RENEG': 'false',
'SSL_SERVER_A_KEY': 'rsaEncryption',
'SSL_SERVER_A_SIG': 'sha1WithRSAEncryption',
'SSL_SERVER_M_SERIAL': '426C6EA4',
'SSL_SERVER_M_VERSION': '3',
'SSL_SERVER_S_DN': '/C=PT/O=MULTICERT-CA/OU=CERTIPOR - RA/OU=Corporate/OU=PT Comunicacoes S.A./OU=Web Server/CN=id.sapo.pt',
'SSL_SERVER_S_DN_C': 'PT',
'SSL_SERVER_S_DN_CN': 'id.sapo.pt',
'SSL_SERVER_S_DN_O': 'MULTICERT-CA',
'SSL_SERVER_S_DN_OU': 'CERTIPOR - RA',
'SSL_SERVER_S_DN_OU_1': 'Corporate',
'SSL_SERVER_S_DN_OU_2': 'PT Comunicacoes S.A.',
'SSL_SERVER_S_DN_OU_3': 'Web Server',
'SSL_SERVER_V_END': 'Apr 22 16:34:31 2012 GMT',
'SSL_SERVER_V_START': 'Apr 22 16:33:03 2010 GMT',
'SSL_VERSION_INTERFACE': 'mod_ssl/2.2.16',
'mod_wsgi.application_group': 'id.sapo.pt|',
'mod_wsgi.callable_object': 'application',
'mod_wsgi.handler_script': '',
'mod_wsgi.input_chunked': '0',
'mod_wsgi.listener_host': '',
'mod_wsgi.listener_port': '443',
'mod_wsgi.process_group': '',
'mod_wsgi.request_handler': 'wsgi-script',
'mod_wsgi.script_reloading': '1',
'mod_wsgi.version': (3, 3),
'wsgi.errors': <mod_wsgi.Log object at 0x994e5fc0>,
'wsgi.file_wrapper': <built-in method file_wrapper of mod_wsgi.Adapter object at 0x99431260>,
'wsgi.input': <mod_wsgi.Input object at 0x994e5e08>,
'wsgi.multiprocess': True,
'wsgi.multithread': True,
'wsgi.run_once': False,
'wsgi.url_scheme': 'https',
'wsgi.version': (1, 1)}>

[Almad]

Confirming bug -- observed with Django 1.3.1 on latest Debian Stable (Squeeze).

[Carl Meyer]

Given that the mod_python handler has been deprecated in Django since 1.3 in favor of the mod_wsgi handler and is scheduled to be removed entirely in Django 1.5, and that it's not at all clear from the above discussion (which included the mod_python maintainer who has since moved on to mod_wsgi) that this is even a correct fix, I'm wontfixing this. We just don't have development energy to spare on figuring out the correct fix for a deprecated handler: just use mod_wsgi instead.

Thanks for the contributions from the various people in this thread, sorry it's likely not going to make it in.

[anonymous]

This is also a problem under mod_wsgi.

[Carl Meyer]

Since this can occur under mod_wsgi as well as mod_python, the original reason for a wontfix (deprecation of mod_python handler) does not apply. (I now see that mod_wsgi was mentioned earlier in the thread, sorry I missed that the first time around.)

However, after discussion with grahamd (author of mod_wsgi) on IRC, we are in agreement that the proposed fix here (catching IOError in Django's handler) is not appropriate, and could mask other, more serious, errors (and that users should have the choice of whether the error described here is "interesting" to them, Django should not make a unilateral decision that it is not). In other words, this is not an issue in Django's WSGIHandler, the correct fix is for users to filter error reporting in order to not email errors that are uninteresting to them. Thus the wontfix still stands.

Since Django's admin error emails are now handled by the Python stdlib logging module, filtering them is rather easy - just a matter of defining a custom logging Filter and including it in your logging config. This can be done today and doesn't require any code changes to Django. We could add a documentation example of doing this; that's tracked by #17069.

[Thomas Güttler]

Related question on stackoverflow: ​http://stackoverflow.com/questions/3823280/ioerror-request-data-read-error