diff --git a/pytest.ini b/pytest.ini index 229013d7..223ce029 100644 --- a/pytest.ini +++ b/pytest.ini @@ -2,4 +2,4 @@ testpaths=tests timeout=30 timeout_method=thread -addopts=-n8 +addopts=-n6 diff --git a/src/ptvsd/__main__.py b/src/ptvsd/__main__.py index 5dee9cc1..e25cbe71 100644 --- a/src/ptvsd/__main__.py +++ b/src/ptvsd/__main__.py @@ -60,6 +60,7 @@ HELP = ('''ptvsd %s See https://aka.ms/ptvsd for documentation. Usage: ptvsd --host
[--port ] [--wait] [--multiprocess] + [--log-dir ] ''' + TARGET + ''' ''') % (ptvsd.version.__version__,) @@ -128,6 +129,7 @@ switches = [ ('--port', '', set_arg('port', port), False), ('--wait', None, set_true('wait'), False), ('--multiprocess', None, set_true('multiprocess'), False), + ('--log-dir', '', set_arg('log_dir', string), False), # Switches that are used internally by the IDE or ptvsd itself. ('--nodebug', None, set_nodebug, False), @@ -224,10 +226,12 @@ def setup_connection(): else: _, _, _, sys.argv[0] = runpy._get_module_details(opts.target) except Exception: - pass + ptvsd.log.exception('Error determining module path for sys.argv') else: assert False + ptvsd.log.debug('sys.argv after patching: {0!r}', sys.argv) + addr = (opts.host, opts.port) global daemon @@ -246,14 +250,21 @@ def setup_connection(): def run_file(): setup_connection() + target = ptvsd.options.target + ptvsd.log.info('Running file {0}', target) # run_path has one difference with invoking Python from command-line: # if the target is a file (rather than a directory), it does not add its # parent directory to sys.path. Thus, importing other modules from the # same directory is broken unless sys.path is patched here. if os.path.isfile(target): - sys.path.insert(0, os.path.dirname(target)) + dir = os.path.dirname(target) + ptvsd.log.debug('Adding {0} to sys.path.', dir) + sys.path.insert(0, dir) + else: + ptvsd.log.debug('Not a file: {0}', target) + runpy.run_path(target, run_name='__main__') @@ -267,6 +278,8 @@ def run_module(): if sys.version_info < (3,) and not isinstance(target, bytes): target = target.encode(sys.getfilesystemencoding()) + ptvsd.log.info('Running module {0}', target) + # Add current directory to path, like Python itself does for -m. sys.path.insert(0, '') @@ -278,12 +291,15 @@ def run_module(): try: run_module_as_main = runpy._run_module_as_main except AttributeError: + ptvsd.log.warning('runpy._run_module_as_main is missing, falling back to run_module.') runpy.run_module(target, alter_sys=True) else: run_module_as_main(target, alter_argv=True) def run_code(): + ptvsd.log.info('Running code:\n\n{0}', ptvsd.options.target) + # Add current directory to path, like Python itself does for -c. sys.path.insert(0, '') code = compile(ptvsd.options.target, '', 'exec') @@ -293,16 +309,21 @@ def run_code(): def attach_to_pid(): def quoted_str(s): + if s is None: + return s assert not isinstance(s, bytes) unescaped = set(chr(ch) for ch in range(32, 127)) - {'"', "'", '\\'} def escape(ch): return ch if ch in unescaped else '\\u%04X' % ord(ch) return 'u"' + ''.join(map(escape, s)) + '"' + ptvsd.log.info('Attaching to process with ID {0}', ptvsd.options.target) + pid = ptvsd.options.target host = quoted_str(ptvsd.options.host) port = ptvsd.options.port client = ptvsd.options.client + log_dir = quoted_str(ptvsd.options.log_dir) ptvsd_path = os.path.abspath(os.path.join(ptvsd.__file__, '../..')) if isinstance(ptvsd_path, bytes): @@ -320,10 +341,15 @@ import ptvsd del sys.path[0] import ptvsd.options +ptvsd.options.log_dir = {log_dir} ptvsd.options.client = {client} ptvsd.options.host = {host} ptvsd.options.port = {port} +import ptvsd.log +ptvsd.log.to_file() +ptvsd.log.info('Debugger successfully injected') + if ptvsd.options.client: from ptvsd._remote import attach attach(({host}, {port})) @@ -332,6 +358,8 @@ else: '''.format(**locals()) print(code) + ptvsd.log.debug('Injecting debugger into target process.') + pydevd_attach_to_process_path = os.path.join( os.path.dirname(pydevd.__file__), 'pydevd_attach_to_process') @@ -341,12 +369,17 @@ else: def main(argv=sys.argv): + saved_argv = argv try: sys.argv[:] = [argv[0]] + list(parse(argv[1:])) except Exception as ex: print(HELP + '\nError: ' + str(ex), file=sys.stderr) sys.exit(2) + ptvsd.log.to_file() + ptvsd.log.info('main({0!r})', saved_argv) + ptvsd.log.info('sys.argv after parsing: {0!r}', sys.argv) + try: run = { 'file': run_file, @@ -356,6 +389,7 @@ def main(argv=sys.argv): }[ptvsd.options.target_kind] run() except SystemExit as ex: + ptvsd.log.exception('Debuggee exited via SystemExit', category='D') if daemon is not None: if ex.code is None: daemon.exitcode = 0 diff --git a/src/ptvsd/_local.py b/src/ptvsd/_local.py index 8ccd9085..666d4869 100644 --- a/src/ptvsd/_local.py +++ b/src/ptvsd/_local.py @@ -115,7 +115,6 @@ def _run_main_argv(filename, extra): def _run(argv, addr, _pydevd=pydevd, _install=install, **kwargs): """Start pydevd with the given commandline args.""" - #print(' '.join(argv)) # Pydevd assumes that the "__main__" module is the "pydevd" module # and does some tricky stuff under that assumption. For example, diff --git a/src/ptvsd/_remote.py b/src/ptvsd/_remote.py index 8da0c314..cdc2d750 100644 --- a/src/ptvsd/_remote.py +++ b/src/ptvsd/_remote.py @@ -9,6 +9,7 @@ import time from _pydevd_bundle.pydevd_comm import get_global_debugger import ptvsd +import ptvsd.log import ptvsd.options from ptvsd._util import new_hidden_thread from ptvsd.pydevd_hooks import install @@ -32,12 +33,6 @@ def _pydevd_settrace(redirect_output=None, _pydevd=pydevd, **kwargs): _pydevd.settrace(**kwargs) -# TODO: Split up enable_attach() to align with module organization. -# This should including making better use of Daemon (e,g, the -# start_server() method). -# Then move at least some parts to the appropriate modules. This module -# is focused on running the debugger. - global_next_session = lambda: None @@ -49,15 +44,16 @@ def enable_attach(address, **kwargs): ptvsd.main_thread = threading.current_thread() - host, port = address def wait_for_connection(daemon, host, port, next_session=None): + ptvsd.log.debug('Waiting for pydevd ...') debugger = get_global_debugger() while debugger is None: time.sleep(0.1) debugger = get_global_debugger() + ptvsd.log.debug('Unblocking pydevd.') debugger.ready_to_run = True while True: @@ -82,6 +78,7 @@ def enable_attach(address, singlesession=False, **kwargs) + ptvsd.log.debug('Starting connection listener thread') connection_thread = new_hidden_thread('ptvsd.listen_for_connection', wait_for_connection, args=(daemon, host, port)) @@ -90,6 +87,7 @@ def enable_attach(address, if ptvsd.options.no_debug: _setup_nodebug() else: + ptvsd.log.debug('pydevd.settrace()') _pydevd.settrace(host=host, stdoutToServer=redirect_output, stderrToServer=redirect_output, @@ -107,13 +105,13 @@ def attach(address, **kwargs): ptvsd.main_thread = threading.current_thread() - host, port = address daemon = _install(_pydevd, address, singlesession=False, **kwargs) if ptvsd.options.no_debug: _setup_nodebug() else: + ptvsd.log.debug('pydevd.settrace()') _pydevd.settrace(host=host, port=port, stdoutToServer=redirect_output, @@ -125,6 +123,7 @@ def attach(address, def _setup_nodebug(): + ptvsd.log.debug('Running pydevd in nodebug mode.') debugger = pydevd.PyDB() debugger.init_matplotlib_support = lambda *arg: None # We are invoking run() solely for side effects here - setting up the diff --git a/src/ptvsd/_util.py b/src/ptvsd/_util.py index 42fbc77b..5a4e84dc 100644 --- a/src/ptvsd/_util.py +++ b/src/ptvsd/_util.py @@ -5,28 +5,12 @@ from __future__ import print_function import contextlib -import os import threading import time import types import sys - -DEBUG = False -if os.environ.get('PTVSD_DEBUG', ''): - DEBUG = True - - -def debug(*msg, **kwargs): - if not DEBUG: - return - tb = kwargs.pop('tb', False) - assert not kwargs - if tb: - import traceback - traceback.print_exc() - print(*msg, file=sys.__stderr__) - sys.__stderr__.flush() +import ptvsd.log @contextlib.contextmanager @@ -34,9 +18,9 @@ def ignore_errors(log=None): """A context manager that masks any raised exceptions.""" try: yield - except Exception as exc: + except Exception: if log is not None: - log('ignoring error', exc) + ptvsd.log.exception('Ignoring error', category='I') def call_all(callables, *args, **kwargs): @@ -52,37 +36,6 @@ def call_all(callables, *args, **kwargs): return results -######################## -# pydevd stuff - -from _pydevd_bundle import pydevd_comm # noqa - - -def log_pydevd_msg(cmdid, seq, args, inbound, - log=debug, prefix=None, verbose=False): - """Log a representation of the given pydevd msg.""" - if log is None or (log is debug and not DEBUG): - return - if not verbose and cmdid == pydevd_comm.CMD_WRITE_TO_CONSOLE: - return - - if prefix is None: - prefix = '-> ' if inbound else '<- ' - try: - cmdname = pydevd_comm.ID_TO_MEANING[str(cmdid)] - except KeyError: - for cmdname, value in vars(pydevd_comm).items(): - if cmdid == value: - break - else: - cmdname = '???' - cmd = '{} ({})'.format(cmdid, cmdname) - if isinstance(args, bytes) or isinstance(args, str): - args = args.replace('\n', '\\n') - msg = '{}{:28} [{:>10}]: |{}|'.format(prefix, cmd, seq, args) - log(msg) - - ######################## # threading stuff diff --git a/src/ptvsd/attach_server.py b/src/ptvsd/attach_server.py index be2de016..1a8cdfa4 100644 --- a/src/ptvsd/attach_server.py +++ b/src/ptvsd/attach_server.py @@ -2,13 +2,15 @@ # Licensed under the MIT License. See LICENSE in the project root # for license information. +import sys + +import ptvsd.log from ptvsd._remote import ( attach as ptvsd_attach, enable_attach as ptvsd_enable_attach, _pydevd_settrace, ) from ptvsd.wrapper import debugger_attached -import sys import pydevd from _pydevd_bundle.pydevd_constants import get_global_debugger @@ -32,10 +34,11 @@ def wait_for_attach(timeout=None): timeout : float, optional The timeout for the operation in seconds (or fractions thereof). """ + ptvsd.log.info('wait_for_attach{0!r}', (timeout,)) debugger_attached.wait(timeout) -def enable_attach(address=(DEFAULT_HOST, DEFAULT_PORT), redirect_output=True): +def enable_attach(address=(DEFAULT_HOST, DEFAULT_PORT), redirect_output=True, log=None): """Enables a client to attach to this process remotely to debug Python code. Parameters @@ -50,6 +53,8 @@ def enable_attach(address=(DEFAULT_HOST, DEFAULT_PORT), redirect_output=True): redirect_output : bool, optional Specifies whether any output (on both `stdout` and `stderr`) produced by this program should be sent to the debugger. Default is ``True``. + log : str, optional + Name of the file that debugger will use as a log. Notes ----- @@ -63,8 +68,15 @@ def enable_attach(address=(DEFAULT_HOST, DEFAULT_PORT), redirect_output=True): attached. Any threads that are already running before this function is called will not be visible. """ + + if log: + ptvsd.log.to_file(log) + ptvsd.log.info('enable_attach{0!r}', (address, redirect_output)) + if is_attached(): + ptvsd.log.info('enable_attach() ignored - already attached.') return + debugger_attached.clear() # Ensure port is int @@ -77,7 +89,7 @@ def enable_attach(address=(DEFAULT_HOST, DEFAULT_PORT), redirect_output=True): ) -def attach(address, redirect_output=True): +def attach(address, redirect_output=True, log=None): """Attaches this process to the debugger listening on a given address. Parameters @@ -90,9 +102,18 @@ def attach(address, redirect_output=True): redirect_output : bool, optional Specifies whether any output (on both `stdout` and `stderr`) produced by this program should be sent to the debugger. Default is ``True``. + log : str, optional + Name of the file that debugger will use as a log. """ + + if log: + ptvsd.log.to_file(log) + ptvsd.log.info('attach{0!r}', (address, redirect_output)) + if is_attached(): + ptvsd.log.info('attach() ignored - already attached.') return + debugger_attached.clear() # Ensure port is int @@ -101,8 +122,6 @@ def attach(address, redirect_output=True): ptvsd_attach(address, redirect_output=redirect_output) -# TODO: Add disable_attach()? - def is_attached(): """Returns ``True`` if debugger is attached, ``False`` otherwise.""" @@ -113,7 +132,11 @@ def break_into_debugger(): """If a remote debugger is attached, pauses execution of all threads, and breaks into the debugger with current thread as active. """ + + ptvsd.log.info('break_into_debugger()') + if not is_attached(): + ptvsd.log.info('break_into_debugger() ignored - debugger not attached') return # Get the first frame in the stack that's not an internal frame. diff --git a/src/ptvsd/daemon.py b/src/ptvsd/daemon.py index 9b1d8330..abdcf6c0 100644 --- a/src/ptvsd/daemon.py +++ b/src/ptvsd/daemon.py @@ -6,6 +6,7 @@ import contextlib import sys import threading +import ptvsd.log from ptvsd import wrapper, options, multiproc from ptvsd.socket import ( close_socket, create_server, create_client, connect, Address) @@ -14,7 +15,7 @@ from .exit_handlers import ( kill_current_proc) from .session import PyDevdDebugSession from ._util import ( - ClosedError, NotRunningError, ignore_errors, debug, lock_wait) + ClosedError, NotRunningError, ignore_errors, lock_wait) session_not_bound = threading.Event() @@ -150,13 +151,16 @@ class DaemonBase(object): def start_server(self, addr, hidebadsessions=True): """Return ("socket", next_session) with a new server socket.""" + + ptvsd.log.debug('Starting server daemon on {0!r}.', addr) + addr = Address.from_raw(addr) with self.started(): assert self._sessionlock is None assert self.session is None self._server = create_server(addr.host, addr.port) host, port = self._server.getsockname() - debug('server socket created on %r:%r' % (host, port)) + ptvsd.log.debug('Server socket created on {0!r}', addr) self._sessionlock = threading.Lock() sock = self._sock @@ -170,28 +174,27 @@ class DaemonBase(object): sessionlock = self._sessionlock check_ready(checksession=False) - debug('getting next session') + ptvsd.log.debug('Getting next session...') sessionlock.acquire() # Released in _finish_session(). - debug('session lock acquired') + ptvsd.log.debug('Session lock acquired.') # It may have closed or stopped while we waited. check_ready() timeout = kwargs.pop('timeout', None) try: - debug('getting session socket') + ptvsd.log.debug('Getting session socket...') client = connect(server, None, **kwargs) self._bind_session(client) - debug('starting session') + ptvsd.log.debug('Starting session...') self._start_session_safely('ptvsd.Server', timeout=timeout) - debug('session started') + ptvsd.log.debug('Session started.') return self._session - except Exception as exc: - debug('session exc:', exc, tb=True) + except Exception: + ptvsd.log.exception(category=('D' if hidebadsessions else 'E')) with ignore_errors(): self._finish_session() if hidebadsessions: - debug('hiding bad session') - # TODO: Log the error? + ptvsd.log.debug('Hiding bad session') return None self._stop_quietly() raise @@ -203,6 +206,9 @@ class DaemonBase(object): def start_client(self, addr): """Return ("socket", start_session) with a new client socket.""" + + ptvsd.log.debug('Starting client daemon on {0!r}.', addr) + addr = Address.from_raw(addr) self._singlesession = True with self.started(): @@ -234,6 +240,9 @@ class DaemonBase(object): If "session" is a client socket then a session is created from it. """ + + ptvsd.log.debug('Starting session.') + self._check_ready_for_session() if self._server is not None: raise RuntimeError('running as server') @@ -244,6 +253,9 @@ class DaemonBase(object): def close(self): """Stop all loops and release all resources.""" + + ptvsd.log.debug('Stopping daemon.') + with self._lock: if self._closed: raise DaemonClosedError('already closed') @@ -298,7 +310,7 @@ class DaemonBase(object): self._stop() def _handle_session_disconnecting(self, session): - debug('handling disconnecting session') + ptvsd.log.debug('Handling disconnecting session') if self._singlesession: if self._killonclose: with self._lock: @@ -316,7 +328,7 @@ class DaemonBase(object): pass def _handle_session_closing(self, session): - debug('handling closing session') + ptvsd.log.debug('Handling closing session') if self._singlesession: if self._killonclose: @@ -344,9 +356,9 @@ class DaemonBase(object): try: sessionlock.release() except Exception: # TODO: Make it more specific? - debug('session lock not released') + ptvsd.log.exception('Session lock not released', category='D') else: - debug('session lock released') + ptvsd.log.debug('Session lock released') # internal session-related methods @@ -367,6 +379,7 @@ class DaemonBase(object): try: self._start_session(threadname, **kwargs) except Exception: + ptvsd.log.exception() with ignore_errors(): self._finish_session() raise @@ -376,12 +389,12 @@ class DaemonBase(object): session_not_bound.set() try: session = self._release_session() - debug('session stopped') + ptvsd.log.debug('Session stopped') finally: self._clear_sessionlock() if self._singlesession: - debug('closing daemon after single session') + ptvsd.log.debug('Closing daemon after single session') try: self.close() except DaemonClosedError: @@ -427,7 +440,7 @@ class DaemonBase(object): pass def _handle_atexit(self): - debug('handling atexit') + ptvsd.log.debug('Handling atexit') with self._lock: self._exiting_via_atexit_handler = True session = self.session @@ -455,7 +468,7 @@ class DaemonBase(object): session.wait_until_stopped() def _handle_signal(self, signum, frame): - debug('handling signal') + ptvsd.log.debug('Handling signal') try: self.close() except DaemonClosedError: diff --git a/src/ptvsd/futures.py b/src/ptvsd/futures.py index 0678889b..5f17d03f 100644 --- a/src/ptvsd/futures.py +++ b/src/ptvsd/futures.py @@ -7,6 +7,8 @@ from __future__ import print_function, with_statement, absolute_import import sys import threading import traceback + +import ptvsd.log from ptvsd.reraise import reraise @@ -16,21 +18,34 @@ class Future(object): def __init__(self, loop): self._lock = threading.Lock() self._loop = loop - self._done = False + self._done = None self._observed = False self._done_callbacks = [] self._exc_info = None + self._handling = ptvsd.log.current_handler() + + # It's expensive, so only capture the origin if logging is enabled. + if ptvsd.log.is_enabled(): + self._origin = traceback.extract_stack() + else: + self._origin = None def __del__(self): - if self._lock: - with self._lock: - if self._done and self._exc_info and not self._observed: - print( - 'Unobserved exception in a Future:', - file=sys.__stderr__) - traceback.print_exception( - *self._exc_info, - file=sys.__stderr__) + # Do not run any checks if Python is shutting down. + if not sys or not self._lock: + return + + with self._lock: + assert self._done or self._done is None + exc_info = self._exc_info + if exc_info and not self._observed: + msg = 'Unobserved failed future' + origin = self._origin + if origin: + origin = '\n'.join(traceback.format_list(origin)) + msg += ' originating from:\n\n{origin}\n\n' + ptvsd.log.exception(msg, origin=origin, exc_info=exc_info) + traceback.print_exception(*exc_info, file=sys.__stderr__) def result(self): # TODO: docstring @@ -79,7 +94,7 @@ class Future(object): done = self._done self._done_callbacks.append(callback) if done: - callback(self) + self._loop.call_soon(lambda: callback(self)) def remove_done_callback(self, callback): # TODO: docstring @@ -114,14 +129,16 @@ class EventLoop(object): f(*args) except: if sys is None or traceback is None: - # Errors during shutdown are expected as this is a daemon - # thread, so, just silence it. + # Errors during shutdown are expected as this is a daemon thread, + # so just silence it. We can't even log it at this point. pass else: + # Try to log it, but guard against the possibility of shutdown + # in the middle of it. try: - traceback.print_exc() + ptvsd.log.exception('Exception escaped to event loop') except: - pass # Could give an error during shutdown. + pass def stop(self): self._stop = True @@ -145,8 +162,6 @@ class Result(object): def wrap_async(f): - # TODO: docstring - def g(self, loop, *args, **kwargs): it = f(self, *args, **kwargs) result = Future(loop) @@ -154,7 +169,9 @@ def wrap_async(f): result.set_result(None) return result - def callback(fut): + async_handler = ptvsd.log.current_handler() + + def resume(fut): try: if fut is None: x = next(it) @@ -164,17 +181,22 @@ def wrap_async(f): x = it.throw(*exc_info) else: x = it.send(fut.result()) + except AssertionError: + raise except StopIteration: result.set_result(None) - except BaseException: + except: result.set_exc_info(sys.exc_info()) else: if isinstance(x, Result): result.set_result(x.value) else: + def callback(fut): + with ptvsd.log.handling(async_handler): + resume(fut) x.add_done_callback(callback) - callback(None) + resume(None) return result return g diff --git a/src/ptvsd/ipcjson.py b/src/ptvsd/ipcjson.py index f5846be5..880dcbd2 100644 --- a/src/ptvsd/ipcjson.py +++ b/src/ptvsd/ipcjson.py @@ -21,11 +21,10 @@ import sys import time import traceback -from .socket import TimeoutError, convert_eof +import ptvsd.log +from ptvsd.socket import TimeoutError, convert_eof -_TRACE = None - SKIP_TB_PREFIXES = [ os.path.normcase( os.path.dirname( @@ -50,11 +49,6 @@ else: pass -def _trace(*msg): - if _TRACE: - _TRACE(''.join(_str_or_call(m) for m in msg) + '\n') - - def _str_or_call(m): # TODO: Use callable() here. try: @@ -82,7 +76,6 @@ class SocketIO(object): port = kwargs.pop('port', None) socket = kwargs.pop('socket', None) own_socket = kwargs.pop('own_socket', True) - logfile = kwargs.pop('logfile', None) if socket is None: if port is None: raise ValueError( @@ -96,18 +89,13 @@ class SocketIO(object): self.__port = port self.__socket = socket self.__own_socket = own_socket - self.__logfile = logfile def _send(self, **payload): - # TODO: docstring + ptvsd.log.debug('IDE <-- {0!j}', payload) content = json.dumps(payload).encode('utf-8') headers = ('Content-Length: {}\r\n\r\n'.format(len(content)) ).encode('ascii') - # TODO: We never actually use a logfile... - if self.__logfile is not None: - self.__logfile.write(content) - self.__logfile.write('\n'.encode('utf-8')) - self.__logfile.flush() + try: self.__socket.send(headers) self.__socket.send(content) @@ -203,10 +191,13 @@ class SocketIO(object): content = self._buffered_read_as_utf8(length) try: msg = json.loads(content) + ptvsd.log.debug('IDE --> {0!j}', msg) self._receive_message(msg) except ValueError: + ptvsd.log.exception('IDE --> {0}', content) raise InvalidContentError('Error deserializing message content.') except json.decoder.JSONDecodeError: + ptvsd.log.exception('IDE --> {0}', content) raise InvalidContentError('Error deserializing message content.') def _close(self): @@ -215,34 +206,6 @@ class SocketIO(object): self.__socket.close() -''' -class StandardIO(object): - # TODO: docstring - - def __init__(self, stdin, stdout, *args, **kwargs): - super(StandardIO, self).__init__(*args, **kwargs) - try: - self.__stdin = stdin.buffer - self.__stdout = stdout.buffer - except AttributeError: - self.__stdin = stdin - self.__stdout = stdout - - def _send(self, **payload): - data = json.dumps(payload).encode('utf-8') + NEWLINE_BYTES - self.__stdout.write(data) - self.__stdout.flush() - - def _wait_for_message(self): - msg = json.loads( - self.__stdin.readline().decode('utf-8', 'replace').rstrip()) - self._receive_message(msg) - - def _close(self): - pass -''' - - class IpcChannel(object): # TODO: docstring @@ -303,11 +266,12 @@ class IpcChannel(object): while not self.__exit: try: self.process_one_message() - _trace('self.__exit is ', self.__exit) + except AssertionError: + raise except Exception: + ptvsd.log.exception(category=('D' if self.__exit else 'E')) if not self.__exit: raise - # TODO: log the error? def process_one_message(self): # TODO: docstring @@ -327,22 +291,25 @@ class IpcChannel(object): if self._fail_after is not None: self._fail_after = time.time() + self._timeout - _trace('Received ', msg) + what = msg.copy() + what.pop('arguments', None) + what.pop('body', None) - try: - if msg['type'] == 'request': - self.on_request(msg) - elif msg['type'] == 'response': - self.on_response(msg) - elif msg['type'] == 'event': - self.on_event(msg) - else: - self.on_invalid_request(msg, {}) - except AssertionError: - raise - except Exception: - _trace('Error ', traceback.format_exc) - traceback.print_exc() + with ptvsd.log.handling(what): + try: + if msg['type'] == 'request': + self.on_request(msg) + elif msg['type'] == 'response': + self.on_response(msg) + elif msg['type'] == 'event': + self.on_event(msg) + else: + self.on_invalid_request(msg, {}) + except AssertionError: + ptvsd.log.exception() + raise + except Exception: + ptvsd.log.exception() def on_request(self, request): # TODO: docstring @@ -351,10 +318,9 @@ class IpcChannel(object): cmd = request.get('command', '') args = request.get('arguments', {}) - target = getattr(self, 'on_' + cmd, - self.on_invalid_request) + target = getattr(self, 'on_' + cmd, self.on_invalid_request) + try: - _trace('Calling ', repr(target)) target(request, args) except AssertionError: raise diff --git a/src/ptvsd/log.py b/src/ptvsd/log.py new file mode 100644 index 00000000..1103918d --- /dev/null +++ b/src/ptvsd/log.py @@ -0,0 +1,162 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. See LICENSE in the project root +# for license information. + +from __future__ import print_function, absolute_import, unicode_literals + +import contextlib +import functools +import io +import json +import platform +import os +import string +import sys +import threading +import time +import traceback + +import ptvsd +import ptvsd.options + + +class Formatter(string.Formatter): + def convert_field(self, value, conversion): + if conversion == 'j': + return json.dumps(value, indent=4) + return super(Formatter, self).convert_field(value, conversion) + + +lock = threading.Lock() +file = None +formatter = Formatter() +tls = threading.local() + + +if sys.version_info >= (3, 5): + clock = time.monotonic +else: + clock = time.clock + + +timestamp_zero = clock() + +def timestamp(): + return clock() - timestamp_zero + + +def is_enabled(): + return bool(file) + + +def write(category, fmt, *args, **kwargs): + assert category in 'DIWE' + if not file and category not in 'WE': + return + + t = timestamp() + + try: + message = formatter.format(fmt, *args, **kwargs) + except Exception: + exception('ptvsd.log.write({0!r}): invalid format string', (category, fmt, args, kwargs)) + raise + + prefix = '{}{:09.3f}: '.format(category, t) + indent = '\n' + (' ' * len(prefix)) + message = indent.join(message.split('\n')) + + if current_handler(): + prefix += '(while handling {}){}'.format(current_handler(), indent) + + message = prefix + message + '\n\n' + with lock: + if file: + file.write(message) + file.flush() + if category in 'WE': + sys.__stderr__.write(message) + + +debug = functools.partial(write, 'D') +info = functools.partial(write, 'I') +warn = functools.partial(write, 'W') +error = functools.partial(write, 'E') + + +def stack(title='Stack trace'): + stack = '\n'.join(traceback.format_stack()) + debug('{0}:\n\n{1}', title, stack) + + +def exception(fmt='', *args, **kwargs): + category = kwargs.pop('category', 'E') + exc_info = kwargs.pop('exc_info', None) + + if fmt: + fmt += '\n\n' + fmt += '{exception}' + + exception = traceback.format_exception(*exc_info) if exc_info else traceback.format_exc() + write(category, fmt, *args, exception=exception, **kwargs) + + +def escaped_exceptions(f): + def g(*args, **kwargs): + try: + return f(*args, **kwargs) + except: + try: + name = f.__qualname__ + except AttributeError: + name = f.__name__ + exception('Exception escaped from {0}', name) + raise + return g + + +def to_file(): + global file + + if ptvsd.options.log_dir: + assert not file + filename = ptvsd.options.log_dir + '/ptvsd-{}.log'.format(os.getpid()) + file = io.open(filename, 'w', encoding='utf-8') + + info( + '{0} {1}\n{2} {3} ({4}-bit)\nptvsd {5}', + platform.platform(), + platform.machine(), + platform.python_implementation(), + platform.python_version(), + 64 if sys.maxsize > 2**32 else 32, + ptvsd.__version__, + ) + + +def current_handler(): + try: + return tls.current_handler + except AttributeError: + tls.current_handler = None + return None + + +@contextlib.contextmanager +def handling(what): + assert current_handler() is None, "Can't handle {} - already handling {}".format(what, current_handler()) + tls.current_handler = what + try: + yield + finally: + tls.current_handler = None + + +@contextlib.contextmanager +def suspend_handling(): + what = current_handler() + tls.current_handler = None + try: + yield + finally: + tls.current_handler = what diff --git a/src/ptvsd/messaging.py b/src/ptvsd/messaging.py index d8814187..bd75ac36 100644 --- a/src/ptvsd/messaging.py +++ b/src/ptvsd/messaging.py @@ -9,8 +9,10 @@ import itertools import json import sys import threading -import traceback -from ._util import new_hidden_thread + +import ptvsd.log +from ptvsd._util import new_hidden_thread + class JsonIOStream(object): """Implements a JSON value stream over two byte streams (input and output). @@ -22,7 +24,7 @@ class JsonIOStream(object): MAX_BODY_SIZE = 0xFFFFFF @classmethod - def from_stdio(cls): + def from_stdio(cls, name='???'): if sys.version_info >= (3,): stdin = sys.stdin.buffer stdout = sys.stdout.buffer @@ -33,16 +35,16 @@ class JsonIOStream(object): import os, msvcrt msvcrt.setmode(stdin.fileno(), os.O_BINARY) msvcrt.setmode(stdout.fileno(), os.O_BINARY) - return cls(stdin, stdout) + return cls(stdin, stdout, name) @classmethod - def from_socket(cls, socket): + def from_socket(cls, socket, name='???'): if socket.gettimeout() is not None: raise ValueError('Socket must be in blocking mode') socket_io = socket.makefile('rwb', 0) - return cls(socket_io, socket_io) + return cls(socket_io, socket_io, name) - def __init__(self, reader, writer): + def __init__(self, reader, writer, name='???'): """Creates a new JsonIOStream. reader is a BytesIO-like object from which incoming messages are read; @@ -51,6 +53,7 @@ class JsonIOStream(object): writer is a BytesIO-like object to which outgoing messages are written. """ + self.name = name self._reader = reader self._writer = writer self._is_closing = False @@ -93,6 +96,7 @@ class JsonIOStream(object): if not (0 <= length <= self.MAX_BODY_SIZE): raise ValueError except (KeyError, ValueError): + ptvsd.log.exception('{0} --> {1}', self.name, headers) raise IOError('Content-Length is missing or invalid') try: @@ -104,8 +108,21 @@ class JsonIOStream(object): raise if isinstance(body, bytes): - body = body.decode('utf-8') - return json.loads(body) + try: + body = body.decode('utf-8') + except Exception: + ptvsd.log.exception('{0} --> {1}', self.name, body) + raise + + try: + body = json.loads(body) + except Exception: + ptvsd.log.exception('{0} --> {1}', self.name, body) + raise + + ptvsd.log.debug('{0} --> {1!j}', self.name, body) + return body + def write_json(self, value): """Write a single JSON object to writer. @@ -113,16 +130,27 @@ class JsonIOStream(object): object must be in the format suitable for json.dump(). """ - body = json.dumps(value, sort_keys=True) + try: + body = json.dumps(value, sort_keys=True) + except Exception: + ptvsd.log.exception('{0} <-- {1!r}', self.name, value) + if not isinstance(body, bytes): body = body.encode('utf-8') - header = 'Content-Length: %d\r\n\r\n' % len(body) - if not isinstance(header, bytes): - header = header.encode('ascii') + try: + header = 'Content-Length: %d\r\n\r\n' % len(body) + if not isinstance(header, bytes): + header = header.encode('ascii') + + self._writer.write(header) + self._writer.write(body) + except Exception: + ptvsd.log.exception('{0} <-- {1!j}', self.name, value) + raise + + ptvsd.log.debug('{0} <-- {1!j}', self.name, value) - self._writer.write(header) - self._writer.write(body) class Request(object): @@ -263,14 +291,15 @@ class JsonMessageChannel(object): Debug Adapter Protocol (https://microsoft.github.io/debug-adapter-protocol/overview). """ - def __init__(self, stream, handlers=None, name='vsc_messaging'): + def __init__(self, stream, handlers=None, name=None): self.stream = stream + self.name = name if name is not None else stream.name self._lock = threading.Lock() self._stop = threading.Event() self._seq_iter = itertools.count(1) self._requests = {} self._handlers = handlers - self._worker = new_hidden_thread(name, self._process_incoming_messages) + self._worker = new_hidden_thread('{} message channel worker'.format(self.name), self._process_incoming_messages) self._worker.daemon = True def close(self): @@ -404,17 +433,16 @@ class JsonMessageChannel(object): try: self.on_message(message) except Exception: - print('Error while processing message:\n%r\n\n' % message, file=sys.__stderr__) - traceback.print_exc(file=sys.__stderr__) + ptvsd.log.exception('Error while processing message for {0}:\n\n{1!r}', self.name, message) raise finally: try: self.on_disconnect() except Exception: - print('Error while processing disconnect', file=sys.__stderr__) - traceback.print_exc(file=sys.__stderr__) + ptvsd.log.exception('Error while processing disconnect for {0}', self.name) raise + class MessageHandlers(object): """A simple delegating message handlers object for use with JsonMessageChannel. For every argument provided, the object has an attribute with the corresponding diff --git a/src/ptvsd/multiproc.py b/src/ptvsd/multiproc.py index e2bc048c..05fa3ce2 100644 --- a/src/ptvsd/multiproc.py +++ b/src/ptvsd/multiproc.py @@ -13,17 +13,17 @@ import socket import sys import threading import time -import traceback try: import queue except ImportError: import Queue as queue +import ptvsd.log from ptvsd import options from ptvsd.socket import create_server, create_client from ptvsd.messaging import JsonIOStream, JsonMessageChannel -from ptvsd._util import new_hidden_thread, debug +from ptvsd._util import new_hidden_thread from _pydev_bundle import pydev_monkey from _pydevd_bundle.pydevd_comm import get_global_debugger @@ -138,7 +138,7 @@ def _handle_subprocess(n, stream): with subprocess_lock: subprocesses[self._pid] = channel - debug('ptvsd_subprocess: %r' % arguments) + ptvsd.log.debug('ptvsd_subprocess: {0!r}', arguments) response = {'incomingConnection': False} subprocess_queue.put((arguments, response)) subprocess_queue.join() @@ -149,7 +149,7 @@ def _handle_subprocess(n, stream): with subprocess_lock: subprocesses.pop(self._pid, None) - name = 'SubprocessListener-%d' % n + name = 'subprocess-%d' % n channel = JsonMessageChannel(stream, Handlers(), name) channel.start() @@ -157,10 +157,10 @@ def _handle_subprocess(n, stream): def notify_root(port): assert options.subprocess_of - debug('Subprocess %d notifying root process at port %d' % (os.getpid(), options.subprocess_notify)) + ptvsd.log.debug('Subprocess {0} notifying root process at port {1}', os.getpid(), options.subprocess_notify) conn = create_client() conn.connect(('localhost', options.subprocess_notify)) - stream = JsonIOStream.from_socket(conn) + stream = JsonIOStream.from_socket(conn, 'root-process') channel = JsonMessageChannel(stream) channel.start() @@ -180,8 +180,7 @@ def notify_root(port): try: response = request.wait_for_response() except Exception: - print('Failed to send subprocess notification; exiting', file=sys.__stderr__) - traceback.print_exc() + ptvsd.log.exception('Failed to send subprocess notification; exiting') sys.exit(0) # Keep the channel open until we exit - root process uses open channels to keep @@ -189,6 +188,7 @@ def notify_root(port): atexit.register(lambda: channel.close()) if not response['incomingConnection']: + ptvsd.log.debug('No IDE connection is expected for this subprocess; unpausing.') debugger = get_global_debugger() while debugger is None: time.sleep(0.1) @@ -207,12 +207,12 @@ def patch_args(args): python -R -Q warn .../ptvsd/__main__.py --host localhost --port 0 ... -m app """ + if not options.multiprocess: return args - assert options.multiprocess - args = list(args) + ptvsd.log.debug('Patching subprocess command line: {0!r}', args) # First, let's find the target of the invocation. This is one of: # @@ -278,7 +278,7 @@ def patch_args(args): # Now we need to inject the ptvsd invocation right before the target. The target # itself can remain as is, because ptvsd is compatible with Python in that respect. from ptvsd import __main__ - args[i:i] = [ + ptvsd_args = [ __main__.__file__, '--host', options.host, '--port', '0', @@ -287,7 +287,11 @@ def patch_args(args): '--subprocess-of', str(os.getpid()), '--subprocess-notify', str(options.subprocess_notify or subprocess_listener_port()), ] + if options.log_dir: + ptvsd_args += ['--log-dir', options.log_dir] + args[i:i] = ptvsd_args + ptvsd.log.debug('Patched subprocess command line: {0!r}', args) return args diff --git a/src/ptvsd/options.py b/src/ptvsd/options.py index 10435535..b2c49f18 100644 --- a/src/ptvsd/options.py +++ b/src/ptvsd/options.py @@ -4,10 +4,17 @@ from __future__ import print_function, with_statement, absolute_import +import os + """ptvsd command-line options that need to be globally available. """ +log_dir = os.getenv('PTVSD_LOG_DIR') +"""If not None, debugger logs its activity to a file named ptvsd-.log in +the specified directory, where is the return value of os.getpid(). +""" + target_kind = None """One of: None, 'file', 'module', 'code', or 'pid'. """ diff --git a/src/ptvsd/pydevd_hooks.py b/src/ptvsd/pydevd_hooks.py index 6c8fb94b..a12377d6 100644 --- a/src/ptvsd/pydevd_hooks.py +++ b/src/ptvsd/pydevd_hooks.py @@ -10,13 +10,15 @@ from _pydev_bundle import pydev_monkey from _pydevd_bundle import pydevd_comm import ptvsd +import ptvsd.log from ptvsd import multiproc from ptvsd.socket import Address from ptvsd.daemon import Daemon, DaemonStoppedError, DaemonClosedError -from ptvsd._util import debug, new_hidden_thread +from ptvsd._util import new_hidden_thread from ptvsd import options +@ptvsd.log.escaped_exceptions def start_server(daemon, host, port, **kwargs): """Return a socket to a (new) local pydevd-handling daemon. @@ -29,28 +31,28 @@ def start_server(daemon, host, port, **kwargs): def handle_next(): try: + ptvsd.log.debug('Waiting for session...') session = next_session(**kwargs) - debug('done waiting') + ptvsd.log.debug('Got session') return session except (DaemonClosedError, DaemonStoppedError): # Typically won't happen. - debug('stopped') + ptvsd.log.exception('Daemon stopped while waiting for session', category='D') raise - except Exception as exc: - # TODO: log this? - debug('failed:', exc, tb=True) + except Exception: + ptvsd.log.exception() return None def serve_forever(): - debug('waiting on initial connection') + ptvsd.log.debug('Waiting for initial connection...') handle_next() while True: - debug('waiting on next connection') + ptvsd.log.debug('Waiting for next connection...') try: handle_next() except (DaemonClosedError, DaemonStoppedError): break - debug('done') + ptvsd.log.debug('Done serving') t = new_hidden_thread( target=serve_forever, @@ -60,6 +62,7 @@ def start_server(daemon, host, port, **kwargs): return sock +@ptvsd.log.escaped_exceptions def start_client(daemon, host, port, **kwargs): """Return a socket to an existing "remote" pydevd-handling daemon. @@ -74,6 +77,7 @@ def start_client(daemon, host, port, **kwargs): # See pydevd/_vendored/pydevd/_pydev_bundle/pydev_monkey.py +@ptvsd.log.escaped_exceptions def get_python_c_args(host, port, indC, args, setup): runner = ''' import sys @@ -117,6 +121,9 @@ def install(pydevd_module, address, this is somewhat fragile (since the monkeypatching sites may change). """ + + ptvsd.log.debug('Installing pydevd hooks.') + addr = Address.from_raw(address) daemon = Daemon(**kwargs) @@ -134,6 +141,7 @@ def install(pydevd_module, address, if not options.multiprocess and not options.no_debug: # This means '--multiprocess' flag was not passed via command line args. Patch the # new process functions here to handle multiprocess being enabled via debug options. + ptvsd.log.debug('Monkey-patching multiprocess functions.') pydev_monkey.patch_new_process_functions() # Ensure that pydevd is using our functions. diff --git a/src/ptvsd/session.py b/src/ptvsd/session.py index eeaa940c..4e1e3591 100644 --- a/src/ptvsd/session.py +++ b/src/ptvsd/session.py @@ -2,9 +2,10 @@ # Licensed under the MIT License. See LICENSE in the project root # for license information. +import ptvsd.log from .socket import is_socket, close_socket from .wrapper import VSCodeMessageProcessor -from ._util import TimeoutError, ClosedError, Closeable, Startable, debug +from ._util import TimeoutError, ClosedError, Closeable, Startable class DebugSession(Startable, Closeable): @@ -57,7 +58,7 @@ class DebugSession(Startable, Closeable): def handle_closing(before): if before: return - debug('closing session socket') + ptvsd.log.debug('Closing session socket') proc = self._msgprocessor if self._pre_socket_close is not None: self._pre_socket_close() @@ -65,7 +66,7 @@ class DebugSession(Startable, Closeable): try: proc.wait_while_connected(10) # seconds except TimeoutError: - debug('timed out waiting for disconnect') + ptvsd.log.exception('timed out waiting for disconnect', category='D') close_socket(self._sock) self.add_close_handler(handle_closing) @@ -123,7 +124,7 @@ class DebugSession(Startable, Closeable): if proc is None: return - debug('proc stopping') + ptvsd.log.debug('Message processor is stopping.') # TODO: We should not need to wait if not exiting. # The editor will send a "disconnect" request at this point. proc._wait_for_disconnect() @@ -131,8 +132,7 @@ class DebugSession(Startable, Closeable): self._msgprocessor = None def _close(self): - debug('session closing') - pass + ptvsd.log.debug('Session is closing.') def _msgprocessor_running(self): if self._msgprocessor is None: @@ -143,12 +143,12 @@ class DebugSession(Startable, Closeable): # internal methods for VSCodeMessageProcessor def _handle_vsc_disconnect(self, pre_socket_close=None): - debug('disconnecting') + ptvsd.log.debug('Disconnecting.') self._pre_socket_close = pre_socket_close # TODO: Fail if already set? self._notify_disconnecting(self) def _handle_vsc_close(self): - debug('processor closing') + ptvsd.log.debug('Message processor is closing.') try: self.close() except ClosedError: @@ -191,5 +191,5 @@ class PyDevdDebugSession(DebugSession): # internal methods for VSCodeMessageProcessor def _handle_vsc_debugger_ready(self): - debug('ready to debug') + ptvsd.log.debug('Ready to debug') self._notify_debugger_ready(self) diff --git a/src/ptvsd/wrapper.py b/src/ptvsd/wrapper.py index 7b28a5e1..19a88325 100644 --- a/src/ptvsd/wrapper.py +++ b/src/ptvsd/wrapper.py @@ -38,11 +38,11 @@ import _pydevd_bundle.pydevd_extension_api as pydevd_extapi # noqa import _pydevd_bundle.pydevd_extension_utils as pydevd_extutil # noqa import _pydevd_bundle.pydevd_frame as pydevd_frame # noqa from pydevd_file_utils import get_abs_path_real_path_and_base_from_file # noqa -# from _pydevd_bundle.pydevd_comm import pydevd_log from _pydevd_bundle.pydevd_dont_trace_files import PYDEV_FILE # noqa from _pydevd_bundle import pydevd_additional_thread_info import ptvsd +import ptvsd.log from ptvsd import _util from ptvsd import multiproc from ptvsd import options @@ -54,7 +54,6 @@ from ptvsd.pathutils import PathUnNormcase # noqa from ptvsd.version import __version__ # noqa from ptvsd.socket import TimeoutError # noqa -LOG_FILENAME = 'pydevd.log' WAIT_FOR_THREAD_FINISH_TIMEOUT = 1 # seconds @@ -71,13 +70,8 @@ EXCEPTION_REASONS = { pydevd_comm.CMD_ADD_EXCEPTION_BREAK } -debug = _util.debug debugger_attached = threading.Event() -# def ipcjson_trace(s): -# print(s) -# ipcjson._TRACE = ipcjson_trace - def NOOP(*args, **kwargs): pass @@ -279,7 +273,6 @@ class PydevdSocket(object): """ def __init__(self, handle_msg, handle_close, getpeername, getsockname): - # self.log = open(LOG_FILENAME, 'w') self._handle_msg = handle_msg self._handle_close = handle_close self._getpeername = getpeername @@ -345,8 +338,6 @@ class PydevdSocket(object): if pipe_r is None: return b'' data = os.read(pipe_r, count) - # self.log.write('>>>[' + data.decode('utf8') + ']\n\n') - # self.log.flush() return data def recv_into(self, buf): @@ -359,13 +350,10 @@ class PydevdSocket(object): # are encoded first and then quoted as individual bytes. In Python 3, # however, we just get a properly UTF-8-encoded string. if sys.version_info < (3,): - @staticmethod def _decode_and_unquote(data): return unquote(data).decode('utf8') - else: - @staticmethod def _decode_and_unquote(data): return unquote(data.decode('utf8')) @@ -382,38 +370,67 @@ class PydevdSocket(object): """ result = len(data) - if data.startswith(b'{'): - # A json message was received. - data = data.decode('utf-8') - # self.log.write('<<<[' + data + ']\n\n') - # self.log.flush() - as_dict = json.loads(data) - cmd_id = as_dict['pydevd_cmd_id'] - if 'request_seq' in as_dict: - seq = as_dict['request_seq'] + # Defer logging until we have as much information about the message + # as possible - after decoding it, parsing it, determining whether + # it's a response etc. This way it can be logged in the most readable + # representation and with the most context. + # + # However, if something fails at any of those stages, we want to log + # as much as we have by then. Thus, the format string for for trace() + # is also constructed dynamically, reflecting the available info. + + trace_prefix = 'PYD --> ' + trace_fmt = '{data}' + + try: + if data.startswith(b'{'): # JSON + data = data.decode('utf-8') + data = json.loads(data) + trace_fmt = '{data!j}' + cmd_id = data['pydevd_cmd_id'] + if 'request_seq' in data: + seq = data['request_seq'] + else: + seq = data['seq'] + args = data else: - seq = as_dict['seq'] - args = as_dict + assert data.endswith(b'\n') + data = self._decode_and_unquote(data[:-1]) + cmd_id, seq, args = data.split('\t', 2) + if ptvsd.log.is_enabled(): + trace_fmt = '{cmd_name} {seq}\n{args}' + except: + ptvsd.log.exception(trace_prefix + trace_fmt, data=data) + raise - else: - data = self._decode_and_unquote(data) - # self.log.write('<<<[' + data + ']\n\n') - # self.log.flush() - cmd_id, seq, args = data.split('\t', 2) - - cmd_id = int(cmd_id) seq = int(seq) - _util.log_pydevd_msg(cmd_id, seq, args, inbound=True) + cmd_id = int(cmd_id) + try: + cmd_name = pydevd_comm.ID_TO_MEANING[str(cmd_id)] + except KeyError: + cmd_name = cmd_id + with self.lock: - loop, fut = self.requests.pop(seq, (None, None)) + loop, fut, requesting_handler = self.requests.pop(seq, (None, None, None)) + + if requesting_handler is not None: + trace_prefix = '(requested while handling {requesting_handler})\n' + trace_prefix + ptvsd.log.debug( + trace_prefix + trace_fmt, + data=data, + cmd_id=cmd_id, + cmd_name=cmd_name, + seq=seq, + args=args, + requesting_handler=requesting_handler, + ) + if fut is None: - # self.log.write('handle message: %s' % (args,)) - # self.log.flush() - self._handle_msg(cmd_id, seq, args) + with ptvsd.log.handling((cmd_name, seq)): + self._handle_msg(cmd_id, seq, args) else: - # self.log.write('set result message: %s' % (args,)) - # self.log.flush() loop.call_soon_threadsafe(fut.set_result, (cmd_id, seq, args)) + return result sendall = send @@ -427,6 +444,14 @@ class PydevdSocket(object): with self.lock: seq = self.seq self.seq += 1 + + if ptvsd.log.is_enabled(): + try: + cmd_name = pydevd_comm.ID_TO_MEANING[str(cmd_id)] + except KeyError: + cmd_name = cmd_id + ptvsd.log.debug('PYD <-- {0} {1} {2}', cmd_name, seq, args) + s = '{}\t{}\t{}\n'.format(cmd_id, seq, args) return seq, s @@ -436,6 +461,9 @@ class PydevdSocket(object): seq = self.seq self.seq += 1 args['seq'] = seq + + ptvsd.log.debug('PYD <-- {0!j}', args) + s = json.dumps(args) return seq, s @@ -443,7 +471,6 @@ class PydevdSocket(object): if self.pipe_w is None: raise EOFError seq, s = self.make_packet(cmd_id, args) - _util.log_pydevd_msg(cmd_id, seq, args, inbound=False) with self.lock: os.write(self.pipe_w, s.encode('utf8')) @@ -460,11 +487,10 @@ class PydevdSocket(object): seq, s = self.make_json_packet(cmd_id, args) else: seq, s = self.make_packet(cmd_id, args) - _util.log_pydevd_msg(cmd_id, seq, args, inbound=False) fut = loop.create_future() with self.lock: - self.requests[seq] = loop, fut + self.requests[seq] = loop, fut, ptvsd.log.current_handler() as_bytes = s if not isinstance(as_bytes, bytes): as_bytes = as_bytes.encode('utf-8') @@ -795,14 +821,11 @@ def _parse_debug_options(opts): class VSCodeMessageProcessorBase(ipcjson.SocketIO, ipcjson.IpcChannel): """The base class for VSC message processors.""" - def __init__(self, socket, notify_closing, - timeout=None, logfile=None, own_socket=False - ): + def __init__(self, socket, notify_closing, timeout=None, own_socket=False): super(VSCodeMessageProcessorBase, self).__init__( socket=socket, own_socket=False, timeout=timeout, - logfile=logfile, ) self.socket = socket self._own_socket = own_socket @@ -861,14 +884,14 @@ class VSCodeMessageProcessorBase(ipcjson.SocketIO, ipcjson.IpcChannel): try: self.process_messages() except (EOFError, TimeoutError): - debug('client socket closed') + ptvsd.log.exception('Client socket closed', category='I') with self._connlock: _util.lock_release(self._listening) _util.lock_release(self._connected) self.close() except socket.error as exc: if exc.errno == errno.ECONNRESET: - debug('client socket forcibly closed') + ptvsd.log.exception('Client socket forcibly closed', category='I') with self._connlock: _util.lock_release(self._listening) _util.lock_release(self._connected) @@ -883,14 +906,12 @@ class VSCodeMessageProcessorBase(ipcjson.SocketIO, ipcjson.IpcChannel): self.server_thread.start() # special initialization - debug('sending output') self.send_event( 'output', category='telemetry', output='ptvsd', data={'version': __version__}, ) - debug('output sent') self.readylock.release() def close(self): @@ -898,7 +919,7 @@ class VSCodeMessageProcessorBase(ipcjson.SocketIO, ipcjson.IpcChannel): if self.closed: return self._closing = True - debug('raw closing') + ptvsd.log.debug('Raw closing') self._notify_closing() # Close the editor-side socket. @@ -941,8 +962,7 @@ class VSCodeMessageProcessorBase(ipcjson.SocketIO, ipcjson.IpcChannel): self.socket.close() self._set_disconnected() except Exception: - # TODO: log the error - pass + ptvsd.log.exception('Error on socket shutdown') # methods for subclasses to override @@ -990,16 +1010,14 @@ class VSCLifecycleMsgProcessor(VSCodeMessageProcessorBase): EXITWAIT = 1 - def __init__(self, socket, - notify_disconnecting, notify_closing, - notify_launch=None, notify_ready=None, - timeout=None, logfile=None, debugging=True, - ): + def __init__( + self, socket, notify_disconnecting, notify_closing, + notify_launch=None, notify_ready=None, timeout=None, debugging=True, + ): super(VSCLifecycleMsgProcessor, self).__init__( socket=socket, notify_closing=notify_closing, timeout=timeout, - logfile=logfile, ) self._notify_launch = notify_launch or NOOP self._notify_ready = notify_ready or NOOP @@ -1187,17 +1205,17 @@ class VSCodeMessageProcessor(VSCLifecycleMsgProcessor): protocol. """ - def __init__(self, socket, pydevd_notify, pydevd_request, - notify_debugger_ready, - notify_disconnecting, notify_closing, - timeout=None, logfile=None, - ): + def __init__( + self, socket, pydevd_notify, pydevd_request, + notify_debugger_ready, + notify_disconnecting, notify_closing, + timeout=None, + ): super(VSCodeMessageProcessor, self).__init__( socket=socket, notify_disconnecting=notify_disconnecting, notify_closing=notify_closing, timeout=timeout, - logfile=logfile, ) self._pydevd_notify = pydevd_notify self._pydevd_request = pydevd_request @@ -1278,15 +1296,7 @@ class VSCodeMessageProcessor(VSCLifecycleMsgProcessor): m = futures.wrap_async(m) def f(self, *args, **kwargs): - fut = m(self, self.loop, *args, **kwargs) - - def done(fut): - try: - fut.result() - except BaseException: - traceback.print_exc(file=sys.__stderr__) - - fut.add_done_callback(done) + return m(self, self.loop, *args, **kwargs) return f @@ -1298,19 +1308,9 @@ class VSCodeMessageProcessor(VSCLifecycleMsgProcessor): # PyDevd "socket" entry points (and related helpers) def pydevd_notify(self, cmd_id, args): - # self.log.write('pydevd_notify: %s %s\n' % (cmd_id, args)) - # self.log.flush() - # TODO: docstring - try: - return self._pydevd_notify(cmd_id, args) - except BaseException: - traceback.print_exc(file=sys.__stderr__) - raise + return self._pydevd_notify(cmd_id, args) def pydevd_request(self, cmd_id, args, is_json=False): - # self.log.write('pydevd_request: %s %s\n' % (cmd_id, args)) - # self.log.flush() - # TODO: docstring return self._pydevd_request(self.loop, cmd_id, args, is_json=is_json) # Instances of this class provide decorators to mark methods as @@ -1330,10 +1330,6 @@ class VSCodeMessageProcessor(VSCLifecycleMsgProcessor): pydevd_events = EventHandlers() def on_pydevd_event(self, cmd_id, seq, args): - # with open(LOG_FILENAME, 'a+') as stream: - # stream.write('on_pydevd_event: %s %s %s\n' % (cmd_id, seq, args)) - - # TODO: docstring if not self._detached: try: f = self.pydevd_events[cmd_id] @@ -1479,7 +1475,7 @@ class VSCodeMessageProcessor(VSCLifecycleMsgProcessor): self._initialize_path_maps(args) def _handle_detach(self): - debug('detaching') + ptvsd.log.info('Detaching ...') # TODO: Skip if already detached? self._detached = True diff --git a/tests/helpers/debuggee/backchannel.py b/tests/helpers/debuggee/backchannel.py index 892b7cb9..ca975c80 100644 --- a/tests/helpers/debuggee/backchannel.py +++ b/tests/helpers/debuggee/backchannel.py @@ -11,13 +11,16 @@ fixture and its backchannel method.""" import os import socket +import ptvsd.log from ptvsd.messaging import JsonIOStream + port = int(os.getenv('PTVSD_BACKCHANNEL_PORT')) -# print('Connecting to bchan#%d' % port) +ptvsd.log.debug('Connecting to bchan#{0}', port) + sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) sock.connect(('localhost', port)) -stream = JsonIOStream.from_socket(sock) +stream = JsonIOStream.from_socket(sock, name='test') def read_json(): diff --git a/tests/helpers/messaging.py b/tests/helpers/messaging.py index d68fb033..6aaff117 100644 --- a/tests/helpers/messaging.py +++ b/tests/helpers/messaging.py @@ -44,6 +44,7 @@ class LoggingJsonStream(object): def __init__(self, stream, id=None): self.stream = stream self.id = id or next(self.id_iter) + self.name = self.id def close(self): self.stream.close() diff --git a/tests/helpers/session.py b/tests/helpers/session.py index 7ef072cd..2d89742b 100644 --- a/tests/helpers/session.py +++ b/tests/helpers/session.py @@ -320,7 +320,7 @@ class DebugSession(object): assert telemetry == Event('output', { 'category': 'telemetry', 'output': 'ptvsd', - 'data': {'version': ptvsd.__version__} + 'data': {'version': ptvsd.__version__}, }) if self.perform_handshake: diff --git a/tox.ini b/tox.ini index 80c7edc5..e9a05030 100644 --- a/tox.ini +++ b/tox.ini @@ -4,3 +4,4 @@ envlist = py{27,34,35,36,37} [testenv] deps = -rtest_requirements.txt commands = pytest {posargs:-vv} +passenv = PTVSD_LOG_DIR