From 5117f7d47621b248c9e503e8cb607cd7894c9422 Mon Sep 17 00:00:00 2001
From: Jan Wester <sciolist@kalda.nl>
Date: Sat, 2 Nov 2019 15:32:31 +0100
Subject: [PATCH] Logging uncaught & unraisable exceptions

When implementing most of the logging code weeks ago, I got so caught up
in implementing and testing the Qt bits that I completely blanked on
actually implementing the Python-side of catching exceptions.

Unfortunately, it is not exactly trivial. PyQt complicates things, but
also Python itself isn't very helpful in older versions which will rob
the ability to properly log errors from threads. By the time I realized
we don't actually use the threading module and that catching the errors
on there does not actually help to fix the weirdness I was seeing, it
was already implemented. Thank you PyQt for surprising me yet again! :-)

I have tested this on Python 3.7 by raising random exceptions in various
parts of the codebase to make sure it behaves as expected. I haven't
quite gotten around to installing Python 3.8 yet but this gets it out
for testing. I'll hopefully not forget to do more tests in 3.8 when I do
the final squashing prior to a merge.
---
 manuskript/logging.py | 66 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 66 insertions(+)

diff --git a/manuskript/logging.py b/manuskript/logging.py
index 69d0963d..6ae492dc 100644
--- a/manuskript/logging.py
+++ b/manuskript/logging.py
@@ -5,6 +5,7 @@
 # manuskript needs to keep it separate from the rest of the logic.
 
 import os
+import sys
 import logging
 
 from manuskript.functions import writablePath
@@ -39,6 +40,9 @@ def setUp(console_level=logging.WARN):
     ch.setFormatter(logging.Formatter(LOGFORMAT_CONSOLE))
     root_logger.addHandler(ch)
 
+    # Any exceptions we did not account for need to be logged.
+    logFutureExceptions()
+
     LOGGER.debug("Logging to STDERR.")
 
 
@@ -71,6 +75,68 @@ def logToFile(file_level=logging.DEBUG, logfile=None):
     except Exception as ex:
         LOGGER.warning("Cannot log to file '%s'. Reason: %s", logfile, ex)
 
+# Log uncaught and unraisable exceptions.
+
+# Uncaught exceptions trigger moments before a thread is terminated due to
+# an uncaught exception. It is the final stop, and as such is very likely
+# to be the reason Manuskript suddenly closed on the user without warning.
+# (It can also happen on other threads, but it is a bad thing regardless!)
+def handle_uncaught_exception(exc_type, exc_value, exc_traceback):
+    # Allow Ctrl+C for script execution to keep functioning as-is.
+    if issubclass(exc_type, KeyboardInterrupt):
+        sys.__excepthook__(exc_type, exc_value, exc_traceback)
+        return # default exception hook handled it
+
+    # Anything that reaches this handler can be considered a deal-breaker.
+    LOGGER.critical("An unhandled exception has occurred!", exc_info=(exc_type, exc_value, exc_traceback))
+
+    # Exit the program to preserve PyQt 'functionality' that is broken by
+    # having our own uncaught exception hook. For more information, see:
+    #   https://stackoverflow.com/questions/49065371/why-does-sys-excepthook-behave-differently-when-wrapped
+    sys.exit(1)
+
+    # Note that without it, unhandled Python exceptions thrown while in the
+    # bowels of Qt may be written to the log multiple times. Under the motto
+    # of failing fast and not having a misleading log file, this appears to
+    # be the best course of action.
+
+
+# The situation with threads and uncaught exceptions is fraught in peril.
+# Hopefully this solves our problems on more recent versions of Python.
+def handle_uncaught_thread_exception(args):
+    if issubclass(exc_type, SystemExit):
+        return # match behaviour of default hook, see manual
+
+    # Anything that reaches this handler can be considered a minor deal-breaker.
+    LOGGER.error("An unhandled exception has occurred in a thread: %s", repr(args.thread),
+                    exc_info=(args.exc_type, args.exc_value, args.exc_traceback))
+
+
+# Unraisable exceptions are exceptions that failed to be raised to a caller
+# due to the nature of the exception. Examples: __del__(), GC error, etc.
+# Logging these may expose bugs / errors that would otherwise go unnoticed.
+def handle_unraisable_exception(unraisable):
+    # Log as warning because the application is likely to limp along with
+    # no serious side effects; a resource leak is the most likely.
+    LOGGER.warning("%s: %s", unraisable.err_msg or "Exception ignored in", repr(unraisable.object),
+                    exc_info=(unraisable.exc_type, unraisable.exc_value, unraisable.exc_traceback))
+
+
+# Because we are already somewhat careful in regards to the order of code
+# execution when it comes to setting up the logging environment, this has
+# been put in its own function as opposed to letting a direct import handle it.
+def logFutureExceptions():
+    """Log all the interesting exceptions that may happen in the future."""
+    sys.excepthook = handle_uncaught_exception
+    try:
+        import threading # threading module was optional pre-3.7
+        if hasattr(threading, "excepthook"):  # Python 3.8+
+            threading.excepthook = handle_uncaught_thread_exception
+    except:
+        pass
+    if hasattr(sys, "unraisablehook"):  # Python 3.8+
+        sys.unraisablehook = handle_unraisable_exception
+
 
 # Qt has its own logging facility that we would like to integrate into our own.
 # See: http://thispageintentionally.blogspot.com/2014/03/trapping-qt-log-messages.html