Open
Bug 1455211
Opened 4 years ago
Updated 4 years ago
Intermittent ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_outputTimeout[firefox] TEST-UNEXPECTED-FAIL
Categories
(Testing :: Mozbase, defect, P5)
Tracking
(firefox60 unaffected, firefox61 affected)
NEW
Tracking | Status | |
---|---|---|
firefox60 | --- | unaffected |
firefox61 | --- | affected |
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=174440769&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/aNxL_cdqQjqlBZLZfz-JGg/runs/0/artifacts/public/logs/live_backing.log 01:04:05 INFO - z:\build\build\src\testing\mozbase\mozrunner\tests\test_start.py 01:04:05 INFO - ============================= test session starts ============================= 01:04:05 INFO - platform win32 -- Python 2.7.14, pytest-3.1.3, py-1.4.34, pluggy-0.4.0 -- z:\build\build\src\obj-firefox\_virtualenv\Scripts\python.exe 01:04:05 INFO - rootdir: z:\build\build\src\testing\mozbase\mozrunner, inifile: 01:04:05 INFO - collecting ... collected 8 items 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_process[firefox] PASSED 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_process[chrome] SKIPPED 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_process_called_twice[firefox] PASSED 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_process_called_twice[chrome] SKIPPED 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_timeout[firefox] PASSED 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_timeout[chrome] SKIPPED 01:04:05 WARNING - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_outputTimeout[firefox] TEST-UNEXPECTED-FAIL 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_outputTimeout[firefox] ERROR 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_outputTimeout[chrome] SKIPPED 01:04:05 INFO - =================================== ERRORS ==================================== 01:04:05 INFO - _________ ERROR at teardown of test_start_with_outputTimeout[firefox] _________ 01:04:05 INFO - request = <SubRequest 'runner' for <Function 'test_start_with_outputTimeout[firefox]'>> 01:04:05 INFO - get_binary = <function inner at 0x00000000046C3438> 01:04:05 INFO - @pytest.fixture(params=['firefox', 'chrome']) 01:04:05 INFO - def runner(request, get_binary): 01:04:05 INFO - app = request.param 01:04:05 INFO - binary = get_binary(app) 01:04:05 INFO - cmdargs = ['--headless'] 01:04:05 INFO - if app == 'chrome': 01:04:05 INFO - # prevents headless chrome from exiting after loading the page 01:04:05 INFO - cmdargs.append('--remote-debugging-port=9222') 01:04:05 INFO - # only needed on Windows, but no harm in specifying it everywhere 01:04:05 INFO - cmdargs.append('--disable-gpu') 01:04:05 INFO - runner = mozrunner.runners[app](binary, cmdargs=cmdargs) 01:04:05 INFO - runner.app = app 01:04:05 INFO - yield runner 01:04:05 INFO - > runner.stop() 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\conftest.py:50: 01:04:05 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 01:04:05 INFO - ..\testing\mozbase\mozrunner\mozrunner\base\runner.py:197: in stop 01:04:05 INFO - self.process_handler.kill(sig=sig) 01:04:05 INFO - ..\testing\mozbase\mozprocess\mozprocess\processhandler.py:788: in kill 01:04:05 INFO - self.proc.kill(sig=sig) 01:04:05 INFO - ..\testing\mozbase\mozprocess\mozprocess\processhandler.py:200: in kill 01:04:05 INFO - self.returncode = self.wait() 01:04:05 INFO - ..\testing\mozbase\mozprocess\mozprocess\processhandler.py:221: in wait 01:04:05 INFO - self.returncode = self._wait() 01:04:05 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
Comment 1•4 years ago
|
||
New failure since bug 1445944 has been landed. Andrew, can you please have a look?
Blocks: 1445944
status-firefox60:
--- → unaffected
status-firefox61:
--- → affected
Flags: needinfo?(ahalberstadt)
Comment 2•4 years ago
|
||
Here some more info: 01:04:05 INFO - except Exception: 01:04:05 INFO - traceback.print_exc() 01:04:05 INFO - > raise OSError("IO Completion Port failed to signal process shutdown") 01:04:05 INFO - E OSError: IO Completion Port failed to signal process shutdown 01:04:05 INFO - ..\testing\mozbase\mozprocess\mozprocess\processhandler.py:527: OSError 01:04:05 INFO - -------------------------- Captured stderr teardown --------------------------- 01:04:05 INFO - Traceback (most recent call last): 01:04:05 INFO - File "z:\build\build\src\testing\mozbase\mozprocess\mozprocess\processhandler.py", line 521, in _wait 01:04:05 INFO - self.MAX_PROCESS_KILL_DELAY) 01:04:05 INFO - File "c:\mozilla-build\python\Lib\Queue.py", line 176, in get 01:04:05 INFO - raise Empty 01:04:05 INFO - Empty 01:04:05 INFO - ================================== FAILURES =================================== 01:04:05 INFO - ___________________ test_start_with_outputTimeout[firefox] ____________________ 01:04:05 INFO - runner = <mozrunner.base.browser.GeckoRuntimeRunner object at 0x00000000046F4B70> 01:04:05 INFO - def test_start_with_outputTimeout(runner): 01:04:05 INFO - """Start the process and set a timeout""" 01:04:05 INFO - runner.start(outputTimeout=0.1) 01:04:05 INFO - sleep(1) 01:04:05 INFO - > assert not runner.is_running() 01:04:05 INFO - E assert not True 01:04:05 INFO - E + where True = <bound method GeckoRuntimeRunner.is_running of <mozrunner.base.browser.GeckoRuntimeRunner object at 0x00000000046F4B70>>() 01:04:05 INFO - E + where <bound method GeckoRuntimeRunner.is_running of <mozrunner.base.browser.GeckoRuntimeRunner object at 0x00000000046F4B70>> = <mozrunner.base.browser.GeckoRuntimeRunner object at 0x00000000046F4B70>.is_running 01:04:05 INFO - ..\testing\mozbase\mozrunner\tests\test_start.py:48: AssertionError Maybe this failure was tracked differently before the conversion of the tests to pytest. Sadly the error summary doesn't contain the real failure of the assertion. Andrew, maybe we have to do something similar for mozbase tests as what I did for wdspec on bug 1433923?
Comment 3•4 years ago
|
||
Hm, I did bump down the sleeps in some of the tests to make them run faster. I ran a lot of retriggers, but maybe the intermittent is just very infrequent. I can try bumping the sleep back up I guess. I'd love if we didn't use sleeps at all in these tests, but that's probably a decent amount of work in itself. I'll at least file a follow-up bug.
Flags: needinfo?(ahalberstadt)
Comment 4•4 years ago
|
||
Btw, the failure in that test is that the runner is still running after it should have been killed via the outputTimeout. It's possible that this is a legit bug in mozrunner/mozprocess. Or it's possible that the tests are just written poorly.
Comment hidden (Intermittent Failures Robot) |
Comment 6•4 years ago
|
||
(In reply to Andrew Halberstadt [:ahal] (PTO until May 1st) from comment #4) > Btw, the failure in that test is that the runner is still running after it > should have been killed via the outputTimeout. It's possible that this is a > legit bug in mozrunner/mozprocess. Or it's possible that the tests are just > written poorly. This might perfectly be a side-effect from bug 1438009.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•