1459548 - Intermittent TEST-UNEXPECTED-OK | /webdriver/tests/new_session/create_alwaysMatch.py | expected TIMEOUT

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=177157361&repo=autoland

https://queue.taskcluster.net/v1/task/an1CWVxbSkyFGYqIdmjSdQ/runs/0/artifacts/public/logs/live_backing.log

[task 2018-05-06T10:06:58.949Z] 10:06:58     INFO - PID 4523 | nsStringStats
[task 2018-05-06T10:06:58.949Z] 10:06:58     INFO - PID 4523 |  => mAllocCount:          66165
[task 2018-05-06T10:06:58.951Z] 10:06:58     INFO - PID 4523 |  => mReallocCount:         5447
[task 2018-05-06T10:06:58.952Z] 10:06:58     INFO - PID 4523 |  => mFreeCount:           66164  --  LEAKED 1 !!!
[task 2018-05-06T10:06:58.952Z] 10:06:58     INFO - PID 4523 |  => mShareCount:          60457
[task 2018-05-06T10:06:58.953Z] 10:06:58     INFO - PID 4523 |  => mAdoptCount:           2785
[task 2018-05-06T10:06:58.954Z] 10:06:58     INFO - PID 4523 |  => mAdoptFreeCount:       2829
[task 2018-05-06T10:06:58.955Z] 10:06:58     INFO - PID 4523 |  => Process ID: 7789, Thread ID: 139980220323648
[task 2018-05-06T10:06:58.971Z] 10:06:58     INFO - PID 4523 | 1525601218965	geckodriver::marionette	DEBUG	Browser process stopped: exit code: 0
[task 2018-05-06T10:06:58.980Z] 10:06:58     INFO - STDOUT: =================================== FAILURES ===================================
[task 2018-05-06T10:06:58.980Z] 10:06:58     INFO - STDOUT: _________________________ test_valid[timeouts-value10] _________________________
[task 2018-05-06T10:06:58.980Z] 10:06:58     INFO - PID 4523 | 1525601218970	webdriver::server	DEBUG	<- 200 OK {"value": {}}
[task 2018-05-06T10:06:58.981Z] 10:06:58     INFO - STDOUT: new_session = <function create_session at 0x7f8516799050>
[task 2018-05-06T10:06:58.981Z] 10:06:58     INFO - STDOUT: add_browser_capabilites = <function update_capabilities at 0x7f8516799140>
[task 2018-05-06T10:06:58.982Z] 10:06:58     INFO - STDOUT: key = 'timeouts'
[task 2018-05-06T10:06:58.983Z] 10:06:58     INFO - STDOUT: value = {'implicit': 9007199254740991, 'pageLoad': 2.0, 'script': 0}
[task 2018-05-06T10:06:58.983Z] 10:06:58     INFO - STDOUT:     @pytest.mark.parametrize("key,value", flatten(product(*item) for item in valid_data))
[task 2018-05-06T10:06:58.984Z] 10:06:58     INFO - STDOUT:     def test_valid(new_session, add_browser_capabilites, key, value):
[task 2018-05-06T10:06:58.984Z] 10:06:58     INFO - STDOUT: >       resp = new_session({"capabilities": {"alwaysMatch": add_browser_capabilites({key: value})}})
[task 2018-05-06T10:06:58.984Z] 10:06:58     INFO - STDOUT: add_browser_capabilites = <function update_capabilities at 0x7f8516799140>
[task 2018-05-06T10:06:58.985Z] 10:06:58     INFO - STDOUT: key        = 'timeouts'
[task 2018-05-06T10:06:58.986Z] 10:06:58     INFO - STDOUT: new_session = <function create_session at 0x7f8516799050>
[task 2018-05-06T10:06:58.986Z] 10:06:58     INFO - STDOUT: value      = {'implicit': 9007199254740991, 'pageLoad': 2.0, 'script': 0}
[task 2018-05-06T10:06:58.987Z] 10:06:58     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/sessions/new_session/create_alwaysMatch.py
[task 2018-05-06T10:06:58.987Z] 10:06:58     INFO - STDOUT: :12: 
[task 2018-05-06T10:06:58.987Z] 10:06:58     INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2018-05-06T10:06:58.988Z] 10:06:58     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/support/fixtures.py
[task 2018-05-06T10:06:58.988Z] 10:06:58     INFO - STDOUT: :192: in create_session
[task 2018-05-06T10:06:58.988Z] 10:06:58     INFO - STDOUT:     value = _session.send_command("POST", "session", body=body)
[task 2018-05-06T10:06:58.989Z] 10:06:58     INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2018-05-06T10:06:58.990Z] 10:06:58     INFO - STDOUT: self = <Session (disconnected)>, method = 'POST', url = 'session'
[task 2018-05-06T10:06:58.991Z] 10:06:58     INFO - STDOUT: body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox...eb-platform.test,www1.web-platform.test'}}, 'timeouts': {'implicit': 9007199254740991, 'pageLoad': 2.0, 'script': 0}}}}
[task 2018-05-06T10:06:58.991Z] 10:06:58     INFO - STDOUT:     def send_command(self, method, url, body=None):
[task 2018-05-06T10:06:58.991Z] 10:06:58     INFO - STDOUT:         """
[task 2018-05-06T10:06:58.992Z] 10:06:58     INFO - STDOUT:             Send a command to the remote end and validate its success.
[task 2018-05-06T10:06:58.992Z] 10:06:58     INFO - STDOUT:     
[task 2018-05-06T10:06:58.993Z] 10:06:58     INFO - STDOUT:             :param method: HTTP method to use in request.
[task 2018-05-06T10:06:58.993Z] 10:06:58     INFO - STDOUT:             :param uri: "Command part" of the HTTP request URL,
[task 2018-05-06T10:06:58.993Z] 10:06:58     INFO - STDOUT:                 e.g. `window/rect`.
[task 2018-05-06T10:06:58.994Z] 10:06:58     INFO - STDOUT:             :param body: Optional body of the HTTP request.
[task 2018-05-06T10:06:58.994Z] 10:06:58     INFO - STDOUT:     
[task 2018-05-06T10:06:58.995Z] 10:06:58     INFO - STDOUT:             :return: `None` if the HTTP response body was empty, otherwise
[task 2018-05-06T10:06:58.996Z] 10:06:58     INFO - STDOUT:                 the `value` field returned after parsing the response
[task 2018-05-06T10:06:58.996Z] 10:06:58     INFO - STDOUT:                 body as JSON.
[task 2018-05-06T10:06:58.997Z] 10:06:58     INFO - STDOUT:     
[task 2018-05-06T10:06:58.997Z] 10:06:58     INFO - STDOUT:             :raises ValueError: If the response body does not contain a
[task 2018-05-06T10:06:58.997Z] 10:06:58     INFO - STDOUT:                 `value` key.
[task 2018-05-06T10:06:58.998Z] 10:06:58     INFO - STDOUT:             :raises error.WebDriverException: If the remote end returns
[task 2018-05-06T10:06:58.998Z] 10:06:58     INFO - STDOUT:                 an error.
[task 2018-05-06T10:06:58.999Z] 10:06:58     INFO - STDOUT:             """
[task 2018-05-06T10:06:58.999Z] 10:06:58     INFO - STDOUT:         response = self.transport.send(
[task 2018-05-06T10:06:58.999Z] 10:06:58     INFO - STDOUT:             method, url, body,
[task 2018-05-06T10:06:59.000Z] 10:06:59     INFO - STDOUT:             encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2018-05-06T10:06:59.000Z] 10:06:59     INFO - STDOUT:             session=self)
[task 2018-05-06T10:06:59.000Z] 10:06:59     INFO - STDOUT:     
[task 2018-05-06T10:06:59.001Z] 10:06:59     INFO - STDOUT:         if response.status != 200:
[task 2018-05-06T10:06:59.002Z] 10:06:59     INFO - STDOUT: >           raise error.from_response(response)
[task 2018-05-06T10:06:59.002Z] 10:06:59     INFO - STDOUT: E           InvalidArgumentException: invalid argument (400): pageLoad timeouts value is not an integer: 2.0
[task 2018-05-06T10:06:59.003Z] 10:06:59     INFO - STDOUT: body       = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox...eb-platform.test,www1.web-platform.test'}}, 'timeouts': {'implicit': 9007199254740991, 'pageLoad': 2.0, 'script': 0}}}}
[task 2018-05-06T10:06:59.004Z] 10:06:59     INFO - STDOUT: method     = 'POST'
[task 2018-05-06T10:06:59.004Z] 10:06:59     INFO - STDOUT: response   = <Response status=400 error=<InvalidArgumentException http_status=400>>
[task 2018-05-06T10:06:59.004Z] 10:06:59     INFO - STDOUT: self       = <Session (disconnected)>
[task 2018-05-06T10:06:59.005Z] 10:06:59     INFO - STDOUT: url        = 'session'
[task 2018-05-06T10:06:59.005Z] 10:06:59     INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/client.py
[task 2018-05-06T10:06:59.006Z] 10:06:59     INFO - STDOUT: :438: InvalidArgumentException
[task 2018-05-06T10:06:59.006Z] 10:06:59     INFO - STDOUT: =============================== warnings summary ===============================
[task 2018-05-06T10:06:59.006Z] 10:06:59     INFO - STDOUT: None
[task 2018-05-06T10:06:59.006Z] 10:06:59     INFO - STDOUT:   Module already imported so cannot be rewritten: mozlog
[task 2018-05-06T10:06:59.006Z] 10:06:59     INFO - STDOUT: -- Docs: http://doc.pytest.org/en/latest/warnings.html
[task 2018-05-06T10:06:59.006Z] 10:06:59     INFO - STDOUT: ============== 1 failed, 22 passed, 1 warnings in 362.84 seconds ===============
[task 2018-05-06T10:06:59.028Z] 10:06:59     INFO - TEST-UNEXPECTED-OK | /webdriver/tests/sessions/new_session/create_alwaysMatch.py | expected TIMEOUT

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Similar to bug 1459549 for `create_firstMatch.py`. As it looks like we expect a timeout (bug 1418778) even with have a longer timeout requested, but due to the fix on bug 1411908 we might not see the timeout anymore.

