Open Bug 1569941 Opened 4 months ago Updated 4 days ago

Intermittent 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_after_external_kill TEST-UNEXPECTED-FAIL

Categories

(Testing :: Mozbase, defect, P5)

Version 3
defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression)

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=258973294&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/FIEuUGVtTAKj9kHyPiV62w/runs/0/artifacts/public/logs/live_backing.log


[task 2019-07-30T10:36:40.884Z] 0:46.14 ============================= test session starts ==============================
[task 2019-07-30T10:36:40.887Z] 0:46.14 platform darwin -- Python 3.7.3, pytest-3.6.2, py-1.5.4, pluggy-0.6.0 -- /usr/local/bin/python3
[task 2019-07-30T10:36:40.888Z] 0:46.14 rootdir: /Users/cltbld/tasks/task_1564479930/checkouts/gecko, inifile: /Users/cltbld/tasks/task_1564479930/checkouts/gecko/config/mozunit/mozunit/pytest.ini
[task 2019-07-30T10:36:40.888Z] 0:46.14 collecting ... collected 6 items
[task 2019-07-30T10:36:40.888Z] 0:46.14
[task 2019-07-30T10:36:40.888Z] 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_after_double_kill PASSED
[task 2019-07-30T10:36:40.889Z] 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_after_external_kill TEST-UNEXPECTED-FAIL
[task 2019-07-30T10:36:40.889Z] 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_after_kill PASSED
[task 2019-07-30T10:36:40.889Z] 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_after_kill_no_process_group PASSED
[task 2019-07-30T10:36:40.889Z] 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_before_run PASSED
[task 2019-07-30T10:36:40.889Z] 0:46.14 testing/mozbase/mozprocess/tests/test_poll.py::ProcTestPoll::test_poll_while_running PASSED
[task 2019-07-30T10:36:40.889Z] 0:46.14
[task 2019-07-30T10:36:40.889Z] 0:46.14 =================================== FAILURES ===================================
[task 2019-07-30T10:36:40.889Z] 0:46.14 __________________ ProcTestPoll.test_poll_after_external_kill __________________
[task 2019-07-30T10:36:40.889Z] 0:46.14
[task 2019-07-30T10:36:40.889Z] 0:46.14 self = <test_poll.ProcTestPoll testMethod=test_poll_after_external_kill>
[task 2019-07-30T10:36:40.889Z] 0:46.14
[task 2019-07-30T10:36:40.889Z] 0:46.14 @unittest.skipIf(sys.platform.startswith("win"), "Bug 1493796")
[task 2019-07-30T10:36:40.890Z] 0:46.14 def test_poll_after_external_kill(self):
[task 2019-07-30T10:36:40.890Z] 0:46.14 """Process is killed externally, and poll() is called."""
[task 2019-07-30T10:36:40.890Z] 0:46.14 p = processhandler.ProcessHandler([self.python, self.proclaunch,
[task 2019-07-30T10:36:40.890Z] 0:46.14 "process_normal_finish.ini"],
[task 2019-07-30T10:36:40.890Z] 0:46.14 cwd=here)
[task 2019-07-30T10:36:40.890Z] 0:46.14 p.run()
[task 2019-07-30T10:36:40.890Z] 0:46.14
[task 2019-07-30T10:36:40.890Z] 0:46.14 os.kill(p.pid, signal.SIGTERM)
[task 2019-07-30T10:36:40.890Z] 0:46.14
[task 2019-07-30T10:36:40.890Z] 0:46.14 # Allow the output reader thread to finish processing remaining data
[task 2019-07-30T10:36:40.890Z] 0:46.14 for i in range(0, 100):
[task 2019-07-30T10:36:40.890Z] 0:46.14 time.sleep(processhandler.INTERVAL_PROCESS_ALIVE_CHECK)
[task 2019-07-30T10:36:40.891Z] 0:46.14 returncode = p.poll()
[task 2019-07-30T10:36:40.891Z] 0:46.14 if returncode is not None:
[task 2019-07-30T10:36:40.891Z] 0:46.14 break
[task 2019-07-30T10:36:40.891Z] 0:46.14
[task 2019-07-30T10:36:40.891Z] 0:46.14 # We killed the process, so the returncode should be non-zero
[task 2019-07-30T10:36:40.891Z] 0:46.14 if mozinfo.isWin:
[task 2019-07-30T10:36:40.891Z] 0:46.14 self.assertEqual(returncode, signal.SIGTERM,
[task 2019-07-30T10:36:40.891Z] 0:46.14 'Positive returncode expected, got "%s"' % returncode)
[task 2019-07-30T10:36:40.891Z] 0:46.14 else:
[task 2019-07-30T10:36:40.891Z] 0:46.14 self.assertEqual(returncode, -signal.SIGTERM,
[task 2019-07-30T10:36:40.891Z] 0:46.14 > '%s expected, got "%s"' % (-signal.SIGTERM, returncode))
[task 2019-07-30T10:36:40.891Z] 0:46.14 E AssertionError: -9 != -15 : -15 expected, got "-9"
[task 2019-07-30T10:36:40.891Z] 0:46.14
[task 2019-07-30T10:36:40.891Z] 0:46.15 testing/mozbase/mozprocess/tests/test_poll.py:128: AssertionError
[task 2019-07-30T10:36:40.892Z] 0:46.15 ====================== 1 failed, 5 passed in 0.61 seconds ======================
[task 2019-07-30T10:36:40.895Z] 0:46.15 Setting retcode to 1 from /Users/cltbld/tasks/task_1564479930/checkouts/gecko/testing/mozbase/mozprocess/tests/test_poll.py
[task 2019-07-30T10:36:41.757Z] 0:47.01 /Users/cltbld/tasks/task_1564479930/checkouts/gecko/testing/mozbase/mozprofile/tests/test_addonid.py

nodejs reports a similar issue in their CI.

At least starting with Darwin Kernel Version 16.4.0, sending a SIGTERM
to a process that is still starting up kills it with SIGKILL instead of
SIGTERM.

Refs: libuv/libuv#1226

You need to log in before you can comment on or make changes to this bug.