pycryptopp-related hang of unit tests on platforms using buggy Gnu as 2.20 (e.g. MinGW 5.1.x, Ubuntu Karmic)

[zooko]

Kai posted this bug report ​http://allmydata.org/pipermail/tahoe-dev/2009-December/003298.html

Hi, all

I'm interested in Tahoe and tried to install it in my Windows box (XP SP3.)
However, I encountered the following problem:

> C:\allmydata-tahoe-1.5.0-r4108>c:\Python262\Scripts\tahoe.exe start --basedir C:\tahoebase
> STARTING C:\tahoebase
> c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\persisted\sob.py:12: DeprecationWarning: the md5 module is deprecated; use hashlib instead
>   import os, md5, sys
> c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\python\filepath.py:12: DeprecationWarning: the sha module is deprecated; use the hashlib module instead
>   import sha
> c:\Python262\lib\site-packages\foolscap-0.4.2-py2.6.egg\foolscap\banana.py:2: DeprecationWarning: the sets module is deprecated
>   import struct, sets, time
> c:\Python262\lib\site-packages\nevow-0.9.33_r17222-py2.6.egg\formless\annotate.py:730: DeprecationWarning: object.__new__() takes no parameters
>   rv = cls = InterfaceClass.__new__(cls, name, bases, dct)
> c:\Python262\lib\site-packages\nevow-0.9.33_r17222-py2.6.egg\nevow\testutil.py:7: DeprecationWarning: The popen2 module is deprecated.  Use the subprocess module.
>   from popen2 import Popen3
> 
> This application has requested the Runtime to terminate it in an unusual way.
> Please contact the application's support team for more information.
> client node probably not started

\tahoebase\logs\twistd.log
> 2009-12-11 15:51:53+0900 [-] Log opened.
> 2009-12-11 15:51:53+0900 [-] twistd 8.2.0 (c:\Python262\python.exe 2.6.2) starting up.
> 2009-12-11 15:51:53+0900 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
> 2009-12-11 15:51:53+0900 [-] foolscap.pb.Listener starting on 4759
> 2009-12-11 15:51:57+0900 [-] nevow.appserver.NevowSite starting on 3456
> 2009-12-11 15:51:57+0900 [-] Starting factory <nevow.appserver.NevowSite instance at 0x01A5F580>
> 2009-12-11 15:51:57+0900 [-] My pid: 4748
> 2009-12-11 15:51:57+0900 [-] twisted.internet.protocol.DatagramProtocol starting on 4762
> 2009-12-11 15:51:57+0900 [-] Starting protocol <twisted.internet.protocol.DatagramProtocol instance at 0x01B07490>
> 2009-12-11 15:51:57+0900 [-] Unhandled Error
> 	Traceback (most recent call last):
> 	  File "c:\Python262\lib\site-packages\allmydata_tahoe-1.5.0_r4108-py2.6.egg\allmydata\node.py", line 259, in <lambda>
> 	    d.addCallback(lambda res: iputil.get_local_addresses_async())
> 	  File "c:\Python262\lib\site-packages\allmydata_tahoe-1.5.0_r4108-py2.6.egg\allmydata\util\iputil.py", line 102, in get_local_addresses_async
> 	    d.addCallback(_collect)
> 	  File "c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\internet\defer.py", line 195, in addCallback
> 	    callbackKeywords=kw)
> 	  File "c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\internet\defer.py", line 186, in addCallbacks
> 	    self._runCallbacks()
> 	--- <exception caught here> ---
> 	  File "c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\internet\defer.py", line 328, in _runCallbacks
> 	    self.result = callback(self.result, *args, **kw)
> 	  File "c:\Python262\lib\site-packages\allmydata_tahoe-1.5.0_r4108-py2.6.egg\allmydata\util\iputil.py", line 98, in _collect
> 	    for addr in res:
> 	exceptions.TypeError: 'NoneType' object is not iterable
> 	
> 2009-12-11 15:51:57+0900 [-] Node._startService failed, aborting
> 2009-12-11 15:51:57+0900 [-] [Failure instance: Traceback: <type 'exceptions.TypeError'>: 'NoneType' object is not iterable
> 2009-12-11 15:51:57+0900 [-] c:\Python262\lib\site-packages\allmydata_tahoe-1.5.0_r4108-py2.6.egg\allmydata\node.py:259:<lambda>
> 2009-12-11 15:51:57+0900 [-] c:\Python262\lib\site-packages\allmydata_tahoe-1.5.0_r4108-py2.6.egg\allmydata\util\iputil.py:102:get_local_addresses_async
> 2009-12-11 15:51:57+0900 [-] c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\internet\defer.py:195:addCallback
> 2009-12-11 15:51:57+0900 [-] c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\internet\defer.py:186:addCallbacks
> 2009-12-11 15:51:57+0900 [-] --- <exception caught here> ---
> 2009-12-11 15:51:57+0900 [-] c:\Python262\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\internet\defer.py:328:_runCallbacks
> 2009-12-11 15:51:57+0900 [-] c:\Python262\lib\site-packages\allmydata_tahoe-1.5.0_r4108-py2.6.egg\allmydata\util\iputil.py:98:_collect
> 2009-12-11 15:51:57+0900 [-] ]
> 2009-12-11 15:51:57+0900 [-] calling os.abort()
> 2009-12-11 15:51:57+0900 [-] calling os.abort()

