Closed Bug 1499082 Opened 5 years ago Closed 4 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change | AssertionError: 1 != 0

Categories

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

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

Tracking

(firefox67 wontfix, firefox68 fixed, firefox69 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla69
Tracking Flags:
Tracking Status
firefox67 --- wontfix
firefox68 --- fixed
firefox69 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

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

Attachments

(1 file)

Bug 1499082 - [marionette] Fix focus handling on Android for newly opened tab. r=ato
47 bytes, text/x-phabricator-request
Details | Review 
Filed by: ebalazs [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=205506492&repo=try

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

TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change
[task 2018-10-15T12:20:41.145Z] 12:20:41  WARNING -  TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change | AssertionError: 1 != 0
[task 2018-10-15T12:20:41.147Z] 12:20:41     INFO -  Traceback (most recent call last):
[task 2018-10-15T12:20:41.148Z] 12:20:41     INFO -    File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-10-15T12:20:41.148Z] 12:20:41     INFO -      testMethod()
[task 2018-10-15T12:20:41.149Z] 12:20:41     INFO -    File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py", line 102, in test_switch_tabs_with_focus_change
[task 2018-10-15T12:20:41.150Z] 12:20:41     INFO -      self.assertEqual(self.get_selected_tab_index(), self.selected_tab_index)
[task 2018-10-15T12:20:41.150Z] 12:20:41     INFO -  TEST-INFO took 8078ms
[task 2018-10-15T12:20:42.229Z] 12:20:42     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_without_focus_change
[task 2018-10-15T12:20:49.090Z] 12:20:49     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_without_focus_change | took 6861ms
[task 2018-10-15T12:20:49.298Z] 12:20:49     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_to_new_private_browsing_window_has_to_register_browsers
[task 2018-10-15T12:20:51.779Z] 12:20:51     INFO -  TEST-SKIP | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_to_new_private_browsing_window_has_to_register_browsers | took 2482ms
[task 2018-10-15T12:20:52.438Z] 12:20:52     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicit_wait_reaches_timeout
[task 2018-10-15T12:20:57.888Z] 12:20:57     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicit_wait_reaches_timeout | took 5450ms
[task 2018-10-15T12:20:58.095Z] 12:20:58     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicitly_wait_for_single_element
[task 2018-10-15T12:21:03.539Z] 12:21:03     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicitly_wait_for_single_element | took 5444ms
[task 2018-10-15T12:21:03.953Z] 12:21:03     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_teardown_context_preserved.py TestTearDownContext.test_skipped_teardown_ok
[task 2018-10-15T12:21:04.564Z] 12:21:04     INFO -  TEST-SKIP | testing/marionette/harness/marionette_harness/tests/unit/test_teardown_context_preserved.py TestTearDownContext.test_skipped_teardown_ok | took 612ms
[task 2018-10-15T12:21:05.048Z] 12:21:05     INFO -  SUMMARY
[task 2018-10-15T12:21:05.050Z] 12:21:05     INFO -  -------
[task 2018-10-15T12:21:05.050Z] 12:21:05     INFO -  passed: 18
[task 2018-10-15T12:21:05.050Z] 12:21:05  WARNING -  failed: 1
[task 2018-10-15T12:21:05.050Z] 12:21:05  WARNING -  One or more unittests failed.
[task 2018-10-15T12:21:05.051Z] 12:21:05     INFO -  todo: 40 (skipped: 2)
[task 2018-10-15T12:21:05.051Z] 12:21:05     INFO -  FAILED TESTS
[task 2018-10-15T12:21:05.051Z] 12:21:05     INFO -  -------
[task 2018-10-15T12:21:05.051Z] 12:21:05     INFO -  test_switch_window_content.py test_switch_window_content.TestSwitchToWindowContent.test_switch_tabs_with_focus_change
[task 2018-10-15T12:21:05.258Z] 12:21:05     INFO -  SUITE-END | took 141s
[task 2018-10-15T12:21:09.197Z] 12:21:09    ERROR - Return code: 10
[task 2018-10-15T12:21:09.198Z] 12:21:09     INFO - TinderboxPrint: marionette<br/>18/<em class="testfail">1</em>/40
[task 2018-10-15T12:21:09.198Z] 12:21:09     INFO - ##### marionette log ends
[task 2018-10-15T12:21:09.198Z] 12:21:09  WARNING - # TBPL WARNING #
[task 2018-10-15T12:21:09.198Z] 12:21:09  WARNING - setting return code to 1
[task 2018-10-15T12:21:09.199Z] 12:21:09  WARNING - The marionette suite: marionette ran with return status: WARNING
[task 2018-10-15T12:21:09.199Z] 12:21:09     INFO - Running post-action listener: _package_coverage_data
[task 2018-10-15T12:21:09.199Z] 12:21:09     INFO - Running post-action listener: _resource_record_post_action
[task 2018-10-15T12:21:09.199Z] 12:21:09     INFO - Running post-action listener: process_java_coverage_data
[task 2018-10-15T12:21:09.199Z] 12:21:09     INFO - Running post-action listener: stop_device
[task 2018-10-15T12:21:09.200Z] 12:21:09     INFO - Killing logcat pid 1072.
[task 2018-10-15T12:21:09.200Z] 12:21:09     INFO - Killing every process called emulator64-arm
[task 2018-10-15T12:21:09.209Z] 12:21:09     INFO - Killing pid 440.
[task 2018-10-15T12:21:09.209Z] 12:21:09     INFO - [mozharness: 2018-10-15 12:21:09.209643Z] Finished run-tests step (success)
[task 2018-10-15T12:21:09.210Z] 12:21:09     INFO - Running post-run listener: _resource_record_post_run
[task 2018-10-15T12:21:09.265Z] 12:21:09     INFO - Total resource usage - Wall time: 285s; CPU: 36.0%; Read bytes: 14024704; Write bytes: 643928064; Read time: 368; Write time: 86012
[task 2018-10-15T12:21:09.267Z] 12:21:09     INFO - TinderboxPrint: CPU usage<br/>36.5%
[task 2018-10-15T12:21:09.267Z] 12:21:09     INFO - TinderboxPrint: I/O read bytes / time<br/>14,024,704 / 368
[task 2018-10-15T12:21:09.267Z] 12:21:09     INFO - TinderboxPrint: I/O write bytes / time<br/>643,928,064 / 86,012
[task 2018-10-15T12:21:09.267Z] 12:21:09     INFO - TinderboxPrint: CPU idle<br/>713.8 (63.3%)
[task 2018-10-15T12:21:09.267Z] 12:21:09     INFO - TinderboxPrint: CPU user<br/>404.4 (35.8%)
[task 2018-10-15T12:21:09.267Z] 12:21:09     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2018-10-15T12:21:09.268Z] 12:21:09     INFO - verify-device - Wall time: 5s; CPU: 4.0%; Read bytes: 0; Write bytes: 1753088; Read time: 0; Write time: 0
[task 2018-10-15T12:21:09.269Z] 12:21:09     INFO - install - Wall time: 37s; CPU: 25.0%; Read bytes: 1748992; Write bytes: 197177344; Read time: 20; Write time: 47644
[task 2018-10-15T12:21:09.273Z] 12:21:09     INFO - run-tests - Wall time: 244s; CPU: 39.0%; Read bytes: 12275712; Write bytes: 444956672; Read time: 348; Write time: 38368
[task 2018-10-15T12:21:09.355Z] 12:21:09     INFO - Running post-run listener: copy_logs_to_upload_dir
[task 2018-10-15T12:21:09.356Z] 12:21:09     INFO - Copying logs to upload dir...
[task 2018-10-15T12:21:09.356Z] 12:21:09     INFO - mkdir: /builds/worker/workspace/build/upload/logs
[task 2018-10-15T12:21:09.358Z] 12:21:09     INFO - Copying logs to upload dir...
[task 2018-10-15T12:21:09.360Z] 12:21:09  WARNING - returning nonzero exit status 1
[task 2018-10-15T12:21:09.382Z] cleanup
[task 2018-10-15T12:21:09.382Z] + cleanup
[task 2018-10-15T12:21:09.382Z] + local rv=1
[task 2018-10-15T12:21:09.382Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2018-10-15T12:21:09.382Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2018-10-15T12:21:09.384Z] + true
[task 2018-10-15T12:21:09.384Z] + cleanup_xvfb
[task 2018-10-15T12:21:09.384Z] pidof Xvfb
[task 2018-10-15T12:21:09.384Z] ++ pidof Xvfb
[task 2018-10-15T12:21:09.387Z] + local xvfb_pid=25
[task 2018-10-15T12:21:09.387Z] + local vnc=false
[task 2018-10-15T12:21:09.391Z] + local interactive=false
[task 2018-10-15T12:21:09.391Z] + '[' -n 25 ']'
[task 2018-10-15T12:21:09.391Z] + [[ false == false ]]
[task 2018-10-15T12:21:09.391Z] + [[ false == false ]]
[task 2018-10-15T12:21:09.392Z] + kill 25
[task 2018-10-15T12:21:09.392Z] + screen -XS xvfb quit
[task 2018-10-15T12:21:09.397Z] XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":0"
[task 2018-10-15T12:21:09.397Z]       after 1087 requests (1087 known processed) with 0 events remaining.
[task 2018-10-15T12:21:09.397Z] compizconfig - Info: Backend     : ini
[task 2018-10-15T12:21:09.397Z] compizconfig - Info: Integration : true
[task 2018-10-15T12:21:09.397Z] compizconfig - Info: Profile     : default
[task 2018-10-15T12:21:09.554Z] No screen session found.
[task 2018-10-15T12:21:09.554Z] + true
[task 2018-10-15T12:21:09.555Z] + exit 1
[taskcluster 2018-10-15 12:21:09.850Z] === Task Finished ===
[taskcluster 2018-10-15 12:21:17.083Z] Unsuccessful task run with exit code: 1 completed in 398.835 seconds
OS: Unspecified → Android
Hardware: Unspecified → ARM
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=221587814&repo=try&lineNumber=1642
[task 2019-01-13T13:14:26.001Z] 13:14:26 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change
[task 2019-01-13T13:14:32.127Z] 13:14:32 WARNING - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change | AssertionError: 1 != 0
[task 2019-01-13T13:14:32.127Z] 13:14:32 INFO - Traceback (most recent call last):
[task 2019-01-13T13:14:32.128Z] 13:14:32 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-01-13T13:14:32.128Z] 13:14:32 INFO - testMethod()
[task 2019-01-13T13:14:32.129Z] 13:14:32 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py", line 79, in test_switch_tabs_with_focus_change
[task 2019-01-13T13:14:32.130Z] 13:14:32 INFO - self.assertEqual(self.get_selected_tab_index(), self.selected_tab_index)
[task 2019-01-13T13:14:32.130Z] 13:14:32 INFO - TEST-INFO took 6128ms
[task 2019-01-13T13:14:33.658Z] 13:14:33 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_without_focus_change
[task 2019-01-13T13:14:38.109Z] 13:14:38 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_without_focus_change | took 4451ms
[task 2019-01-13T13:14:38.318Z] 13:14:38 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_to_new_private_browsing_tab
[task 2019-01-13T13:14:48.013Z] 13:14:48 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_to_new_private_browsing_tab | took 9695ms
[task 2019-01-13T13:14:48.430Z] 13:14:48 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicit_wait_reaches_timeout
[task 2019-01-13T13:14:55.660Z] 13:14:55 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicit_wait_reaches_timeout | took 7230ms
[task 2019-01-13T13:14:55.869Z] 13:14:55 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicitly_wait_for_single_element
[task 2019-01-13T13:15:00.559Z] 13:15:00 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_implicit_waits.py TestImplicitWaits.test_implicitly_wait_for_single_element | took 4690ms
[task 2019-01-13T13:15:00.977Z] 13:15:00 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_teardown_context_preserved.py TestTearDownContext.test_skipped_teardown_ok
[task 2019-01-13T13:15:01.594Z] 13:15:01 INFO - TEST-SKIP | testing/marionette/harness/marionette_harness/tests/unit/test_teardown_context_preserved.py TestTearDownContext.test_skipped_teardown_ok | took 617ms
[task 2019-01-13T13:15:02.085Z] 13:15:02 INFO - SUMMARY
[task 2019-01-13T13:15:02.086Z] 13:15:02 INFO - -------
[task 2019-01-13T13:15:02.086Z] 13:15:02 INFO - passed: 19
[task 2019-01-13T13:15:02.086Z] 13:15:02 WARNING - failed: 1
[task 2019-01-13T13:15:02.086Z] 13:15:02 WARNING - One or more unittests failed.
[task 2019-01-13T13:15:02.086Z] 13:15:02 INFO - todo: 35 (skipped: 1)
[task 2019-01-13T13:15:02.086Z] 13:15:02 INFO - FAILED TESTS
[task 2019-01-13T13:15:02.086Z] 13:15:02 INFO - -------
[task 2019-01-13T13:15:02.086Z] 13:15:02 INFO - test_switch_window_content.py test_switch_window_content.TestSwitchToWindowContent.test_switch_tabs_with_focus_change
[task 2019-01-13T13:15:02.293Z] 13:15:02 INFO - SUITE-END | took 161s
[task 2019-01-13T13:15:06.679Z] 13:15:06 ERROR - Return code: 10
[task 2019-01-13T13:15:06.680Z] 13:15:06 INFO - TinderboxPrint: marionette<br/>19/<em class="testfail">1</em>/35
[task 2019-01-13T13:15:06.680Z] 13:15:06 INFO - ##### marionette log ends
[task 2019-01-13T13:15:06.680Z] 13:15:06 WARNING - # TBPL WARNING #

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Might be fixed when moving to the x86_64 emulator.

