src,win: informative stack traces #23822

refack · 2018-10-22T19:40:37Z

Refresh Win32SymbolDebuggingContext::LookupSymbol to use more APIs
Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address
Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-undecorated-symbol-names

Before:

DEV D:\code\node>Debug\node.exe test\parallel\test-fs-stat-bigint.js
C:\WINDOWS\system32\cmd.exe - Debug\node.exe  test\parallel\test-fs-stat-bigint.js [37304]: d:\code\node\deps\gsl\gsl\gsl_assert:132: Assertion `unknown' failed.
 1: 00007FF7A3B9F67A
 2: 00007FF7A3B0A1B7
 3: 00007FF7A3B0A307
 4: 00007FF7A394BB25
 5: 00007FF7A394B844
 6: 00007FF7A394AC6A
 7: 00007FF7A394BF91
 8: 00007FF7A3A7C36B
 9: 00007FF7A480D165
10: 00007FF7A480BB5C
11: 00007FF7A480CE1B
12: 00007FF7A480C6C3
13: 0000039475106628

After (with PDB available):

DEV D:\code\node>Debug\node.exe test\parallel\test-fs-stat-bigint.js
C:\WINDOWS\system32\cmd.exe - Debug\node.exe  test\parallel\test-fs-stat-bigint.js [38392]: d:\code\node\deps\gsl\gsl\gsl_assert:132: Assertion `unknown' failed.
 1: 00007FF7A3B9F67A node::DumpBacktrace [d:\code\node\src\debug_utils.cc]:L237+138
 2: 00007FF7A3B0A1B7 node::Abort [d:\code\node\src\node.cc]:L1030+39
 3: 00007FF7A3B0A307 node::Assert [d:\code\node\src\node.cc]:L1049+295
 4: 00007FF7A394BB25 gsl::details::throw_exception<gsl::narrowing_error> [d:\code\node\deps\gsl\gsl\gsl_assert]:L137+149
 5: 00007FF7A394B844 gsl::narrow<double,unsigned __int64> [d:\code\node\deps\gsl\gsl\gsl_util]:L117+148
 6: 00007FF7A394AC6A node::FillStatsArray<double,v8::Float64Array> [d:\code\node\src\node_internals.h]:L328+634
 7: 00007FF7A394BF91 node::FillGlobalStatsArray [d:\code\node\src\node_internals.h]:L360+129
 8: 00007FF7A3A7C36B node::fs::LStat [d:\code\node\src\node_file.cc]:L985+1083
 9: 00007FF7A480D165 v8::internal::FunctionCallbackArguments::Call [d:\code\node\deps\v8\src\api-arguments-inl.h]:L120+469
