3:54 a.m.
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 << ---------------------