Moreover, setup.py test freezes:
> C:\allmydata-tahoe-1.5.0-r4108>c:\Python262\python.exe setup.py test
[snip]
>   BackupDB
>     test_basic ...                                                         [OK]
>     test_check ...                                                         [OK]
>     test_fail ...                                                          [OK]
>     test_wrong_version ...                                                 [OK]
> allmydata.test.test_base62
>   T
>     test_ende_0x00 ...                                                     [OK]
>     test_ende_0x000000 ...                                                 [OK]
>     test_ende_0x01 ...                                                     [OK]
>     test_ende_0x0100 ...                                                   [OK]
>     test_ende_0x010000 ...                                                 [OK]
>     test_ende_longrandstr ...                                              [OK]
>     test_ende_randstr ...                                                  [OK]
>     test_num_octets_that_encode_to_this_many_chars ...                     [OK]
>     test_odd_sizes ...                                                     [OK]
> allmydata.test.test_checker
>   WebResultsRendering
>     test_check ...
At this point, python.exe had to be terminated by Task Manager.

I used Python 2.6.2 MinGW-5.1.4 and pywin32-214.win32-py2.6 .
Upgrading to Python 2.6.4 and Mingw-5.1.6 didn't improve the situation.

Additioally,

>echo %PATH%
C:\MinGW514\bin

Any advice is welcome.

Thanks,

Kai

[zooko]

For what it is worth, we have a buildbot which tests Tahoe-LAFS on WinXP, and it works on that machine, so we have a starting point from which to figure out what is different between that build machine [1] and your machine.

Here is the report of the most recent five builds on the Windows buildbot:

​http://allmydata.org/buildbot/builders/windows

And here is the dump of the versions of various components on that machine:

​http://allmydata.org/buildbot/builders/windows/builds/1651/steps/show-tool-versions/logs/stdio

[zooko]

Kai: after you run the test and the test freezes, could you please look in the _trial_temp subdirectory and attach the test.log file to this ticket?

[zooko]

Just out of curiousity, why are you using Tahoe-LAFS v1.5.0-r4108? The v1.5.0 release was -r4037 and the current head is -r4128. I guess you downloaded -r4108 back when it was the current head? I don't have any reason to think that this affects your bug.

[zooko]

So I've been looking at the code and I can't see how res can be None on line 98 of iputil.py. _collect() will be invoked and the argument passed to it will be whatever was returned from _find_addresses_via_config(). Unless the thing that was returned from find_addresses_via_config() is a Deferred, in which case the argument passed to _collect() will be whatever value is given to that Deferred when it is fired. (This is the way Twisted works.)

_find_addresses_via_config() is defined on line 238... Oh, okay I see where a None can be returned. From here. Okay, so this suggests that on Kai's machine there is no route.exe executable on the path which emits a dotted-quad IPv4 address when executed as route.exe print.

