gevent 1.1.0 causes data truncation?

[jaddison]

I don't know how to best describe this, but monkey-patching Django in manage.py and using its runserver management command causes data 'truncation' issues in browsers. I see this error in the Chrome console:

Failed to load resource: net::ERR_CONTENT_LENGTH_MISMATCH

Althought sometimes I don't see this error, but the issue persists.

Pages fail to load properly; viewing the page source shows that html pages, css/js files are incompletely downloaded. If I disable the monkeypatching, all is well.

Environment: Python 3.4, Django dev code for 1.10

manage.py:

#!/usr/bin/env python

# TODO: set env variable GEVENT_RESOLVER=ares on servers (gunicorn, celery, etc)

try:
    from gevent import monkey
    monkey.patch_all()
except ImportError:
    pass

try:
    import psycogreen.gevent
    psycogreen.gevent.patch_psycopg()
except ImportError:
    pass

import os
import sys

if __name__ == "__main__":
    os.environ.setdefault("DJANGO_SETTINGS_MODULE", "myproj.settings")

    from django.core.management import execute_from_command_line

    execute_from_command_line(sys.argv)

[jamadden]

I'm afraid we'll need more details. Either an HTTP trace demonstrating the problem, or a standalone reproduction (e.g., not using something as complicated as django.)

[jamadden]

Is there any more information available?

[jaddison]

No, I do not know how to reproduce this without Django.

[jamadden]

Can you reproduce it with a stable django release? My understanding is that 1.10 changes their networking layer quite a bit.

[jaddison]

@jamadden I've reproduced this with Django's latest stable release (v1.9.5). Here is a sample repo: https://github.com/jaddison/gevent_django_cutoff

Steps to reproduce problem are in the repo's README.md.

Note that package versions installed were:

Django==1.9.5
gevent==1.1.0
greenlet==0.4.9

[jamadden]

@jaddison Thanks. I was able to reproduce this.

This looks like a bug in the standard library's wsgiref implementation (or possibly in the SimpleHTTPServer).

I tracked this down to a call to socket.send(data). This method only sends whatever portion of the data it is possible to send at the time, and it returns the count of the data that was sent. The caller of socket.send() is responsible for looping to make sure the full len of the data is sent. This is clearly documented.

In this case, there is a call to send trying to send the full response, but only a portion of it is able to be immediately written. Here's a transcript of the first request (I modified gevent's socket.send method to print how much data is actually sent each time):

Django version 1.9.5, using settings 'gdc.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.
SENDING 17
SENT 17 OF 17
SENDING 37
SENT 37 OF 37
SENDING 38
SENT 38 OF 38
SENDING 71
SENT 71 OF 71
SENDING 1757905
SENT 555444 OF 1757905
[03/Apr/2016 19:48:31] "GET / HTTP/1.1" 200 1757905

Note that there's no retry on the short send.

Here's the stack trace for that short send; we can clearly see that there is no retry loop in place:

  //3.4/lib/python3.4/wsgiref/handlers.py(138)run()
    136             self.setup_environ()
    137             self.result = application(self.environ, self.start_response)
--> 138             self.finish_response()
    139         except:
    140             try:

  //3.4/lib/python3.4/wsgiref/handlers.py(180)finish_response()
    178             if not self.result_is_file() or not self.sendfile():
    179                 for data in self.result:
--> 180                     self.write(data)
    181                 self.finish_content()
    182         finally:

  //3.4/lib/python3.4/wsgiref/handlers.py(279)write()
    277
    278         # XXX check Content-Length and truncate if too many bytes written?
--> 279         self._write(data)
    280         self._flush()
    281

  //3.4/lib/python3.4/wsgiref/handlers.py(453)_write()
    451
    452     def _write(self,data):
--> 453         self.stdout.write(data)
    454
    455     def _flush(self):

  //3.4/lib/python3.4/socket.py(398)write()
    396         self._checkWritable()
    397         try:
--> 398             return self._sock.send(b)
    399         except error as e:
    400             # XXX what about EINTR?

> //gevent/_socket3.py(384)send()
    382                 from IPython.core.debugger import Tracer; Tracer()() ## DEBUG ##
    383
--> 384             return count

self.stdout is an instance of socket.SocketIO (which is returned from socket.makefile). This is not documented on the web, but the docstring also clearly documents that callers of write should loop to make sure all data gets sent.

This has previously been reported to bugs.python.org. I'll add a comment there.

[jamadden]

One workaround I can offer is to do this in manage.py just after the monkey patch (tested for 1.9):

import django.core.servers.basehttp
django.core.servers.basehttp.WSGIRequestHandler.wbufsize = -1

This turns on buffering for the write SocketIO object (default is completely unbuffered) which should mask the problem (it does in this test case anyway).

[jaddison]

@jamadden, thank you for the quick turnaround on the cause of this, for pushing it up the line to the python bug tracker, and finally, for the workaround. Brilliant.

Closing this now, as it isn't gevent-specific.

[jamadden]

@jaddison And thank you for the small reproducible example!