From de9ea2cb9cfd87e7dba6ed9b4cdf2f0abe333ec1 Mon Sep 17 00:00:00 2001 From: Pavel Minaev Date: Thu, 20 Feb 2020 17:21:21 -0800 Subject: [PATCH] Improve exception logging to make swallowing/reraising explicit in all cases. --- src/debugpy/adapter/__main__.py | 6 +-- src/debugpy/adapter/clients.py | 2 +- src/debugpy/adapter/components.py | 2 +- src/debugpy/adapter/servers.py | 10 ++--- src/debugpy/adapter/sessions.py | 6 +-- src/debugpy/common/log.py | 51 ++++++++++++----------- src/debugpy/common/messaging.py | 36 ++++++++-------- src/debugpy/common/sockets.py | 2 +- src/debugpy/common/stacks.py | 2 +- src/debugpy/launcher/__main__.py | 2 +- src/debugpy/launcher/debuggee.py | 6 +-- src/debugpy/server/api.py | 12 +++--- src/debugpy/server/attach_pid_injected.py | 7 ++-- src/debugpy/server/cli.py | 13 +++--- tests/debug/comms.py | 4 +- tests/debug/session.py | 4 +- tests/debugpy/test_path_mapping.py | 4 +- tests/net.py | 2 +- tests/watchdog/__init__.py | 4 +- tests/watchdog/worker.py | 10 ++--- 20 files changed, 93 insertions(+), 92 deletions(-) diff --git a/src/debugpy/adapter/__main__.py b/src/debugpy/adapter/__main__.py index f4ab6154..e01bfec9 100644 --- a/src/debugpy/adapter/__main__.py +++ b/src/debugpy/adapter/__main__.py @@ -86,7 +86,7 @@ def main(args): finally: sockets.close_socket(sock) except Exception: - raise log.exception("Error sending endpoints info to debug server:") + log.reraise_exception("Error sending endpoints info to debug server:") if "error" in endpoints: log.error("Couldn't set up endpoints; exiting.") @@ -101,14 +101,14 @@ def main(args): try: os.remove(listener_file) except Exception: - log.exception("Failed to delete {0!r}", listener_file, level="warning") + log.swallow_exception("Failed to delete {0!r}", listener_file, level="warning") 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:") + log.reraise_exception("Error writing endpoints info to file:") if args.port is None: clients.Client("stdio") diff --git a/src/debugpy/adapter/clients.py b/src/debugpy/adapter/clients.py index d3ad8600..2a285308 100644 --- a/src/debugpy/adapter/clients.py +++ b/src/debugpy/adapter/clients.py @@ -459,4 +459,4 @@ def stop_serving(): try: listener.close() except Exception: - log.exception(level="warning") + log.swallow_exception(level="warning") diff --git a/src/debugpy/adapter/components.py b/src/debugpy/adapter/components.py index 17a0fd86..5f9c5273 100644 --- a/src/debugpy/adapter/components.py +++ b/src/debugpy/adapter/components.py @@ -123,7 +123,7 @@ def missing(session, type): try: raise ComponentNotAvailable(type) except Exception as exc: - raise log.exception("{0} in {1}", exc, session) + log.reraise_exception("{0} in {1}", exc, session) return Missing() diff --git a/src/debugpy/adapter/servers.py b/src/debugpy/adapter/servers.py index 09034e6a..c7e54aeb 100644 --- a/src/debugpy/adapter/servers.py +++ b/src/debugpy/adapter/servers.py @@ -99,7 +99,7 @@ if 'debugpy' not in sys.modules: # Failure to inject is not a fatal error - such a subprocess can # still be debugged, it just won't support "import debugpy" in user # code - so don't terminate the session. - log.exception( + log.swallow_exception( "Failed to inject debugpy into {0}:", self, level="warning" ) @@ -119,7 +119,7 @@ if 'debugpy' not in sys.modules: _connections_changed.set() except Exception: - log.exception("Failed to accept incoming server connection:") + log.swallow_exception("Failed to accept incoming server connection:") self.channel.close() # If this was the first server to connect, and the main thread is inside @@ -142,7 +142,7 @@ if 'debugpy' not in sys.modules: # session. We still want to keep the connection around, in case the # client reconnects later. If the parent session was "launch", it'll take # care of closing the remaining server connections. - log.exception("Failed to notify parent session about {0}:", self) + log.swallow_exception("Failed to notify parent session about {0}:", self) def __str__(self): return "Server" + fmt("[?]" if self.pid is None else "[pid={0}]", self.pid) @@ -354,7 +354,7 @@ def stop_serving(): try: listener.close() except Exception: - log.exception(level="warning") + log.swallow_exception(level="warning") def connections(): @@ -442,7 +442,7 @@ def inject(pid, debugpy_args): stderr=subprocess.STDOUT, ) except Exception as exc: - log.exception("Failed to inject debug server into process with PID={0}", pid) + log.swallow_exception("Failed to inject debug server into process with PID={0}", pid) raise messaging.MessageHandlingError( fmt( "Failed to inject debug server into process with PID={0}: {1}", pid, exc diff --git a/src/debugpy/adapter/sessions.py b/src/debugpy/adapter/sessions.py index 986641d6..8287fc70 100644 --- a/src/debugpy/adapter/sessions.py +++ b/src/debugpy/adapter/sessions.py @@ -163,7 +163,7 @@ class Session(util.Observable): except Exception: # Finalization should never fail, and if it does, the session is in an # indeterminate and likely unrecoverable state, so just fail fast. - log.exception("Fatal error while finalizing {0}", self) + log.swallow_exception("Fatal error while finalizing {0}", self) os._exit(1) log.info("{0} finalized.", self) @@ -215,7 +215,7 @@ class Session(util.Observable): try: self.launcher.channel.close() except Exception: - log.exception() + log.swallow_exception() if self.client: if self.client.is_connected: @@ -253,7 +253,7 @@ class Session(util.Observable): try: os.kill(conn.pid, signal.SIGTERM) except Exception: - log.exception("Failed to kill {0}", conn) + log.swallow_exception("Failed to kill {0}", conn) pids_killed.add(conn.pid) diff --git a/src/debugpy/common/log.py b/src/debugpy/common/log.py index 85d3da18..d92e9033 100644 --- a/src/debugpy/common/log.py +++ b/src/debugpy/common/log.py @@ -152,8 +152,7 @@ def write_format(level, format_string, *args, **kwargs): try: text = fmt(format_string, *args, **kwargs) except Exception: - exception() - raise + reraise_exception() return write(level, text, kwargs.pop("_to_files", all)) @@ -178,26 +177,7 @@ def error(*args, **kwargs): return AssertionError(write_format("error", *args, **kwargs)) -def exception(format_string="", *args, **kwargs): - """Logs an exception with full traceback. - - If format_string is specified, it is formatted with fmt(*args, **kwargs), and - prepended to the exception traceback on a separate line. - - If exc_info is specified, the exception it describes will be logged. Otherwise, - sys.exc_info() - i.e. the exception being handled currently - will be logged. - - If level is specified, the exception will be logged as a message of that level. - The default is "error". - - Returns the exception object, for convenient re-raising:: - - try: - ... - except Exception: - raise log.exception() # log it and re-raise - """ - +def _exception(format_string="", *args, **kwargs): level = kwargs.pop("level", "error") exc_info = kwargs.pop("exc_info", sys.exc_info()) @@ -218,7 +198,30 @@ def exception(format_string="", *args, **kwargs): level, format_string, *args, exception=exception, stack=stack, **kwargs ) - return exc_info[1] + +def swallow_exception(format_string="", *args, **kwargs): + """Logs an exception with full traceback. + + If format_string is specified, it is formatted with fmt(*args, **kwargs), and + prepended to the exception traceback on a separate line. + + If exc_info is specified, the exception it describes will be logged. Otherwise, + sys.exc_info() - i.e. the exception being handled currently - will be logged. + + If level is specified, the exception will be logged as a message of that level. + The default is "error". + """ + + _exception(format_string, *args, **kwargs) + + +def reraise_exception(format_string="", *args, **kwargs): + """Like swallow_exception(), but re-raises the current exception after logging it. + """ + + assert "exc_info" not in kwargs + _exception(format_string, *args, **kwargs) + raise def to_file(filename=None, prefix=None, levels=LEVELS): @@ -300,7 +303,7 @@ def describe_environment(header): report("{0}\n", prefix) return except Exception: - exception( + swallow_exception( "Error evaluating {0}", repr(expr) if expr else compat.srcnameof(get_paths), ) diff --git a/src/debugpy/common/messaging.py b/src/debugpy/common/messaging.py index c0df496b..1794ee76 100644 --- a/src/debugpy/common/messaging.py +++ b/src/debugpy/common/messaging.py @@ -177,7 +177,7 @@ class JsonIOStream(object): # read() or write(), which is a common and expected occurrence with # JsonMessageChannel, so don't even bother logging it. if sys.version_info >= (3,): - raise log.exception("Error while closing {0} message stream", self.name) + log.reraise_exception("Error while closing {0} message stream", self.name) def _log_message(self, dir, data, logger=log.debug): format_string = "{0} {1} " + ( @@ -190,8 +190,8 @@ class JsonIOStream(object): while True: try: line += reader.readline() - except Exception as ex: - raise NoMoreMessages(str(ex), stream=self) + except Exception as exc: + raise NoMoreMessages(str(exc), stream=self) if not line: raise NoMoreMessages(stream=self) if line.endswith(b"\r\n"): @@ -212,7 +212,7 @@ class JsonIOStream(object): # If any error occurs while reading and parsing the message, log the original # raw message data as is, so that it's possible to diagnose missing or invalid # headers, encoding issues, JSON syntax errors etc. - def log_message_and_exception(format_string="", *args, **kwargs): + def log_message_and_reraise_exception(format_string="", *args, **kwargs): if format_string: format_string += "\n\n" format_string += "{name} -->\n{raw_lines}" @@ -220,7 +220,7 @@ class JsonIOStream(object): raw_lines = b"".join(raw_chunks).split(b"\n") raw_lines = "\n".join(repr(line) for line in raw_lines) - return log.exception( + log.reraise_exception( format_string, *args, name=self.name, raw_lines=raw_lines, **kwargs ) @@ -236,8 +236,9 @@ class JsonIOStream(object): # there's no message data to log in any case, and the caller might # be anticipating the error - e.g. NoMoreMessages on disconnect. if headers: - log_message_and_exception("Error while reading message headers:") - raise + log_message_and_reraise_exception("Error while reading message headers:") + else: + raise raw_chunks += [line, b"\n"] if line == b"": @@ -254,7 +255,7 @@ class JsonIOStream(object): try: raise IOError("Content-Length is missing or invalid:") except Exception: - raise log_message_and_exception() + log_message_and_reraise_exception() body_start = len(raw_chunks) body_remaining = length @@ -265,9 +266,6 @@ class JsonIOStream(object): raise EOFError except Exception as exc: # Not logged due to https://github.com/microsoft/ptvsd/issues/1699 - # log_message_and_exception( - # "Couldn't read the expected {0} bytes of body:", length - # ) raise NoMoreMessages(str(exc), stream=self) raw_chunks.append(chunk) @@ -278,12 +276,12 @@ class JsonIOStream(object): try: body = body.decode("utf-8") except Exception: - raise log_message_and_exception() + log_message_and_reraise_exception() try: body = decoder.decode(body) except Exception: - raise log_message_and_exception() + log_message_and_reraise_exception() # If parsed successfully, log as JSON for readability. self._log_message("-->", body) @@ -628,7 +626,7 @@ class Event(Message): str(exc), ) except Exception: - raise log.exception( + log.reraise_exception( "Handler {0}\ncouldn't handle {1}:", compat.srcnameof(handler), self.describe(), @@ -785,7 +783,7 @@ class Request(Message): ) except Exception: - raise log.exception( + log.reraise_exception( "Handler {0}\ncouldn't handle {1}:", compat.srcnameof(handler), self.describe(), @@ -868,7 +866,7 @@ class OutgoingRequest(Request): str(exc), ) except Exception: - raise log.exception( + log.reraise_exception( "Handler {0}\ncouldn't handle {1}:", compat.srcnameof(handler), response.describe(), @@ -1059,7 +1057,7 @@ class MessageHandlingError(Exception): try: raise self except MessageHandlingError: - log.exception() + log.swallow_exception() def __hash__(self): return hash((self.reason, id(self.cause))) @@ -1423,7 +1421,7 @@ class JsonMessageChannel(object): except Exception as exc: if isinstance(exc, NoMoreMessages) and exc.stream is self.stream: raise - log.exception( + log.swallow_exception( "Fatal error in channel {0} while parsing:\n{1!j}", self, message_dict ) os._exit(1) @@ -1533,7 +1531,7 @@ class JsonMessageChannel(object): try: handler() except Exception: - raise log.exception( + log.reraise_exception( "Handler {0}\ncouldn't handle disconnect from {1}:", compat.srcnameof(handler), self, diff --git a/src/debugpy/common/sockets.py b/src/debugpy/common/sockets.py index 169f42d4..6f575db9 100644 --- a/src/debugpy/common/sockets.py +++ b/src/debugpy/common/sockets.py @@ -68,7 +68,7 @@ def serve(name, handler, host, port=0, backlog=socket.SOMAXCONN, timeout=None): try: listener = create_server(host, port, backlog, timeout) except Exception: - raise log.exception( + log.reraise_exception( "Error listening for incoming {0} connections on {1}:{2}:", name, host, port ) host, port = listener.getsockname() diff --git a/src/debugpy/common/stacks.py b/src/debugpy/common/stacks.py index 45ba305e..8a10dc5b 100644 --- a/src/debugpy/common/stacks.py +++ b/src/debugpy/common/stacks.py @@ -59,7 +59,7 @@ def dump_after(secs): try: dump() except: - log.exception() + log.swallow_exception() thread = threading.Thread(target=dumper) thread.daemon = True diff --git a/src/debugpy/launcher/__main__.py b/src/debugpy/launcher/__main__.py index 5704b36a..40ecf32a 100644 --- a/src/debugpy/launcher/__main__.py +++ b/src/debugpy/launcher/__main__.py @@ -35,7 +35,7 @@ def main(): try: return type(os.environ.pop(name, *args)) except Exception: - raise log.exception("Error parsing {0!r}:", name) + log.reraise_exception("Error parsing {0!r}:", name) launcher_port = option("DEBUGPY_LAUNCHER_PORT", int) diff --git a/src/debugpy/launcher/debuggee.py b/src/debugpy/launcher/debuggee.py index 07b396cc..787b26fa 100644 --- a/src/debugpy/launcher/debuggee.py +++ b/src/debugpy/launcher/debuggee.py @@ -92,7 +92,7 @@ def spawn(process_name, cmdline, cwd, env, redirect_output): try: os.close(fd) except Exception: - log.exception() + log.swallow_exception() def kill(): @@ -103,7 +103,7 @@ def kill(): log.info("Killing {0}", describe()) process.kill() except Exception: - log.exception("Failed to kill {0}", describe()) + log.swallow_exception("Failed to kill {0}", describe()) def wait_for_exit(): @@ -116,7 +116,7 @@ def wait_for_exit(): # taking the lowest 8 bits of that negative returncode. code &= 0xFF except Exception: - log.exception("Couldn't determine process exit code:") + log.swallow_exception("Couldn't determine process exit code:") code = -1 log.info("{0} exited with code {1}", describe(), code) diff --git a/src/debugpy/server/api.py b/src/debugpy/server/api.py index cff8493a..7696319d 100644 --- a/src/debugpy/server/api.py +++ b/src/debugpy/server/api.py @@ -121,7 +121,7 @@ def _starts_debugging(func): try: return func(address, settrace_kwargs, **kwargs) except Exception: - raise log.exception("{0}() failed:", func.__name__, level="info") + log.reraise_exception("{0}() failed:", func.__name__, level="info") return debug @@ -138,7 +138,7 @@ def listen(address, settrace_kwargs): try: endpoints_listener = sockets.create_server("127.0.0.1", 0, timeout=10) except Exception as exc: - log.exception("Can't listen for adapter endpoints:") + log.swallow_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( @@ -188,7 +188,7 @@ def listen(address, settrace_kwargs): _adapter_process.returncode = 0 pydevd.add_dont_terminate_child_pid(_adapter_process.pid) except Exception as exc: - log.exception("Error spawning debug adapter:", level="info") + log.swallow_exception("Error spawning debug adapter:", level="info") raise RuntimeError("error spawning debug adapter: " + str(exc)) try: @@ -203,10 +203,10 @@ def listen(address, settrace_kwargs): finally: sockets.close_socket(sock) except socket.timeout: - log.exception("Timed out waiting for adapter to connect:", level="info") + log.swallow_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") + log.swallow_exception("Error retrieving adapter endpoints:", level="info") raise RuntimeError("error retrieving adapter endpoints: " + str(exc)) log.info("Endpoints received from adapter: {0!j}", endpoints) @@ -220,7 +220,7 @@ def listen(address, settrace_kwargs): client_host = str(endpoints["client"]["host"]) client_port = int(endpoints["client"]["port"]) except Exception as exc: - log.exception( + log.swallow_exception( "Error parsing adapter endpoints:\n{0!j}\n", endpoints, level="info" ) raise RuntimeError("error parsing adapter endpoints: " + str(exc)) diff --git a/src/debugpy/server/attach_pid_injected.py b/src/debugpy/server/attach_pid_injected.py index 9e64dabe..e6345996 100644 --- a/src/debugpy/server/attach_pid_injected.py +++ b/src/debugpy/server/attach_pid_injected.py @@ -86,8 +86,9 @@ def attach(setup): import traceback traceback.print_exc() - if log is not None: - log.exception() - raise + if log is None: + raise + else: + log.reraise_exception() log.info("debugpy injected successfully") diff --git a/src/debugpy/server/cli.py b/src/debugpy/server/cli.py index b31c0092..a99195cb 100644 --- a/src/debugpy/server/cli.py +++ b/src/debugpy/server/cli.py @@ -284,7 +284,7 @@ def run_module(): else: _, _, _, argv_0 = runpy._get_module_details(options.target) except Exception: - log.exception("Error determining module path for sys.argv") + log.swallow_exception("Error determining module path for sys.argv") start_debugging(argv_0) @@ -392,7 +392,7 @@ attach_pid_injected.attach(setup); show_debug_info=int(os.getenv("DEBUGPY_ATTACH_BY_PID_DEBUG_INFO", "0")), ) except Exception: - raise log.exception("Code injection into PID={0} failed:", pid) + log.reraise_exception("Code injection into PID={0} failed:", pid) log.info("Code injection into PID={0} completed.", pid) @@ -400,8 +400,8 @@ def main(): original_argv = list(sys.argv) try: parse_argv() - except Exception as ex: - print(HELP + "\nError: " + str(ex), file=sys.stderr) + except Exception as exc: + print(HELP + "\nError: " + str(exc), file=sys.stderr) sys.exit(2) if options.log_to is not None: @@ -425,6 +425,5 @@ def main(): "pid": attach_to_pid, }[options.target_kind] run() - except SystemExit as ex: - log.exception("Debuggee exited via SystemExit: {0!r}", ex.code, level="debug") - raise + except SystemExit as exc: + log.reraise_exception("Debuggee exited via SystemExit: {0!r}", exc.code, level="debug") diff --git a/tests/debug/comms.py b/tests/debug/comms.py index de686900..55dc48c3 100644 --- a/tests/debug/comms.py +++ b/tests/debug/comms.py @@ -47,12 +47,12 @@ class BackChannel(object): if self._server_socket is None: return else: - raise log.exception("Timed out waiting for {0} to connect", self) + log.reraise_exception("Timed out waiting for {0} to connect", self) except Exception: if self._server_socket is None: return else: - raise log.exception("Error accepting connection for {0}:", self) + log.reraise_exception("Error accepting connection for {0}:", self) sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) log.info("Incoming connection from {0} accepted.", self) diff --git a/tests/debug/session.py b/tests/debug/session.py index 486e2200..556c2421 100644 --- a/tests/debug/session.py +++ b/tests/debug/session.py @@ -227,7 +227,7 @@ class Session(object): self.wait_for_exit() else: # Log the error, in case another one happens during shutdown. - log.exception(exc_info=(exc_type, exc_val, exc_tb)) + log.swallow_exception(exc_info=(exc_type, exc_val, exc_tb)) if exc_type is None: self.disconnect() @@ -498,7 +498,7 @@ class Session(object): self.spawn_debuggee(args, cwd, exe=exe) return {} except OSError as exc: - log.exception('"runInTerminal" failed:') + log.swallow_exception('"runInTerminal" failed:') raise request.cant_handle(str(exc)) else: raise request.isnt_valid("not supported") diff --git a/tests/debugpy/test_path_mapping.py b/tests/debugpy/test_path_mapping.py index 50b9f389..8d635014 100644 --- a/tests/debugpy/test_path_mapping.py +++ b/tests/debugpy/test_path_mapping.py @@ -134,8 +134,8 @@ def test_with_path_mappings(pyfile, long_tmpdir, target, run): try: session.request("source", {"sourceReference": 0}) - except Exception as ex: - assert "Source unavailable" in str(ex) + except Exception as exc: + assert "Source unavailable" in str(exc) else: pytest.fail("sourceReference=0 should not be valid") diff --git a/tests/net.py b/tests/net.py index 291b55ff..082fc86a 100644 --- a/tests/net.py +++ b/tests/net.py @@ -130,7 +130,7 @@ class WebRequest(object): self.request = func(self.url, *args, **kwargs) except Exception as exc: if self.log_errors: - log.exception("{0} failed:", self) + log.swallow_exception("{0} failed:", self) self.exception = exc else: log.info( diff --git a/tests/watchdog/__init__.py b/tests/watchdog/__init__.py index 451768bc..a1ae3e3f 100644 --- a/tests/watchdog/__init__.py +++ b/tests/watchdog/__init__.py @@ -74,7 +74,7 @@ def _dump_worker_log(command, problem, exc_info=None): if exc_info is None: log.error("{0}", reason) else: - log.exception("{0}", reason, exc_info=exc_info) + log.swallow_exception("{0}", reason, exc_info=exc_info) return reason @@ -111,7 +111,7 @@ def stop(): _invoke("stop") _stream.close() except Exception: - log.exception() + log.swallow_exception() def register_spawn(pid, name): diff --git a/tests/watchdog/worker.py b/tests/watchdog/worker.py index 268e2deb..5cfdae68 100644 --- a/tests/watchdog/worker.py +++ b/tests/watchdog/worker.py @@ -93,15 +93,15 @@ def main(tests_pid): stream.write_json(["ok"]) - except Exception as ex: - stream.write_json(["error", str(ex)]) - raise log.exception() + except Exception as exc: + stream.write_json(["error", str(exc)]) + log.reraise_exception() finally: try: stream.close() except Exception: - log.exception() + log.swallow_exception() # If the test runner becomes a zombie process, it is still considered alive, # and wait() will block indefinitely. Poll status instead. @@ -156,7 +156,7 @@ def main(tests_pid): except psutil.NoSuchProcess: pass except Exception: - log.exception() + log.swallow_exception() log.info("WatchDog-{0} exiting", tests_pid)