From 8884bac0ed85d2b9377ab30318400859032be2ba Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Mon, 14 Oct 2019 03:43:17 +0200 Subject: [PATCH] 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. --- manuskript/logging.py | 106 +++++++++++++++++++++++++++++++++++ manuskript/main.py | 61 ++++++++++++++++---- manuskript/tests/__init__.py | 3 +- 3 files changed, 157 insertions(+), 13 deletions(-) create mode 100644 manuskript/logging.py diff --git a/manuskript/logging.py b/manuskript/logging.py new file mode 100644 index 0000000..56e5bf2 --- /dev/null +++ b/manuskript/logging.py @@ -0,0 +1,106 @@ +# -*- 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. + +from manuskript.functions import writablePath +import os +import logging + +LOGFORMAT_CONSOLE = "%(levelname)s> %(message)s" +LOGFORMAT_FILE = "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + +logger = logging.getLogger(__name__) + +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) + + 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') + 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) + + +# 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 ""), msg_log_context.line) + ) + qtcl.log(logging.DEBUG, + ' ! {0}'.format((msg_log_context.function or "")) + ) + 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) \ No newline at end of file diff --git a/manuskript/main.py b/manuskript/main.py index 2988a89..3b05544 100644 --- a/manuskript/main.py +++ b/manuskript/main.py @@ -6,6 +6,7 @@ import platform import sys import signal +import manuskript.logging import manuskript.ui.views.webView from PyQt5.QtCore import QLocale, QTranslator, QSettings, Qt from PyQt5.QtGui import QIcon, QColor, QPalette @@ -16,15 +17,24 @@ from manuskript.version import getVersion faulthandler.enable() +import logging +logger = logging.getLogger(__name__) -def prepare(tests=False): +def prepare(arguments, tests=False): app = QApplication(sys.argv) app.setOrganizationName("manuskript" + ("_tests" if tests else "")) app.setOrganizationDomain("www.theologeek.ch") app.setApplicationName("manuskript" + ("_tests" if tests else "")) app.setApplicationVersion(getVersion()) - print("Running manuskript version {}.".format(getVersion())) + # Beginning logging to a file. This cannot be done earlier due to the + # default location of the log file being dependent on QApplication. + manuskript.logging.logToFile(logfile=arguments.logfile) + + # Handle all sorts of Qt logging messages in Python. + manuskript.logging.integrateQtLogging() + + logger.info("Running manuskript version {}.".format(getVersion())) icon = QIcon() for i in [16, 32, 64, 128, 256, 512]: icon.addFile(appPath("icons/Manuskript/icon-{}px.png".format(i))) @@ -47,7 +57,7 @@ def prepare(tests=False): """Tries to load and activate a given translation for use.""" if appTranslator.load(translation, appPath("i18n")): app.installTranslator(appTranslator) - print("Loaded translation: {}".format(translation)) + logger.info("Loaded translation: {}".format(translation)) # Note: QTranslator.load() does some fancy heuristics where it simplifies # the given locale until it is 'close enough' if the given filename does # not work out. For example, if given 'i18n/manuskript_en_US.qm', it tries: @@ -62,7 +72,7 @@ def prepare(tests=False): # filenames when you observe strange behaviour with the loaded translations. return True else: - print("No translation found or loaded. ({})".format(translation)) + logger.info("No translation found or loaded. ({})".format(translation)) return False def activateTranslation(translation, source): @@ -85,7 +95,7 @@ def prepare(tests=False): break if using_builtin_translation: - print("Using the builtin translation.") + logger.info("Using the builtin translation. (U.S. English)") # Load application translation translation = "" @@ -99,7 +109,7 @@ def prepare(tests=False): translation = QLocale().uiLanguages() source = "available ui languages" - print("Preferred translation: {} (based on {})".format(("builtin" if translation == "" else translation), source)) + logger.info("Preferred translation: {} (based on {})".format(("builtin" if translation == "" else translation), source)) activateTranslation(translation, source) def respectSystemDarkThemeSetting(): @@ -164,15 +174,16 @@ def prepare(tests=False): MW._defaultCursorFlashTime = qApp.cursorFlashTime() # Command line project - if len(sys.argv) > 1 and sys.argv[1][-4:] == ".msk": + #if len(sys.argv) > 1 and sys.argv[1][-4:] == ".msk": + if arguments.filename is not None and arguments.filename[-4:] == ".msk": + #TODO: integrate better with argparsing. if os.path.exists(sys.argv[1]): path = os.path.abspath(sys.argv[1]) MW._autoLoadProject = path return app, MW - -def launch(app, MW=None): +def launch(arguments, app, MW = None): if MW == None: from manuskript.functions import mainWindow MW = mainWindow() @@ -184,7 +195,7 @@ def launch(app, MW=None): # Code reference : # https://github.com/ipython/ipykernel/blob/master/examples/embedding/ipkernel_qtapp.py # https://github.com/ipython/ipykernel/blob/master/examples/embedding/internal_ipkernel.py - if len(sys.argv) > 1 and sys.argv[-1] == "--console": + if arguments.console: try: from IPython.lib.kernel import connect_qtconsole from ipykernel.kernelapp import IPKernelApp @@ -241,18 +252,44 @@ def setup_signal_handlers(MW): signal.signal(signal.SIGTERM, sigint_handler("SIGTERM", MW)) +def process_commandline(argv): + import argparse + parser = argparse.ArgumentParser(description="Run the manuskript application.") + parser.add_argument("--console", help="open the IPython Jupyter QT Console as a debugging aid", + action="store_true") + parser.add_argument("-v", "--verbose", action="count", default=1, help="lower the threshold for messages logged to the terminal") + parser.add_argument("-L", "--logfile", default=None, help="override the default log file location") + parser.add_argument("filename", nargs="?", metavar="FILENAME", help="the manuskript project (.msk) to open") + + args = parser.parse_args(args=argv) + + # Verbosity logic, see: https://gist.github.com/ms5/9f6df9c42a5f5435be0e + #args.verbose = 70 - (10*args.verbose) if args.verbose > 0 else 0 + + # Users cannot report what they do not notice: show CRITICAL, ERROR and WARNING always. + # Note that the default is set to 1, so account for that. + args.verbose = 40 - (10*args.verbose) if args.verbose > 0 else 0 + + return args + + def run(): """ Run separates prepare and launch for two reasons: 1. I've read somewhere it helps with potential segfault (see comment below) 2. So that prepare can be used in tests, without running the whole thing """ + # Parse command-line arguments. + arguments = process_commandline(sys.argv) + # Initialize logging. (Does not include Qt integration yet.) + manuskript.logging.setUp(console_level=arguments.verbose) + # Need to return and keep `app` otherwise it gets deleted. - app, MW = prepare() + app, MW = prepare(arguments) setup_signal_handlers(MW) # Separating launch to avoid segfault, so it seem. # Cf. http://stackoverflow.com/questions/12433491/is-this-pyqt-4-python-bug-or-wrongly-behaving-code - launch(app, MW) + launch(arguments, app, MW) if __name__ == "__main__": diff --git a/manuskript/tests/__init__.py b/manuskript/tests/__init__.py index 19c56d6..54a0fe1 100644 --- a/manuskript/tests/__init__.py +++ b/manuskript/tests/__init__.py @@ -13,7 +13,8 @@ QApplication([]) # Create app and mainWindow from manuskript import main -app, MW = main.prepare(tests=True) +arguments = main.process_commandline([]) +app, MW = main.prepare(arguments, tests=True) # FIXME: Again, don't know why, but when closing a project and then reopening # one, we get a `TypeError: connection is not unique` in MainWindow: