mirror of
https://github.com/olivierkes/manuskript.git
synced 2024-05-19 12:22:23 +12:00
5117f7d476
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.
286 lines
12 KiB
Python
286 lines
12 KiB
Python
# -*- coding: utf-8 -*-
|
|
|
|
# While all logging should be done through the facilities offered by the
|
|
# standard python `logging` module, this module will take care of specific
|
|
# manuskript needs to keep it separate from the rest of the logic.
|
|
|
|
import os
|
|
import sys
|
|
import logging
|
|
|
|
from manuskript.functions import writablePath
|
|
from importlib import import_module
|
|
|
|
LOGGER = logging.getLogger(__name__)
|
|
|
|
LOGFORMAT_CONSOLE = "%(levelname)s> %(message)s"
|
|
LOGFORMAT_FILE = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
|
|
|
|
def setUp(console_level=logging.WARN):
|
|
"""Sets up a convenient environment for logging.
|
|
|
|
To console: >WARNING, plain. (Only the essence.)"""
|
|
|
|
# The root_logger should merely trigger on warnings since it is the final
|
|
# stop after all categories we really care about didn't match.
|
|
root_logger = logging.getLogger()
|
|
root_logger.setLevel(logging.WARN)
|
|
# The manuskript_logger is what all of our own code will come by.
|
|
# Obviously, we care greatly about logging every single message.
|
|
manuskript_logger = logging.getLogger("manuskript")
|
|
manuskript_logger.setLevel(logging.DEBUG)
|
|
# The qt_logger sees all the Qt nonsense when it breaks.
|
|
# We don't really want to know... but we have to know.
|
|
qt_logger = logging.getLogger("qt")
|
|
qt_logger.setLevel(logging.DEBUG)
|
|
|
|
# Send logs of WARNING+ to STDERR for higher visibility.
|
|
ch = logging.StreamHandler()
|
|
ch.setLevel(console_level)
|
|
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.")
|
|
|
|
|
|
def logToFile(file_level=logging.DEBUG, logfile=None):
|
|
"""Sets up the FileHandler that logs to a file.
|
|
|
|
This is being done separately due to relying on QApplication being properly
|
|
configured; without it we cannot detect the proper location for the log file.
|
|
|
|
To log file: >DEBUG, timestamped. (All the details.)"""
|
|
|
|
if logfile is None:
|
|
logfile = os.path.join(writablePath(), "manuskript.log")
|
|
|
|
# Log with extreme prejudice; everything goes to the log file.
|
|
# Because Qt gave me a megabyte-sized logfile while testing, it
|
|
# makes sense that the default behaviour of appending to existing
|
|
# log files may not be in our users best interest for the time
|
|
# being. (Unfortunately.)
|
|
try:
|
|
fh = logging.FileHandler(logfile, mode='w', encoding='utf-8')
|
|
fh.setLevel(file_level)
|
|
fh.setFormatter(logging.Formatter(LOGFORMAT_FILE))
|
|
|
|
root_logger = logging.getLogger()
|
|
root_logger.addHandler(fh)
|
|
|
|
# Use INFO level to make it easier to find for users.
|
|
LOGGER.info("Logging to file: %s", logfile)
|
|
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
|
|
|
|
from PyQt5.QtCore import qInstallMessageHandler, QLibraryInfo, QMessageLogContext
|
|
from PyQt5.Qt import QtMsgType
|
|
|
|
def qtMessageHandler(msg_type, msg_log_context, msg_string):
|
|
"""Forwards Qt messages to Python logging system."""
|
|
# Convert Qt msg type to logging level
|
|
log_level = [logging.DEBUG,
|
|
logging.WARNING,
|
|
logging.ERROR,
|
|
logging.FATAL] [ int(msg_type) ]
|
|
qtcl = logging.getLogger(msg_log_context.category or "qt.???")
|
|
# Some information may not be available unless using a PyQt debug build.
|
|
# See: https://www.riverbankcomputing.com/static/Docs/PyQt5/api/qtcore/qmessagelogcontext.html
|
|
if QLibraryInfo.isDebugBuild():
|
|
qtcl.log(logging.DEBUG,
|
|
' @ {0} : {1}'.format((msg_log_context.file or "<unknown source file>"), msg_log_context.line)
|
|
)
|
|
qtcl.log(logging.DEBUG,
|
|
' ! {0}'.format((msg_log_context.function or "<unknown function>"))
|
|
)
|
|
qtcl.log(log_level, msg_string)
|
|
|
|
def integrateQtLogging():
|
|
"""Integrates Qt logging facilities to be a part of our own."""
|
|
|
|
# Note: the qtlogger is initialized in setUp() because it fits in
|
|
# nicely with the initialization of the other loggers over there.
|
|
# I also feel a lot safer this way. Qt is a curse that just keeps
|
|
# on giving, even when it isn't actually at fault. I hate you, Qt.
|
|
|
|
qInstallMessageHandler(qtMessageHandler)
|
|
|
|
|
|
def versionTupleToString(t):
|
|
"""A bit of generic tuple conversion code that hopefully handles all the
|
|
different sorts of tuples we may come across while logging versions.
|
|
|
|
None -> "N/A"
|
|
(,) -> "N/A"
|
|
(2, 4, 6) -> "2.4.6"
|
|
(2, 4, "alpha", 8) -> "2.4-alpha.8"
|
|
"""
|
|
|
|
s = []
|
|
if t is None or len(t) == 0:
|
|
return "N/A"
|
|
else:
|
|
s.append(str(t[0]))
|
|
|
|
def version_chunk(v):
|
|
if isinstance(v, str):
|
|
return "-", str(v)
|
|
else:
|
|
return ".", str(v)
|
|
|
|
s.extend(f for p in t[1:] for f in version_chunk(p))
|
|
return "".join(s)
|
|
|
|
def attributesFromOptionalModule(module, *attributes):
|
|
"""It is nice to cut down on the try-except boilerplate by
|
|
putting this logic into its own function.
|
|
|
|
Returns as many values as there are attributes.
|
|
A value will be None if it failed to get the attribute."""
|
|
|
|
assert(len(attributes) != 0)
|
|
v = []
|
|
try:
|
|
m = import_module(module)
|
|
|
|
for a in attributes:
|
|
v.append(getattr(m, a, None))
|
|
except ImportError:
|
|
v.extend(None for _ in range(len(attributes)))
|
|
|
|
if len(v) == 1:
|
|
# Return the value directly so we can use it in an expression.
|
|
return v[0]
|
|
else:
|
|
# The list is consumed as a part of the unpacking syntax.
|
|
return v
|
|
|
|
import pathlib
|
|
|
|
def logVersionInformation(logger=None):
|
|
"""Logs all important runtime information neatly together.
|
|
|
|
Due to the generic nature, use the manuskript logger by default."""
|
|
|
|
if not logger:
|
|
logger = logging.getLogger("manuskript")
|
|
|
|
vt2s = versionTupleToString
|
|
afom = attributesFromOptionalModule
|
|
|
|
# Basic system information.
|
|
from platform import python_version, platform, processor, machine
|
|
logger.info("Operating System: %s", platform())
|
|
logger.info("Hardware: %s / %s", machine(), processor())
|
|
|
|
# Manuskript and Python info.
|
|
from manuskript.functions import getGitRevisionAsString, getManuskriptPath
|
|
from manuskript.version import getVersion
|
|
logger.info("Manuskript %s%s (Python %s)", getVersion(),
|
|
getGitRevisionAsString(getManuskriptPath(), short=True),
|
|
python_version())
|
|
|
|
# Installed Python packages.
|
|
|
|
# PyQt + Qt
|
|
from PyQt5.Qt import PYQT_VERSION_STR, qVersion
|
|
from PyQt5.QtCore import QT_VERSION_STR
|
|
logger.info("* PyQt %s (compiled against Qt %s)", PYQT_VERSION_STR, QT_VERSION_STR)
|
|
logger.info(" * Qt %s (runtime)", qVersion())
|
|
|
|
# Lxml
|
|
# See: https://lxml.de/FAQ.html#i-think-i-have-found-a-bug-in-lxml-what-should-i-do
|
|
from lxml import etree
|
|
logger.info("* lxml.etree %s", vt2s(etree.LXML_VERSION))
|
|
logger.info(" * libxml %s (compiled: %s)", vt2s(etree.LIBXML_VERSION), vt2s(etree.LIBXML_COMPILED_VERSION))
|
|
logger.info(" * libxslt %s (compiled: %s)", vt2s(etree.LIBXSLT_VERSION), vt2s(etree.LIBXSLT_COMPILED_VERSION))
|
|
|
|
# Spellcheckers. (Optional)
|
|
enchant_mod_ver, enchant_lib_ver = afom("enchant", "__version__", "get_enchant_version")
|
|
if enchant_lib_ver:
|
|
enchant_lib_ver = enchant_lib_ver()
|
|
if isinstance(enchant_lib_ver, bytes): # PyEnchant version < 3.0.2
|
|
enchant_lib_ver = enchant_lib_ver.decode('utf-8')
|
|
logger.info("* pyEnchant %s (libenchant: %s)", enchant_mod_ver or "N/A", enchant_lib_ver or "N/A")
|
|
|
|
logger.info("* pySpellChecker %s", afom("spellchecker", "__version__") or "N/A")
|
|
logger.info("* Symspellpy %s", afom("symspellpy", "__version__") or "N/A")
|
|
|
|
# Markdown. (Optional)
|
|
logger.info("* Markdown %s", afom("markdown", "__version__") or "N/A")
|
|
|
|
# Web rendering engine
|
|
from manuskript.ui.views.webView import webEngine
|
|
logger.info("Web rendering engine: %s", webEngine)
|
|
|
|
# Do not collect version information for Pandoc; that would require
|
|
# executing `pandov -v` and parsing the output, all of which is too slow.
|