Closed Bug 995820 Opened 10 years ago Closed 10 years ago

Intermittent testJavascriptBridge | GeckoEventExpecter - blockForEvent timeout: Robocop:JS

Categories

(Firefox for Android Graveyard :: Testing, defect)

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

Tracking

(firefox29 unaffected, firefox30 unaffected, firefox31 fixed, firefox-esr24 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 31
Tracking Flags:
Tracking Status
firefox29 --- unaffected
firefox30 --- unaffected
firefox31 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: RyanVM, Assigned: jchen)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

Wait for JavaBridge to load before sending messages to it (v1)
3.67 KB, patch
mcomella
: review+
Details | Diff | Splinter Review
Add more docs for JavascriptBridge
2.90 KB, patch
jchen
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=37724235&tree=Fx-Team

Android 4.0 Panda fx-team opt test robocop-5 on 2014-04-13 15:24:21 PDT for push f822097ecc4e
slave: panda-0669

15:45:30     INFO -  0 INFO SimpleTest START
15:45:30     INFO -  1 INFO TEST-START | testJavascriptBridge
15:45:30     INFO -  2 INFO TEST-PASS | testJavascriptBridge | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
15:45:30     INFO -  EventExpecter: no longer listening for Gecko:Ready
15:45:30     INFO -  3 INFO TEST-PASS | testJavascriptBridge | url is not null - /robocop/robocop_javascript.html?path=testJavascriptBridge.js should not equal null
15:45:30     INFO -  4 INFO TEST-PASS | testJavascriptBridge | url is not null - /robocop/robocop_javascript.html?path=testJavascriptBridge.js should not equal null
15:45:30     INFO -  5 INFO TEST-PASS | testJavascriptBridge | The toolbar is not in the editing state -
15:45:30     INFO -  6 INFO TEST-PASS | testJavascriptBridge | Waiting for Toolbar to enter editing mode. -
15:45:30     INFO -  7 INFO TEST-PASS | testJavascriptBridge | Waiting for UrlEditText to be input method target. -
15:45:30     INFO -  8 INFO TEST-PASS | testJavascriptBridge | url is not null - http://mochi.test:8888/tests/robocop/robocop_javascript.html?path=testJavascriptBridge.js should not equal null
15:45:30     INFO -  9 INFO TEST-PASS | testJavascriptBridge | The toolbar is in the editing state -
15:45:30     INFO -  10 INFO TEST-PASS | testJavascriptBridge | The UrlEditText is the input method target -
15:45:30     INFO -  11 INFO TEST-PASS | testJavascriptBridge | The toolbar is in the editing state -
15:45:30     INFO -  12 INFO TEST-PASS | testJavascriptBridge | initiatingAction is not null - org.mozilla.gecko.tests.components.ToolbarComponent$2@413304e0 should not equal null
15:45:30     INFO -  ToolbarTitleTextChangeVerifier: stored title, "".
15:45:30     INFO -  13 INFO TEST-PASS | testJavascriptBridge | Given message occurred for registered event: {"type":"DOMTitleChanged","title":"Twitter","tabID":0} - DOMTitleChanged should equal DOMTitleChanged
15:45:30     INFO -  14 INFO TEST-PASS | testJavascriptBridge | Given message occurred for registered event: {"errorType":"","bgColor":"rgb(238, 238, 238)","type":"DOMContentLoaded","tabID":0} - DOMContentLoaded should equal DOMContentLoaded
15:45:30     INFO -  EventExpecter: no longer listening for DOMContentLoaded
15:45:30     INFO -  EventExpecter: no longer listening for DOMTitleChanged
15:45:30     INFO -  ToolbarTitleTextChangeVerifier: state changed to title, "Twitter".
15:45:30     INFO -  ToolbarTitleTextChangeVerifier: was satisfied.
15:45:30     INFO -  15 INFO TEST-PASS | testJavascriptBridge | Waiting for Toolbar to exit editing mode. -
15:45:30     INFO -  Dumping ALL the threads!
15:45:30     INFO -  Thread[Signal Catcher,5,system]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  Thread[Gecko,5,main]
15:45:30     INFO -  org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
15:45:30     INFO -  org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:345)
15:45:30     INFO -  org.mozilla.gecko.GeckoThread.run(GeckoThread.java:174)
15:45:30     INFO -  Thread[actionMode,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Object.wait(Object.java:364)
15:45:30     INFO -  java.util.Timer$TimerImpl.run(Timer.java:214)
15:45:30     INFO -  Thread[Binder Thread #2,5,main]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  Thread[ModernAsyncTask #4,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Thread.parkFor(Thread.java:1231)
15:45:30     INFO -  sun.misc.Unsafe.park(Unsafe.java:323)
15:45:30     INFO -  java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
15:45:30     INFO -  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
15:45:30     INFO -  java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[main,5,main]
15:45:30     INFO -  android.os.MessageQueue.nativePollOnce(Native Method)
15:45:30     INFO -  android.os.MessageQueue.next(MessageQueue.java:118)
15:45:30     INFO -  android.os.Looper.loop(Looper.java:118)
15:45:30     INFO -  android.app.ActivityThread.main(ActivityThread.java:4424)
15:45:30     INFO -  java.lang.reflect.Method.invokeNative(Native Method)
15:45:30     INFO -  java.lang.reflect.Method.invoke(Method.java:511)
15:45:30     INFO -  com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:784)
15:45:30     INFO -  com.android.internal.os.ZygoteInit.main(ZygoteInit.java:551)
15:45:30     INFO -  dalvik.system.NativeStart.main(Native Method)
15:45:30     INFO -  Thread[FinalizerDaemon,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Object.wait(Object.java:401)
15:45:30     INFO -  java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
15:45:30     INFO -  java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
15:45:30     INFO -  java.lang.Daemons$FinalizerDaemon.run(Daemons.java:168)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[GeckoBackgroundThread,5,main]
15:45:30     INFO -  android.os.MessageQueue.nativePollOnce(Native Method)
15:45:30     INFO -  android.os.MessageQueue.next(MessageQueue.java:118)
15:45:30     INFO -  android.os.Looper.loop(Looper.java:118)
15:45:30     INFO -  org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:32)
15:45:30     INFO -  Thread[pool-1-thread-1,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Thread.parkFor(Thread.java:1231)
15:45:30     INFO -  sun.misc.Unsafe.park(Unsafe.java:323)
15:45:30     INFO -  java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
15:45:30     INFO -  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
15:45:30     INFO -  java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[FinalizerWatchdogDaemon,5,main]
15:45:30     INFO -  java.lang.VMThread.sleep(Native Method)
15:45:30     INFO -  java.lang.Thread.sleep(Thread.java:1031)
15:45:30     INFO -  java.lang.Thread.sleep(Thread.java:1013)
15:45:30     INFO -  java.lang.Daemons$FinalizerWatchdogDaemon.run(Daemons.java:213)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[ModernAsyncTask #2,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Thread.parkFor(Thread.java:1231)
15:45:30     INFO -  sun.misc.Unsafe.park(Unsafe.java:323)
15:45:30     INFO -  java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
15:45:30     INFO -  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
15:45:30     INFO -  java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[ModernAsyncTask #3,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Thread.parkFor(Thread.java:1231)
15:45:30     INFO -  sun.misc.Unsafe.park(Unsafe.java:323)
15:45:30     INFO -  java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
15:45:30     INFO -  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
15:45:30     INFO -  java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[Thread-147,5,main]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  Thread[GC,5,system]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  Thread[JDWP,5,system]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  Thread[Binder Thread #1,5,main]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  Thread[RefQueueWorker@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@412a8710,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Object.wait(Object.java:401)
15:45:30     INFO -  java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:102)
15:45:30     INFO -  java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:73)
15:45:30     INFO -  org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:102)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[ModernAsyncTask #1,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Thread.parkFor(Thread.java:1231)
15:45:30     INFO -  sun.misc.Unsafe.park(Unsafe.java:323)
15:45:30     INFO -  java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
15:45:30     INFO -  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
15:45:30     INFO -  java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[Timer-0,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Object.wait(Object.java:401)
15:45:30     INFO -  java.util.Timer$TimerImpl.run(Timer.java:238)
15:45:30     INFO -  Thread[ReferenceQueueDaemon,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Object.wait(Object.java:364)
15:45:30     INFO -  java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:128)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[Instr: org.mozilla.gecko.FennecInstrumentationTestRunner,5,main]
15:45:30     INFO -  dalvik.system.VMStack.getThreadStackTrace(Native Method)
15:45:30     INFO -  java.lang.Thread.getStackTrace(Thread.java:591)
15:45:30     INFO -  java.lang.Thread.getAllStackTraces(Thread.java:528)
15:45:30     INFO -  org.mozilla.gecko.FennecNativeDriver.logAllStackTraces(FennecNativeDriver.java:301)
15:45:30     INFO -  org.mozilla.gecko.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:95)
15:45:30     INFO -  org.mozilla.gecko.FennecNativeActions$GeckoEventExpecter.blockForEvent(FennecNativeActions.java:80)
15:45:30     INFO -  org.mozilla.gecko.FennecNativeActions$GeckoEventExpecter.blockForEventData(FennecNativeActions.java:144)
15:45:30     INFO -  org.mozilla.gecko.tests.helpers.JavascriptBridge.processPendingMessage(JavascriptBridge.java:142)
15:45:30     INFO -  org.mozilla.gecko.tests.helpers.JavascriptBridge.syncCall(JavascriptBridge.java:95)
15:45:30     INFO -  org.mozilla.gecko.tests.testJavascriptBridge.testJavascriptBridge(testJavascriptBridge.java:37)
15:45:30     INFO -  java.lang.reflect.Method.invokeNative(Native Method)
15:45:30     INFO -  java.lang.reflect.Method.invoke(Method.java:511)
15:45:30     INFO -  android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214)
15:45:30     INFO -  android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199)
15:45:30     INFO -  android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:192)
15:45:30     INFO -  junit.framework.TestCase.runBare(TestCase.java:127)
15:45:30     INFO -  junit.framework.TestResult$1.protect(TestResult.java:106)
15:45:30     INFO -  junit.framework.TestResult.runProtected(TestResult.java:124)
15:45:30     INFO -  junit.framework.TestResult.run(TestResult.java:109)
15:45:30     INFO -  junit.framework.TestCase.run(TestCase.java:118)
15:45:30     INFO -  android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
15:45:30     INFO -  android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
15:45:30     INFO -  android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:545)
15:45:30     INFO -  android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1551)
15:45:30     INFO -  Thread[ModernAsyncTask #5,5,main]
15:45:30     INFO -  java.lang.Object.wait(Native Method)
15:45:30     INFO -  java.lang.Thread.parkFor(Thread.java:1231)
15:45:30     INFO -  sun.misc.Unsafe.park(Unsafe.java:323)
15:45:30     INFO -  java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
15:45:30     INFO -  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2022)
15:45:30     INFO -  java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1009)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1069)
15:45:30     INFO -  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[GeckoANRReporter,5,main]
15:45:30     INFO -  android.os.MessageQueue.nativePollOnce(Native Method)
15:45:30     INFO -  android.os.MessageQueue.next(MessageQueue.java:118)
15:45:30     INFO -  android.os.Looper.loop(Looper.java:118)
15:45:30     INFO -  org.mozilla.gecko.ANRReporter$1.run(ANRReporter.java:95)
15:45:30     INFO -  java.lang.Thread.run(Thread.java:856)
15:45:30     INFO -  Thread[Compiler,5,system]
15:45:30     INFO -  dalvik.system.NativeStart.run(Native Method)
15:45:30     INFO -  16 INFO TEST-UNEXPECTED-FAIL | testJavascriptBridge | GeckoEventExpecter - blockForEvent timeout: Robocop:JS
15:45:30     INFO -  EventExpecter: no longer listening for Robocop:JS
15:45:30     INFO -  17 INFO TEST-END | testJavascriptBridge | finished in 103611ms
15:45:30     INFO -  18 INFO TEST-START | Shutdown
15:45:30     INFO -  19 INFO Passed: 14
15:45:30  WARNING -  20 INFO Failed: 1
15:45:30  WARNING -  One or more unittests failed.
15:45:30     INFO -  21 INFO Todo: 0
15:45:30     INFO -  22 INFO SimpleTest FINISHED
re comment 1, we first get:

