Port stack tracing to Windows #168

andyleejordan · 2017-03-04T00:55:07Z

This set of patches implements the stack trace, symbolizer, and demangler for Windows, and their unit tests. It utilizes the Windows debugging APIs in "Dbghelp.h".

There is one TODO for IsFailureSignalHandlerInstalled as I'm unsure yet how to implement it for Windows. That said, in order to make stack trace reporting work "as expected" for test failures, the data dump needs to be done immediately, instead of in the signal handler (see commit message for details).

I've integration tested this with Mesos, and so far it is working well. I've also updated the unit tests where appropriate.

andyleejordan · 2017-03-04T00:57:59Z

Also note: I updated the CMakeLists.txt build system, as that's what I'm familiar with, but there appear to be several Windows build systems maintained in parallel.

This relies on an updated `glog-da816ea70.tar.gz` tarball in the Mesos 3rdparty repository, which is itself generated from the `da816ea70` commit on github.com/google/glog. Additionally, this applies a patch that includes stacktrace support to glog on Windows. The code in this patch is included in an upstream pull request: google/glog#168 If and when that pull request gets merged, we will update the glog tarball and remove the need for the extra patch file. Review: https://reviews.apache.org/r/57490/

kaysoky · 2017-03-14T19:02:02Z

Note: The contents of this PR have been applied to the Windows build of Apache Mesos (apache/mesos@ef3ebf3).

andyleejordan · 2017-04-04T20:56:34Z

Ping @ukai 😄

andyleejordan · 2017-05-23T16:57:09Z

@ukai can a maintainer please take a look?

andyleejordan · 2017-06-05T17:59:05Z

@ukai and @shinh anything blocking this, please, can it at least be reviewed?

andyleejordan · 2017-06-05T18:26:36Z

Adding @sergiud for a possible review.

andyleejordan · 2017-06-08T22:55:50Z

Ping @sergiud @ukai @shinh

shinh

Also, could you update AUTHORS and CONTRIBUTORS as well (see CONTRIBUTING.md)?

shinh · 2017-06-10T09:27:42Z

src/signalhandler.cc

