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

REOPENED
Unassigned

Status

defect
P5
normal
REOPENED
6 months ago
14 hours ago

People

(Reporter: intermittent-bug-filer, Unassigned)

Tracking

({intermittent-failure})

Version 3
mozilla67
All
Android
Points:
---

Firefox Tracking Flags

(firefox67 affected)

Details

(Whiteboard: [stockwel:needsowner])

Attachments

(1 attachment)

(Reporter)

Description

6 months ago
treeherder
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
Comment hidden (Intermittent Failures Robot)
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Last Resolved: 5 months 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 → ---
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)

Might be fixed when moving to the x86_64 emulator.

Depends on: 1500509
No longer depends on: 1500509
Comment hidden (Intermittent Failures Robot)

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.

Assignee: nobody → hskupin
Status: REOPENED → ASSIGNED
Priority: P5 → P1
Hardware: ARM → All

Comment 14

a month ago
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

Comment 15

a month ago
bugherder
Status: ASSIGNED → RESOLVED
Last Resolved: 5 months agoa month ago
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
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]
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)

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

Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.