IOError: request data read error

[Ryan J Ollos]

2015-12-23 21:11:35,203 Trac[main] ERROR: Internal Server Error: <RequestWithSession "POST '/newticket'">, referrer 'http://trac.edgewall.org/demo-1.0/newticket'
Traceback (most recent call last):
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/main.py", line 554, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/main.py", line 212, in dispatch
    self._pre_process_request(req, chosen_handler)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/main.py", line 375, in _pre_process_request
    chosen_handler = filter_.pre_process_request(req, chosen_handler)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/tracopt/ticket/deleter.py", line 111, in pre_process_request
    action = req.args.get('action')
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/api.py", line 338, in <lambda>
    'args': lambda req: arg_list_to_args(req.arg_list),
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/virtualenv/1.0-stable/lib/python2.7/site-packages/trac/web/api.py", line 725, in _parse_arg_list
    fs = _FieldStorage(fp, environ=self.environ, keep_blank_values=True)
  File "/usr/lib/python2.7/cgi.py", line 506, in __init__
    self.read_urlencoded()
  File "/usr/lib/python2.7/cgi.py", line 607, in read_urlencoded
    qs = self.fp.read(self.length)
IOError: request data read error

[Jun Omae]

Are you using mod_wsgi? If cannot read request body by network issues (e.g. the client disconnects, etc…), mod_wsgi raises the IOError exception.

Similar issue: #9973.

$ git grep "request data read error" 3.5
3.5:mod_wsgi.c:                PyErr_SetString(PyExc_IOError, "request data read error");
3.5:mod_wsgi.c:                    PyErr_SetString(PyExc_IOError, "request data read error");
3.5:mod_wsgi.c:            PyErr_SetString(PyExc_IOError, "request data read error");
3.5:mod_wsgi.c:                PyErr_SetString(PyExc_IOError, "request data read error");
3.5:mod_wsgi.c:                PyErr_SetString(PyExc_IOError, "request data read error");
3.5:mod_wsgi.c:                PyErr_SetString(PyExc_IOError, "request data read error");

[Ryan J Ollos]

Yeah, it's mod_wsgi 3.3 on Debian 7.9. Do you think we should just add request data read error to the tuple that was added in [11841]?

[Jun Omae]

The changes of [11841] trap IOError on writing data to client connection. Instead, it's need to trap the IOError on initiating FieldStorage.

Could you please try t12317-trap-ioerror-on-read-request.diff​?

[Ryan J Ollos]

Thanks, I'll install to demo server in the next day or so.

[Jun Omae]

I got the same error while reading the request body on initiating FieldStorage at another location. I think that is caused by the client disconnection. We can ignore the errors and the proposed patch would fix the noisy logging.

Traceback (most recent call last):
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/main.py", line 554, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/main.py", line 237, in dispatch
    req.args.get('__FORM_TOKEN') != req.form_token:
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/api.py", line 338, in <lambda>
    'args': lambda req: arg_list_to_args(req.arg_list),
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/api.py", line 355, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/api.py", line 725, in _parse_arg_list
    fs = _FieldStorage(fp, environ=self.environ, keep_blank_values=True)
  File "/usr/lib64/python2.6/cgi.py", line 508, in __init__
    self.read_multi(environ, keep_blank_values, strict_parsing)
  File "/usr/local/virtualenv/lib/python2.6/site-packages/trac/web/api.py", line 208, in read_multi
    cgi.FieldStorage.read_multi(self, *args, **kwargs)
  File "/usr/lib64/python2.6/cgi.py", line 637, in read_multi
    environ, keep_blank_values, strict_parsing)
  File "/usr/lib64/python2.6/cgi.py", line 510, in __init__
    self.read_single()
  File "/usr/lib64/python2.6/cgi.py", line 647, in read_single
    self.read_lines()
  File "/usr/lib64/python2.6/cgi.py", line 669, in read_lines
    self.read_lines_to_outerboundary()
  File "/usr/lib64/python2.6/cgi.py", line 697, in read_lines_to_outerboundary
    line = self.fp.readline(1<<16)
IOError: request data read error

[Christian Boos]

We also have a bunch of (errno.EPIPE, errno.ECONNRESET, 10053, 10054) in trac/web/wsgi.py, so we could now have:

def is_client_disconnect_exception(e):
    return e.args[0] in (errno.EPIPE, errno.ECONNRESET, _WSAECONNABORTED,
                         _WSAECONNRESET)

in trac/web/wsgi.py, and reuse it in api.py (as we already have a dependency in this direction due to the reuse of _FileWrapper).

[Ryan J Ollos]

Replying to Jun Omae:

I got the same error while reading the request body on initiating FieldStorage at another location. I think that is caused by the client disconnection. We can ignore the errors and the proposed patch would fix the noisy logging.

That sounds good. I've been seeing that traceback as well and posted in comment:3:ticket:12316. Feel free to take ownership of the ticket.

[Jun Omae]

Thanks for the review! Updated log:jomae.git@t12317 included suggested is_client_disconnect_exception().

Also, we can reproduce this issue with the following:

$ python -c "print('--_BOUNDARY_\r\nContent-Disposition: form-data; name=baz\r\n\r\n' + 'x' * 0x10000)" >./contents.dat
$ curl --header 'Content-Length: 123456789' --data @./contents.dat http://localhost/tracenv/ticket/1
^C  # <== kill curl process

[Jun Omae]

Committed in [14648] and merged to trunk in [14649].