Closed Bug 1150052 Opened 9 years ago Closed 9 years ago

Can't join my own rooms

Categories

(Hello (Loop) :: Client, defect, P1)

defect
Points:
5

Tracking

(firefox37 wontfix, firefox38 wontfix, firefox38.0.5 wontfix, firefox39 fixed, firefox40 fixed, firefox41 fixed, relnote-firefox 39+)

RESOLVED FIXED
mozilla41
Iteration:
41.1 - May 25
Tracking Status
firefox37 --- wontfix
firefox38 --- wontfix
firefox38.0.5 --- wontfix
firefox39 --- fixed
firefox40 --- fixed
firefox41 --- fixed
relnote-firefox --- 39+

People

(Reporter: blassey, Assigned: mikedeboer)

References

Details

(Whiteboard: [quality, bug])

Attachments

(2 files)

I've been seeing this for a while, but had been previously told it was e10s related. For the last week I've been keeping Dev Edition running to use for Loop calls so I could capture logs when there were problems (about:webrtc is broken under e10s).

Quite often I click on one of my rooms and nothing happens. I currently have two rooms created. A few minutes ago I clicked on one and nothing happened. After waiting an appropriate amount of time, I clicked on the other and was able to join.

Here's my browser console:

"on error:" "update:JZ9LlY1uEJY" MozLoopAPI.jsm:157
1427879286890	readinglist.serverclient	DEBUG	received response status: 200 OK
1427879286891	readinglist.serverclient	DEBUG	initial request got status 200
1427879286891	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Wed, 01 Apr 2015 09:08:05 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427653618037","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}
1427879286891	readinglist.sync	DEBUG	Phase 3: Uploading material changes
1427879286892	readinglist.sync	DEBUG	No local changes to upload
1427879286892	readinglist.sync	INFO	Sync done
1427879286892	readinglist.scheduler	INFO	Sync completed successfully
1427879286893	readinglist.scheduler	INFO	canSync=true
1427879286893	readinglist.scheduler	INFO	next scheduled sync is in 7200000ms (at Wed Apr 01 2015 07:08:06 GMT-0400 (EDT))
1427886491849	readinglist.scheduler	DEBUG	starting sync
1427886491850	readinglist.sync	INFO	Starting sync
1427886491850	readinglist.sync	DEBUG	Phase 1 part 1: Uploading status changes
1427886491852	readinglist.sync	DEBUG	No local changes to upload
1427886491852	readinglist.sync	DEBUG	Phase 1 part 2: Uploading new items
1427886491854	readinglist.sync	DEBUG	No new local items to upload
1427886491854	readinglist.sync	DEBUG	Phase 1 part 3: Uploading deleted items
1427886491855	readinglist.sync	DEBUG	No local deleted synced items to upload
1427886491855	readinglist.sync	DEBUG	Phase 2: Downloading modified items
1427886491855	readinglist.sync	DEBUG	Sending request: {"method":"GET","path":"/articles?_since=1427653618037"}
1427886494573	readinglist.serverclient	DEBUG	dispatching request to: https://readinglist.services.mozilla.com/v1/articles?_since=1427653618037
1427886497638	readinglist.serverclient	DEBUG	received response status: 200 OK
1427886497638	readinglist.serverclient	DEBUG	initial request got status 200
1427886497638	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Wed, 01 Apr 2015 11:08:15 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427653618037","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}
1427886497639	readinglist.sync	DEBUG	Phase 3: Uploading material changes
1427886497640	readinglist.sync	DEBUG	No local changes to upload
1427886497641	readinglist.sync	INFO	Sync done
1427886497641	readinglist.scheduler	INFO	Sync completed successfully
1427886497642	readinglist.scheduler	INFO	canSync=true
1427886497642	readinglist.scheduler	INFO	next scheduled sync is in 7200000ms (at Wed Apr 01 2015 09:08:17 GMT-0400 (EDT))
1427893702806	readinglist.scheduler	DEBUG	starting sync
1427893702807	readinglist.sync	INFO	Starting sync
1427893702807	readinglist.sync	DEBUG	Phase 1 part 1: Uploading status changes
1427893702809	readinglist.sync	DEBUG	No local changes to upload
1427893702809	readinglist.sync	DEBUG	Phase 1 part 2: Uploading new items
1427893702810	readinglist.sync	DEBUG	No new local items to upload
1427893702810	readinglist.sync	DEBUG	Phase 1 part 3: Uploading deleted items
1427893702811	readinglist.sync	DEBUG	No local deleted synced items to upload
1427893702811	readinglist.sync	DEBUG	Phase 2: Downloading modified items
1427893702811	readinglist.sync	DEBUG	Sending request: {"method":"GET","path":"/articles?_since=1427653618037"}
1427893703560	readinglist.serverclient	DEBUG	dispatching request to: https://readinglist.services.mozilla.com/v1/articles?_since=1427653618037
1427893703980	readinglist.serverclient	DEBUG	received response status: 200 OK
1427893703980	readinglist.serverclient	DEBUG	initial request got status 200
1427893703980	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Wed, 01 Apr 2015 13:08:22 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427653618037","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}
1427893703981	readinglist.sync	DEBUG	Phase 3: Uploading material changes
1427893703984	readinglist.sync	DEBUG	No local changes to upload
1427893703984	readinglist.sync	INFO	Sync done
1427893703985	readinglist.scheduler	INFO	Sync completed successfully
1427893703986	readinglist.scheduler	INFO	canSync=true
1427893703986	readinglist.scheduler	INFO	next scheduled sync is in 7200000ms (at Wed Apr 01 2015 11:08:23 GMT-0400 (EDT))
"[Dispatcher] Dispatching action caused an exception: " Error: Encountered unsupported value type writing stack-scoped structured clone
Stack trace:
cloneValueInto@resource:///modules/loop/MozLoopAPI.jsm:111:13
injectObjectAPI/</injectedAPI[func]@resource:///modules/loop/MozLoopAPI.jsm:168:18
loop.store.RoomStore<.openRoom@chrome://browser/content/loop/shared/js/roomStore.js:417:7
Dispatcher.prototype._dispatchNextAction/<@chrome://browser/content/loop/shared/js/dispatcher.js:76:11
Dispatcher.prototype._dispatchNextAction@chrome://browser/content/loop/shared/js/dispatcher.js:74:7
Dispatcher.prototype.dispatch@chrome://browser/content/loop/shared/js/dispatcher.js:48:7
RoomEntry<.handleClickEntry@chrome://browser/content/loop/js/panel.js:508:1
a@chrome://browser/content/loop/shared/libs/react-0.12.2.js:12:23169
[92]</R.executeDispatch@chrome://browser/content/loop/shared/libs/react-0.12.2.js:15:20972
i@chrome://browser/content/loop/shared/libs/react-0.12.2.js:12:23101
s@chrome://browser/content/loop/shared/libs/react-0.12.2.js:12:23222
[19]</c@chrome://browser/content/loop/shared/libs/react-0.12.2.js:12:19991
[123]</n@chrome://browser/content/loop/shared/libs/react-0.12.2.js:16:1309
[19]</p.processEventQueue@chrome://browser/content/loop/shared/libs/react-0.12.2.js:12:20898
n@chrome://browser/content/loop/shared/libs/react-0.12.2.js:14:14066
[60]</o.handleTopLevel@chrome://browser/content/loop/shared/libs/react-0.12.2.js:14:14183
o@chrome://browser/content/loop/shared/libs/react-0.12.2.js:14:14642
[104]</r.perform@chrome://browser/content/loop/shared/libs/react-0.12.2.js:15:27988
[54]</p.batchedUpdates@chrome://browser/content/loop/shared/libs/react-0.12.2.js:14:7657
o@chrome://browser/content/loop/shared/libs/react-0.12.2.js:15:11152
[61]</m.dispatchEvent@chrome://browser/content/loop/shared/libs/react-0.12.2.js:14:15701
 dispatcher.js:78:10

