Closed Bug 1519614 Opened 6 years ago Closed 6 years ago

Perma tier2 testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_basic | NoSuchWindowException: Unable to locate window: 16

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Platform:
Unspecified
Android
Type:
defect

Tracking

(firefox65 unaffected, firefox66 affected)

Status:
RESOLVED DUPLICATE of bug 1519552
Tracking Flags:
Tracking Status
firefox65 --- unaffected
firefox66 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell needswork])

Filed by: shindli [at] mozilla.com

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

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

[task 2019-01-12T07:57:16.888Z] 07:57:16 WARNING - The marionette suite: marionette ran with return status: WARNING
[task 2019-01-12T07:57:16.888Z] 07:57:16 INFO - Running post-action listener: _package_coverage_data
[task 2019-01-12T07:57:16.889Z] 07:57:16 INFO - Running post-action listener: _resource_record_post_action
[task 2019-01-12T07:57:16.889Z] 07:57:16 INFO - Running post-action listener: process_java_coverage_data
[task 2019-01-12T07:57:16.889Z] 07:57:16 INFO - Running post-action listener: stop_device
[task 2019-01-12T07:57:16.889Z] 07:57:16 INFO - Killing logcat pid 1091.
[task 2019-01-12T07:57:16.890Z] 07:57:16 INFO - Killing every process called emulator64-arm
[task 2019-01-12T07:57:16.899Z] 07:57:16 INFO - Killing pid 471.
[task 2019-01-12T07:57:16.900Z] 07:57:16 INFO - [mozharness: 2019-01-12 07:57:16.900177Z] Finished run-tests step (success)
[task 2019-01-12T07:57:16.900Z] 07:57:16 INFO - Running post-run listener: _resource_record_post_run
[task 2019-01-12T07:57:16.994Z] 07:57:16 INFO - Total resource usage - Wall time: 760s; CPU: 15.0%; Read bytes: 1613824; Write bytes: 738172928; Read time: 24; Write time: 122592
[task 2019-01-12T07:57:16.994Z] 07:57:16 INFO - TinderboxPrint: CPU usage<br/>14.8%
[task 2019-01-12T07:57:16.995Z] 07:57:16 INFO - TinderboxPrint: I/O read bytes / time<br/>1,613,824 / 24
[task 2019-01-12T07:57:16.995Z] 07:57:16 INFO - TinderboxPrint: I/O write bytes / time<br/>738,172,928 / 122,592
[task 2019-01-12T07:57:16.995Z] 07:57:16 INFO - TinderboxPrint: CPU idle<br/>2,557.5 (85.1%)
[task 2019-01-12T07:57:16.996Z] 07:57:16 INFO - TinderboxPrint: CPU user<br/>435.3 (14.5%)
[task 2019-01-12T07:57:16.996Z] 07:57:16 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2019-01-12T07:57:16.997Z] 07:57:16 INFO - verify-device - Wall time: 5s; CPU: 7.0%; Read bytes: 0; Write bytes: 4227072; Read time: 0; Write time: 2256
[task 2019-01-12T07:57:16.998Z] 07:57:16 INFO - install - Wall time: 58s; CPU: 25.0%; Read bytes: 0; Write bytes: 381177856; Read time: 0; Write time: 69732
[task 2019-01-12T07:57:17.006Z] 07:57:17 INFO - run-tests - Wall time: 698s; CPU: 14.0%; Read bytes: 1613824; Write bytes: 350711808; Read time: 24; Write time: 50204
[task 2019-01-12T07:57:17.242Z] 07:57:17 WARNING - returning nonzero exit status 1
[task 2019-01-12T07:57:17.259Z] cleanup
[task 2019-01-12T07:57:17.259Z] + cleanup
[task 2019-01-12T07:57:17.259Z] + local rv=1
[task 2019-01-12T07:57:17.259Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2019-01-12T07:57:17.259Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2019-01-12T07:57:17.261Z] + true
[task 2019-01-12T07:57:17.261Z] + cleanup_xvfb
[task 2019-01-12T07:57:17.261Z] pidof Xvfb
[task 2019-01-12T07:57:17.261Z] ++ pidof Xvfb
[task 2019-01-12T07:57:17.265Z] + local xvfb_pid=25
[task 2019-01-12T07:57:17.265Z] + local vnc=false
[task 2019-01-12T07:57:17.265Z] + local interactive=false
[task 2019-01-12T07:57:17.265Z] + '[' -n 25 ']'
[task 2019-01-12T07:57:17.265Z] + [[ false == false ]]
[task 2019-01-12T07:57:17.265Z] + [[ false == false ]]
[task 2019-01-12T07:57:17.275Z] + kill 25
[task 2019-01-12T07:57:17.276Z] + screen -XS xvfb quit
[task 2019-01-12T07:57:17.276Z] XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
[task 2019-01-12T07:57:17.276Z] after 1066 requests (1066 known processed) with 1 events remaining.
[task 2019-01-12T07:57:17.276Z] compizconfig - Info: Backend : ini
[task 2019-01-12T07:57:17.276Z] compizconfig - Info: Integration : true
[task 2019-01-12T07:57:17.276Z] compizconfig - Info: Profile : default
[task 2019-01-12T07:57:17.475Z] No screen session found.
[task 2019-01-12T07:57:17.475Z] + true
[task 2019-01-12T07:57:17.475Z] + exit 1
[taskcluster 2019-01-12 07:57:17.789Z] === Task Finished ===
[taskcluster 2019-01-12 07:57:25.323Z] Unsuccessful task run with exit code: 1 completed in 874.965 seconds

