Edgewall Software
Modify

Opened 3 years ago

Closed 3 years ago

#12650 closed defect (fixed)

client disconnect errors are logged again with newer versions of mod_wsgi

Reported by: Christian Boos Owned by: Christian Boos
Priority: normal Milestone: 1.0.14
Component: web frontend/mod_wsgi Version:
Severity: normal Keywords: logging
Cc: Branch:
Release Notes:

Reduce logging noise with client disconnects, for recent versions of mod_wsgi (e.g. 4.5.13)

API Changes:

Description

We have an internal check to avoid polluting the trac.log with errors related to client disconnections or response write failures.

For mod_wsgi, this check rely on error messages. Newer versions (don't know since when exactly) add the "Apache/mod_wsgi" prefix to these messages, so we need to take that into account.

Example:

[pid 3682 139642907973376] 2017-01-05 17:00:28,194 Trac[main] ERROR: Internal Server Error: <RequestWithSession "GET '/log/trunk/trac/admin?rev=11508'">, referrer None
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 617, in _dispatch_request
    dispatcher.dispatch(req)
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 274, in dispatch
    req.send(output, content_type or 'text/html')
  File "build/bdist.linux-x86_64/egg/trac/web/api.py", line 693, in send
    self.write(content)
  File "build/bdist.linux-x86_64/egg/trac/web/api.py", line 833, in write
    self._write(''.join(buf))
IOError: Apache/mod_wsgi failed to write response data: Broken pipeBroken pipe

Also, it's "failed to write response data" now instead of "failed to write data".

I think fixing this starting from 1.0 is good enough.

Attachments (0)

Change History (12)

comment:1 by Christian Boos, 3 years ago

I thought it was a good idea to use a 'dev-mod_wsgi_prefix' tag while testing the change live on t.e.o, unfortunately, this variant of the 'dev' tag caused the SpamFilter to refuse to load…

[pid 3681 139642907973376] 2017-01-05 16:55:18,068 Trac[loader] ERROR: Skipping "spamfilter = tracspamfilter.api": (version conflict "VersionConflict: (Trac 1.2.1dev-mod-wsgi-prefix (/usr/local/virtualenv/1.2-stable/lib/python2.7/site-packages/Trac-1.2.1dev_mod_wsgi_prefix-py2.7.egg), Requirement.parse('Trac>=1.0'))")

Good to know ;-)

comment:2 by Jun Omae, 3 years ago

1.2.1dev-mod-wsgi-prefix string is incompatible with PEP-440. As the result, requirement Trac>=1.0 fails. dev tag is not the reason to fail.

>>> from pkg_resources import parse_version
>>> parse_version('1.2.1dev-mod-wsgi-prefix')
<LegacyVersion('1.2.1dev-mod-wsgi-prefix')>
>>> parse_version('1.2.1dev') >= parse_version('1.0')
True
>>> parse_version('1.2.1dev-mod-wsgi-prefix') >= parse_version('1.0')
False
>>> parse_version('1.0dev') >= parse_version('1.0')
False
>>> parse_version('1.0') >= parse_version('1.0')
True

comment:3 by Christian Boos, 3 years ago

Thanks for the heads up, Jun! I seemed to remember something like that, yes. It's too bad we can't use that, as it would be very handy to have a quick way to check in the /about page that we have indeed loaded the version of Trac we expected.

comment:4 by Christian Boos, 3 years ago

Resolution: fixed
Status: assignedclosed

Fixed in r15323, merged up in r15324 and r15325.

in reply to:  3 ; comment:5 by Ryan J Ollos, 3 years ago

Replying to Christian Boos:

Thanks for the heads up, Jun! I seemed to remember something like that, yes. It's too bad we can't use that, as it would be very handy to have a quick way to check in the /about page that we have indeed loaded the version of Trac we expected.

See also #12038.

comment:6 by Jun Omae, 3 years ago