Depends on: 1500509
No longer depends on: 1500509
Depends on: 1533079

Switching to the x86_64 emulator actually increased the volume of failures for opt builds. As it looks like in some cases we return too early:

03-09 22:44:18.190 2435 2451 I Gecko : 1552171458190 Marionette DEBUG 584 -> [0,14,"WebDriver:NewWindow",{"type":"tab","focus":true}]
03-09 22:44:18.220 2435 2451 I Gecko : 1552171458220 Marionette TRACE [861] Frame script loaded
03-09 22:44:18.220 2435 2451 I Gecko : 1552171458220 Marionette TRACE [861] Frame script registered
03-09 22:44:18.220 2435 2435 D GeckoToolbar: onTabChanged: ADDED
03-09 22:44:18.220 2435 2435 D GeckoBrowserApp: BrowserApp.onTabChanged: 52: ADDED
03-09 22:44:18.230 2435 2451 D GeckoScreenOrientation: unlocking
03-09 22:44:18.230 2435 2451 I Gecko : 1552171458230 Marionette TRACE Received DOM event TabOpen for [object XULFrameElement]
03-09 22:44:18.230 2435 2451 D GeckoViewAutoFill: Clearing auto-fill
03-09 22:44:18.230 2435 2451 W GeckoEventDispatcher: No listener for Website:AppLeft
03-09 22:44:18.230 2435 2451 I Gecko : 1552171458230 Marionette DEBUG 584 <- [1,14,null,{"handle":"861","type":"tab"}]
03-09 22:44:18.240 2435 2451 I Gecko : 1552171458240 Marionette DEBUG 584 -> [0,15,"WebDriver:GetWindowHandles",{}]
03-09 22:44:18.240 2435 2451 I Gecko : 1552171458240 Marionette DEBUG 584 <- [1,15,null,["595","861"]]
03-09 22:44:18.240 2435 2435 D GeckoToolbar: onTabChanged: SELECTED
03-09 22:44:18.240 2435 2435 D GeckoBrowserApp: BrowserApp.onTabChanged: 52: SELECTED
03-09 22:44:18.240 2435 2435 D GeckoToolbar: onTabChanged: UNSELECTED
03-09 22:44:18.240 2435 2435 D GeckoBrowserApp: BrowserApp.onTabChanged: 33: UNSELECTED

