Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
# -*- 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
|
2019-11-03 03:32:31 +13:00
|
|
|
import sys
|
2021-04-13 23:32:46 +12:00
|
|
|
import time
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
import logging
|
2019-11-05 02:35:21 +13:00
|
|
|
import pathlib
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
|
2019-10-15 07:16:07 +13:00
|
|
|
from manuskript.functions import writablePath
|
|
|
|
from importlib import import_module
|
2019-11-05 02:35:21 +13:00
|
|
|
from pprint import pformat
|
2019-10-15 07:16:07 +13:00
|
|
|
|
|
|
|
LOGGER = logging.getLogger(__name__)
|
|
|
|
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
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)
|
|
|
|
|
2019-11-03 03:32:31 +13:00
|
|
|
# Any exceptions we did not account for need to be logged.
|
|
|
|
logFutureExceptions()
|
|
|
|
|
2019-10-15 07:16:07 +13:00
|
|
|
LOGGER.debug("Logging to STDERR.")
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
|
|
|
|
|
2021-04-13 23:32:46 +12:00
|
|
|
def getDefaultLogFile():
|
|
|
|
"""Returns a filename to log to inside {datadir}/logs/.
|
|
|
|
|
|
|
|
It also prunes old logs so that we do not hog disk space excessively over time.
|
|
|
|
"""
|
|
|
|
# Ensure logs directory exists.
|
|
|
|
logsPath = os.path.join(writablePath(), "logs")
|
|
|
|
os.makedirs(logsPath, exist_ok=True)
|
|
|
|
# Prune irrelevant log files. They are only kept for 35 days.
|
|
|
|
try: # Guard against os.scandir() in the name of paranoia.
|
|
|
|
now = time.time()
|
|
|
|
with os.scandir(logsPath) as it:
|
|
|
|
for f in it:
|
|
|
|
try: # Avoid triggering outer try-except inside loop.
|
|
|
|
if f.is_dir():
|
|
|
|
continue # If a subdirectory exists for whatever reason, don't touch it.
|
|
|
|
if (now - f.stat().st_ctime) // (24 * 3600) >= 35:
|
|
|
|
os.remove(f)
|
|
|
|
except OSError:
|
|
|
|
continue # Fail silently, but make sure we check other files.
|
|
|
|
except OSError:
|
|
|
|
pass # Fail silently. Don't explode and prevent Manuskript from starting.
|
|
|
|
return os.path.join(logsPath, "%Y-%m-%d_%H-%M-%S_manuskript#%#.log")
|
|
|
|
|
|
|
|
|
|
|
|
def formatLogName(formatString, pid=None, now=None):
|
|
|
|
"""A minor hack on top of `strftime()` to support an identifier for the process ID.
|
|
|
|
|
|
|
|
We want to support this in case some genius manages to start two manuskript processes
|
|
|
|
during the exact same second, causing a conflict in log filenames.
|
|
|
|
|
|
|
|
Additionally, there is a tiny chance that the pid could actually end up relevant when
|
|
|
|
observing strange behaviour with a Manuskript process but having multiple instances open.
|
|
|
|
"""
|
|
|
|
if pid == None:
|
|
|
|
pid = os.getpid()
|
|
|
|
if now == None:
|
|
|
|
now = time.localtime()
|
|
|
|
|
|
|
|
# Replace %# that is NOT preceded by %. Although this is not a perfect solution,
|
|
|
|
# it is good enough because it is unlikely anyone would want to format '%pid'.
|
|
|
|
lidx = 0
|
|
|
|
while True: # This could be neater with the := operator of Python 3.8 ...
|
|
|
|
fidx = formatString.find("%#", lidx)
|
|
|
|
if fidx == -1:
|
|
|
|
break
|
|
|
|
elif (fidx == 0) or (formatString[fidx-1] != "%"):
|
|
|
|
formatString = formatString[:fidx] + str(pid) + formatString[fidx+2:]
|
|
|
|
lidx = fidx + len(str(pid)) - 2
|
|
|
|
else: # skip and avoid endless loop
|
|
|
|
lidx = fidx + 1
|
|
|
|
|
|
|
|
# Finally apply strftime normally.
|
|
|
|
return time.strftime(formatString, now)
|
|
|
|
|
|
|
|
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
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:
|
2021-04-13 23:32:46 +12:00
|
|
|
logfile = getDefaultLogFile()
|
|
|
|
|
|
|
|
logfile = formatLogName(logfile)
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
|
|
|
|
# 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:
|
2019-10-19 11:38:27 +13:00
|
|
|
fh = logging.FileHandler(logfile, mode='w', encoding='utf-8')
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
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.
|
2019-10-15 07:16:07 +13:00
|
|
|
LOGGER.info("Logging to file: %s", logfile)
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
except Exception as ex:
|
2019-10-15 07:16:07 +13:00
|
|
|
LOGGER.warning("Cannot log to file '%s'. Reason: %s", logfile, ex)
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
|
2021-04-13 23:32:46 +12:00
|
|
|
|
|
|
|
def getLogFilePath():
|
|
|
|
"""Extracts a filename we are logging to from the first FileHandler we find."""
|
|
|
|
root_logger = logging.getLogger()
|
|
|
|
for handler in root_logger.handlers:
|
|
|
|
if isinstance(handler, logging.FileHandler):
|
|
|
|
return handler.baseFilename
|
|
|
|
return None
|
|
|
|
|
|
|
|
|
2019-11-03 03:32:31 +13:00
|
|
|
# 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
|
|
|
|
|
Added logging & proper argument parsing.
Sometimes you want to do just one thing, and in the process of
implementing that one thing, you implement several others. This is one
of those types of commits.
Implementing the argparse library is for the sake of controlling the
logging behaviour as well as other future I have yet to implement.
It has all the standard goodies you'd expect, and I have also ported
over the existing commandline arguments. (They may need a bit of polish
still, but there is no regression compared to before, only improvement.)
The logger is because it really needed to happen for numerous reasons.
It still logs to the terminal, but by default it only does so for
messages classified WARNING and above. These are the things we actively
want users to see. But if this is not good enough, adding the --verbose
flag will increasingly show more (-v shows INFO level and -vv also shows
the DEBUG messages) so that us coders don't have to miss anything in the
most convenient location.
It also logs to a file with the very original filename manuskript.log. I
may have to add commandline and/or settings arguments to improve that at
some point in the future, but there distractions are endless.
The log file contains timestamps and module information for easy
interpretation that are not present on the terminal, and it contains all
messages classified DEBUG and up. Ideally users will just be able to
attach it to an issue(*) to deliver us all the information we need to
help them with their inquiry.
Last but not least, the other reason I needed logging implemented is
that Qt has its own logging framework, and I needed to figure out how to
siphon out the data and make it shut up. But there was no point in doing
that as long as our own logging facilities were lacking...
(*) I have yet to convert all existing print statements over to the new
system, but that is probably going to be the next commit. This one has
enough change in it already.
2019-10-14 14:43:17 +13:00
|
|
|
|
|
|
|
# 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.
|
|
|
|
|
2019-10-15 07:16:07 +13:00
|
|
|
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
|
|
|
|
|
2019-11-05 02:35:21 +13:00
|
|
|
def logRuntimeInformation(logger=None):
|
2019-10-15 07:16:07 +13:00
|
|
|
"""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())
|
|
|
|
|
2019-11-05 02:35:21 +13:00
|
|
|
# Information about the running instance. See:
|
|
|
|
# https://pyinstaller.readthedocs.io/en/v3.3.1/runtime-information.html
|
|
|
|
# http://www.py2exe.org/index.cgi/Py2exeEnvironment
|
|
|
|
# https://cx-freeze.readthedocs.io/en/latest/faq.html#data-files
|
|
|
|
frozen = getattr(sys, 'frozen', False)
|
|
|
|
if frozen:
|
|
|
|
logger.info("Running in a frozen (packaged) state.")
|
|
|
|
logger.debug("* sys.frozen = %s", pformat(frozen))
|
|
|
|
|
|
|
|
# PyInstaller, py2exe and cx_Freeze modules are not accessible while frozen,
|
|
|
|
# so logging their version is (to my knowledge) impossible without including
|
|
|
|
# special steps into the distribution process. But some traces do exist...
|
|
|
|
logger.debug("* sys._MEIPASS = %s", getattr(sys, '_MEIPASS', "N/A")) # PyInstaller bundle
|
|
|
|
# cx_Freeze and py2exe do not appear to leave anything similar exposed.
|
|
|
|
else:
|
|
|
|
logger.info("Running from unpackaged source code.")
|
|
|
|
|
|
|
|
# File not found? These bits of information might help.
|
|
|
|
logger.debug("* sys.executable = %s", pformat(sys.executable))
|
|
|
|
logger.debug("* sys.argv = %s", pformat(sys.argv))
|
|
|
|
logger.debug("* sys.path = %s", pformat(sys.path))
|
|
|
|
logger.debug("* sys.prefix = %s", pformat(sys.prefix))
|
|
|
|
|
2019-10-15 07:16:07 +13:00
|
|
|
# Manuskript and Python info.
|
2019-10-16 01:32:07 +13:00
|
|
|
from manuskript.functions import getGitRevisionAsString, getManuskriptPath
|
2019-10-15 07:16:07 +13:00
|
|
|
from manuskript.version import getVersion
|
2019-10-16 01:32:07 +13:00
|
|
|
logger.info("Manuskript %s%s (Python %s)", getVersion(),
|
|
|
|
getGitRevisionAsString(getManuskriptPath(), short=True),
|
|
|
|
python_version())
|
2019-10-15 07:16:07 +13:00
|
|
|
|
|
|
|
# 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.
|