From a8ffe4a5a93d323087fcef37253734c1021cbd70 Mon Sep 17 00:00:00 2001 From: Pavel Minaev Date: Mon, 23 Dec 2019 12:01:44 -0800 Subject: [PATCH] Fix #2004: Adapter process is not fully detached from parent server (#2007) Close stdin, stdout, and stderr in the adapter. Double-fork() and setsid() on Unix to daemonize properly. Use CREATE_NEW_PROCESS_GROUP and CREATE_NO_WINDOW on Win32 to daemonize properly. Propagate socket errors from adapter to server for enable_attach(). --- .vscode/launch.json | 7 ++ src/ptvsd/adapter/__main__.py | 108 ++++++++++++++++++------- src/ptvsd/common/sockets.py | 17 ++-- src/ptvsd/server/api.py | 145 +++++++++++++++++++++++----------- 4 files changed, 196 insertions(+), 81 deletions(-) diff --git a/.vscode/launch.json b/.vscode/launch.json index 79ea906f..76d310aa 100644 --- a/.vscode/launch.json +++ b/.vscode/launch.json @@ -34,5 +34,12 @@ "port": 5678, "logToFile": true, }, + { + "name": "Debug Tests", + "type": "python", + "request": "test", + "console": "integratedTerminal", + "justMyCode": true + } ] } \ No newline at end of file diff --git a/src/ptvsd/adapter/__main__.py b/src/ptvsd/adapter/__main__.py index 2c66837b..4b420d78 100644 --- a/src/ptvsd/adapter/__main__.py +++ b/src/ptvsd/adapter/__main__.py @@ -21,9 +21,22 @@ __file__ = os.path.abspath(__file__) def main(args): from ptvsd import adapter - from ptvsd.common import compat, log + from ptvsd.common import compat, log, sockets from ptvsd.adapter import ide, servers, sessions + if args.for_server is not None: + if os.name == "posix": + # On POSIX, we need to leave the process group and its session, and then + # daemonize properly by double-forking (first fork already happened when + # this process was spawned). + os.setsid() + if os.fork() != 0: + sys.exit(0) + + for stdio in sys.stdin, sys.stdout, sys.stderr: + if stdio is not None: + stdio.close() + if args.log_stderr: log.stderr.levels |= set(log.LEVELS) if args.log_dir is not None: @@ -32,35 +45,59 @@ def main(args): log.to_file(prefix="ptvsd.adapter") log.describe_environment("ptvsd.adapter startup environment:") - if args.for_server and args.port is None: - log.error("--for-server requires --port") - sys.exit(64) - servers.access_token = args.server_access_token - if not args.for_server: - adapter.access_token = compat.force_str( - codecs.encode(os.urandom(32), "hex") + if args.for_server is None: + adapter.access_token = compat.force_str(codecs.encode(os.urandom(32), "hex")) + + try: + server_host, server_port = servers.listen() + except Exception as exc: + if args.for_server is None: + raise + endpoints = {"error": "Can't listen for server connections: " + str(exc)} + else: + endpoints = {"server": {"host": server_host, "port": server_port}} + try: + ide_host, ide_port = ide.listen(port=args.port) + except Exception as exc: + if args.for_server is None: + raise + endpoints = { + "error": "Can't listen for IDE connections: " + str(exc) + } + else: + endpoints["ide"] = {"host": ide_host, "port": ide_port} + + if args.for_server is not None: + log.info( + "Sending endpoints info to debug server at localhost:{0}:\n{1!j}", + args.for_server, + endpoints, ) - server_host, server_port = servers.listen() - ide_host, ide_port = ide.listen(port=args.port) - endpoints_info = { - "ide": {"host": ide_host, "port": ide_port}, - "server": {"host": server_host, "port": server_port}, - } + try: + sock = sockets.create_client() + try: + sock.settimeout(None) + sock.connect(("127.0.0.1", args.for_server)) + sock_io = sock.makefile("wb", 0) + try: + sock_io.write(json.dumps(endpoints).encode("utf-8")) + finally: + sock_io.close() + finally: + sockets.close_socket(sock) + except Exception: + raise log.exception("Error sending endpoints info to debug server:") - if args.for_server: - log.info("Writing endpoints info to stdout:\n{0!r}", endpoints_info) - print(json.dumps(endpoints_info)) - sys.stdout.flush() - - if args.port is None: - ide.IDE("stdio") + if "error" in endpoints: + log.error("Couldn't set up endpoints; exiting.") + sys.exit(1) listener_file = os.getenv("PTVSD_ADAPTER_ENDPOINTS") if listener_file is not None: log.info( - "Writing endpoints info to {0!r}:\n{1!r}", listener_file, endpoints_info + "Writing endpoints info to {0!r}:\n{1!j}", listener_file, endpoints ) def delete_listener_file(): @@ -70,9 +107,15 @@ def main(args): except Exception: log.exception("Failed to delete {0!r}", listener_file, level="warning") - with open(listener_file, "w") as f: - atexit.register(delete_listener_file) - print(json.dumps(endpoints_info), file=f) + try: + with open(listener_file, "w") as f: + atexit.register(delete_listener_file) + print(json.dumps(endpoints), file=f) + except Exception: + raise log.exception("Error writing endpoints info to file:") + + if args.port is None: + ide.IDE("stdio") # These must be registered after the one above, to ensure that the listener sockets # are closed before the endpoint info file is deleted - this way, another process @@ -90,6 +133,10 @@ def main(args): def _parse_argv(argv): parser = argparse.ArgumentParser() + parser.add_argument( + "--for-server", type=int, metavar="PORT", help=argparse.SUPPRESS + ) + parser.add_argument( "--port", type=int, @@ -110,8 +157,6 @@ def _parse_argv(argv): "--server-access-token", type=str, help="access token expected by the server" ) - parser.add_argument("--for-server", action="store_true", help=argparse.SUPPRESS) - parser.add_argument( "--log-dir", type=str, @@ -124,8 +169,13 @@ def _parse_argv(argv): ) args = parser.parse_args(argv[1:]) - if args.port is None and args.log_stderr: - parser.error("--log-stderr can only be used with --port") + + if args.port is None: + if args.log_stderr: + parser.error("--log-stderr requires --port") + if args.for_server is not None: + parser.error("--for-server requires --port") + return args diff --git a/src/ptvsd/common/sockets.py b/src/ptvsd/common/sockets.py index da1836f5..09f0f25f 100644 --- a/src/ptvsd/common/sockets.py +++ b/src/ptvsd/common/sockets.py @@ -73,14 +73,17 @@ class ClientConnection(object): name = cls.__name__ assert cls.listener is None - cls.listener = create_server(host, port, timeout) + try: + cls.listener = create_server(host, port, timeout) + except Exception: + raise log.exception( + "Error listening for incoming {0} connections on {1}:{2}:", + name, + host, + port, + ) host, port = cls.listener.getsockname() - log.info( - "Waiting for incoming {0} connections on {1}:{2}...", - name, - host, - port, - ) + log.info("Listening for incoming {0} connections on {1}:{2}...", name, host, port) def accept_worker(): while True: diff --git a/src/ptvsd/server/api.py b/src/ptvsd/server/api.py index 1e5d7bfa..8bed44ca 100644 --- a/src/ptvsd/server/api.py +++ b/src/ptvsd/server/api.py @@ -9,25 +9,28 @@ import contextlib import json import os import pydevd +import socket import sys import threading import ptvsd -from ptvsd.common import compat, log +from ptvsd import adapter +from ptvsd.common import compat, log, sockets from ptvsd.server import options from _pydevd_bundle.pydevd_constants import get_global_debugger from pydevd_file_utils import get_abs_path_real_path_and_base_from_file -_QUEUE_TIMEOUT = 10 -_ADAPTER_PATH = os.path.join(os.path.dirname(ptvsd.__file__), "adapter") +def _settrace(*args, **kwargs): + log.debug("pydevd.settrace(*{0!r}, **{1!r})", args, kwargs) + return pydevd.settrace(*args, **kwargs) def wait_for_attach(): - log.info("wait_for_attach()") + log.debug("wait_for_attach()") dbg = get_global_debugger() if dbg is None: - raise RuntimeError("wait_for_attach() called before enable_attach().") + raise RuntimeError("wait_for_attach() called before enable_attach()") cancel_event = threading.Event() ptvsd.wait_for_attach.cancel = wait_for_attach.cancel = cancel_event.set @@ -41,7 +44,7 @@ def _starts_debugging(func): log.to_file(prefix="ptvsd.server") log.describe_environment("ptvsd.server debug start environment:") - log.info("{0}{1!r}", func.__name__, (address, log_dir, multiprocess)) + log.debug("{0}{1!r}", func.__name__, (address, log_dir, multiprocess)) if is_attached(): log.info("{0}() ignored - already attached.", func.__name__) @@ -69,24 +72,38 @@ def _starts_debugging(func): try: return func(start_patterns, end_patterns) except Exception: - raise log.exception("{0}() failed:", func.__name__) + raise log.exception("{0}() failed:", func.__name__, level="info") return debug @_starts_debugging def enable_attach(dont_trace_start_patterns, dont_trace_end_patterns): - if hasattr(enable_attach, "called"): - raise RuntimeError("enable_attach() can only be called once per process.") - - server_access_token = compat.force_str(codecs.encode(os.urandom(32), "hex")) + # Errors below are logged with level="info", because the caller might be catching + # and handling exceptions, and we don't want to spam their stderr unnecessarily. import subprocess + if hasattr(enable_attach, "adapter"): + raise AssertionError("enable_attach() can only be called once per process") + + server_access_token = compat.force_str(codecs.encode(os.urandom(32), "hex")) + + try: + endpoints_listener = sockets.create_server("127.0.0.1", 0, timeout=5) + except Exception as exc: + log.exception("Can't listen for adapter endpoints:") + raise RuntimeError("can't listen for adapter endpoints: " + str(exc)) + endpoints_host, endpoints_port = endpoints_listener.getsockname() + log.info( + "Waiting for adapter endpoints on {0}:{1}...", endpoints_host, endpoints_port + ) + adapter_args = [ sys.executable, - _ADAPTER_PATH, + os.path.dirname(adapter.__file__), "--for-server", + str(endpoints_port), "--host", options.host, "--port", @@ -94,29 +111,77 @@ def enable_attach(dont_trace_start_patterns, dont_trace_end_patterns): "--server-access-token", server_access_token, ] - if log.log_dir is not None: adapter_args += ["--log-dir", log.log_dir] + log.info("enable_attach() spawning adapter: {0!j}", adapter_args) - log.info("enable_attach() spawning adapter: {0!r}", adapter_args) + # On Windows, detach the adapter from our console, if any, so that it doesn't + # receive Ctrl+C from it, and doesn't keep it open once we exit. + creationflags = 0 + if sys.platform == "win32": + creationflags |= 0x08000000 # CREATE_NO_WINDOW + creationflags |= 0x00000200 # CREATE_NEW_PROCESS_GROUP - # Adapter will outlive this process, so we shouldn't wait for it. However, we do - # need to ensure that the Popen instance for it doesn't get garbage-collected, to - # avoid triggering https://bugs.python.org/issue37380. - enable_attach.process = process = subprocess.Popen( - adapter_args, bufsize=0, stdout=subprocess.PIPE + # Adapter will outlive this process, so we shouldn't wait for it. However, we + # need to ensure that the Popen instance for it doesn't get garbage-collected + # by holding a reference to it in a non-local variable, to avoid triggering + # https://bugs.python.org/issue37380. + try: + enable_attach.adapter = subprocess.Popen( + adapter_args, close_fds=True, creationflags=creationflags + ) + if os.name == "posix": + # It's going to fork again to daemonize, so we need to wait on it to + # clean it up properly. + enable_attach.adapter.wait() + else: + # Suppress misleading warning about child process still being alive when + # this process exits (https://bugs.python.org/issue38890). + enable_attach.adapter.returncode = 0 + pydevd.add_dont_terminate_child_pid(enable_attach.adapter.pid) + except Exception as exc: + log.exception("Error spawning debug adapter:", level="info") + raise RuntimeError("error spawning debug adapter: " + str(exc)) + + try: + sock, _ = endpoints_listener.accept() + try: + sock.settimeout(None) + sock_io = sock.makefile("rb", 0) + try: + endpoints = json.loads(sock_io.read().decode("utf-8")) + finally: + sock_io.close() + finally: + sockets.close_socket(sock) + except socket.timeout: + log.exception("Timed out waiting for adapter to connect:", level="info") + raise RuntimeError("timed out waiting for adapter to connect") + except Exception as exc: + log.exception("Error retrieving adapter endpoints:", level="info") + raise RuntimeError("error retrieving adapter endpoints: " + str(exc)) + + log.info("Endpoints received from adapter: {0!j}", endpoints) + + if "error" in endpoints: + raise RuntimeError(str(endpoints["error"])) + + try: + host = str(endpoints["server"]["host"]) + port = int(endpoints["server"]["port"]) + options.port = int(endpoints["ide"]["port"]) + except Exception as exc: + log.exception( + "Error parsing adapter endpoints:\n{0!j}\n", endpoints, level="info" + ) + raise RuntimeError("error parsing adapter endpoints: " + str(exc)) + log.info( + "Adapter is accepting incoming IDE connections on {0}:{1}", + options.host, + options.port, ) - line = process.stdout.readline() - if isinstance(line, bytes): - line = line.decode("utf-8") - connection_details = json.JSONDecoder().decode(line) - log.info("Connection details received from adapter: {0!r}", connection_details) - - host = "127.0.0.1" # This should always be loopback address. - port = connection_details["server"]["port"] - - pydevd.settrace( + _settrace( host=host, port=port, suspend=False, @@ -128,23 +193,13 @@ def enable_attach(dont_trace_start_patterns, dont_trace_end_patterns): access_token=server_access_token, client_access_token=options.client_access_token, ) - - log.info("pydevd debug client connected to: {0}:{1}", host, port) - - # Ensure that we ignore the adapter process when terminating the debugger. - pydevd.add_dont_terminate_child_pid(process.pid) - options.port = connection_details["ide"]["port"] - - enable_attach.called = True - log.info( - "ptvsd debug server running at: {0}:{1}", options.host, options.port - ) + log.info("pydevd is connected to adapter at {0}:{1}", host, port) return options.host, options.port @_starts_debugging def attach(dont_trace_start_patterns, dont_trace_end_patterns): - pydevd.settrace( + _settrace( host=options.host, port=options.port, suspend=False, @@ -160,7 +215,7 @@ def is_attached(): def break_into_debugger(): - log.info("break_into_debugger()") + log.debug("break_into_debugger()") if not is_attached(): log.info("break_into_debugger() ignored - debugger not attached") @@ -175,7 +230,7 @@ def break_into_debugger(): ): stop_at_frame = stop_at_frame.f_back - pydevd.settrace( + _settrace( suspend=True, trace_only_current_thread=True, patch_multiprocessing=False, @@ -185,8 +240,8 @@ def break_into_debugger(): def debug_this_thread(): - log.info("debug_this_thread()") - pydevd.settrace(suspend=False) + log.debug("debug_this_thread()") + _settrace(suspend=False) _tls = threading.local()