Kgn/logging revamp (#2720)

* update config files

* rebase after electron remove

* added toml to requirements

* logging update

* Unified use of the TOML format instead of INI [no ci]

* Unified use of the TOML format instead of INI [no ci]

* moving debug*.py to debug dir, moving some part for debugger [no ci]

* use of alternate logging in some cases

* updated debug logger [no ci]

* logging update

* updated notes

* updated notes about logging

* style check

1 files changed, 251 insertions, 0 deletions

diff --git a/lib/debug/debug.py b/lib/debug/debug.py
new file mode 100644
index 00000000..ab5132e4
--- /dev/null
+++ b/lib/debug/debug.py
@@ -0,0 +1,251 @@
+# Authors: see git history
+#
+# Copyright (c) 2010 Authors
+# Licensed under the GNU GPL version 3.0 or later.  See the file LICENSE for details.
+
+import atexit  # to save svg file on exit
+import time    # to measure time of code block, use time.monotonic() instead of time.time()
+from datetime import datetime
+
+from contextlib import contextmanager  # to measure time of with block
+from pathlib import Path  # to work with paths as objects
+
+import inkex
+from lxml import etree   # to create svg file
+
+from ..svg import line_strings_to_path
+from ..svg.tags import INKSCAPE_GROUPMODE, INKSCAPE_LABEL
+
+import logging
+logger = logging.getLogger("inkstitch.debug")   # create module logger with name 'inkstitch.debug'
+
+# to log messages if previous debug logger is not enabled
+logger_inkstich = logging.getLogger("inkstitch")   # create module logger with name 'inkstitch'
+
+
+# --------------------------------------------------------------------------------------------
+# decorator to check if debugging is enabled
+# - if debug is not enabled then decorated function is not called
+def check_enabled(func):
+    def decorated(self, *args, **kwargs):
+        if self.enabled:
+            return func(self, *args, **kwargs)
+
+    return decorated
+
+
+# unwrapping = provision for functions as arguments
+# - if argument is callable then it is called and return value is used as argument
+#   otherwise argument is returned as is
+def _unwrap(arg):
+    if callable(arg):
+        return arg()
+    else:
+        return arg
+
+
+# decorator to unwrap arguments if they are callable
+#   eg: if argument is lambda function then it is called and return value is used as argument
+def unwrap_arguments(func):
+    def decorated(self, *args, **kwargs):
+        unwrapped_args = [_unwrap(arg) for arg in args]
+        unwrapped_kwargs = {name: _unwrap(value) for name, value in kwargs.items()}
+
+        return func(self, *unwrapped_args, **unwrapped_kwargs)
+
+    return decorated
+
+
+class Debug(object):
+    """Tools to help debug Ink/Stitch
+
+    This class contains methods to log strings and SVG elements.  Strings are
+    logged to debug.log, and SVG elements are stored in debug.svg to aid in
+    debugging stitch algorithms.
+
+    All functionality is gated by self.enabled.  If debugging is not enabled,
+    then debug calls will consume very few resources.  Any method argument
+    can be a callable, in which case it is called and the return value is
+    logged instead.  This way one can log potentially expensive expressions
+    by wrapping them in a lambda:
+
+    debug.log(lambda: some_expensive_function(some_argument))
+
+    The lambda is only called if debugging is enabled.
+    """
+
+    def __init__(self):
+        self.enabled = False
+        self.last_log_time = None
+        self.current_layer = None
+        self.group_stack = []
+        self.svg_filename = None
+
+    def enable(self):
+        # determine svg filename from logger
+        if len(logger.handlers) > 0 and isinstance(logger.handlers[0], logging.FileHandler):
+            # determine filename of svg file from logger
+            filename = Path(logger.handlers[0].baseFilename)
+            self.svg_filename = filename.with_suffix(".svg")
+            self.svg_filename.unlink(missing_ok=True)      # remove existing svg file
+
+        # self.log is activated by active logger
+        # - enabled only if logger first handler is FileHandler
+        #   to disable "inkstitch.debug" simply set logging level to CRITICAL
+        if logger.isEnabledFor(logging.INFO) and self.svg_filename is not None:
+            self.enabled = True
+            self.log(f"Logging enabled with svg file: {self.svg_filename}")
+            self.init_svg()
+
+        else:
+            # use alternative logger to log message if logger has no handlers
+            logger_inkstich.info("No handlers in logger, cannot enable logging and svg file creation")
+
+    def init_svg(self):
+        self.svg = etree.Element("svg", nsmap=inkex.NSS)
+        atexit.register(self.save_svg)
+
+    def save_svg(self):
+        if self.enabled and self.svg_filename is not None:
+            self.log(f"Writing svg file: {self.svg_filename}")
+            tree = etree.ElementTree(self.svg)
+            tree.write(str(self.svg_filename))    # lxml <5.0.0 does not support Path objects, requires string
+        else:
+            # use alternative logger to log message if logger has no handlers
+            logger_inkstich.info(f"Saving to svg file is not activated {self.svg_filename=}")
+
+    @check_enabled
+    @unwrap_arguments
+    def add_layer(self, name="Debug"):
+        layer = etree.Element("g", {
+            INKSCAPE_GROUPMODE: "layer",
+            INKSCAPE_LABEL: name,
+            "style": "display: none"
+        })
+        self.svg.append(layer)
+        self.current_layer = layer
+
+    @check_enabled
+    @unwrap_arguments
+    def open_group(self, name="Group"):
+        group = etree.Element("g", {
+            INKSCAPE_LABEL: name
+        })
+
+        self.log_svg_element(group)
+        self.group_stack.append(group)
+
+    @check_enabled
+    @unwrap_arguments
+    def close_group(self):
+        if self.group_stack:
+            self.group_stack.pop()
+
+    @check_enabled
+    @unwrap_arguments
+    def log(self, message, *args):
+        if self.last_log_time:
+            message = "(+%s) %s" % (datetime.now() - self.last_log_time, message)
+
+        self.raw_log(message, *args)
+
+    def raw_log(self, message, *args):
+        now = datetime.now()
+        self.last_log_time = now
+
+        msg = message % args
+        logger.info(msg)
+
+    # decorator to measure time of function
+    def time(self, func):
+        def decorated(*args, **kwargs):
+            if self.enabled:
+                self.raw_log("entering %s()", func.__name__)
+                start = time.monotonic()
+
+            result = func(*args, **kwargs)
+
+            if self.enabled:
+                end = time.monotonic()
+                self.raw_log("leaving %s(), duration = %s", func.__name__, round(end - start, 6))
+
+            return result
+
+        return decorated
+
+    @check_enabled
+    @unwrap_arguments
+    def log_svg_element(self, element):
+        if self.current_layer is None:
+            self.add_layer()
+
+        if self.group_stack:
+            self.group_stack[-1].append(element)
+        else:
+            self.current_layer.append(element)
+
+    @check_enabled
+    @unwrap_arguments
+    def log_line_string(self, line_string, name=None, color=None):
+        """Add a Shapely LineString to the SVG log."""
+        self.log_line_strings([line_string], name, color)
+
+    @check_enabled
+    @unwrap_arguments
+    def log_line_strings(self, line_strings, name=None, color=None):
+        path = line_strings_to_path(line_strings)
+        path.set('style', str(inkex.Style({"stroke": color or "#000000", "stroke-width": "0.3", "fill": None})))
+
+        if name is not None:
+            path.set(INKSCAPE_LABEL, name)
+
+        self.log_svg_element(path)
+
+    @check_enabled
+    @unwrap_arguments
+    def log_line(self, start, end, name="line", color=None):
+        self.log_svg_element(etree.Element("path", {
+            "d": "M%s,%s %s,%s" % (start + end),
+            "style": str(inkex.Style({"stroke": color or "#000000", "stroke-width": "0.3", "fill": None})),
+            INKSCAPE_LABEL: name
+        }))
+
+    @check_enabled
+    @unwrap_arguments
+    def log_point(self, point, name="point", color=None):
+        self.log_svg_element(etree.Element("circle", {
+            "cx": str(point.x),
+            "cy": str(point.y),
+            "r": "1",
+            "style": str(inkex.Style({"fill": "#000000"})),
+        }))
+
+    @check_enabled
+    @unwrap_arguments
+    def log_graph(self, graph, name="Graph", color=None):
+        d = ""
+
+        for edge in graph.edges:
+            d += "M%s,%s %s,%s" % (edge[0] + edge[1])
+
+        self.log_svg_element(etree.Element("path", {
+            "d": d,
+            "style": str(inkex.Style({"stroke": color or "#000000", "stroke-width": "0.3", "fill": None})),
+            INKSCAPE_LABEL: name
+        }))
+
+    # decorator to measure time of with block
+    @contextmanager
+    def time_this(self, label="code block"):
+        if self.enabled:
+            start = time.monotonic()
+            self.raw_log("begin %s", label)
+
+        yield
+
+        if self.enabled:
+            self.raw_log("completed %s, duration = %s", label, time.monotonic() - start)
+
+
+# global debug object
+debug = Debug()