For opening a tab we call BrowserApp.addTab(null, {selected: focus}). As it looks like this method doesn't wait until the new tab has the focus, but returns earlier. As such we might have to wait for a focus event for that tab.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0d3c3fcd2e9f8a522b01bb56e91d1ac104bb8896

Assignee: nobody → hskupin
Status: REOPENED → ASSIGNED
status-firefox67: --- → affected
Priority: P5 → P1
Hardware: ARM → All
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d57870ac257d
[marionette] Fix focus handling on Android for newly opened tab. r=ato

https://hg.mozilla.org/mozilla-central/rev/d57870ac257d

Status: ASSIGNED → RESOLVED
Closed: 5 years ago → 5 years ago
status-firefox67: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla67

Lets reopen this bug. I hope that the number of failures has been decreased a lot so that this intermittent failure doesn't happen that often anymore. I won't have the time to further work on it in the next weeks.

Assignee: hskupin → nobody
Status: RESOLVED → REOPENED
status-firefox67: fixed → affected
Flags: needinfo?(hskupin)
Priority: P1 → P5
Resolution: FIXED → ---

There are 27 total failures in the last 7 days

Since the patch here landed, there have been 8 occurences.

Recent occurences here seem to have started with https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=a83c218cd961857e02be7bac0ff9c971b026c4ce on the 6th of March.