22:07:12     INFO -  04-13 21:58:04.293 D/Robocop ( 1594): handleMessage called for: Robocop:JS; expecting: Robocop:JS
22:07:12     INFO -  04-13 21:58:04.293 I/Robocop ( 1594): 15 INFO TEST-PASS | testJavascriptBridge | 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
22:07:12     INFO -  04-13 21:58:04.303 D/Robocop ( 1594): received event Robocop:JS
22:07:12     INFO -  04-13 21:58:04.303 D/Robocop ( 1594): unblocked on expecter for Robocop:JS
22:07:12     INFO -  04-13 21:58:04.313 I/Robocop ( 1594): 16 INFO TEST-INFO | testJavascriptBridge | (xpcshell/head.js) - test 1 pending

Meaning we're waiting on do_check_eq in the JS, I believe (I'm not sure where progress messages get called from). However, shortly after we see:

22:07:12     INFO -  04-13 21:58:04.493 D/GeckoTabs( 1594): handleMessage: DOMContentLoaded

Which is the second time this is called, after we already "finished waiting for the page to load" with the first DOMContentLoaded. Fishy.
(In reply to Michael Comella (:mcomella) from comment #9)
> Which is the second time this is called, after we already "finished waiting
> for the page to load" with the first DOMContentLoaded. Fishy.

Ah, actually, we timeout the first time so this is the first message we are supposed to have blocked on and received. I wonder if this isn't a loading timeout then (perhaps fixable with `Gecko:DelayedStartup`)? Or perhaps the message gets lost because it's sent before the page (and associated JS) is loaded (or listeners are attached)?
I'll stop tbplbot commenting on them now, but the Android 2.3 emulator tests (which are hidden because of the constant stream of bug 985155 crashes) are not intermittent with this, it's been permaorange since https://tbpl.mozilla.org/?rev=4b27cfbf2f3b&tree=Fx-Team&showall=1
22:07:12     INFO -  04-13 21:58:04.313 I/Robocop ( 1594): 16 INFO TEST-INFO | testJavascriptBridge | (xpcshell/head.js) - test 1 pending

is printed by `do_test_pending`, which is called in the top-level of testJavascriptBridge.js, so this message shows us when the JavaScript is read. However, at this point, the functions have not be defined yet and we've already sent our Java->JS message, meaning it's possible that the JS tried to call `check_js_int_arg`, the first function, but it was not defined, and the call failed silently.

However, we do report errors in calling JS functions [1], but no error was thrown. Perhaps throwing errors from JS does not work as expected, given the Java<->JS nature?

[1]: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/tests/robocop_head.js?rev=5cece5a197f2#1190
(In reply to Michael Comella (:mcomella) from comment #12)
> However, we do report errors in calling JS functions [1], but no error was
> thrown. Perhaps throwing errors from JS does not work as expected, given the
> Java<->JS nature?

I added a throw to [1] and, though this error does not immediately end the test (bug 996316), throwing errors should log output, which we don't see here.

I noticed that the JavaBridge (and thus the event observer) is created at the top of the file - which means we're likely missing the Java message's event.

I think the solution is to ensure the page loads before continuing. Perhaps:
  * We should fail on DOMContentLoaded timeout to prevent confusion like this where the problem is described as something besides, "Page failed to load on time", when that's actually the problem
  * We can try waiting for "Gecko:DelayedStartup" which should hopefully allow the page to load more quickly, and possibly prevent this issue.
Assignee: nobody → michael.l.comella
Status: NEW → ASSIGNED
Comment on attachment 8406505 [details] [diff] [review]
Wait for DelayedStartup in testJavascriptBridge.

Review of attachment 8406505 [details] [diff] [review]:
-----------------------------------------------------------------

We can do this if it helps. I think the real underlying cause is we don't wait for JavaBridge to load (and register its observer) before we send the message. In that case, the first message ends up being ignored.
Attachment #8406505 - Flags: review?(nchen) → review+
This patch adds a "notify-loaded" message that JavaBridge sends once it gets loaded. In JavascriptBridge, we don't send any messages until we see the "notify-loaded" message.

Looks like this does fix the perma-orange on 2.3, https://tbpl.mozilla.org/?tree=Try&rev=6ec976916cca&showall=1
Attachment #8406906 - Flags: review?(michael.l.comella)
Comment on attachment 8406906 [details] [diff] [review]
Wait for JavaBridge to load before sending messages to it (v1)

Review of attachment 8406906 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm.
Attachment #8406906 - Flags: review?(michael.l.comella) → review+
Unrelated: Each instance of Java(script)Bridge uses the same channel, right? Meaning we can't have two bridges communicating independently? Perhaps we should add a comment, if this is expected behavior.
Comment on attachment 8406505 [details] [diff] [review]
Wait for DelayedStartup in testJavascriptBridge.

You have the better solution.
Attachment #8406505 - Attachment is obsolete: true
(In reply to Michael Comella (:mcomella) from comment #19)
> Unrelated: Each instance of Java(script)Bridge uses the same channel, right?
> Meaning we can't have two bridges communicating independently? Perhaps we
> should add a comment, if this is expected behavior.

Yeah good point. We should add a comment.
Assignee: michael.l.comella → nchen
Keywords: checkin-needed
Adding more docs including a line about multiple instances.
Attachment #8406991 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/a6ed5860261f
https://hg.mozilla.org/mozilla-central/rev/90a54293fd84
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 31
re comment 28:

Looks like the page never finished loading:

07:20:21     INFO -  ToolbarTitleTextChangeVerifier: timed out.

meaning the response we're waiting for never occurred. Sounds like Robocop:JS could be a whole new blend of ambiguous failures! I wonder if we shouldn't just fail if the toolbar title text fails to change (meaning we'd have to have an invariant that ensures the page title changes on page load in all tests).
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: