908426 - "System JS : ERROR jar:file:///system/b2g/omni.ja!/components/WifiWorker.js:2943 TypeError: this._stateRequests[0] is undefined" in green B2G mochitest-8 runs

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Wifi, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

+++ This bug was initially created as a clone of Bug #904631 +++

Looks like it started after bug 888227 landed.

https://tbpl.mozilla.org/php/getParsedLog.php?id=26887699&tree=B2g-Inbound

b2g_emulator_vm b2g-inbound opt test mochitest-8 on 2013-08-22 13:09:41 PDT for push 39599246f51b
slave: tst-linux64-ec2-024

13:13:29     INFO -  System JS : ERROR jar:file:///system/b2g/omni.ja!/components/WifiWorker.js:2943
13:13:29     INFO -                       TypeError: this._stateRequests[0] is undefined

Comment 1

[Henry Chang [:hchang]]

It doesn't seem to be caused by bug 888227 but I will look into it anyways. Thanks.

Comment 2

[Ryan VanderMeulen [:RyanVM]]

All I can say with certainty is that it started on that push. That much is clear from the logs. Maybe bug 888227 just exposed the underlying issue.

Comment 3

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

maybe replace |callback| with |callback.bind(this)| in http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2930

Comment 4

[Henry Chang [:hchang]]