Henrik, is there anything you would like us to look into?

Whiteboard: [stockwel:needsowner]

This bug has failed 42 times in the last 7 days. Occurs on android-em-7-0-x86_64 opt and debug builds.

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

(In reply to Dorel Luca [:dluca] from comment #24)

This bug has failed 42 times in the last 7 days. Occurs on android-em-7-0-x86_64 opt and debug builds.

Latest Intermittent comment states 19 failures in the last 7 days. How did you get to the 42 failures?

status-firefox68: --- → affected
Flags: needinfo?(dluca)
Keywords: mobile
Target Milestone: mozilla67 → ---

At the time I looked in orange factor and used the last 7 days time range.

Here is a link of that time range, where it shows it has over 50 hits:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-11&endday=2019-04-18&tree=all&bug=1499082

Flags: needinfo?(dluca) → needinfo?(hskupin)

(In reply to Dorel Luca [:dluca] from comment #27)

At the time I looked in orange factor and used the last 7 days time range.

Here is a link of that time range, where it shows it has over 50 hits:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-11&endday=2019-04-18&tree=all&bug=1499082

Indeed. Maybe put this link into your comment, and not only a recent log. This would help. Thanks.

Geoff, I assume that this bug might also be affected by the slowdown of machines via packet.net (bug 1545308). The failure rate increased a lot over the last two weeks. Could you please verify?

Flags: needinfo?(hskupin) → needinfo?(gbrown)

Based on performance logs from the last few days, this is not related to bug 1545308.

Flags: needinfo?(gbrown)

(In reply to Geoff Brown [:gbrown] (pto April 26-29) from comment #29)

Based on performance logs from the last few days, this is not related to bug 1545308.

But since Chris worked on bug 1545308 the number of failures here got way better. There was no failure reported yesterday! I will re-check this bug mid of the week.

In the last 7 days, there have been 48 failures.

The failures are on android-em-7-0-x86_64 platform, opt build type.

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=245309675&repo=autoland&lineNumber=2515

And the relevant part of the log:
[task 2019-05-08T11:39:25.556Z] 11:39:25 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change
[task 2019-05-08T11:39:25.935Z] 11:39:25 WARNING - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py TestSwitchToWindowContent.test_switch_tabs_with_focus_change | AssertionError: 1 != 0
[task 2019-05-08T11:39:25.936Z] 11:39:25 INFO - Traceback (most recent call last):
[task 2019-05-08T11:39:25.936Z] 11:39:25 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-05-08T11:39:25.937Z] 11:39:25 INFO - testMethod()
[task 2019-05-08T11:39:25.937Z] 11:39:25 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py", line 79, in test_switch_tabs_with_focus_change
[task 2019-05-08T11:39:25.937Z] 11:39:25 INFO - self.assertEqual(self.get_selected_tab_index(), self.selected_tab_index)
[task 2019-05-08T11:39:25.937Z] 11:39:25 INFO - TEST-INFO took 379ms

OF link: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-08&endday=2019-05-08&tree=trunk&bug=1499082

Henrik, could you please take a look at this?
Thank you!

Flags: needinfo?(hskupin)
Whiteboard: [stockwel:needsowner] → [stockwell needswork:owner]

This bug failed 41 times in the last 7 days. Occurs on android-em-7-0-x86_64 on opt build types.

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

Sorry, but I still won't have the time to further investigate this bug over the next few weeks. Maybe David has a slot and could check why we still return too early in the "WebDriver:SwitchToWindow" command. Otherwise we might want to disable this test for the time being.

Flags: needinfo?(hskupin) → needinfo?(dburns)

I can now replicate this problem locally but only with the x86_64 emulator. The test still just works fine for my ARM Android device.

As it looks like a delay of about 450ms helps to make the test pass. This is actually a really long time for switching to a new tab. But maybe this is still the emulator, and it won't happen on a real device.

I will. have a look into that problem.

Assignee: nobody → hskupin
Status: REOPENED → ASSIGNED
Flags: needinfo?(dburns)
Priority: P5 → P1

Ok, so this basically happens because switchToWindow doesn't wait for the focus and activate events. It means this failure will be gone once bug 1335085 has been fixed.

status-firefox67: affected → wontfix
status-firefox69: --- → affected
Depends on: 1335085

With bug 1335085 fixed this seems to be fixed now too.

Status: ASSIGNED → RESOLVED
Closed: 5 years ago → 4 years ago
status-firefox69: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla69
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.