964228 - Race condition in NetworkStatsService.jsm

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Albert [:albert]]

As seen in bug 961162 there is a race condition in 'saveStats' and 'updateCachedStats' functions. Is necessary to add a mechanism to ensure single or synchronized access to 'cachedStats' array.

Comment 1

[Albert [:albert]]

Race condition can be identified because cachedStats array is cleared before calling _db.saveStats and produces the following error:

 E/GeckoConsole( 3649): [JavaScript Error: "aStats is undefined" {file: "resource://gre/modules/NetworkStatsDB.jsm" line: 258}]

Comment 2

[John Shih]

I'll work on it

Comment 3

[Marina Rodríguez [:mai]]

FYI: 
I obtain the same error when I browse with Gecko-c5866e0 and Gaia-bb2e2f3:

E/GeckoConsole(  822): [JavaScript Error: "aStats is undefined" {file: "resource://gre/modules/NetworkStatsDB.jsm" line: 354}]

Regards

Comment 4

[Marina Rodríguez [:mai]]

Occurs the same on v1.3 branch, after browse, when open datausage, I saw the same error:

E/GeckoConsole(  477): [JavaScript Error: "aStats is undefined" {file: "resource://gre/modules/NetworkStatsDB.jsm" line: 234}]
E/GeckoConsole(  477): [JavaScript Error: "aStats is undefined" {file: "resource://gre/modules/NetworkStatsDB.jsm" line: 234}]

Comment 5

[Marina Rodríguez [:mai]]

I've been seeing occasionally this bug with the following STR:

1. Browse 
2. Starts the data usage app. 

Actual behaviour:
  After launching the usage app, the data usage chart is not displayed. 
Expected behavior:
  Usage app can display data usage chart

After the error is produced if you reopen the application the behaviour is normal. 
 
I tried to reproduce several times this bug and it doesn't occurs always, approximately the twenty percent of the time with the previous STR.

Regards

Comment 6

[Noemí Freire (:noemi)]

Per comment 5 nominating to v1.3?

Comment 7

[John Shih]

Sorry I was stuck on another emergency blocker this week. Will work on this bug ASAP. (As I said in  Comment 2, I believe this bug will be covered by the work in Bug 928289, which is going to re-factor some logic of NetworkStatsService).

Comment 8

[Preeti Raghunath(:Preeti)]

Please do not rely on the feature Bug 928289. 1.3+

Comment 9

[John Shih]

Attachment: (v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

In the patch I en-queue all the operations related to DB/cached read&write and It works for me.
But since I don't have a good STR to reproduce the race condition, I might need you or QA can help on test this solution.

Comment 10

[John Shih]

Could you help on testing with the patch (or provide a good STR to reproduce the bug)? Actually I can't reproduce the bug on my own v1.3 build. But I still try to refactor the logic in NetworkStatsService and hope can solve the problem.

Comment 11

[Marina Rodríguez [:mai]]

Hi, 
i don't mind testing the patch. The STR to reproduce is explained on Comment 5. 
1. Browse with the navigator.
2.  Minimize the browser, although the page is not completely loaded.
3. Launchs Costcontrol application.

Anyway, I'm going to test now, and i'll give you my feedback ;). 

Regards, 
Mai

Comment 12

[John Shih]

(In reply to marina rodríguez [:mai] from comment #11)
> Hi, 
> i don't mind testing the patch. The STR to reproduce is explained on Comment
> 5. 
> 1. Browse with the navigator.
> 2.  Minimize the browser, although the page is not completely loaded.
> 3. Launchs Costcontrol application.
> 
> Anyway, I'm going to test now, and i'll give you my feedback ;). 
> 
> Regards, 
> Mai

Thanks for your help!

Comment 13

[Albert [:albert]]