The only solution I could see here would be to split-up the tests in different modules.

Comment 2

[Intermittent Failures Robot]

3 failures in 660 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 2
* mozilla-inbound: 1

Platform breakdown:
* linux64-qr: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1459548&startday=2018-05-07&endday=2018-05-13&tree=trunk

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Similar to bug 1459549 this failure seem to only happen for Firefox with webrender enabled. I think we have to update some manifests to just disable the tests for now similar to others as marked as being blocked by bug 1425588.

Comment 4

[Intermittent Failures Robot]

12 failures in 639 pushes (0.019 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 2
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux64-qr: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1459548&startday=2018-05-14&endday=2018-05-20&tree=trunk

Comment 5

[Stefan Hindli [:stefan_hindli]]

Over the last 7 days there are 30 failures on this bug, these happen only on linux64-qr.
Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=180430429&repo=mozilla-inbound&lineNumber=51230

[task 2018-05-27T00:21:57.547Z] 00:21:57     INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/client.py
[task 2018-05-27T00:21:57.547Z] 00:21:57     INFO - STDOUT: :445: InvalidArgumentException
[task 2018-05-27T00:21:57.547Z] 00:21:57     INFO - STDOUT: =============================== warnings summary ===============================
[task 2018-05-27T00:21:57.548Z] 00:21:57     INFO - STDOUT: None
[task 2018-05-27T00:21:57.549Z] 00:21:57     INFO - STDOUT:   Module already imported so cannot be rewritten: mozlog
[task 2018-05-27T00:21:57.550Z] 00:21:57     INFO - STDOUT: -- Docs: http://doc.pytest.org/en/latest/warnings.html
[task 2018-05-27T00:21:57.551Z] 00:21:57     INFO - STDOUT: ============== 1 failed, 22 passed, 1 warnings in 363.00 seconds ===============
[task 2018-05-27T00:21:57.559Z] 00:21:57     INFO - TEST-UNEXPECTED-OK | /webdriver/tests/new_session/create_alwaysMatch.py | expected TIMEOUT
[task 2018-05-27T00:21:57.560Z] 00:21:57     INFO - TEST-INFO expected TIMEOUT | took 363205ms
[task 2018-05-27T00:21:57.590Z] 00:21:57  WARNING - u'runner_teardown': ()

Comment 6

[Intermittent Failures Robot]

58 failures in 632 pushes (0.092 failures/push) were associated with this bug in the last 7 days. 

This is the #33 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* try: 28
* autoland: 15
* mozilla-inbound: 12
* mozilla-central: 3

Platform breakdown:
* linux64-qr: 58

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1459548&startday=2018-05-21&endday=2018-05-27&tree=trunk

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This is blocked on bug 1464756.

Comment 8

[Intermittent Failures Robot]

24 failures in 74 pushes (0.324 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 15
* try: 5
* mozilla-central: 4

Platform breakdown:
* linux64-qr: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1459548&startday=2018-05-28&endday=2018-05-28&tree=trunk

Comment 9

[Kartikaya Gupta (email:[e-mail])]

Apparently bug 1463416 made this "permafail" in that now it never times out on QR. So I landed a follow-up patch on that bug to remove the webrender:timeout expectation from this test. I probably should have landed it on this bug, but too late for that now.

Anyway, once that merges to m-c I expect we can close this bug as fixed.

https://hg.mozilla.org/integration/mozilla-inbound/rev/66b6a79c3bb0440c54dbad39189bd5cd44c74347

Comment 10

[Intermittent Failures Robot]

72 failures in 139 pushes (0.518 failures/push) were associated with this bug yesterday.    

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. ** 

Repository breakdown:
* mozilla-inbound: 28
* autoland: 25
* try: 15
* mozilla-central: 4

Platform breakdown:
* linux64-qr: 72

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1459548&startday=2018-05-29&endday=2018-05-29&tree=trunk

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #9)
> Apparently bug 1463416 made this "permafail" in that now it never times out
> on QR.

This are great news! Do you have an idea which of the changes could have improved the startup/shutdown times of Firefox?

> So I landed a follow-up patch on that bug to remove the
> webrender:timeout expectation from this test. I probably should have landed
> it on this bug, but too late for that now.

No, this is totally fine as long as we are aware of that change.

> Anyway, once that merges to m-c I expect we can close this bug as fixed.

Thanks again.

I will also check all the other test failures as marked as deps on bug 1464756 if we have more improvements.

Comment 12

[Kartikaya Gupta (email:[e-mail])]

(In reply to Henrik Skupin (:whimboo) from comment #11)
> Do you have an idea which of the changes could have
> improved the startup/shutdown times of Firefox?

I looked at the try pushes in bug 1463416 for the various WR csets, and it looks like it was caused by servo/webrender#2767. Interestingly, that change also caused a bunch of talos perf improvements and memory regression (see bug 1465098).

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Thanks. I will keep an eye on that memory regression bug.

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The test is not disabled on beta, so it's a wontfix.

Comment 15

[Intermittent Failures Robot]

97 failures in 655 pushes (0.148 failures/push) were associated with this bug in the last 7 days. 

This is the #8 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 39
* mozilla-inbound: 29
* try: 21
* mozilla-central: 8

Platform breakdown:
* linux64-qr: 97

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1459548&startday=2018-05-28&endday=2018-06-03&tree=trunk

Comment 16

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.