Merge pull request #667 from worstje/arguments-and-logging

Logging and command-line arguments

.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

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)

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

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()
         #

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:

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
 

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

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)
+    LOGGER.info("Loading: %s", project)
-    print("Detected file format version: {}. Zip: {}.".format(version, isZip))
+    LOGGER.info("Detected file format version: {}. Zip: {}.".format(version, isZip))
 
     if version == 0:
         v0.loadProject(project)

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)

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
 
@@ -51,8 +54,6 @@ characterMap = OrderedDict([
     (Character.notes, "Notes")
 ])
 
-# If true, logs infos while saving and loading.
-LOG = False
 
 def formatMetaData(name, value, tabLength=10):
 
@@ -92,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
@@ -110,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 = []
@@ -125,7 +121,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 +303,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
 
     ####################################################################################################################
@@ -341,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:
@@ -358,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
@@ -368,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
 
@@ -379,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:
@@ -393,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)
@@ -410,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
@@ -536,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, ")")
+            LOGGER.debug("%s has been renamed (%s → %s)", child.title(), lp,  spath)
-            log(" → We mark for moving:", lp)
+            LOGGER.debug(" → We mark for moving: %s", lp)
 
         # Updates item last's path
         child._lastPath = spath
@@ -553,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
@@ -631,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)
 
@@ -695,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
@@ -703,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))
 
@@ -716,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")
@@ -762,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"])
 
@@ -771,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():
@@ -798,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")
@@ -814,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()
@@ -840,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
@@ -848,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
@@ -910,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"]
 
@@ -919,12 +915,12 @@ 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"]
 
         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):
@@ -976,17 +972,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"])
 
 
@@ -998,7 +996,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)

manuskript/logging.py

