[ovirt-devel] [VDSM] Tests leaking child processes --with-leaked-processes

Hi all, The most common test failure on travis (and when running locally) is tests failing with EINTR: IOError: [Errno 4] Interrupted system call This happens because we are using zombiereaper, and it adds a signal handler for SIGCHLD. When a test leaks a child process and the child process terminates, the test runner get a SIGCHLD. If this happens when the test framework is writing to stdout, the write is interrupted and the test fail, failing the entire build. Here is an example failure on travis: https://travis-ci.org/oVirt/vdsm/jobs/187464715 To fix this we need to find the buggy tests (or tested code) leaking child processes. I added a new plugin for this here: https://gerrit.ovirt.org/69324 (mostly stolen from https://gerrit.ovirt.org/69040) Here is the result of running this plugin with current tests: $ make check NOSE_WITH_LEAKED_PROCESSES=1 ... ====================================================================== ERROR: test_running_repr (storage_check_test.TestDirectioChecker) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "3858" } ] -------------------- >> begin captured stdout << --------------------- <DirectioChecker /path running next_check=4321478.96 at 0x7f0f99812e90> --------------------- >> end captured stdout << ---------------------- -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:32,478 DEBUG (MainThread) [storage.check] Checker '/path' started (check:233) 2016-12-30 02:21:32,479 DEBUG (MainThread) [storage.check] START check '/path' (delay=0.00) (check:283) 2016-12-30 02:21:32,489 DEBUG (MainThread) [storage.asyncevent] Closing <EventLoop running=False closed=False at 0x139704976616848> (asyncevent:215) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_running_start_raises (storage_check_test.TestDirectioChecker) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "3861" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:32,513 DEBUG (MainThread) [storage.check] Checker '/path' started (check:233) 2016-12-30 02:21:32,514 DEBUG (MainThread) [storage.check] START check '/path' (delay=0.00) (check:283) 2016-12-30 02:21:32,524 DEBUG (MainThread) [storage.asyncevent] Closing <EventLoop running=False closed=False at 0x139704979209232> (asyncevent:215) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_stopping_repr (storage_check_test.TestDirectioChecker) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "3864" } ] -------------------- >> begin captured stdout << --------------------- <DirectioChecker /path stopping at 0x7f0f99812cd0> --------------------- >> end captured stdout << ---------------------- -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:32,548 DEBUG (MainThread) [storage.check] Checker '/path' started (check:233) 2016-12-30 02:21:32,548 DEBUG (MainThread) [storage.check] START check '/path' (delay=0.00) (check:283) 2016-12-30 02:21:32,557 DEBUG (MainThread) [storage.check] Checker '/path' stopping (check:250) 2016-12-30 02:21:32,558 DEBUG (MainThread) [storage.asyncevent] Closing <EventLoop running=False closed=False at 0x139704976616592> (asyncevent:215) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_stopping_start_raises (storage_check_test.TestDirectioChecker) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "3867" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:32,586 DEBUG (MainThread) [storage.check] Checker '/path' started (check:233) 2016-12-30 02:21:32,586 DEBUG (MainThread) [storage.check] START check '/path' (delay=0.00) (check:283) 2016-12-30 02:21:32,596 DEBUG (MainThread) [storage.check] Checker '/path' stopping (check:250) 2016-12-30 02:21:32,597 DEBUG (MainThread) [storage.asyncevent] Closing <EventLoop running=False closed=False at 0x139704976616720> (asyncevent:215) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_stopping_stop_ignored (storage_check_test.TestDirectioChecker) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "3870" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:32,621 DEBUG (MainThread) [storage.check] Checker '/path' started (check:233) 2016-12-30 02:21:32,622 DEBUG (MainThread) [storage.check] START check '/path' (delay=0.00) (check:283) 2016-12-30 02:21:32,632 DEBUG (MainThread) [storage.check] Checker '/path' stopping (check:250) 2016-12-30 02:21:32,632 DEBUG (MainThread) [storage.asyncevent] Closing <EventLoop running=False closed=False at 0x139704976616912> (asyncevent:215) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_taskset_missing (storage_check_test.TestDirectioChecker) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "3873" } ] -------------------- >> begin captured stdout << --------------------- [<CheckResult path=/var/tmp/tmpaIeNcE rc=127 err='Error starting process: [Errno 2] No such file or directory' time=4321479.14 elapsed=0.01 at 0x7f0f99a8bc90>] --------------------- >> end captured stdout << ---------------------- -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:32,658 DEBUG (MainThread) [storage.check] Checker '/var/tmp/tmpaIeNcE' started (check:233) 2016-12-30 02:21:32,658 DEBUG (MainThread) [storage.check] START check '/var/tmp/tmpaIeNcE' (delay=0.00) (check:283) 2016-12-30 02:21:32,662 DEBUG (MainThread) [storage.check] FINISH check '/var/tmp/tmpaIeNcE' (rc=127, elapsed=0.01) (check:328) 2016-12-30 02:21:32,663 INFO (MainThread) [storage.asyncevent] Stopping <EventLoop running=False closed=False at 0x139704976616272> (asyncevent:194) 2016-12-30 02:21:32,663 INFO (MainThread) [storage.asyncevent] Starting <EventLoop running=True closed=False at 0x139704976616272> (asyncevent:122) 2016-12-30 02:21:32,663 DEBUG (MainThread) [storage.asyncevent] <EventLoop running=False closed=False at 0x139704976616272> stopped (asyncevent:130) 2016-12-30 02:21:32,664 DEBUG (MainThread) [storage.asyncevent] Closing <EventLoop running=False closed=False at 0x139704976616272> (asyncevent:215) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testTimeout (storage_iscsi_test.RescanTimeoutTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "sleep 2", "pid": "4293" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:37,279 DEBUG (MainThread) [storage.SamplingMethod] Trying to enter sampling method (vdsm.storage.iscsi.rescan) (misc:467) 2016-12-30 02:21:37,279 DEBUG (MainThread) [storage.SamplingMethod] Got in to sampling method (misc:470) 2016-12-30 02:21:37,279 DEBUG (MainThread) [storage.ISCSI] Performing SCSI scan, this will take up to 1 seconds (iscsi:457) 2016-12-30 02:21:37,279 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 2 (cwd None) (commands:69) 2016-12-30 02:21:38,285 DEBUG (MainThread) [storage.SamplingMethod] Returning last result (misc:477) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test (storage_misc_test.AsyncProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4367" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:39,392 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 cat (cwd None) (commands:69) 2016-12-30 02:21:39,402 INFO (MainThread) [AsyncProcTests] Writing data to std out (storage_misc_test:241) 2016-12-30 02:21:39,403 INFO (MainThread) [AsyncProcTests] Written data reading (storage_misc_test:244) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testCommunicate (storage_misc_test.AsyncProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4370" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:39,426 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 /bin/dd (cwd None) (commands:69) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testMutiWrite (storage_misc_test.AsyncProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4373" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:40,463 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 cat (cwd None) (commands:69) 2016-12-30 02:21:40,473 INFO (MainThread) [AsyncProcTests] Writing data to std out (storage_misc_test:256) 2016-12-30 02:21:40,473 INFO (MainThread) [AsyncProcTests] Writing more data to std out (storage_misc_test:258) 2016-12-30 02:21:40,473 INFO (MainThread) [AsyncProcTests] Written data reading (storage_misc_test:261) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testWaitCond (storage_misc_test.AsyncProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4376" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:40,501 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 12 (cwd None) (commands:69) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testWaitTimeout (storage_misc_test.AsyncProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4379" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:42,537 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 12 (cwd None) (commands:69) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testWriteLargeData (storage_misc_test.AsyncProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4382" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:44,572 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 cat (cwd None) (commands:69) 2016-12-30 02:21:44,580 INFO (MainThread) [AsyncProcTests] Writing data to std out (storage_misc_test:286) 2016-12-30 02:21:44,582 INFO (MainThread) [AsyncProcTests] Written data reading (storage_misc_test:289) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: Test that stop really stops the copying process. ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4413" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:21:45,963 DEBUG (MainThread) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-3 /usr/bin/nice -n 19 /usr/bin/ionice -c 3 /usr/bin/dd if=/tmp/tmpUsJOxV of=/tmp/tmpjQOhqP bs=64 seek=0 skip=0 conv=notrunc,fdatasync count=1 (cwd None) (commands:69) 2016-12-30 02:21:45,974 INFO (MainThread) [DdWatchCopy] Looks like it stopped! (storage_misc_test:465) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testNoCommandWithoutAffinity (storage_misc_test.ExecCmd) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4449" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:02,309 DEBUG (MainThread) [root] I.DONT.EXIST (cwd None) (commands:69) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: Test that stopping the process really works. ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "4582" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:06,000 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 10 (cwd None) (commands:69) 2016-12-30 02:22:06,005 INFO (MainThread) [WatchCmd] Looks like task stopped! (storage_misc_test:897) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testAmountOfInstancesPerPoolName (storage_outofprocess_test.OopWrapperTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "/usr/libexec/ioprocess --read-pipe-fd 93 --write-pipe-fd 92 --max-threads 10 --max-queued-requests 10", "pid": "4861" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:18,447 DEBUG (MainThread) [storage.oop] Creating ioprocess Global (outOfProcess:87) 2016-12-30 02:22:18,447 INFO (MainThread) [IOProcessClient] Starting client ioprocess-14 (__init__:325) 2016-12-30 02:22:18,447 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-14 (__init__:334) 2016-12-30 02:22:18,452 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-14 (__init__:386) 2016-12-30 02:22:18,452 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-14 started (__init__:398) 2016-12-30 02:22:18,452 DEBUG (MainThread) [storage.oop] Creating ioprocess A (outOfProcess:87) 2016-12-30 02:22:18,452 INFO (MainThread) [IOProcessClient] Starting client ioprocess-15 (__init__:325) 2016-12-30 02:22:18,453 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-15 (__init__:334) 2016-12-30 02:22:18,453 INFO (ioprocess communication (4848)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:18,453 DEBUG (ioprocess communication (4848)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:18,453 DEBUG (ioprocess communication (4848)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:18,457 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-15 (__init__:386) 2016-12-30 02:22:18,458 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-15 started (__init__:398) 2016-12-30 02:22:18,458 INFO (ioprocess communication (4854)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:18,458 DEBUG (ioprocess communication (4854)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:18,458 DEBUG (ioprocess communication (4854)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:24,464 DEBUG (MainThread) [storage.oop] Removing idle ioprocess A (outOfProcess:77) 2016-12-30 02:22:24,464 INFO (MainThread) [IOProcessClient] Closing client ioprocess-15 (__init__:593) 2016-12-30 02:22:24,464 DEBUG (MainThread) [storage.oop] Creating ioprocess B (outOfProcess:87) 2016-12-30 02:22:24,465 INFO (MainThread) [IOProcessClient] Starting client ioprocess-16 (__init__:325) 2016-12-30 02:22:24,465 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-16 (__init__:334) 2016-12-30 02:22:24,470 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-16 (__init__:386) 2016-12-30 02:22:24,470 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-16 started (__init__:398) 2016-12-30 02:22:24,515 INFO (ioprocess communication (4861)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:24,515 DEBUG (ioprocess communication (4861)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:24,516 DEBUG (ioprocess communication (4861)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:25,557 INFO (MainThread) [IOProcessClient] Closing client ioprocess-14 (__init__:593) 2016-12-30 02:22:25,557 DEBUG (MainThread) [IOProcessClient] Waiting for communication thread for ioprocess-14 (__init__:599) 2016-12-30 02:22:25,557 INFO (ioprocess communication (4848)) [IOProcessClient] shutdown requested (__init__:124) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testDifferentPoolName (storage_outofprocess_test.OopWrapperTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "/usr/libexec/ioprocess --read-pipe-fd 109 --write-pipe-fd 108 --max-threads 10 --max-queued-requests 10", "pid": "4882" }, { "command": "/usr/libexec/ioprocess --read-pipe-fd 101 --write-pipe-fd 99 --max-threads 10 --max-queued-requests 10", "pid": "4876" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:25,583 DEBUG (MainThread) [storage.oop] Creating ioprocess Global (outOfProcess:87) 2016-12-30 02:22:25,584 INFO (MainThread) [IOProcessClient] Starting client ioprocess-17 (__init__:325) 2016-12-30 02:22:25,584 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-17 (__init__:334) 2016-12-30 02:22:25,592 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-17 (__init__:386) 2016-12-30 02:22:25,593 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-17 started (__init__:398) 2016-12-30 02:22:25,593 DEBUG (MainThread) [storage.oop] Creating ioprocess A (outOfProcess:87) 2016-12-30 02:22:25,593 INFO (ioprocess communication (4870)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:25,593 DEBUG (ioprocess communication (4870)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:25,594 INFO (MainThread) [IOProcessClient] Starting client ioprocess-18 (__init__:325) 2016-12-30 02:22:25,594 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-18 (__init__:334) 2016-12-30 02:22:25,594 DEBUG (ioprocess communication (4870)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:25,604 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-18 (__init__:386) 2016-12-30 02:22:25,604 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-18 started (__init__:398) 2016-12-30 02:22:25,605 DEBUG (MainThread) [storage.oop] Creating ioprocess B (outOfProcess:87) 2016-12-30 02:22:25,605 INFO (ioprocess communication (4876)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:25,605 DEBUG (ioprocess communication (4876)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:25,605 INFO (MainThread) [IOProcessClient] Starting client ioprocess-19 (__init__:325) 2016-12-30 02:22:25,605 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-19 (__init__:334) 2016-12-30 02:22:25,605 DEBUG (ioprocess communication (4876)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:25,610 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-19 (__init__:386) 2016-12-30 02:22:25,610 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-19 started (__init__:398) 2016-12-30 02:22:25,611 INFO (MainThread) [IOProcessClient] Closing client ioprocess-16 (__init__:593) 2016-12-30 02:22:25,611 INFO (MainThread) [IOProcessClient] Closing client ioprocess-17 (__init__:593) 2016-12-30 02:22:25,611 INFO (ioprocess communication (4882)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:25,611 DEBUG (ioprocess communication (4882)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:25,611 INFO (ioprocess communication (4870)) [IOProcessClient] shutdown requested (__init__:124) 2016-12-30 02:22:25,612 DEBUG (MainThread) [IOProcessClient] Waiting for communication thread for ioprocess-17 (__init__:599) 2016-12-30 02:22:25,612 DEBUG (ioprocess communication (4882)) [IOProcess] Opening communication channels... (__init__:445) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testSamePoolName (storage_outofprocess_test.OopWrapperTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "/usr/libexec/ioprocess --read-pipe-fd 96 --write-pipe-fd 94 --max-threads 10 --max-queued-requests 10", "pid": "4918" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:25,718 DEBUG (MainThread) [storage.oop] Creating ioprocess Global (outOfProcess:87) 2016-12-30 02:22:25,719 INFO (MainThread) [IOProcessClient] Starting client ioprocess-22 (__init__:325) 2016-12-30 02:22:25,719 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-22 (__init__:334) 2016-12-30 02:22:25,723 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-22 (__init__:386) 2016-12-30 02:22:25,724 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-22 started (__init__:398) 2016-12-30 02:22:25,724 DEBUG (MainThread) [storage.oop] Creating ioprocess A (outOfProcess:87) 2016-12-30 02:22:25,724 INFO (MainThread) [IOProcessClient] Starting client ioprocess-23 (__init__:325) 2016-12-30 02:22:25,724 DEBUG (MainThread) [IOProcessClient] Starting ioprocess for client ioprocess-23 (__init__:334) 2016-12-30 02:22:25,724 INFO (ioprocess communication (4912)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:25,724 DEBUG (ioprocess communication (4912)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:25,725 DEBUG (ioprocess communication (4912)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:25,729 DEBUG (MainThread) [IOProcessClient] Starting communication thread for client ioprocess-23 (__init__:386) 2016-12-30 02:22:25,730 DEBUG (MainThread) [IOProcessClient] Communication thread for client ioprocess-23 started (__init__:398) 2016-12-30 02:22:25,730 INFO (MainThread) [IOProcessClient] Closing client ioprocess-18 (__init__:593) 2016-12-30 02:22:25,730 INFO (ioprocess communication (4918)) [IOProcess] Starting ioprocess (__init__:447) 2016-12-30 02:22:25,730 DEBUG (ioprocess communication (4918)) [IOProcess] Closing unrelated FDs... (__init__:445) 2016-12-30 02:22:25,730 DEBUG (ioprocess communication (4918)) [IOProcess] Opening communication channels... (__init__:445) 2016-12-30 02:22:25,731 INFO (MainThread) [IOProcessClient] Closing client ioprocess-22 (__init__:593) 2016-12-30 02:22:25,731 INFO (ioprocess communication (4912)) [IOProcessClient] shutdown requested (__init__:124) 2016-12-30 02:22:25,731 DEBUG (MainThread) [IOProcessClient] Waiting for communication thread for ioprocess-22 (__init__:599) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_get (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7676" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,549 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7676 (cwd None) (commands:69) 2016-12-30 02:22:54,555 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) 2016-12-30 02:22:54,555 DEBUG (MainThread) [root] /usr/bin/taskset --pid 567 (cwd None) (commands:69) 2016-12-30 02:22:54,562 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_set_from_child(frozenset([0, 3])) (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7684" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,652 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7684 (cwd None) (commands:69) 2016-12-30 02:22:54,658 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_set_from_child(frozenset([0])) (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7689" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,701 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7689 (cwd None) (commands:69) 2016-12-30 02:22:54,707 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_set_from_child(frozenset([1, 2])) (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7694" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,752 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7694 (cwd None) (commands:69) 2016-12-30 02:22:54,763 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_set_from_parent(frozenset([0, 3])) (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7699" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,797 DEBUG (MainThread) [root] /usr/bin/taskset --pid --cpu-list 0,3 7699 (cwd None) (commands:69) 2016-12-30 02:22:54,808 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) 2016-12-30 02:22:54,808 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7699 (cwd None) (commands:69) 2016-12-30 02:22:54,813 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_set_from_parent(frozenset([0])) (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7704" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,849 DEBUG (MainThread) [root] /usr/bin/taskset --pid --cpu-list 0 7704 (cwd None) (commands:69) 2016-12-30 02:22:54,855 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) 2016-12-30 02:22:54,855 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7704 (cwd None) (commands:69) 2016-12-30 02:22:54,861 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: test_set_from_parent(frozenset([1, 2])) (tasksetTests.AffinityTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "7710" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:22:54,909 DEBUG (MainThread) [root] /usr/bin/taskset --pid --cpu-list 1,2 7710 (cwd None) (commands:69) 2016-12-30 02:22:54,920 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) 2016-12-30 02:22:54,920 DEBUG (MainThread) [root] /usr/bin/taskset --pid 7710 (cwd None) (commands:69) 2016-12-30 02:22:54,925 DEBUG (MainThread) [root] SUCCESS: <err> = ''; <rc> = 0 (commands:93) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testWait(['sleep', '1'], ['sleep', '3'], False) (v2vTests.PipelineProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "9495" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:23:34,072 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 1 (cwd None) (v2v:1301) 2016-12-30 02:23:34,082 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 3 (cwd None) (v2v:1301) 2016-12-30 02:23:37,086 DEBUG (MainThread) [root] Killing pid=9494 (v2v:679) 2016-12-30 02:23:37,086 DEBUG (MainThread) [root] Killing pid=9495 (v2v:679) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testWait(['sleep', '3'], ['sleep', '1'], False) (v2vTests.PipelineProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "9498" }, { "command": "", "pid": "9499" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:23:37,112 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 3 (cwd None) (v2v:1301) 2016-12-30 02:23:37,122 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 1 (cwd None) (v2v:1301) 2016-12-30 02:23:39,134 DEBUG (MainThread) [root] Killing pid=9498 (v2v:679) 2016-12-30 02:23:39,135 DEBUG (MainThread) [root] Killing pid=9499 (v2v:679) --------------------- >> end captured logging << --------------------- ====================================================================== ERROR: testWait(['sleep', '3'], ['sleep', '3'], False) (v2vTests.PipelineProcTests) ---------------------------------------------------------------------- Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/nose/case.py", line 133, in run self.runTest(result) File "/usr/lib/python2.7/site-packages/nose/case.py", line 151, in runTest test(result) AssertionError: Test leaked child processes: [ { "command": "", "pid": "9503" }, { "command": "", "pid": "9504" } ] -------------------- >> begin captured logging << -------------------- 2016-12-30 02:23:39,164 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 3 (cwd None) (v2v:1301) 2016-12-30 02:23:39,176 DEBUG (MainThread) [root] /usr/bin/taskset --cpu-list 0-3 sleep 3 (cwd None) (v2v:1301) 2016-12-30 02:23:41,186 DEBUG (MainThread) [root] Killing pid=9503 (v2v:679) 2016-12-30 02:23:41,187 DEBUG (MainThread) [root] Killing pid=9504 (v2v:679) --------------------- >> end captured logging << ---------------------