10: 00007FF7A480BB5C v8::internal::`anonymous namespace'::HandleApiCallHelper<0> [d:\code\node\deps\v8\src\builtins\builtins-api.cc]:L111+684
11: 00007FF7A480CE1B v8::internal::Builtin_Impl_HandleApiCall [d:\code\node\deps\v8\src\builtins\builtins-api.cc]:L139+507
12: 00007FF7A480C6C3 v8::internal::Builtin_HandleApiCall [d:\code\node\deps\v8\src\builtins\builtins-api.cc]:L127+451
13: 000003BBE9486628

Fallback with no PDB loaded:

 1: 00007FF7A3B9F67A AES_cbc_encrypt+5220586
 2: 00007FF7A3B0A1B7 AES_cbc_encrypt+4609063
 3: 00007FF7A3B0A307 AES_cbc_encrypt+4609399
 4: 00007FF7A394BB25 AES_cbc_encrypt+2780565
 5: 00007FF7A394B844 AES_cbc_encrypt+2779828
 6: 00007FF7A394AC6A AES_cbc_encrypt+2776794
 7: 00007FF7A394BF91 AES_cbc_encrypt+2781697
 8: 00007FF7A3A7C36B AES_cbc_encrypt+4027867
 9: 00007FF7A480D165 AES_cbc_encrypt+18252757
10: 00007FF7A480BB5C AES_cbc_encrypt+18247116
11: 00007FF7A480CE1B AES_cbc_encrypt+18251915
12: 00007FF7A480C6C3 AES_cbc_encrypt+18250035
13: 0000039475106628

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
commit message follows commit guidelines

refack · 2018-10-22T19:42:41Z

~~CI: https://ci.nodejs.org/job/node-test-pull-request/18049/~~
CI: https://ci.nodejs.org/job/node-test-commit/22540/
/CC @nodejs/platform-windows @nodejs/diagnostics

nodejs-github-bot · 2018-10-22T20:47:20Z

@refack build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/1338/pipeline

TimothyGu · 2018-10-23T02:14:13Z

src/debug_utils.cc

 class Win32SymbolDebuggingContext final : public NativeSymbolDebuggingContext {
 public:
-  Win32SymbolDebuggingContext() {
+  explicit Win32SymbolDebuggingContext(void* out) {
+    out_ = reinterpret_cast<FILE*>(out);


Why not just take a FILE* as input parameter?

Polymorphism with the POSIX class:
https://github.com/nodejs/node/blob/0b565eb7f7404fb8774865826afba10c1919788f/src/debug_utils.cc#L253
I could move the cast to https://github.com/nodejs/node/blob/0b565eb7f7404fb8774865826afba10c1919788f/src/debug_utils.cc#L232-L235
(Now that I see it I could assume it's always stderr and eliminate the argument).

Since this is only used for printing diagnostic information, I don’t think an extra parameter is necessary at all; we can always just use stderr

src/debug_utils.cc

TimothyGu · 2018-10-23T02:16:44Z

src/debug_utils.cc

+    // Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address
+    // Patches:
+    // * Use `fprintf(out, ` instead of `printf`
+    // * `sym ~= line` on success


What does the ~= mean?

assign almost all fields... I'll rephrase
(I might have used more fields in an earlier imp)

TimothyGu · 2018-10-23T02:17:36Z

src/debug_utils.cc

-    char demangled[MAX_SYM_NAME];
+  using NameAndDisplacement = std::pair<std::string, DWORD64>;
+  NameAndDisplacement WrappedSymFromAddr(DWORD64 dwAddress) const {
+    HANDLE hProcess = current_process_;


snake_case for variables.

I wanted to keep the code as similar as possible to https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address

TimothyGu · 2018-10-23T02:18:30Z

src/debug_utils.cc

+    // Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address
+    // Patches:
+    // * Use `fprintf(out_, ` instead of `printf`
+    // * `sym.filename = pSymbol->Name` on success


I feel this information about what you changed isn’t particularly useful. Both of the patches are fairly trivial. This also apply to the other places.

I'd rather keep the comment, AFAIK more comment never hurt...
Also they might be useful since the examples on MSDN change from time to time (for example they changed since the last time this code was lifted, and I had to reverse engineer the patches).

Also they might be useful since the examples on MSDN change from time to time

Wouldn’t that be a good reason to drop the comment, since the diff can change on both sides, and so the Patches: list can grow out of date?

I'll sleep on it.

Since MSDN does have a history, I'm thinking the comments might still be useful.
Anyway they are free, and IMHO more info is almost always better then missing info...
I did go over them to make sure they are uniform, and not too obfuscated.

TimothyGu · 2018-10-23T02:20:22Z

src/debug_utils.cc

+    // * `sym ~= line` on success
+
+    // Patch: made into arg - DWORD64  dwAddress;
+    DWORD  dwDisplacement;


nit: one space after DWORD.

richardlau · 2018-10-23T02:27:23Z

cc @gireeshpunathil There may be opportunities here to reuse some code for Windows backtraces w.r.t. node-report in core and this PR.

addaleax · 2018-10-23T02:49:07Z

src/debug_utils.h

+        oss << "+" << dis;
+      }
+      return oss.str();
+    }


Can we put this back in the .cc file?

Done.
But may I ask why?

src/debug_utils.cc

addaleax · 2018-10-23T02:51:07Z

src/debug_utils.cc

 class Win32SymbolDebuggingContext final : public NativeSymbolDebuggingContext {
 public:
-  Win32SymbolDebuggingContext() {
+  explicit Win32SymbolDebuggingContext(void* out) {
+    out_ = reinterpret_cast<FILE*>(out);


Since this is only used for printing diagnostic information, I don’t think an extra parameter is necessary at all; we can always just use stderr

addaleax · 2018-10-23T02:53:04Z

src/debug_utils.cc

+    } else {
+      // SymFromAddr failed
+      const DWORD error = GetLastError();
+#ifdef _DEBUG


When is #ifdef _DEBUG defined? Is it the same as our #ifdef DEBUG?

node/common.gypi

Line 109 in f1b9546

'defines': [ 'DEBUG', '_DEBUG', 'V8_ENABLE_CHECKS' ],

I picked it arbitrarily... I'll change

Since I don’t know much about the Windows debugging stuff … how common would these errors be? i.e. do we only print them in debug mode because they would otherwise appear relatively frequently?

i.e. do we only print them in debug mode because they would otherwise appear relatively frequently?

Yes very frequent. If the *.pdb is not available, or is partial. Also the last (deepest) frame almost always fails to resolve.

Done /s/_DEBUG/DEBUG

addaleax · 2018-10-23T02:53:33Z

src/debug_utils.cc


+  SymbolInfo LookupSymbol(void* address) override {
+    auto dwAddress = reinterpret_cast<DWORD64>(address);


DWORD64 dw_address

Ack.
But the type stated explicitly on the rhs.
And the name is copied from the example, which I'd rather not change...

refack · 2018-10-23T13:06:56Z

New CI: ~~https://ci.nodejs.org/job/node-test-commit/22567/~~
https://ci.nodejs.org/job/node-test-commit/22575/

refack · 2018-10-23T13:23:55Z

i.e. do we only print them in debug mode because they would otherwise appear relatively frequently?

Yes very frequent. If the *.pdb is not available, or is partial. Also the last (deepest) frame almost always fails to resolve.

Debug mode exe:

Example output with .pdb present:

DEV D:\code\node>Debug\node.exe test\parallel\test-fs-stat-bigint.js
C:\WINDOWS\system32\cmd.exe - Debug\node.exe  test\parallel\test-fs-stat-bigint.js [37716]: d:\code\node\src\node_file.cc:962: Assertion `(argc) >= (11)' failed.
 1: 00007FF61F72EE8A node::DumpBacktrace+138 [d:\code\node\src\debug_utils.cc]:L254
 2: 00007FF61F6999C7 node::Abort+39 [d:\code\node\src\node.cc]:L1030
 3: 00007FF61F699B17 node::Assert+295 [d:\code\node\src\node.cc]:L1049
 4: 00007FF61F60B7AC node::fs::LStat+108 [d:\code\node\src\node_file.cc]:L962
 5: 00007FF62039C925 v8::internal::FunctionCallbackArguments::Call+469 [d:\code\node\deps\v8\src\api-arguments-inl.h]:L120
 6: 00007FF62039B31C v8::internal::`anonymous namespace'::HandleApiCallHelper<0>+684 [d:\code\node\deps\v8\src\builtins\builtins-api.cc]:L111
 7: 00007FF62039C5DB v8::internal::Builtin_Impl_HandleApiCall+507 [d:\code\node\deps\v8\src\builtins\builtins-api.cc]:L139
 8: 00007FF62039BE83 v8::internal::Builtin_HandleApiCall+451 [d:\code\node\deps\v8\src\builtins\builtins-api.cc]:L127
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
 9: 000003B89AE86628

Without .pdb

DEV D:\code\node>Debug\node.exe test\parallel\test-fs-stat-bigint.js
C:\WINDOWS\system32\cmd.exe - Debug\node.exe  test\parallel\test-fs-stat-bigint.js [37020]: d:\code\node\src\node_file.cc:962: Assertion `(argc) >= (11)' failed.
SymGetLineFromAddr64 returned error : 487
 1: 00007FF61F72EE8A AES_cbc_encrypt+5218554
SymGetLineFromAddr64 returned error : 487
 2: 00007FF61F6999C7 AES_cbc_encrypt+4607031
SymGetLineFromAddr64 returned error : 487
 3: 00007FF61F699B17 AES_cbc_encrypt+4607367
SymGetLineFromAddr64 returned error : 487
 4: 00007FF61F60B7AC AES_cbc_encrypt+4024860
SymGetLineFromAddr64 returned error : 487
 5: 00007FF62039C925 AES_cbc_encrypt+18250645
SymGetLineFromAddr64 returned error : 487
 6: 00007FF62039B31C AES_cbc_encrypt+18245004
SymGetLineFromAddr64 returned error : 487
 7: 00007FF62039C5DB AES_cbc_encrypt+18249803
SymGetLineFromAddr64 returned error : 487
 8: 00007FF62039BE83 AES_cbc_encrypt+18247923
SymGetLineFromAddr64 returned error : 126
SymFromAddr returned error : 126
 9: 00000074D8C06628

refack · 2018-10-28T22:26:18Z

All comments addressed, PTAL.

tniessen · 2018-10-28T22:33:14Z

src/debug_utils.cc

+      // UnDecorateSymbolName returned success
+      return szUndName;
+    } else {
+      // UnDecorateSymbolName failed


I am not a fan of this type of comment: What happens is obvious in both branches, and the branches themselves are short. (And I think we have a convention of ending comments with a period.)

This code was lifter verbatim from https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address
I would rather keep changes to minimon, for future reverse engineering.

tniessen · 2018-10-28T22:34:03Z

src/debug_utils.cc

+    // Patches:
+    // Use `fprintf(stderr, ` instead of `printf`.
+    // Assign values to `sym` on success.
+    // `current_process_` instead of `hProcess.


I am still not sure whether this is going to help us at some point, I suspect it won't.

Comment are free.
Personally I have not been in a situation where I said "I wish there was less comments"

I tend to agree, but someone will either change our code or the original, and updating the comment will mostly be a maintenance burden at that point from my perspective.

tniessen

LGTM either way, even though I don't see much value in some of the comments.

Refresh `Win32SymbolDebuggingContext::LookupSymbol` to use more APIs PR-URL: nodejs#23822 Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-undecorated-symbol-names Reviewed-By: Tobias Nießen <[email protected]>

Refresh `Win32SymbolDebuggingContext::LookupSymbol` to use more APIs PR-URL: #23822 Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-undecorated-symbol-names Reviewed-By: Tobias Nießen <[email protected]>

Notable changes: * child_process: * All child processes will again open up a new Window on Windows by default. [#24034](#24034) * deps: * A new and fast experimental HTTP parser (`llhttp`) is now supported. [#24059](#24059) * **Windows** * A crashing process will now show the names of stack frames if the node.pdb file is available. [#23822](#23822) * Added new collaborators: * [oyyd](https://github.com/oyyd) - Ouyang Yadong. [#24300](#24300) * [psmarshall](https://github.com/psmarshall) - Peter Marshall. [#24170](#24170) * [shisama](https://github.com/shisama) - Masashi Hirano. [#24136](#24136)

Notable changes: * deps: * A new experimental HTTP parser (`llhttp`) is now supported. #24059 * timers: * Fixed an issue that could cause setTimeout to stop working as expected. #24322 * Windows * A crashing process will now show the names of stack frames if the node.pdb file is available. #23822 * Continued effort to improve the installer's new stage that installs native build tools. #23987, #24348 * child_process: * On Windows the `windowsHide` option default was restored to `false`. This means `detached` child processes and GUI apps will once again start in a new window. #24034 * Added new collaborators: * [oyyd](https://github.com/oyyd) - Ouyang Yadong. #24300 * [psmarshall](https://github.com/psmarshall) - Peter Marshall. #24170 * [shisama](https://github.com/shisama) - Masashi Hirano. #24136

Notable changes: * deps: * A new experimental HTTP parser (`llhttp`) is now supported. #24059 * timers: * Fixed an issue that could cause setTimeout to stop working as expected. #24322 * Windows * A crashing process will now show the names of stack frames if the node.pdb file is available. #23822 * Continued effort to improve the installer's new stage that installs native build tools. #23987, #24348 * child_process: * On Windows the `windowsHide` option default was restored to `false`. This means `detached` child processes and GUI apps will once again start in a new window. #24034 * Added new collaborators: * [oyyd](https://github.com/oyyd) - Ouyang Yadong. #24300 * [psmarshall](https://github.com/psmarshall) - Peter Marshall. #24170 * [shisama](https://github.com/shisama) - Masashi Hirano. #24136 PR-URL: #24350

Refresh `Win32SymbolDebuggingContext::LookupSymbol` to use more APIs PR-URL: #23822 Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-undecorated-symbol-names Reviewed-By: Tobias Nießen <[email protected]>

MylesBorins · 2018-11-27T01:02:29Z

This does not land cleanly in v8.x LTS. Please feel free to manually backport by following the guide. Please also feel free to replace do-not-land if it is being backported

Refresh `Win32SymbolDebuggingContext::LookupSymbol` to use more APIs PR-URL: #23822 Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-symbol-information-by-address Refs: https://docs.microsoft.com/en-us/windows/desktop/Debug/retrieving-undecorated-symbol-names Reviewed-By: Tobias Nießen <[email protected]>

Notable changes: * deps: * upgrade to c-ares v1.15.0 (Ben Noordhuis) #23854 * Windows: * A crashing process will now show the names of stack frames if the node.pdb file is available. (Refael Ackermann) #23822 * Added new collaborators: * Peter Marshall. #24170 * Masashi Hirano. #24136 PR-URL: #24727

Notable changes: * deps: * upgrade to c-ares v1.15.0 (Ben Noordhuis) nodejs#23854 * Windows: * A crashing process will now show the names of stack frames if the node.pdb file is available. (Refael Ackermann) nodejs#23822 * Added new collaborators: * Peter Marshall. nodejs#24170 * Masashi Hirano. nodejs#24136 PR-URL: nodejs#24727

refack requested review from bnoordhuis, addaleax, joaocgreis and bzoz October 22, 2018 19:41

refack self-assigned this Oct 22, 2018

refack added c++ Issues and PRs that require attention from people who are familiar with C++. windows Issues and PRs related to the Windows platform. post-mortem Issues and PRs related to the post-mortem diagnostics of Node.js. labels Oct 22, 2018

TimothyGu reviewed Oct 23, 2018

View reviewed changes

addaleax reviewed Oct 23, 2018

View reviewed changes

refack force-pushed the win-native-stacks branch from bf00718 to 073a5be Compare October 23, 2018 13:03

refack requested review from joyeecheung and tniessen October 28, 2018 22:26

tniessen reviewed Oct 28, 2018

View reviewed changes

tniessen approved these changes Oct 29, 2018

View reviewed changes

refack force-pushed the win-native-stacks branch from 073a5be to 247b513 Compare October 30, 2018 01:45

refack merged commit 247b513 into nodejs:master Oct 30, 2018

refack removed their assignment Oct 30, 2018

refack removed request for joaocgreis, bnoordhuis, joyeecheung and bzoz October 30, 2018 01:54

refack deleted the win-native-stacks branch October 30, 2018 01:54

BridgeAR mentioned this pull request Nov 14, 2018

Release proposal: v11.2 #24350

Merged

BridgeAR added the notable-change PRs with changes that should be highlighted in changelogs. label Nov 15, 2018

MylesBorins added backport-requested-v8.x labels Nov 27, 2018

codebytere mentioned this pull request Nov 27, 2018

v10.13.1 proposal #24675

Closed

codebytere mentioned this pull request Nov 29, 2018

v10.14.2 proposal #24727

Merged


		SymbolInfo LookupSymbol(void* address) override {
		auto dwAddress = reinterpret_cast<DWORD64>(address);

src,win: informative stack traces #23822

src,win: informative stack traces #23822

Conversation

refack commented Oct 22, 2018

Checklist

refack commented Oct 22, 2018 • edited Loading

nodejs-github-bot commented Oct 22, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

addaleax Oct 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

richardlau commented Oct 23, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

refack Oct 23, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

refack commented Oct 23, 2018 • edited Loading

refack commented Oct 23, 2018

Debug mode exe:

refack commented Oct 28, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tniessen left a comment

Choose a reason for hiding this comment

MylesBorins commented Nov 27, 2018

refack commented Oct 22, 2018 •

edited

Loading

addaleax Oct 23, 2018 •

edited

Loading

refack Oct 23, 2018 •

edited

Loading

refack commented Oct 23, 2018 •

edited

Loading