@@ -0,0 +1,308 @@
+# -*- coding: utf-8 -*-
+
+# While all logging should be done through the facilities offered by the
+# standard python `logging` module, this module will take care of specific
+# manuskript needs to keep it separate from the rest of the logic.
+
+import os
+import sys
+import logging
+import pathlib
+
+from manuskript.functions import writablePath
+from importlib import  import_module
+from pprint import pformat
+
+LOGGER = logging.getLogger(__name__)
+
+LOGFORMAT_CONSOLE = "%(levelname)s> %(message)s"
+LOGFORMAT_FILE = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+
+def setUp(console_level=logging.WARN):
+    """Sets up a convenient environment for logging.
+
+    To console:  >WARNING, plain.        (Only the essence.)"""
+
+    # The root_logger should merely trigger on warnings since it is the final
+    # stop after all categories we really care about didn't match.
+    root_logger = logging.getLogger()
+    root_logger.setLevel(logging.WARN)
+    # The manuskript_logger is what all of our own code will come by.
+    # Obviously, we care greatly about logging every single message.
+    manuskript_logger = logging.getLogger("manuskript")
+    manuskript_logger.setLevel(logging.DEBUG)
+    # The qt_logger sees all the Qt nonsense when it breaks.
+    # We don't really want to know... but we have to know.
+    qt_logger = logging.getLogger("qt")
+    qt_logger.setLevel(logging.DEBUG)
+
+    # Send logs of WARNING+ to STDERR for higher visibility.
+    ch = logging.StreamHandler()
+    ch.setLevel(console_level)
+    ch.setFormatter(logging.Formatter(LOGFORMAT_CONSOLE))
+    root_logger.addHandler(ch)
+
+    # Any exceptions we did not account for need to be logged.
+    logFutureExceptions()
+
+    LOGGER.debug("Logging to STDERR.")
+
+
+def logToFile(file_level=logging.DEBUG, logfile=None):
+    """Sets up the FileHandler that logs to a file.
+
+    This is being done separately due to relying on QApplication being properly
+    configured; without it we cannot detect the proper location for the log file.
+
+    To log file: >DEBUG, timestamped.    (All the details.)"""
+
+    if logfile is None:
+        logfile = os.path.join(writablePath(), "manuskript.log")
+
+    # Log with extreme prejudice; everything goes to the log file.
+    # Because Qt gave me a megabyte-sized logfile while testing, it
+    # makes sense that the default behaviour of appending to existing
+    # log files may not be in our users best interest for the time
+    # being. (Unfortunately.)
+    try:
+        fh = logging.FileHandler(logfile, mode='w', encoding='utf-8')
+        fh.setLevel(file_level)
+        fh.setFormatter(logging.Formatter(LOGFORMAT_FILE))
+
+        root_logger = logging.getLogger()
+        root_logger.addHandler(fh)
+
+        # Use INFO level to make it easier to find for users.
+        LOGGER.info("Logging to file: %s", logfile)
+    except Exception as ex:
+        LOGGER.warning("Cannot log to file '%s'. Reason: %s", logfile, ex)
+
+# Log uncaught and unraisable exceptions.
+
+# Uncaught exceptions trigger moments before a thread is terminated due to
+# an uncaught exception. It is the final stop, and as such is very likely
+# to be the reason Manuskript suddenly closed on the user without warning.
+# (It can also happen on other threads, but it is a bad thing regardless!)
+def handle_uncaught_exception(exc_type, exc_value, exc_traceback):
+    # Allow Ctrl+C for script execution to keep functioning as-is.
+    if issubclass(exc_type, KeyboardInterrupt):
+        sys.__excepthook__(exc_type, exc_value, exc_traceback)
+        return # default exception hook handled it
+
+    # Anything that reaches this handler can be considered a deal-breaker.
+    LOGGER.critical("An unhandled exception has occurred!", exc_info=(exc_type, exc_value, exc_traceback))
+
+    # Exit the program to preserve PyQt 'functionality' that is broken by
+    # having our own uncaught exception hook. For more information, see:
+    #   https://stackoverflow.com/questions/49065371/why-does-sys-excepthook-behave-differently-when-wrapped
+    sys.exit(1)
+
+    # Note that without it, unhandled Python exceptions thrown while in the
+    # bowels of Qt may be written to the log multiple times. Under the motto
+    # of failing fast and not having a misleading log file, this appears to
+    # be the best course of action.
+
+
+# The situation with threads and uncaught exceptions is fraught in peril.
+# Hopefully this solves our problems on more recent versions of Python.
+def handle_uncaught_thread_exception(args):
+    if issubclass(exc_type, SystemExit):
+        return # match behaviour of default hook, see manual
+
+    # Anything that reaches this handler can be considered a minor deal-breaker.
+    LOGGER.error("An unhandled exception has occurred in a thread: %s", repr(args.thread),
+                    exc_info=(args.exc_type, args.exc_value, args.exc_traceback))
+
+
+# Unraisable exceptions are exceptions that failed to be raised to a caller
+# due to the nature of the exception. Examples: __del__(), GC error, etc.
+# Logging these may expose bugs / errors that would otherwise go unnoticed.
+def handle_unraisable_exception(unraisable):
+    # Log as warning because the application is likely to limp along with
+    # no serious side effects; a resource leak is the most likely.
+    LOGGER.warning("%s: %s", unraisable.err_msg or "Exception ignored in", repr(unraisable.object),
+                    exc_info=(unraisable.exc_type, unraisable.exc_value, unraisable.exc_traceback))
+
+
+# Because we are already somewhat careful in regards to the order of code
+# execution when it comes to setting up the logging environment, this has
+# been put in its own function as opposed to letting a direct import handle it.
+def logFutureExceptions():
+    """Log all the interesting exceptions that may happen in the future."""
+    sys.excepthook = handle_uncaught_exception
+    try:
+        import threading # threading module was optional pre-3.7
+        if hasattr(threading, "excepthook"):  # Python 3.8+
+            threading.excepthook = handle_uncaught_thread_exception
+    except:
+        pass
+    if hasattr(sys, "unraisablehook"):  # Python 3.8+
+        sys.unraisablehook = handle_unraisable_exception
+
+
+# Qt has its own logging facility that we would like to integrate into our own.
+# See: http://thispageintentionally.blogspot.com/2014/03/trapping-qt-log-messages.html
+
+from PyQt5.QtCore import qInstallMessageHandler, QLibraryInfo, QMessageLogContext
+from PyQt5.Qt import QtMsgType
+
+def qtMessageHandler(msg_type, msg_log_context, msg_string):
+    """Forwards Qt messages to Python logging system."""
+    # Convert Qt msg type to logging level
+    log_level = [logging.DEBUG,
+                 logging.WARNING,
+                 logging.ERROR,
+                 logging.FATAL] [ int(msg_type) ]
+    qtcl = logging.getLogger(msg_log_context.category or "qt.???")
+    # Some information may not be available unless using a PyQt debug build.
+    # See: https://www.riverbankcomputing.com/static/Docs/PyQt5/api/qtcore/qmessagelogcontext.html
+    if QLibraryInfo.isDebugBuild():
+        qtcl.log(logging.DEBUG,
+                    ' @ {0} : {1}'.format((msg_log_context.file or "<unknown source file>"), msg_log_context.line)
+                    )
+        qtcl.log(logging.DEBUG,
+                    ' ! {0}'.format((msg_log_context.function or "<unknown function>"))
+                    )
+    qtcl.log(log_level, msg_string)
+
+def integrateQtLogging():
+    """Integrates Qt logging facilities to be a part of our own."""
+
+    # Note: the qtlogger is initialized in setUp() because it fits in
+    # nicely with the initialization of the other loggers over there.
+    # I also feel a lot safer this way. Qt is a curse that just keeps
+    # on giving, even when it isn't actually at fault. I hate you, Qt.
+
+    qInstallMessageHandler(qtMessageHandler)
+
+
+def versionTupleToString(t):
+    """A bit of generic tuple conversion code that hopefully handles all the
+    different sorts of tuples we may come across while logging versions.
+
+    None                -> "N/A"
+    (,)                 -> "N/A"
+    (2, 4, 6)           -> "2.4.6"
+    (2, 4, "alpha", 8)  -> "2.4-alpha.8"
+    """
+
+    s = []
+    if t is None or len(t) == 0:
+        return "N/A"
+    else:
+        s.append(str(t[0]))
+
+    def version_chunk(v):
+        if isinstance(v, str):
+            return "-", str(v)
+        else:
+            return ".", str(v)
+
+    s.extend(f for p in t[1:] for f in version_chunk(p))
+    return "".join(s)
+
+def attributesFromOptionalModule(module, *attributes):
+    """It is nice to cut down on the try-except boilerplate by
+    putting this logic into its own function.
+
+    Returns as many values as there are attributes.
+    A value will be None if it failed to get the attribute."""
+
+    assert(len(attributes) != 0)
+    v = []
+    try:
+        m = import_module(module)
+
+        for a in attributes:
+            v.append(getattr(m, a, None))
+    except ImportError:
+        v.extend(None for _ in range(len(attributes)))
+
+    if len(v) == 1:
+        # Return the value directly so we can use it in an expression.
+        return v[0]
+    else:
+        # The list is consumed as a part of the unpacking syntax.
+        return v
+
+def logRuntimeInformation(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())
+
+    # 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
+    logger.info("Manuskript %s%s (Python %s)", getVersion(),
+                    getGitRevisionAsString(getManuskriptPath(), short=True),
+                    python_version())
+
+    # Installed Python packages.
+
+    # PyQt + Qt
+    from PyQt5.Qt import PYQT_VERSION_STR, qVersion
+    from PyQt5.QtCore import QT_VERSION_STR
+    logger.info("* PyQt %s (compiled against Qt %s)", PYQT_VERSION_STR, QT_VERSION_STR)
+    logger.info("  * Qt %s (runtime)", qVersion())
+
+    # Lxml
+    # See: https://lxml.de/FAQ.html#i-think-i-have-found-a-bug-in-lxml-what-should-i-do
+    from lxml import etree
+    logger.info("* lxml.etree %s",                vt2s(etree.LXML_VERSION))
+    logger.info("  * libxml   %s (compiled: %s)", vt2s(etree.LIBXML_VERSION), vt2s(etree.LIBXML_COMPILED_VERSION))
+    logger.info("  * libxslt  %s (compiled: %s)", vt2s(etree.LIBXSLT_VERSION), vt2s(etree.LIBXSLT_COMPILED_VERSION))
+
+    # Spellcheckers. (Optional)
+    enchant_mod_ver, enchant_lib_ver = afom("enchant", "__version__", "get_enchant_version")
+    if enchant_lib_ver:
+        enchant_lib_ver = enchant_lib_ver()
+        if isinstance(enchant_lib_ver, bytes):  # PyEnchant version < 3.0.2
+            enchant_lib_ver = enchant_lib_ver.decode('utf-8')
+    logger.info("* pyEnchant %s (libenchant: %s)", enchant_mod_ver or "N/A", enchant_lib_ver or "N/A")
+
+    logger.info("* pySpellChecker %s", afom("spellchecker", "__version__") or "N/A")
+    logger.info("* Symspellpy %s", afom("symspellpy", "__version__") or "N/A")
+
+    # Markdown. (Optional)
+    logger.info("* Markdown %s", afom("markdown", "__version__") or "N/A")
+
+    # Web rendering engine
+    from manuskript.ui.views.webView import webEngine
+    logger.info("Web rendering engine: %s", webEngine)
+
+    # Do not collect version information for Pandoc; that would require
+    # executing `pandov -v` and parsing the output, all of which is too slow.

