Closed Bug 907720 Opened 8 years ago Closed 8 years ago

Intermittent Android tcheck2 | application crashed [@ mozalloc_abort(char const*)] ("java.lang.IllegalStateException: Fragment already added: PinBookmarkDialog{48425208 #3 pin_bookmark}")

Categories

(Firefox for Android Graveyard :: Awesomescreen, defect, P1)

Product:
Firefox for Android Graveyard
Component:
Awesomescreen
Platform:
ARM
Android
Type:
defect

Tracking

(firefox24 unaffected, firefox25 unaffected, firefox26 fixed, fennec26+)

Status:
RESOLVED FIXED
Milestone:
Firefox 26
Tracking Flags:
Tracking Status
firefox24 --- unaffected
firefox25 --- unaffected
firefox26 --- fixed
fennec 26+ ---

People

(Reporter: emorley, Assigned: Margaret)

References

Details

(Keywords: crash, intermittent-failure)

Attachments

(1 file, 1 obsolete file)

wait for HomePager to be hidden
4.33 KB, patch
gbrown
: review+
Details | Diff | Splinter Review 
Android Tegra 250 fig talos remote-trobocheck2 on 2013-08-21 05:18:17 PDT for push 7e83ba2dfb51

slave: tegra-039

https://tbpl.mozilla.org/php/getParsedLog.php?id=26815583&full=1&branch=fig

{
FIRE PROC: ' "MOZ_CRASHREPORTER_SHUTDOWN=1,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1" am instrument -w -e deviceroot /mnt/sdcard/tests -e class org.mozilla.fennec_fig.tests.testCheck2 org.mozilla.roboexample.test/org.mozilla.fennec_fig.FennecInstrumentationTestRunner'
INFO : EventExpecter: no longer listening for Gecko:Ready
PaintExpecter: no longer listening for events
__startBeforeLaunchTimestamp1377087902288__endBeforeLaunchTimestamp
__startAfterTerminationTimestamp1377087943607__endAfterTerminationTimestamp

pushing directory: /tmp/tmpyiu6Ws/profile to /mnt/sdcard/tests/profile
	Screen width/height:1024/768
	colorDepth:24
	Browser inner width/height: 1024/695


browser_name:Fennec
browser_version:26.0a1
buildID:20130821040220

removing file: /mnt/sdcard/tests/fennec_ids.txt
removing file: /mnt/sdcard/tests/robotium.config
removing file: /mnt/sdcard/tests/browser_output.txt
removing file: /mnt/sdcard/tests/browser_output.txt
removing file: /mnt/sdcard/tests/profile/sessionstore.js
getting files in '/mnt/sdcard/tests/profile/minidumps/'
removing file: /mnt/sdcard/tests/browser_output.txt
removing file: /mnt/sdcard/tests/profile/sessionstore.js
getting files in '/mnt/sdcard/tests/profile/minidumps/'
PROCESS-CRASH | tcheck2 | application crashed [@ mozalloc_abort(char const*)]
Crash dump filename: /tmp/tmpPtM48s/469f2341-9b77-5a0d-31e4eb41-270f459d.dmp
Operating system: Android
                  0.0.0 Linux 2.6.32.9-00002-gd8084dc-dirty #1 SMP PREEMPT Wed Feb 2 11:32:06 PST 2011 armv7l nvidia/harmony/harmony/harmony:2.2/FRF91/20110202.102810:eng/test-keys
CPU: arm
     2 CPUs

Crash reason:  SIGSEGV
Crash address: 0x0

Thread 0 (crashed)
 0  libmozalloc.so!mozalloc_abort(char const*) [mozalloc_abort.cpp:7e83ba2dfb51 : 30 + 0x4]
     r4 = 0x0000aa50    r5 = 0x00000000    r6 = 0x483f35b0    r7 = 0x430cbf30
     r8 = 0xbe9697b0    r9 = 0x430cbf28   r10 = 0x430cbf14    fp = 0x00000000
     sp = 0xbe969728    lr = 0x4498a0bb    pc = 0x4498a0be
    Found by: given as instruction pointer in context
 1  libxul.so!Java_org_mozilla_gecko_GeckoAppShell_reportJavaCrash [AndroidJNI.cpp:7e83ba2dfb51 : 102 + 0x3]
     r4 = 0x0000aa50    r5 = 0x00000000    r6 = 0x483f35b0    r7 = 0x430cbf30
     r8 = 0xbe9697b0    r9 = 0x430cbf28   r10 = 0x430cbf14    fp = 0x00000000
     sp = 0xbe969730    pc = 0x55700ef7
    Found by: call frame info
 2  libmozglue.so!Java_org_mozilla_gecko_GeckoAppShell_reportJavaCrash [jni-stubs.inc:7e83ba2dfb51 : 108 + 0x1]
     r4 = 0x0000aa50    r5 = 0x00000000    r6 = 0x483f35b0    r7 = 0x430cbf30
     r8 = 0xbe9697b0    r9 = 0x430cbf28   r10 = 0x430cbf14    fp = 0x00000000
     sp = 0xbe9697a8    pc = 0x80c1b4a3
    Found by: call frame info
 3  libdvm.so + 0x16e36
     r4 = 0xbe9697d0    r5 = 0x00000000    r6 = 0x483f35b0    r7 = 0x430cbf30
     r8 = 0xbe9697b0    r9 = 0x430cbf28   r10 = 0x430cbf14    fp = 0x00000000
     sp = 0xbe9697b0    pc = 0x80816e38
    Found by: call frame info
 4  dalvik-LinearAlloc (deleted) + 0x22dfb2
     sp = 0xbe9697b8    pc = 0x432f9fb4
    Found by: stack scanning
 5  2 (deleted) + 0x6d5ae
     sp = 0xbe9697bc    pc = 0x483f35b0
    Found by: stack scanning
 6  libdvm.so + 0x16ffe
     sp = 0xbe9697c4    pc = 0x80817000
    Found by: stack scanning
}

