975838 - Log things getting touched off the UI Thread

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Richard Newman [:rnewman]]

This bug was filed from the Socorro interface and is 
report bp-ef5d94fb-48d6-41ee-92c5-b95a42140222.
=============================================================

https://crash-stats.mozilla.com/report/index/ef5d94fb-48d6-41ee-92c5-b95a42140222

java.util.ConcurrentModificationException
	at java.util.HashMap$HashIterator.nextEntry(HashMap.java:792)
	at java.util.HashMap$KeyIterator.next(HashMap.java:819)
	at org.mozilla.gecko.menu.GeckoMenu.refresh(GeckoMenu.java:647)
	at org.mozilla.gecko.GeckoApp.onPreparePanel(GeckoApp.java:429)
	at org.mozilla.gecko.GeckoApp.onCreatePanelView(GeckoApp.java:397)
	at com.android.internal.policy.impl.PhoneWindow.preparePanel(PhoneWindow.java:431)
	at com.android.internal.policy.impl.PhoneWindow.openPanel(PhoneWindow.java:626)
	at com.android.internal.policy.impl.PhoneWindow.openPanel(PhoneWindow.java:586)
	at android.app.Activity.openOptionsMenu(Activity.java:2891)
	at org.mozilla.gecko.BrowserApp.openOptionsMenu(BrowserApp.java:2042)

Distinct from Bug 826064.

Comment 1

[Richard Newman [:rnewman]]

Cause: mSecondaryActionItems is being modified by code off the UI thread, and it's racing with openOptionsMenu.

There are a fair few callers of this, so it'll take a little while to poke around in Eclipse and see. 

Adding an assert for being on the UI thread wherever those HashMaps are modified is one good debugging strategy, if someone can repro this.

Another solution is to simply make those HashMaps into ConcurrentHashMaps, and stop worrying about which thread modifies them. That's a little bit cavalier, though.

Comment 2

[Richard Newman [:rnewman]]

There are 85 crashes with this signature in the last week, so nomming.

Comment 3

[Brian Nicholson (:bnicholson)]

Possibly related: Adapter#notifyDataSetChanged() must be called on the UI thread, but we're apparently calling it off the UI thread. Assuming the comment at [1] is correct, note that we call notifyDataSetChanged immediately after that comment at [2].

[1] http://hg.mozilla.org/mozilla-central/file/31113754db3b/mobile/android/base/menu/GeckoMenu.java#l486
[2] http://hg.mozilla.org/mozilla-central/file/31113754db3b/mobile/android/base/menu/GeckoMenu.java#l506

Since the menu is UI and extends ListView, we should require that all GeckoMenu methods be called on the UI thread. Allowing these methods to be called off the UI thread and then posting them a la [1] is messy and error prone.

Comment 4

[Richard Newman [:rnewman]]

Attachment: Scream bloody murder if accessed off the UI thread.

I tried to provoke an error by using the attached patch, but was unable to. It adds assertOnUiThread calls to most methods on GeckoMenu and its inner classes, and additionally replaces HashMap with a UIThreadHashMap implementation, which throws if accessed off the main thread.

Oh well.

Comment 5

[Ashish Namdev]

Hi 

I too had this crash today.

Report ID
bp-b4c90446-618b-4e6e-891b-a66332140224

Comment 7

[Aaron Train [:aaronmt]]

Updated my Nightly from the 19th to today's build on my Galaxy S4. Attempts to open the menu crash the browser.

Comment 8

[Aaron Train [:aaronmt]]

Regression from bug 975525?

Comment 9

[Aaron Train [:aaronmt]]

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=7010ab83a06e&tochange=84c9885475e7 m-c range

Comment 10

[Nick Alexander :nalexander [he/him]]

