Closed Bug 945675 Opened 11 years ago Closed 8 years ago

Intermittent TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status

Categories

(Firefox for Android Graveyard :: General, defect)

Product:
Firefox for Android Graveyard
Component:
General
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1252570

People

(Reporter: cbook, Unassigned)

References

(
URL
)

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled][leave open]) 

Android 2.2 Armv6 Tegra fx-team opt test robocop-2 on 2013-12-03 00:54:12 PST for push 1659537d5ed3

slave: tegra-225

https://tbpl.mozilla.org/php/getParsedLog.php?id=31369349&tree=Fx-Team

12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
junit.framework.AssertionFailedError: 12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
13 INFO TEST-UNEXPECTED-FAIL | testMozPay | Exception caught - junit.framework.AssertionFailedError: 12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
12-03 01:20:30.094 I/Robocop ( 6667): 12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
12-03 01:20:30.124 I/Robocop ( 6667): junit.framework.AssertionFailedError: 12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
12-03 01:20:30.124 I/Robocop ( 6667): 13 INFO TEST-UNEXPECTED-FAIL | testMozPay | Exception caught - junit.framework.AssertionFailedError: 12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
12-03 01:20:31.264 I/TestRunner( 6667): junit.framework.AssertionFailedError: 13 INFO TEST-UNEXPECTED-FAIL | testMozPay | Exception caught - junit.framework.AssertionFailedError: 12 INFO TEST-UNEXPECTED-FAIL | testMozPay | GeckoEventExpecter - blockForEvent timeout: Robocop:Status
Mochi-Remote ERROR   | Automation Error: Missing end of test marker (process crashed?)
This seems to only happen on Armv6.

I see an exception in the logcats:

12-05 05:29:50.256 D/GeckoTabs( 6628): handleMessage: Content:LocationChange
12-05 05:29:50.256 D/GeckoTab( 6628): Ignoring location change event: URIs are the same.
12-05 05:29:50.256 D/GeckoTabs( 6628): handleMessage: Content:SecurityChange
12-05 05:29:50.286 D/GeckoToolbar( 6628): onTabChanged: FAVICON
12-05 05:29:50.286 D/GeckoBrowserApp( 6628): BrowserApp.onTabChanged: 0: FAVICON
12-05 05:29:50.286 D/GeckoToolbar( 6628): onTabChanged: SECURITY_CHANGE
12-05 05:29:50.286 D/GeckoBrowserApp( 6628): BrowserApp.onTabChanged: 1: SECURITY_CHANGE
12-05 05:29:50.296 D/GeckoTabs( 6628): handleMessage: DOMTitleChanged
12-05 05:29:50.306 D/GeckoTabs( 6628): handleMessage: DOMContentLoaded
12-05 05:29:50.306 E/GeckoConsole( 6628): [JavaScript Error: "uncaught exception: Can't find method getMCC"]
12-05 05:29:50.316 W/dalvikvm( 6628): JNI WARNING: JNI method called with exception raised
12-05 05:29:50.316 W/dalvikvm( 6628):              in Lorg/mozilla/gecko/mozglue/GeckoLoader;.nativeRun (Ljava/lang/String;)V (CallBooleanMethodV)
12-05 05:29:50.316 W/dalvikvm( 6628): Pending exception is:
12-05 05:29:50.316 I/dalvikvm( 6628): Ljava/lang/NoSuchMethodError;: getMCC
12-05 05:29:50.316 I/dalvikvm( 6628): 	at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
12-05 05:29:50.316 I/dalvikvm( 6628): 	at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:372)
12-05 05:29:50.316 I/dalvikvm( 6628): 	at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:177)
12-05 05:29:50.316 I/dalvikvm( 6628): "Gecko" prio=5 tid=12 NATIVE
12-05 05:29:50.316 I/dalvikvm( 6628):   | group="main" sCount=0 dsCount=0 s=N obj=0x48583600 self=0x26ee40
12-05 05:29:50.316 I/dalvikvm( 6628):   | sysTid=6645 nice=0 sched=0/0 cgrp=unknown handle=2551680
12-05 05:29:50.316 I/dalvikvm( 6628):   | schedstat=( 3928030000 663654000 1847 )
12-05 05:29:50.316 I/dalvikvm( 6628):   at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
12-05 05:29:50.316 I/dalvikvm( 6628):   at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
12-05 05:29:50.316 I/dalvikvm( 6628):   at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:372)
12-05 05:29:50.316 I/dalvikvm( 6628):   at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:177)
12-05 05:29:50.316 I/dalvikvm( 6628): 
12-05 05:29:50.316 E/dalvikvm( 6628): VM aborting
12-05 05:29:50.356 D/GeckoToolbar( 6628): onTabChanged: TITLE
12-05 05:29:50.356 D/GeckoBrowserApp( 6628): BrowserApp.onTabChanged: 1: TITLE
12-05 05:29:50.356 D/GeckoToolbar( 6628): onTabChanged: LOADED
12-05 05:29:50.356 D/GeckoBrowserApp( 6628): BrowserApp.onTabChanged: 1: LOADED
12-05 05:29:50.556 D/GeckoThumbnailHelper( 6628): Using new thumbnail size: 242544 (width 326)
12-05 05:29:50.556 D/GeckoThumbnailHelper( 6628): Sending thumbnail event: 326, 186
wesj had a look at this today, but no fix was obvious.

