Many servers (wsgiref, http.server, etc) can truncate large output blobs

[JonathanKamens]

BPO	24291
Nosy	@pjeby, @pitrou, @benjaminp, @tarekziade, @vadmium, @serhiy-storchaka, @jamadden
Files	wsgi-partial.py: Demo wfile-partial.patch wfile-partial.v2.patch wfile-partial.v3.patch wsgiref-only.patch: wsgiref fix only wsgiref-only.v2.patch wfile-partial.v4.patch wfile-partial.v5.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2017-10-27.22:16:08.493>
created_at = <Date 2015-05-26.20:18:01.494>
labels = ['type-bug', 'library', 'expert-IO']
title = 'Many servers (wsgiref, http.server, etc) can truncate large output blobs'
updated_at = <Date 2017-10-27.22:16:08.491>
user = 'https://bugs.python.org/JonathanKamens'

bugs.python.org fields:

activity = <Date 2017-10-27.22:16:08.491>
actor = 'martin.panter'
assignee = 'none'
closed = True
closed_date = <Date 2017-10-27.22:16:08.493>
closer = 'martin.panter'
components = ['Library (Lib)', 'IO']
creation = <Date 2015-05-26.20:18:01.494>
creator = 'Jonathan Kamens'
dependencies = []
files = ['42411', '42412', '42427', '42870', '43066', '43143', '43233', '43840']
hgrepos = []
issue_num = 24291
keywords = ['patch']
message_count = 30.0
messages = ['244131', '244138', '244489', '244505', '244506', '244550', '260844', '262830', '262831', '262833', '262834', '262835', '262836', '262837', '263079', '263085', '263087', '263163', '263789', '265528', '265615', '265691', '266750', '266926', '266986', '267097', '267393', '267406', '271066', '305140']
nosy_count = 12.0
nosy_names = ['pje', 'pitrou', 'benjamin.peterson', 'tarek', 'stutzbach', 'python-dev', 'martin.panter', 'serhiy.storchaka', 'jmadden', 'Jonathan Kamens', 'marcjofre', 'Paolo Veglia']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue24291'
versions = ['Python 3.5']

[JonathanKamens]

The _write method of wsgiref.handlers.SimpleHandler reads as follows:

    def _write(self,data):
        self.stdout.write(data)

The problem here is that calling write() on a socket is not actually guaranteed to write all of the data in the buffer. If the length of data is large enough, then the kernel will take only part of it. In that case, the rest of the response data will be silently discarded by wsgiref.

_write needs to check the return value of self.stdout.write(data), and if it is less than the length of data, repeat the write from the middle of the data buffer, etc., until all the data has been written.

[vadmium]

[UTF-8 error workaround]

What kind of object is “stdout”? Plain Python socket objects don’t have a write() method.

Perhaps “stdout” is meant to implement the BufferedIOBase.write() interface, which guarantees everything is written, even if it takes multiple raw calls. Wrapping your output stream in BufferedWriter might be a solution.

[marcjofre]

When executing, wsgiref produces the following error dump:
D:\SixSensoCytometerWebBased\include\bin>D:\SixSensoCytometerWebBased\include\bi
n\manage.exe runserver 8765
Validating models...

0 errors found
May 26, 2015 - 16:20:56
Django version 1.5.8, using settings 'settings'
Development server is running at http://127.0.0.1:8765/
Quit the server with CTRL-BREAK.
[26/May/2015 16:20:56] "GET / HTTP/1.1" 200 29661
100
[26/May/2015 16:20:59] "POST /login HTTP/1.1" 200 25980
[26/May/2015 16:20:59] "GET /static/js/ready.js HTTP/1.1" 500 79563
Traceback (most recent call last):
  File "D:\WinPython-64bit-2.7.6.3\python-2.7.6.amd64\Lib\wsgiref\handlers.py",
line 86, in run
    self.finish_response()
  File "D:\WinPython-64bit-2.7.6.3\python-2.7.6.amd64\Lib\wsgiref\handlers.py",
line 128, in finish_response
    self.write(data)
  File "D:\WinPython-64bit-2.7.6.3\python-2.7.6.amd64\Lib\wsgiref\handlers.py",
line 217, in write
    self._write(data)
  File "D:\WinPython-64bit-2.7.6.3\python-2.7.6.amd64\lib\socket.py", line 324,
in write
[26/May/2015 16:20:59] "GET /static/js/ClasePrincipalAutobahn.js HTTP/1.1" 500 7
9818
[26/May/2015 16:20:59] "GET /static/img/initialGUIimage.png HTTP/1.1" 500 79777
    self.flush()
  File "D:\WinPython-64bit-2.7.6.3\python-2.7.6.amd64\lib\socket.py", line 303,