no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
1427900903794	readinglist.scheduler	DEBUG	starting sync
1427900903794	readinglist.sync	INFO	Starting sync
1427900903794	readinglist.sync	DEBUG	Phase 1 part 1: Uploading status changes
1427900903796	readinglist.sync	DEBUG	No local changes to upload
1427900903796	readinglist.sync	DEBUG	Phase 1 part 2: Uploading new items
1427900903797	readinglist.sync	DEBUG	No new local items to upload
1427900903797	readinglist.sync	DEBUG	Phase 1 part 3: Uploading deleted items
1427900903798	readinglist.sync	DEBUG	No local deleted synced items to upload
1427900903798	readinglist.sync	DEBUG	Phase 2: Downloading modified items
1427900903798	readinglist.sync	DEBUG	Sending request: {"method":"GET","path":"/articles?_since=1427653618037"}
1427900904176	readinglist.serverclient	DEBUG	dispatching request to: https://readinglist.services.mozilla.com/v1/articles?_since=1427653618037
1427900904593	readinglist.serverclient	DEBUG	received response status: 200 OK
1427900904594	readinglist.serverclient	DEBUG	initial request got status 200
1427900904594	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Wed, 01 Apr 2015 15:08:22 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427653618037","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}
1427900904594	readinglist.sync	DEBUG	Phase 3: Uploading material changes
1427900904595	readinglist.sync	DEBUG	No local changes to upload
1427900904596	readinglist.sync	INFO	Sync done
1427900904596	readinglist.scheduler	INFO	Sync completed successfully
1427900904597	readinglist.scheduler	INFO	canSync=true
1427900904597	readinglist.scheduler	INFO	next scheduled sync is in 7200000ms (at Wed Apr 01 2015 13:08:24 GMT-0400 (EDT))
RTCIceServer.url is deprecated! Use urls instead. <unknown>
Mandatory/optional in createOffer options is deprecated! Use {"mozDontOfferDataChannel":true} instead (note the case difference)! <unknown>
no element found ClientEvent:1:1
RTCIceServer.url is deprecated! Use urls instead. <unknown>
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientQos:1:1
no element found ClientEvent:1:1
no element found ClientQos:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
TypeError: win.gBrowser is null ReaderParent.jsm:125:0
OpenGL compositor Initialized Succesfully.
Version: 2.1 NVIDIA-8.26.28 310.40.55b01
Vendor: NVIDIA Corporation
Renderer: NVIDIA GeForce GT 750M OpenGL Engine
FBO Texture Target: TEXTURE_2D
TypeError: win.gBrowser is null ReaderParent.jsm:125:0
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientQos:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
no element found ClientEvent:1:1
OpenGL compositor Initialized Succesfully.
Version: 2.1 NVIDIA-8.26.28 310.40.55b01
Vendor: NVIDIA Corporation
Renderer: NVIDIA GeForce GT 750M OpenGL Engine
FBO Texture Target: TEXTURE_2D
I'm seeing the same bug in Fx37.
Severity: normal → blocker
Points: --- → 5
Priority: -- → P1
Rank: 4
Flags: firefox-backlog+
Whiteboard: [error]
Walking down the stack we have the following:

