Closed Bug 1280818 Opened 8 years ago Closed 8 years ago

Binding console is not showing file and line numbers in console

Categories

(DevTools :: Console, defect)

46 Branch
defect
Not set
normal

Tracking

(firefox47 wontfix, firefox48 wontfix, firefox49 wontfix, firefox50 verified)

VERIFIED FIXED
Firefox 50
Tracking Status
firefox47 --- wontfix
firefox48 --- wontfix
firefox49 --- wontfix
firefox50 --- verified

People

(Reporter: door, Assigned: bzbarsky)

References

Details

(Keywords: regression)

Attachments

(2 files, 3 obsolete files)

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:47.0) Gecko/20100101 Firefox/47.0
Build ID: 20160604131506

Steps to reproduce:

var log = console.log.bind(console);
log("hi");


Actual results:

hi and then (unknown) for the file and line numbers show up in console.


Expected results:

hi and (File and Line number) should show up in console's right hand column.

It used to work before version 46 but for 46 and 47 it has been broken.  Still works well in other browsers.  I thought I already filed a bug for this but now can't find it...
Status: UNCONFIRMED → NEW
Component: Untriaged → Developer Tools: Console
Ever confirmed: true
Related badness is that this testcase:

  <script>
  function f() {
    var trace = console.log.bind(console);
    trace();
  }
  f();
  </script>

shows not only a location of "(unknown)" but also an empty stacktrace.
Looks like the empty trace issue predates this one by a good deal.  Filed bug 1280836 on that.

The m-c regression range for the "(unknown)" bit is http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=e790bba372f14241addda469a4bdb7ab00786ab3&tochange=531d1f6d1cde1182e9f7f9dff81a4fc5abc0a601 and the obvious change in there is bug 1000780.  This causes the top saved stack frame to be the one for the self-hosted function, not the thing we actually care about.
Hmm.  Except I'd expect the top saved stack frame to still be for the actual underlying function, and the _next_ one to be for the self-hosted thing....
So it looks like the top stackframe is in fact for the bound function.  I don't know why, but ok.

Given that, the real problem here is that Console::MethodInternal only captures a stack one level deep for console API functions that don't need a full stacktrace.  Then we end up with the self-hosted frame there, try to get location info from it while ignoring self-hosted frames and find nothing.

Changing that code to get a two-deep stack trace fixes this testcase:

  <script>
  var log = console.log.bind(console);
  log("a");
  </script>

but leaves this one with "(unknown)" (just like it was in Firefox 45):

  <script>
  var log = console.log.bind(console);
  ["a"].map(log);
  </script>

We could try to make that work, I guess, but it seems like in general it would require us to capture an arbitrarily long stack, unless we can get some API for "capture the stack up to the first non-selfhosted frame".  Nick, how would you feel about adding that?
Blocks: 1000780
Flags: needinfo?(nfitzgerald)
(In reply to Boris Zbarsky [:bz] from comment #4)
> So it looks like the top stackframe is in fact for the bound function.  I
> don't know why, but ok.

That is indeed pretty strange. It seems like fixing it would also fix this issue, and be strictly better, no?

> We could try to make that work, I guess, but it seems like in general it
> would require us to capture an arbitrarily long stack, unless we can get
> some API for "capture the stack up to the first non-selfhosted frame". 
> Nick, how would you feel about adding that?

Assuming fixing the top stackframe thing doesn't work/isn't the right solution, could we have an API that just captures the first non-selfhosted frame using NonBuiltinStackFrameIter, instead of also saving all the frames above it that we really don't care about?
> That is indeed pretty strange. It seems like fixing it would also fix this issue, and be strictly better, no?

Unclear.  If the top stackframe were for the JSNative-backed function, then we'd still not have the thing we want, which is the file/line of the _caller_ of the jsnative.

Fwiw, right now SavedStacks.cpp uses FrameIter, which is documented to walk the stack of JS activations, which is presumably why it doesn't show JSNative things.
SavedFrames have never had JSNatives, nor did Error().stack include JSNatives before it used SavedFrame stacks. Including them would be a cool feature, but I'm not sure how it would be done (I don't think we have a FrameIter variant that includes them). But as you say, bz, that wouldn't fix this issue because then the console's reported frame would always be "function log() { [native code] }".

