Make test_multiprocessing.test_keyboardinterrupt much more reliable.

It turns out that even under Linux, start up times for subprocesses can
vary considerably.  As with most threading/multiprocess-based solutions,
sleep() proves to be an inadequate solution to knowing when to send a
signal to interrupt a waiting process.  We may end up sending the kill
signal before the child process is on the right statement, causing some
assertions to fail in our tests.

Instead, let's introduce the concept of a kill file in these tests.  The
kill file will be generated by the unit-under-test, and we'll wait for
them to show up.  This works much better since the kill file is created
just before the sleep() in the unit-under-test.  Once we detect the kill
file, then we can remove it, and fire off the signal.  Where I was
seeing random failures before, I no longer see them now.

4 files changed, 50 insertions, 16 deletions

diff --git a/functional_tests/test_multiprocessing/support/fake_nosetest.py b/functional_tests/test_multiprocessing/support/fake_nosetest.py
index f5a6289..8319da8 100644
--- a/functional_tests/test_multiprocessing/support/fake_nosetest.py
+++ b/functional_tests/test_multiprocessing/support/fake_nosetest.py
@@ -8,7 +8,10 @@ from nose.plugins.manager import PluginManager
 
 if __name__ == '__main__':
     if len(sys.argv) < 3:
-        print "USAGE: %s TEST_FILE LOG_FILE" % sys.argv[0]
+        print "USAGE: %s TEST_FILE LOG_FILE KILL_FILE" % sys.argv[0]
         sys.exit(1)
     os.environ['NOSE_MP_LOG']=sys.argv[2]
-    nose.main(defaultTest=sys.argv[1], argv=[sys.argv[0],'--processes=1','-v'], config=Config(plugins=PluginManager(plugins=[MultiProcess()])))
+    os.environ['NOSE_MP_KILL']=sys.argv[3]
+    nose.main(
+            defaultTest=sys.argv[1], argv=[sys.argv[0],'--processes=1','-v'],
+            config=Config(plugins=PluginManager(plugins=[MultiProcess()])))
diff --git a/functional_tests/test_multiprocessing/support/keyboardinterrupt.py b/functional_tests/test_multiprocessing/support/keyboardinterrupt.py
index 2c36d95..5f2c64f 100644
--- a/functional_tests/test_multiprocessing/support/keyboardinterrupt.py
+++ b/functional_tests/test_multiprocessing/support/keyboardinterrupt.py
@@ -7,17 +7,24 @@ if 'NOSE_MP_LOG' not in os.environ:
     raise Exception('Environment variable NOSE_MP_LOG is not set')
 
 logfile = os.environ['NOSE_MP_LOG']
+killfile = os.environ['NOSE_MP_KILL']
 
 def log(w):
     f = open(logfile, 'a')
     f.write(w+"\n")
     f.close()
+
+def touch_killfile():
+    f = open(killfile,'wb')
+    f.close()
+
 #make sure all tests in this file are dispatched to the same subprocess
 def setup():
     log('setup')
 
 def test_timeout():
     log('test_timeout')
+    touch_killfile()
     sleep(2)
     log('test_timeout_finished')
 
diff --git a/functional_tests/test_multiprocessing/support/keyboardinterrupt_twice.py b/functional_tests/test_multiprocessing/support/keyboardinterrupt_twice.py
index 3932bbd..c971436 100644
--- a/functional_tests/test_multiprocessing/support/keyboardinterrupt_twice.py
+++ b/functional_tests/test_multiprocessing/support/keyboardinterrupt_twice.py
@@ -7,11 +7,17 @@ if 'NOSE_MP_LOG' not in os.environ:
     raise Exception('Environment variable NOSE_MP_LOG is not set')
 
 logfile = os.environ['NOSE_MP_LOG']
+killfile = os.environ['NOSE_MP_KILL']
 
 def log(w):
     f = open(logfile, 'a')
     f.write(w+"\n")
     f.close()
