From 225bb961e970d44eefaa30f5791687f79f2296a6 Mon Sep 17 00:00:00 2001 From: fabioz Date: Tue, 17 Jul 2018 14:51:09 -0300 Subject: [PATCH] #653: unhandled exceptions no longer reported twice. --- .../pydevd/_pydev_bundle/pydev_override.py | 62 ++-- .../pydevd_additional_thread_info_regular.py | 3 + .../pydevd/_pydevd_bundle/pydevd_console.py | 10 +- .../pydevd_trace_dispatch_regular.py | 22 +- .../pydevd/_pydevd_bundle/pydevd_vars.py | 19 +- ptvsd/_vendored/pydevd/pydevd.py | 34 ++ .../pydevd/tests_python/debugger_unittest.py | 104 ++++-- ...bugger_case_remote_unhandled_exceptions.py | 14 + ...ugger_case_remote_unhandled_exceptions2.py | 20 + ..._case_unhandled_exceptions_on_top_level.py | 1 + ...case_unhandled_exceptions_on_top_level2.py | 6 + .../pydevd/tests_python/test_debugger.py | 341 ++++++++++++++++-- .../pydevd/tests_python/test_dump_threads.py | 11 + 13 files changed, 541 insertions(+), 106 deletions(-) create mode 100644 ptvsd/_vendored/pydevd/tests_python/resources/_debugger_case_remote_unhandled_exceptions.py create mode 100644 ptvsd/_vendored/pydevd/tests_python/resources/_debugger_case_remote_unhandled_exceptions2.py create mode 100644 ptvsd/_vendored/pydevd/tests_python/resources/_debugger_case_unhandled_exceptions_on_top_level.py create mode 100644 ptvsd/_vendored/pydevd/tests_python/resources/_debugger_case_unhandled_exceptions_on_top_level2.py create mode 100644 ptvsd/_vendored/pydevd/tests_python/test_dump_threads.py diff --git a/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_override.py b/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_override.py index bb0c50438..d7581d207 100644 --- a/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_override.py +++ b/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_override.py @@ -1,49 +1,35 @@ def overrides(method): ''' - Initially meant to be used as + Meant to be used as class B: @overrides(A.m1) def m1(self): pass - - but as we want to be compatible with Jython 2.1 where decorators have an uglier syntax (needing an assign - after the method), it should now be used without being a decorator as below (in which case we don't even check - for anything, just that the parent name was actually properly loaded). - - i.e.: - - class B: - overrides(A.m1) - def m1(self): - pass ''' - return + def wrapper(func): + if func.__name__ != method.__name__: + msg = "Wrong @override: %r expected, but overwriting %r." + msg = msg % (func.__name__, method.__name__) + raise AssertionError(msg) -# def wrapper(func): -# if func.__name__ != method.__name__: -# msg = "Wrong @override: %r expected, but overwriting %r." -# msg = msg % (func.__name__, method.__name__) -# raise AssertionError(msg) -# -# if func.__doc__ is None: -# func.__doc__ = method.__doc__ -# -# return func -# -# return wrapper + if func.__doc__ is None: + func.__doc__ = method.__doc__ + + return func + + return wrapper def implements(method): - return -# def wrapper(func): -# if func.__name__ != method.__name__: -# msg = "Wrong @implements: %r expected, but implementing %r." -# msg = msg % (func.__name__, method.__name__) -# raise AssertionError(msg) -# -# if func.__doc__ is None: -# func.__doc__ = method.__doc__ -# -# return func -# -# return wrapper \ No newline at end of file + def wrapper(func): + if func.__name__ != method.__name__: + msg = "Wrong @implements: %r expected, but implementing %r." + msg = msg % (func.__name__, method.__name__) + raise AssertionError(msg) + + if func.__doc__ is None: + func.__doc__ = method.__doc__ + + return func + + return wrapper \ No newline at end of file diff --git a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_additional_thread_info_regular.py b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_additional_thread_info_regular.py index a3069ec36..9c961f41c 100644 --- a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_additional_thread_info_regular.py +++ b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_additional_thread_info_regular.py @@ -77,6 +77,7 @@ class PyDBAdditionalThreadInfo(object): # cdef public int suspend_type; # cdef public int pydev_next_line; # cdef public str pydev_func_name; + # cdef public bint suspended_at_unhandled; # ELSE __slots__ = [ 'pydev_state', @@ -93,6 +94,7 @@ class PyDBAdditionalThreadInfo(object): 'suspend_type', 'pydev_next_line', 'pydev_func_name', + 'suspended_at_unhandled', ] # ENDIF @@ -111,6 +113,7 @@ def __init__(self): self.suspend_type = PYTHON_SUSPEND self.pydev_next_line = -1 self.pydev_func_name = '.invalid.' # Must match the type in cython + self.suspended_at_unhandled = False def iter_frames(self, t): # sys._current_frames(): dictionary with thread id -> topmost frame diff --git a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_console.py b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_console.py index cc60fa749..d504b6698 100644 --- a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_console.py +++ b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_console.py @@ -66,7 +66,7 @@ def to_xml(self): #======================================================================================================================= class DebugConsoleStdIn(BaseStdIn): - overrides(BaseStdIn.readline) + @overrides(BaseStdIn.readline) def readline(self, *args, **kwargs): sys.stderr.write('Warning: Reading from stdin is still not supported in this console.\n') return '\n' @@ -79,7 +79,7 @@ class DebugConsole(InteractiveConsole, BaseInterpreterInterface): errors and outputs to the debug console """ - overrides(BaseInterpreterInterface.create_std_in) + @overrides(BaseInterpreterInterface.create_std_in) def create_std_in(self, *args, **kwargs): try: if not self.__buffer_output: @@ -90,7 +90,7 @@ def create_std_in(self, *args, **kwargs): return DebugConsoleStdIn() #If buffered, raw_input is not supported in this console. - overrides(InteractiveConsole.push) + @overrides(InteractiveConsole.push) def push(self, line, frame, buffer_output=True): """Change built-in stdout and stderr methods by the new custom StdMessage. @@ -134,12 +134,12 @@ def push(self, line, frame, buffer_output=True): return more, [], [] - overrides(BaseInterpreterInterface.do_add_exec) + @overrides(BaseInterpreterInterface.do_add_exec) def do_add_exec(self, line): return InteractiveConsole.push(self, line) - overrides(InteractiveConsole.runcode) + @overrides(InteractiveConsole.runcode) def runcode(self, code): """Execute a code object. diff --git a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_trace_dispatch_regular.py b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_trace_dispatch_regular.py index a17871e2c..468f96392 100644 --- a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_trace_dispatch_regular.py +++ b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_trace_dispatch_regular.py @@ -51,7 +51,7 @@ def trace_dispatch(py_db, frame, event, arg): if name == 'threading': if f_unhandled.f_code.co_name in ('__bootstrap', '_bootstrap'): # We need __bootstrap_inner, not __bootstrap. - return py_db.trace_dispatch + return None elif f_unhandled.f_code.co_name in ('__bootstrap_inner', '_bootstrap_inner'): # Note: be careful not to use threading.currentThread to avoid creating a dummy thread. @@ -62,6 +62,10 @@ def trace_dispatch(py_db, frame, event, arg): break elif name == 'pydevd': + if f_unhandled.f_code.co_name in ('run', 'main'): + # We need to get to _exec + return None + if f_unhandled.f_code.co_name == '_exec': only_trace_for_unhandled_exceptions = True break @@ -92,7 +96,7 @@ def trace_dispatch(py_db, frame, event, arg): thread_tracer = ThreadTracer((py_db, thread, additional_info, global_cache_skips, global_cache_frame_skips)) if f_unhandled is not None: - # print(' --> found', f_unhandled.f_code.co_name, f_unhandled.f_code.co_filename, f_unhandled.f_code.co_firstlineno) + # print(' --> found to trace unhandled', f_unhandled.f_code.co_name, f_unhandled.f_code.co_filename, f_unhandled.f_code.co_firstlineno) if only_trace_for_unhandled_exceptions: f_trace = thread_tracer.trace_unhandled_exceptions else: @@ -135,7 +139,9 @@ def __init__(self, pydb_frame_trace, unhandled_trace): self._unhandled_trace = unhandled_trace def trace_dispatch(self, frame, event, arg): + # print('PyDbFrameTraceAndUnhandledExceptionsTrace', event, frame.f_code.co_name, frame.f_code.co_filename, frame.f_code.co_firstlineno) if event == 'exception' and arg is not None: + # print('self._unhandled_trace', self._unhandled_trace) self._unhandled_trace(frame, event, arg) else: self._pydb_frame_trace(frame, event, arg) @@ -171,12 +177,17 @@ def __init__(self, args): def trace_unhandled_exceptions(self, frame, event, arg): # Note that we ignore the frame as this tracing method should only be put in topmost frames already. + # print('trace_unhandled_exceptions', event, frame.f_code.co_name, frame.f_code.co_filename, frame.f_code.co_firstlineno) if event == 'exception' and arg is not None: from _pydevd_bundle.pydevd_breakpoints import stop_on_unhandled_exception py_db, t, additional_info = self._args[0:3] if arg is not None: - exctype, value, tb = arg - stop_on_unhandled_exception(py_db, t, additional_info, exctype, value, tb) + if not additional_info.suspended_at_unhandled: + if frame.f_back is not None: + additional_info.suspended_at_unhandled = True + + exctype, value, tb = arg + stop_on_unhandled_exception(py_db, t, additional_info, exctype, value, tb) # IFDEF CYTHON # return SafeCallWrapper(self.trace_unhandled_exceptions) # ELSE @@ -184,6 +195,7 @@ def trace_unhandled_exceptions(self, frame, event, arg): # ENDIF def trace_dispatch_and_unhandled_exceptions(self, frame, event, arg): + # print('trace_dispatch_and_unhandled_exceptions', event, frame.f_code.co_name, frame.f_code.co_filename, frame.f_code.co_firstlineno) if event == 'exception' and arg is not None: self.trace_unhandled_exceptions(frame, event, arg) ret = self.trace_dispatch_and_unhandled_exceptions @@ -197,7 +209,7 @@ def trace_dispatch_and_unhandled_exceptions(self, frame, event, arg): # Ok, this frame needs to be traced and needs to deal with unhandled exceptions. Create # a class which does this for us. py_db_frame_trace_and_unhandled_exceptions_trace = PyDbFrameTraceAndUnhandledExceptionsTrace( - self.trace_dispatch_and_unhandled_exceptions, pydb_frame_trace) + pydb_frame_trace, self.trace_dispatch_and_unhandled_exceptions) ret = py_db_frame_trace_and_unhandled_exceptions_trace.trace_dispatch # IFDEF CYTHON # return SafeCallWrapper(ret) diff --git a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_vars.py b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_vars.py index 8da4f43b4..d07e2b777 100644 --- a/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_vars.py +++ b/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_vars.py @@ -137,13 +137,18 @@ def find_frame(thread_id, frame_id): else: msgFrames += ' - ' - errMsg = '''find_frame: frame not found. - Looking for thread_id:%s, frame_id:%s - Current thread_id:%s, available frames: - %s\n - ''' % (thread_id, lookingFor, curr_thread_id, msgFrames) - - sys.stderr.write(errMsg) +# Note: commented this error message out (it may commonly happen +# if a message asking for a frame is issued while a thread is paused +# but the thread starts running before the message is actually +# handled). +# Leaving code to uncomment during tests. +# err_msg = '''find_frame: frame not found. +# Looking for thread_id:%s, frame_id:%s +# Current thread_id:%s, available frames: +# %s\n +# ''' % (thread_id, lookingFor, curr_thread_id, msgFrames) +# +# sys.stderr.write(err_msg) return None return frameFound diff --git a/ptvsd/_vendored/pydevd/pydevd.py b/ptvsd/_vendored/pydevd/pydevd.py index b822c6f0d..a0fdb90dd 100644 --- a/ptvsd/_vendored/pydevd/pydevd.py +++ b/ptvsd/_vendored/pydevd/pydevd.py @@ -1130,6 +1130,40 @@ def enable_qt_support(qt_support_mode): pydev_monkey_qt.patch_qt(qt_support_mode) +def dump_threads(stream=None): + ''' + Helper to dump thread info. + ''' + if stream is None: + stream = sys.stderr + thread_id_to_name = {} + try: + for t in threading.enumerate(): + thread_id_to_name[t.ident] = '%s (daemon: %s, pydevd thread: %s)' % ( + t.name, t.daemon, getattr(t, 'is_pydev_daemon_thread', False)) + except: + pass + + stack_trace = [ + '===============================================================================', + 'Threads running', + '================================= Thread Dump ================================='] + + for thread_id, stack in sys._current_frames().items(): + stack_trace.append('\n-------------------------------------------------------------------------------') + stack_trace.append(" Thread %s" % thread_id_to_name.get(thread_id, thread_id)) + stack_trace.append('') + + if 'self' in stack.f_locals: + stream.write(str(stack.f_locals['self']) + '\n') + + for filename, lineno, name, line in traceback.extract_stack(stack): + stack_trace.append(' File "%s", line %d, in %s' % (filename, lineno, name)) + if line: + stack_trace.append(" %s" % (line.strip())) + stack_trace.append('\n=============================== END Thread Dump ===============================') + stream.write('\n'.join(stack_trace)) + def usage(doExit=0): sys.stdout.write('Usage:\n') diff --git a/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py b/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py index 204ba62bf..13f8cefaf 100644 --- a/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py +++ b/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py @@ -78,6 +78,11 @@ CMD_ERROR = 901 +REASON_CAUGHT_EXCEPTION = CMD_STEP_CAUGHT_EXCEPTION +REASON_UNCAUGHT_EXCEPTION = CMD_ADD_EXCEPTION_BREAK +REASON_STOP_ON_BREAKPOINT = CMD_SET_BREAK +REASON_THREAD_SUSPEND = CMD_THREAD_SUSPEND + # Always True (because otherwise when we do have an error, it's hard to diagnose). SHOW_WRITES_AND_READS = True @@ -95,6 +100,22 @@ except: xrange = range +def overrides(method): + ''' + Helper to check that one method overrides another (redeclared in unit-tests to avoid importing pydevd). + ''' + def wrapper(func): + if func.__name__ != method.__name__: + msg = "Wrong @override: %r expected, but overwriting %r." + msg = msg % (func.__name__, method.__name__) + raise AssertionError(msg) + + if func.__doc__ is None: + func.__doc__ = method.__doc__ + + return func + + return wrapper #======================================================================================================================= # ReaderThread @@ -126,10 +147,16 @@ def get_next_message(self, context_messag): raise AssertionError('No message was written in %s seconds. Error message:\n%s' % (self.TIMEOUT, context_messag,)) else: frame = sys._getframe().f_back - frame_info = ' -- File "%s", line %s, in %s\n' % (frame.f_code.co_filename, frame.f_lineno, frame.f_code.co_name) - frame_info += ' -- File "%s", line %s, in %s\n' % (frame.f_back.f_code.co_filename, frame.f_back.f_lineno, frame.f_back.f_code.co_name) + frame_info = '' + while frame: + stack_msg = ' -- File "%s", line %s, in %s\n' % (frame.f_code.co_filename, frame.f_lineno, frame.f_code.co_name) + if 'run' == frame.f_code.co_name: + frame_info = stack_msg # Ok, found the writer thread 'run' method (show only that). + break + frame_info += stack_msg + frame = frame.f_back frame = None - sys.stdout.write('Message returned in get_next_message(): %s -- ctx: %s, returned to:\n%s\n' % (unquote_plus(unquote_plus(msg)), context_messag, frame_info)) + sys.stdout.write('Message returned in get_next_message(): %s -- ctx: %s, asked at:\n%s\n' % (unquote_plus(unquote_plus(msg)), context_messag, frame_info)) return msg def run(self): @@ -176,7 +203,7 @@ def add_command_line_args(self, args): port = int(writer_thread.port) localhost = pydev_localhost.get_localhost() - ret = args + [ + ret = [ writer_thread.get_pydevd_file(), '--DEBUG_RECORD_SOCKET_READS', '--qt-support', @@ -189,8 +216,9 @@ def add_command_line_args(self, args): if writer_thread.IS_MODULE: ret += ['--module'] - ret = ret + ['--file'] + writer_thread.get_command_line_args() - return ret + ret += ['--file'] + writer_thread.get_command_line_args() + ret = writer_thread.update_command_line_args(ret) # Provide a hook for the writer + return args + ret def check_case(self, writer_thread_class): if callable(writer_thread_class): @@ -226,7 +254,7 @@ def create_process(self, args, writer_thread): process = subprocess.Popen( args, stdout=subprocess.PIPE, - stderr=subprocess.STDOUT, + stderr=subprocess.PIPE, cwd=writer_thread.get_cwd() if writer_thread is not None else '.', env=writer_thread.get_environ() if writer_thread is not None else None, ) @@ -239,7 +267,7 @@ def run_process(self, args, writer_thread): finish = [False] try: - def read(stream, buffer): + def read(stream, buffer, debug_stream, stream_name): for line in stream.readlines(): if finish[0]: return @@ -247,10 +275,11 @@ def read(stream, buffer): line = line.decode('utf-8', errors='replace') if SHOW_STDOUT: - sys.stdout.write('stdout: %s' % (line,)) + debug_stream.write('%s: %s' % (stream_name, line,)) buffer.append(line) - start_new_thread(read, (process.stdout, stdout)) + start_new_thread(read, (process.stdout, stdout, sys.stdout, 'stdout')) + start_new_thread(read, (process.stderr, stderr, sys.stderr, 'stderr')) if SHOW_OTHER_DEBUG_INFO: @@ -297,10 +326,10 @@ def read(stream, buffer): "The other process may still be running -- and didn't give any output.", stdout, stderr, writer_thread) check = 0 - while 'TEST SUCEEDED' not in ''.join(stdout): + while not writer_thread.check_test_suceeded_msg(stdout, stderr): check += 1 if check == 50: - self.fail_with_message("TEST SUCEEDED not found in stdout.", stdout, stderr, writer_thread) + self.fail_with_message("TEST SUCEEDED not found.", stdout, stderr, writer_thread) time.sleep(.1) for _i in xrange(100): @@ -338,8 +367,35 @@ def __init__(self): self._next_breakpoint_id = 0 self.log = [] + def check_test_suceeded_msg(self, stdout, stderr): + return 'TEST SUCEEDED' in ''.join(stdout) + + def update_command_line_args(self, args): + return args + + def _ignore_stderr_line(self, line): + if line.startswith(( + 'debugger: ', + '>>', + '<<', + 'warning: Debugger speedups', + 'pydev debugger: New process is launching', + 'pydev debugger: To debug that process' + )): + return True + + if re.match(r'^(\d+)\t(\d)+', line): + return True + + return False + def additional_output_checks(self, stdout, stderr): - pass + for line in stderr.splitlines(): + line = line.strip() + if not line: + continue + if not self._ignore_stderr_line(line): + raise AssertionError('Did not expect to have line in stderr:\n\n%s\n\nFull stderr:\n\n%s' % (line, stderr)) def get_environ(self): return None @@ -384,14 +440,15 @@ def start_socket(self, port=None): socket_name = get_socket_name(close=True) else: socket_name = (pydev_localhost.get_localhost(), port) - s = socket.socket(socket.AF_INET, socket.SOCK_STREAM) - s.bind(socket_name) + server_socket = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + server_socket.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + server_socket.bind(socket_name) self.port = socket_name[1] - s.listen(1) + server_socket.listen(1) if SHOW_WRITES_AND_READS: print('Waiting in socket.accept()') - self.server_socket = s - new_sock, addr = s.accept() + self.server_socket = server_socket + new_sock, addr = server_socket.accept() if SHOW_WRITES_AND_READS: print('Test Writer Thread Socket:', new_sock, addr) @@ -443,7 +500,7 @@ def wait_for_output(self): def wait_for_breakpoint_hit(self, *args, **kwargs): return self.wait_for_breakpoint_hit_with_suspend_type(*args, **kwargs)[:-1] - def wait_for_breakpoint_hit_with_suspend_type(self, reason='111', get_line=False, get_name=False): + def wait_for_breakpoint_hit_with_suspend_type(self, reason=REASON_STOP_ON_BREAKPOINT, get_line=False, get_name=False): ''' 108 is over 109 is return @@ -451,9 +508,10 @@ def wait_for_breakpoint_hit_with_suspend_type(self, reason='111', get_line=False ''' self.log.append('Start: wait_for_breakpoint_hit') # wait for hit breakpoint - last = '' + last = self.reader_thread.get_next_message('wait_for_breakpoint_hit. reason=%s' % (reason,)) while not ('stop_reason="%s"' % reason) in last: last = self.reader_thread.get_next_message('wait_for_breakpoint_hit. reason=%s' % (reason,)) + # we have something like