The first thing we need to do is make Tahoe-LAFS handle this case more gracefully. Let's see it is src/allmydata/node.py@4108#L259 that invokes iputil.get_local_address_async(), and the result is passed to _setup_tub(). What should we do when the answer to "list all of my IP addresses" is that there are none?

In any case it seems like maybe iputil's SequentialTrier should return an empty set instead of None when it runs out of executables to query.

[Grumpf]

I'm investigating a cryptopp problem on my Windows Seven 64, using official Mingw-5.1.6, which shows up as a WebResultsRendering? never ending test_check.

I had to manually install pycryptopp patching his config.h, disabling assembler parts (#define CRYPTOPP_DISABLE_ASM) in order to pass tahoe tests.

Kai, could you please run this command and report if it loops to infinite :

setup.py trial -s allmydata.test.test_util.HashUtilTests

Are you using a 64-bits XP ? What is your processor ? Thanks.

zooko: We are using r4108 because it is the ​latest generated tarball (builder ​tarballs seems defunct since 21^th November).

[zooko]

Please help me diagnose this pycryptopp problem. What version of pycryptopp?

There have been some bugs in amd64 Crypto++ assembly recently but all known problems are fixed in the most recent release of pycryptopp. There could be an interaction with Mingw -- I don't think many people have used Mingw to build pycryptopp before.

The tarballs stopped coming because some of the Supported Platforms stopped passing unit tests after r4108. That means that r4108 is the most recent version for which all the Supported Platforms passed all unit tests. r4108 is fine for now.

[nodakai]

_trial_tmp\test.log

[nodakai]

Replying to zooko:

Just out of curiousity, why are you using Tahoe-LAFS v1.5.0-r4108? The v1.5.0 release was -r4037 and the current head is -r4128. I guess you downloaded -r4108 back when it was the current head? I don't have any reason to think that this affects your bug.

I have no experience to use darcs. So I DLed the latest package in ​http://allmydata.org/source/tahoe/tarballs/ , that is, allmydata-tahoe-1.5.0-r4108.tar.bz2 .

[nodakai]

Replying to zooko: ...

_find_addresses_via_config() is defined on line 238... Oh, okay I see where a None can be returned. From here. Okay, so this suggests that on Kai's machine there is no route.exe executable on the path which emits a dotted-quad IPv4 address when executed as route.exe print.

Oops. I set PATH=C:\mingw516\bin , which resulted in excluding route.exe from PATH! As I had already installed cygwin tools including g++ and python, I thought that it was better to exclude them from PATH not to confuse build process, and that setting PATH=C:\mingw516\bin was the easiest way to do it. After installation of Tahoe with PATH=C:\mingw516\bin, I started a new shell without changing PATH and started Tahoe with it. Tahoe successfully started and I could access the WUI with firefox. However, when I tried to DL a JPG file found in ​http://testgrid.allmydata.org:3567/ via my WUI, it freezes again and no access to my WUI was possible, including the access to the main screen. At this time, python.exe occupies ~100 % CPU.

[nodakai]

Replying to Grumpf:

I'm investigating a cryptopp problem on my Windows Seven 64, using official Mingw-5.1.6, which shows up as a WebResultsRendering? never ending test_check.

I had to manually install pycryptopp patching his config.h, disabling assembler parts (#define CRYPTOPP_DISABLE_ASM) in order to pass tahoe tests.

Kai, could you please run this command and report if it loops to infinite :

setup.py trial -s allmydata.test.test_util.HashUtilTests

C:\allmydata-tahoe-1.5.0-r4108>setup.py trial -s allmydata.test.test_util.HashUtilTests
running darcsver
running trial
running egg_info
writing requirements to src\allmydata_tahoe.egg-info\requires.txt
writing src\allmydata_tahoe.egg-info\PKG-INFO
writing top-level names to src\allmydata_tahoe.egg-info\top_level.txt
writing dependency_links to src\allmydata_tahoe.egg-info\dependency_links.txt
writing entry points to src\allmydata_tahoe.egg-info\entry_points.txt
reading manifest file 'src\allmydata_tahoe.egg-info\SOURCES.txt'
writing manifest file 'src\allmydata_tahoe.egg-info\SOURCES.txt'
running build_ext
C:\Python264\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\persisted\sob.py:12: DeprecationWarning: the md5 module is deprecated; use hashlib instead
  import os, md5, sys
C:\Python264\lib\site-packages\twisted-8.2.0-py2.6-win32.egg\twisted\python\filepath.py:12: DeprecationWarning: the sha
module is deprecated; use the hashlib module instead
  import sha
C:\Python264\lib\site-packages\foolscap-0.4.2-py2.6.egg\foolscap\banana.py:2: DeprecationWarning: the sets module is deprecated
  import struct, sets, time
allmydata.test.test_util
  HashUtilTests
    test_chk ...

At this time, python occupied ~100 % CPU and had to terminated by Task Manager. The content of _trial_tmp\test.log was:

2009-12-12 17:06:32+0900 [-] Log opened.
2009-12-12 17:06:32+0900 [-] --> allmydata.test.test_util.HashUtilTests.test_chk <--

Are you using a 64-bits XP ? What is your processor ?

The above test was done on my PC in my home. WinXP Pro SP3 32 bit is installed, as the CPU is PenM 1.2 GHz. When I first reported the problem, it was on the PC in my office. So I don't remember the detailed specs about the OS (sorry,) but probably it was WinXP Pro SP3 32 bit running on Core2Duo E7400.

[nodakai]

Replying to zooko:

Please help me diagnose this pycryptopp problem. What version of pycryptopp?

According to the WUI just after startup,

My versions

allmydata-tahoe: 1.5.0-r4108, foolscap: 0.4.2, pycryptopp: 0.5.17, zfec: 1.4.5, Twisted: 8.2.0, Nevow: 0.9.33, zope.interface: 3.5.2, python: 2.6.4, platform: Windows-XP-5.1.2600-SP3, sqlite: 3.5.9, simplejson: 2.0.9, pyopenssl: 0.9, argparse: 0.9.1, twisted: 8.2.0, nevow: 0.9.33-r17222, pyOpenSSL: 0.9, pyutil: 1.3.34, zbase32: 1.1.1, setuptools: 0.6c12dev, pysqlite: 2.4.1

[zooko]

Okay I moved the issue about route.exe not being found over to a new ticket: #854 (what to do when you can't find any IP address for yourself).

This ticket is now renamed to "unit tests hang on Windows (pycryptopp related?)". Let me see if I understand what has been reported so far:

• Kai reports the unit test process hangs or spins at allmydata.test.test_checker.WebResultsRendering.test_check using the official "python.org" Python 2.6.4 (from ​http://www.python.org/download/ ) on Windows XP SP3 32-bit. His test.log doesn't have anything useful in it. Kai: would you please turn on verbose logging ( ​http://allmydata.org/trac/tahoe/browser/docs/logging.txt ) and try again?
• Grumpf reports "I had to manually install pycryptopp patching his config.h, disabling assembler parts (#define CRYPTOPP_DISABLE_ASM) in order to pass tahoe tests.". Grumpf: what happens if you do not manually install pycryptopp and patch his config.h? Does Tahoe-LAFS fail to build? Does it build but fail its unit tests? If so in what way? Also could you please run the pycryptopp unit tests.

[nodakai]

Replying to zooko:

• Kai reports the unit test process hangs or spins at allmydata.test.test_checker.WebResultsRendering.test_check using the official "python.org" Python 2.6.4 (from ​http://www.python.org/download/ ) on Windows XP SP3 32-bit. His test.log doesn't have anything useful in it. Kai: would you please turn on verbose logging ( ​http://allmydata.org/trac/tahoe/browser/docs/logging.txt ) and try again?

I couldn't turn on verbose logging mode either by the arguments of make, nor by SET FLOGTOTWISTED=1 etc. The content of test.log was same as before.

2009-12-13 16:30:16+0900 [-] Log opened.
2009-12-13 16:30:16+0900 [-] --> allmydata.test.test_backupdb.BackupDB.test_basic <--
2009-12-13 16:30:17+0900 [-] --> allmydata.test.test_backupdb.BackupDB.test_check <--
2009-12-13 16:30:20+0900 [-] --> allmydata.test.test_backupdb.BackupDB.test_fail <--
2009-12-13 16:30:20+0900 [-] --> allmydata.test.test_backupdb.BackupDB.test_wrong_version <--
2009-12-13 16:30:21+0900 [-] --> allmydata.test.test_checker.WebResultsRendering.test_check <--

C:\allmydata-tahoe-1.5.0-r4108>set
...
FLOGLEVEL=1
FLOGTOTWISTED=1

I also tried SET FLOGFILE=flog.out, only to find empty flog.out. Zooko: Could you tell me what am I doing wrong with this, or how to hard-code the verbose mode flag into some .py files ?

(Instead I manually inserted print inspect.stack()[0][1:3] after each line of WebResultsRendering.test_check and saw that u = uri.CHKFileURI("\x00"*16, "\x00"*32, 3, 10, 1234) causes hangup. And with respect to HashUtilTests, the cause was h1 = hashutil.convergence_hash(3, 10, 1000, "data", "secret") . But I didn't investigate further ...)

Additionally, when I DLed and built pycryptopp independently from Tahoe, the unit test aborted:

C:\pycryptopp-0.5.17>python setup.py -v test
running darcsver
setup.py darcsver: Failure from attempt to find version tags with 'darcs changes', and pycryptopp\_version.py already exists, so leaving it alone.
running test
running "unittest --verbose pycryptopp.test"
running egg_info
writing requirements to pycryptopp.egg-info\requires.txt
writing pycryptopp.egg-info\PKG-INFO
writing top-level names to pycryptopp.egg-info\top_level.txt
writing dependency_links to pycryptopp.egg-info\dependency_links.txt
Importing new compiler from distutils.msvc9compiler
reading manifest file 'pycryptopp.egg-info\SOURCES.txt'
writing manifest file 'pycryptopp.egg-info\SOURCES.txt'
running build_ext
skipping 'pycryptopp._pycryptopp' extension (up-to-date)
copying build\lib.win32-2.6\pycryptopp\_pycryptopp.pyd -> pycryptopp
test_encrypt_zeroes (pycryptopp.test.test_aes.AES128) ...

At this time, the "sorry for the inconvenience" dialog appeared.

Moreover, the unit test of Crypto++ also aborted during the test of SHA-256. It might be that Crypto++ doesn't compile with Mingw, but I'm not sure which part of the programs is responsible for our problem.

[Grumpf]

Working crappy workaround is to downgrade GNU as from 2.20 (current MinGW) to previous ​2.19.1 (both as.exe files and nothing else at all).

The problem is inherited from Crypto++.

Now to figure if it is a MinGW-centric problem, and a real fix...

Zooko: I suffer the exact same problems nodakai do. I pinned it down to Crypto++, symptoms are never-ending Tahoe test units, crash during first pycrypto test unit and never-ending Crypto++ SHA256 test.

[davidsarah]

Same underlying issue as ​http://www.mail-archive.com/cryptopp-users@googlegroups.com/msg05292.html ?

Maybe the fix mentioned in ​http://www.mail-archive.com/cryptopp-users@googlegroups.com/msg05299.html didn't make it into as 2.20.

[davidsarah]

Replying to davidsarah:

Maybe the fix mentioned in ​http://www.mail-archive.com/cryptopp-users@googlegroups.com/msg05299.html didn't make it into as 2.20.

Sorry, the regression was in 2.20. It is fixed in some branch of 2.20, but not released.

Removing windows tag since this is known to happen also on Ubuntu Linux (​https://bugs.launchpad.net/ubuntu/+bug/461303) when using the buggy as.

The pycryptopp bug is ​http://allmydata.org/trac/pycryptopp/ticket/31 .

[zooko]

Here is the launchpad page which tracks this issue across all of the various operating systems and projects that it affects:

​https://bugs.launchpad.net/ubuntu/+source/binutils/+bug/461303

[davidsarah]

The as bug is x86-specific. It's not clear whether it affects only x86-64, or also x86-32.

[zooko]

Hrm. So we *could* work-around this by releasing a new version of pycryptopp which inspects the version number of GNU assembler and the platform and tries to figure out if this particular version of GNU assembler has this bug, and if so then disable the assembly optimizations. Or, it could even be more clever and try compiling and executing, and if it segfaults then it turns off assembly optimization and tries again. But I think instead we should just close this as 'invalid', indicating that it is the problem of some other people (a combination of binutils to produce a new fixed release -- ​http://sourceware.org/bugzilla/show_bug.cgi?id=10856 -- and/or MingW to patch binutils or to upgrade binutils in MingW to the fixed release -- ​https://sourceforge.net/tracker/index.php?func=detail&aid=2913876&group_id=2435&atid=102435 ).

[davidsarah]

Replying to zooko:

Hrm. So we *could* work-around this by releasing a new version of pycryptopp which inspects the version number of GNU assembler and the platform and tries to figure out if this particular version of GNU assembler has this bug, and if so then disable the assembly optimizations. Or, it could even be more clever and try compiling and executing, and if it segfaults then it turns off assembly optimization and tries again. But I think instead we should just close this as 'invalid', indicating that it is the problem of some other people [...]

I don't entirely agree. This isn't the first time that pycryptopp/Crypto++ has failed in a platform-dependent way that was detected by unit tests -- see ​pycryptopp#17 and ​pycryptopp#24. If pycryptopp (or Crypto++) were to do the "more clever" behaviour above, then we'd have a good chance of heading off such problems in future. (Some bugs would be prevented, others would fail compilation rather than failing only if unit tests are run explicitly.) But that can be a separate ticket.

[zooko]

Well, the idea I floated above of attempting compilation, then test, then recompilation a different way if the test fails makes me think it is "too clever". I could imagine a bug in that process leading to problems even when there isn't a bug in Crypto++! On the other hand, I definitely think we should add a "quick start up self test" to pycryptopp and in fact I have already done so but I haven't committed to to pycryptopp trunk yet. Once that is in place then Tahoe-LAFS can import pycryptopp, execute the quick start-up self-test, and if it fails Tahoe-LAFS can exit quickly and loudly.

What do you think?

By the way there is an idiom in Python packaging which is to try compiling a native-code extension module and if the compilation fails (such as if there is no C compiler present, or some necessary header files are missing), then go ahead and use the pure-Python implementation of that module instead. So maybe if we wanted to go down this route we could start by adapting that idiom.

[davidsarah]

Replying to zooko:

On the other hand, I definitely think we should add a "quick start up self test" to pycryptopp and in fact I have already done so but I haven't committed to to pycryptopp trunk yet. Once that is in place then Tahoe-LAFS can import pycryptopp, execute the quick start-up self-test, and if it fails Tahoe-LAFS can exit quickly and loudly.

+1.

[davidsarah]

FreeStorm? also hit this bug, on Windows XP with MinGW. The symptoms were slightly different: when running the pycryptopp tests using python setup.py test, the error was

test_encrypt_zeroes (pycryptopp.test.test_aes.AES128) ... program finished with exit code -1073741819

This was solved by downgrading to binutils 2.19.1 -- specifically, by extracting ​binutils-2.19.1-mingw32-bin.tar.gz over the MinGW installation directory.

[davidsarah]

Replying to davidsarah:

This was solved by downgrading to binutils 2.19.1 -- specifically, by extracting ​binutils-2.19.1-mingw32-bin.tar.gz over the MinGW installation directory.

AdvancedInstall#Whatifthatdoesntwork has been updated to describe this.

[weidai]

I just tested this on MinGW, and it looks like the issue has been fixed there (probably because they upgraded to the latest snapshot of binutils, version 2.20.51.20100613, to fix an unrelated bug).

[zooko]

Thanks, Wei Dai. I've updated AdvancedInstall.

[zooko]

binutils 2.20.1, released 2010-03-03, does *not* have the ChangeLog? entry from ​http://sourceware.org/bugzilla/show_bug.cgi?id=10856#c5 but *does* have the patch to expr.c. Weird. But I guess it is fixed in binutils 2.20.1.