(In reply to Brian Nicholson (:bnicholson) from comment #3)
> Possibly related: Adapter#notifyDataSetChanged() must be called on the UI
> thread, but we're apparently calling it off the UI thread. Assuming the
> comment at [1] is correct, note that we call notifyDataSetChanged
> immediately after that comment at [2].
> 
> [1]
> http://hg.mozilla.org/mozilla-central/file/31113754db3b/mobile/android/base/
> menu/GeckoMenu.java#l486
> [2]
> http://hg.mozilla.org/mozilla-central/file/31113754db3b/mobile/android/base/
> menu/GeckoMenu.java#l506
> 
> Since the menu is UI and extends ListView, we should require that all
> GeckoMenu methods be called on the UI thread. Allowing these methods to be
> called off the UI thread and then posting them a la [1] is messy and error
> prone.

So, is this the right time to ask Java to help us?  That is, can we annotate methods as needing to be called on the UI thread, and either error or post them to the UI thread if they are not?  Seems like somebody would have built this, a la FindBugs [1].  A quick search turns up [2], which looks pretty messy, but points the way.

At first, I expect this would just be "annotation to assert", but we could try to add static analysis to force callers of annotated code to make appropriate arrangements.

[1] http://findbugs.sourceforge.net
[2] https://github.com/excilys/androidannotations

Comment 11

[Richard Newman [:rnewman]]

bzexport auto-assigned this to me, but I ain't working on it.

Comment 12

[Robert Kaiser]

This has been by far the topcrash on Android Nightly in the last few days, accounting for 3/4 of all crashes yesterday. I see bug 975525 has been backed out, let's see it that helps.

Comment 13

[Aaron Train [:aaronmt]]

Seems fixed for me on today's build. Shall we close this or do we still want the attached patch?

Comment 14

[Aaron Train [:aaronmt]]

Actually I take it back, I can still crash on today's build. The back-out didn't hit m-c yet.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

Merge of backout:
https://hg.mozilla.org/mozilla-central/rev/069f663e7e64

Comment 16

[Ashish Namdev]

I had 12 crashes in a series on yesterday's build : Nightly 30.0a1 (2014-02-25)

Launch Nightly
Tap on Menu to open Firefox Menu 
 1.  Crash!
 2.  Crash!
 3.  Crash!
 4.  Freezed
 5.  Crash! on launch It self.
 6.  Crash!
 7.  Browse for some times then try to open menu - Crash!
 8.  Crash!
 10. Crash!
 11. Crash!
 12. Crash!

Comment 17

[Ashish Namdev]

Submitted Crash Reports : 

     Report ID                            Date Submitted 
bp-9b82ce74-e58f-40df-beb3-00c542140226   02/26/14 17:28
bp-0c50e7a0-7fc0-4089-accc-ee2d82140226   02/26/14 17:28
bp-40bce16a-b3ff-4781-a27c-bca5a2140226   02/26/14 17:26
bp-9c1bcf60-fb66-4df6-bac8-a8fe22140226   02/26/14 17:06
bp-29cebfa9-5116-4122-9238-448112140226   02/26/14 17:05
bp-208d3d1f-1e00-4f01-b82e-56dad2140226   02/26/14 17:04
bp-beb867e6-10ab-455b-8735-309122140226   02/26/14 17:01
bp-a339f777-1963-443f-8019-0fcde2140226   02/26/14 17:01
bp-b4c90446-618b-4e6e-891b-a66332140224   02/24/14 12:20

Comment 18

[Aaron Train [:aaronmt]]

Ashish, yesterday's build of Nightly based off of mozilla-central did not contain the backout as mentioned in comment #14. Today's build, (02/26) should be better.

Comment 19

[Ashish Namdev]

Hi Aaron ,

I am not seeing this issue on  build of 26-02
seems fix has been landed now

Comment 20

[Richard Newman [:rnewman]]

The approach I'd like to take for this: augment assertOnUiThread to fail hard on dev builds (and Nightly?), to log otherwise, and spread it liberally around code that should only be called on the UI thread.

If I can, I'll make that an Annotation, so just anno @UIThread or @NonUIThread.

If we only log, we're relying on developers to read the logs, and we know not many of us do that.

Brian, do you agree with that approach?

Comment 21

[Brian Nicholson (:bnicholson)]

(In reply to Richard Newman [:rnewman] from comment #20)
> The approach I'd like to take for this: augment assertOnUiThread to fail
> hard on dev builds (and Nightly?), to log otherwise, and spread it liberally
> around code that should only be called on the UI thread.
> 
> If I can, I'll make that an Annotation, so just anno @UIThread or
> @NonUIThread.
> 
> If we only log, we're relying on developers to read the logs, and we know
> not many of us do that.
> 
> Brian, do you agree with that approach?

Sounds perfect. I'm glad we're finally untangling this mess!

Comment 22

[Richard Newman [:rnewman]]

Attachment: Part 1: add methods to log or throw if called on the wrong thread. v1

We pass in the argument, 'cos we don't want ThreadUtils to be coupled to our release definitions.

Comment 23

[Richard Newman [:rnewman]]

Attachment: Part 2: pepper GeckoMenu with thread affinities. v1

These are all of the call sites that touch the HashMaps in question.

Comment 24

[Richard Newman [:rnewman]]

Attachment: Part 3: robocop test that a GeckoMenu call will fail on the wrong thread. v1

Yay tests!

Comment 25

[Wesley Johnston (:wesj)]

Comment on attachment 8383319 [details] [diff] [review]
Part 3: robocop test that a GeckoMenu call will fail on the wrong thread. v1

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

::: mobile/android/base/tests/testGeckoMenu.java
@@ +61,5 @@
> +            mAsserter.is(exception, null, "No exception was thrown: release build.");
> +            return;
> +        }
> +
> +        mAsserter.is(exception != null, true, "An exception was thrown.");

We have mAsserter.ok(condition, message, diag). (though I've never understood what diag is supposed to stand for...)

Comment 26

[Wesley Johnston (:wesj)]

Comment on attachment 8383316 [details] [diff] [review]
Part 2: pepper GeckoMenu with thread affinities. v1

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

A couple questions, but I don't hate doing this. Just want clarification. Are we moving things to the UI thread because they definately do UI things.

If we get a call from Gecko to add a menu item, in most cases that code doesn't need to run on the UI thread at all. It updates a list that updates an adapter that doesn't do anything if the menu isn't currently showing. This forces a few of those code paths onto the UI thread (I think?).

::: mobile/android/base/menu/GeckoMenu.java
@@ +160,5 @@
>          return menuItem;
>      }
>  
>      private void addItem(GeckoMenuItem menuItem) {
> +        ThreadUtils.assertOnUiThread(!AppConstants.RELEASE_BUILD);

Do we care that this is only called on the UI Thread? This method doesn't actually update UI, it just updates our list (which may update the UI....). Are we using this as a hefty synchronization method here? This does call adapter.addMenuItem, which would eventually call notifyDataSetChanged, which might update the UI.

So I guess I'm curious here, would we rather force you onto the UI thread early or wait until we really know you need to be on it?

@@ +359,5 @@
>      }
>  
>      @Override
>      public boolean hasVisibleItems() {
> +        ThreadUtils.assertOnUiThread(!AppConstants.RELEASE_BUILD);

This just queries the in memory data stores. It seems better to synchronize it on them if we're worried...

Comment 27

[(inactive) Jim Chen [:jchen] [:darchons]]

(In reply to Richard Newman [:rnewman] from comment #22)
> Created attachment 8383315 [details] [diff] [review]
> Part 1: add methods to log or throw if called on the wrong thread. v1
> 
> We pass in the argument, 'cos we don't want ThreadUtils to be coupled to our
> release definitions.

Drive-by comment: you can also introduce a "strict mode" that, once set, throws on assertion failure instead of logs. This way you don't have to repeat |!AppConstants.RELEASE_BUILD| a bunch of times :)

Comment 28

[Brian Nicholson (:bnicholson)]

(In reply to Wesley Johnston (:wesj) from comment #26)
> doesn't need to run on the UI thread at all. It updates a list that updates
> an adapter that doesn't do anything if the menu isn't currently showing.

Without seeing the code in question, the "updates an adapter" part of this sounds dangerous. Adapter is not thread-safe, and updates must always happen on the UI thread.

Comment 29

[Wesley Johnston (:wesj)]

Comment on attachment 8383315 [details] [diff] [review]
Part 1: add methods to log or throw if called on the wrong thread. v1

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

Whoops. I forgot to hit send on this.

::: mobile/android/base/GeckoEditable.java
@@ +360,5 @@
>          return mIcRunHandler.getLooper() == Looper.myLooper();
>      }
>  
>      private void assertOnIcThread() {
> +        ThreadUtils.assertOnThread(mIcRunHandler.getLooper().getThread(), true);

I hate boolean parameters. Can we pass an enum value?

Comment 30

[Richard Newman [:rnewman]]

Switched to an enum, did a little tidying, landed in two parts.

Thanks, chaps!

   https://hg.mozilla.org/integration/fx-team/rev/1e8fa32e8abd
   https://hg.mozilla.org/integration/fx-team/rev/02bceb824051

Comment 31

[Richard Newman [:rnewman]]

I backed this out because the test apparently stopped working.

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

   https://hg.mozilla.org/integration/fx-team/rev/d903a9acda02
   https://hg.mozilla.org/integration/fx-team/rev/c0ef88442945

Will fix and reland in the morning.

Comment 32

[Richard Newman [:rnewman]]

Relanded with a JUnit3 test, rather than a Robocop test.

   https://hg.mozilla.org/integration/fx-team/rev/3ccf68571575
   https://hg.mozilla.org/integration/fx-team/rev/67a7d2c4e987

Comment 33

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/3ccf68571575
https://hg.mozilla.org/mozilla-central/rev/67a7d2c4e987