manuskript/main.py

@@ -6,7 +6,7 @@ import platform
 import sys
 import signal
 
-import manuskript.ui.views.webView
+import manuskript.logging
 from PyQt5.QtCore import QLocale, QTranslator, QSettings, Qt
 from PyQt5.QtGui import QIcon, QColor, QPalette
 from PyQt5.QtWidgets import QApplication, qApp, QStyleFactory
@@ -16,15 +16,26 @@ 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()
+
+    # Log all the versions for less headaches.
+    manuskript.logging.logRuntimeInformation()
+
     icon = QIcon()
     for i in [16, 32, 64, 128, 256, 512]:
         icon.addFile(appPath("icons/Manuskript/icon-{}px.png".format(i)))
@@ -47,7 +58,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 +73,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 +96,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 +110,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 +175,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(arguments, app, MW = None):
-def launch(app, MW=None):
     if MW == None:
         from manuskript.functions import mainWindow
         MW = mainWindow()
@@ -184,7 +196,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
@@ -230,6 +242,8 @@ def launch(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.')
 
@@ -241,18 +255,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__":

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
@@ -639,7 +642,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 +667,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()
 
@@ -854,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
@@ -865,18 +864,15 @@ 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)
-
+            LOGGER.warning("Project {} not saved.".format(projectName))
-        # Giving some feedback in console
-        print(feedback)
 
     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)
