Comment 5 for bug 505913

Note that this test consistently fails when run locally by itself:

jml@truth:~/src/launchpad/stable$ ./bin/test -cvv lp.services.job.tests.test_runner test_timeout
Running tests at level 1
Running canonical.testing.layers.LaunchpadZopelessLayer tests:
  Set up canonical.testing.layers.BaseLayer in 0.065 seconds.
  Set up canonical.testing.layers.ZopelessLayer in 6.982 seconds.
  Set up canonical.testing.layers.DatabaseLayer in 0.989 seconds.
  Set up canonical.testing.layers.LibrarianLayer in 9.038 seconds.
  Set up canonical.testing.layers.MemcachedLayer in 0.122 seconds.
  Set up canonical.testing.layers.LaunchpadLayer in 0.000 seconds.
  Set up canonical.testing.layers.LaunchpadScriptLayer in 0.015 seconds.
  Set up canonical.testing.layers.LaunchpadZopelessLayer in 0.000 seconds.
  Running:
 lp.services.job.tests.test_runner.TestTwistedJobRunner.test_timeoutTraceback (most recent call last):
  File "/home/jml/src/launchpad/devel/eggs/Twisted-10.2.0_4395fix_1_4909-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 286, in addCallbacks
    self._runCallbacks()
  File "/home/jml/src/launchpad/devel/eggs/Twisted-10.2.0_4395fix_1_4909-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 542, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/jml/src/launchpad/stable/lib/lp/services/twistedsupport/task.py", line 172, in got_task
    task_consumer.taskStarted(task)
  File "/home/jml/src/launchpad/stable/lib/lp/services/twistedsupport/task.py", line 306, in taskStarted
    d = defer.maybeDeferred(task)
--- <exception caught here> ---
  File "/home/jml/src/launchpad/devel/eggs/Twisted-10.2.0_4395fix_1_4909-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 133, in maybeDeferred
    result = f(*args, **kw)
  File "/home/jml/src/launchpad/stable/lib/lp/services/job/runner.py", line 405, in <lambda>
    yield lambda: self.runJobInSubprocess(job)
  File "/home/jml/src/launchpad/stable/lib/lp/services/job/runner.py", line 376, in runJobInSubprocess
    RunJobCommand, job_id = job_id, _deadline=deadline)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/pool.py", line 310, in doWork
    self.startAWorker()
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/pool.py", line 196, in startAWorker
    ampChildArgs=self.ampChildArgs)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/main.py", line 243, in startAMPProcess
    return self.startPythonProcess(prot, *args)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/main.py", line 259, in startPythonProcess
    usePTY=self.usePTY, packages=self.packages)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/main.py", line 275, in spawnProcess
    p = os.path.split(imp.find_module(pkg)[1])[0]
exceptions.ImportError: No module named _pythonpath
Traceback (most recent call last):
  File "/home/jml/src/launchpad/devel/eggs/Twisted-10.2.0_4395fix_1_4909-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 286, in addCallbacks
    self._runCallbacks()
  File "/home/jml/src/launchpad/devel/eggs/Twisted-10.2.0_4395fix_1_4909-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 542, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/home/jml/src/launchpad/stable/lib/lp/services/twistedsupport/task.py", line 172, in got_task
    task_consumer.taskStarted(task)
  File "/home/jml/src/launchpad/stable/lib/lp/services/twistedsupport/task.py", line 306, in taskStarted
    d = defer.maybeDeferred(task)
--- <exception caught here> ---
  File "/home/jml/src/launchpad/devel/eggs/Twisted-10.2.0_4395fix_1_4909-py2.6-linux-x86_64.egg/twisted/internet/defer.py", line 133, in maybeDeferred
    result = f(*args, **kw)
  File "/home/jml/src/launchpad/stable/lib/lp/services/job/runner.py", line 405, in <lambda>
    yield lambda: self.runJobInSubprocess(job)
  File "/home/jml/src/launchpad/stable/lib/lp/services/job/runner.py", line 376, in runJobInSubprocess
    RunJobCommand, job_id = job_id, _deadline=deadline)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/pool.py", line 310, in doWork
    self.startAWorker()
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/pool.py", line 196, in startAWorker
    ampChildArgs=self.ampChildArgs)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/main.py", line 243, in startAMPProcess
    return self.startPythonProcess(prot, *args)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/main.py", line 259, in startPythonProcess
    usePTY=self.usePTY, packages=self.packages)
  File "/home/jml/src/launchpad/devel/eggs/ampoule-0.2.0-py2.6.egg/ampoule/main.py", line 275, in spawnProcess
    p = os.path.split(imp.find_module(pkg)[1])[0]
