Edgewall Software

Opened 8 years ago

Closed 8 years ago

#12317 closed defect (fixed)

IOError: request data read error — at Version 10

Reported by: Ryan J Ollos Owned by: Jun Omae
Priority: normal Milestone: 1.0.11
Component: web frontend Version:
Severity: normal Keywords:
Cc: Branch:
Release Notes:

Avoid logging stacktrace of IOError while reading request.

API Changes:
Internal Changes:

Description

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

Change History (11)

comment:1 by Jun Omae, 8 years ago

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");
Last edited 8 years ago by Jun Omae (previous) (diff)

comment:2 by Ryan J Ollos, 8 years ago

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]?

comment:3 by Jun Omae, 8 years ago

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?

comment:4 by Ryan J Ollos, 8 years ago

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

comment:5 by Ryan J Ollos, 8 years ago

Milestone: 1.0.101.0.11

comment:6 by Jun Omae, 8 years ago

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

comment:7 by Christian Boos, 8 years ago

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).

in reply to:  6 comment:8 by Ryan J Ollos, 8 years ago

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.

comment:9 by Jun Omae, 8 years ago

Component: generalweb frontend
Owner: changed from Ryan J Ollos to 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

comment:10 by Jun Omae, 8 years ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

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

Note: See TracTickets for help on using tickets.