@@ -889,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)
 
@@ -1531,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)
@@ -1625,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"),

manuskript/models/abstractItem.py

@@ -13,6 +13,8 @@ import re
 
 from manuskript import enums
 
+import logging
+LOGGER = logging.getLogger(__name__)
 
 class abstractItem():
 
@@ -215,7 +217,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():

manuskript/models/abstractModel.py

@@ -26,6 +26,8 @@ except:
     pass
 import time, os
 
+import logging
+LOGGER = logging.getLogger(__name__)
 
 class abstractModel(QAbstractItemModel):
     """
@@ -83,7 +85,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
@@ -177,7 +179,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:

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()

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

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:

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:

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)

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

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 \

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)
 

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)

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)
 

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

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.")
+            LOGGER.warning("Unable to match fetched data for tooltip to original request.")
-            print("- Completed request:", url_key)
+            LOGGER.warning("- Completed request: %s", url_key)
-            print("- Status upon finishing:", reply.error(), reply.errorString())
+            LOGGER.warning("- Status upon finishing: %s, %s", reply.error(), reply.errorString())
-            print("- Currently processing:", ImageTooltip.processing)
+            LOGGER.warning("- Currently processing: %s", ImageTooltip.processing)
             return
 
         # Update cache with retrieved data.

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:

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)
 

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)

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

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(
+            LOGGER.info("Last accessed directory \"{}\" loaded.".format(lastDirectory))
-                lastDirectory))
         return lastDirectory
 
     def setLastAccessedDirectory(self, dir):
@@ -422,10 +424,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 +437,10 @@ class welcome(QWidget, Ui_welcome):
                 settings.viewMode = "simple"
 
         # Tasks
-        self.mw.mdlFlatData = QStandardItemModel(2, 8, self.mw)
+        self.mw.mdlFlatData.setRowCount(2)     # data from: infos.txt, summary.txt
-
+        self.mw.mdlFlatData.setColumnCount(8)  # version_1.py: len(infos.txt) == 8
-        # 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"])
 
         # Labels
-        self.mw.mdlLabels = QStandardItemModel(self.mw)
         for color, text in [
             (Qt.transparent, ""),
             (Qt.yellow, self.tr("Idea")),
@@ -458,7 +452,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 +461,9 @@ class welcome(QWidget, Ui_welcome):
         ]:
             self.mw.mdlStatus.appendRow(QStandardItem(text))
 
-        # Plot
+        # Plot (nothing special needed)
-        self.mw.mdlPlots = plotModel(self.mw)
 
         # Outline
-        self.mw.mdlOutline = outlineModel(self.mw)
-
-        # World
-        self.mw.mdlWorld = worldModel(self.mw)
 
         root = self.mw.mdlOutline.rootItem
         _type = "md"
@@ -509,3 +497,5 @@ class welcome(QWidget, Ui_welcome):
 
         if self.template and self.template[1]:
             addElement(root, self.template[1])
+
+        # World (nothing special needed)