exceptions.ImportError: No module named _pythonpath

Failure in test lp.services.job.tests.test_runner.TestTwistedJobRunner.test_timeout
Traceback (most recent call last):
_StringException: Text attachment: librarian-log
------------
2011-03-17 18:31:05+0530 [-] Log opened.
2011-03-17 18:31:05+0530 [-] twistd 10.2.0 (/usr/bin/python2.6 2.6.6) starting up.
2011-03-17 18:31:05+0530 [-] reactor class: twisted.internet.selectreactor.SelectReactor.
2011-03-17 18:31:05+0530 [-] canonical.librarian.libraryprotocol.FileUploadFactory starting on 54995
2011-03-17 18:31:05+0530 [-] Starting factory <canonical.librarian.libraryprotocol.FileUploadFactory instance at 0x3fd9440>
2011-03-17 18:31:05+0530 [-] twisted.web.server.Site starting on 39415
2011-03-17 18:31:05+0530 [-] Starting factory <twisted.web.server.Site instance at 0x3fd9518>
2011-03-17 18:31:05+0530 [-] canonical.librarian.libraryprotocol.FileUploadFactory starting on 60708
2011-03-17 18:31:05+0530 [-] Starting factory <canonical.librarian.libraryprotocol.FileUploadFactory instance at 0x3fd93f8>
2011-03-17 18:31:05+0530 [-] twisted.web.server.Site starting on 36546
2011-03-17 18:31:05+0530 [-] Starting factory <twisted.web.server.Site instance at 0x3fd9320>
2011-03-17 18:31:05+0530 [-] Not using upstream librarian
2011-03-17 18:31:05+0530 [-] daemon ready!
2011-03-17 18:31:05+0530 [HTTPChannel,0,127.0.0.1] 127.0.0.1 - - [17/Mar/2011:13:01:05 +0000] "GET / HTTP/1.0" 200 340 "-" "Python-urllib/1.17"
2011-03-17 18:31:06+0530 [HTTPChannel,1,127.0.0.1] 127.0.0.1 - - [17/Mar/2011:13:01:05 +0000] "GET / HTTP/1.0" 200 340 "-" "Python-urllib/1.17"
------------
Text attachment: traceback
------------
Traceback (most recent call last):
  File "/home/jml/src/launchpad/devel/eggs/testtools-0.9.8-py2.6.egg/testtools/runtest.py", line 169, in _run_user
    return fn(*args, **kwargs)
  File "/home/jml/src/launchpad/devel/eggs/testtools-0.9.8-py2.6.egg/testtools/testcase.py", line 499, in _run_test_method
    return self._get_test_method()()
  File "/home/jml/src/launchpad/stable/lib/lp/services/job/tests/test_runner.py", line 379, in test_timeout
    self.assertEqual(1, len(runner.completed_jobs))
  File "/home/jml/src/launchpad/devel/eggs/testtools-0.9.8-py2.6.egg/testtools/testcase.py", line 268, in assertEqual
    self.assertThat(observed, matcher)
  File "/home/jml/src/launchpad/devel/eggs/testtools-0.9.8-py2.6.egg/testtools/testcase.py", line 345, in assertThat
    % (matchee, matcher, mismatch.describe()))
AssertionError: Match failed. Matchee: "0"
Matcher: Equals(1)
Difference: 1 != 0

------------

  Ran 1 tests with 1 failures and 0 errors in 0.990 seconds.
Tearing down left over layers:
  Tear down canonical.testing.layers.LaunchpadZopelessLayer in 0.000 seconds.
  Tear down canonical.testing.layers.LaunchpadScriptLayer in 0.002 seconds.
  Tear down canonical.testing.layers.ZopelessLayer ... not supported
  Tear down canonical.testing.layers.LaunchpadLayer in 0.000 seconds.
  Tear down canonical.testing.layers.LibrarianLayer in 0.002 seconds.
  Tear down canonical.testing.layers.MemcachedLayer in 0.001 seconds.
  Tear down canonical.testing.layers.DatabaseLayer in 0.286 seconds.
  Tear down canonical.testing.layers.BaseLayer in 0.003 seconds.

Tests with failures:
   lp.services.job.tests.test_runner.TestTwistedJobRunner.test_timeout (subunit.RemotedTestCase)

Confirmed on wgrant's machine & mine.