commit e1b90b5fc6df32d08bcc2c60ccfddf6fc22131ad Author: Damian Johnson <atagar@torproject.org> Date: Tue Apr 16 09:44:03 2019 -0700 Improve readability of thread stacktrace dumps Making a few adjustments to how we dump our stacktraces... * Adding dividers to improve readability. Here's an example of what our new dumps look like... ================================================================================ Signal SIGUSR1 received by thread MainThread in process 5819 -------------------------------------------------------------------------------- MainThread thread stacktrace File "./run_tests.py", line 434, in <module> main() File "./run_tests.py", line 316, in main task.join() # no-op if these haven't been run File "/home/atagar/Desktop/stem/test/task.py", line 276, in join self.result = self._background_process.join() File "/home/atagar/Desktop/stem/stem/util/system.py", line 281, in join self._process.join() File "/usr/lib/python2.7/multiprocessing/process.py", line 145, in join res = self._popen.wait(timeout) File "/usr/lib/python2.7/multiprocessing/forking.py", line 154, in wait return self.poll(0) File "/usr/lib/python2.7/multiprocessing/forking.py", line 135, in poll pid, sts = os.waitpid(self.pid, flag) File "./run_tests.py", line 86, in log_traceback for thread_name, stacktrace in test.output.thread_stacktraces().items(): File "/home/atagar/Desktop/stem/test/output.py", line 110, in thread_stacktraces stacktraces[thread.name] = ''.join(traceback.format_stack(frame)) ================================================================================ * Providing this output on stderr rather than stdout. Our test.output module's println() flushes, so there's no need to explicitly do that. * Noting the signal's name rather than its numeric identifier. * Dropping signal suspension. I'd be open to adding this back but without a usecase where it helps I'd prefer to bias toward keeping this simple. --- run_tests.py | 74 ++++++++++++++++++++-------------------------------------- test/output.py | 22 +++++++++++++++++ 2 files changed, 47 insertions(+), 49 deletions(-) diff --git a/run_tests.py b/run_tests.py index 220208b4..6d0951e9 100755 --- a/run_tests.py +++ b/run_tests.py @@ -72,62 +72,40 @@ New capabilities are: """ -def enable_signal_handlers(): - """ - Enable signal handlers for USR1 and ABRT. - """ - signal.signal(signal.SIGABRT, log_traceback) - signal.signal(signal.SIGUSR1, log_traceback) - - -def disable_signal_handlers(): - """ - Ignore signals USR1 and ABRT. - """ - signal.signal(signal.SIGABRT, signal.SIG_IGN) - signal.signal(signal.SIGUSR1, signal.SIG_IGN) - - -def format_traceback(thread): +def log_traceback(sig, frame): """ - Format the traceback for process pid and thread ident using the stack frame. + Dump the stacktraces of all threads on stderr. """ - frame = sys._current_frames().get(thread.ident, None) - - if frame is not None: - return ('Traceback for thread %s in process %d:\n\n%s' % - (thread.name, os.getpid(), ''.join(traceback.format_stack(frame)))) - else: - return ('No traceback for thread %s in process %d.' % (thread.name, os.getpid())) + # Attempt to get the name of our signal. Unfortunately the signal module + # doesn't provide a reverse mapping, so we need to get this ourselves + # from the attributes. + signal_name = str(sig) -def log_traceback(sig, frame): - """ - Signal handler that: - - logs the current thread id and pid, - - logs tracebacks for all threads, - - flushes stdio buffers, - - propagate the signal to multiprocessing.active_children(), and - - in the case of SIGABRT, aborts our process with exit status -1. - While this signal handler is running, other signals are ignored. - """ + for attr_name, value in signal.__dict__.items(): + if attr_name.startswith('SIG') and value == sig: + signal_name = attr_name + break - disable_signal_handlers() + lines = [ + '', # initial NL so we start on our own line + '=' * 80, + 'Signal %s received by thread %s in process %i' % (signal_name, threading.current_thread().name, os.getpid()), + ] - # format and log tracebacks - thread_tracebacks = [format_traceback(thread) - for thread in threading.enumerate()] - print('Signal %s received by thread %s in process %d:\n\n%s' % - (sig, threading.current_thread().name, os.getpid(), - '\n\n'.join(thread_tracebacks))) + for thread_name, stacktrace in test.output.thread_stacktraces().items(): + lines.append('-' * 80) + lines.append('%s thread stacktrace' % thread_name) + lines.append('') + lines.append(stacktrace) - # we're about to signal our children, and maybe do a hard abort, so flush - sys.stdout.flush() + lines.append('=' * 80) + println('\n'.join(lines)) # propagate the signal to any multiprocessing children + for p in multiprocessing.active_children(): - # avoid race conditions if p.is_alive(): os.kill(p.pid, sig) @@ -135,9 +113,6 @@ def log_traceback(sig, frame): # we need to use os._exit() to abort every thread in the interpreter, # rather than raise a SystemExit exception that can be caught os._exit(-1) - else: - # we're done: stop ignoring signals - enable_signal_handlers() def get_unit_tests(module_prefix = None): @@ -194,7 +169,8 @@ def main(): println('%s\n' % exc) sys.exit(1) - enable_signal_handlers() + signal.signal(signal.SIGABRT, log_traceback) + signal.signal(signal.SIGUSR1, log_traceback) test_config = stem.util.conf.get_config('test') test_config.load(os.path.join(test.STEM_BASE, 'test', 'settings.cfg')) diff --git a/test/output.py b/test/output.py index 8ca64372..0eedfa27 100644 --- a/test/output.py +++ b/test/output.py @@ -7,6 +7,8 @@ together for improved readability. """ import re +import threading +import traceback import sys import stem.util.enum @@ -92,6 +94,26 @@ def print_logging(logging_buffer): print('') +def thread_stacktraces(): + """ + Provides a dump of the stacktrace information for all active threads. + + :returns: **dict** that maps thread names to their stacktrace + """ + + stacktraces = {} + + for thread in threading.enumerate(): + frame = sys._current_frames().get(thread.ident, None) + + if frame: + stacktraces[thread.name] = ''.join(traceback.format_stack(frame)) + else: + stacktraces[thread.name] = 'No traceback available' + + return stacktraces + + def apply_filters(testing_output, *filters): """ Gets the tests results, possibly processed through a series of filters. The