Closed Bug 908426 Opened 11 years ago Closed 11 years ago

"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

Categories

(Firefox OS Graveyard :: Wifi, defect)

Product:
Firefox OS Graveyard
Component:
Wifi
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox24 unaffected, firefox25 unaffected, firefox26 affected)

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox24 --- unaffected
firefox25 --- unaffected
firefox26 --- affected

People

(Reporter: RyanVM, Assigned: hchang)

References

Details

+++ 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
Assignee: nobody → hchang
It doesn't seem to be caused by bug 888227 but I will look into it anyways. Thanks.
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.
(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|.
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|.
(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?
> > 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.
Depends on: 906631
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.
No longer blocks: 892958
Blocks: log-SnR
(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...
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}
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?
Test away! Those tests run on AWS, so we have plentiful slave resources :)
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.
(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 :)
No longer depends on: 906631
Blocks: 920191
No longer blocks: log-SnR
I think this is fixed.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.