Open Bug 1533084 Opened 7 months ago Updated 13 hours ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py TestScreenOrientation.test_set_orientation_portrait_secondary | TimeoutException: Timed out after 5.1 seconds

Categories

(Testing :: Marionette, defect, P5)

Version 3
ARM64
Android
defect

Tracking

(firefox68 fixed, firefox69 disabled)

Tracking Status
firefox68 --- fixed
firefox69 --- disabled

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(5 keywords, Whiteboard: [stockwell unknown])

Attachments

(1 file)

#[markdown(off)]
Filed by: ncsoregi [at] mozilla.com

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

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

[task 2019-03-06T17:17:33.256Z] 17:17:33 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py TestScreenOrientation.test_set_orientation_portrait_secondary
[task 2019-03-06T17:17:38.735Z] 17:17:38 WARNING - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py TestScreenOrientation.test_set_orientation_portrait_secondary | TimeoutException: Timed out after 5.1 seconds
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - Traceback (most recent call last):
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - testMethod()
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 33, in wrapper
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - return func(self, *args, **kwargs)
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/decorators.py", line 114, in skip_wrapper
[task 2019-03-06T17:17:38.735Z] 17:17:38 INFO - return test_item(self, *args, **kwargs)
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py", line 44, in test_set_orientation
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - self.wait_for_orientation(orientation)
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py", line 35, in wait_for_orientation
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - lambda _: self.marionette.orientation == orientation)
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/wait.py", line 154, in until
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - cause=last_exc)
[task 2019-03-06T17:17:38.736Z] 17:17:38 INFO - TEST-INFO took 5479ms

This started failing intermittently when we moved android marionette to the 7.0 x86_64 emulator.

Blocks: 1500509

Looks like the new orientation isn't accepted and it returns again to portrait-primary:

03-07 04:52:57.032 2642 2660 I Gecko : 1551934377032 Marionette DEBUG 673 -> [0,5,"Marionette:SetScreenOrientation",{"orientation":"portrait-secondary"}]
03-07 04:52:57.034 2642 2660 D GeckoScreenOrientation: locking to PORTRAIT_SECONDARY
03-07 04:52:57.189 2642 2660 D GeckoScreenOrientation: updating to new orientation PORTRAIT_SECONDARY
03-07 04:52:57.190 2642 2642 D GeckoScreenOrientation: updating to new orientation PORTRAIT_PRIMARY
03-07 04:52:57.199 2642 2660 I Gecko : 1551934377199 Marionette DEBUG 673 <- [1,5,null,{"value":null}]
03-07 04:52:57.214 2642 2660 I Gecko : 1551934377214 Marionette DEBUG 673 -> [0,6,"Marionette:GetScreenOrientation",{}]
03-07 04:52:57.220 1535 1578 I InputReader: Reconfiguring input devices. changes=0x00000004
03-07 04:52:57.220 1535 1578 I InputReader: Device reconfigured: id=0, name='qwerty2', size 800x1280, orientation 2, mode 1, display id 0
03-07 04:52:57.231 2642 2660 I Gecko : 1551934377231 Marionette DEBUG 673 <- [1,6,null,{"value":"portrait-primary"}]

Jan, do you have an idea?

Flags: needinfo?(jh+bugzilla)

Without the debug logging that gbrown added temporarily for one of those try runs it's hard to say.

Flags: needinfo?(jh+bugzilla)

Hm not sure what that was. Geoff, could you please do the same? Looks like that we might hit this issue on try.

Flags: needinfo?(gbrown)

I think I have the logging here and am trying to reproduce this failure:

https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=2081701d0292f351632c2d73eb9addaf8111bbda

Flags: needinfo?(gbrown)

There is another request to switch back to portrait-primary, which is not initiated by Marionette:

