tahoe-lafs/trac

regression coincident with iputil fixes, on FreeBSD and Slackware #2023

New issue

Closed

opened 2013-07-16 15:54:23 +00:00 by zooko · 15 comments

zooko commented

2013-07-16 15:54:23 +00:00

Our buildbot shows that when this batch of patches went in:

f77ec470d75f4b8fb81b1abca4ee3b73f1ad8b22, [8e31d66cd0b0821ccaa2c7c259e7d6f262ad4738], [6a445d73bc5253ec4ae0dec70af02e33bc869cf6], d85a75d7f689cb55ecddb319dc2057f38e4db87a

Then the FreeBSD and Slackware builders went from green to red. See this historical waterfall view:

[//buildbot-tahoe-lafs/waterfall?builder=Markus+slackware64+current&builder=Randy+FreeBSD-amd64&reload=none&last_time=1372000000 https://tahoe-lafs.org/buildbot-tahoe-lafs/waterfall?builder=Markus+slackware64+current&builder=Randy+FreeBSD-amd64&reload=none&last_time=1372000000]

Out of those four patches, I don't believe that d85a75d7f689cb55ecddb319dc2057f38e4db87a is relevant, but the other three could be. Especially note that the error message on the FreeBSD and Slackware builders is "twisted.trial.unittest.FailTest: Errors snooped, terminating early", and that f77ec470d75f4b8fb81b1abca4ee3b73f1ad8b22 adds a call to log.err. If that call to log.err is getting called, then that would cause the tests to fail in this way.

Our buildbot shows that when this batch of patches went in: f77ec470d75f4b8fb81b1abca4ee3b73f1ad8b22, [8e31d66cd0b0821ccaa2c7c259e7d6f262ad4738], [6a445d73bc5253ec4ae0dec70af02e33bc869cf6], d85a75d7f689cb55ecddb319dc2057f38e4db87a Then the FreeBSD and Slackware builders went from green to red. See this historical waterfall view: [//buildbot-tahoe-lafs/waterfall?builder=Markus+slackware64+current&builder=Randy+FreeBSD-amd64&reload=none&last_time=1372000000 <https://tahoe-lafs.org/buildbot-tahoe-lafs/waterfall?builder=Markus+slackware64+current&builder=Randy+FreeBSD-amd64&reload=none&last_time=1372000000>] Out of those four patches, I don't believe that d85a75d7f689cb55ecddb319dc2057f38e4db87a is relevant, but the other three could be. Especially note that the error message on the FreeBSD and Slackware builders is "twisted.trial.unittest.FailTest: Errors snooped, terminating early", and that f77ec470d75f4b8fb81b1abca4ee3b73f1ad8b22 adds a call to `log.err`. If that call to `log.err` is getting called, then that would cause the tests to fail in this way.

zooko added the

labels 2013-07-16 15:54:23 +00:00

zooko added this to the soon milestone 2013-07-16 15:54:23 +00:00

daira was assigned by zooko

2013-07-16 15:54:23 +00:00

daira commented

2013-07-17 15:10:13 +00:00

I'd already tried changing the log.err to log.msg, so it is more complicated than that.

I'd already tried changing the `log.err` to `log.msg`, so it is more complicated than that.

zooko modified the milestone from soon to 1.11.0

2013-08-28 15:37:20 +00:00

zooko commented

2013-12-02 14:00:07 +00:00

Author

#2121 may be a duplicate of this on markberger's development system.

daira commented

2014-09-02 16:43:51 +00:00

warner will get in touch with the buildslave owners and markberger.

daira removed their assignment 2014-09-02 16:43:51 +00:00

warner was assigned by daira

2014-09-02 16:43:51 +00:00

warner commented

2014-09-02 18:17:48 +00:00

I think I might have reproduced this locally (at least using the stock OS-X 10.9 python-2.7.5 gives me an "Address already in use" error during test_system.SystemTest.test_filesystem, which the Homebrew python-2.7.8 does not).

I'll investigate. I might back out the f77ec470 patch (the one that avoids dropping the Deferred).. I vaguely remember thinking about the differences between the normal tahoe run environment and the unit test environment that could be significant.

I think I might have reproduced this locally (at least using the stock OS-X 10.9 python-2.7.5 gives me an "Address already in use" error during `test_system.SystemTest.test_filesystem`, which the Homebrew python-2.7.8 does not). I'll investigate. I might back out the f77ec470 patch (the one that avoids dropping the Deferred).. I vaguely remember thinking about the differences between the normal `tahoe run` environment and the unit test environment that could be significant.

warner commented

2014-09-03 04:52:50 +00:00

.. and now I can't reproduce it, because using the OS-X python results in an "error: Installed distribution Twisted 12.2.0 conflicts with requirement twisted>=13.0". I know OS-X is providing that 12.2.0 Twisted, but I don't know what's insisting upon >=13.0 (I don't think it's tahoe). Did I mention that I really hate these sorts of packaging bugs?

warner commented

2014-09-03 05:31:55 +00:00

Oh, and now I can, by editing _auto_deps.py to require twisted >=13.0 . (maybe this causes twisted to be installed into support/lib/ before whatever other mysterious thing gets installed that demands >=13.0 but is unable to install it).

The cluster of failures I'm getting includes:

close failed in file object destructor: IO Error: [9]Errno Bad file descriptor.

This appears to be happening in node.Node._setup_tub > fileutil.write_atomically, just after calling
iputil.get_local_addresses_async(), as it tries to write the
kernel-assigned port number to disk. In one case, this caused an
exception to be caught by the node-startup-time Deferred chain, which
then bails (os.abort) via the Node._startService failed, aborting
path. In another case, this didn't actually flunk the test.

twisted.internet.error.CannotListenError: Couldn't listen on any:64198: [48]Errno Address already in use,

in SystemTestMixin.bounce_client as it tries to start up a new Client
service, just after shutting down the old one (and waiting for the
disownServiceParent deferred to fire, then waiting an extra 1.0
seconds for good measure). The arbitrary 1.0 second stall already
smells funny (I left a note there blaming windows, but I'm seeing this
problem on OS-X too).

CannotListenError, on any:0, with [9]Errno Bad file descriptor,

in get_local_addresses_async > get_local_ip_for > listenUDP > startListening > _bindSocket, again with the "close failed in file
object destructor" message, and triggering the Node._startService failed, aborting path.

exceptions.OSError: [9]Errno Bad file descriptor on a call to
os.urandom() inside Foolscap. I think this might be collateral

damage due to --rterrors or the bail-on-failure stuff, when the test
fails, but part of the code charges on ahead without realizing it, and
then you've got one thread closing all fds in preparation for
shutdown, and a different thread trying to use those fds.

sometimes combinations of these errors
I also see "Malformed file descriptor found. Preening lists." in the

logs, which happens when select() gets an error (ValueError,
TypeError, or our old friend Bad File Descriptor).

Exceptions that occur during object destructors are always screwy (actually anything that happens inside a destructor call is screwy). They're a concurrency hazard that's worse than threads: at least with threads you can pretend to fix the problem with locks. But it seems like something is triggering a bunch of Bad File Descriptor errors in random places.

Hm, I know Twisted has had, at various times, a feature to close extra fds when preparing for a fork(), and I think that code got simplified or changed recently (last two years?) to take advantage of some feature that lets you mark fds for automatic closing instead of manually calling os.close() on them. Maybe something in a newer version of python? I'm wondering if the thread that gets started when Twisted's DNS resolver is created (the one on which the blocking gethostbyname() is called), or the fork/exec that might happen when iputil.py spawns off ifconfig, is causing existing fds to be killed, wreaking all sorts of havoc.

Oh, and now I can, by editing `_auto_deps.py` to require twisted >=13.0 . (maybe this causes twisted to be installed into support/lib/ before whatever other mysterious thing gets installed that demands >=13.0 but is unable to install it). The cluster of failures I'm getting includes: * `close failed in file object destructor: IO Error: [9]Errno Bad file descriptor`. > This appears to be happening in `node.Node._setup_tub > > fileutil.write_atomically`, just after calling `iputil.get_local_addresses_async()`, as it tries to write the > kernel-assigned port number to disk. In one case, this caused an > exception to be caught by the node-startup-time Deferred chain, which > then bails (os.abort) via the `Node._startService failed, aborting` > path. In another case, this didn't actually flunk the test. * `twisted.internet.error.CannotListenError: Couldn't listen on any:64198: [48]Errno Address already in use`, > in `SystemTestMixin.bounce_client` as it tries to start up a new Client > service, just after shutting down the old one (and waiting for the `disownServiceParent` deferred to fire, then waiting an extra 1.0 > seconds for good measure). The arbitrary 1.0 second stall already > smells funny (I left a note there blaming windows, but I'm seeing this > problem on OS-X too). * `CannotListenError`, on `any:0`, with `[9]Errno Bad file descriptor`, > in `get_local_addresses_async > get_local_ip_for > listenUDP > > startListening > _bindSocket`, again with the "close failed in file > object destructor" message, and triggering the `Node._startService > failed, aborting` path. * `exceptions.OSError: [9]Errno Bad file descriptor` on a call to `os.urandom()` inside Foolscap. I think this might be collateral > damage due to --rterrors or the bail-on-failure stuff, when the test > fails, but part of the code charges on ahead without realizing it, and > then you've got one thread closing all fds in preparation for > shutdown, and a different thread trying to use those fds. * sometimes combinations of these errors * I also see "Malformed file descriptor found. Preening lists." in the > logs, which happens when `select()` gets an error (`ValueError`, `TypeError`, or our old friend Bad File Descriptor). Exceptions that occur during object destructors are always screwy (actually anything that happens inside a destructor call is screwy). They're a concurrency hazard that's worse than threads: at least with threads you can pretend to fix the problem with locks. But it seems like *something* is triggering a bunch of Bad File Descriptor errors in random places. Hm, I know Twisted has had, at various times, a feature to close extra fds when preparing for a fork(), and I think that code got simplified or changed recently (last two years?) to take advantage of some feature that lets you mark fds for automatic closing instead of manually calling os.close() on them. Maybe something in a newer version of python? I'm wondering if the thread that gets started when Twisted's DNS resolver is created (the one on which the blocking `gethostbyname()` is called), or the fork/exec that might happen when iputil.py spawns off ifconfig, is causing existing fds to be killed, wreaking all sorts of havoc.

zooko commented

2014-09-04 13:06:56 +00:00

Author

Replying to warner:

.. and now I can't reproduce it, because using the OS-X python results in an "error: Installed distribution Twisted 12.2.0 conflicts with requirement twisted>=13.0". I know OS-X is providing that 12.2.0 Twisted, but I don't know what's insisting upon >=13.0 (I don't think it's tahoe). Did I mention that I really hate these sorts of packaging bugs?

FWIW, this is #2249. Everyone hates these sorts of packaging bugs. :-(

Replying to [warner](/tahoe-lafs/trac/issues/2023#issuecomment-394195): > .. and now I can't reproduce it, because using the OS-X python results in an "error: Installed distribution Twisted 12.2.0 conflicts with requirement twisted>=13.0". I know OS-X is providing that 12.2.0 Twisted, but I don't know what's insisting upon >=13.0 (I don't think it's tahoe). Did I mention that I really hate these sorts of packaging bugs? FWIW, this is #2249. Everyone hates these sorts of packaging bugs. :-(

warner commented

2014-09-05 04:57:59 +00:00

FYI, I'm not getting the failures on linux (using python-2.7.5 nor 2.7.8). Bummer, because I've got more tools to investigate things there (I was thinking of strace'ing the process and watching for the close() calls).

warner commented

2014-09-11 00:45:10 +00:00

I've got a fix: https://github.com/tahoe-lafs/tahoe-lafs/pull/108

The core issue is that python-2.7.4, 2.7.5, 2.7.6, and 2.7.7 suffer from
python bug 18851 (http://bugs.python.org/issue18851), in which the
stdlib 'subprocess' module closes most/all (unrelated) file descriptors
when subprocess.call() fails the exec(), such as when the executable
being invoked does not actually exist. There appears to be some
randomness involved: it happened at different times during my tests.
This was fixed in python-2.7.8.

Tahoe's iputil.py uses subprocess.call on many different "ifconfig"-type
executables, most of which don't exist on any given platform (git commit
8e31d66). This results in a lot of random file-descriptor closing, which
(at least during unit tests) tends to clobber important things like Tub
TCP sockets. This seems to be the root cause behind #2121, in which
normal code tries to close already-closed sockets, gets an EBADF ("not a
socket") during node setup, and bails with os.abort(). Since different
platforms have different ifconfigs, some platforms will experience more
failed execs than others, so this bug could easily behave differently on
linux vs freebsd, as well as working normally on python-2.7.8 or 2.7.4.

My proposed fix is to switch to the 'subprocess32' module from PyPI,
which is a backport of the newer 'subprocess' from python3's stdlib. In
python issue 18851, Gregory P. Smith recommends subprocess32 for all
python2 users who would normally use the stdlib version, since it does
not suffer from this bug (and has other bugfixes too).

I'm pretty sure this is the fix for #2121. We could also fix it by
requiring python >= 2.7.8, but that would rule out development and
deployment on the current OS-X release 10.9 (which ships with
python-2.7.5), as well as other platforms. Using subprocess32 seems like
the easiest fix.

I don't know what exactly this ticket (#2023) is doing, since we no
longer have the logfiles that prompted it (note to future bug-reporters:
please copy the relevant part of the logs into the ticket, rather than
relying upon long-term access to buildbot logs). But since some of us
apparently believed that #2121 might be a duplicate, and since it's
plausible that this problem could appear on FreeBSD and Slackware from
that era and not on linux or other python versions, I'm willing to bet
that this change will fix #2023 too.

I've got a fix: <https://github.com/tahoe-lafs/tahoe-lafs/pull/108> The core issue is that python-2.7.4, 2.7.5, 2.7.6, and 2.7.7 suffer from python bug 18851 (<http://bugs.python.org/issue18851>), in which the stdlib 'subprocess' module closes most/all (unrelated) file descriptors when `subprocess.call()` fails the `exec()`, such as when the executable being invoked does not actually exist. There appears to be some randomness involved: it happened at different times during my tests. This was fixed in python-2.7.8. Tahoe's iputil.py uses subprocess.call on many different "ifconfig"-type executables, most of which don't exist on any given platform (git commit 8e31d66). This results in a lot of random file-descriptor closing, which (at least during unit tests) tends to clobber important things like Tub TCP sockets. This seems to be the root cause behind #2121, in which normal code tries to close already-closed sockets, gets an EBADF ("not a socket") during node setup, and bails with os.abort(). Since different platforms have different ifconfigs, some platforms will experience more failed execs than others, so this bug could easily behave differently on linux vs freebsd, as well as working normally on python-2.7.8 or 2.7.4. My proposed fix is to switch to the 'subprocess32' module from PyPI, which is a backport of the newer 'subprocess' from python3's stdlib. In python issue 18851, Gregory P. Smith recommends subprocess32 for all python2 users who would normally use the stdlib version, since it does not suffer from this bug (and has other bugfixes too). I'm pretty sure this is the fix for #2121. We could also fix it by requiring python >= 2.7.8, but that would rule out development and deployment on the current OS-X release 10.9 (which ships with python-2.7.5), as well as other platforms. Using subprocess32 seems like the easiest fix. I don't know what exactly this ticket (#2023) is doing, since we no longer have the logfiles that prompted it (note to future bug-reporters: please copy the relevant part of the logs into the ticket, rather than relying upon long-term access to buildbot logs). But since some of us apparently believed that #2121 might be a duplicate, and since it's plausible that this problem could appear on FreeBSD and Slackware from that era and not on linux or other python versions, I'm willing to bet that this change will fix #2023 too.

warner removed their assignment 2014-09-11 00:45:26 +00:00

daira was assigned by warner

2014-09-11 00:45:26 +00:00

warner commented

2014-09-11 21:09:12 +00:00

Incidentally, I was able to induce the EBADF failures on linux by shuffling the order of _unix_commands in iputil.py, to put /usr/sbin/ifconfig and /usr/etc/ifconfig first. The normal ordering puts /bin/ip first, which is present on linux and thus short-circuits the function, so it never tries to run a program that isn't there. /usr/sbin/ifconfig doesn't exist on linux (it lives in /sbin), so this triggers the subprocess bug.

Incidentally, I was able to induce the EBADF failures on linux by shuffling the order of `_unix_commands` in iputil.py, to put `/usr/sbin/ifconfig` and `/usr/etc/ifconfig` first. The normal ordering puts `/bin/ip` first, which is present on linux and thus short-circuits the function, so it never tries to run a program that isn't there. `/usr/sbin/ifconfig` doesn't exist on linux (it lives in `/sbin`), so this triggers the subprocess bug.

warner commented

2014-09-11 21:12:30 +00:00

Daira and I decided that it'd be slightly easier to fix this by dodging the bug: modify iputil.py (and other code that uses subprocess) to check for the existence of the executable before allowing subprocess.Popen to try and run it. This seems to work, and avoids adding a new dependency. I'll file a PR with this change in a moment. Hopefully this will tide us over until 1.11 is released, and we can switch to a whole new way of managing local IP addresses (probably by having the Introducer tell us ala #50 or #2152, or requiring server admins to configure them explicitly).

Daira and I decided that it'd be slightly easier to fix this by dodging the bug: modify iputil.py (and other code that uses subprocess) to check for the existence of the executable before allowing `subprocess.Popen` to try and run it. This seems to work, and avoids adding a new dependency. I'll file a PR with this change in a moment. Hopefully this will tide us over until 1.11 is released, and we can switch to a whole new way of managing local IP addresses (probably by having the Introducer tell us ala #50 or #2152, or requiring server admins to configure them explicitly).

daira was unassigned by warner

2014-09-11 21:12:30 +00:00

warner self-assigned this 2014-09-11 21:12:30 +00:00

warner commented

2014-09-12 04:28:07 +00:00

I've got a new patch up: https://github.com/tahoe-lafs/tahoe-lafs/pull/109 , which uses os.path.isfile() instead of subprocess32.

I've got a new patch up: <https://github.com/tahoe-lafs/tahoe-lafs/pull/109> , which uses `os.path.isfile()` instead of `subprocess32`.

warner removed their assignment 2014-09-12 04:28:07 +00:00

daira was assigned by warner

2014-09-12 04:28:07 +00:00

warner commented

2014-09-12 07:08:57 +00:00

Yay: the Slackware buildslave passes with this patch, and was failing with EBADF before:

https://tahoe-lafs.org/buildbot-tahoe-lafs/builders/Markus%20slackware64%20stable/builds/17

Yay: the Slackware buildslave passes with this patch, and was failing with EBADF before: <https://tahoe-lafs.org/buildbot-tahoe-lafs/builders/Markus%20slackware64%20stable/builds/17>