Function test execution hangs in trac.ticket.tests.functional

[Ryan J Ollos]

On 1.0-stable (and probably the trunk as well), the Trac functional test execution hangs in TestTicketQueryLinks and TestTicketQueryOrClause. If I comment out both of those test cases, the test suite will execute successfully.

I've been experiencing this issue at various times over the past several months. It seems to occur consistently for a given environment, but doesn't happen in all environments. Recent experience suggests that it may be occurring in a virtualenv with Python 2.7, but not in a virtualenv with Python 2.6.

[Ryan J Ollos]

I'm not sure if this is related, but I see the following error when executing the test suite with the two test cases commented out.

Doctest: trac.test.Mock ... ok

----------------------------------------------------------------------
Ran 1529 tests in 196.178s

OK
Exception TypeError: "'NoneType' object is not callable" in <function <lambda> at 0xc129938> ignored

I have all of the dependencies installed, so there are no tests being skipped.

[Remy Blank]

The message "Exception … ignored" usually means that an exception occurred in a __del__() method.

[Ryan J Ollos]

Here is what I've found so far. For both test cases that cause the test execution to hang, the issue seems to be caused by an identical function call tc.submit('rm_filter_0_owner_0') (found here​ and here​). When I send a keyboard interrupt, the traceback that results is:

Traceback (most recent call last):
  File "/home/user/Workspace/t11245-2.7/teo-rjollos.git/trac/ticket/tests/functional.py", line 1879, in <module>
    unittest.main(defaultTest='functionalSuite')
  File "/usr/lib/python2.7/unittest/main.py", line 95, in __init__
    self.runTests()
  File "/usr/lib/python2.7/unittest/main.py", line 232, in runTests
    self.result = testRunner.run(self.test)
  File "/usr/lib/python2.7/unittest/runner.py", line 151, in run
    test(result)
  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)
  File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
    test(result)
  File "/usr/lib/python2.7/unittest/suite.py", line 70, in __call__
    return self.run(*args, **kwds)
  File "/home/user/Workspace/t11245-2.7/teo-rjollos.git/trac/test.py", line 142, in run
    unittest.TestSuite.run(self, result)
  File "/usr/lib/python2.7/unittest/suite.py", line 108, in run
    test(result)
  File "/usr/lib/python2.7/unittest/case.py", line 396, in __call__
    return self.run(*args, **kwds)
  File "/usr/lib/python2.7/unittest/case.py", line 332, in run
    testMethod()
  File "/home/user/Workspace/t11245-2.7/teo-rjollos.git/trac/ticket/tests/functional.py", line 228, in runTest
    tc.submit('rm_filter_0_owner_0')
  File "/home/user/Workspace/t11245-2.7/teo-rjollos.git/trac/tests/functional/better_twill.py", line 169, in better_submit
    b.submit(fieldname, formname)
  File "/home/user/Workspace/t11245-2.7/teo-rjollos.git/trac/tests/functional/better_twill.py", line 165, in better_browser_submit
    old_submit(fieldname)
  File "/usr/lib/python2.7/dist-packages/twill/browser.py", line 468, in submit
    self._journey('open', request)
  File "/usr/lib/python2.7/dist-packages/twill/browser.py", line 524, in _journey
    r = func(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/mechanize/_mechanize.py", line 203, in open
    return self._mech_open(url, data, timeout=timeout)
  File "/usr/lib/python2.7/dist-packages/mechanize/_mechanize.py", line 230, in _mech_open
    response = UserAgentBase.open(self, request, data)
  File "/usr/lib/python2.7/dist-packages/mechanize/_opener.py", line 193, in open
    response = urlopen(self, req, data)
  File "/usr/lib/python2.7/dist-packages/mechanize/_urllib2_fork.py", line 344, in _open
    '_open', req)
  File "/usr/lib/python2.7/dist-packages/mechanize/_urllib2_fork.py", line 332, in _call_chain
    result = func(*args)
  File "/usr/lib/python2.7/dist-packages/twill/_browser.py", line 16, in http_open
    return self.do_open(wsgi_intercept.WSGI_HTTPConnection, req)
  File "/usr/lib/python2.7/dist-packages/mechanize/_urllib2_fork.py", line 1116, in do_open
    r = h.getresponse()
  File "/usr/lib/python2.7/httplib.py", line 1045, in getresponse
    response.begin()
  File "/usr/lib/python2.7/httplib.py", line 409, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python2.7/httplib.py", line 365, in _read_status
    line = self.fp.readline(_MAXLINE + 1)
  File "/usr/lib/python2.7/socket.py", line 476, in readline
    data = self._sock.recv(self._rbufsize)

I've debugged several levels down into the code and the traceback is accurate of where execution hangs.

Some additional findings:

• Changing rm_filter_0_owner_0 → rm_filter_0_status_0 leads to the same result.
• The test execution will complete with a failure when the tc.submit call is commented out.
• I've tested in several additional environments and I'm fairly convinced this occurs with Python 2.7 only.

It is fairly easy to reproduce and debug the issue since it occurs with all of the other test cases in trac/ticket/tests/functional.py commented out, and executing just that module with the command PYTHONPATH=. python ./trac/wiki/tests/functional.py.

It looks to me like there is a request sent, and it hangs waiting for a response. Maybe there is something in particular about the remove filter submit buttons​ that causes problems for twill or a lower level library. So far I haven't been able to find anything.

[Jun Omae]

Replying to rjollos:

I've debugged several levels down into the code and the traceback is accurate of where execution hangs.

Reproduced with python 2.7.3 on Ubuntu 12.04. Also, I found the workaround to use ​pypi:twill/0.9 instead of twill and mechanize in ubuntu package. I think that the ubuntu packages has the issue.

[Ryan J Ollos]

I tried the Twill package from PyPI and it resolves the issue. Thanks.

Without digging deeper I guess there is nothing more we can do, and the appropriate resolution seems to be cantfix.

[Ryan J Ollos]

Replying to rblank:

The message "Exception … ignored" usually means that an exception occurred in a __del__() method.

I've not had any luck tracking down this issue yet, but it seems to happen only with Python 2.7. I'll continue to try to isolate the test case that is throwing the error. Thanks for the hint.

[Ryan J Ollos]

Replying to rjollos:

Replying to rblank:

The message "Exception … ignored" usually means that an exception occurred in a __del__() method.

I've not had any luck tracking down this issue yet, but it seems to happen only with Python 2.7. I'll continue to try to isolate the test case that is throwing the error. Thanks for the hint.

More info about this problem in #11505.