03-08 16:44:57.510 2422 2444 I Gecko : 1552063497510 Marionette DEBUG 673 -> [0,5,"Marionette:SetScreenOrientation",{"orientation":"portrait-secondary"}]
03-08 16:44:57.510 2422 2444 D GeckoScreenOrientation: locking to PORTRAIT_SECONDARY
03-08 16:44:57.600 1315 1357 I InputReader: Reconfiguring input devices. changes=0x00000004
03-08 16:44:57.600 1315 1357 I InputReader: Device reconfigured: id=0, name='qwerty2', size 800x1280, orientation 2, mode 1, display id 0
03-08 16:44:57.600 2422 2444 D GeckoScreenOrientation: request for new orientation PORTRAIT_SECONDARY
03-08 16:44:57.600 2422 2444 D GeckoScreenOrientation: updating to new orientation PORTRAIT_SECONDARY
03-08 16:44:57.610 2422 2444 W System.err: java.lang.Exception
03-08 16:44:57.610 2422 2444 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.update(GeckoScreenOrientation.java:167)
03-08 16:44:57.610 2422 2444 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.lock(GeckoScreenOrientation.java:254)
03-08 16:44:57.610 2422 2444 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.lock(GeckoScreenOrientation.java:236)
03-08 16:44:57.610 2422 2444 W System.err: at org.mozilla.gecko.GeckoAppShell.lockScreenOrientation(GeckoAppShell.java:1697)
03-08 16:44:57.610 2422 2444 W System.err: at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
03-08 16:44:57.610 2422 2444 W System.err: at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:474)
03-08 16:44:57.610 2422 2444 D GeckoScreenOrientation: update complete for PORTRAIT_SECONDARY
03-08 16:44:57.610 2422 2422 D GeckoScreenOrientation: request for new orientation PORTRAIT_PRIMARY
03-08 16:44:57.610 2422 2422 D GeckoScreenOrientation: updating to new orientation PORTRAIT_PRIMARY
03-08 16:44:57.610 2422 2422 W System.err: java.lang.Exception
03-08 16:44:57.610 2422 2422 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.update(GeckoScreenOrientation.java:167)
03-08 16:44:57.610 2422 2422 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.update(GeckoScreenOrientation.java:143)
03-08 16:44:57.610 2422 2422 W System.err: at org.mozilla.geckoview.GeckoRuntime.orientationChanged(GeckoRuntime.java:447)
03-08 16:44:57.610 2422 2422 W System.err: at org.mozilla.geckoview.GeckoView.onConfigurationChanged(GeckoView.java:468)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.View.dispatchConfigurationChanged(View.java:10418)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1311)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewRootImpl.updateConfiguration(ViewRootImpl.java:3337)
03-08 16:44:57.610 2422 2422 W System.err: at android.view.ViewRootImpl$ViewRootHandler.handleMessage(ViewRootImpl.java:3494)
03-08 16:44:57.610 2422 2422 W System.err: at android.os.Handler.dispatchMessage(Handler.java:102)
03-08 16:44:57.610 2422 2422 W System.err: at android.os.Looper.loop(Looper.java:154)
03-08 16:44:57.610 2422 2422 W System.err: at android.app.ActivityThread.main(ActivityThread.java:6077)
03-08 16:44:57.610 2422 2422 W System.err: at java.lang.reflect.Method.invoke(Native Method)
03-08 16:44:57.610 2422 2422 W System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
03-08 16:44:57.610 2422 2422 W System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
03-08 16:44:57.620 2422 2422 D GeckoScreenOrientation: update complete for PORTRAIT_PRIMARY
03-08 16:44:57.630 2422 2444 I Gecko : 1552063497630 Marionette DEBUG 673 <- [1,5,null,{"value":null}]
03-08 16:44:57.630 2422 2444 I Gecko : 1552063497630 Marionette DEBUG 673 -> [0,6,"Marionette:GetScreenOrientation",{}]
03-08 16:44:57.630 2422 2444 I Gecko : 1552063497630 Marionette DEBUG 673 <- [1,6,null,{"value":"portrait-primary"}]

Flags: needinfo?(jh+bugzilla)

Is that failure the result of bug 1527959?

Yes, seems like it. Sorry for the lack of progress there, but I haven't had much time for actual coding recently.

Flags: needinfo?(jh+bugzilla)

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

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

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

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

Where do you see 44 failures? Latest intermittent comment only states 17 failures.

Flags: needinfo?(dluca)
Keywords: mobile
OS: Unspecified → Android
Hardware: Unspecified → ARM64
Flags: needinfo?(dluca) → needinfo?(hskupin)

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 bug is not related to bug 1545308.