From logcat:

{
08-21 05:25:09.177 W/GeckoGlobalHistory( 2110): Rebuilding visited link set...
08-21 05:25:09.357 I/Robocop ( 2110): PaintExpecter: no longer listening for events
08-21 05:25:09.414 I/dalvikvm-heap( 2110): Grow heap (frag case) to 9.185MB for 2846736-byte allocation
08-21 05:25:09.444 I/SUTAgentAndroid( 1516): 10.250.49.155 : isdir /mnt/sdcard/tests
08-21 05:25:09.464 I/SUTAgentAndroid( 1516): 10.250.49.155 : cd /mnt/sdcard/tests
08-21 05:25:09.494 I/SUTAgentAndroid( 1516): 10.250.49.155 : ls
08-21 05:25:09.554 I/SUTAgentAndroid( 1516): 10.250.49.155 : pull /mnt/sdcard/tests/browser_output.txt
08-21 05:25:09.644 I/global  ( 2110): Default buffer size used in BufferedOutputStream constructor. It would be better to be explicit if an 8k buffer is required.
08-21 05:25:10.137 I/RobocopMotionEventReplayer( 2110): Initialized using offset (0,73)
08-21 05:25:10.137 I/global  ( 2110): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
08-21 05:25:10.147 V/RobocopMotionEventReplayer( 2110): Injecting MotionEvent{484e83f8 action=0 x=566.6796 y=426.84274 pressure=0.0 size=0.0}
08-21 05:25:10.184 V/RobocopMotionEventReplayer( 2110): Injecting MotionEvent{48414d40 action=2 x=569.52014 y=426.17374 pressure=0.0 size=0.0}
08-21 05:25:10.257 V/RobocopMotionEventReplayer( 2110): Injecting MotionEvent{484ffa30 action=1 x=569.52014 y=426.17374 pressure=0.0 size=0.0}
08-21 05:25:10.284 V/RobocopMotionEventReplayer( 2110): Injecting MotionEvent{48445948 action=0 x=563.8391 y=388.70782 pressure=0.0 size=0.0}
08-21 05:25:10.347 V/RobocopMotionEventReplayer( 2110): Injecting MotionEvent{48513010 action=1 x=563.8391 y=388.70782 pressure=0.0 size=0.0}
08-21 05:25:10.584 D/AndroidRuntime( 2110): Shutting down VM
08-21 05:25:10.594 E/GeckoAppShell( 2110): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 1 ("main")
08-21 05:25:10.594 E/GeckoAppShell( 2110): java.lang.IllegalStateException: Fragment already added: PinBookmarkDialog{48425208 #3 pin_bookmark}
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.support.v4.app.FragmentManagerImpl.addFragment(FragmentManager.java:1159)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.support.v4.app.BackStackRecord.run(BackStackRecord.java:616)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.support.v4.app.FragmentManagerImpl.execPendingActions(FragmentManager.java:1444)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.support.v4.app.FragmentManagerImpl$1.run(FragmentManager.java:429)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.os.Handler.handleCallback(Handler.java:587)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.os.Handler.dispatchMessage(Handler.java:92)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.os.Looper.loop(Looper.java:123)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at android.app.ActivityThread.main(ActivityThread.java:4627)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at java.lang.reflect.Method.invokeNative(Native Method)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at java.lang.reflect.Method.invoke(Method.java:521)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
08-21 05:25:10.594 E/GeckoAppShell( 2110): 	at dalvik.system.NativeStart.main(Native Method)
08-21 05:25:10.594 E/Gecko   ( 2110): mozalloc_abort: Redirecting call to abort() to mozalloc_abort
}
Summary: Intermittent PROCESS-CRASH | tcheck2 | application crashed [@ mozalloc_abort(char const*)] ("java.lang.IllegalStateException: Fragment already added: PinBookmarkDialog{48425208 #3 pin_bookmark}") → Intermittent Android tcheck2 | application crashed [@ mozalloc_abort(char const*)] ("java.lang.IllegalStateException: Fragment already added: PinBookmarkDialog{48425208 #3 pin_bookmark}")
This java crash is pretty frequent - would it be possible to prioritise it above some of the other intermittent failures? :-)
Flags: needinfo?(lucasr.at.mozilla)
tracking-fennec: --- → ?
Flags: needinfo?(lucasr.at.mozilla)
Priority: -- → P1
Assignee: nobody → lucasr.at.mozilla
tracking-fennec: ? → 26+
Running testCheck2 locally, I'm seeing the about:home content get panned and scrolled, so I think there's some issue here where we start doing the test actions before the HomePager is hidden.

