From b41fb00b0d71008a48d092cb7a7661b8bd173a43 Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Sun, 13 Oct 2019 21:38:53 +0200 Subject: [PATCH 1/9] Several tiny things squashed into one All Models should have only one object managing them, and it is not the class responsible for doing the welcome-related tasks. Small .gitignore update --- .gitignore | 2 ++ manuskript/mainWindow.py | 6 ------ manuskript/ui/welcome.py | 26 +++++++------------------- 3 files changed, 9 insertions(+), 25 deletions(-) diff --git a/.gitignore b/.gitignore index 7f75726..1b14a20 100644 --- a/.gitignore +++ b/.gitignore @@ -12,12 +12,14 @@ .project .pydevproject .settings/org.eclipse.core.resources.prefs +.vscode ExportTest Notes.t2t dist build icons/Numix manuskript/pycallgraph.txt +manuskript.log snowflake* test-projects main.pyproject.user diff --git a/manuskript/mainWindow.py b/manuskript/mainWindow.py index 7e96af2..38d5e4b 100644 --- a/manuskript/mainWindow.py +++ b/manuskript/mainWindow.py @@ -639,7 +639,6 @@ class MainWindow(QMainWindow, Ui_MainWindow): self.mdlCharacter.dataChanged.connect(self.startTimerNoChanges) self.mdlPlots.dataChanged.connect(self.startTimerNoChanges) self.mdlWorld.dataChanged.connect(self.startTimerNoChanges) - # self.mdlPersosInfos.dataChanged.connect(self.startTimerNoChanges) self.mdlStatus.dataChanged.connect(self.startTimerNoChanges) self.mdlLabels.dataChanged.connect(self.startTimerNoChanges) @@ -665,9 +664,6 @@ class MainWindow(QMainWindow, Ui_MainWindow): # Add project name to Window's name self.setWindowTitle(self.projectName() + " - " + self.tr("Manuskript")) - # Stuff - # self.checkPersosID() # Shouldn't be necessary any longer - # Show main Window self.switchToProject() @@ -875,8 +871,6 @@ class MainWindow(QMainWindow, Ui_MainWindow): def loadEmptyDatas(self): self.mdlFlatData = QStandardItemModel(self) self.mdlCharacter = characterModel(self) - # self.mdlPersosProxy = persosProxyModel(self) - # self.mdlPersosInfos = QStandardItemModel(self) self.mdlLabels = QStandardItemModel(self) self.mdlStatus = QStandardItemModel(self) self.mdlPlots = plotModel(self) diff --git a/manuskript/ui/welcome.py b/manuskript/ui/welcome.py index ba2ef53..5d2b90e 100644 --- a/manuskript/ui/welcome.py +++ b/manuskript/ui/welcome.py @@ -422,10 +422,12 @@ class welcome(QWidget, Ui_welcome): self.tree.expandAll() def loadDefaultDatas(self): + """Initialize a basic Manuskript project.""" # Empty settings imp.reload(settings) settings.initDefaultValues() + self.mw.loadEmptyDatas() if self.template: t = [i for i in self._templates if i[0] == self.template[0]] @@ -433,20 +435,10 @@ class welcome(QWidget, Ui_welcome): settings.viewMode = "simple" # Tasks - self.mw.mdlFlatData = QStandardItemModel(2, 8, self.mw) - - # Persos - # self.mw.mdlPersos = QStandardItemModel(0, 0, self.mw) - self.mw.mdlCharacter = characterModel(self.mw) - # self.mdlPersosProxy = None # persosProxyModel() # None - # self.mw.mdlPersosProxy = persosProxyModel(self.mw) - - # self.mw.mdlPersosInfos = QStandardItemModel(1, 0, self.mw) - # self.mw.mdlPersosInfos.insertColumn(0, [QStandardItem("ID")]) - # self.mw.mdlPersosInfos.setHorizontalHeaderLabels(["Description"]) + self.mw.mdlFlatData.setRowCount(2) # data from: infos.txt, summary.txt + self.mw.mdlFlatData.setColumnCount(8) # version_1.py: len(infos.txt) == 8 # Labels - self.mw.mdlLabels = QStandardItemModel(self.mw) for color, text in [ (Qt.transparent, ""), (Qt.yellow, self.tr("Idea")), @@ -458,7 +450,6 @@ class welcome(QWidget, Ui_welcome): self.mw.mdlLabels.appendRow(QStandardItem(iconFromColor(color), text)) # Status - self.mw.mdlStatus = QStandardItemModel(self.mw) for text in [ "", self.tr("TODO"), @@ -468,14 +459,9 @@ class welcome(QWidget, Ui_welcome): ]: self.mw.mdlStatus.appendRow(QStandardItem(text)) - # Plot - self.mw.mdlPlots = plotModel(self.mw) + # Plot (nothing special needed) # Outline - self.mw.mdlOutline = outlineModel(self.mw) - - # World - self.mw.mdlWorld = worldModel(self.mw) root = self.mw.mdlOutline.rootItem _type = "md" @@ -509,3 +495,5 @@ class welcome(QWidget, Ui_welcome): if self.template and self.template[1]: addElement(root, self.template[1]) + + # World (nothing special needed) From 8884bac0ed85d2b9377ab30318400859032be2ba Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Mon, 14 Oct 2019 03:43:17 +0200 Subject: [PATCH 2/9] 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: From ff2cbca028194c0ed3fef5ef9e4de2d211e883ec Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Mon, 14 Oct 2019 14:36:06 +0200 Subject: [PATCH 3/9] Converted most print statements to use logging Some snippets have yet to be converted due to the more complex nature of those snippets, and to keep things neat a separate commit makes more sense for those. --- manuskript/converters/markdownConverter.py | 5 +++- manuskript/converters/pandocConverter.py | 6 +++-- manuskript/exporter/basic.py | 6 +++-- manuskript/exporter/manuskript/plainText.py | 5 +++- manuskript/exporter/pandoc/__init__.py | 6 +++-- manuskript/loadSave.py | 6 +++-- manuskript/load_save/version_0.py | 13 +++++---- manuskript/load_save/version_1.py | 9 ++++--- manuskript/main.py | 14 +++++----- manuskript/mainWindow.py | 23 +++++++++------- manuskript/models/abstractItem.py | 4 ++- manuskript/models/abstractModel.py | 6 +++-- manuskript/models/outlineItem.py | 4 ++- manuskript/models/references.py | 13 +++++---- manuskript/settings.py | 5 +++- manuskript/ui/collapsibleGroupBox.py | 4 ++- manuskript/ui/editors/MDFunctions.py | 4 ++- manuskript/ui/editors/fullScreenEditor.py | 6 +++-- manuskript/ui/editors/mainEditor.py | 4 ++- manuskript/ui/editors/tabSplitter.py | 4 ++- .../ui/highlighters/basicHighlighter.py | 6 +++-- .../ui/highlighters/markdownTokenizer.py | 5 +++- manuskript/ui/views/MDEditView.py | 10 ++++--- manuskript/ui/views/dndView.py | 1 - manuskript/ui/views/propertiesView.py | 4 ++- manuskript/ui/views/textEditView.py | 27 ++++++++++--------- manuskript/ui/welcome.py | 6 +++-- 27 files changed, 133 insertions(+), 73 deletions(-) diff --git a/manuskript/converters/markdownConverter.py b/manuskript/converters/markdownConverter.py index 1b2883a..6d4f2a4 100644 --- a/manuskript/converters/markdownConverter.py +++ b/manuskript/converters/markdownConverter.py @@ -11,6 +11,9 @@ from PyQt5.QtGui import QCursor from manuskript.converters import abstractConverter from manuskript.functions import mainWindow +import logging +LOGGER = logging.getLogger(__name__) + try: import markdown as MD except ImportError: @@ -31,7 +34,7 @@ class markdownConverter(abstractConverter): @classmethod def convert(self, markdown): if not self.isValid: - print("ERROR: markdownConverter is called but not valid.") + LOGGER.error("markdownConverter is called but not valid.") return "" html = MD.markdown(markdown) diff --git a/manuskript/converters/pandocConverter.py b/manuskript/converters/pandocConverter.py index ea91e9a..566c580 100644 --- a/manuskript/converters/pandocConverter.py +++ b/manuskript/converters/pandocConverter.py @@ -11,6 +11,8 @@ from PyQt5.QtGui import QCursor from manuskript.converters import abstractConverter from manuskript.functions import mainWindow +import logging +LOGGER = logging.getLogger(__name__) class pandocConverter(abstractConverter): @@ -38,7 +40,7 @@ class pandocConverter(abstractConverter): @classmethod def convert(self, src, _from="markdown", to="html", args=None, outputfile=None): if not self.isValid: - print("ERROR: pandocConverter is called but not valid.") + LOGGER.error("pandocConverter is called but not valid.") return "" cmd = [self.runCmd()] @@ -70,7 +72,7 @@ class pandocConverter(abstractConverter): if stderr: err = stderr.decode("utf-8") - print(err) + LOGGER.error(err) QMessageBox.critical(mainWindow().dialog, qApp.translate("Export", "Error"), err) return None diff --git a/manuskript/exporter/basic.py b/manuskript/exporter/basic.py index 4fa4ad2..7f02f9c 100644 --- a/manuskript/exporter/basic.py +++ b/manuskript/exporter/basic.py @@ -10,6 +10,8 @@ from PyQt5.QtWidgets import QWidget from manuskript.models import outlineItem from manuskript.functions import mainWindow +import logging +LOGGER = logging.getLogger(__name__) class basicExporter: @@ -58,7 +60,7 @@ class basicExporter: elif self.isValid() == 1: run = self.customPath else: - print("Error: no command for", self.name) + LOGGER.error("No command for %s.", self.name) return None r = subprocess.check_output([run] + args) # timeout=.2 return r.decode("utf-8") @@ -71,7 +73,7 @@ class basicExporter: # try: # output = subprocess.check_output(cmdl, stdin=cmd.stdout, stderr=subprocess.STDOUT) # , cwd="/tmp" # except subprocess.CalledProcessError as e: - # print("Error!") + # LOGGER.error("Failed to read from process output.") # return text # cmd.wait() # diff --git a/manuskript/exporter/manuskript/plainText.py b/manuskript/exporter/manuskript/plainText.py index 4eac456..187e863 100644 --- a/manuskript/exporter/manuskript/plainText.py +++ b/manuskript/exporter/manuskript/plainText.py @@ -10,6 +10,9 @@ from manuskript.models import outlineItem from manuskript.ui.exporters.manuskript.plainTextSettings import exporterSettings import codecs +import logging +LOGGER = logging.getLogger(__name__) + class plainText(basicFormat): name = qApp.translate("Export", "Plain text") description = qApp.translate("Export", """Simplest export to plain text. Allows you to use your own markup not understood @@ -90,7 +93,7 @@ class plainText(basicFormat): content = self.output(settingsWidget) if not content: - print("Error: No content. Nothing saved.") + LOGGER.error("No content. Nothing saved.") return with open(filename, "w", encoding='utf8') as f: diff --git a/manuskript/exporter/pandoc/__init__.py b/manuskript/exporter/pandoc/__init__.py index a920fcb..a9637e9 100644 --- a/manuskript/exporter/pandoc/__init__.py +++ b/manuskript/exporter/pandoc/__init__.py @@ -13,6 +13,8 @@ from manuskript.exporter.pandoc.outputFormats import ePub, OpenDocument, DocX from manuskript.exporter.pandoc.plainText import reST, markdown, latex, OPML from manuskript.functions import mainWindow +import logging +LOGGER = logging.getLogger(__name__) class pandocExporter(basicExporter): @@ -53,7 +55,7 @@ class pandocExporter(basicExporter): elif self.isValid() == 1: run = self.customPath else: - print("Error: no command for pandoc") + LOGGER.error("No command for pandoc.") return None args = [run] + args @@ -101,7 +103,7 @@ class pandocExporter(basicExporter): + "Return code" + ": %d\n" % (p.returncode) \ + "Command and parameters" + ":\n%s\n" % (p.args) \ + "Stderr content" + ":\n" + stderr.decode("utf-8") - print(err) + LOGGER.error(err) QMessageBox.critical(mainWindow().dialog, qApp.translate("Export", "Error"), err) return None diff --git a/manuskript/loadSave.py b/manuskript/loadSave.py index e0d95b2..7657376 100644 --- a/manuskript/loadSave.py +++ b/manuskript/loadSave.py @@ -9,6 +9,8 @@ import zipfile import manuskript.load_save.version_0 as v0 import manuskript.load_save.version_1 as v1 +import logging +LOGGER = logging.getLogger(__name__) def saveProject(version=None): @@ -57,8 +59,8 @@ def loadProject(project): with open(project, "r", encoding="utf-8") as f: version = int(f.read()) - print("Loading:", project) - print("Detected file format version: {}. Zip: {}.".format(version, isZip)) + LOGGER.info("Loading: %s", project) + LOGGER.info("Detected file format version: {}. Zip: {}.".format(version, isZip)) if version == 0: v0.loadProject(project) diff --git a/manuskript/load_save/version_0.py b/manuskript/load_save/version_0.py index e89aa22..a64f851 100644 --- a/manuskript/load_save/version_0.py +++ b/manuskript/load_save/version_0.py @@ -16,6 +16,9 @@ from manuskript import settings from manuskript.functions import iconColor, iconFromColorString, mainWindow from manuskript.models.characterModel import Character, CharacterInfo +import logging +LOGGER = logging.getLogger(__name__) + try: import zlib # Used with zipfile for compression @@ -37,7 +40,7 @@ def saveProject(): files.append((saveStandardItemModelXML(mw.mdlFlatData), "flatModel.xml")) - print("ERROR: file format 0 does not save characters !") + LOGGER.error("File format 0 does not save characters!") # files.append((saveStandardItemModelXML(mw.mdlCharacter), # "perso.xml")) files.append((saveStandardItemModelXML(mw.mdlWorld), @@ -91,7 +94,7 @@ def saveStandardItemModelXML(mdl, xml=None): data = ET.SubElement(root, "data") saveItem(data, mdl) - # print(qApp.tr("Saving to {}.").format(xml)) + # LOGGER.info("Saving to {}.".format(xml)) if xml: ET.ElementTree(root).write(xml, encoding="UTF-8", xml_declaration=True, pretty_print=True) else: @@ -189,13 +192,13 @@ def loadStandardItemModelXML(mdl, xml, fromString=False): """Load data to a QStandardItemModel mdl from xml. By default xml is a filename. If fromString=True, xml is a string containing the data.""" - # print(qApp.tr("Loading {}... ").format(xml), end="") + # LOGGER.info("Loading {}...".format(xml)) if not fromString: try: tree = ET.parse(xml) except: - print("Failed.") + LOGGER.error("Failed to load XML for QStandardItemModel (%s).", xml) return else: root = ET.fromstring(xml) @@ -210,7 +213,7 @@ def loadStandardItemModelXML(mdl, xml, fromString=False): for l in root.find("header").find("vertical").findall("label"): vLabels.append(l.attrib["text"]) - # print(root.find("header").find("vertical").text) + # LOGGER.debug(root.find("header").find("vertical").text) # mdl.setVerticalHeaderLabels(vLabels) # mdl.setHorizontalHeaderLabels(hLabels) diff --git a/manuskript/load_save/version_1.py b/manuskript/load_save/version_1.py index a5e9626..8536eb9 100644 --- a/manuskript/load_save/version_1.py +++ b/manuskript/load_save/version_1.py @@ -26,6 +26,9 @@ from manuskript.load_save.version_0 import loadFilesFromZip from manuskript.models.characterModel import CharacterInfo from manuskript.models import outlineItem +import logging +LOGGER = logging.getLogger(__name__) + try: import zlib # Used with zipfile for compression @@ -125,7 +128,7 @@ def saveProject(zip=None): # Sanity check (see PR-583): make sure we actually have a current project. if project == None: - print("Error: cannot save project because there is no current project in the UI.") + LOGGER.error("Cannot save project because there is no current project in the UI.") return False # File format version @@ -307,7 +310,7 @@ def saveProject(zip=None): # not exist, we check the parent folder, because it might be a new project. if os.path.exists(project) and not os.access(project, os.W_OK) or \ not os.path.exists(project) and not os.access(os.path.dirname(project), os.W_OK): - print("Error: you don't have write access to save this project there.") + LOGGER.error("You don't have write access to save this project there.") return False #################################################################################################################### @@ -924,7 +927,7 @@ def addTextItems(mdl, odict, parent=None): item._lastPath = odict[k + ":lastPath"] elif not ":lastPath" in k and k != "folder.txt": - print("* Strange things in file {}".format(k)) + LOGGER.debug("Strange things in file %s".format(k)) def outlineFromMMD(text, parent): diff --git a/manuskript/main.py b/manuskript/main.py index 3b05544..e9f3a08 100644 --- a/manuskript/main.py +++ b/manuskript/main.py @@ -18,7 +18,7 @@ from manuskript.version import getVersion faulthandler.enable() import logging -logger = logging.getLogger(__name__) +LOGGER = logging.getLogger(__name__) def prepare(arguments, tests=False): app = QApplication(sys.argv) @@ -34,7 +34,7 @@ def prepare(arguments, tests=False): # Handle all sorts of Qt logging messages in Python. manuskript.logging.integrateQtLogging() - logger.info("Running manuskript version {}.".format(getVersion())) + 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))) @@ -57,7 +57,7 @@ def prepare(arguments, tests=False): """Tries to load and activate a given translation for use.""" if appTranslator.load(translation, appPath("i18n")): app.installTranslator(appTranslator) - logger.info("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: @@ -72,7 +72,7 @@ def prepare(arguments, tests=False): # filenames when you observe strange behaviour with the loaded translations. return True else: - logger.info("No translation found or loaded. ({})".format(translation)) + LOGGER.info("No translation found or loaded. ({})".format(translation)) return False def activateTranslation(translation, source): @@ -95,7 +95,7 @@ def prepare(arguments, tests=False): break if using_builtin_translation: - logger.info("Using the builtin translation. (U.S. English)") + LOGGER.info("Using the builtin translation. (U.S. English)") # Load application translation translation = "" @@ -109,7 +109,7 @@ def prepare(arguments, tests=False): translation = QLocale().uiLanguages() source = "available ui languages" - logger.info("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(): @@ -241,6 +241,8 @@ def launch(arguments, app, MW = None): def sigint_handler(sig, MW): def handler(*args): + # Log before winding down to preserve order of cause and effect. + LOGGER.info(f'{sig} received. Quitting...') MW.close() print(f'{sig} received, quit.') diff --git a/manuskript/mainWindow.py b/manuskript/mainWindow.py index 38d5e4b..4352070 100644 --- a/manuskript/mainWindow.py +++ b/manuskript/mainWindow.py @@ -38,6 +38,9 @@ from manuskript.ui.statusLabel import statusLabel from manuskript.ui.views.textEditView import textEditView from manuskript.functions import Spellchecker +import logging +LOGGER = logging.getLogger(__name__) + class MainWindow(QMainWindow, Ui_MainWindow): # dictChanged = pyqtSignal(str) @@ -584,7 +587,7 @@ class MainWindow(QMainWindow, Ui_MainWindow): If ``loadFromFile`` is False, then it does not load datas from file. It assumes that the datas have been populated in a different way.""" if loadFromFile and not os.path.exists(project): - print(self.tr("The file {} does not exist. Has it been moved or deleted?").format(project)) + LOGGER.warning("The file {} does not exist. Has it been moved or deleted?".format(project)) F.statusMessage( self.tr("The file {} does not exist. Has it been moved or deleted?").format(project), importance=3) return @@ -850,7 +853,7 @@ class MainWindow(QMainWindow, Ui_MainWindow): # No UI feedback here as this code path indicates a race condition that happens # after the user has already closed the project through some way. But in that # scenario, this code should not be reachable to begin with. - print("Bug: there is no current project to save.") + LOGGER.error("There is no current project to save.") return r = loadSave.saveProject() # version=0 @@ -861,12 +864,11 @@ class MainWindow(QMainWindow, Ui_MainWindow): feedback = self.tr("Project {} saved.").format(projectName) F.statusMessage(feedback, importance=0) + LOGGER.info("Project {} saved.".format(projectName)) else: feedback = self.tr("WARNING: Project {} not saved.").format(projectName) F.statusMessage(feedback, importance=3) - - # Giving some feedback in console - print(feedback) + LOGGER.warning("Project {} not saved.".format(projectName)) def loadEmptyDatas(self): self.mdlFlatData = QStandardItemModel(self) @@ -883,13 +885,13 @@ class MainWindow(QMainWindow, Ui_MainWindow): # Giving some feedback if not errors: - print(self.tr("Project {} loaded.").format(project)) + LOGGER.info("Project {} loaded.".format(project)) F.statusMessage( self.tr("Project {} loaded.").format(project), 2000) else: - print(self.tr("Project {} loaded with some errors:").format(project)) + LOGGER.error("Project {} loaded with some errors:".format(project)) for e in errors: - print(self.tr(" * {} wasn't found in project file.").format(e)) + LOGGER.error(" * {} wasn't found in project file.".format(e)) F.statusMessage( self.tr("Project {} loaded with some errors.").format(project), 5000, importance = 3) @@ -1525,7 +1527,7 @@ class MainWindow(QMainWindow, Ui_MainWindow): self.menuView.addMenu(self.menuMode) self.menuView.addSeparator() - # print("Generating menus with", settings.viewSettings) + # LOGGER.debug("Generating menus with %s.", settings.viewSettings) for mnu, mnud, icon in menus: m = QMenu(mnu, self.menuView) @@ -1619,7 +1621,8 @@ class MainWindow(QMainWindow, Ui_MainWindow): warning2 = self.tr("PyQt {} and Qt {} are in use.").format(qVersion(), PYQT_VERSION_STR) # Don't translate for debug log. - print("WARNING:", warning1, warning2) + LOGGER.warning(warning1) + LOGGER.warning(warning2) msg = QMessageBox(QMessageBox.Warning, self.tr("Proceed with import at your own risk"), diff --git a/manuskript/models/abstractItem.py b/manuskript/models/abstractItem.py index a6e6096..e481b4d 100644 --- a/manuskript/models/abstractItem.py +++ b/manuskript/models/abstractItem.py @@ -13,6 +13,8 @@ import re from manuskript import enums +import logging +LOGGER = logging.getLogger(__name__) class abstractItem(): @@ -209,7 +211,7 @@ class abstractItem(): self.IDs = self.listAllIDs() if max([self.IDs.count(i) for i in self.IDs if i]) != 1: - print("WARNING ! There are some items with same IDs:", [i for i in self.IDs if i and self.IDs.count(i) != 1]) + LOGGER.warning("There are some items with overlapping IDs: %s", [i for i in self.IDs if i and self.IDs.count(i) != 1]) def checkChildren(item): for c in item.children(): diff --git a/manuskript/models/abstractModel.py b/manuskript/models/abstractModel.py index 828643d..425e0a2 100644 --- a/manuskript/models/abstractModel.py +++ b/manuskript/models/abstractModel.py @@ -26,6 +26,8 @@ except: pass import time, os +import logging +LOGGER = logging.getLogger(__name__) class abstractModel(QAbstractItemModel): """ @@ -74,7 +76,7 @@ class abstractModel(QAbstractItemModel): if len(parent.children()) == 0: return None - # print(item.title(), [i.title() for i in parent.children()]) + #LOGGER.debug("%s: %s", item.title(), [i.title() for i in parent.children()]) row = parent.children().index(item) col = column @@ -168,7 +170,7 @@ class abstractModel(QAbstractItemModel): # self.dataChanged.emit(index.sibling(index.row(), 0), # index.sibling(index.row(), max([i.value for i in Outline]))) - # print("Model emit", index.row(), index.column()) + # LOGGER.debug("Model dataChanged emit: %s, %s", index.row(), index.column()) self.dataChanged.emit(index, index) if index.column() == Outline.type: diff --git a/manuskript/models/outlineItem.py b/manuskript/models/outlineItem.py index 1d80be6..97160aa 100644 --- a/manuskript/models/outlineItem.py +++ b/manuskript/models/outlineItem.py @@ -23,6 +23,8 @@ except: # number formatting pass +import logging +LOGGER = logging.getLogger(__name__) class outlineItem(abstractItem, searchableItem): @@ -382,7 +384,7 @@ class outlineItem(abstractItem, searchableItem): searchIn = character.name() else: searchIn = "" - print("Character POV not found:", self.POV()) + LOGGER.error("Character POV not found: %s", self.POV()) elif c == self.enum.status: searchIn = mainWindow.mdlStatus.item(F.toInt(self.status()), 0).text() diff --git a/manuskript/models/references.py b/manuskript/models/references.py index c54e290..9baa8db 100644 --- a/manuskript/models/references.py +++ b/manuskript/models/references.py @@ -3,6 +3,9 @@ import re +import logging +LOGGER = logging.getLogger(__name__) + ############################################################################### # SHORT REFERENCES ############################################################################### @@ -627,7 +630,7 @@ def open(ref): mw.lstCharacters.setCurrentItem(item) return True - print("Error: Ref {} not found".format(ref)) + LOGGER.error("Character reference {} not found.".format(ref)) return False elif _type == TextLetter: @@ -639,7 +642,7 @@ def open(ref): mw.mainEditor.setCurrentModelIndex(index, newTab=True) return True else: - print("Ref not found") + LOGGER.error("Text reference {} not found.".format(ref)) return False elif _type == PlotLetter: @@ -651,7 +654,7 @@ def open(ref): mw.lstPlots.setCurrentItem(item) return True - print("Ref not found") + LOGGER.error("Plot reference {} not found.".format(ref)) return False elif _type == WorldLetter: @@ -664,8 +667,8 @@ def open(ref): mw.mdlWorld.indexFromItem(item)) return True - print("Ref not found") + LOGGER.error("World reference {} not found.".format(ref)) return False - print("Ref not implemented") + LOGGER.error("Unable to identify reference type: {}.".format(ref)) return False diff --git a/manuskript/settings.py b/manuskript/settings.py index 8f4884e..56eb0ec 100644 --- a/manuskript/settings.py +++ b/manuskript/settings.py @@ -8,6 +8,9 @@ from PyQt5.QtWidgets import qApp from manuskript.enums import Outline +import logging +LOGGER = logging.getLogger(__name__) + # TODO: move some/all of those settings to application settings and not project settings # in order to allow a shared project between several writers @@ -187,7 +190,7 @@ def load(string, fromString=False, protocol=None): allSettings = pickle.load(f) except: - print("{} doesn't exist, cannot load settings.".format(string)) + LOGGER.error("Cannot load settings, {} does not exist.".format(string)) return else: if protocol == 0: diff --git a/manuskript/ui/collapsibleGroupBox.py b/manuskript/ui/collapsibleGroupBox.py index 2b3cc04..e6c1b44 100644 --- a/manuskript/ui/collapsibleGroupBox.py +++ b/manuskript/ui/collapsibleGroupBox.py @@ -6,6 +6,8 @@ from PyQt5.QtWidgets import QSizePolicy, QGroupBox, QWidget, QStylePainter, QSty QStyle, QStyleOptionFrame, QStyleOptionFocusRect from manuskript.ui import style as S +import logging +LOGGER = logging.getLogger(__name__) class collapsibleGroupBox(QGroupBox): def __init__(self, parent=None): @@ -25,7 +27,7 @@ class collapsibleGroupBox(QGroupBox): self.tempWidget.setLayout(self.layout()) # Set empty layout l = QVBoxLayout() - # print(l.contentsMargins().left(), l.contentsMargins().bottom(), l.contentsMargins().top(), ) + # LOGGER.debug("Bounds: %s, %s, %s, %s", l.contentsMargins().left(), l.contentsMargins().bottom(), l.contentsMargins().top(), l.contentsMargins().right()) l.setContentsMargins(0, 0, 0, 0) self.setLayout(l) self.setSizePolicy(QSizePolicy.Preferred, QSizePolicy.Maximum) diff --git a/manuskript/ui/editors/MDFunctions.py b/manuskript/ui/editors/MDFunctions.py index 0fbd8b8..058de34 100644 --- a/manuskript/ui/editors/MDFunctions.py +++ b/manuskript/ui/editors/MDFunctions.py @@ -6,6 +6,8 @@ import re from PyQt5.QtCore import QRegExp from PyQt5.QtGui import QTextCursor +import logging +LOGGER = logging.getLogger(__name__) def MDFormatSelection(editor, style): """ @@ -15,5 +17,5 @@ def MDFormatSelection(editor, style): 1: italic 2: code """ - print("Formatting:", style, " (Unimplemented yet !)") + LOGGER.error("Formatting: %s (Not implemented!)", style) # FIXME \ No newline at end of file diff --git a/manuskript/ui/editors/fullScreenEditor.py b/manuskript/ui/editors/fullScreenEditor.py index 42941f9..5c7200d 100644 --- a/manuskript/ui/editors/fullScreenEditor.py +++ b/manuskript/ui/editors/fullScreenEditor.py @@ -19,6 +19,8 @@ from manuskript.ui.editors.themes import loadThemeDatas from manuskript.ui.views.MDEditView import MDEditView from manuskript.functions import Spellchecker +import logging +LOGGER = logging.getLogger(__name__) class fullScreenEditor(QWidget): def __init__(self, index, parent=None, screenNumber=None): @@ -177,7 +179,7 @@ class fullScreenEditor(QWidget): # self.show() def __del__(self): - # print("Leaving fullScreenEditor via Destructor event", flush=True) + LOGGER.debug("Leaving fullScreenEditor via Destructor event.") self.showNormal() self.close() @@ -286,7 +288,7 @@ class fullScreenEditor(QWidget): def keyPressEvent(self, event): if event.key() in [Qt.Key_Escape, Qt.Key_F11] and \ not self._locked: - # print("Leaving fullScreenEditor via keyPressEvent", flush=True) + LOGGER.debug("Leaving fullScreenEditor via keyPressEvent.") self.showNormal() self.close() elif (event.modifiers() & Qt.AltModifier) and \ diff --git a/manuskript/ui/editors/mainEditor.py b/manuskript/ui/editors/mainEditor.py index d8a5c67..8cc6453 100644 --- a/manuskript/ui/editors/mainEditor.py +++ b/manuskript/ui/editors/mainEditor.py @@ -20,6 +20,9 @@ try: except: pass +import logging +LOGGER = logging.getLogger(__name__) + class mainEditor(QWidget, Ui_mainEditor): """ `mainEditor` is responsible for opening `outlineItem`s and offering information @@ -389,7 +392,6 @@ class mainEditor(QWidget, Ui_mainEditor): ############################################################################### def setDict(self, dict): - print(dict) for w in self.allAllTabs(): w.setDict(dict) diff --git a/manuskript/ui/editors/tabSplitter.py b/manuskript/ui/editors/tabSplitter.py index 0ba8750..d6f4ff3 100644 --- a/manuskript/ui/editors/tabSplitter.py +++ b/manuskript/ui/editors/tabSplitter.py @@ -10,6 +10,8 @@ from manuskript.functions import mainWindow, appPath from manuskript.ui import style from manuskript.ui.editors.tabSplitter_ui import Ui_tabSplitter +import logging +LOGGER = logging.getLogger(__name__) class tabSplitter(QWidget, Ui_tabSplitter): """ @@ -39,7 +41,7 @@ class tabSplitter(QWidget, Ui_tabSplitter): # try: # self.tab.setTabBarAutoHide(True) # except AttributeError: - # print("Info: install Qt 5.4 or higher to use tab bar auto-hide in editor.") + # LOGGER.info("Install Qt 5.4 or higher to use tab bar auto-hide in editor.") # Button to split self.btnSplit = QPushButton(self) diff --git a/manuskript/ui/highlighters/basicHighlighter.py b/manuskript/ui/highlighters/basicHighlighter.py index 17ae8bd..2e7358e 100644 --- a/manuskript/ui/highlighters/basicHighlighter.py +++ b/manuskript/ui/highlighters/basicHighlighter.py @@ -12,6 +12,8 @@ import manuskript.ui.style as S from manuskript import settings from manuskript import functions as F +import logging +LOGGER = logging.getLogger(__name__) class BasicHighlighter(QSyntaxHighlighter): def __init__(self, editor): @@ -130,14 +132,14 @@ class BasicHighlighter(QSyntaxHighlighter): before you do any custom highlighting. Or implement doHighlightBlock. """ - #print(">", self.currentBlock().document().availableUndoSteps()) + #LOGGER.debug("undoSteps before: %s", self.currentBlock().document().availableUndoSteps()) c = QTextCursor(self.currentBlock()) #c.joinPreviousEditBlock() bf = QTextBlockFormat(self._defaultBlockFormat) if bf != c.blockFormat(): c.setBlockFormat(bf) #c.endEditBlock() - #print(" ", self.currentBlock().document().availableUndoSteps()) + #LOGGER.debug("undoSteps after: %s", self.currentBlock().document().availableUndoSteps()) # self.setFormat(0, len(text), self._defaultCharFormat) diff --git a/manuskript/ui/highlighters/markdownTokenizer.py b/manuskript/ui/highlighters/markdownTokenizer.py index 9bae886..237b18e 100644 --- a/manuskript/ui/highlighters/markdownTokenizer.py +++ b/manuskript/ui/highlighters/markdownTokenizer.py @@ -9,6 +9,9 @@ from PyQt5.QtWidgets import * from manuskript.ui.highlighters import MarkdownState as MS from manuskript.ui.highlighters import MarkdownTokenType as MTT +import logging +LOGGER = logging.getLogger(__name__) + # This file is simply a python translation of GhostWriter's Tokenizer. # http://wereturtle.github.io/ghostwriter/ # GPLV3+. @@ -56,7 +59,7 @@ class HighlightTokenizer: self.tokens.append(token) if token.type == -1: - print("Error here", token.position, token.length) + LOGGER.error("Token type invalid: position %s, length %s.", token.position, token.length) def setState(self, state): self.state = state diff --git a/manuskript/ui/views/MDEditView.py b/manuskript/ui/views/MDEditView.py index c5f4c33..dcd5e3a 100644 --- a/manuskript/ui/views/MDEditView.py +++ b/manuskript/ui/views/MDEditView.py @@ -14,6 +14,8 @@ from manuskript.ui.highlighters.markdownEnums import MarkdownState as MS from manuskript.ui.highlighters.markdownTokenizer import MarkdownTokenizer as MT from manuskript import functions as F +import logging +LOGGER = logging.getLogger(__name__) class MDEditView(textEditView): @@ -660,10 +662,10 @@ class ImageTooltip: return else: # Somehow we lost track. Log what we can to hopefully figure it out. - print("Warning: unable to match fetched data for tooltip to original request.") - print("- Completed request:", url_key) - print("- Status upon finishing:", reply.error(), reply.errorString()) - print("- Currently processing:", ImageTooltip.processing) + LOGGER.warning("Unable to match fetched data for tooltip to original request.") + LOGGER.warning("- Completed request: %s", url_key) + LOGGER.warning("- Status upon finishing: %s, %s", reply.error(), reply.errorString()) + LOGGER.warning("- Currently processing: %s", ImageTooltip.processing) return # Update cache with retrieved data. diff --git a/manuskript/ui/views/dndView.py b/manuskript/ui/views/dndView.py index c028964..b2abf08 100644 --- a/manuskript/ui/views/dndView.py +++ b/manuskript/ui/views/dndView.py @@ -13,7 +13,6 @@ class dndView(QAbstractItemView): def dragMoveEvent(self, event): # return QAbstractItemView.dragMoveEvent(self, event) - # print(a) if event.keyboardModifiers() & Qt.ControlModifier: event.setDropAction(Qt.CopyAction) else: diff --git a/manuskript/ui/views/propertiesView.py b/manuskript/ui/views/propertiesView.py index 2ae088d..0c5f95b 100644 --- a/manuskript/ui/views/propertiesView.py +++ b/manuskript/ui/views/propertiesView.py @@ -7,6 +7,8 @@ from manuskript.enums import Outline from manuskript.ui.views.propertiesView_ui import Ui_propertiesView from manuskript.models.characterPOVModel import characterPOVModel +import logging +LOGGER = logging.getLogger(__name__) class propertiesView(QWidget, Ui_propertiesView): def __init__(self, parent=None): @@ -39,7 +41,7 @@ class propertiesView(QWidget, Ui_propertiesView): def selectionChanged(self, sourceView): indexes = self.getIndexes(sourceView) - # print(indexes) + # LOGGER.debug("selectionChanged indexes: %s", indexes) if len(indexes) == 0: self.setEnabled(False) diff --git a/manuskript/ui/views/textEditView.py b/manuskript/ui/views/textEditView.py index b361bdf..b4f07e9 100644 --- a/manuskript/ui/views/textEditView.py +++ b/manuskript/ui/views/textEditView.py @@ -17,6 +17,9 @@ from manuskript.functions import Spellchecker from manuskript.models.characterModel import Character, CharacterInfo +import logging +LOGGER = logging.getLogger(__name__) + class textEditView(QTextEdit): def __init__(self, parent=None, index=None, html=None, spellcheck=None, highlighting=False, dict="", autoResize=False): @@ -58,13 +61,13 @@ class textEditView(QTextEdit): self.updateTimer.setInterval(500) self.updateTimer.setSingleShot(True) self.updateTimer.timeout.connect(self.submit) - # self.updateTimer.timeout.connect(lambda: print("Timeout")) + # self.updateTimer.timeout.connect(lambda: LOGGER.debug("Timeout.")) self.updateTimer.stop() self.document().contentsChanged.connect(self.updateTimer.start, F.AUC) - # self.document().contentsChanged.connect(lambda: print("Document changed")) + # self.document().contentsChanged.connect(lambda: LOGGER.debug("Document changed.")) - # self.document().contentsChanged.connect(lambda: print(self.objectName(), "Contents changed")) + # self.document().contentsChanged.connect(lambda: LOGGER.debug("Contents changed: %s", self.objectName())) self.setEnabled(False) @@ -248,7 +251,7 @@ class textEditView(QTextEdit): if topLeft.parent() != self._index.parent(): return - # print("Model changed: ({}:{}), ({}:{}/{}), ({}:{}) for {} of {}".format( + # LOGGER.debug("Model changed: ({}:{}), ({}:{}/{}), ({}:{}) for {} of {}".format( # topLeft.row(), topLeft.column(), # self._index.row(), self._index.row(), self._column, # bottomRight.row(), bottomRight.column(), @@ -278,11 +281,11 @@ class textEditView(QTextEdit): def updateText(self): self._updating.lock() - # print("Updating", self.objectName()) + # LOGGER.debug("Updating %s", self.objectName()) if self._index: self.disconnectDocument() if self.toPlainText() != F.toString(self._index.data()): - # print(" Updating plaintext") + # LOGGER.debug(" Updating plaintext") self.document().setPlainText(F.toString(self._index.data())) self.reconnectDocument() @@ -319,18 +322,18 @@ class textEditView(QTextEdit): text = self.toPlainText() self._updating.unlock() - # print("Submitting", self.objectName()) + # LOGGER.debug("Submitting %s", self.objectName()) if self._index and self._index.isValid(): # item = self._index.internalPointer() if text != self._index.data(): - # print(" Submitting plain text") + # LOGGER.debug(" Submitting plain text") self._model.setData(QModelIndex(self._index), text) elif self._indexes: for i in self._indexes: item = i.internalPointer() if text != F.toString(item.data(self._column)): - print("Submitting many indexes") + LOGGER.debug("Submitting many indexes") self._model.setData(i, text) def keyPressEvent(self, event): @@ -484,7 +487,7 @@ class textEditView(QTextEdit): def newCharacter(self): text = self.sender().data() - print("new character!", text) + LOGGER.debug(f'New character: {text}') # switch to character page mw = F.mainWindow() mw.tabMain.setCurrentIndex(mw.TabPersos) @@ -496,7 +499,7 @@ class textEditView(QTextEdit): def newPlotItem(self): text = self.sender().data() - print("new plot item!", text) + LOGGER.debug(f'New plot item: {text}') # switch to plot page mw = F.mainWindow() mw.tabMain.setCurrentIndex(mw.TabPlots) @@ -509,7 +512,7 @@ class textEditView(QTextEdit): def newWorldItem(self): text = self.sender().data() - print("new world item!", text) + LOGGER.debug(f'New world item: {text}') mw = F.mainWindow() mw.tabMain.setCurrentIndex(mw.TabWorld) item = mw.mdlWorld.addItem(title=text) diff --git a/manuskript/ui/welcome.py b/manuskript/ui/welcome.py index 5d2b90e..c612253 100644 --- a/manuskript/ui/welcome.py +++ b/manuskript/ui/welcome.py @@ -21,6 +21,9 @@ from manuskript.models.worldModel import worldModel from manuskript.ui.welcome_ui import Ui_welcome from manuskript.ui import style as S +import logging +LOGGER = logging.getLogger(__name__) + try: locale.setlocale(locale.LC_ALL, '') except: @@ -57,8 +60,7 @@ class welcome(QWidget, Ui_welcome): sttgs = QSettings() lastDirectory = sttgs.value("lastAccessedDirectory", defaultValue=".", type=str) if lastDirectory != '.': - print(qApp.translate("lastAccessedDirectoryInfo", "Last accessed directory \"{}\" loaded.").format( - lastDirectory)) + LOGGER.info("Last accessed directory \"{}\" loaded.".format(lastDirectory)) return lastDirectory def setLastAccessedDirectory(self, dir): From 37becdf80a1bf0cbfa3cb65c5ffbadbb2b606b49 Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Mon, 14 Oct 2019 14:56:55 +0200 Subject: [PATCH 4/9] Converted version_1.py to new logging style It had its own mini-logging facility to suppress the most useless debug messages. Since the new facility does not show debug messages to the user, but still allows them to end up in the log file, I replaced it entirely with DEBUG-level logging. Some spots have received an extra ERROR-level logging on top for the sake of alerting the user to issues we would like to hear about, and to avoid breaking up the hierarchical indenting done by the DEBUG-level messages. --- manuskript/load_save/version_1.py | 65 ++++++++++++++----------------- 1 file changed, 30 insertions(+), 35 deletions(-) diff --git a/manuskript/load_save/version_1.py b/manuskript/load_save/version_1.py index 8536eb9..39f1b7d 100644 --- a/manuskript/load_save/version_1.py +++ b/manuskript/load_save/version_1.py @@ -54,8 +54,6 @@ characterMap = OrderedDict([ (Character.notes, "Notes") ]) -# If true, logs infos while saving and loading. -LOG = False def formatMetaData(name, value, tabLength=10): @@ -95,11 +93,6 @@ def slugify(name): return newName -def log(*args): - if LOG: - print(" ".join(str(a) for a in args)) - - def saveProject(zip=None): """ Saves the project. If zip is False, the project is saved as a multitude of plain-text files for the most parts @@ -113,7 +106,7 @@ def saveProject(zip=None): if zip == None: zip = settings.saveToZip - log("\n\nSaving to:", "zip" if zip else "folder") + LOGGER.info("Saving to: %s", "zip" if zip else "folder") # List of files to be written files = [] @@ -344,7 +337,7 @@ def saveProject(zip=None): folder = os.path.splitext(os.path.basename(project))[0] # Debug - log("\nSaving to folder", folder) + LOGGER.debug("Saving to folder %s", folder) # If cache is empty (meaning we haven't loaded from disk), we wipe folder, just to be sure. if not cache: @@ -361,7 +354,7 @@ def saveProject(zip=None): # Move the old file to the new place try: os.replace(oldPath, newPath) - log("* Renaming/moving {} to {}".format(old, new)) + LOGGER.debug("* Renaming/moving {} to {}".format(old, new)) except FileNotFoundError: # Maybe parent folder has been renamed pass @@ -371,7 +364,7 @@ def saveProject(zip=None): for f in cache: f2 = f.replace(old, new) if f2 != f: - log(" * Updating cache:", f, f2) + LOGGER.debug(" * Updating cache: %s, %s", f, f2) cache2[f2] = cache[f] cache = cache2 @@ -382,7 +375,7 @@ def saveProject(zip=None): # Check if content is in cache, and write if necessary if path not in cache or cache[path] != content: - log("* Writing file {} ({})".format(path, "not in cache" if path not in cache else "different")) + LOGGER.debug("* Writing file {} ({})".format(path, "not in cache" if path not in cache else "different")) # mode = "w" + ("b" if type(content) == bytes else "") if type(content) == bytes: with open(filename, "wb") as f: @@ -396,7 +389,7 @@ def saveProject(zip=None): # Removing phantoms for path in [p for p in cache if p not in [p for p, c in files]]: filename = os.path.join(dir, folder, path) - log("* Removing", path) + LOGGER.debug("* Removing %s", path) if os.path.isdir(filename): shutil.rmtree(filename) @@ -413,7 +406,7 @@ def saveProject(zip=None): newDir = os.path.join(root, dir) try: os.removedirs(newDir) - log("* Removing empty directory:", newDir) + LOGGER.debug("* Removing empty directory: %s", newDir) except: # Directory not empty, we don't remove. pass @@ -539,8 +532,8 @@ def exportOutlineItem(root): lp = child._lastPath if lp and spath != lp: moves.append((lp, spath)) - log(child.title(), "has been renamed (", lp, " → ", spath, ")") - log(" → We mark for moving:", lp) + LOGGER.debug("%s has been renamed (%s → %s)", child.title(), lp, spath) + LOGGER.debug(" → We mark for moving: %s", lp) # Updates item last's path child._lastPath = spath @@ -556,7 +549,7 @@ def exportOutlineItem(root): files.append((spath, content)) else: - log("Unknown type") + LOGGER.debug("Unknown type: %s", child.type()) f, m, r = exportOutlineItem(child) files += f @@ -634,7 +627,7 @@ def loadProject(project, zip=None): #################################################################################################################### # Read and store everything in a dict - log("\nLoading {} ({})".format(project, "ZIP" if zip else "not zip")) + LOGGER.debug("Loading {} ({})".format(project, "zip" if zip else "folder")) if zip: files = loadFilesFromZip(project) @@ -698,7 +691,7 @@ def loadProject(project, zip=None): mdl = mw.mdlLabels mdl.appendRow(QStandardItem("")) # Empty = No labels if "labels.txt" in files: - log("\nReading labels:") + LOGGER.debug("Reading labels:") for s in files["labels.txt"].split("\n"): if not s: continue @@ -706,7 +699,7 @@ def loadProject(project, zip=None): m = re.search(r"^(.*?):\s*(.*)$", s) txt = m.group(1) col = m.group(2) - log("* Add status: {} ({})".format(txt, col)) + LOGGER.debug("* Add status: {} ({})".format(txt, col)) icon = iconFromColorString(col) mdl.appendRow(QStandardItem(icon, txt)) @@ -719,11 +712,11 @@ def loadProject(project, zip=None): mdl = mw.mdlStatus mdl.appendRow(QStandardItem("")) # Empty = No status if "status.txt" in files: - log("\nReading Status:") + LOGGER.debug("Reading status:") for s in files["status.txt"].split("\n"): if not s: continue - log("* Add status:", s) + LOGGER.debug("* Add status: %s", s) mdl.appendRow(QStandardItem(s)) else: errors.append("status.txt") @@ -765,7 +758,7 @@ def loadProject(project, zip=None): mdl = mw.mdlPlots if "plots.xml" in files: - log("\nReading plots:") + LOGGER.debug("Reading plots:") # xml = bytearray(files["plots.xml"], "utf-8") root = ET.fromstring(files["plots.xml"]) @@ -774,7 +767,7 @@ def loadProject(project, zip=None): row = getStandardItemRowFromXMLEnum(plot, Plot) # Log - log("* Add plot: ", row[0].text()) + LOGGER.debug("* Add plot: %s", row[0].text()) # Characters if row[Plot.characters].text(): @@ -801,7 +794,7 @@ def loadProject(project, zip=None): mdl = mw.mdlWorld if "world.opml" in files: - log("\nReading World:") + LOGGER.debug("Reading World:") # xml = bytearray(files["plots.xml"], "utf-8") root = ET.fromstring(files["world.opml"]) body = root.find("body") @@ -817,7 +810,7 @@ def loadProject(project, zip=None): # Characters mdl = mw.mdlCharacter - log("\nReading Characters:") + LOGGER.debug("Reading Characters:") for f in [f for f in files if "characters" in f]: md, body = parseMMDFile(files[f]) c = mdl.addCharacter() @@ -843,7 +836,7 @@ def loadProject(project, zip=None): else: c.infos.append(CharacterInfo(c, desc, val)) - log("* Adds {} ({})".format(c.name(), c.ID())) + LOGGER.debug("* Adds {} ({})".format(c.name(), c.ID())) #################################################################################################################### # Texts @@ -851,14 +844,14 @@ def loadProject(project, zip=None): # everything, but the outline folder takes precedence (in cases it's been edited outside of manuskript. mdl = mw.mdlOutline - log("\nReading outline:") + LOGGER.debug("Reading outline:") paths = [f for f in files if "outline" in f] outline = OrderedDict() # We create a structure of imbricated OrderedDict to store the whole tree. for f in paths: split = f.split(os.path.sep)[1:] - # log("* ", split) + # LOGGER.debug("* %s", split) last = "" parent = outline @@ -913,7 +906,7 @@ def addTextItems(mdl, odict, parent=None): if type(odict[k]) == OrderedDict and "folder.txt" in odict[k]: # Adds folder - log("{}* Adds {} to {} (folder)".format(" " * parent.level(), k, parent.title())) + LOGGER.debug("{}* Adds {} to {} (folder)".format(" " * parent.level(), k, parent.title())) item = outlineFromMMD(odict[k]["folder.txt"], parent=parent) item._lastPath = odict[k + ":lastPath"] @@ -922,7 +915,7 @@ def addTextItems(mdl, odict, parent=None): # k is not a folder elif type(odict[k]) == str and k != "folder.txt" and not ":lastPath" in k: - log("{}* Adds {} to {} (file)".format(" " * parent.level(), k, parent.title())) + LOGGER.debug("{}* Adds {} to {} (file)".format(" " * parent.level(), k, parent.title())) item = outlineFromMMD(odict[k], parent=parent) item._lastPath = odict[k + ":lastPath"] @@ -977,17 +970,19 @@ def appendRevisions(mdl, root): # Get root's ID ID = root.attrib["ID"] if not ID: - log("* Serious problem: no ID!") + LOGGER.debug("* Serious problem: no ID!") + LOGGER.error("Revision has no ID associated!") continue # Find outline item in model item = mdl.getItemByID(ID) if not item: - log("* Error: no item whose ID is", ID) + LOGGER.debug("* Error: no item whose ID is %s", ID) + LOGGER.error("Could not identify the item matching the revision ID.") continue # Store revision - log("* Appends revision ({}) to {}".format(child.attrib["timestamp"], item.title())) + LOGGER.debug("* Appends revision ({}) to {}".format(child.attrib["timestamp"], item.title())) item.appendRevision(child.attrib["timestamp"], child.attrib["text"]) @@ -999,7 +994,7 @@ def getOutlineItem(item, enum): @return: [QStandardItem] """ row = getStandardItemRowFromXMLEnum(item, enum) - log("* Add worldItem:", row[0].text()) + LOGGER.debug("* Add worldItem: %s", row[0].text()) for child in item: sub = getOutlineItem(child, enum) row[0].appendRow(sub) From 239e66e7cb98efe178f4ead1ae83212e57cb24ca Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Mon, 14 Oct 2019 20:16:07 +0200 Subject: [PATCH 5/9] Comprehensively log all version information Manuskript now logs the versions of modules and libraries powering them for as far those are easily accessible. This includes all the optional modules, too. None of this is visible on the terminal of course - unless Manuskript is run with the --verbose flag. This clears up the last bit of unnecessary console spam, leaving our users blissfully unaware. Until we (and/or Qt) break something again, that is... --- manuskript/logging.py | 122 +++++++++++++++++++++++++++++++-- manuskript/main.py | 5 +- manuskript/ui/views/webView.py | 3 - 3 files changed, 118 insertions(+), 12 deletions(-) diff --git a/manuskript/logging.py b/manuskript/logging.py index 56e5bf2..1561463 100644 --- a/manuskript/logging.py +++ b/manuskript/logging.py @@ -4,15 +4,17 @@ # 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 +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" -logger = logging.getLogger(__name__) - def setUp(console_level=logging.WARN): """Sets up a convenient environment for logging. @@ -37,7 +39,7 @@ def setUp(console_level=logging.WARN): ch.setFormatter(logging.Formatter(LOGFORMAT_CONSOLE)) root_logger.addHandler(ch) - logger.debug("Logging to STDERR.") + LOGGER.debug("Logging to STDERR.") def logToFile(file_level=logging.DEBUG, logfile=None): @@ -65,9 +67,9 @@ def logToFile(file_level=logging.DEBUG, logfile=None): root_logger.addHandler(fh) # Use INFO level to make it easier to find for users. - logger.info("Logging to file: %s", logfile) + LOGGER.info("Logging to file: %s", logfile) except Exception as ex: - logger.warning("Cannot log to file '%s'. Reason: %s", logfile, 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. @@ -103,4 +105,110 @@ def integrateQtLogging(): # 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 + 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 + +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.version import getVersion + logger.info("Manuskript %s (Python %s)", getVersion(), 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. diff --git a/manuskript/main.py b/manuskript/main.py index e9f3a08..c3aeb25 100644 --- a/manuskript/main.py +++ b/manuskript/main.py @@ -7,7 +7,6 @@ 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 from PyQt5.QtWidgets import QApplication, qApp, QStyleFactory @@ -34,7 +33,9 @@ def prepare(arguments, tests=False): # Handle all sorts of Qt logging messages in Python. manuskript.logging.integrateQtLogging() - LOGGER.info("Running manuskript version {}.".format(getVersion())) + # Log all the versions for less headaches. + manuskript.logging.logVersionInformation() + icon = QIcon() for i in [16, 32, 64, 128, 256, 512]: icon.addFile(appPath("icons/Manuskript/icon-{}px.png".format(i))) diff --git a/manuskript/ui/views/webView.py b/manuskript/ui/views/webView.py index 4d6462c..23e09d1 100644 --- a/manuskript/ui/views/webView.py +++ b/manuskript/ui/views/webView.py @@ -22,16 +22,13 @@ else: if features['qtwebkit']: from PyQt5.QtWebKitWidgets import QWebView - print("Debug: Web rendering engine used: QWebView") webEngine = "QtWebKit" webView = QWebView elif features['qtwebengine']: from PyQt5 import QtWebEngineWidgets - print("Debug: Web rendering engine used: QWebEngineView") webEngine = "QtWebEngine" webView = QtWebEngineWidgets.QWebEngineView else: from PyQt5.QtWidgets import QTextEdit - print("Debug: Web rendering engine used: QTextEdit") webEngine = "QTextEdit" webView = QTextEdit From c797b5a18b2d459d0e7f310fbb6180d86b2f896f Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Tue, 15 Oct 2019 14:32:07 +0200 Subject: [PATCH 6/9] Log the git revision if applicable During development, the version number does not have much meaning... but when faced with a reported issue, you would still like to know in more detail what version of the Manuskript code was at work there. Knowing the exact git revision will hopefully make it easier to troubleshoot such issues in the future. Note: this code takes special care to not rely on external modules (we have enough dependencies) or even the git executable (invoking a program can be relatively slow on some operating systems). It might not handle all the edge cases, but I think it should cover our needs well enough. --- manuskript/functions/__init__.py | 47 ++++++++++++++++++++++++++++++++ manuskript/logging.py | 7 ++++- 2 files changed, 53 insertions(+), 1 deletion(-) diff --git a/manuskript/functions/__init__.py b/manuskript/functions/__init__.py index 4acae75..7e4edd6 100644 --- a/manuskript/functions/__init__.py +++ b/manuskript/functions/__init__.py @@ -3,6 +3,8 @@ import os import re +import sys +import pathlib from random import * from PyQt5.QtCore import Qt, QRect, QStandardPaths, QObject, QRegExp, QDir @@ -13,6 +15,9 @@ from PyQt5.QtWidgets import qApp, QFileDialog from manuskript.enums import Outline +import logging +LOGGER = logging.getLogger(__name__) + # Used to detect multiple connections AUC = Qt.AutoConnection | Qt.UniqueConnection MW = None @@ -493,5 +498,47 @@ def getSearchResultContext(text, startPos, endPos): return context + +# Based on answer by jfs at: +# https://stackoverflow.com/questions/3718657/how-to-properly-determine-current-script-directory +def getManuskriptPath(follow_symlinks=True): + """Used to obtain the path Manuskript is located at.""" + if getattr(sys, 'frozen', False): # py2exe, PyInstaller, cx_Freeze + path = os.path.abspath(sys.executable) + else: + import inspect + path = inspect.getabsfile(getManuskriptPath) + "/../.." + if follow_symlinks: + path = os.path.realpath(path) + return os.path.dirname(path) + +# Based on answer by kagronik at: +# https://stackoverflow.com/questions/14989858/get-the-current-git-hash-in-a-python-script +def getGitRevision(base_path): + """Get git revision without relying on external processes or libraries.""" + git_dir = pathlib.Path(base_path) / '.git' + if not git_dir.exists(): + return None + + with (git_dir / 'HEAD').open('r') as head: + ref = head.readline().split(' ')[-1].strip() + + with (git_dir / ref).open('r') as git_hash: + return git_hash.readline().strip() + +def getGitRevisionAsString(base_path, short=False): + """Catches errors and presents a nice string.""" + try: + rev = getGitRevision(base_path) + if rev is not None: + if short: + rev = rev[:7] + return "#" + rev + else: + return "" # not a git repository + except Exception as e: + LOGGER.warning("Failed to obtain Git revision: %s", e) + return "#ERROR" + # Spellchecker loads writablePath from this file, so we need to load it after they get defined from manuskript.functions.spellchecker import Spellchecker diff --git a/manuskript/logging.py b/manuskript/logging.py index 1561463..5c33b9a 100644 --- a/manuskript/logging.py +++ b/manuskript/logging.py @@ -157,6 +157,8 @@ def attributesFromOptionalModule(module, *attributes): # 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. @@ -174,8 +176,11 @@ def logVersionInformation(logger=None): 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 (Python %s)", getVersion(), python_version()) + logger.info("Manuskript %s%s (Python %s)", getVersion(), + getGitRevisionAsString(getManuskriptPath(), short=True), + python_version()) # Installed Python packages. From 091024689937939cab363776cadfa2a29df14153 Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Sat, 19 Oct 2019 00:38:27 +0200 Subject: [PATCH 7/9] Write log file in UTF-8 to fix encoding errors Some log messages use characters in the Unicode character set that aren't typically represented in the older encodings. One such example was the messages that happen when renaming an item and saving the project. Positive note though: errors while logging might not end up in the log file when the log file is the cause, but they still showed on the terminal with excessive detail. Also, despite the exceptions and errors, the project I was testing successfully completed its saving procedures as a subsequent reload showed. I am personally quite happy with the degree of thought and care put into the Python logging system. :-) --- manuskript/logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/manuskript/logging.py b/manuskript/logging.py index 5c33b9a..69d0963 100644 --- a/manuskript/logging.py +++ b/manuskript/logging.py @@ -59,7 +59,7 @@ def logToFile(file_level=logging.DEBUG, logfile=None): # log files may not be in our users best interest for the time # being. (Unfortunately.) try: - fh = logging.FileHandler(logfile, mode='w') + fh = logging.FileHandler(logfile, mode='w', encoding='utf-8') fh.setLevel(file_level) fh.setFormatter(logging.Formatter(LOGFORMAT_FILE)) From 5117f7d47621b248c9e503e8cb607cd7894c9422 Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Sat, 2 Nov 2019 15:32:31 +0100 Subject: [PATCH 8/9] 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 69d0963..6ae492d 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 From 2d622792f382caa4b1b12962b02a2aa8f0f6bee3 Mon Sep 17 00:00:00 2001 From: Jan Wester Date: Mon, 4 Nov 2019 14:35:21 +0100 Subject: [PATCH 9/9] Additional logging centered around sys module Due to my struggles reproducing the official build, I felt it might be useful to log extra information regarding the version of PyInstaller. Unfortunately, such information is not available due to the way things work. However, during that process I came across some other interesting details that would likely be useful when logged. --- manuskript/logging.py | 29 ++++++++++++++++++++++++++--- manuskript/main.py | 2 +- 2 files changed, 27 insertions(+), 4 deletions(-) diff --git a/manuskript/logging.py b/manuskript/logging.py index 6ae492d..b0218d6 100644 --- a/manuskript/logging.py +++ b/manuskript/logging.py @@ -7,9 +7,11 @@ import os import sys import logging +import pathlib from manuskript.functions import writablePath from importlib import import_module +from pprint import pformat LOGGER = logging.getLogger(__name__) @@ -223,9 +225,7 @@ def attributesFromOptionalModule(module, *attributes): # The list is consumed as a part of the unpacking syntax. return v -import pathlib - -def logVersionInformation(logger=None): +def logRuntimeInformation(logger=None): """Logs all important runtime information neatly together. Due to the generic nature, use the manuskript logger by default.""" @@ -241,6 +241,29 @@ def logVersionInformation(logger=None): logger.info("Operating System: %s", platform()) logger.info("Hardware: %s / %s", machine(), processor()) + # 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)) + # Manuskript and Python info. from manuskript.functions import getGitRevisionAsString, getManuskriptPath from manuskript.version import getVersion diff --git a/manuskript/main.py b/manuskript/main.py index c3aeb25..c4d5bb6 100644 --- a/manuskript/main.py +++ b/manuskript/main.py @@ -34,7 +34,7 @@ def prepare(arguments, tests=False): manuskript.logging.integrateQtLogging() # Log all the versions for less headaches. - manuskript.logging.logVersionInformation() + manuskript.logging.logRuntimeInformation() icon = QIcon() for i in [16, 32, 64, 128, 256, 512]: