Closed Bug 1109608 Opened 5 years ago Closed 5 years ago

Log.stackTrace should use human-readable task stack traces if available

Categories

(Toolkit :: Async Tooling, defect)

x86
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla39
Tracking Status
firefox39 --- fixed

People

(Reporter: Yoric, Assigned: waffles, Mentored)

Details

(Whiteboard: [lang=js][good first bug])

Attachments

(1 file, 5 obsolete files)

Log.jsm offers a facility for logging errors in Log.stackTrace. However, this does not handle Task-style asynchronous stacks. We should use function `Task.Debugging.generateReadableStack`, which provides readable stacks whether the error is synchronous or asynchronous.

The source code to change lives here: http://dxr.mozilla.org/mozilla-central/source/toolkit/modules/Log.jsm?from=Log.jsm#164

Human-readable task stack traces are defined by `Task.Debugging.generateReadableStack`, here: http://dxr.mozilla.org/mozilla-central/source/toolkit/modules/Task.jsm?from=Task.jsm#496
Hi, I would like to work on this bug. Could you assign this to me?
Hi Aishwarya, and thanks for picking that bug. I'll assign it to you as soon as you have attached your first patch. If you have any question, feel free to ask, either here, or on IRC http://client00.chat.mibbit.com/?server=irc.mozilla.org&channel=%23introduction&nick=Aishwarya

Have fun :)
Any news, Aishwarya?
Flags: needinfo?(aiishwarya.sivaraman)
HI,
I already completed the building of Firefox code.
I want to work on this bug.
can u give me some instructions.
Thanks.
Flags: needinfo?(aiishwarya.sivaraman) → needinfo?(dteller)
:Yoric I can work on this bug (I can quite get the gist of it). But, I've got a question. How do I reproduce the bug? I mean, I've no idea of what I should do to find the bug (or) test the bug.
Good question.

I believe that the easiest way to check would be to write a xpcshell test that does something along the lines of

Components.utils.import("resource://gre/modules/Promise.jsm", this);
Components.utils.import("resource://gre/modules/Log.jsm", this);

add_task(function* test_stack() {
  yield Promise.resolve(); // This typically scrambles the stack
  do_print(Log.stackTrace(new Error())); // Print the (possibly scrambled) stack
});

function run_test() {
  run_next_test();
}

Prior to fixing the bug, the stack printed will show code from Promise.jsm, Task.jsm, and will not show `test_stack`. After fixing the bug, the stack should not show Promise.jsm or Task.jsm and will show `test_stack`.
Flags: needinfo?(dteller)
Hey Yoric, I tried the xpcshell test. When I tested it first, I got the output like this (http://i.stack.imgur.com/MaRnE.jpg), which had those "Promise.jsm" & "Task.jsm" files (just like you said).

When I passed `e.stack` from `Log.stackTrace` to `Task.Debugging.generateReadableStack`, I got the output like this (http://i.stack.imgur.com/To7a4.jpg). But, I don't understand that `test_stack` part which doesn't show up before the fix, and which shows up after the fix. Can you help me out?
Flags: needinfo?(dteller)
Well, if you're doing what I wrote in comment 6, `test_stack` is just the name of the function/generator in which you're writing your test.
Flags: needinfo?(dteller)
Attached patch stacktrace.patch (obsolete) — Splinter Review
Dear Yoric, Am I right with the approach?
Attachment #8574294 - Flags: review?(dteller)
And, I'm sorry about the "xpcshell.ini". I screwed up the list at the start. So, I had to reinsert all those into the file (using bash, which explains the scrambled file list)
Comment on attachment 8574294 [details] [diff] [review]
stacktrace.patch

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

::: toolkit/modules/tests/xpcshell/xpcshell.ini
@@ +7,5 @@
>    propertyLists/bug710259_propertyListXML.plist
>    chromeappsstore.sqlite
>    zips/zen.zip
>  
> +[test_Task.js]

Instead of reordering the, page, you can just copy everything from http://mxr.mozilla.org/mozilla-central/source/toolkit/modules/tests/xpcshell/xpcshell.ini?raw=1
Attached patch stacktrace1.patch (obsolete) — Splinter Review
Corrections made in response to @Manishearth's review...
Attachment #8574294 - Attachment is obsolete: true
Attachment #8574294 - Flags: review?(dteller)
Attachment #8574376 - Flags: review?(dteller)
Comment on attachment 8574376 [details] [diff] [review]
stacktrace1.patch

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

::: toolkit/modules/Log.jsm
@@ +193,5 @@
>        return "Stack trace: " + output.join(" < ");
>      }
>      // Standard JS exception
>      if (e.stack) {
> +      return "JS Stack trace: " + Task.Debugging.generateReadableStack(e.stack);

I'm not sure why the original code replaced every newline with " < ", but I believe that this still necessary.

@@ -194,5 @@
>      }
>      // Standard JS exception
>      if (e.stack) {
> -      return "JS Stack trace: " + e.stack.trim().replace(/\n/g, " < ").
> -        replace(/@[^@]*?([^\/\.]+\.\w+:)/g, "@$1");

That regexp you removed, /@[^@]*?([^\/\.]+\.\w+:)/g, do you know exactly what it's doing?

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +590,5 @@
> + */
> +
> +add_task(function* test_stack() {
> +  yield Promise.resolve(); // This typically scrambles the stack
> +  do_print(Log.stackTrace(new Error())); // Print the (possibly scrambled) stack

Ok, that's useful for checking visually that the error is printed correctly. Now, let's automate this.

Let's merge this test with the previous test and check that:
- `str` doesn't contain any reference to Promise.jsm or Task.jsm;
- `str` shows `test_stack`.
Attachment #8574376 - Flags: review?(dteller) → feedback+
Attached patch stacktrace.patch (obsolete) — Splinter Review
Indeed, I missed the trim(), which fixes the `newline` problem at the ends. And, I noticed that the regexp is necessary to grab the filenames from the paths. Now, I've fixed that.
Attachment #8574376 - Attachment is obsolete: true
Attachment #8575164 - Flags: review?(dteller)
Comment on attachment 8575164 [details] [diff] [review]
stacktrace.patch

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

Good for Log.jsm. Waiting for your changes for test_Log.js :)

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +590,5 @@
> + */
> +
> +add_task(function* test_stack() {
> +  yield Promise.resolve(); // This typically scrambles the stack
> +  do_print(Log.stackTrace(new Error())); // Print the (possibly scrambled) stack

My comment from the previous review still applies.
Attachment #8575164 - Flags: review?(dteller) → feedback+
Attached patch stacktrace.patch (obsolete) — Splinter Review
Merged the test with previous test named `format_errors()`. Made sure that "Promise.jsm" and "Task.jsm" are not referenced during the testing...
Attachment #8575164 - Attachment is obsolete: true
Attachment #8575368 - Flags: review?(dteller)
Comment on attachment 8575368 [details] [diff] [review]
stacktrace.patch

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

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +582,5 @@
>      // Make sure we identified it as an Error and formatted the error location as
>      // lineNumber:columnNumber.
>      do_check_true(str.contains(":1:11)"));
>    }
> +  

Nit: Please don't add whitespace on empty lines. Same below.

@@ +584,5 @@
>      do_check_true(str.contains(":1:11)"));
>    }
> +  
> +  // Test function for bug #1109608 (Log.stackTrace should use human-readable
> +  // task stack traces if available)

Just: // Make sure that we use human-readable stack traces.

@@ +588,5 @@
> +  // task stack traces if available)
> +  
> +  // Check that the error doesn't contain any reference to "Promise.jsm" or "Task.jsm"
> +  yield Promise.resolve(); // Scrambles the stack
> +  err = new Error();

Let's reuse `e` of line 579+.

@@ +589,5 @@
> +  
> +  // Check that the error doesn't contain any reference to "Promise.jsm" or "Task.jsm"
> +  yield Promise.resolve(); // Scrambles the stack
> +  err = new Error();
> +  str = Log.stackTrace(err);  // Contains the (possibly scrambled) stack

Let's reuse `str` of line 580, rather than calling manually `Log.stackTrace`.

@@ +591,5 @@
> +  yield Promise.resolve(); // Scrambles the stack
> +  err = new Error();
> +  str = Log.stackTrace(err);  // Contains the (possibly scrambled) stack
> +  do_check_false(str.contains("Promise.jsm"));
> +  do_check_false(str.contains("Task.jsm"));

Could you also check that it contains "format_error"?
Attachment #8575368 - Flags: review?(dteller) → feedback+
Attached patch stacktrace.patch (obsolete) — Splinter Review
Now, I've reused the exception, checked if `format_errors` exists, and revised the comments...
Attachment #8575368 - Attachment is obsolete: true
Attachment #8575723 - Flags: review?(dteller)
Comment on attachment 8575723 [details] [diff] [review]
stacktrace.patch

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

One last thing (I believe), then we should be good.
To run this test
 ./mach xpcshell-test toolkit/modules/tests/xpcshell/test_Log.js

::: toolkit/modules/tests/xpcshell/test_Log.js
@@ +582,5 @@
>      // Make sure we identified it as an Error and formatted the error location as
>      // lineNumber:columnNumber.
>      do_check_true(str.contains(":1:11)"));
> +    // Make sure that we use human-readable stack traces
> +    yield Promise.resolve();  // Scrambles the stack

We need to scramble the stack before we throw the error. Can you move that `yield` to before the line with `eval`?
Attachment #8575723 - Flags: review?(dteller) → feedback+
Attached patch stacktrace.patchSplinter Review
Oops... Yeah, I understood what you meant there. Fixed now :)
Attachment #8575723 - Attachment is obsolete: true
Attachment #8575885 - Flags: review?(dteller)
Assignee: nobody → wafflespeanut
Comment on attachment 8575885 [details] [diff] [review]
stacktrace.patch

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

Looks good, let's test it: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1297666b76f7
Attachment #8575885 - Flags: review?(dteller) → review+
This looks good. Let's land it!
Keywords: checkin-needed
https://hg.mozilla.org/integration/fx-team/rev/f69c5955f8c7
Flags: in-testsuite+
Keywords: checkin-needed
Whiteboard: [lang=js][good first bug] → [lang=js][good first bug][fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/f69c5955f8c7
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Whiteboard: [lang=js][good first bug][fixed-in-fx-team] → [lang=js][good first bug]
Target Milestone: --- → mozilla39
You need to log in before you can comment on or make changes to this bug.