debug logging (#2)

Author: lexakimov

setup.py

@@ -2,7 +2,7 @@
 
 setup(
     name='xmlgenerator',
-    version='0.1.0',
+    version='0.2.0',
     packages=find_packages(exclude=("tests", "tests.*")),
     entry_points={
         'console_scripts': [

xmlgenerator/arguments.py

@@ -1,9 +1,12 @@
+import logging
 import sys
 from argparse import ArgumentParser, HelpFormatter
 from pathlib import Path
 
 import shtab
 
+logger = logging.getLogger(__name__)
+
 
 class MyParser(ArgumentParser):
     def error(self, message):
@@ -99,6 +102,10 @@ def parse_args():
     parser = _get_parser()
     args = parser.parse_args()
 
+    # setup logger
+    log_level = logging.DEBUG if args.debug else logging.INFO
+    logger.setLevel(log_level)
+
     if args.config_yaml:
         config_path = Path(args.config_yaml)
         if not config_path.exists() or not config_path.is_file():

xmlgenerator/bootstrap.py

@@ -1,39 +1,55 @@
+import logging
+
 from lxml import etree
+from xmlschema import XMLSchema
+
+import xmlgenerator
+from xmlgenerator import configuration, validation, randomization, substitution, generator
 from xmlgenerator.arguments import parse_args
 from xmlgenerator.configuration import load_config
 from xmlgenerator.generator import XmlGenerator
 from xmlgenerator.randomization import Randomizer
 from xmlgenerator.substitution import Substitutor
 from xmlgenerator.validation import XmlValidator
-from xmlschema import XMLSchema
-
 
 # TODO Generator - обработка стандартных xsd типов
 # TODO кастомные переменные для локального контекста
 # TODO валидация по Schematron
-# TODO debug logging
 # TODO типизировать
 # TODO Почистить и перевести комментарии
 # TODO Дописать тесты
-# TODO нативная сборка
-# TODO выкладка на github releases
-# TODO опубликовать https://pypi.org/
+
+logging.basicConfig(level=logging.WARN, format='%(asctime)s [%(name)-26s] %(levelname)-6s - %(message)s')
+
+logger = logging.getLogger('xmlgenerator.bootstrap')
 
 
 def main():
+    try:
+        _main()
+    except KeyboardInterrupt as ex:
+        logger.info('processing interrupted')
+
+
+def _main():
     args, xsd_files, output_path = parse_args()
+    _setup_loggers(args)
 
-    config = load_config(args.config_yaml)
+    if output_path:
+        logger.debug('specified output path: %s', output_path.absolute())
+    else:
+        logger.debug('output path is not specified. Generated xml will be written to stdout')
 
-    print(f"Найдено схем: {len(xsd_files)}")
+    config = load_config(args.config_yaml)
 
     randomizer = Randomizer(args.seed)
     substitutor = Substitutor(randomizer)
     generator = XmlGenerator(randomizer, substitutor)
     validator = XmlValidator(args.validation, args.fail_fast)
 
+    logger.debug('found %s schemas', len(xsd_files))
     for xsd_file in xsd_files:
-        print(f"Processing schema: {xsd_file.name}")
+        logger.debug('processing schema: %s', xsd_file.name)
 
         # get configuration override for current schema
         local_config = config.get_for_file(xsd_file.name)
@@ -52,6 +68,7 @@ def main():
 
         # Print out to console
         if not output_path:
+            logger.debug('print xml document to stdout')
             print(decoded)
 
         # Validation (if enabled)
@@ -65,9 +82,20 @@ def main():
             output_file = output_path
             if output_path.is_dir():
                 output_file = output_path / f'{xml_filename}.xml'
+            logger.debug('save xml document as %s', output_file.absolute())
             with open(output_file, 'wb') as f:
                 f.write(xml_str)
-            print(f"Saved document: {output_file.name}")
+
+
+def _setup_loggers(args):
+    log_level = logging.DEBUG if args.debug else logging.INFO
+    logger.setLevel(log_level)
+    configuration.logger.setLevel(log_level)
+    validation.logger.setLevel(log_level)
+    xmlgenerator.generator.logger.setLevel(log_level)
+    substitution.logger.setLevel(log_level)
+    randomization.logger.setLevel(log_level)
+
 
 if __name__ == "__main__":
     main()

xmlgenerator/configuration.py

@@ -1,11 +1,14 @@
 import dataclasses
+import logging
 import re
 import sys
 from dataclasses import dataclass, field, Field
 from typing import Dict, get_args, get_origin, Any
 
 import yaml
 
+logger = logging.getLogger(__name__)
+
 
 @dataclass
 class RandomizationConfig:
@@ -45,24 +48,31 @@ class Config:
     def get_for_file(self, xsd_name):
         for pattern, conf in self.specific.items():
             if re.match(pattern, xsd_name):
+                logger.debug("resolved configration with pattern '%s'", pattern)
                 base_dict = dataclasses.asdict(self.global_)
                 override_dict = dataclasses.asdict(conf, dict_factory=lambda x: {k: v for (k, v) in x if v is not None})
                 updated_dict = _recursive_update(base_dict, override_dict)
                 merged_config = _map_to_class(updated_dict, GeneratorConfig, "")
                 local_override = conf.value_override
                 global_override = self.global_.value_override
                 merged_config.value_override = _merge_dicts(local_override, global_override)
+                _log_configration('using specific configuration:', merged_config)
                 return merged_config
 
+        _log_configration('using global configration:', self.global_)
         return self.global_
 
 
 def load_config(file_path: str | None) -> "Config":
     if not file_path:
-        return Config()
+        config = Config()
+        _log_configration("created default configuration:", config)
+        return config
     with open(file_path, 'r') as file:
         config_data: dict[str, str] = yaml.safe_load(file) or {}
-        return _map_to_class(config_data, Config, "")
+        config = _map_to_class(config_data, Config, "")
+        _log_configration(f"configuration loaded from {file_path}:", config)
+        return config
 
 
 def _map_to_class(data_dict: dict, cls, parent_path: str):
@@ -80,7 +90,7 @@ def _map_to_class(data_dict: dict, cls, parent_path: str):
             for yaml_name, value in data_dict.items():
                 class_field_name = yaml_name if yaml_name != "global" else "global_"
                 if class_field_name not in class_fields:
-                    print(f"YAML parse error: unexpected property: {parent_path}.{yaml_name}", file=sys.stderr)
+                    logger.error('YAML parse error: unexpected property: %s.%s', parent_path, yaml_name)
                     sys.exit(1)
 
                 # Определяем тип поля
@@ -90,10 +100,10 @@ def _map_to_class(data_dict: dict, cls, parent_path: str):
         # Проверка на отсутствие обязательных полей
         missing_fields = required_fields - yaml_items.keys()
         if missing_fields:
-            print(f"YAML parse error: missing required properties in {parent_path}:", file=sys.stderr)
+            logger.error('YAML parse error: missing required properties in %s:', parent_path)
             for missing_field in missing_fields:
                 yaml_field_name = missing_field if missing_field != "global_" else "global"
-                print(yaml_field_name, file=sys.stderr)
+                logger.error(yaml_field_name)
             sys.exit(1)
 
         return cls(**yaml_items)
@@ -133,3 +143,12 @@ def _merge_dicts(base_dict, extra_dict):
         if key not in merged_dict:
             merged_dict[key] = value
     return merged_dict
+
+
+def _log_configration(message, config):
+    if logger.isEnabledFor(logging.DEBUG):
+        logger.debug(message)
+        as_dict = dataclasses.asdict(config)
+        dumped = yaml.safe_dump(as_dict, allow_unicode=True, width=float("inf"), sort_keys=False, indent=4)
+        for line in dumped.splitlines():
+            logger.debug('|\t%s', line)

xmlgenerator/generator.py

@@ -1,5 +1,5 @@
+import logging
 import re
-import sys
 
 import rstr
 import xmlschema
@@ -12,6 +12,8 @@
 from xmlgenerator.randomization import Randomizer
 from xmlgenerator.substitution import Substitutor
 
+logger = logging.getLogger(__name__)
+
 
 class XmlGenerator:
     def __init__(self, randomizer: Randomizer, substitutor: Substitutor):
@@ -28,21 +30,27 @@ def _add_elements(self, xml_element: etree.Element, xsd_element, local_config: G
         rnd = self.randomizer.rnd
 
         xsd_element_type = getattr(xsd_element, 'type', None)
+        logger.debug('fill down element "%s" with type %s', xsd_element.name, type(xsd_element_type).__name__)
 
         # Add attributes if they are
         attributes = getattr(xsd_element, 'attributes', dict())
         if len(attributes) > 0 and xsd_element_type.local_name != 'anyType':
+            logger.debug('add attributes to element %s', xsd_element.name)
             for attr_name, attr in attributes.items():
+                logger.debug('attribute: %s', attr_name)
                 use = attr.use  # optional | required | prohibited
                 if use == 'prohibited':
+                    logger.debug('skipped')
                     continue
                 elif use == 'optional':
                     if rnd.random() > local_config.randomization.probability:
-                        continue    # skip optional attribute
+                        logger.debug('skipped')
+                        continue  # skip optional attribute
 
                 attr_value = self._generate_value(attr.type, attr_name, local_config)
                 if attr_value is not None:
                     xml_element.set(attr_name, str(attr_value))
+                    logger.debug(f'attribute %s set with value %s', attr_name, attr_value)
 
         # Process child elements --------------------------------------------------------------------------------------
         if isinstance(xsd_element, XsdElement):
@@ -69,7 +77,7 @@ def _add_elements(self, xml_element: etree.Element, xsd_element, local_config: G
             group_min_occurs = getattr(xsd_element, 'min_occurs', None)
             group_max_occurs = getattr(xsd_element, 'max_occurs', None)
             group_min_occurs = group_min_occurs if group_min_occurs is not None else 0
-            group_max_occurs = group_max_occurs if group_max_occurs is not None else 10 # TODO externalize
+            group_max_occurs = group_max_occurs if group_max_occurs is not None else 10  # TODO externalize
             group_occurs = rnd.randint(group_min_occurs, group_max_occurs)
 
             if model == 'all':
@@ -80,7 +88,7 @@ def _add_elements(self, xml_element: etree.Element, xsd_element, local_config: G
                         element_min_occurs = getattr(xsd_child_element_type, 'min_occurs', None)
                         element_max_occurs = getattr(xsd_child_element_type, 'max_occurs', None)
                         element_min_occurs = element_min_occurs if element_min_occurs is not None else 0
-                        element_max_occurs = element_max_occurs if element_max_occurs is not None else 10 # TODO externalize
+                        element_max_occurs = element_max_occurs if element_max_occurs is not None else 10  # TODO externalize
                         element_occurs = rnd.randint(element_min_occurs, element_max_occurs)
 
                         for _ in range(element_occurs):
@@ -96,7 +104,7 @@ def _add_elements(self, xml_element: etree.Element, xsd_element, local_config: G
                         element_min_occurs = getattr(xsd_child_element_type, 'min_occurs', None)
                         element_max_occurs = getattr(xsd_child_element_type, 'max_occurs', None)
                         element_min_occurs = element_min_occurs if element_min_occurs is not None else 0
-                        element_max_occurs = element_max_occurs if element_max_occurs is not None else 10 # TODO externalize
+                        element_max_occurs = element_max_occurs if element_max_occurs is not None else 10  # TODO externalize
                         element_occurs = rnd.randint(element_min_occurs, element_max_occurs)
 
                         if isinstance(xsd_child_element_type, XsdElement):
@@ -123,7 +131,7 @@ def _add_elements(self, xml_element: etree.Element, xsd_element, local_config: G
                     element_min_occurs = getattr(xsd_child_element_type, 'min_occurs', None)
                     element_max_occurs = getattr(xsd_child_element_type, 'max_occurs', None)
                     element_min_occurs = element_min_occurs if element_min_occurs is not None else 0
-                    element_max_occurs = element_max_occurs if element_max_occurs is not None else 10 # TODO externalize
+                    element_max_occurs = element_max_occurs if element_max_occurs is not None else 10  # TODO externalize
                     element_occurs = rnd.randint(element_min_occurs, element_max_occurs)
 
                     for _ in range(element_occurs):
@@ -232,7 +240,6 @@ def _generate_value(self, xsd_type, target_name, local_config: GeneratorConfig)
 
         raise RuntimeError(f"Can't generate value - unhandled type. Target name: {target_name}")
 
-
     def _generate_value_by_type(self, xsd_type, target_name, patterns, min_length, max_length, min_value, max_value,
                                 total_digits, fraction_digits) -> str | None:
 
@@ -295,11 +302,15 @@ def _generate_string(self, target_name, patterns, min_length, max_length):
             xeger = rstr.xeger(random_pattern.attrib['value'])
             xeger = re.sub(r'\s', ' ', xeger)
             if min_length > -1 and len(xeger) < min_length:
-                print(
-                    f"Possible mistake in schema: {target_name} generated value '{xeger}' can't be shorter than {min_length}",
-                    file=sys.stderr)
+                logger.warning(
+                    "Possible mistake in schema: %s generated value '%s' can't be shorter than %s",
+                    target_name, xeger, min_length
+                )
             if -1 < max_length < len(xeger):
-                print(f"Possible mistake in schema: {target_name} generated value '{xeger}' can't be longer than {max_length}", file=sys.stderr)
+                logger.warning(
+                    "Possible mistake in schema: %s generated value '%s' can't be longer than %s",
+                    target_name, xeger, max_length
+                )
             return xeger
 
         # Иначе генерируем случайную строку

xmlgenerator/randomization.py

@@ -1,12 +1,22 @@
+import logging
 import random
 import string
+import sys
 from datetime import datetime, timedelta
 
 from faker import Faker
 
+logger = logging.getLogger(__name__)
+
 
 class Randomizer:
     def __init__(self, seed=None):
+        if not seed:
+            seed = random.randrange(sys.maxsize)
+            logger.debug('initialize with random seed: %s', seed)
+        else:
+            logger.debug('initialize with provided seed: %s', seed)
+
         self.rnd = random.Random(seed)
         self.fake = Faker(locale='ru_RU')
         self.fake.seed_instance(seed)

xmlgenerator/substitution.py

@@ -1,3 +1,4 @@
+import logging
 import re
 import uuid
 
@@ -9,6 +10,8 @@
 
 _pattern = re.compile(pattern=r'\{\{\s*(?:(?P<function>\S*?)(?:\(\s*(?P<argument>[^)]*)\s*\))?\s*(?:\|\s*(?P<modifier>.*?))?)?\s*}}')
 
+logger = logging.getLogger(__name__)
+
 class Substitutor:
     def __init__(self, randomizer: Randomizer):
         fake = randomizer.fake
@@ -69,6 +72,11 @@ def reset_context(self, xsd_filename, config_local):
         resolved_value = self._process_expression(output_filename)
         self._local_context['output_filename'] = resolved_value
 
+        logger.debug('local_context reset')
+        logger.debug('local_context["source_filename"]  = %s', xsd_filename)
+        logger.debug('local_context["source_extracted"] = %s (extracted with regexp %s)', source_extracted, source_filename)
+        logger.debug('local_context["output_filename"]  = %s', resolved_value)
+
     def get_output_filename(self):
         return self._local_context.get("output_filename")
 
@@ -83,6 +91,7 @@ def substitute_value(self, target_name, items):
         return False, None
 
     def _process_expression(self, expression):
+        logger.debug('processing expression: %s', expression)
         global_context = self._global_context
         local_context = self._local_context
         result_value: str = expression
@@ -115,4 +124,5 @@ def _process_expression(self, expression):
         for span, replacement in reversed(list(span_to_replacement.items())):
             result_value = result_value[:span[0]] + replacement + result_value[span[1]:]
 
+        logger.debug('expression resolved to value: %s', result_value)
         return result_value