in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
error: [Errno 10053] An established connection was aborted by the software in yo
ur host machine

[vadmium]

Marc, if you think your connection aborted error is related, can you say what kind of object the “stdout” parameter is in the handler class? In other words, what class’s method is being called in the write() function at line 217?

[vadmium]

Actually, looking closer at Marc’s traceback, it appears to be the ordinary socket._fileobject class. So I suspect it is unrelated to this bug because the Python 2 socket code appears to call sendall() in a loop.

[marcjofre]

Hi all,

I did more tests, identifying that the main issue I have resides in another script (multiprocessing), when using nuitka compiler.

I will get back to you with more info when I solve the multiprocessing issue.

The command prompt dump is:

data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042954F8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042954F8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042954F8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x0000000004291A20>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x0000000004291B10>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042917C8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x0000000004291930>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042954F8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042954F8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042919A8>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x0000000004291930>
data: HTTP/1.0 200 OK
self.stdout: <socket._fileobject object at 0x00000000042954F8>
data: HTTP/1.0 500 INTERNAL SERVER ERROR
self.stdout: <socket._fileobject object at 0x00000000042954F8>

[PaoloVeglia]

I had the same issue as Jonathan with Python 3.5.1, big chunks of data get truncated (to ~85KB).

The problem disappears when splitting original data into smaller chunks:

    def _write(self,data):
        chunk_size = 1024
        for chunk in (data[i:i+chunk_size] for i in range(0, len(data), chunk_size)):
            self.stdout.write(chunk)

[jamadden]

gevent has another simple reproducer for this. I do believe it's not gevent's fault, the fault is in the standard library; SimpleHandler._write needs to loop until sent += self.stdeout.write(data) is len(data).

I have written up more on this at gevent/gevent#778 (comment) For convenience I'll reproduce the bulk of that comment here:

The user supplied a django application that produced a very large response that was getting truncated when using gevent under Python 3.4. (I believe gevent's non-blocking sockets are simply running into a different buffering behaviour, making it more likely to be hit under those conditions simply because they are faster).

This looks like a bug in the standard library's wsgiref implementation.

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.

[jamadden]

Django uses a wsgiref.simple_server to serve requests, which in turn uses socketserver.StreamRequestHandler to implement its WSGIRequestHandler. That base class explicitly turns off buffering for writes (wbufsize = 0 is the class default which gets passed to socket.makefile). So that explains how there's no BufferedWriter wrapped around the SocketIO instance.

[vadmium]

Okay now I see the conflict. The use of WSGIRequestHandler with wbufsize = 0 was the missing key. I see two possible solutions:

1. Change SimpleHandler._write() to allow self.stdout to be a RawIOBase writer, and loop over stdout.write() until all the data is written. This seems to be what most people are suggesting here. But it requires that stdout.write() returns the number of bytes written, so could be a compatibility problem.

2. Document that the SimpleHandler(stdout=...) parameter should be a BufferedIOBase writer, and fix WSGIRequestHandler to pass in a BufferedWriter (by overriding the wbufsize attribute with -1 or io.DEFAULT_BUFFER_SIZE).

I am not super familiar with the wsgiref package, but the second option seems more preferable to me and more in line with my understanding of how it was intended to work.

[jamadden]

Is there an expected self.stdout implementation that doesn't return the number of bytes it writes? sys.stdout does, as does io.RawIOBase. It doesn't seem clear to me that practically speaking there's a compatibility problem with requiring that for self.stdout.

[jamadden]

self.stdin and self.stderr are documented to be wsgi.input and wsgi.errors, which are both described as "file-like" objects, meaning that the write method should return bytes written. It seems like the same could reasonably be said to be true for self.stdout, though it isn't strictly documented as such.

The WSGI spec says that each chunk the application yields should be written immediately, with no buffering (https://www.python.org/dev/peps/pep-3333/#buffering-and-streaming), so I don't think having the default output stream be buffered would be in compliance.

If there is a compatibility problem, writing the loop this way could bypass it (untested):

  def _write(self, data):
    written = self.stdout.write(data)
    while written is not None and written < len(data):
        written += self.stdout.write(data[written:])

[vadmium]

My worry was that it is easy to make a write() method that does not return anything, but is still useful in most cases. Since BufferedIOBase.write() has to guarantee to write everything, it may not seem important to return a value. But we could explicitly check for None as you suggested.

In the BaseHandler class, each chunk yielded by the application is passed to BaseHandler.write(). But that method calls self._flush(), which should avoid any buffering problem. SimpleHandler._flush() implements this by calling self.stdout.flush().