Closed Bug 1139984 Opened 5 years ago Closed 5 years ago

New console.log calls don't show output after toolbox open

Categories

(DevTools :: WebIDE, defect)

x86
macOS
defect
Not set

Tracking

(firefox37 unaffected, firefox38 fixed, firefox39 fixed)

RESOLVED FIXED
Firefox 39
Tracking Status
firefox37 --- unaffected
firefox38 --- fixed
firefox39 --- fixed

People

(Reporter: justindarc, Assigned: ochameau)

References

Details

(Keywords: regression)

Attachments

(1 file)

I have been unable to see console.log() messages when debugging on a FxOS device in WebIDE on both aurora and nightly channels for the last few days.
I have had this problem as well.
Flags: needinfo?(paul)
Paul does not work on WebIDE regularly anymore.
Flags: needinfo?(paul) → needinfo?(poirot.alex)
Any update on this? Its been almost a week since this bug was last commented on. This is impacting our ability to debug Gaia apps.
(In reply to Justin D'Arcangelo [:justindarc] from comment #3)
> Any update on this? Its been almost a week since this bug was last commented
> on. This is impacting our ability to debug Gaia apps.

Sorry for the delay, I was out last week, and Alex hopes to get to this soon but hasn't yet.

In any case, can you identify a specific console.log you expect to see but now are not?

I just tried WebIDE from Nightly 2015-03-09 with a Flame running:

Build ID               20150310165147
Gaia Revision          cd9ed21cc0cea4b75004d50f29e6f5136cf6e977
Gaia Date              2015-03-10 21:35:01
Gecko Revision         n/a
Gecko Version          39.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.jryans.20150310.163751
Firmware Date          Tue Mar 10 16:39:54 CDT 2015
Bootloader             L1TC10011880

and I see logging printed from the Clock app.
Flags: needinfo?(jdarcangelo)
jryans: Any console.log called *before* you open the devtools in WebIDE will show up. However, once you have the devtools open, any future console.log's will not show up until you close and re-open the devtools again.
Flags: needinfo?(jdarcangelo)
jryans: You can also open the console in WebIDE and run a console.log command:

```
console.log('test');
```

You should expect to see "test" echoed back immediately, but you do not. However, if you close the console and re-open it, you'll see it.
Okay, thanks for the extra info!  I am able to reproduce this in a simple test app.

I'll try to spot what's wrong, or at least hand off to Alex with some extra insight.
Summary: [WebIDE] console.log is broken → New console.log calls don't show output after toolbox open
So far, this seems to be a server side change.  Also, this does not appear to affect the simulator, only real devices.

This suggests it's related to e10s / child process changes, as the simulator does not use multiple processes.

I found a regression window via Flame device builds:

Last Working Build: 

Build ID:    2015-01-29-01-02-39
Gecko (hg):  6bfc0e1c4b29
Gecko (git): a4cef467ebde6112812977dbb5a56a38dfdeb196

First Broken Build:

Build ID:    2015-01-29-16-02-30
Gecko (hg):  29b05d283b00
Gecko (git): f62801541d1c5a5676c7d926ee63317e358e22c6

I'll see if I can find some suspects from the push log[1].

[1]: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=6bfc0e1c4b29&tochange=29b05d283b00
I couldn't easily subdivide further as building individual changes wasn't working for me.

I am hopeful Alex can spot the problem from the change list.
I'm sorry but I'm unable to get a working build environment for my flame (unagi support got broken...).
I'll most likely continue looking into that on monday, hopefully I'll be able to have a clean env by then.
May be downloading the zillion of git repos will be faster during the weekend... It looks like my git repos are corrected and ./repo isn't able to recover.
(In reply to Alexandre Poirot [:ochameau] from comment #10)
> I'm sorry but I'm unable to get a working build environment for my flame
> (unagi support got broken...).
> I'll most likely continue looking into that on monday, hopefully I'll be
> able to have a clean env by then.
> May be downloading the zillion of git repos will be faster during the
> weekend... It looks like my git repos are corrected and ./repo isn't able to
> recover.

FWIW, I don't think this issue is limited to the Flame. I'm having the same problem with my Aries device and WebIDE (Sony Z3 Compact).
Reverting bug 1126042 (changes to e10s window IDs) fixes the regression here.

So, we'll need to fix the console somehow to adapt to the world about that bug.  I don't yet know what needs to change.
Blocks: 1126042
Keywords: regression
I was finally able to build a custom image for my phone, but it is not handy I have to do full flash because it ended up being in production mode for some unknown reason (I just used VARIANT=user).
It looks like modifying userconfig isn't enough, I'll have to rebuild everything from scratch :'(


Anyway I was able to track it down to:
http://mxr.mozilla.org/mozilla-central/source/toolkit/devtools/webconsole/utils.js#1450
  let msgWindow = Services.wm.getCurrentInnerWindowWithId(apiMessage.innerID);

msgWindow is null whereas apiMessage.innerID is defined and looks good...
I'll continue tracking this down.
Flags: needinfo?(poirot.alex)
Bill, any idea how bug 1126042 would have broke nsGlobalWindow* GetInnerWindowWithId?

I tracked it down to this line:
 http://mxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.h#721
 nsGlobalWindow* innerWindow = sWindowsById->Get(aInnerWindowID);

innerWindow is null. aInnerWindowID was 4 in my test case (web console message scenario).

I'm lost because I also tracked down this line:
  http://mxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.cpp#1224
  sWindowsById->Put(mWindowID, this);
We do call this line with mWindowID also equal to 4.

Now, I haven't try to check the very precise type/value of mWindowID/aInnerWindow, I printf these values as %ld and casted them as (long). Nor did I tried to dump sWindowsById whole content from GetInnerWindowWithId.
Flags: needinfo?(wmccloskey)
Bug 1126042 makes window IDs bigger than will fit in 32 bits, although in theory they always could have gotten that big. It looks like our console code assumes that window IDs will fit inside 32 bits. The WebIDL for a ConsoleEvent is here:
http://mxr.mozilla.org/mozilla-central/source/dom/webidl/Console.webidl#47
The type for innerID is (unsigned long or DOMString). unsigned long seems to map to uint32_t in C++.

We store the ID in this field as follows:
http://mxr.mozilla.org/mozilla-central/source/dom/base/Console.cpp#1154
We always take the eNumber path here.

Boris, what should we do here? Can I just use a wider type in the WebIDL? Or should I use the string instead? Not sure what effect that would have on callers.
Flags: needinfo?(wmccloskey) → needinfo?(bzbarsky)
Yikes.  The use of "long" there is just bunk.  

I suspect think using strings there will confuse the chrome JS, at least if it ever compares things with === instead of ==.

The simple fix is to use "unsigned long long" in the IDL, at least if we're pretty sure our window IDs will fit in 53 bits.  Which given the patch in bug 1126042 should be ok.  Then the Web IDL union struct will use a 64-bit int type, which we'll convert to a JS Number value in the usual way and whatnot.
Flags: needinfo?(bzbarsky)
Attached patch patch v1Splinter Review
That fixes the console issue, is that enough?
Attachment #8578644 - Flags: review?(wmccloskey)
Comment on attachment 8578644 [details] [diff] [review]
patch v1

Yep, that's all you need.  r=me
Attachment #8578644 - Flags: review?(wmccloskey) → review+
dom/media/test/test_eme_playback.html often fails but I'll consider it as a know very intermittent.
Assignee: nobody → poirot.alex
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/28de9a3cbb55
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 39
Don't forget to uplift.
Flags: needinfo?(poirot.alex)
Comment on attachment 8578644 [details] [diff] [review]
patch v1

Approval Request Comment
[Feature/regressing bug #]:
  bug 1126042
[User impact if declined]:
  Webconsole has the bug described in comment 0.
[Describe test coverage new/current, TreeHerder]:
  We still do not conver testing webconsole with child processes.
  That's why no test broke when bug 1126042 landed.
  But hopefully bug 1064253 is going to allow us cover this scenario.
[Risks and why]: 
  bug 1126042 regressed the console, so idealy this patch is going to get applied everywhere bug 1126042 landed.
[String/UUID change made/needed]:
  no.
Flags: needinfo?(poirot.alex)
Attachment #8578644 - Flags: approval-mozilla-aurora?
Attachment #8578644 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
I don't know why it wasn't catched by mochitests-devtools e10s...
But it will surely be catched by new tests running on the upcoming luciddream new test harness (bug 1064253).
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.