client disconnect errors are logged again with newer versions of mod_wsgi

[Christian Boos]

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.

[Christian Boos]

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

[Jun Omae]

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

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

[Christian Boos]

Fixed in r15323, merged up in r15324 and r15325.

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

[Jun Omae]

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

trac/web/api.py

@@ -832 +832 @@
         # Note that mod_wsgi raises an IOError with only a message
         # if the client disconnects
         if 'mod_wsgi.version' in self.environ:
-            if 'mod_wsgi.version' in self.environ:
-                mod_wsgi_prefix = 'Apache/mod_wsgi '
-                m = e.args[0]
-                if m.startswith(mod_wsgi_prefix):
-                    m = m[len(mod_wsgi_prefix):]
+            mod_wsgi_prefix = 'Apache/mod_wsgi '
+            m = e.args[0]
+            if m.startswith(mod_wsgi_prefix):
+                m = m[len(mod_wsgi_prefix):]
             return m.startswith(('failed to write response data',
                                  'failed to write data',
                                  '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

[Christian Boos]

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

[Christian Boos]

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,

[Christian Boos]

See [ab5bebe0/cboos.git].

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

[Ryan J Ollos]

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.

[Christian Boos]

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.

[Christian Boos]

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.