The stack should look like this:

    console.log (JSNative)
    bound function (self-hosted)
    ...

Given that we don't see/capture JSNatives, it makes sense to me that the top frame is therefore the self-hosted bound function frame.

I think adding a "capture back to the first non-self-hosted frame" API would be a fine addition to SavedStacks. It's what we want here because we don't know how deep we will have to walk down the stack before we reach a non-self-hosted frame, if we even ever reach one.

If we really wanted, we could also implement that API in terms of what till suggests: skip the usual SavedStacks::insertFrames path that uses FrameIter and instead use NonBuiltinStackFrameIter to get just the first non-self-hosted frame and create a one-off SavedFrame for only that frame instead of the whole stack back to that first non-self-hosted frame.

The more I think about it, the more I think that callers either only want the first non-self-hosted (non-chrome privileged?) frame or they want the whole stack. I doubt anyone ever really wants just the first 10 frames, they just fear the performance costs of capturing the whole stack, but we do a really good job of amortizing that cost _iff you capture the whole stack_ so usually it is better to capture the whole stack. Perhaps we should change the API to reflect this.
Flags: needinfo?(nfitzgerald)
> callers either only want the first non-self-hosted (non-chrome privileged?)
> frame or they want the whole stack.

The places where we ask for something other than the full stack are:

1) CaptureStack in jsexn; purposefully trying to avoid problems with super-deep overrecursed stacks.  Not sure how useful this is in practice.

2) The console code here.  It cuts off at either 200 or 1 depending on the console method.  Longer stacks are of limited use here, really.

3) The various places that call dom::GetCurrentJSStack.  These all limit to 100 frames except GetJSStackForBlob which limits to whatever a pref is set to, except by default it's set to "don't capture at all".

I think the cost of capturing the whole stack is one worry.  The memory impact is another.  Though it's possibly less of an issue now that we lazily reify the nsIStackFrames... except that for console stuff we have to ship all this stuff over IPC, so the more we capture the more we have to ship.

Nick, do you want to add the API bits we need here, or should I try to?
Flags: needinfo?(nfitzgerald)
(In reply to Boris Zbarsky [:bz] from comment #9)
> > callers either only want the first non-self-hosted (non-chrome privileged?)
> > frame or they want the whole stack.
> 
> The places where we ask for something other than the full stack are:
> 
> 1) CaptureStack in jsexn; purposefully trying to avoid problems with
> super-deep overrecursed stacks.  Not sure how useful this is in practice.
> 
> 2) The console code here.  It cuts off at either 200 or 1 depending on the
> console method.  Longer stacks are of limited use here, really.
> 
> 3) The various places that call dom::GetCurrentJSStack.  These all limit to
> 100 frames except GetJSStackForBlob which limits to whatever a pref is set
> to, except by default it's set to "don't capture at all".

So, are you saying that all three of these cases are OK with capturing the first non-self-hosted and non-chrome-privileged frame or the whole stack?

> I think the cost of capturing the whole stack is one worry.  The memory
> impact is another.  Though it's possibly less of an issue now that we lazily
> reify the nsIStackFrames... except that for console stuff we have to ship
> all this stuff over IPC, so the more we capture the more we have to ship.

The `SavedFrame`s are de-duplicated in spidermonkey and could be re-de-duplicated on the other side of IPC but that could get a little funky and if the nsIStackFrames aren't also de-duplicated it probably isn't worth it...

Regarding size of things on IPC, we could also reference stack frames that have already been sent rather than re-serialize them every time, but then we have to figure out how to manage lifetimes.

> Nick, do you want to add the API bits we need here, or should I try to?

If you're ok with the memory/ipc implications, I can whip up a patch. I can also make it so that one can still capture a maximum of N stack frames if they really wish, so that we can easily compare approaches and only gain new abilities rather than lose old ones.
Flags: needinfo?(nfitzgerald)
> So, are you saying that all three of these cases are OK with capturing the first non-self-hosted and non-chrome-privileged frame or the whole stack?