Flags: needinfo?(gbrown)

There are 32 total failures in the last 7 day on android-em-7-0-x86_64: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-24&endday=2019-05-01&tree=trunk&bug=1533084

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=243832333&repo=mozilla-inbound&lineNumber=2869

[task 2019-05-01T05:33:41.890Z] 05:33:41 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py TestScreenOrientation.test_set_orientation_portrait_secondary
[task 2019-05-01T05:33:48.466Z] 05:33:48 WARNING - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py TestScreenOrientation.test_set_orientation_portrait_secondary | TimeoutException: Timed out after 5.0 seconds
[task 2019-05-01T05:33:48.466Z] 05:33:48 INFO - Traceback (most recent call last):
[task 2019-05-01T05:33:48.467Z] 05:33:48 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-01T05:33:48.467Z] 05:33:48 INFO - testMethod()
[task 2019-05-01T05:33:48.468Z] 05:33:48 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 33, in wrapper
[task 2019-05-01T05:33:48.468Z] 05:33:48 INFO - return func(self, *args, **kwargs)
[task 2019-05-01T05:33:48.469Z] 05:33:48 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/decorators.py", line 114, in skip_wrapper
[task 2019-05-01T05:33:48.469Z] 05:33:48 INFO - return test_item(self, *args, **kwargs)
[task 2019-05-01T05:33:48.469Z] 05:33:48 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py", line 44, in test_set_orientation
[task 2019-05-01T05:33:48.470Z] 05:33:48 INFO - self.wait_for_orientation(orientation)
[task 2019-05-01T05:33:48.470Z] 05:33:48 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py", line 35, in wait_for_orientation
[task 2019-05-01T05:33:48.471Z] 05:33:48 INFO - lambda _: self.marionette.orientation == orientation)
[task 2019-05-01T05:33:48.471Z] 05:33:48 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/wait.py", line 154, in until
[task 2019-05-01T05:33:48.471Z] 05:33:48 INFO - cause=last_exc)
[task 2019-05-01T05:33:48.471Z] 05:33:48 INFO - TEST-INFO took 6585ms

David, could you please assign this to someone?

Flags: needinfo?(dburns)
Whiteboard: [stockwell needswork:owner]

There has been a significant drop in the intermittence rate with no changes on our end so think that it could be related to bug 1545308

Flags: needinfo?(dburns)

Yes, I also assume so. Right now no more failures since 24h ago. Lets wait until Monday before closing this bug.

Depends on: 1545308

(In reply to Jan Henning [:JanH] (away in June) from comment #11)

Yes, seems like it. Sorry for the lack of progress there, but I haven't had much time for actual coding recently.

Looks like Jan isn't around in June. Which means if the number of failures stays high, we might have to disable this test. Jan, when you returned maybe you could let us know when you think that you can work on bug 1527959 (or at all).

Depends on: 1527959
Flags: needinfo?(jh+bugzilla)

Sorry for not making much progress there - given the announcement of the Fennec EOL, I had hoped we might be able to muddle through until that time to avoid the complication of keeping the old implementation around, too, for API16 compatibility. "That time", i.e. the removal of the Fennec code from mozilla-central is only scheduled for 71, though, so still a little while away.

Thanks for the update! So I would suggest that we skip this test for Fennec only. We don't have the Marionette tests running for other browsers on Android, but once we do the test should be running immediately.

Turns out that with the Marionette specific parameterized decorator we cannot simply skip a single platform. As such I have to completely comment out the following line:

https://searchfox.org/mozilla-central/rev/f8b11433159cbc9cc80500b3e579d767473fa539/testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py#41

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3c51580b01ad
[marionette] Skip test_set_orientation_portrait_secondary on Android for Fennec failures. r=webdriver-reviewers,ato
Flags: needinfo?(jh+bugzilla)
Whiteboard: [stockwell unknown] → [stockwell unknown][checkin-needed-beta]
Whiteboard: [stockwell unknown][checkin-needed-beta] → [stockwell unknown]
You need to log in before you can comment on or make changes to this bug.