994819 - Sending many SMS messages rapidly causes AbortError

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::Cost Control, defect)

Description

[Carol Yang [:cyang]]

This is related to bug 936703.

Running on Moz RIL or reference RIL, I see the following when rapidly sending SMS messages out:

11318:04-08 14:18:40.654   224   224 E GeckoConsole: [JavaScript Error: "AbortError"]

Comment 1

[Preeti Raghunath(:Preeti)]

blocks a blocker

Comment 2

[Preeti Raghunath(:Preeti)]

nom'ing for 1.4 as it blocks a blocker.

Comment 3

[Steve Chung [:steveck]]

Hi Bevis, could you help investigate whether this AbortErrorcomes comes from message db or other place? Thanks.

Comment 4

[Bevis Tseng[:bevis][:btseng](Exited)]

Can we have STR and what's the impact on the device after showing this error?
It's hard to know where is error come from with only one line log.

So far, I didn't see "AbortError" is defined in MobileMessage related implementation.

Comment 5

[Julien Wajsberg [:julienw]]

I've seen in the past that "AbortError" is sent by the IndexedDB implementation.

Now, I don't see why this should be a blocker: would a user do this? Or even be capable of doing this?

Comment 6

[Vicamo Yang [:vicamo][:vyang]]

(In reply to Bevis Tseng [:bevistseng] ([e-mail]) from comment #4)
> Can we have STR and what's the impact on the device after showing this error?
> It's hard to know where is error come from with only one line log.
> 
> So far, I didn't see "AbortError" is defined in MobileMessage related
> implementation.

That's an IndexedDB error.  We can probably try to have a test script that sends multiple SMS in a short time to observe this.  If that doesn't happen, try to send via Gaia SMS app.

Comment 7

[Carol Yang [:cyang]]

> That's an IndexedDB error.  We can probably try to have a test script that
> sends multiple SMS in a short time to observe this.  If that doesn't happen,
> try to send via Gaia SMS app.

I initially started seeing this when sending multiple SMSs out via a test script. But it is rather easy to reproduce even with Gaia SMS app directly. Just send about 5-10 SMS messages to the same number quickly (type and send while the previous message is still being sent).

Comment 8

[Bevis Tseng[:bevis][:btseng](Exited)]

I just reproduced this locally.
1. send 6 SMS to the same recipient quickly.
2. From the log, I saw the AbortError twice.
3. 6 SMS are sent successfully.
4. 6 SMS are stored in DB successfully even after device reboot.
5. 6 SMS are received in the remote side correctly.

However, I didn't see any impact that causes this as a 1.4 blocker.

Comment 9

[Bevis Tseng[:bevis][:btseng](Exited)]

04-16 10:23:12.249  5826  5826 E GeckoConsole: [JavaScript Error: "AbortError"]
04-16 10:23:12.249  5826  6186 E GeckoConsole: [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:864"]

Comment 10

[Bevis Tseng[:bevis][:btseng](Exited)]

(In reply to Bevis Tseng [:bevistseng] ([e-mail]) from comment #9)
> 04-16 10:23:12.249  5826  5826 E GeckoConsole: [JavaScript Error:
> "AbortError"]
> 04-16 10:23:12.249  5826  6186 E GeckoConsole: [JavaScript Error: "IndexedDB
> UnknownErr: IDBTransaction.cpp:864"]

http://hg.mozilla.org/mozilla-central/file/16e9cda44250/dom/indexedDB/IDBTransaction.cpp#l864

Comment 11

[Anshul]

(In reply to Bevis Tseng [:bevistseng] ([e-mail]) from comment #8)
> I just reproduced this locally.
> 1. send 6 SMS to the same recipient quickly.
> 2. From the log, I saw the AbortError twice.
> 3. 6 SMS are sent successfully.
> 4. 6 SMS are stored in DB successfully even after device reboot.
> 5. 6 SMS are received in the remote side correctly.
> 
> However, I didn't see any impact that causes this as a 1.4 blocker.
Hello Bevis, these abort errors cause our test scripts to fail and without them it is very hard for us to ensure the quality of a release on a daily basis. This is not a new issue and has been plaguing us for a long time now. Unless this is marked a blocker I don't see anyone paying attention to it and so I would request to please consider this a blocker.

Comment 12

[Bevis Tseng[:bevis][:btseng](Exited)]

(In reply to Anshul from comment #11)
> Hello Bevis, these abort errors cause our test scripts to fail and without
> them it is very hard for us to ensure the quality of a release on a daily
> basis. This is not a new issue and has been plaguing us for a long time now.
> Unless this is marked a blocker I don't see anyone paying attention to it
> and so I would request to please consider this a blocker.

Thanks for clarification. We'll look into this and feedback you soon.

Comment 13

[Bevis Tseng[:bevis][:btseng](Exited)]

After printing out the database name before rising the error of [JavaScript Error: "IndexedDB UnknownErr: IDBTransaction.cpp:864"],
I found that the database of this transaction |asyncStorage| even the solution in bug 936703 already included.
Need to dig out why there is access to asyncStorage after IndexedDBDatabaseParent::ActorDestroy().

Comment 14

[Bevis Tseng[:bevis][:btseng](Exited)]

After commenting this line in costcontrol app [1] to updateSMSCount(), I can not reproduce this problem anymore.
[1] https://github.com/mozilla-b2g/gaia/blob/master/apps/costcontrol/js/message_handler.js#L509

In addition, I found that coscontrol app was executed in the preallocated slave process by nuwa.

NI salva for further clarification of cost control app to see if
there is any clue that causes the access to the asyncStorage abnormally.

Comment 15

[Jason Smith [:jsmith]]

CS blocker - so blocking+

Comment 16

[Bevis Tseng[:bevis][:btseng](Exited)]

Since this issue is more related to costcontrol app & the shared module of async_storage.js in gaia instead of RIL,
I'd like to ni correct owners(salva, david) who are more familiar with this to follow up.

Comment 17

[Julien Wajsberg [:julienw]]

Hey Fernando, maybe you can help with this FTU issue?

Comment 18

[David Flanagan [:djf]]

Ben: Do you know what the internal error at IDBTransaction.cpp:864 is about? (See comment #10)  Could there be something going wrong in gecko here?

Salva: How does the cost control app work when an SMS message is received? If lots of messages are received at the same time, is it possible that there could be two instances of the app running (and modifying the async storage db) at the same time?

Comment 19

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to David Flanagan [:djf] from comment #18)
> Ben: Do you know what the internal error at IDBTransaction.cpp:864 is about?
> (See comment #10)  Could there be something going wrong in gecko here?

The invalidated state means that the parent process has decided that no further transactions are allowed to succeed for a given database. That usually happens when a transaction is in progress and the window that started the transaction gets closed.

Comment 20

[Wesley Huang [:wesley_huang] (EPM) (NI me)]

Hi Anshul,
From user experience, this doesn't look as critical as a blocker. 
Not sure how bad this impacts QC test script. 
It seems the investigation of root cause is ongoing, so is it possible to defer this as 2.0+ ?
Late fix landing also incurs risk, IMO.

Comment 21

[Fernando Campo (:fcampo)]

(In reply to Julien Wajsberg [:julienw] from comment #17)
> Hey Fernando, maybe you can help with this FTU issue?
Did you mean to ni? me from another bug? I don't see the relation with FTE in here...

Comment 22

[Anshul]

(In reply to Wesley Huang [:wesley_huang] from comment #20)
> Hi Anshul,
> From user experience, this doesn't look as critical as a blocker. 
> Not sure how bad this impacts QC test script. 
> It seems the investigation of root cause is ongoing, so is it possible to
> defer this as 2.0+ ?
> Late fix landing also incurs risk, IMO.
Wesley, I am fine with this change not landing on 1.4 but I would like to have some one work on it so we have a patch that we can pull in internally to enable our tests.

Comment 23

[Julien Wajsberg [:julienw]]

(In reply to Fernando Campo (:fcampo) from comment #21)
> (In reply to Julien Wajsberg [:julienw] from comment #17)
> > Hey Fernando, maybe you can help with this FTU issue?
> Did you mean to ni? me from another bug? I don't see the relation with FTE
> in here...

Yeah I really got confused, sorry.

Comment 24

[Kai-Chih Hu [:khu]]

(In reply to Anshul from comment #22)
> (In reply to Wesley Huang [:wesley_huang] from comment #20)
> > Hi Anshul,
> > From user experience, this doesn't look as critical as a blocker. 
> > Not sure how bad this impacts QC test script. 
> > It seems the investigation of root cause is ongoing, so is it possible to
> > defer this as 2.0+ ?
> > Late fix landing also incurs risk, IMO.
> Wesley, I am fine with this change not landing on 1.4 but I would like to
> have some one work on it so we have a patch that we can pull in internally
> to enable our tests.

Thanks, Anshul. 

No matter how, we should find someone to work on it of course. 
David, because you're the owner for this component(Cost Control), do you think that you can help to find someone to work on it? Thanks!

Comment 25

[David Flanagan [:djf]]

Comment 19 seems like a seriously big hint here about what is going on.  Whoever takes this bug might want to check how the app is exiting and have it wait for the async_storage update to call its success callback.

Comment 26

[Salvador de la Puente González [:salva]]

(In reply to David Flanagan [:djf] from comment #18)
> Ben: Do you know what the internal error at IDBTransaction.cpp:864 is about?
> (See comment #10)  Could there be something going wrong in gecko here?
> 
> Salva: How does the cost control app work when an SMS message is received?
> If lots of messages are received at the same time, is it possible that there
> could be two instances of the app running (and modifying the async storage
> db) at the same time?

Hi David. Nop. In theory, the system message is dispatched to the same window if there is a window already open. It should not open another window or process. If it does, it is not related with CC app but with window manager.

Nevertheless, I'm thinking it is possible the Cost Control application try to closes itself before completing all transactions but I though bug 936703 solved this.

Comment 27

[Jason Smith [:jsmith]]

Backlog per comment 24 - this isn't required for 1.4 anymore.

Comment 28

[Joe Cheng [:jcheng] (please needinfo)]

ni? reporter to confirm again as bug 936703 is solved

Comment 29

[Anshul]

(In reply to Joe Cheng [:jcheng] from comment #28)
> ni? reporter to confirm again as bug 936703 is solved
Joe, as per comment #0, the bug 936703 doesn't solve the problem.

Comment 30

[Vicamo Yang [:vicamo][:vyang]]

(In reply to Salvador de la Puente González [:salva] from comment #26)
> Nevertheless, I'm thinking it is possible the Cost Control application try
> to closes itself before completing all transactions but I though bug 936703
> solved this.

Hi, like I've pointed out in bug 936703 comment 49, the resolved state of bug 936703 doesn't follow that Cost Control will then be free of similar problems.  All that bug 936703 does is to prevent actions being taken before an IndexedDB transaction really completes.  However, there can still be cascaded transactions, and there can still be multiple concurrent transactions.  That's why you see the STR to replicate this bug is to "rapidly send SMS messages out".  These composite, concurrent transactions themselves become another super-transaction and absolutely need to take extra care, and it's beyond the work in bug 936703 but similar.

Comment 31

[Vicamo Yang [:vicamo][:vyang]]

There are multiple weaknesses in cost control app:

1) apps/costcontrol/js/config/config_manager.js, function requestSettings, https://github.com/mozilla-b2g/gaia/blob/master/apps/costcontrol/js/config/config_manager.js#L174, callback may be invoked while a companion asyncStorage.setItem() call is on going.

2) apps/costcontrol/js/config/config_manager.js, function setOption, https://github.com/mozilla-b2g/gaia/blob/master/apps/costcontrol/js/config/config_manager.js#L234, callback may be invoked while a companion requestSettings() call is on going.

3) apps/costcontrol/js/config/config_manager.js, function syncOption, https://github.com/mozilla-b2g/gaia/blob/master/apps/costcontrol/js/config/config_manager.js#L250, no way to track complete state because this call doesn't accept a callback.

4) apps/costcontrol/js/message_handler.js, function _onNetworkAlarm, https://github.com/mozilla-b2g/gaia/blob/master/apps/costcontrol/js/message_handler.js#L333, function closeIfProceeds may be invoked while a companion ConfigManager.setOption() call is on going.

Just a rough scan of these two files.

Comment 32

[Vicamo Yang [:vicamo][:vyang]]

Cancel NI per comment 29, 30, 31.

Comment 33

[Vicamo Yang [:vicamo][:vyang]]

(In reply to Vicamo Yang [:vicamo][:vyang] from comment #31)
> There are multiple weaknesses in cost control app:

In my opinion, these weaknesses are probably not the root cause of this bug, but they can also become practical problems under some serious stress tests.  The root cause should be the racing between multiple system message handler transactions. I think.

Comment 34

[Vicamo Yang [:vicamo][:vyang]]

Reproducible with emulator.

Comment 35

[Vicamo Yang [:vicamo][:vyang]]

(In reply to Vicamo Yang [:vicamo][:vyang] from comment #33)
> In my opinion, these weaknesses are probably not the root cause of this bug,
> but they can also become practical problems under some serious stress tests.
> The root cause should be the racing between multiple system message handler
> transactions. I think.

Oops! It seems 2) alone is sufficient enough to wipes out all the AbortError messages from logcat.

Comment 36

[Vicamo Yang [:vicamo][:vyang]]

(In reply to Vicamo Yang [:vicamo][:vyang] from comment #35)
> Oops! It seems 2) alone is sufficient enough to wipes out all the AbortError
> messages from logcat.

I don't have a good reason for this.  I thought that requestAll() is not re-entrant safe and might break normal control flow so no error was emitted, but it's not.  Anyway, I'm going to send a patch for this.

Comment 37

[Vicamo Yang [:vicamo][:vyang]]

Attachment: Github PR for Gaia

Comment 38

[Vicamo Yang [:vicamo][:vyang]]

Attachment: patch

This patch is generated from previous git pull request (attachment 8416849 [details] [review]) for review.  It fixes only 1), 2), and 4) I mentioned in comment 31.  However, 2) alone is sufficient for this bug.

Comment 39

[Salvador de la Puente González [:salva]]

Comment on attachment 8416851 [details] [diff] [review]
patch

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

Just attend the comments I leave you. Thank you very much for spotting these weakness.

::: apps/costcontrol/js/config/config_manager.js
@@ +222,5 @@
>      var currentICCID = Common.dataSimIccId || NO_ICCID;
>      asyncStorage.setItem(currentICCID, JSON.stringify(settings),
>        function _onSet() {
>          requestSettings(Common.dataSimIccId, function _onSettings(settings) {
> +          if (callback) {

I would prefer this call to be at the end of the process, I mean after dispatching the events.

::: apps/costcontrol/js/message_handler.js
@@ +328,5 @@
>          var limitText = Formatting.formatData(Formatting.smartRound(limit));
>          var title = _('data-limit-notification-title2', { limit: limitText });
>          var message = _('data-limit-notification-text2');
>          NotificationHelper.send(title, message, iconURL, goToDataUsage);
> +        ConfigManager.setOption({ 'dataUsageNotified': true }, closeIfProceeds);

Nice, thank you.

Comment 40

[Vicamo Yang [:vicamo][:vyang]]

Comment on attachment 8416851 [details] [diff] [review]
patch

Addressed review comments in pull request.

Comment 41

[Vicamo Yang [:vicamo][:vyang]]

Comment on attachment 8416849 [details] [review]
Github PR for Gaia

This pull request solves the problem in my emulator box, but I still need further confirmation from you.  Thanks.

Comment 42

[Carol Yang [:cyang]]

Comment on attachment 8416849 [details] [review]
Github PR for Gaia

Sorry I've been out of the office for the last few weeks. Just pulled this patch in and stopped seeing abort errors while running my test case which rapidly sends SMS out.

Comment 43

[Vicamo Yang [:vicamo][:vyang]]

(In reply to Carol Yang [:cyang] from comment #42)
> Sorry I've been out of the office for the last few weeks. Just pulled this
> patch in and stopped seeing abort errors while running my test case which
> rapidly sends SMS out.

Never mind.  Good to know it works for you as well.  Thank you!

Comment 44

[Vicamo Yang [:vicamo][:vyang]]

https://github.com/mozilla-b2g/gaia/commit/4c8c9c166b2e4b3a3628de0631b437d4f0c6063e

https://hg.mozilla.org/integration/b2g-inbound/rev/37efa1d32c1b