Comment on attachment 8384437 [details] [diff] [review]
(v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

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

I can reproduce the bug in 1.3 and it is fixed with your patch

Thanks John!

::: dom/network/src/NetworkStatsService.jsm
@@ +549,5 @@
>      }
>  
> +    // Prevent from executing processQueue multiple times while queue is already
> +    // under process
> +    if (this.isQueueRunning) {

'if' not needed, same 'if' statement is evaluated in processQueue function.

@@ +702,5 @@
> +                            queueType: QUEUE_TYPE_WRITE_CACHE });
> +
> +    // Prevent from executing processQueue multiple times while queue is already
> +    // undger process.
> +    if (this.isQueueRunning) {

ditto

@@ +779,5 @@
> +    this.updateQueue.push({ callbacks: [aCallback],
> +                            queueType: QUEUE_TYPE_UPDATE_CACHE });
> +    // Prevent from executing processQueue multiple times while queue is already
> +    // undger process.
> +    if (this.isQueueRunning) {

ditto

Comment 14

[John Shih]

(In reply to Albert [:albert] from comment #13)
> Comment on attachment 8384437 [details] [diff] [review]
> (v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene,
> albert
> 
> Review of attachment 8384437 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I can reproduce the bug in 1.3 and it is fixed with your patch
> 
> Thanks John!
> 
> ::: dom/network/src/NetworkStatsService.jsm
> @@ +549,5 @@
> >      }
> >  
> > +    // Prevent from executing processQueue multiple times while queue is already
> > +    // under process
> > +    if (this.isQueueRunning) {
> 
> 'if' not needed, same 'if' statement is evaluated in processQueue function.
> 
> @@ +702,5 @@
> > +                            queueType: QUEUE_TYPE_WRITE_CACHE });
> > +
> > +    // Prevent from executing processQueue multiple times while queue is already
> > +    // undger process.
> > +    if (this.isQueueRunning) {
> 
> ditto
> 
> @@ +779,5 @@
> > +    this.updateQueue.push({ callbacks: [aCallback],
> > +                            queueType: QUEUE_TYPE_UPDATE_CACHE });
> > +    // Prevent from executing processQueue multiple times while queue is already
> > +    // undger process.
> > +    if (this.isQueueRunning) {
> 
> ditto

Yes, I also notice the duplicated logic here. But when I remove these check and test, the successive processQueue call (without callback) could occur, which doesn't happen with these check. I'm guessing there is a timing issue or other problems. Will investigate more on it tomorrow.

Comment 15

[John Shih]

Attachment: (v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

Patch update: remove redundant 'if' statement.

Comment 16

[John Shih]

Hi Albert,

After investigating deeper on the patch, I found another timing issue:
the error message is 
E/GeckoConsole(  520): [JavaScript Error: "item is undefined" {file: "resource://gre/modules/NetworkStatsService.jsm" line: 584}]

It is caused by while a queue is under process (with multiple callbacks), another processQueue() is called. In this case, the processQueue() will be called one more time. 

Please see the log below for more clear:
I/Gecko   (  520): jshih 4 processQueue start undefined
I/Gecko   (  520): jshih 4 queueType 0
I/Gecko   (  520): jshih 5 processQueue start true
I/Gecko   (  520): jshih 5 queue [{"netId":"00","callbacks":[null,null,null],"queueType":0}]
* Begins to handle execute callbacks
I/Gecko   (  520): jshih 6 processQueue start undefined
* Another processQueue is called
I/Gecko   (  520): jshih 6 queueType 1
I/Gecko   (  520): jshih 7 processQueue start undefined
I/Gecko   (  520): jshih 7 queue is running (length > 1). return.
I/Gecko   (  520): jshih 8 processQueue start undefined
I/Gecko   (  520): jshih 8 queue is running (length > 1). return.
I/Gecko   (  520): jshih 5 queueType 1
* Previous callbacks handling is ended. Cause executing processQueue one more time.
I/Gecko   (  520): jshih 9 processQueue start true
I/Gecko   (  520): jshih 9 queue [{"callbacks":[null],"queueType":1},{"callbacks":[null],"queueType":1},{"callbacks":[null],"queueType":1}]
I/Gecko   (  520): jshih 9 queueType 1
I/Gecko   (  520): jshih 10 processQueue start true
I/Gecko   (  520): jshih 10 queue [{"callbacks":[null],"queueType":1},{"callbacks":[null],"queueType":1}]
I/Gecko   (  520): jshih 10 queueType 1
I/Gecko   (  520): jshih 11 processQueue start true
I/Gecko   (  520): jshih 11 queue [{"callbacks":[null],"queueType":1}]
I/Gecko   (  520): jshih 11 turn isQueueRunning to false. return.
I/Gecko   (  520): jshih 12 processQueue start true
I/Gecko   (  520): jshih 12 queue []
* Error occurs, since there is no |callbacks| here.

What do you think on this case? Compare to my original method (add more check of isQueueRunning before each processQueue is called), I think the easy way might be adding a check (updateQueue is empty or not) before 
let item = this.updateQueue.shift();

Comment 17

[John Shih]

Attachment: (v1.3)NetworkStatsService.jsm with debug message

Debug message for processQueue

Comment 18

[John Shih]

> 
> What do you think on this case? Compare to my original method (add more
> check of isQueueRunning before each processQueue is called), I think the
> easy way might be adding a check (updateQueue is empty or not) before 
> let item = this.updateQueue.shift();

One more thought! I think we can just change 
if(this.updateQueue.length > 1)
to 
if(this.updateQueue.length > 0)

Comment 19

[John Shih]

Attachment: (v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

Comment 20

[John Shih]

Attachment: Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

patch for mozilla-central

Comment 21

[John Shih]

The modification here will be affected by Bug 922926, Bug 964270, which were tagged as 1.3T+. Ask for triage.

Comment 22

[Albert [:albert]]

John how do you reproduce it?

Comment 23

[John Shih]

(In reply to Albert [:albert] from comment #22)
> John how do you reproduce it?

Firstly you should remove the all the 'if' statements you mentioned in my previous patch, and then remain
if(this.updateQueue.length > 1)

The STR is simple, just open Usage app (mostly occur in the first launch time)
the alternative way is 
1. Open a browser
2. Navigate to a web (find one needs to load for a while, e.g., 'tw.yahoo.com', which I always test with)
3. During wed loading, press home button
4. Launch Usage app

It's easily reproducible for me.

Comment 24

[Albert [:albert]]

Comment on attachment 8385214 [details] [diff] [review]
(v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

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

Looks good for me.

::: dom/network/src/NetworkStatsService.jsm
@@ +578,5 @@
>        // The caller is a function that has pushed new elements to the queue,
>        // if isQueueRunning is false it means there is no processing currently
>        // being done, so start.
>        if (this.isQueueRunning) {
> +        if(this.updateQueue.length > 0) {

Now that we are checking that length > 0, does make sense to have two if statements? I mean, we can return if isQueueRunning. Are you agree?

Comment 25

[Albert [:albert]]

Comment on attachment 8385218 [details] [diff] [review]
Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

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

Looks fine.

Same comment as the one for 1.3 patch regarding the if in processQueue.

Can you launch a try to ensure nothing is broken?

Comment 26

[John Shih]

Attachment: (v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

Update based on Comment 24.

Comment 27

[John Shih]

Attachment: Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

update based on Comment 25

Comment 28

[John Shih]

Attachment: Bug 964228 - Part 1: Fix race condition in NetworkStatsService.jsm. r=gene, albert

Fix some errors founded by testing.

Comment 29

[John Shih]

Attachment: Bug 964228 - Part 2: Tests update. r=gene, albert

tests update for corresponding change

Comment 30

[John Shih]

Attachment: Bug 964228 - Part 2: Tests update. r=gene, albert

fix nits

Comment 31

[John Shih]

Attachment: (v1.3) Bug 964228: Fix race condition in NetworkStatsService.jsm. r=gene, albert

Comment 32

[John Shih]

Attachment: Bug 964228 - Part 2: Tests update. r=gene, albert

Fix nits.

Comment 33

[John Shih]

Attachment: (v1.3) Bug 964228 - Part 2: Tests update. r=gene, albert

Test cases for v1.3

Comment 34

[John Shih]

try result: https://tbpl.mozilla.org/?tree=Try&rev=c35091cad1ee

Comment 35

[Gene Lian (I already quit Mozilla)]

I don't really have time to review this until next week because I'm joining the work week with partners. Having Albert's review is enough to land if we're rushing to fix this for v1.3.

Again, please remember to get Fabrice's approval before uplifting.

Comment 36

[John Shih]

Attachment: (v1.3) Bug 964228 - Part 1: Fix race condition in NetworkStatsService.jsm. r=albert a=fabrice

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
User impact if declined: Caused JS Error sometimes when launch CostControl App
Testing completed: yes
Risk to taking this patch (and alternatives if risky): low
String or UUID changes made by this patch: none

Comment 37

[John Shih]

Comment on attachment 8386610 [details] [diff] [review]
Bug 964228 - Part 1: Fix race condition in NetworkStatsService.jsm. r=gene, albert

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

r=albert.

Comment 38

[John Shih]

Comment on attachment 8386707 [details] [diff] [review]
Bug 964228 - Part 2: Tests update. r=gene, albert

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

Since Gene is not available for review, removing the flag.

Comment 39

[John Shih]

Comment on attachment 8386709 [details] [diff] [review]
(v1.3) Bug 964228 - Part 2: Tests update. r=gene, albert

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

Since Gene is not available for review, removing the flag.

Comment 40

[[:fabrice] Fabrice Desré]

John, just ask for approval when it's ready, I track these.

Comment 41

[Albert [:albert]]

Comment on attachment 8386707 [details] [diff] [review]
Bug 964228 - Part 2: Tests update. r=gene, albert

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

Looks fine

Comment 42

[Albert [:albert]]

Comment on attachment 8386709 [details] [diff] [review]
(v1.3) Bug 964228 - Part 2: Tests update. r=gene, albert

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

Thanks John!

Comment 43

[John Shih]

Fabrice,

I think it is ready for landing now, ask for approval.

Comment 44

[John Shih]

Hi Joe,

As I mentioned in Comment 21, this bug should also be uplifted to 1.3T. Can you take a look and make a confirmation?

Comment 45

[[:fabrice] Fabrice Desré]

John, you need to ask for approval in the patch details page, and fill in the approval questionnaire.

Comment 46

[Albert [:albert]]

John, 1.4 also need the patch.

Comment 48

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

since its 1.3+, it should also get uplifted to 1.3T

Comment 49

[John Shih]

Comment on attachment 8387347 [details] [diff] [review]
(v1.3) Bug 964228 - Part 1: Fix race condition in NetworkStatsService.jsm. r=albert a=fabrice

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

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
User impact if declined: Caused JS Error sometimes when launch CostControl App
Testing completed: yes
Risk to taking this patch (and alternatives if risky): low
String or UUID changes made by this patch: none

Comment 50

[John Shih]

(In reply to Albert [:albert] from comment #46)
> John, 1.4 also need the patch.

The patch for 1.4 is already provided, so I'm guessing you are saying 1.3t, right ? ;)
I'll provide the patch later.

Comment 51

[John Shih]

Attachment: (v1.3t) Bug 964228 - Part 1: Fix race condition in NetworkStatsService.jsm. r=albert a=fabrice

Rebase for v1.3t

Comment 52

[John Shih]

Attachment: (v1.3t) Bug 964228 - Part 2: Tests update. r=gene, albert

rebase for v1.3t

Comment 53

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/861f6c26ef3a
https://hg.mozilla.org/integration/mozilla-inbound/rev/49ec48262f79

Comment 54

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/861f6c26ef3a
https://hg.mozilla.org/mozilla-central/rev/49ec48262f79

Comment 55

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/80069f20fa18
https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/2a8e950d9099

Comment 56

[Ryan VanderMeulen [:RyanVM]]

Goes without saying that this made for some good times when merging b2g28 to v1.3t. Please double-check the files patched in this bug on the 1.3t branch to make sure everything looks sane. Basically what I did was revert them to their pre-merge versions then manually apply the 1.3t patches attached to this bug, and committed the results as part of the merge cset. Everything went smoothly like that, but it would still be nice to get confirmation :)

Comment 57

[John Shih]

Thanks Ryan! I've verified the newest 1.3t build locally, and it works fine (both running device and test cases)

Comment 58

[Ryan VanderMeulen [:RyanVM]]

Thank *you* for posting the 1.3t patches. I would have been completely lost without them :)