No, I'm saying all three cases are purposefully trying to avoid capturing too much stack.  Whether they should continue to do so is open to debate, of course.

> and if the nsIStackFrames aren't also de-duplicated it probably isn't worth it

I'm not sure what console actually sends across the IPC boundary here, honestly.

> I can also make it so that one can still capture a maximum of N stack frames if
> they really wish, so that we can easily compare approaches and only gain new 
> abilities rather than lose old ones.

That sounds like a good idea to me, if it will mean in practice that we add an API to capture either the first non-self-hosted frame or something equivalent.
Before this commit, one could either capture all stack frames (by passing
maxFrameCount = 0) or a maximum of N frames (by passing maxFrameCount = N). This
commit introduces the ability to capture the first frame (by default ignoring
self hosted frames) with some target principals. This new option required
replacing the `unsigned maxFrameCount` parameter with the introduction of a new
sum type to describe the stack capturing behavior:

  StackCapture = AllFrames
               | MaxFrames(unsigned n)
               | FirstFrameWithPrincipals(JSPrincipals* p, bool ignoreSelfHosted)

This is obviously more wordy in C++ than we'd like, but does make the stack
capturing more explicit rather than reling on the sentinal 0 to stand in for
infinity.
Attachment #8772213 - Flags: review?(jimb)
Attachment #8772213 - Flags: review?(bzbarsky)
Comment on attachment 8772213 [details] [diff] [review]
Add the ability to capture the stack until the first non-self-hosted frame with the given principals

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

I sort of expected this to use principal subsumption, and not principal equality, but if that's what the customer wants...

::: js/src/jit-test/tests/saved-stacks/capture-first-frame-with-principals.js
@@ +10,5 @@
> +const g2 = newGlobal({
> +  principal: 0xff
> +});
> +
> +// Introduce everyone to themselves and each other.

haha

::: js/src/jsapi.h
@@ +5912,5 @@
> + * capture.
> + */
> +struct FirstFrameWithPrincipals
> +{
> +    JSPrincipals* principals;

Could this type call JS_HoldPrincipals in the constructor, and JS_DropPrincipals in the destructor? Just in case...

@@ +5938,5 @@
> + *
> + *   * |JS::FirstFrameWithPrincipals|: Capture the first frame whose principals
> + *     are |JS::FirstFrameWithPrincipals::principals|. By default, do not
> + *     consider self-hosted frames; this can be controlled via the
> + *     |JS::FirstFrameWithPrincipals::ignoreSelfHosted| flag.

You should mention that this also disables the attachment of async stacks.

::: js/src/vm/SavedStacks.cpp
@@ +1144,5 @@
> +                               const JSPrincipals* principals,
> +                               const JSAtom* source)
> +{
> +    return target.principals == principals &&
> +           (!target.ignoreSelfHosted || source != cx->names().selfHosted);

This should be a method of FirstFrameWithPrincipals. It can be declared out-of-line, and defined here, so it will still be able to see cx->names().

@@ +1248,5 @@
>          }
>  
> +        bool capturedMaxFrames = capture.is<JS::MaxFrames>() &&
> +                                 capture.as<JS::MaxFrames>().maxFrames == 1;
> +        bool capturedFrameWithPrincipals =

This bit looks like it should be a 'match'?