In bug 905591, we updated loadAndGetPainted to use loadUrl, which does not go through the manual process of entering a URL. I think the problem is that we have code to hide the HomePager in commitEditingMode/dismissEditingMode, but we don't go through that logic when we use loadUrl, so we're not hiding it until we get a location change event (one of the other places we end up hiding HomePager). I think we're not waiting long enough for that location change event.

I haven't looked through the implementation of PaintExpecter yet, but if it's just checking on the state of the gecko stuff happening underneath HomePager, it may be saying that the paint is done before we actually hide the HomePager.
I can reproduce this crash pretty reliably locally, and when I added some debug logging, I found is that we're actually never calling hideHomePager() on location change. For some reason on location change the isAboutHome(tab) call here sometimes returns true:
http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/BrowserApp.java#192

I'm really confused about how this could even happen, since Tab.handleLocationChange takes care of updating the URL itself, and then it sends a LOCATION_CHANGE TabEvent afterwards:
http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/Tab.java#602

I will continue to investigate...
(In reply to :Margaret Leibovic from comment #140)
> I can reproduce this crash pretty reliably locally, and when I added some
> debug logging, I found is that we're actually never calling hideHomePager()
> on location change. For some reason on location change the isAboutHome(tab)
> call here sometimes returns true:
> http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/BrowserApp.
> java#192

Correction: it always returns true. The browser just sometimes doesn't crash because it sometimes will end up tapping on a bookmark thumbnail, which gets loaded and panned/scrolled. So this test is consistently doing the wrong thing.
I think I may been reading this debug logging incorrectly... I think we're just slow in processing these events, so I was seeing the events from the original about:home load on startup. I added some more logging, and I do see us attempt to load the URL we're actually trying to test, but I don't see us getting a location change event for that at all.

In fact, I do sometimes see us successfully load that URL if we don't crash or accidentally tap on a bookmark thumbnail to load a different page.

So, I think we just need to do something to make sure we wait for the HomePager to be gone before we start touching things.
This fix is working for me locally, pushed to try:
https://tbpl.mozilla.org/?tree=Try&rev=93da8a985e6a

I'm still not sure how much I like this approach, but at least it's a band-aid that would fix this test. However, I'm wondering if this problem affects other tests as well.
Here's the patch I pushed to try. I can trigger a bunch of test runs to see if it makes things better.
Comment on attachment 794960 [details] [diff] [review]
patch to wait for non-empty title

Looking pretty green so far, so flagging for review.
Attachment #794960 - Flags: review?(gbrown)
Comment on attachment 794960 [details] [diff] [review]
patch to wait for non-empty title

Gr, it still crashes sometimes on 2.2.
Attachment #794960 - Flags: review?(gbrown)
Assignee: lucasr.at.mozilla → margaret.leibovic
Some thoughts on the logs from the try run (comment 143):

 - Even in successful runs, the new waitForTest often times-out:

INFO : waitForTest timeout after 3000 ms

INFO : __start_report2.7865772__end_report
__startTimestamp1377294590297__endTimestamp

 - In the failure logs, I usually (always?) see just one drawFinished:

08-24 00:27:32.226 D/Robocop ( 2276): Received drawFinished notification

I think this is technically okay, but it seems unusual to me. I thought a page load normally generated quite a few drawFinished's.
I decided to try something new before seeing gbrown's comment:

https://tbpl.mozilla.org/?tree=Try&rev=b9fc920c0f5f

(In reply to Geoff Brown [:gbrown] from comment #245)
> Some thoughts on the logs from the try run (comment 143):
> 
>  - Even in successful runs, the new waitForTest often times-out:
> 
> INFO : waitForTest timeout after 3000 ms
> 
> INFO : __start_report2.7865772__end_report
> __startTimestamp1377294590297__endTimestamp

So maybe that new waitForTest was just acting like a timeout to delay the test a little bit. In my new patch I'm trying to explictly make sure the home pager is hidden, maybe that will work better. 

>  - In the failure logs, I usually (always?) see just one drawFinished:
> 
> 08-24 00:27:32.226 D/Robocop ( 2276): Received drawFinished notification
> 
> I think this is technically okay, but it seems unusual to me. I thought a
> page load normally generated quite a few drawFinished's.

Maybe we're crashing before we have the chance for more drawFinished notifications to fire?
Trying again with a longer timeout:
https://tbpl.mozilla.org/?tree=Try&rev=4f93bd2715ee

Maybe this is an issue with the tegras just being slower to hide the HomePager? I'm not sure why else this just seems to be an issue on 2.2 not 4.0.
Margaret - Shane Tully had a Tegra (I think) in the SF office. Could you get it and try to run the test? Maybe the Android 2.2 OS is really slow to show/hide the Home page UI? I thought I saw a bug about Fig being slow on 2.2.
The last try run was a lot greener, I think we just needed a larger max wait time for the tegras. I triggered more test runs to get more data, but at this point I think we should land something if we know it's an improvement.
Attachment #794960 - Attachment is obsolete: true
Attachment #796072 - Flags: review?(gbrown)
Comment on attachment 796072 [details] [diff] [review]
wait for HomePager to be hidden

Should verifyHomePagerHidden() be part of loadAndPaint()?
Attachment #796072 - Flags: review?(gbrown) → review+
(In reply to Geoff Brown [:gbrown] from comment #319)
> Comment on attachment 796072 [details] [diff] [review]
> wait for HomePager to be hidden
> 
> Should verifyHomePagerHidden() be part of loadAndPaint()?

Here's a try push that does that:
https://tbpl.mozilla.org/?tree=Try&rev=4ba851225b4c

I was hesitant to do this before because I didn't want to risk problems to other tests, but it does seem like a sensible change to try.

If this doesn't work out, I'll just go ahead and land the previous patch.