Open Bug 1455211 Opened 3 years ago Updated 2 years ago

Intermittent ..\testing\mozbase\mozrunner\tests\test_start.py::test_start_with_outputTimeout[firefox] TEST-UNEXPECTED-FAIL

Categories

(Testing :: Mozbase, defect, P5)

Product:
Testing
Component:
Mozbase
Version:
Version 3
Type:
defect

Tracking

(firefox60 unaffected, firefox61 affected)

Tracking Flags:
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 - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
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)
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?
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)
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.
(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.
You need to log in before you can comment on or make changes to this bug.