@@ +1287,5 @@
> +    unsigned maxAsyncFrames = capture.is<JS::MaxFrames>()
> +        ? capture.as<JS::MaxFrames>().maxFrames
> +        : ASYNC_STACK_MAX_FRAME_COUNT;
> +    if (asyncStack &&
> +        !capture.is<JS::FirstFrameWithPrincipals>() &&

I think I'd write:

    if (asyncStack && !capture.is<JS::FirstFrameWithPrincipals>()) {
        unsigned maxAsyncFrames = ...;
        if (!adoptAsyncStack(...))
            return false;
    }
Attachment #8772213 - Flags: review?(jimb) → review+
Comment on attachment 8772213 [details] [diff] [review]
Add the ability to capture the stack until the first non-self-hosted frame with the given principals

>+    return target.principals == principals &&

This should be a subsumes check, I would think.  Hard to tell, since the only consumer is a test...

This patch on its own doesn't fix the bug; there's an additional DOM part needed.  I'll write that.
Comment on attachment 8772213 [details] [diff] [review]
Add the ability to capture the stack until the first non-self-hosted frame with the given principals

Oh, and r=me on the DOM bits here.
Attachment #8772213 - Flags: review?(bzbarsky) → review+
Thank you both for your reviews!

Ok, will switch to subsumes checking rather than pointer equality.

Yes, was going to leave the DOM bits to you, bz. Thanks!
Before this commit, one could either capture all stack frames (by passing
maxFrameCount = 0) or a maximum of N frames (by passing maxFrameCount = N). This
commit introduces the ability to capture the first frame (by default ignoring
self hosted frames) with some target principals. This new option required
replacing the `unsigned maxFrameCount` parameter with the introduction of a new
sum type to describe the stack capturing behavior:

  StackCapture = AllFrames
               | MaxFrames(unsigned n)
               | FirstSubsumedFrame(JSPrincipals* p, bool ignoreSelfHosted)

This is obviously more wordy in C++ than we'd like, but does make the stack
capturing more explicit rather than relying on the sentinal 0 to stand in for
infinity.
Attachment #8772532 - Flags: review+
Attachment #8772213 - Attachment is obsolete: true
ni myself to remember to do a try push when the tree reopens
Flags: needinfo?(nfitzgerald)
Attachment #8772532 - Attachment is obsolete: true
Assignee: nobody → bzbarsky
Status: NEW → ASSIGNED
Attachment #8772557 - Flags: review?(amarchesini) → review+
That was an out of date patch, will post a try push for the up to date one when I'm back on OSX...
Attachment #8772544 - Attachment is obsolete: true
https://treeherder.mozilla.org/#/jobs?repo=try&revision=da2ac96b3b2f is the try push of both patches with the shadowing fix.
Pushed by bzbarsky@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0916f44729ff
part 1 - Add the ability to capture the stack until the first non-self-hosted frame with the given principals; r=bz,jimb
https://hg.mozilla.org/integration/mozilla-inbound/rev/3ad6f81739fb
part 2.  Change console to capture the first non-self-hosted subsumed frame when it just needs a caller location, instead of capturing the first frame and then possibly failing to get useful location info out of it because it's self-hosted.  r=baku
https://hg.mozilla.org/mozilla-central/rev/0916f44729ff
https://hg.mozilla.org/mozilla-central/rev/3ad6f81739fb
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 50
I have reproduced this bug with Nightly 50.0a1 (2016-06-19) on Windows 7, 64 Bit!

This bug's fix is verified on latest Aurora

Build   ID   20160803004014
User Agent   Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:50.0) Gecko/20100101 Firefox/50.0

[bugday-20160803]
Reproduced this bug in firefox nightly 50.0a1 (2016-06-19) as comment 0 with ubuntu 16.04 (64 bit)

Verified this bug as fixed with latest firefox aurora 50.0a2 (Build ID: 20160804004004)
Mozilla/5.0 (X11; Linux x86_64; rv:50.0) Gecko/20100101 Firefox/50.0
QA Whiteboard: [bugday-20160803]
Thank you very much! Confirming it works in Nightly 51.0a1 on Win10 too
Is this something we'd consider uplifting to 49?
Flags: needinfo?(nfitzgerald)
Flags: needinfo?(lhenry)
We could probably do it if we had to; the risk is not too terrible.  But it doesn't seem to be worth the win this late in the game.
Nothing to add on top of bz's comment.
Flags: needinfo?(nfitzgerald)
Flags: needinfo?(lhenry)
It is not really my say of course, but I am teaching Interactive Media at Sheridan and we start in September with a library using the console bind.  I breath a sigh of relief when they are using Chrome because it is working properly - they need line numbers for debugging.  I will be happy as a peach when it is working again in Firefox, my browser of choice.  You guys did an amazing job - very interesting to see super programming at work - I can certainly wait until 50 if that is what has to happen but I am biting my nails!
Yeah, the 49 release is in 2 weeks or so, which _would_ help your students, but is also soon enough that uplifting things there is a bit dicey.  :(  The 50 release is in November...
Status: RESOLVED → VERIFIED
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: