1104624 - Tests are failing when trying to switch frame with MarionetteException: Frame not responding, switching to root frame

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::UI Tests, defect)

Description

[Viorela Ioia [:viorela]]

There are some tests failing intermittently on b2g-inbound while executing self.marionette.switch_to_frame(): http://jenkins1.qa.scl3.mozilla.com/job/flame-kk-319.b2g-inbound.ui.functional.smoke/1356/HTML_Report/
I was able to reproduce the failure locally, by running one of those automated tests (test_add_photo_to_contact.py).
Reproduction rate: 2/10
The issue is not reproducible manually.

TEST-UNEXPECTED-ERROR | test_add_photo_to_contact.py TestContacts.test_add_photo_from_gallery_to_contact | MarionetteException: MarionetteException: Frame not responding (app://gallery.gaiamobile.org/manifest.webapp), switching to root frame

Traceback (most recent call last):
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/.env/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette_test.py", line 264, in run
testMethod()
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/tests/python/gaia-ui-tests/gaiatest/tests/functional/contacts/test_add_photo_to_contact.py", line 51, in test_add_photo_from_gallery_to_contact
image.tap_crop_done()
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/tests/python/gaia-ui-tests/gaiatest/apps/gallery/regions/crop_view.py", line 23, in tap_crop_done
self.wait_for_condition(lambda m: self.apps.displayed_app.src != self._src)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/tests/python/gaia-ui-tests/gaiatest/apps/base.py", line 56, in wait_for_condition
Wait(self.marionette, timeout).until(method, message=message)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/.env/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/wait.py", line 122, in until
rv = condition(self.marionette)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/tests/python/gaia-ui-tests/gaiatest/apps/gallery/regions/crop_view.py", line 23, in <lambda>
self.wait_for_condition(lambda m: self.apps.displayed_app.src != self._src)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/tests/python/gaia-ui-tests/gaiatest/gaia_test.py", line 79, in displayed_app
self.marionette.switch_to_frame()
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/.env/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette.py", line 987, in switch_to_frame
response = self._send_message('switchToFrame', 'ok', id=frame, focus=focus)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/.env/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/decorators.py", line 35, in _
return func(*args, **kwargs)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/.env/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette.py", line 638, in _send_message
self._handle_error(response)
File "/var/jenkins/1/workspace/flame-kk-319.b2g-inbound.ui.functional.smoke/.env/local/lib/python2.7/site-packages/marionette_client-0.8.4-py2.7.egg/marionette/marionette.py", line 712, in _handle_error
raise errors.MarionetteException(message=message, status=status, stacktrace=stacktrace)
MarionetteException: MarionetteException: Frame not responding (app://gallery.gaiamobile.org/manifest.webapp), switching to root frame

Regression range, based on mozilla-inbound:
Last working:
Gaia-Rev        3b4c64b5a05d106568dae3f88d38bdbb3d5bc29e
Gecko-Rev       https://hg.mozilla.org/integration/mozilla-inbound/rev/252b954764ee
Build-ID        20141124060745
Version         36.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20141124.092916
FW-Date         Mon Nov 24 09:29:27 EST 2014
Bootloader      L1TC10011880


First failing:
Gaia-Rev        3b4c64b5a05d106568dae3f88d38bdbb3d5bc29e
Gecko-Rev       https://hg.mozilla.org/integration/mozilla-inbound/rev/5671737e4f24
Build-ID        20141124061445
Version         36.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20141124.093133
FW-Date         Mon Nov 24 09:31:44 EST 2014
Bootloader      L1TC10011880

Gaia changes: None

Gecko changes: https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=252b954764ee&tochange=5671737e4f24

Comment 1

[Viorela Ioia [:viorela]]

It looks like commit https://hg.mozilla.org/integration/mozilla-inbound/rev/5671737e4f24 caused this failure. Rwood, can you please take a look? Thanks!

Comment 2

[Robert Wood [:rwood]]

I'll take a look.

Comment 3

[Robert Wood [:rwood]]

Looks like the OOP frame heartbeart is timing out sometimes when grabbing the currently displayed app (self.apps.displayed_app), which switches to the system app then back to the current app. Investigating...

Comment 4

[Robert Wood [:rwood]]

Got to the bottom of this one.

Contacts app launched, OOP frame heartbeat starts (pinging contacts app)
Inside edit contacts, edit picture is clicked, "select from" system dialog appears
Switches to system frame, OOP frame heartbeat stops
Gallery is selected in "Select from" dialog, gallery app starts and becomes the displayed app
Switch to frame into gallery app, OOP frame heartbeat starts (pinging gallery app)
Image thumbnail is tapped, 'crop' screen appears, 'Done' button becomes enabled
'Done' button tapped; gallery app closed; returns to contacts app (edit contacts)
Switch to system frame, so we can grab the apps.displayed_app, to verify we have returned to contacts

-- Most times --
The most recent OOP frame heartbeat gallery ping is received before the gallery app is closed. Then when we switch to system frame, the OOP frame heartbeat monitor is turned off (stops pinging gallery). Test continues as usual and passes

-- Intermittently --
The OOP frame heartbeat gallery ping is sent just slightly right at the moment or just after the gallery app is closed (but before the switch to system frame); resulting in an error sending the ping, and ultimately the OOP frame heartbeat marionette exception.

Solution in the works...

Comment 5

[Robert Wood [:rwood]]

Definitely a timing issue. When trying to reproduce this locally (with the latest central builds): on device (flame-kk 319MB) out of 500 test runs (test_add_photo_to_contact.py), the intermittent failure occurred only once. On the b2g-destkop, I couldn't get it to reproduce at all (0/500). On the b2g-emulator, the failure happened the very first run, and every time after that (15/15). Adding debug code and running on the emulator, to be certain what the problem is.

Comment 6

[Robert Wood [:rwood]]

I/Gecko   ( 2369): 1418161815986 Marionette: emitting Touch event of type touchstart to element with id: crop-done-button and tag name: BUTTON at coordinates (294, 25) relative to the viewport
I/Gecko   ( 2369): 1418161815997 Marionette: emitting Touch event of type touchend to element with id: crop-done-button and tag name: BUTTON at coordinates (294, 25) relative to the viewport
I/Gecko   ( 2369): 1418161816010 Marionette: emitting Mouse event of type mousemove at coordinates (294, 25) relative to the viewport
I/Gecko   ( 2369): 1418161816025 Marionette: emitting Mouse event of type mousedown at coordinates (294, 25) relative to the viewport
I/Gecko   ( 2369): 1418161816071 Marionette: emitting Mouse event of type mouseup at coordinates (294, 25) relative to the viewport
I/Gecko   ( 1908): 1418161816523	Marionette	INFO	RJ: Now is 1418161816523
I/Gecko   ( 1908): 1418161816525	Marionette	INFO	RJ: Last pong was at 1418161814999
I/Gecko   ( 1908): 1418161816544	Marionette	INFO	RJ: Elapsed is 1524
I/Gecko   ( 1908): 1418161816555	Marionette	INFO	RJ: Sending ping 35
I/Gecko   ( 1908): 1418161816561	Marionette	INFO	sendToClient: {"from":"0","ok":true}, {6c3472d6-f05e-4b0b-b005-0dc7e3c0dbdb}, {6c3472d6-f05e-4b0b-b005-0dc7e3c0dbdb}
I/Gecko   ( 1908): 1418161816681	Marionette	INFO	RJ: Received pong number 33
I/Gecko   ( 1908): 1418161816684	Marionette	INFO	RJ: last pong is 1418161816683
I/Gecko   ( 1908): 1418161816701	Marionette	INFO	RJ: Received pong number 34
I/Gecko   ( 1908): 1418161816702	Marionette	INFO	RJ: last pong is 1418161816702
D/skia    ( 2022): START /proc/cpuinfo:
D/skia    ( 2022): Processor	: ARMv7 Processor rev 0 (v7l)
D/skia    ( 2022): BogoMIPS	: 419.43
D/skia    ( 2022): Features	: swp half thumb fastmult vfp edsp neon vfpv3 
D/skia    ( 2022): CPU implementer	: 0x41
D/skia    ( 2022): CPU architecture: 7
D/skia    ( 2022): CPU variant	: 0x0
D/skia    ( 2022): CPU part	: 0xc08
D/skia    ( 2022): CPU revision	: 0
D/skia    ( 2022): 
D/skia    ( 2022): Hardware	: Goldfish
D/skia    ( 2022): Revision	: 0000
D/skia    ( 2022): Serial		: 0000000000000000
D/skia    ( 2022): 
D/skia    ( 2022): END /proc/cpuinfo
D/skia    ( 2022): Device supports ARM NEON instructions!
I/Gecko   ( 1908): 1418161817440	Marionette	INFO	RJ: Now is 1418161817440
I/Gecko   ( 1908): 1418161817441	Marionette	INFO	RJ: Last pong was at 1418161816702
I/Gecko   ( 1908): 1418161817442	Marionette	INFO	RJ: Elapsed is 738
I/Gecko   ( 1908): 1418161817443	Marionette	INFO	RJ: Sending ping 36
I/Gecko   ( 1908): 1418161817451	Marionette	INFO	RJ: Pulse - error catch
I/Gecko   ( 1908): 1418161817452	Marionette	INFO	RJ: Error msg: sendAsync failed: false
I/Gecko   ( 1908): 1418161817457	Marionette	INFO	RJ: Error code: undefined
I/Gecko   ( 1908): 1418161817458	Marionette	INFO	RJ: Error stack: null
I/Gecko   ( 1908): 1418161817459	Marionette	INFO	RJ: Stopping heartbeat
I/Gecko   ( 1908): 1418161817461	Marionette	INFO	Deleting frame from remote frames list: 3
I/Gecko   ( 1908): 1418161817523	Marionette	DEBUG	Got request: switchToFrame, data:

Comment 7

[Robert Wood [:rwood]]

sendAsync is returning NS_ERROR_NOT_INITIALIZED; frame has closed. Trying to send PING to the gallery app, but the gallery app has closed already and we have returned to the contacts app; however the OOP heartbeat monitor has not been turned off yet / race condition (my theory in comment 4 is correct)

Comment 8

[Robert Wood [:rwood]]

I've tried setting up event listeners for window 'close' as well as 'mozbrowserclose' but they don't seem to be fired when the gallery app is closed, maybe because it is via web activities?

:mounir, are there any gaia events that I can listen for, that are fired when the gallery is closed via a web activity (i.e. Add new contact, in edit contact tap 'add picture', select gallery, select a photo, click 'Done', gallery closes and we are returned to edit contact).

Comment 9

[Martijn Wargers (dead)]

This seems to have become a regular failure now in test_add_photo_to_contact.py, see bug 1161088.
Robert, is there a workaround for this, perhaps?

Comment 10

[Robert Wood [:rwood]]

Hi Martijn, this bug was caused by a patch in Bug 984508, that was backed out afterwords. Since that patch was backed out, this bug is not valid anymore (I am closing it). The failure in Bug 1161088 is not the same issue. FYI, I don't work on Marionette anymore, but if you ask someone in #ateam they can point you in the right direction. Thanks!

Comment 11

[Martijn Wargers (dead)]

Ok, thanks for the info. I would call this bug fixed, actually, because the patch from bug 984508, but whatever you prefer.