@@ -145,7 +145,7 @@ void DumpTimeInfo() {
 void DumpStackFrameInfo(const char* prefix, void* pc) {
  // Get the symbol name.
  const char *symbol = "(unknown)";
-  char symbolized[1024];  // Big enough for a sane symbol.
+  char symbolized[1024] = {};  // Big enough for a sane symbol.


I couldn't understand why this change is necessary. When Symbolize returns true, SymbolizeAndDemangle fills something to this buffer on both Windows and non-Windows?

Perhaps this was not the case on Linux, but on Windows, the Symbolize() only filled the buffer as far as the symbol took. So you'd run into this kind of problem:

[uninitializedbufferofrandomdata] [main()ializedbufferofrandomdata] [someLongSymbol()ferofrandomdata] [short()gSymbol()ferofrandomdata]

Since the buffer was not being initialized, but the same data location was being reused and only partially filled out, previous longer symbols left gunk in buffer with new shorter symbols.

I solved this by ensuring all elements were initialized to zero each time DumpStackFrameInfo was called. In retrospect, if I ensure a the terminating null is added manually, this becomes unnecessary.

shinh · 2017-06-10T09:32:23Z

src/symbolize.cc

+  symbol->MaxNameLen = MAX_SYM_NAME;
+  bool ret = SymFromAddr(symInitializer.process, reinterpret_cast<DWORD64>(pc), 0, symbol);
+  if (ret && static_cast<int>(symbol->NameLen) < out_size) {
+      strncpy(out, symbol->Name, symbol->NameLen + 1);


Two space indentation please.

Also thanks. Not sure how I messed that up.

shinh · 2017-06-10T09:33:27Z

src/symbolize.cc

+  SYMBOL_INFO *symbol = reinterpret_cast<SYMBOL_INFO*>(buf);
+  symbol->SizeOfStruct = sizeof(SYMBOL_INFO);
+  symbol->MaxNameLen = MAX_SYM_NAME;
+  bool ret = SymFromAddr(symInitializer.process, reinterpret_cast<DWORD64>(pc), 0, symbol);


Could you break after the first comma? We usually don't use more than 80 columns per a line.

Heh, thanks.

shinh · 2017-06-10T09:36:26Z

src/symbolize_unittest.cc

 }
-#endif  // HAVE_STACKTRACE


Could you add // HAVE_SYMBOLIZE? (apparently the previous comment was wrong..)

This took me a little bit to figure out haha, fixing.

shinh · 2017-06-10T09:45:28Z

src/stacktrace_windows-inl.h

+  if (max_depth > 64) {
+    max_depth = 64;
+  }
+  std::vector<void*> stack(max_depth);


Note: On ELF systems, Symbolize and Demangle are meant to be async-signal-safe. As signal handler can be called even while malloc's internal lock is held, I think we use no malloc in Symbolize and Demangle. I don't know Windows signal handler. I assume it's OK to call any functions?

Hmm it seems to be no? https://msdn.microsoft.com/en-us/library/aa272921(v=vs.60).aspx

I'm also worried by Windows API calls to obtain stacktrace/symbol. I guess some of them are calling malloc internally.

shinh · 2017-06-10T09:56:00Z

src/signalhandler.cc

+#elif defined(OS_WINDOWS)
+  typedef void (*SignalHandlerPointer)(int); 
+  SignalHandlerPointer previousHandler;  
+  previousHandler = signal(SIGABRT, &FailureSignalHandler); 


Are you sure you only care SIGABRT? I think handling SIGFPE, SIGILL, and SIGSEGV would be useful.

This is where Windows gets weird. While SIGNAL.H defines all of these signals as valid parameters to signal(), it does so only for compatibility. Explicitly, the signals SIGILL and SIGTERM are not generated on Windows (though you can explicitly raise them).

However, I think that since you can explicitly raise these signals (and it appears that SIGFPE and SIGSEGV might be raised on Windows), I'll change this to handle them all.

Also note:

I ran into a major problem on Windows with signal handling. Let me reproduce the commit message here, as the commit is going to change when I update the PR:

On Windows, the signal handler is invoked on the thread on which it was installed, which is not necessarily the thread where the test failed. So instead of using the signal handler to dump the stack trace, which would dump it from the wrong thread, we dump the information immediately.

Doing this causes us to use a few more frames, so DumpStackInfo needed to configurable skip number.

The nicer approach would be to refactor the MinimalFormatter and info dumping functions out of the signal handler and into the logging library, which is a more relevant home for them, but it is less invasive to simply move the two functions Windows needed into the internal namespace.

So the usual code path that a test failure takes now skips signal handler entirely, and goes straight to dumping stack and symbols.

I think this is because the Windows signal handler is not like what is found on Linux like systems. Instead, it uses structured exception handling (SEH). I don't know much more than what I've researched on this (ironically I am not a Windows dev, I am a Linux dev), but I know this was quite an annoying problem to solve. Signaling on Windows switches threads (to the SEH thread, I guess?) and CaptureStackBackTrace explicitly gets the backtrace for the current thread. I'm looking for a way to do this right.

Oh here it is.

The signal handler was being on the thread on which it was installed, not a dedicated SEH thread (I was mis-remembering), and importantly, not the thread on which the signal was raised.

I fixed this. I did a bit more investigating, and now this works as expected. You install the failure signal handlers, and thing work like they do on Linux.

shinh · 2017-06-10T09:56:19Z

src/demangle.cc

+  // only the mangled symbol, `?func@Foo@@SAXH@Z`. Fortunately, the
+  // mangled symbol is guaranteed not to have parentheses,
+  // so we search for `(` and extract up to `)`.
+  std::string symbol(mangled);


Again, it'd be better to avoid malloc.

Hmm I'm confused. I think I've left a comment in stacktrace_windows-inl.h or somewhere, but the comment has disappeared :(

Anyway, I think calling malloc in signal handler isn't safe, so it'd be nicer to avoid using std::string. https://msdn.microsoft.com/en-us/library/aa272921(v=vs.60).aspx

I'm also worried by Windows APIs.

You're right, I need to fix this up.

(I found your other comment by the way, it was getting hidden under "show outdated" even though I don't think the code was actually outdated. Not sure what GitHub is up to.)

shinh · 2017-06-10T10:15:45Z

src/signalhandler.cc

+void DumpStackFrameInfo(const char* prefix, void* pc) {
+  // Get the symbol name.
+  const char *symbol = "(unknown)";
+  char symbolized[1024] = {};  // Big enough for a sane symbol.


I couldn't understand why this change is necessary. When Symbolize returns true, SymbolizeAndDemangle fills something to this buffer on both Windows and non-Windows?

I think this comment got duplicated.

shinh · 2017-06-10T10:20:59Z

Thanks for the patch! Sorry for the huge latency... Could you update AUTHORS and CONTRIBUTORS as well (see CONTRIBUTING.md)? I'm a bit worried by the use of malloc and Windows APIs in signal handler, but I think it's definitely much nicer than nothing. So I'm planning to merge this PR if others don't objects.

sergiud

Some nitpicking, but otherwise looks good to me.

sergiud · 2017-06-10T11:31:01Z

CMakeLists.txt

+if (WIN32)
+  set (HAVE_STACKTRACE 1)
+  set (HAVE_SYMBOLIZE 1)
+  target_link_libraries (glog PUBLIC Dbghelp.lib)


I would remove the .lib suffix here and replace Dbghelp by proper capitalization of library's name, i.e., DbgHelp .

I agree, and even more so, I think I should instead use:

#pragma comment(lib, "DbgHelp")

In an appropriate header, eliminating the need for us to target_link_libraries or for consumers of Glog to do so either.

sergiud · 2017-06-10T11:32:49Z

src/demangle.cc

 #include "demangle.h"

+#if defined(OS_WINDOWS)
+#include <Dbghelp.h>


For consistency reasons, same as before, i.e., DbgHelp.h instead of Dbghelp.h. Windows Dev Center also suggests this header name.

Got it. This is where I'm going to add the pragma for automatic linking as well.

sergiud · 2017-06-10T11:33:52Z

src/symbolize.cc

@@ -837,6 +837,57 @@ static ATTRIBUTE_NOINLINE bool SymbolizeAndDemangle(void *pc, char *out,

 _END_GOOGLE_NAMESPACE_

+#elif defined(OS_WINDOWS)
+
+#include "Dbghelp.h"


Same as before.

sergiud · 2017-06-10T11:38:03Z

src/symbolize.cc

+
+_START_GOOGLE_NAMESPACE_
+
+class SymInitializer {


This class should not be copied, correct? To ensure no one does this in the future, I'd delete the copy constructor and copy assignment operator by adding the declarations

SymInitializer(const SymInitializer&); SymInitializer& operator=(const SymInitializer&);

to the private section of the class.

andyleejordan · 2017-06-19T19:04:31Z

@serguid and @shinh Thank you so much for getting to this and reviewing it! I'll commit to updating it per reviews (plus feedback on some confusing Windows-y parts) by the end of the week. Talk to you soon!

andyleejordan · 2017-06-24T00:04:26Z

With a fresh set of eyes (and more Windows knowledge) I actually managed to get the signal handler working properly today (just tested an integration with Mesos). I'll get it cleaned up and the PR posted.

andyleejordan · 2017-06-27T04:15:34Z

@shinh and @sergiud this is ready for a final review I believe. I fixed the mentioned issues, and fixed the deeper issue of the signal handler not being all the way hooked up. From my previous comments, I mentioned that I'd plumbed around the signal handler "not working as expected" on Windows; but I now have it working as expected, and undid the unnecessary changes. Users should use InstallFailureSignalHandler() and expect LOG(FATAL), CHECK(...) and abort() etc. to all work.

shinh

Thanks! I'm fine with merging this PR, but I'd like to ask a couple of questions.

shinh · 2017-06-27T07:36:14Z

src/symbolize.cc

+
+__declspec(noinline) static bool SymbolizeAndDemangle(void *pc, char *out,
+                                                      int out_size) {
+  const SymInitializer symInitializer;


I'd guess SymInitialize is a fairly complex function. Does it have no malloc?

Also, is it a good idea to construct SymInitializer every time? Perhaps the results of SymInitialize will be cached internally and the second SymInitialize call is fast?

I think I meant this to be a const static variable so it was initialized only once.

I'd guess SymInitialize is a fairly complex function. Does it have no malloc?

I'm unsure. I suppose we could construct SymInitialize at startup (i.e. move symInitializer out of the function here).

I'm unsure. I suppose we could construct SymInitialize at startup (i.e. move symInitializer out of the function here).

Yeah, but MSDN told me SymInitialize could be slow. Perhaps it might be a good idea to add a function which initializes SymInitialize if a library user wants to be safe. Anyway, it's up to you. I'm OK with the current patch. Probably I'll merge this PR tomorrow unless you want me to wait a bit more.

@shinh that's where I'm at with it; I initialized it in the function since it can be slow. While I think adding a function to pre-initialize it for safety is a good idea, it's also not necessary for most use cases (judging by how I'm using this in Mesos anyways), so I'd rather not add it now.

I am good with the current contents of this PR for you to merge them. Thank you for your help!

Necessary when building with BUILD_SHARED_LIBS=1.

This method ensure that all users of glog get automatically linked to the DbgHelp library without needing to set compiler flags.

andyleejordan · 2017-06-27T18:39:47Z

Just to add some test results:

CentOS 7 (ensuring I didn't break anything):

$ ./autogen.sh
$ ./configure
$ make -j8
$ make check
============================================================================
Testsuite summary for glog 0.3.5
============================================================================
# TOTAL: 6
# PASS:  6
# SKIP:  0
# XFAIL: 0
# FAIL:  0
# XPASS: 0
# ERROR: 0
============================================================================

$ mkdir build
$ cd build
$ cmake3 ..
$ make -j8
$ ctest
Test project /home/andschwa/src/glog/build
    Start 1: demangle
1/6 Test #1: demangle .........................   Passed    0.00 sec
    Start 2: logging
2/6 Test #2: logging ..........................   Passed    0.53 sec
    Start 3: signalhandler
3/6 Test #3: signalhandler ....................   Passed    0.01 sec
    Start 4: stacktrace
4/6 Test #4: stacktrace .......................   Passed    0.00 sec
    Start 5: stl_logging
5/6 Test #5: stl_logging ......................   Passed    0.00 sec
    Start 6: symbolize
6/6 Test #6: symbolize ........................   Passed    0.00 sec

100% tests passed, 0 tests failed out of 6

Total Test time (real) =   0.55 sec

Windows 10:

$ mkdir build
$ cd build
$ cmake ..
$ cmake --build . --config Debug
$ ctest -C Debug
Test project C:/Users/andschwa/src/glog/build
    Start 1: demangle
1/6 Test #1: demangle .........................   Passed    0.05 sec
    Start 2: logging
2/6 Test #2: logging ..........................***Failed    0.47 sec
    Start 3: signalhandler
3/6 Test #3: signalhandler ....................   Passed    0.02 sec
    Start 4: stacktrace
4/6 Test #4: stacktrace .......................***Failed    0.97 sec
    Start 5: stl_logging
5/6 Test #5: stl_logging ......................   Passed    0.01 sec
    Start 6: symbolize
6/6 Test #6: symbolize ........................   Passed    0.03 sec

67% tests passed, 2 tests failed out of 6

Total Test time (real) =   1.58 sec

The following tests FAILED:
          2 - logging (Failed)
          4 - stacktrace (Failed)
Errors while running CTest

The stacktrace test tends to fail in Debug because of the incremental linking table making function and return addresses unreliable. The symbolizer should now be expected to fail because the Release configuration doesn't have symbol information.

$ cmake --build . --config Release
$ ctest -C Release
Test project C:/Users/andschwa/src/glog/build
    Start 1: demangle
1/6 Test #1: demangle .........................   Passed    0.00 sec
    Start 2: logging
2/6 Test #2: logging ..........................***Failed    0.45 sec
    Start 3: signalhandler
3/6 Test #3: signalhandler ....................   Passed    0.02 sec
    Start 4: stacktrace
4/6 Test #4: stacktrace .......................   Passed    0.02 sec
    Start 5: stl_logging
5/6 Test #5: stl_logging ......................   Passed    0.01 sec
    Start 6: symbolize
6/6 Test #6: symbolize ........................***Exception: Other  3.15 sec

67% tests passed, 2 tests failed out of 6

Total Test time (real) =   3.69 sec

The following tests FAILED:
          2 - logging (Failed)
          6 - symbolize (OTHER_FAULT)
Errors while running CTest

And finally, the logging test fails just due to a difference in padding:

$ ctest -V -C Debug
2: Test with golden file failed. We'll try to show the diff:
2: --- C:/Users/andschwa/src/glog/src/logging_unittest.err.munged       Tue Jun 27 11:36:39 2017
2: +++ C:\Users\andschwa\AppData\Local\Temp\/captured.err.munged        Tue Jun 27 11:36:39 2017
2: @@ -78,7 +78,7 @@
2:  IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo bar 10 3.400000
2:  WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: array
2:  IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: const array
2: -IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: ptr 12345678
2: +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: ptr 0000000012345678
2:  IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: ptr 0000000000000000
2:  EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo 1000 0000001000 3e8
2:  IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo 1000
2: diff command was failed.
2: Check failed: MungeAndDiffTestStderr(FLAGS_test_srcdir + "/src/logging_unittest.err")
2/6 Test #2: logging ..........................***Failed    0.45 sec

The golden file has 12345678 and we print 0000000012345678.

Finally, I've also linked this library into Mesos and tested some expected failures with an abort(), a CHECK_EQ(true, false) and a LOG(FATAL) << Failing, and stack traces are being generated properly.

shinh · 2017-06-28T03:32:20Z

Yeah, further changes can be done in a separate PR if necessary. Thanks!

andyleejordan · 2017-06-28T03:33:46Z

Woo! Thank you :)

andyleejordan · 2017-06-30T21:46:51Z

src/utilities.cc

    struct sigaction sig_action;
    memset(&sig_action, 0, sizeof(sig_action));
    sigemptyset(&sig_action.sa_mask);
    sig_action.sa_handler = SIG_DFL;
    sigaction(SIGABRT, &sig_action, NULL);
-  }
+#elif defined(OS_WINDOWS)
+    signal(SIGABRT, SIG_DFL);


Oops, this should set kFailureSignalHandlerInstalled back to false.

Port stack tracing to Windows

bmahler · 2020-03-13T21:36:14Z

Filed to issues to improve this: issue 534 and issue 535.

googlebot added the cla: yes label Mar 4, 2017

andyleejordan force-pushed the windows-stacktrace branch 4 times, most recently from 13d0440 to c2b2dde Compare March 9, 2017 22:31

shinh reviewed Jun 10, 2017

View reviewed changes

sergiud requested changes Jun 10, 2017

View reviewed changes

andyleejordan added 3 commits June 26, 2017 16:21

Add Andrew Schwartzmeyer to authors and contributors

bcaaa5d

Copy stacktrace_generic-inl.h for Windows

9c1d0e6

Support stacktrace on Windows

e5d3644

andyleejordan force-pushed the windows-stacktrace branch from 2a173b0 to 1553f33 Compare June 27, 2017 04:13

andyleejordan force-pushed the windows-stacktrace branch from 1553f33 to 0691a92 Compare June 27, 2017 04:16

shinh approved these changes Jun 27, 2017

View reviewed changes

andyleejordan added 3 commits June 27, 2017 10:50

Support symbolizer and demangler on Windows

f1d64f7

Export GetStackTrace

e2caf98

Necessary when building with BUILD_SHARED_LIBS=1.

Link to DbgHelp using pre-processor directive

7f95ecf

This method ensure that all users of glog get automatically linked to the DbgHelp library without needing to set compiler flags.

Support signal handler on Windows

d1f49ba

andyleejordan force-pushed the windows-stacktrace branch from 0691a92 to d1f49ba Compare June 27, 2017 17:52

shinh merged commit 5cfa9a2 into google:master Jun 28, 2017

andyleejordan deleted the windows-stacktrace branch June 28, 2017 03:34

andyleejordan commented Jun 30, 2017

View reviewed changes

durswd pushed a commit to durswd/glog that referenced this pull request Sep 2, 2019

Merge pull request google#168 from andschwa/windows-stacktrace

c4b329e

Port stack tracing to Windows

ashione mentioned this pull request Oct 19, 2020

[Log] Ignore callstacktrace test for windows ray-project/ray#11413

Merged

6 tasks

		}
		#endif // HAVE_STACKTRACE

Port stack tracing to Windows #168

Port stack tracing to Windows #168

Conversation

andyleejordan commented Mar 4, 2017

andyleejordan commented Mar 4, 2017

kaysoky commented Mar 14, 2017

andyleejordan commented Apr 4, 2017

andyleejordan commented May 23, 2017

andyleejordan commented Jun 5, 2017

andyleejordan commented Jun 5, 2017

andyleejordan commented Jun 8, 2017

shinh left a 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

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

shinh commented Jun 10, 2017

sergiud left a 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

andyleejordan commented Jun 19, 2017

andyleejordan commented Jun 24, 2017

andyleejordan commented Jun 27, 2017

shinh left a 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

andyleejordan commented Jun 27, 2017

shinh commented Jun 28, 2017

andyleejordan commented Jun 28, 2017

Choose a reason for hiding this comment

bmahler commented Mar 13, 2020