diff --git a/inkstitch.py b/inkstitch.py index dde884d7f..6697e107c 100644 --- a/inkstitch.py +++ b/inkstitch.py @@ -6,15 +6,30 @@ import os import sys from pathlib import Path # to work with paths as objects -import configparser # to read DEBUG.ini from argparse import ArgumentParser # to parse arguments and remove --extension +import configparser # to read DEBUG.ini +import toml # to read logging configuration from toml file +import warnings +import logging +import logging.config + import lib.debug_utils as debug_utils +import lib.debug_logging as debug_logging SCRIPTDIR = Path(__file__).parent.absolute() +logger = logging.getLogger("inkstitch") # create module logger with name 'inkstitch' + +ini = configparser.ConfigParser() +ini.read(SCRIPTDIR / "DEBUG.ini") # read DEBUG.ini file if exists, otherwise use default values in ini object running_as_frozen = getattr(sys, 'frozen', None) is not None # check if running from pyinstaller bundle +if not running_as_frozen: # override running_as_frozen from DEBUG.ini - for testing + if ini.getboolean("DEBUG", "force_frozen", fallback=False): + running_as_frozen = True + + if len(sys.argv) < 2: # no arguments - prevent accidentally running this script msg = "No arguments given, exiting!" # without gettext localization see _() @@ -31,8 +46,46 @@ if len(sys.argv) < 2: print(msg) exit(1) -ini = configparser.ConfigParser() -ini.read(SCRIPTDIR / "DEBUG.ini") # read DEBUG.ini file if exists +# Configure logging: +# 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' +if running_as_frozen: # in release mode + 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']: + # enable logging-warning and redirect output to input_svg.inkstitch.log + logfilename = Path(docpath).with_suffix('.inkstitch.log') # log file is created in document path + loglevel = loglevel.upper() + + logging.config.dictConfig(debug_logging.frozen_config) # configure root logger from dict - using loglevel, logfilename + logging.captureWarnings(True) # capture all warnings to log file with level WARNING + logger.info(f"Running as frozen: {running_as_frozen}") + else: + logging.disable() # globally disable all logging of all loggers + warnings.simplefilter('ignore') # ignore all warnings + +else: + # in development mode we want to use configuration from some LOGGING.toml file + logging_config_file = ini.get("LOGGING", "log_config_file", fallback=None) + if logging_config_file is not None: + logging_config_file = Path(logging_config_file) + if logging_config_file.exists(): + with open(logging_config_file, "r") as f: + development_config = toml.load(f) + else: + raise FileNotFoundError(f"{logging_config_file} file not found") + else: # if LOGGING.toml file does not exist, use default logging configuration + loglevel = 'DEBUG' # set log level to DEBUG + logfilename = SCRIPTDIR / "inkstitch.log" # log file is created in current directory + development_config = debug_logging.development_config + + debug_logging.configure_logging(development_config, ini, SCRIPTDIR) # initialize logging configuration + logger.info("Running in development mode") + logger.info(f"Using logging configuration from file: {logging_config_file}") # check if running from inkscape, given by environment variable if os.environ.get('INKSTITCH_OFFLINE_SCRIPT', '').lower() in ['true', '1', 'yes', 'y']: @@ -48,9 +101,9 @@ if not running_as_frozen: # debugging/profiling only in development mode # specify debugger type # but if script was already started from debugger then don't read debug type from ini file or cmd line if not debug_active: - debug_type = debug_utils.resole_debug_type(ini) # read debug type from ini file or cmd line + debug_type = debug_utils.resolve_debug_type(ini) # read debug type from ini file or cmd line - profile_type = debug_utils.resole_profile_type(ini) # read profile type from ini file or cmd line + profile_type = debug_utils.resolve_profile_type(ini) # read profile type from ini file or cmd line if running_from_inkscape: # process creation of the Bash script - should be done before sys.path is modified, see below in prefere_pip_inkex @@ -75,27 +128,8 @@ if debug_type != 'none': # check if debugger is really activated debug_active = bool((gettrace := getattr(sys, 'gettrace')) and gettrace()) -# warnings are used by some modules, we want to ignore them all in release -# - see warnings.warn() -if running_as_frozen or not debug_active: - import warnings - warnings.filterwarnings('ignore') - -# TODO - check if this is still needed for shapely, apparently shapely now uses only exceptions instead of io. -# all logs were removed from version 2.0.0 and above -# ---- plan to remove this in future ---- -# import logging # to set logger for shapely -# from io import StringIO # to store shapely errors -# set logger for shapely - for old versions of shapely -# logger = logging.getLogger('shapely.geos') # attach logger of shapely -# logger.setLevel(logging.DEBUG) -# shapely_errors = StringIO() # in memory file to store shapely errors -# ch = logging.StreamHandler(shapely_errors) -# ch.setLevel(logging.DEBUG) -# formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s') -# ch.setFormatter(formatter) -# logger.addHandler(ch) -# ---- plan to remove this in future ---- +# log startup info +debug_logging.startup_info(logger, SCRIPTDIR, running_as_frozen, running_from_inkscape, debug_active, debug_type, profiler_type) # pop '--extension' from arguments and generate extension class name from extension name # example: --extension=params will instantiate Params() class from lib.extensions. @@ -151,7 +185,4 @@ else: # if not debug nor profile mode finally: restore_stderr() - # if shapely_errors.tell(): # see above plan to remove this in future for shapely - # errormsg(shapely_errors.getvalue()) - sys.exit(0) diff --git a/lib/debug_logging.py b/lib/debug_logging.py new file mode 100644 index 000000000..f94e753e6 --- /dev/null +++ b/lib/debug_logging.py @@ -0,0 +1,197 @@ +# Authors: see git history +# +# Copyright (c) 2010 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 (ChatGPT) +# ----------------------------- +# warnings - a built-in mechanism for alerting developers to potential issues or deprecated features within their code. +# logging - to track events, errors, and other information relevant to the program's operation. +# Developers typically use logging to understand how their program behaves during execution, diagnose issues, +# and monitor performance. +# +# Inkstitch is application for Inkscape, so it is not a library, so we use logging for all messages. +# + +# 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.xyz - suggested name for inkstitch submodule xyz if needed +# +# third-party loggers: +# -------------------- +# - werkzeug - is used by flask +# - shapely.geos - was used by shapely but currently replaced by exceptions and warnings +# + +# -------------------------------------------------------------------------------------------- + +import logging +import warnings + +logger = logging.getLogger('inkstitch') + +# 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. +# - 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": "ext://__main__.logfilename", # access variable logfilename + "mode": "w" # create new file + } + }, + "loggers": { + "root": { # top level logger + "level": "ext://__main__.loglevel", # 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": "ext://__main__.logfilename", # ext: --> access variable logfilename + "mode": "w" # create new file + }, + }, + "loggers": { # configure loggers + "inkstitch": { # specific logger to inkstitch application + "level": "ext://__main__.loglevel", # 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": "ext://__main__.loglevel", # ext: --> access variable loglevel + "handlers": ["file"], # use handler 'file' for logger + } + }, +} + + +# -------------------------------------------------------------------------------------------- +# 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, ini, SCRIPTDIR): + + # replace %(SCRIPTDIR)s -> script path in filenames + config = evaluate_filenames(config, {'SCRIPTDIR': SCRIPTDIR}) + + 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 = ini.getboolean("LOGGING", "disable_logging", fallback=False) + if disable_logging: + logger.warning("Logging is disabled by configuration in ini file.") + logging.disable() # globally disable all logging of all loggers + + +# Evaluate filenames in logging configuration using myvars dictionary: +# "handlers": { +# "file": { +# "class": "logging.FileHandler", +# "filename": "%(SCRIPTDIR)s/xxx.log", # replace %(SCRIPTDIR)s -> script path +# } +# } +# config - logging configuration +# myvars - dictionary with variables +# returns: logging configuration with evaluated filenames +def evaluate_filenames(config, myvars): + import copy + cfg = copy.deepcopy(config) + for k, v in cfg.get('handlers', {}).items(): + if 'filename' in v: + cfg['handlers'][k]['filename'] = v['filename'] % myvars + return cfg + + +def startup_info(logger, SCRIPTDIR, running_as_frozen, running_from_inkscape, debug_active, debug_type, profiler_type): + 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}") + logger.info(f"Profiler type: {profiler_type}") + logger.info(f"Using logging configuration from file: {SCRIPTDIR / 'LOGGING.toml'}") + + # 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.info(f"sys.path: {sys.path}") diff --git a/lib/debug_utils.py b/lib/debug_utils.py index ef8b364d3..c680e9234 100644 --- a/lib/debug_utils.py +++ b/lib/debug_utils.py @@ -147,7 +147,7 @@ def reorder_sys_path(): # ----------------------------------------------------------------------------- # try to resolve debugger type from ini file or cmd line of bash -def resole_debug_type(ini: configparser.ConfigParser): +def resolve_debug_type(ini: configparser.ConfigParser): # enable/disable debugger from bash: -d if os.environ.get('INKSTITCH_DEBUG_ENABLE', '').lower() in ['true', '1', 'yes', 'y']: debug_enable = True @@ -166,7 +166,7 @@ def resole_debug_type(ini: configparser.ConfigParser): # try to resolve profiler type from ini file or cmd line of bash -def resole_profile_type(ini: configparser.ConfigParser): +def resolve_profile_type(ini: configparser.ConfigParser): # enable/disable profiling from bash: -p if os.environ.get('INKSTITCH_PROFILE_ENABLE', '').lower() in ['true', '1', 'yes', 'y']: profile_enable = True diff --git a/lib/extensions/break_apart.py b/lib/extensions/break_apart.py index 581e49bcb..b5104dc74 100644 --- a/lib/extensions/break_apart.py +++ b/lib/extensions/break_apart.py @@ -3,7 +3,6 @@ # Copyright (c) 2010 Authors # Licensed under the GNU GPL version 3.0 or later. See the file LICENSE for details. -import logging from copy import copy import inkex @@ -92,12 +91,7 @@ class BreakApart(InkstitchExtension): return polygons def geom_is_valid(self, geom): - # Don't complain about invalid shapes, we just want to know - logger = logging.getLogger('shapely.geos') - level = logger.level - logger.setLevel(logging.CRITICAL) valid = geom.is_valid - logger.setLevel(level) return valid def ensure_minimum_size(self, polygons, size): diff --git a/lib/extensions/print_pdf.py b/lib/extensions/print_pdf.py index 6d850ccbc..640a168b6 100644 --- a/lib/extensions/print_pdf.py +++ b/lib/extensions/print_pdf.py @@ -4,7 +4,6 @@ # Licensed under the GNU GPL version 3.0 or later. See the file LICENSE for details. import json -import logging import os import socket import sys @@ -249,9 +248,6 @@ class PrintPreviewServer(Thread): debug.log(f"exception in watcher {sys.exc_info()}") pass - def disable_logging(self): - logging.getLogger('werkzeug').setLevel(logging.ERROR) - # https://github.com/aluo-x/Learning_Neural_Acoustic_Fields/blob/master/train.py # https://github.com/pytorch/pytorch/issues/71029 def find_free_port(self): @@ -260,8 +256,6 @@ class PrintPreviewServer(Thread): return s.getsockname()[1] def run(self): - self.disable_logging() - self.host = "127.0.0.1" self.port = self.find_free_port() # exporting the port number for languages to work