Disabled on Android 2.2 only: https://hg.mozilla.org/integration/mozilla-inbound/rev/36bd64203d5d
Whiteboard: [test disabled][leave open]
I see now that this test is failing even more often on Panda, it just isn't causing the test to be reported as a failure on tbpl (darn mozharness!):

https://tbpl.mozilla.org/php/getParsedLog.php?id=31592786&tree=Mozilla-Inbound&full=1#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=31592311&tree=Mozilla-Inbound&full=1#error0

Disabled entirely now:

https://hg.mozilla.org/integration/mozilla-inbound/rev/26fb7e60d288
This was probably fixed by bug 956417.
Maybe we should try re-enabling the test to check if it was really fixed by 956417.
It fails differently now:

http://ftp.mozilla.org/pub/mozilla.org/mobile/try-builds/gbrown@mozilla.com-1d91d69cdb2f/try-android-api-11/try_panda_android_test-robocop-5-bm101-tests1-panda-build3049.txt.gz

09:46:34     INFO -  TEST-START | testMozPay
09:46:34     INFO -  TEST-PASS | testMozPay | Robocop tests need the test device screen to be powered on. -
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
09:46:34     INFO -  EventExpecter: no longer listening for Gecko:Ready
09:46:34     INFO -  Registered listener for Robocop:JS
09:46:34     INFO -  Loading JavaScript test from http://mochi.test:8888/tests/robocop/robocop_javascript.html?slug=1420019189100&path=testMozPay.js
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"\nTEST-INFO | (xpcshell\/head.js) | test 1 pending\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  (xpcshell/head.js) | test 1 pending
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"\nTEST-INFO | (xpcshell\/head.js) | test 2 pending\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  (xpcshell/head.js) | test 2 pending
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"\nTEST-INFO | testMozPay.js | Starting test_get_set","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | Starting test_get_set
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"\nTEST-UNEXPECTED-FAIL | testMozPay.js | undefined == Fake Provider - See following stack:\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34  WARNING -  TEST-UNEXPECTED-FAIL | testMozPay | testMozPay.js - undefined == Fake Provider - See following stack:
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: do_throw :: line 472\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: robocop_head.js :: do_throw :: line 472
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: do_report_result :: line 574\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: robocop_head.js :: do_report_result :: line 574
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: _do_check_eq :: line 584\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: robocop_head.js :: _do_check_eq :: line 584
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: do_check_eq :: line 591\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: robocop_head.js :: do_check_eq :: line 591
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: testMozPay.js :: test_get_set\/< :: line 54\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: testMozPay.js :: test_get_set/< :: line 54
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: jar:jar:file:\/\/\/data\/app\/org.mozilla.fennec-1.apk!\/assets\/omni.ja!\/components\/PaymentsUI.js :: confirmPaymentRequest :: line 80\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: jar:jar:file:///data/app/org.mozilla.fennec-1.apk!/assets/omni.ja!/components/PaymentsUI.js :: confirmPaymentRequest :: line 80
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: testMozPay.js :: test_get_set :: line 51\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: testMozPay.js :: test_get_set :: line 51
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: self-hosted :: next :: line 945\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: self-hosted :: next :: line 945
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: resource:\/\/gre\/modules\/Task.jsm :: TaskImpl_run :: line 330\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 330
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: resource:\/\/gre\/modules\/Task.jsm :: TaskImpl :: line 275\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: resource://gre/modules/Task.jsm :: TaskImpl :: line 275
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: resource:\/\/gre\/modules\/Task.jsm :: createAsyncFunction\/asyncFunction :: line 249\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: resource://gre/modules/Task.jsm :: createAsyncFunction/asyncFunction :: line 249
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: resource:\/\/gre\/modules\/Task.jsm :: Task_spawn :: line 164\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: resource://gre/modules/Task.jsm :: Task_spawn :: line 164
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: _run_next_test :: line 1118\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: robocop_head.js :: _run_next_test :: line 1118
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"JS frame :: robocop_head.js :: do_execute_soon\/<.run :: line 439\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | JS frame :: robocop_head.js :: do_execute_soon/<.run :: line 439
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  testMozPay.js | native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
09:46:34     INFO -  TEST-PASS | testMozPay | Given message occurred for registered event: {"message":"\nTEST-INFO | (xpcshell\/head.js) | exiting test\n","innerType":"progress","type":"Robocop:JS"} - Robocop:JS should equal Robocop:JS
09:46:34     INFO -  (xpcshell/head.js) | exiting test
09:46:34     INFO -  EventExpecter: no longer listening for Robocop:JS
09:46:34     INFO -  Unregistered listener for Robocop:JS
09:46:34     INFO -  TEST-OK | testMozPay | took 6695ms
09:46:34     INFO -  TEST-START | Shutdown
09:46:34     INFO -  Passed: 22
09:46:34     INFO -  Failed: 1
09:46:34     INFO -  Todo: 0
09:46:34     INFO -  SimpleTest FINISHED
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → DUPLICATE
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.