(In reply to Chuck Lee [:chucklee] from comment #3)
> maybe replace |callback| with |callback.bind(this)| in
> http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2930

But |callback| doesn't access |this| at all? It only access |self| instead of |this|.

Comment 5

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

If the |_notifyAfterStateChange()| is cascaded on long wait like following condition:

< 1st entry, called by WifiManager >
_notifyAfterStateChange() {
  this._callbackTimer.initWithCallback(_notifyAfterStateChange);
}
< 2nd entry, called by Timer >
_notifyAfterStateChange() {
  this._callbackTimer.initWithCallback(_notifyAfterStateChange);
}

I think after 2nd entry, the |self| no longer points to |WifiManager|:
1st entry: |_notifyAfterStateChange| is called by WifiManager, so |self = this = WifiManager|.
2nd entry(and so on): |_notifyAfterStateChange| is called by Timer, so |self = this = Timer|.

Comment 6

[Henry Chang [:hchang]]

(In reply to Chuck Lee [:chucklee] from comment #5)
> If the |_notifyAfterStateChange()| is cascaded on long wait like following
> condition:
> 
> < 1st entry, called by WifiManager >
Actually, it's called by WifiWorker:

"this._notifyAfterStateChange(false, this._stateRequests[0].enabled);"
http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2943

|this| here is guaranteed to be WifiWorker since we bound it when registering as a callback: WifiManager.setWifiEnabled(msg.enabled, this._setWifiEnabledCallback.bind(this));
http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2966

> _notifyAfterStateChange() {
>   this._callbackTimer.initWithCallback(_notifyAfterStateChange);
> }
> < 2nd entry, called by Timer >
> _notifyAfterStateChange() {
>   this._callbackTimer.initWithCallback(_notifyAfterStateChange);
> }
> 
> I think after 2nd entry, the |self| no longer points to |WifiManager|:
> 1st entry: |_notifyAfterStateChange| is called by WifiManager, so |self =
> this = WifiManager|.
> 2nd entry(and so on): |_notifyAfterStateChange| is called by Timer, so |self
> = this = Timer|.
The value of |self| has been determined at this line: "self = this;" and will no longer be changed.
http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2909
|this| does point to Timer, but |self| still points to the same object since it's a reference but not something like a reference to a reference.

Besides, if _notifyAfterStateChange is called by anyone other than WifiWorker, the first line: "if (!this._stateRequests.length)"
http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2877
will throw an exception since WifiWorker is the only object owning _stateRequests.

By the way, I couldn't reproduce this error on emulator. Can anyone reproduce it?

Comment 7

[Henry Chang [:hchang]]

> > I think after 2nd entry, the |self| no longer points to |WifiManager|:
> > 1st entry: |_notifyAfterStateChange| is called by WifiManager, so |self =
> > this = WifiManager|.
> > 2nd entry(and so on): |_notifyAfterStateChange| is called by Timer, so |self
> > = this = Timer|.
> The value of |self| has been determined at this line: "self = this;" and
> will no longer be changed.
> http://mxr.mozilla.org/mozilla-central/source/dom/wifi/WifiWorker.js#2909
> |this| does point to Timer, but |self| still points to the same object since
Sorry for something unclear here. What I was saying is |this| points to Timer in the closure:
callback = function(timer) {
             self._notifyAfterStateChange(success, newState);
             timer = null;
           };
but not in _notifyAfterStateChange()
> it's a reference but not something like a reference to a reference.

Comment 8

[Henry Chang [:hchang]]

One of the patches in bug 906631 is trying to refactor the use of command queue, which is highly related to this issue. I am figuring the patch out and see if it fixes this issue.

Comment 9

[Henry Chang [:hchang]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #2)
> All I can say with certainty is that it started on that push. That much is
> clear from the logs. Maybe bug 888227 just exposed the underlying issue.

Hi Ryan:

Did you see any other identical error on TPBL? I can neither reproduce it nor found the same error occurred in the later builds. According to the log, not even one test had been running...

Comment 10

[Ryan VanderMeulen [:RyanVM]]

Yep, still happens.
https://tbpl.mozilla.org/php/getParsedLog.php?id=27196783&tree=Mozilla-Central

b2g_emulator_vm mozilla-central opt test mochitest-8 on 2013-08-29 15:29:50 PDT for push 8c5a94ba1096
slave: tst-linux64-ec2-364

15:32:44     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: start.
15:32:53     INFO -  remount succeeded
15:33:34     INFO -  1377815579887	Marionette	INFO	MarionetteComponent loaded
15:33:34     INFO -  1377815580196	Marionette	INFO	marionette enabled via build flag and pref
15:33:34     INFO -  -*- RadioInterfaceLayer: 1 interfaces
15:33:34     INFO -  1377815586816	Marionette	INFO	marionette-server.js loaded
15:33:34     INFO -  1377815588086	Marionette	INFO	B2G emulator: yes
15:33:34     INFO -  1377815588099	Marionette	INFO	Device detected is generic
15:33:34     INFO -  1377815588108	Marionette	INFO	Bypassing offline status.
15:33:34     INFO -  1377815588137	Marionette	INFO	Listening on port 2828
15:33:34     INFO -  1377815588142	Marionette	INFO	Marionette server ready
15:33:34     INFO -  1377815589655	Marionette	DEBUG	accepted connection on 127.0.0.1:33108
15:33:34     INFO -  PermissionsTable.jsm: expandPermissions: Unknown Permission: network-tcpPermissionsTable.jsm: expandPermissions: Unknown Permission: network-httpPermissionsInstaller.jsm: 'network-tcp' is not a valid Webapps permission name.PermissionsInstaller.jsm: 'network-http' is not a valid Webapps permission name.1377815607217	Marionette	DEBUG	accepted connection on 127.0.0.1:33109
15:33:34     INFO -  System JS : ERROR jar:file:///system/b2g/omni.ja!/components/WifiWorker.js:2932
15:33:34     INFO -                       TypeError: this._stateRequests[0] is undefined
15:33:34     INFO -  1377815607420	Marionette	TRACE	Got: {"to": "root", "type": "getMarionetteID"}
15:33:34     INFO -  1377815608518	Marionette	TRACE	Got: {"to": "0", "type": "newSession"}
15:33:34     INFO -  1377815611955	Marionette	INFO	loaded marionette-listener.js
15:33:34     INFO -  1377815611977	Marionette	INFO	sendToClient: {"from":"0","value":"6-b2g"}, {29329a98-6a6b-478b-86cc-1acf1ec062da}, {29329a98-6a6b-478b-86cc-1acf1ec062da}

Comment 11

[Henry Chang [:hchang]]

I also found the same errors. The weird things is, it only happens just "before" the mochitest test chunk 8... I added some debug log and attempted to reproduce on try server (since I cannot reproduce it on my machine) but failed. (https://tbpl.mozilla.org/php/getParsedLog.php?id=27322259&tree=Try)
Is it okay to continue to test on try server? (I am afraid of making the try server overloading) Or is there any way to add the "mochitest only" debug log so that we can get the debug log on every build?

Comment 12

[Ryan VanderMeulen [:RyanVM]]

Test away! Those tests run on AWS, so we have plentiful slave resources :)

Comment 13

[Henry Chang [:hchang]]

From the debugging log https://tbpl.mozilla.org/php/getParsedLog.php?id=27412916&tree=Try&full=1#error0
WifiManager.setWifiEnabled() is called only once but calls _setWifiEnabledCallback twice. 
It's due to NetworkManager::setWifiOperationMode is call-backed twice. I think here is what's happening:

1. One of the NetworkManager function which passes an unnamed callback to contrlMessage is called before  NetworkManager::setWifiOperationMode()
2. NetworkManager::setWifiOperationMode also passes an unnamed  callback to controlMessage, which overrides the previous associated one. 
3. Both of the commands will be done and both be dispatched to the callback of NetworkManager::setWifiOperationMode. 

If my guess is right, after the patch of bug 909786 lands, this error will no longer appears.

Comment 14

[Vincent Chang[:vchang][changyihsin]]

(In reply to Henry Chang [:henry] from comment #13)
> From the debugging log
> https://tbpl.mozilla.org/php/getParsedLog.
> php?id=27412916&tree=Try&full=1#error0
> WifiManager.setWifiEnabled() is called only once but calls
> _setWifiEnabledCallback twice. 
> It's due to NetworkManager::setWifiOperationMode is call-backed twice. I
> think here is what's happening:
> 
> 1. One of the NetworkManager function which passes an unnamed callback to
> contrlMessage is called before  NetworkManager::setWifiOperationMode()
> 2. NetworkManager::setWifiOperationMode also passes an unnamed  callback to
> controlMessage, which overrides the previous associated one. 
> 3. Both of the commands will be done and both be dispatched to the callback
> of NetworkManager::setWifiOperationMode. 
> 
> If my guess is right, after the patch of bug 909786 lands, this error will
> no longer appears.

Good catch :)

Comment 15

[Vincent Chang[:vchang][changyihsin]]

I think this is fixed.