This is permanently failing. Geoffrey, can you please take a look. We should fix that asap. Thanks.

Flags: needinfo?(geoffers+mozilla)
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_basic | NoSuchWindowException: Unable to locate window: 16 → Perma tier2 testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_basic | NoSuchWindowException: Unable to locate window: 16

This started here: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=android%2C4.3%2Capi16%2B%2Copt%2Ctest-android-em-4.3-arm7-api-16%2Fopt-marionette-1%2C%28mn1%29&revision=0a9c477577dec9ab7b8f4bf6e424e1c19f4db256

There are 31 total failures in the last 7 days, all on android-em-4-3-armv7-api16 opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=221626381&repo=autoland&lineNumber=1614

task 2019-01-13T22:35:43.311Z] 22:35:43 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_basic
[task 2019-01-13T22:35:58.044Z] 22:35:58 WARNING - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_basic | NoSuchWindowException: Unable to locate window: 16
[task 2019-01-13T22:35:58.044Z] 22:35:58 INFO - stacktrace:
[task 2019-01-13T22:35:58.044Z] 22:35:58 INFO - WebDriverError@chrome://marionette/content/error.js:179:5
[task 2019-01-13T22:35:58.045Z] 22:35:58 INFO - NoSuchWindowError@chrome://marionette/content/error.js:411:5
[task 2019-01-13T22:35:58.045Z] 22:35:58 INFO - GeckoDriver.prototype.switchToWindow@chrome://marionette/content/driver.js:1527:11
[task 2019-01-13T22:35:58.045Z] 22:35:58 INFO - despatch@chrome://marionette/content/server.js:290:20
[task 2019-01-13T22:35:58.046Z] 22:35:58 INFO - execute@chrome://marionette/content/server.js:263:11
[task 2019-01-13T22:35:58.046Z] 22:35:58 INFO - onPacket/<@chrome://marionette/content/server.js:236:15
[task 2019-01-13T22:35:58.046Z] 22:35:58 INFO - onPacket@chrome://marionette/content/server.js:235:8
[task 2019-01-13T22:35:58.047Z] 22:35:58 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:493:9
[task 2019-01-13T22:35:58.047Z] 22:35:58 INFO - Traceback (most recent call last):
[task 2019-01-13T22:35:58.047Z] 22:35:58 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 190, in run
[task 2019-01-13T22:35:58.048Z] 22:35:58 INFO - self.tearDown()
[task 2019-01-13T22:35:58.048Z] 22:35:58 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py", line 28, in tearDown
[task 2019-01-13T22:35:58.048Z] 22:35:58 INFO - self.marionette.switch_to_window(self.original_window)
[task 2019-01-13T22:35:58.048Z] 22:35:58 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1522, in switch_to_window
[task 2019-01-13T22:35:58.049Z] 22:35:58 INFO - {"focus": focus, "name": window_id})
[task 2019-01-13T22:35:58.049Z] 22:35:58 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-01-13T22:35:58.050Z] 22:35:58 INFO - return func(*args, **kwargs)
[task 2019-01-13T22:35:58.050Z] 22:35:58 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 764, in _send_message
[task 2019-01-13T22:35:58.050Z] 22:35:58 INFO - self._handle_error(err)
[task 2019-01-13T22:35:58.051Z] 22:35:58 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 784, in _handle_error
[task 2019-01-13T22:35:58.051Z] 22:35:58 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2019-01-13T22:35:58.052Z] 22:35:58 INFO - TEST-INFO took 14733ms

Whiteboard: [stockwell needswork]

Here the trace log from Marionette which shows that there are problems in teardown:

https://taskcluster-artifacts.net/Or7nTvS1QPax3NDL0XV-Hw/0/public/test_info//logcat-emulator-5554.log

01-13 14:35:52.789 760 782 I Gecko : 1547418952790 Marionette DEBUG 24 -> [0,13,"reftest:teardown",{}]
01-13 14:35:52.799 760 782 I Gecko : 1547418952801 Marionette DEBUG 24 <- [1,13,null,{"value":null}]
01-13 14:35:52.829 760 782 E GeckoConsole: [JavaScript Error: "Error: Only supported in Firefox" {file: "chrome://marionette/content/error.js" line: 179}]
01-13 14:35:52.849 760 782 I Gecko : 1547418952854 Marionette DEBUG 24 -> [0,14,"reftest:teardown",{}]
01-13 14:35:52.859 760 782 I Gecko : 1547418952865 Marionette DEBUG 24 <- [1,14,{"error":"unsupported operation","message":"Called reftest:teardown before reftest:start","stacktrace":"WebDriverError@ ... et@chrome://marionette/content/server.js:235:8\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:493:9\n"},null]
01-13 14:35:52.899 760 782 I Gecko : 1547418952902 Marionette DEBUG 24 -> [0,15,"WebDriver:SwitchToWindow",{"focus":true,"name":"16"}]
01-13 14:35:52.909 760 782 I Gecko : 1547418952913 Marionette DEBUG 24 <- [1,15,{"error":"no such window","message":"Unable to locate window: 16","stacktrace":"WebDriverError@chrome://marionette/cont ... et@chrome://marionette/content/server.js:235:8\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:493:9\n"},null]

Blocks: 1510693
status-firefox65: --- → unaffected
status-firefox66: --- → affected
OS: Unspecified → Android

Very, very likely these are both symptoms of the same issue.

Status: NEW → RESOLVED
Closed: 6 years ago
Flags: needinfo?(geoffers+mozilla)
Resolution: --- → DUPLICATE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.