diff options
Diffstat (limited to 'lib/debug')
| -rw-r--r-- | lib/debug/__init__.py | 11 | ||||
| -rw-r--r-- | lib/debug/debug.py | 251 | ||||
| -rw-r--r-- | lib/debug/debugger.py | 192 | ||||
| -rw-r--r-- | lib/debug/logging.py | 294 | ||||
| -rw-r--r-- | lib/debug/utils.py | 278 |
5 files changed, 1026 insertions, 0 deletions
diff --git a/lib/debug/__init__.py b/lib/debug/__init__.py new file mode 100644 index 00000000..8093e6a0 --- /dev/null +++ b/lib/debug/__init__.py @@ -0,0 +1,11 @@ +# Authors: see git history +# +# Copyright (c) 2010 Authors +# Licensed under the GNU GPL version 3.0 or later. See the file LICENSE for details. + + +# this enable: +# from .debug import debug +# from ..debug import debug +from .debug import debug + 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() diff --git a/lib/debug/debugger.py b/lib/debug/debugger.py new file mode 100644 index 00000000..11293c8a --- /dev/null +++ b/lib/debug/debugger.py @@ -0,0 +1,192 @@ +# Authors: see git history +# +# Copyright (c) 2024 Authors +# Licensed under the GNU GPL version 3.0 or later. See the file LICENSE for details. + + +# ### General debugging notes: +# 1. to enable debugging or profiling copy DEBUG_template.toml to DEBUG.toml and edit it + +# ### How create bash script for offline debugging from console +# 1. in DEBUG.toml set create_bash_script = true +# 2. call inkstitch.py extension from inkscape to create bash script named by bash_file_base in DEBUG.toml +# 3. run bash script from console + +# ### Enable debugging +# 1. set debug_type to one of - vscode, pycharm, pydev, see below for details +# debug_type = vscode - 'debugpy' for vscode editor +# debug_type = pycharm - 'pydevd-pycharm' for pycharm editor +# debug_type = pydev - 'pydevd' for eclipse editor +# 2. set debug_enable = true in DEBUG.toml +# or use command line argument -d in bash script +# or set environment variable INKSTITCH_DEBUG_ENABLE = True or 1 or yes or y + +# ### Enable profiling +# 1. set profiler_type to one of - cprofile, profile, pyinstrument +# profiler_type = cprofile - 'cProfile' profiler +# profiler_type = profile - 'profile' profiler +# profiler_type = pyinstrument- 'pyinstrument' profiler +# 2. set profile_enable = true in DEBUG.toml +# or use command line argument -p in bash script +# or set environment variable INKSTITCH_PROFILE_ENABLE = True or 1 or yes or y + +# ### Miscelaneous notes: +# - to disable debugger when running from inkscape set disable_from_inkscape = true in DEBUG.toml +# - to change various output file names see DEBUG.toml +# - to disable waiting for debugger to attach (vscode editor) set wait_attach = false in DEBUG.toml +# - to prefer inkscape version of inkex module over pip version set prefer_pip_inkex = false in DEBUG.toml + +# ### + +# ### How to debug Ink/Stitch with LiClipse: +# +# 1. Install LiClipse (liclipse.com) -- no need to install Eclipse first +# 2. Start debug server as described here: http://www.pydev.org/manual_adv_remote_debugger.html +# * follow the "Note:" to enable the debug server menu item +# 3. Copy and edit a file named "DEBUG.toml" from "DEBUG_template.toml" next to inkstitch.py in your git clone +# and set debug_type = pydev +# 4. Run any extension and PyDev will start debugging. + +# ### + +# ### To debug with PyCharm: + +# You must use the PyCharm Professional Edition and _not_ the Community +# Edition. Jetbrains has chosen to make remote debugging a Pro feature. +# To debug Inkscape python extensions, the extension code and Inkscape run +# independently of PyCharm, and only communicate with the debugger via a +# TCP socket. Thus, debugging is "remote," even if it's on the same machine, +# connected via the loopback interface. +# +# 1. pip install pydev_pycharm +# +# pydev_pycharm is versioned frequently. Jetbrains suggests installing +# a version at least compatible with the current build. For example, if your +# PyCharm build, as found in menu PyCharm -> About Pycharm is 223.8617.48, +# you could do: +# pip install pydevd-pycharm~=223.8617.48 +# +# 2. From the Pycharm "Run" menu, choose "Edit Configurations..." and create a new +# configuration. Set "IDE host name:" to "localhost" and "Port:" to 5678. +# You can leave the default settings for all other choices. +# +# 3. Touch a file named "DEBUG.toml" at the top of your git repo, as above +# set debug_type = pycharm +# +# 4. Create a symbolic link in the Inkscape extensions directory to the +# top-level directory of your git repo. On a mac, for example: +# cd ~/Library/Application\ Support/org.inkscape.Inkscape/config/inkscape/extensions/ +# ln -s <full path to the top level of your Ink/Stitch git repo> +# On other architectures it may be: +# cd ~/.config/inkscape/extensions +# ln -s <full path to the top level of your Ink/Stitch git repo> +# Remove any other Ink/Stitch files or references to Ink/Stitch from the +# extensions directory, or you'll see duplicate entries in the Ink/Stitch +# extensions menu in Inkscape. +# +# 5. In Pycharm, either click on the green "bug" icon if visible in the upper +# right or press Ctrl-D to start debugging.The PyCharm debugger pane will +# display the message "Waiting for process connection..." +# +# 6. Do some action in Inkscape which invokes Ink/Stitch extension code, and the +# debugger will be triggered. If you've left "Suspend after connect" checked +# in the Run configuration, PyCharm will pause in the "self.log("Enabled +# PyDev debugger.)" statement, below. Uncheck the box to have it continue +# automatically to your first set breakpoint. + +# ### + +# ### To debug with VS Code +# see: https://code.visualstudio.com/docs/python/debugging#_command-line-debugging +# https://code.visualstudio.com/docs/python/debugging#_debugging-by-attaching-over-a-network-connection +# +# 1. Install the Python extension for VS Code +# pip install debugpy +# 2. create .vscode/launch.json containing: +# "configurations": [ ... +# { +# "name": "Python: Attach", +# "type": "python", +# "request": "attach", +# "connect": { +# "host": "localhost", +# "port": 5678 +# } +# } +# ] +# 3. Touch a file named "DEBUG.toml" at the top of your git repo, as above +# set debug_type = vscode +# 4. Start the debug server in VS Code by clicking on the debug icon in the left pane +# select "Python: Attach" from the dropdown menu and click on the green arrow. +# The debug server will start and connect to already running python processes, +# but immediately exit if no python processes are running. +# +# Notes: +# to see flask server url routes: +# - comment out the line self.disable_logging() in run() of lib/api/server.py + +import os +import sys + +import socket # to check if debugger is running + +from .utils import safe_get # mimic get method of dict with default value + +import logging + +logger = logging.getLogger("inkstitch") + +# we intentionally disable flakes C901 - function is too complex, beacuse it is used only for debugging +# currently complexity is set 10 see 'make style', this means that function can have max 10 nested blocks, here we have more +# flake8: noqa: C901 +def init_debugger(debug_type:str, ini: dict): + if debug_type == 'none': + return + + wait_attach = safe_get(ini, "DEBUG", "wait_attach", default=True) # currently only for vscode + debugger = debug_type + + try: + if debugger == 'vscode': + import debugpy + elif debugger == 'pycharm': + import pydevd_pycharm + elif debugger == 'pydev': + import pydevd + elif debugger == 'file': + pass + else: + raise ValueError(f"unknown debugger: '{debugger}'") + + except ImportError: + logger.info(f"importing debugger failed (debugger disabled) for {debugger}") + + # pydevd likes to shout about errors to stderr whether I want it to or not + with open(os.devnull, 'w') as devnull: + stderr = sys.stderr + sys.stderr = devnull + + try: + if debugger == 'vscode': + debugpy.listen(('localhost', 5678)) + if wait_attach: + print("Waiting for debugger attach", file=sys.stderr) + debugpy.wait_for_client() # wait for debugger to attach + debugpy.breakpoint() # stop here to start normal debugging + elif debugger == 'pycharm': + pydevd_pycharm.settrace('localhost', port=5678, stdoutToServer=True, + stderrToServer=True) + elif debugger == 'pydev': + pydevd.settrace() + elif debugger == 'file': + pass + else: + raise ValueError(f"unknown debugger: '{debugger}'") + + except socket.error as error: + logger.info("Debugging: connection to pydevd failed: %s", error) + logger.info(f"Be sure to run 'Start debugging server' in {debugger} to enable debugging.") + else: + logger.info(f"Enabled '{debugger}' debugger.") + + sys.stderr = stderr diff --git a/lib/debug/logging.py b/lib/debug/logging.py new file mode 100644 index 00000000..4d3683b6 --- /dev/null +++ b/lib/debug/logging.py @@ -0,0 +1,294 @@ +# Authors: see git history +# +# Copyright (c) 2024 Authors +# Licensed under the GNU GPL version 3.0 or later. See the file LICENSE for details. + +# basic info for inkstitch logging: +# --------------------------------- +# some idea can be found in: Modern Python logging - https://www.youtube.com/watch?v=9L77QExPmI0 +# +# logging vs warnings +# ------------------- +# warnings - see https://docs.python.org/3/library/warnings.html +# logging - see https://docs.python.org/3/library/logging.html +# +# In simplified terms, use "warning" to alert that a specific function is deprecated, and in all other cases, use "logging". +# Warnings are primarily intended for libraries where there's a newer solution available, but for backward compatibility +# reasons, the old functionality is retained. +# +# In complex applications like Inkstitch, it might be sensible to exclusively use one method, namely "logging", +# to unify and simplify the messaging system of such a system. +# +# +# root logger: +# ------------ +# - The primary logger orchestrates all other loggers through logging.xxx() calls. +# - It should only be utilized at the application's highest level to manage the logging of all loggers. +# - It can easily disable all loggers by invoking logging.disable() and channel all warnings to logging +# by setting logging.captureWarnings(True) with the level WARNING. +# - The configuration of all loggers can be achieved via a file, and logging.config.dictConfig(logging_dict). +# + +# module logger: +# -------------- +# - Instantiate the logger by invoking logger=getLogger(name). +# Avoid using __name__ as the name, as it generates numerous loggers per application. +# The logger name persists globally throughout the application. +# - Avoid configuring the module logger within the module itself; +# instead, utilize the top-level application configuration with logging.config. +# This allows users of the application to customize it according to their requirements. + +# example of module logger: +# ------------------------- +# import logging +# logger = logging.getLogger('inkstitch') # create module logger with name 'inkstitch', but configure it at top level of app +# ... +# logger.debug('debug message') # example of using module logger +# ... + +# top level of the application: +# ---------------------------- +# - configure root and other loggers +# - best practice is to configure from a file: eg logging.config.fileConfig('logging.conf') +# - consider toml format for logging configuration (json, yaml, xml, dict are also possible) +# + +# list of loggers in inkstitch (not complete): +# ------------------------------------------- +# - root - main logger that controls all other loggers +# - inkstitch - suggested name for inkstitch +# - inkstitch.debug - uses in debug module with svg file saving +# +# third-party loggers: +# -------------------- +# - werkzeug - is used by flask +# - shapely.geos - was used by shapely but currently replaced by exceptions and warnings +# + +# -------------------------------------------------------------------------------------------- +import os +import sys +from pathlib import Path + +if sys.version_info >= (3, 11): + import tomllib # built-in in Python 3.11+ +else: + import tomli as tomllib + +import warnings # to control python warnings +import logging # to configure logging +import logging.config # to configure logging from dict + +from .utils import safe_get # mimic get method of dict with default value + +logger = logging.getLogger('inkstitch') + + +# -------------------------------------------------------------------------------------------- +# activate_logging - configure logging for inkstitch application +def activate_logging(running_as_frozen: bool, ini: dict, SCRIPTDIR: Path): + if running_as_frozen: # in release mode + activate_for_frozen() + else: # in development + activate_for_development(ini, SCRIPTDIR) + + +# Configure logging in frozen (release) mode of application: +# in release mode normally we want to ignore all warnings and logging, but we can enable it by setting environment variables +# - INKSTITCH_LOGLEVEL - logging level: +# 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL' +# - PYTHONWARNINGS, -W - warnings action controlled by python +# actions: 'error', 'ignore', 'always', 'default', 'module', 'once' +def activate_for_frozen(): + loglevel = os.environ.get('INKSTITCH_LOGLEVEL') # read log level from environment variable or None + docpath = os.environ.get('DOCUMENT_PATH') # read document path from environment variable (set by inkscape) or None + + if docpath is not None and loglevel is not None and loglevel.upper() in ['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL']: + + # The end user enabled logging and warnings are redirected to the input_svg.inkstitch.log file. + + vars = { + 'loglevel': loglevel.upper(), + 'logfilename': Path(docpath).with_suffix('.inkstitch.log') # log file is created in document path + } + config = expand_variables(frozen_config, vars) + + # dictConfig has access to top level variables, dict contains: ext://__main__.var + # - restriction: variable must be last token in string - very limited functionality, avoid using it + + # After this operation, logging will be activated, so we can use the logger. + logging.config.dictConfig(config) # configure root logger from dict + + logging.captureWarnings(True) # capture all warnings to log file with level WARNING + else: + logging.disable() # globally disable all logging of all loggers + warnings.simplefilter('ignore') # ignore all warnings + + +# in development mode we want to use configuration from some LOGGING.toml file +def activate_for_development(ini: dict, SCRIPTDIR: Path): + logging_config_file = safe_get(ini, "LOGGING", "log_config_file", default=None) + vars = {'SCRIPTDIR': SCRIPTDIR} # dynamic data for logging configuration + + if logging_config_file is not None: + logging_config_file = Path(logging_config_file) + if logging_config_file.exists(): + with open(logging_config_file, "rb") as f: + devel_config = tomllib.load(f) # -> dict + else: + raise FileNotFoundError(f"{logging_config_file} file not found") + else: # if LOGGING.toml file does not exist, use default logging configuration + vars['loglevel'] = 'DEBUG' # set log level to DEBUG + vars['logfilename'] = SCRIPTDIR / "inkstitch.log" # log file is created in current directory + devel_config = development_config # get TOML configuration from module + + configure_logging(devel_config, ini, vars) # initialize and activate logging configuration + + logger.info("Running in development mode") + logger.info(f"Using logging configuration from file: {logging_config_file}") + logger.debug(f"Logging configuration: {devel_config = }") + + +# -------------------------------------------------------------------------------------------- +# configure logging from dictionary: +# - capture all warnings to log file with level WARNING - depends on warnings_capture +# - set action for warnings: 'error', 'ignore', 'always', 'default', 'module', 'once' - depends on warnings_action +def configure_logging(config: dict, ini: dict, vars: dict): + config = expand_variables(config, vars) + + # After this operation, logging will be activated, so we can use the logger. + logging.config.dictConfig(config) # configure loggers from dict - using loglevel, logfilename + + warnings_capture = config.get('warnings_capture', True) + logging.captureWarnings(warnings_capture) # capture warnings to log file with level WARNING + warnings_action = config.get('warnings_action', 'default').lower() + warnings.simplefilter(warnings_action) # set action for warnings: 'error', 'ignore', 'always', ... + + disable_logging = safe_get(ini, "LOGGING", "disable_logging", default=False) + if disable_logging: + logger.warning(f"Logging is disabled by configuration in ini file. {disable_logging = }") + logging.disable() # globally disable all logging of all loggers + + +# Evaluate evaluation of variables in logging configuration: +# "handlers": { +# "file": { +# "filename": "%(SCRIPTDIR)s/xxx.log", # <--- replace %(SCRIPTDIR)s -> script path +# "%(logfilename)s", # <--- replace %(logfilename)s -> log file name +# ... +# "loggers": { +# "inkstitch": { +# "level": "%(loglevel)s", # <--- replace %(loglevel)s -> log level +# ... +# - for external configuration file (eg. LOGGING.toml) we cannot pass parameters such as the current directory. +# - we do: filename = "%(SCRIPTDIR)s/inkstitch.log" -> filename = "path/inkstitch.log" +# - safety: we can use only predefined variables in myvars, otherwise we get KeyError +# - return modified configuration +# - create logging directory if not exists, directory cannot end with ":" to avoid error with ext:// keys +def expand_variables(cfg: dict, vars: dict): + for k, v in cfg.get('loggers', {}).items(): + if 'level' in v: # replace level in logger + cfg['loggers'][k]['level'] = v['level'] % vars + + for k, v in cfg.get('handlers', {}).items(): + if 'filename' in v: # replace filename in handler + orig_filename = v['filename'] # original filename for later comparison + cfg['handlers'][k]['filename'] = v['filename'] % vars + # create logging directory only if substitution was done, we need to avoid ext:// cfg:// keys + if orig_filename != cfg['handlers'][k]['filename']: + dirname = Path(cfg['handlers'][k]['filename']).parent + if not dirname.exists(): + # inform user about creating logging directory, otherwise it is silent, logging is not yet active + print(f"DEBUG: Creating logging directory: {dirname} ", file=sys.stderr) + dirname.mkdir(parents=True, exist_ok=True) + return cfg + + +def startup_info(logger: logging.Logger, SCRIPTDIR: Path, running_as_frozen: bool, running_from_inkscape: bool, + debug_active: bool, debug_type: str, profiler_type: str): + logger.info(f"Running as frozen: {running_as_frozen}") + logger.info(f"Running from inkscape: {running_from_inkscape}") + logger.info(f"Debugger active: {debug_active}") + logger.info(f"Debugger type: {debug_type!r}") + logger.info(f"Profiler type: {profiler_type!r}") + + # log Python version, platform, command line arguments, sys.path + import sys + import platform + + logger.info(f"Python version: {sys.version}") + logger.info(f"Platform: {platform.platform()}") + logger.info(f"Command line arguments: {sys.argv}") + logger.debug(f"sys.path: {sys.path}") + + +# example of logger configuration for release mode: +# ------------------------------------------------ +# - logger suitable for release mode, where we assume that the directory of the input SVG file allows writing the log file. +# - in inkstitch.py we check release mode and environment variable INKSTITCH_LOGLEVEL +# - this config redirect all loggers to file svg_file.inkstitch.log to directory of svg file +# - set loglevel and logfilename in inkstitch.py before calling logging.config.dictConfig(frozen_config) +frozen_config = { + "version": 1, # mandatory key and value (int) is 1 + "disable_existing_loggers": False, # false enable all loggers not defined here, true disable + "filters": {}, # no filters + "formatters": { + "simple": { # formatter name (https://docs.python.org/3/library/logging.html#logging.LogRecord) + "format": '%(asctime)s [%(levelname)s]: %(filename)s.%(funcName)s: %(message)s' # format string + } + }, + "handlers": { + "file": { + "class": "logging.FileHandler", # type - file output + "formatter": "simple", # use formatter 'simple' for handler 'file' + "filename": "%(logfilename)s", # access variable logfilename + "mode": "w" # create new file + } + }, + "loggers": { + "root": { # top level logger + "level": "%(loglevel)s", # access variable loglevel + "handlers": ["file"], # use handler 'file' for logger + } + }, +} + +# --------------------------------------------------- +# example of implicit developer logger configuration: +# --------------------------------------------------- +# - configured two loggers: root and inkstitch loggers +# - output is redirected to file 'logfilename' in the directory of inkstitch.py +# - this configuration uses only one log level 'loglevel for both the root and inkstitch loggers. +# - set loglevel and logfilename in inkstitch.py before calling logging.config.dictConfig(development_config) +development_config = { + "warnings_action": "default", # dafault action for warnings + "warnings_capture": True, # capture warnings to log file with level WARNING + + "version": 1, # mandatory key and value (int) is 1 + "disable_existing_loggers": False, # false enable all loggers not defined here, true disable + "filters": {}, # no filters + "formatters": { + "simple": { # formatter name (https://docs.python.org/3/library/logging.html#logging.LogRecord) + "format": '%(asctime)s [%(levelname)s]: %(filename)s.%(funcName)s: %(message)s' # format string + } + }, + "handlers": { + "file": { + "class": "logging.FileHandler", # type - file output + "formatter": "simple", # use formatter 'simple' for handler 'file' + "filename": "%(logfilename)s", # ext: --> access variable logfilename + "mode": "w" # create new file + }, + }, + "loggers": { # configure loggers + "inkstitch": { # specific logger to inkstitch application + "level": "%(loglevel)s", # ext: --> access variable loglevel + "handlers": ["file"], # use handler 'file' for logger + "propagate": False, # don't propagate to root logger - otherwise all will be logged twice + }, + "root": { # top level logger + "level": "%(loglevel)s", # ext: --> access variable loglevel + "handlers": ["file"], # use handler 'file' for logger + } + }, +} diff --git a/lib/debug/utils.py b/lib/debug/utils.py new file mode 100644 index 00000000..9618d173 --- /dev/null +++ b/lib/debug/utils.py @@ -0,0 +1,278 @@ +# Authors: see git history +# +# Copyright (c) 2024 Authors +# Licensed under the GNU GPL version 3.0 or later. See the file LICENSE for details. + +# this file is without: import inkex +# - we need dump argv and sys.path as is on startup from inkscape +# - later sys.path may be modified that influences importing inkex (see prefere_pip_inkex) + +import os +import sys +from pathlib import Path # to work with paths as objects +import logging + +logger = logging.getLogger("inkstitch") + + +# safe_get - get value from nested dictionary, return default if key does not exist +# - to read nested values from dict - mimic get method of dict with default value +# example: safe_get({'a': {'b': 1}}, 'a', 'b') -> 1 +# safe_get({'a': {'b': 1}}, 'a', 'c', default=2) -> 2 +def safe_get(dictionary: dict, *keys, default=None): + for key in keys: + if key not in dictionary: + return default + dictionary = dictionary[key] + return dictionary + + +def write_offline_debug_script(debug_script_dir: Path, ini: dict): + ''' + prepare Bash script for offline debugging from console + arguments: + - debug_script_dir - Path object, absolute path to directory of inkstitch.py + - ini - see DEBUG.toml + ''' + + # define names of files used by offline Bash script + bash_file_base = safe_get(ini, "DEBUG", "bash_file_base", default="debug_inkstitch") + bash_name = Path(bash_file_base).with_suffix(".sh") # Path object + bash_svg = Path(bash_file_base).with_suffix(".svg") # Path object + + # check if input svg file exists in arguments, take argument that not start with '-' as file name + svgs = [arg for arg in sys.argv[1:] if not arg.startswith('-')] + if len(svgs) != 1: + print(f"WARN: {len(svgs)} svg files found, expected 1, [{svgs}]. No script created in write debug script.", file=sys.stderr) + return + + svg_file = Path(svgs[0]) + if svg_file.exists() and bash_svg.exists() and bash_svg.samefile(svg_file): + print("WARN: input svg file is same as output svg file. No script created in write debug script.", file=sys.stderr) + return + + import shutil # to copy svg file + bash_file = debug_script_dir / bash_name + + with open(bash_file, 'w') as f: # "w" text mode, automatic conversion of \n to os.linesep + f.write('#!/usr/bin/env bash\n') + + # cmd line arguments for debugging and profiling + f.write(bash_parser()) # parse cmd line arguments: -d -p + + f.write(f'# python version: {sys.version}\n') # python version + + myargs = " ".join(sys.argv[1:]) + f.write(f'# script: {sys.argv[0]} arguments: {myargs}\n') # script name and arguments + + # environment PATH + f.write('# PATH:\n') + f.write(f'# {os.environ.get("PATH","")}\n') + # for p in os.environ.get("PATH", '').split(os.pathsep): # PATH to list + # f.write(f'# {p}\n') + + # python module path + f.write('# python sys.path:\n') + for p in sys.path: + f.write(f'# {p}\n') + + # see static void set_extensions_env() in inkscape/src/inkscape-main.cpp + f.write('# PYTHONPATH:\n') + for p in os.environ.get('PYTHONPATH', '').split(os.pathsep): # PYTHONPATH to list + f.write(f'# {p}\n') + + f.write(f'# copy {svg_file} to {bash_svg}\n#\n') + shutil.copy(svg_file, debug_script_dir / bash_svg) # copy file to bash_svg + myargs = myargs.replace(str(svg_file), str(bash_svg)) # replace file name with bash_svg + + # see void Extension::set_environment() in inkscape/src/extension/extension.cpp + f.write('# Export inkscape environment variables:\n') + notexported = ['SELF_CALL'] # if an extension calls inkscape itself + exported = ['INKEX_GETTEXT_DOMAIN', 'INKEX_GETTEXT_DIRECTORY', + 'INKSCAPE_PROFILE_DIR', 'DOCUMENT_PATH', 'PYTHONPATH'] + for k in notexported: + if k in os.environ: + f.write(f'# export {k}="{os.environ[k]}"\n') + for k in exported: + if k in os.environ: + f.write(f'export {k}="{os.environ[k]}"\n') + + f.write('# signal inkstitch.py that we are running from offline script\n') + f.write('export INKSTITCH_OFFLINE_SCRIPT="True"\n') + + f.write('# call inkstitch\n') + f.write(f'python3 inkstitch.py {myargs}\n') + bash_file.chmod(0o0755) # make file executable, hopefully ignored on Windows + + +def bash_parser(): + return r''' +set -e # exit on error + +# parse cmd line arguments: +# -d enable debugging +# -p enable profiling +# ":..." - silent error reporting +while getopts ":dp" opt; do + case $opt in + d) + export INKSTITCH_DEBUG_ENABLE="True" + ;; + p) + export INKSTITCH_PROFILE_ENABLE="True" + ;; + \?) + echo "Invalid option: -$OPTARG" >&2 + exit 1 + ;; + :) + echo "Option -$OPTARG requires an argument." >&2 + exit 1 + ;; + esac +done + +''' + + +def reorder_sys_path(): + ''' + change sys.path to prefer pip installed inkex over inkscape bundled inkex + ''' + # see static void set_extensions_env() in inkscape/src/inkscape-main.cpp + # what we do: + # - move inkscape extensions path to the end of sys.path + # - we compare PYTHONPATH with sys.path and move PYTHONPATH to the end of sys.path + # - also user inkscape extensions path is moved to the end of sys.path - may cause problems? + # - path for deprecated-simple are removed from sys.path, will be added later by importing inkex + + # PYTHONPATH to list + pythonpath = os.environ.get('PYTHONPATH', '').split(os.pathsep) + # remove pythonpath from sys.path + sys.path = [p for p in sys.path if p not in pythonpath] + # remove deprecated-simple, it will be added later by importing inkex + pythonpath = [p for p in pythonpath if not p.endswith('deprecated-simple')] + # remove nonexisting paths + pythonpath = [p for p in pythonpath if os.path.exists(p)] + # add pythonpath to the end of sys.path + sys.path.extend(pythonpath) + + +# ----------------------------------------------------------------------------- +# try to resolve debugger type from ini file or cmd line of bash +def resolve_debug_type(ini: dict): + # enable/disable debugger from bash: -d + if os.environ.get('INKSTITCH_DEBUG_ENABLE', '').lower() in ['true', '1', 'yes', 'y']: + debug_enable = True + else: + debug_enable = safe_get(ini, "DEBUG", "debug_enable", default=False) # enable debugger on startup from ini + + debug_type = safe_get(ini, "DEBUG", "debug_type", default="none") # debugger type vscode, pycharm, pydevd + if not debug_enable: + debug_type = 'none' + + return debug_type + + +# try to resolve profiler type from ini file or cmd line of bash +def resolve_profiler_type(ini: dict): + # enable/disable profiling from bash: -p + if os.environ.get('INKSTITCH_PROFILE_ENABLE', '').lower() in ['true', '1', 'yes', 'y']: + profile_enable = True + else: + profile_enable = safe_get(ini, "PROFILE", "profile_enable", default=False) # read from ini + + # specify profiler type + profiler_type = safe_get(ini, "PROFILE", "profiler_type", default="none") # profiler type cprofile, profile, pyinstrument + if not profile_enable: + profiler_type = 'none' + + return profiler_type + +# ----------------------------------------------------------------------------- + +# Profilers: +# currently supported profilers: +# - cProfile - standard python profiler +# - profile - standard python profiler +# - pyinstrument - profiler with nice html output + + +def profile(profiler_type, profile_dir: Path, ini: dict, extension, remaining_args): + ''' + profile with cProfile, profile or pyinstrument + ''' + profile_file_base = safe_get(ini, "PROFILE", "profile_file_base", default="debug_profile") + profile_file_path = profile_dir / profile_file_base # Path object + + # create directory if not exists + dirname = profile_file_path.parent + if not dirname.exists(): + logger.debug(f"Creating directory for profile output: {dirname}") + dirname.mkdir(parents=True, exist_ok=True) + + if profiler_type == 'cprofile': + with_cprofile(extension, remaining_args, profile_file_path) + elif profiler_type == 'profile': + with_profile(extension, remaining_args, profile_file_path) + elif profiler_type == 'pyinstrument': + with_pyinstrument(extension, remaining_args, profile_file_path) + else: + raise ValueError(f"unknown profiler type: '{profiler_type}'") + + +def with_cprofile(extension, remaining_args, profile_file_path: Path): + ''' + profile with cProfile + ''' + import cProfile + import pstats + profiler = cProfile.Profile() + + profiler.enable() + extension.run(args=remaining_args) + profiler.disable() + + profiler.dump_stats(profile_file_path.with_suffix(".prof")) # can be read by 'snakeviz -s' or 'pyprof2calltree' + with open(profile_file_path, 'w') as stats_file: + stats = pstats.Stats(profiler, stream=stats_file) + stats.sort_stats(pstats.SortKey.CUMULATIVE) + stats.print_stats() + print(f"Profiler: cprofile, stats written to '{profile_file_path.name}' and '{profile_file_path.name}.prof'. Use snakeviz to see it.", + file=sys.stderr) + + +def with_profile(extension, remaining_args, profile_file_path: Path): + ''' + profile with profile + ''' + import profile + import pstats + profiler = profile.Profile() + + profiler.run('extension.run(args=remaining_args)') + + profiler.dump_stats(profile_file_path.with_suffix(".prof")) # can be read by 'snakeviz' or 'pyprof2calltree' - seems broken + with open(profile_file_path, 'w') as stats_file: + stats = pstats.Stats(profiler, stream=stats_file) + stats.sort_stats(pstats.SortKey.CUMULATIVE) + stats.print_stats() + print(f"'Profiler: profile, stats written to '{profile_file_path.name}' and '{profile_file_path.name}.prof'. Use of snakeviz is broken.", + file=sys.stderr) + + +def with_pyinstrument(extension, remaining_args, profile_file_path: Path): + ''' + profile with pyinstrument + ''' + import pyinstrument + profiler = pyinstrument.Profiler() + + profiler.start() + extension.run(args=remaining_args) + profiler.stop() + + profile_file_path = profile_file_path.with_suffix(".html") + with open(profile_file_path, 'w') as stats_file: + stats_file.write(profiler.output_html()) + print(f"Profiler: pyinstrument, stats written to '{profile_file_path.name}'. Use browser to see it.", file=sys.stderr) |