https://hg.mozilla.org/releases/mozilla-beta/file/daf8a9291a9b/browser/components/loop/MozLoopAPI.jsm#l111
  --> `clone = Cu.cloneInto(value, targetWindow);`
https://hg.mozilla.org/releases/mozilla-beta/file/daf8a9291a9b/browser/components/loop/MozLoopAPI.jsm#l168
  --> `return cloneValueInto(ex, targetWindow);`
https://hg.mozilla.org/releases/mozilla-beta/file/daf8a9291a9b/browser/components/loop/content/shared/js/roomStore.js#l417
  --> `this._mozLoop.rooms.open(actionData.roomToken);`

In prose:

The content page (from the rooms list in the Loop panel) attempts to open a page, thus calls `mozLoop.rooms.open(tokenString)`.
MozLoopAPI does `Cu.cloneInto` - causing this error message - in two places: one to clone the arguments (tokenString, which won't be cloned because String) and the second for the return value of the function that is invoked, LoopRooms.open in this case.

Since we do type checking on the actionData, we can quite safely assume that the first clone of the roomToken string does not yield this error. So it _must_ be originating from LoopRooms.open:
LoopRooms.open almost immediately proxies to `MozLoopService.openChatWindow`. Does this mean that Chat.jsm or chatbox is (again) the culprit? If so, why is MozLoopService not part of the stack?

It's this or there is something fishy going on after all with the roomToken. I'll attach a patch that will enable logging that we should've had a long time ago.
Assignee: nobody → mdeboer
Status: NEW → ASSIGNED
Whiteboard: [error] → [error][investigating][watch]
Attachment #8587387 - Flags: review?(standard8) → review+
Pushed to fx-team, will request uplift asap: https://hg.mozilla.org/integration/fx-team/rev/eff7edecfdf1
Keywords: leave-open
Comment on attachment 8587387 [details] [diff] [review]
Patch 1: report exceptions that occur in MozLoop object APIs directly to the console

Approval Request Comment
[Feature/regressing bug #]: Loop/ Hello, not a specific bug
[User impact if declined]: This one-line patch adds logging to the console when an error occurs while a specific moLoop API is invoked. This allows developers to see the error and analyze the cause of this specific bug and potentially others better.
[Describe test coverage new/current, TreeHerder]: landed on m-c, existing tests pass.
[Risks and why]: none.
[String/UUID change made/needed]: n/a.
Attachment #8587387 - Flags: approval-mozilla-beta?
Attachment #8587387 - Flags: approval-mozilla-aurora?
Since this doesn't fix the underlying issue and is logging to the console, why do we need to uplift this to beta? Do you want Aurora uplift to get different data with e10s disabled?
Flags: needinfo?(mdeboer)
Comment on attachment 8587387 [details] [diff] [review]
Patch 1: report exceptions that occur in MozLoop object APIs directly to the console

Approving for aurora since this is low risk and may help clean up logging.
Attachment #8587387 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
(In reply to Liz Henry (:lizzard) from comment #7)
> Since this doesn't fix the underlying issue and is logging to the console,
> why do we need to uplift this to beta? Do you want Aurora uplift to get
> different data with e10s disabled?

No, this issue is in fact not related to e10s. Hence I'd like to move this important piece of logging up the train to 38 to get more data to analyze. I need that to be able to see the cause of and fix the underlying issue.
Flags: needinfo?(mdeboer)
Blocks: 1152213
Comment on attachment 8587387 [details] [diff] [review]
Patch 1: report exceptions that occur in MozLoop object APIs directly to the console

Also taking in 38 to help testing. Should be in 38 beta 3.
Attachment #8587387 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Iteration: --- → 40.2 - 27 Apr
Thanks to the added logging I was able to catch this error.

One alternative notation is to write it like:

```js
let cb = this.chatboxForURL.get(aURL);
cb = cb && cb.get();
if (cb) {
  ...
```
Attachment #8603244 - Flags: review?(mixedpuppy)
Attachment #8603244 - Flags: review?(mixedpuppy) → review+
Whiteboard: [error][investigating][watch] → [quality, bug, intestigating][watch]
Keywords: leave-open
sorry had to back this out for test failures like https://treeherder.mozilla.org/logviewer.html#?job_id=3036174&repo=fx-team
Flags: needinfo?(mdeboer)
Iteration: 40.2 - 27 Apr → 41.1 - May 25
https://hg.mozilla.org/mozilla-central/rev/23ec0661bddd
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
Comment on attachment 8603244 [details] [diff] [review]
Patch 2: move up weak reference resolving for garbage collected chatboxes

Approval Request Comment
[Feature/regressing bug #]: no bug, this is a bugfix in the Social API code that most probably affect a large number of Hello users.
[User impact if declined]: User won't be able to open a conversation under certain circumstances.
[Describe test coverage new/current, TreeHerder]: landed on m-c, tests pass.
[Risks and why]: minor.
[String/UUID change made/needed]: n/a.
Attachment #8603244 - Flags: approval-mozilla-beta?
Attachment #8603244 - Flags: approval-mozilla-aurora?
Whiteboard: [quality, bug, intestigating][watch] → [quality, bug]
OS: Mac OS X → All
Hardware: x86 → All
Comment on attachment 8603244 [details] [diff] [review]
Patch 2: move up weak reference resolving for garbage collected chatboxes

Let's get this on Aurora 40 to start. Aurora+
Attachment #8603244 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Comment on attachment 8603244 [details] [diff] [review]
Patch 2: move up weak reference resolving for garbage collected chatboxes

Looks like this has been on central and aurora for a few days. Approved for uplift to beta (39).
Attachment #8603244 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Mike, one more question - would you like to write a release note for this for 39?
Flags: needinfo?(mdeboer)
(In reply to Liz Henry (:lizzard) from comment #27)
> Mike, one more question - would you like to write a release note for this
> for 39?

Sure! How about:

"Fixed an issue where a Hello conversation window would occasionally fail to open."
Flags: needinfo?(mdeboer)
Release Note Request (optional, but appreciated)
[Why is this notable]: User impact 
[Suggested wording]: Fixed an issue where a Hello conversation window would sometimes fail to
open
[Links (documentation, blog post, etc)]:
I can`t seem to reproduce the initial issue using Firefox 37 RC or old Nightly from 2015-04-01. 
Brad or Mike, since you encountered this issue can you please check that this is not longer an issue with you using Firefox 39 beta 1?

For what is worth I could always enter rooms using latest builds (Nightly and 39 beta 1 build 2).
Flags: needinfo?(blassey.bugs)
This was intermittent so there's no way to confirm that.
Flags: needinfo?(blassey.bugs)
You need to log in before you can comment on or make changes to this bug.