Fix #890: Provide option to enable logging

Implement logging framework, and use that in place of existing ad-hoc logging.
This commit is contained in:
Pavel Minaev 2019-02-27 14:26:32 -08:00 committed by Pavel Minaev
parent 09988bf012
commit a26f5d0032
20 changed files with 531 additions and 312 deletions

View file

@ -2,4 +2,4 @@
testpaths=tests
timeout=30
timeout_method=thread
addopts=-n8
addopts=-n6

View file

@ -60,6 +60,7 @@ HELP = ('''ptvsd %s
See https://aka.ms/ptvsd for documentation.
Usage: ptvsd --host <address> [--port <port>] [--wait] [--multiprocess]
[--log-dir <path>]
''' + TARGET + '''
''') % (ptvsd.version.__version__,)
@ -128,6 +129,7 @@ switches = [
('--port', '<port>', set_arg('port', port), False),
('--wait', None, set_true('wait'), False),
('--multiprocess', None, set_true('multiprocess'), False),
('--log-dir', '<path>', 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, '<string>', '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

View file

@ -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,

View file

@ -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

View file

@ -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

View file

@ -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.

View file

@ -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:

View file

@ -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

View file

@ -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

162
src/ptvsd/log.py Normal file
View file

@ -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

View file

@ -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

View file

@ -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

View file

@ -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-<pid>.log in
the specified directory, where <pid> is the return value of os.getpid().
"""
target_kind = None
"""One of: None, 'file', 'module', 'code', or 'pid'.
"""

View file

@ -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.

View file

@ -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)

View file

@ -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

View file

@ -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():

View file

@ -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()

View file

@ -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:

View file

@ -4,3 +4,4 @@ envlist = py{27,34,35,36,37}
[testenv]
deps = -rtest_requirements.txt
commands = pytest {posargs:-vv}
passenv = PTVSD_LOG_DIR