+
+def touch_killfile():
+    f = open(killfile,'wb')
+    f.close()
+
 #make sure all tests in this file are dispatched to the same subprocess
 def setup():
     '''global logfile
@@ -21,6 +27,7 @@ def setup():
 
 def test_timeout():
     log('test_timeout')
+    touch_killfile()
     sleep(2)
     log('test_timeout_finished')
 
@@ -30,5 +37,6 @@ def test_pass():
 
 def teardown():
     log('teardown')
+    touch_killfile()
     sleep(10)
     log('teardown_finished')
diff --git a/functional_tests/test_multiprocessing/test_keyboardinterrupt.py b/functional_tests/test_multiprocessing/test_keyboardinterrupt.py
index 8f07e54..2bcbe73 100644
--- a/functional_tests/test_multiprocessing/test_keyboardinterrupt.py
+++ b/functional_tests/test_multiprocessing/test_keyboardinterrupt.py
@@ -9,36 +9,43 @@ import nose
 support = os.path.join(os.path.dirname(__file__), 'support')
 
 PYTHONPATH = os.environ['PYTHONPATH'] if 'PYTHONPATH' in os.environ else ''
+
 def setup():
     nose_parent_dir = os.path.normpath(os.path.join(os.path.abspath(os.path.dirname(nose.__file__)),'..'))
     paths = [nose_parent_dir]
     if PYTHONPATH:
         paths.append(PYTHONPATH)
     os.environ['PYTHONPATH'] = os.pathsep.join(paths)
+
 def teardown():
     if PYTHONPATH:
         os.environ['PYTHONPATH'] = PYTHONPATH
     else:
         del os.environ['PYTHONPATH']
 
+def waitForKillFile(killfile):
+    retry=100
+    while not os.path.exists(killfile):
+        sleep(0.1)
+        retry -= 1
+        if not retry:
+            raise Exception('Timeout while waiting for kill file to be created')
+    os.remove(killfile)
+
 runner = os.path.join(support, 'fake_nosetest.py')
 def keyboardinterrupt(case):
     #os.setsid would create a process group so signals sent to the
     #parent process will propogates to all children processes
     from tempfile import mktemp
     logfile = mktemp()
-    process = Popen([sys.executable,runner,os.path.join(support,case),logfile], preexec_fn=os.setsid, stdout=PIPE, stderr=PIPE, bufsize=-1)
-
-    #wait until logfile is created:
-    retry=100
-    while not os.path.exists(logfile):
-        sleep(0.1)
-        retry -= 1
-        if not retry:
-            raise Exception('Timeout while waiting for log file to be created by fake_nosetest.py')
+    killfile = mktemp()
+    process = Popen(
+            [sys.executable,runner,os.path.join(support,case),logfile,killfile],
+            preexec_fn=os.setsid, stdout=PIPE, stderr=PIPE, bufsize=-1)
 
+    waitForKillFile(killfile)
     os.killpg(process.pid, signal.SIGINT)
-    return process, logfile
+    return process, logfile, killfile
 
 def get_log_content(logfile):
     '''prefix = 'tempfile is: '
@@ -52,10 +59,14 @@ def get_log_content(logfile):
     return content
 
 def test_keyboardinterrupt():
-    process, logfile = keyboardinterrupt('keyboardinterrupt.py')
+    process, logfile, _ = keyboardinterrupt('keyboardinterrupt.py')
     stdout, stderr = [s.decode('utf-8') for s in process.communicate(None)]
-    print stderr
     log = get_log_content(logfile)
+    print stderr
+    print '----'
+    print stdout
+    print '----'
+    print log
     assert 'setup' in log
     assert 'test_timeout' in log
     assert 'test_timeout_finished' not in log
@@ -68,11 +79,16 @@ def test_keyboardinterrupt():
 
 
 def test_keyboardinterrupt_twice():
-    process, logfile = keyboardinterrupt('keyboardinterrupt_twice.py')
-    sleep(0.5)
+    process, logfile, killfile = keyboardinterrupt('keyboardinterrupt_twice.py')
+    waitForKillFile(killfile)
     os.killpg(process.pid, signal.SIGINT)
     stdout, stderr = [s.decode('utf-8') for s in process.communicate(None)]
     log = get_log_content(logfile)
+    print stderr
+    print '----'
+    print stdout
+    print '----'
+    print log
     assert 'setup' in log
     assert 'test_timeout' in log
     assert 'test_timeout_finished' not in log