After [15323], if 'mod_wsgi.version' in self.environ line is duplicated.

  • trac/web/api.py

    diff --git a/trac/web/api.py b/trac/web/api.py
    index 3b2a8794b..f04cc6b0a 100644
    a b class Request(object):  
    832832        # Note that mod_wsgi raises an IOError with only a message
    833833        # if the client disconnects
    834834        if 'mod_wsgi.version' in self.environ:
    835             if 'mod_wsgi.version' in self.environ:
    836                 mod_wsgi_prefix = 'Apache/mod_wsgi '
    837                 m = e.args[0]
    838                 if m.startswith(mod_wsgi_prefix):
    839                     m = m[len(mod_wsgi_prefix):]
     835            mod_wsgi_prefix = 'Apache/mod_wsgi '
     836            m = e.args[0]
     837            if m.startswith(mod_wsgi_prefix):
     838                m = m[len(mod_wsgi_prefix):]
    840839            return m.startswith(('failed to write response data',
    841840                                 'failed to write data',
    842841                                 'client connection closed',

Another think: an IOError typically has message and errno but several WSGI containers (mod_wsgi, uWSGI, …) raise an IOError without errno because errno cannot be retrieved when reading request/writing response is failing. It might be good to assume client disconnected when the IOError doesn't have errno.

https://github.com/unbit/uwsgi/search?utf8=%E2%9C%93&q=PyExc_IOError%2C+%22write+error%22&type=Code

in reply to:  5 comment:7 by Christian Boos, 3 years ago

Replying to Ryan J Ollos:

Replying to Christian Boos:

Thanks for the heads up, Jun! I seemed to remember something like that, yes. It's too bad we can't use that, as it would be very handy to have a quick way to check in the /about page that we have indeed loaded the version of Trac we expected.

See also #12038.

Yes, and now I see I simply should have used a '+' as a separator instead of a '-' (pep:0440/#local-version-identifiers):

>>> from pkg_resources import parse_version
>>> parse_version('1.2.1dev+mod_wsgi_spec') >= parse_version('1.0dev')
True

in reply to:  6 comment:8 by Christian Boos, 3 years ago

Replying to Jun Omae:

After [15323], if 'mod_wsgi.version' in self.environ line is duplicated.

Hmpf, yes…

Another think: an IOError typically has message and errno but several WSGI containers (mod_wsgi, uWSGI, …) raise an IOError without errno because errno cannot be retrieved when reading request/writing response is failing. It might be good to assume client disconnected when the IOError doesn't have errno.

That would simplify things indeed. I'll give it a try,

comment:9 by Christian Boos, 3 years ago

Resolution: fixed
Status: closedreopened

See [ab5bebe0/cboos.git].

I also simplified the isinstance check, since we're on Python ≥ 2.6 on 1.0.

comment:10 by Ryan J Ollos, 3 years ago

There continue to be many instances of the traceback shown in comment:description for t.e.o. Is that expected? The version is +t16250.2, which is different than the comment:9 patch.

comment:11 by Christian Boos, 3 years ago

Status: reopenedassigned

It's been a few days now it's running with cboos.git@t12650.1, and the errors seem to be correctly ignored.

The /var/log/apache2/error.log show the following for the print >> sys.stderr I left in the is_client_disconnect_exception function:

[Tue Jan 24 06:23:24.655440 2017] [wsgi:error] [pid 25443:tid 139725917722368] [remote 42.156.138.82:52351] is_client_disconnect_exception: IOError = None

errno is indeed None for mod_wsgi.

comment:12 by Christian Boos, 3 years ago

Resolution: fixed
Status: assignedclosed

We still support Python 2.5 on 1.0.14… Well, sorry, I no longer have a running Python 2.5 version for testing, I hope everything will be OK.

Only applying [219e462e/cboos.git] on 1.0-stable (r15377) and [73743369/cboos.git] goes on 1.2-stable (r15378).

Merged on trunk in r15379.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Christian Boos.
The resolution will be deleted. Next status will be 'reopened'.
to as closed The owner will be changed from Christian Boos to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.