improved logging and loading logic

cli/__main__.py

@@ -28,7 +28,6 @@ def setup_logging(log_level: str = "WARNING"):
       ValueError: If the log level is invalid
       RuntimeError: If logging configuration fails
   """
-  # Convert string to logging level
   numeric_level = getattr(logging, log_level.upper(), None)
   if not isinstance(numeric_level, int):
     raise ValueError(
@@ -36,15 +35,13 @@ def setup_logging(log_level: str = "WARNING"):
     )
   
   try:
-    # Configure root logger
     logging.basicConfig(
       level=numeric_level,
       format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
       datefmt='%Y-%m-%d %H:%M:%S'
     )
-    
-    # Get the boilerplates logger and set its level
-    logger = logging.getLogger('boilerplates')
+
+    logger = logging.getLogger('__name__')
     logger.setLevel(numeric_level)
   except Exception as e:
     raise RuntimeError(f"Failed to configure logging: {e}")
@@ -53,19 +50,19 @@ def setup_logging(log_level: str = "WARNING"):
 @app.callback()
 def main(
   ctx: Context,
-  loglevel: Optional[str] = Option(
+  log_level: Optional[str] = Option(
     "WARNING", 
-    "--loglevel", 
+    "--log-level", 
     help="Set the logging level (DEBUG, INFO, WARNING, ERROR, CRITICAL)"
   )
 ):
   """Main CLI application for managing boilerplates."""
   # Configure logging based on the provided log level
-  setup_logging(loglevel)
+  setup_logging(log_level)
   
   # Store log level in context for potential use by other commands
   ctx.ensure_object(dict)
-  ctx.obj['loglevel'] = loglevel
+  ctx.obj['log_level'] = log_level
 
 def init_app():
   """Initialize the application by discovering and registering modules.
@@ -155,7 +152,7 @@ def run():
   except Exception as e:
     # Handle unexpected errors - show simplified message
     console.print(f"[bold red]Unexpected error:[/bold red] {e}")
-    console.print("[dim]Use --loglevel DEBUG for more details[/dim]")
+    console.print("[dim]Use --log-level DEBUG for more details[/dim]")
     sys.exit(1)
 
 if __name__ == "__main__":

cli/core/library.py

@@ -4,7 +4,7 @@ import logging
 from .config import get_config, LibraryConfig
 # Using standard Python exceptions
 
-logger = logging.getLogger('boilerplates')
+logger = logging.getLogger(__name__)
 
 
 class Library:
@@ -33,8 +33,11 @@ class Library:
     """
     from .template import Template  # Import here to avoid circular import
     
+    logger.debug(f"Searching for template '{template_id}' in library '{self.name}' at {self.path} (module: {module_name})")
+    
     module_path = self.path / module_name
     if not module_path.exists():
+      logger.debug(f"Module path '{module_path}' does not exist in library '{self.name}'")
       return None
     
     # Try to find the template directory directly by ID
@@ -50,24 +53,31 @@ class Library:
               template.module = module_name
             # Verify this is actually the template we want
             if template.id == template_id:
+              logger.info(f"Found template '{template_id}' in library '{self.name}' (direct lookup)")
               return template
     
     # Fallback to the original method if direct lookup fails
     # This handles cases where template ID doesn't match directory structure
+    logger.debug(f"Direct lookup failed for '{template_id}', falling back to full scan in library '{self.name}'")
     for template in self.find(module_name, files, sorted=False):
       if template.id == template_id:
+        logger.info(f"Found template '{template_id}' in library '{self.name}' (full scan)")
         return template
     
+    logger.debug(f"Template '{template_id}' not found in library '{self.name}'")
     return None
 
   def find(self, module_name, files, sorted=False):
     """Find templates in this library for a specific module."""
     from .template import Template  # Import here to avoid circular import
     
+    logger.debug(f"Scanning for templates in library '{self.name}' (module: {module_name}, files: {files})")
+    
     templates = []
     module_path = self.path / module_name
     
     if not module_path.exists():
+      logger.debug(f"Module path '{module_path}' does not exist in library '{self.name}'")
       return templates
     
     # Find all files matching the specified filenames
@@ -84,6 +94,10 @@ class Library:
     if sorted:
       templates.sort(key=lambda t: t.id)
 
+    if templates:
+      logger.info(f"Found {len(templates)} templates in library '{self.name}' for module '{module_name}'")
+    else:
+      logger.debug(f"No templates found in library '{self.name}' for module '{module_name}'")
     return templates
 
 
@@ -247,6 +261,7 @@ class LibraryManager:
   def _initialize_libraries(self):
     """Initialize libraries from configuration."""
     config = get_config()
+    logger.info(f"Initializing library manager with {len(config.libraries)} configured libraries")
     
     # First, add configured libraries
     for lib_config in config.libraries:
@@ -254,7 +269,7 @@ class LibraryManager:
         library = self._create_library_from_config(lib_config)
         if library:
           self.libraries.append(library)
-          logger.debug(f"Loaded library '{lib_config.name}' with priority {lib_config.priority}")
+          logger.info(f"Loaded library '{lib_config.name}' (type: {lib_config.type}, priority: {lib_config.priority})")
       except Exception as e:
         logger.warning(f"Failed to load library '{lib_config.name}': {e}")
     
@@ -263,9 +278,13 @@ class LibraryManager:
       script_dir = Path(__file__).parent.parent.parent  # Go up from cli/core/ to project root
       default_library = Library("default", script_dir / "library", priority=-1)  # Lower priority
       self.libraries.append(default_library)
+      logger.info(f"Added default built-in library at '{script_dir / 'library'}' (priority: -1)")
     
     # Sort libraries by priority (highest first)
     self._sort_by_priority()
+    logger.info(f"Successfully initialized {len(self.libraries)} libraries")
+    if self.libraries:
+      logger.debug(f"Libraries in priority order: {[(lib.name, lib.priority) for lib in self.libraries]}")
   
   def _create_library_from_config(self, lib_config):
     """Create a Library instance from configuration.
@@ -319,15 +338,25 @@ class LibraryManager:
 
   def find(self, module_name, files, sorted=False):
     """Find templates across all libraries for a specific module."""
+    logger.debug(f"Searching across {len(self.libraries)} libraries for module '{module_name}'")
     all_templates = []
+    library_counts = {}
     
     for library in self.libraries:
       templates = library.find(module_name, files, sorted=sorted)
+      if templates:
+        library_counts[library.name] = len(templates)
       all_templates.extend(templates)
 
     if sorted:
       all_templates.sort(key=lambda t: t.id)
 
+    if all_templates:
+      logger.info(f"Found {len(all_templates)} total templates for module '{module_name}'")
+      if library_counts:
+        logger.debug(f"Template distribution: {library_counts}")
+    else:
+      logger.debug(f"No templates found for module '{module_name}' across any library")
     return all_templates
 
   def find_by_id(self, module_name, files, template_id):
@@ -353,9 +382,12 @@ class LibraryManager:
         returning the first matching template found. This allows higher-priority libraries
         to override templates from lower-priority ones.
     """
+    logger.debug(f"Searching for template '{template_id}' across {len(self.libraries)} libraries (module: {module_name})")
     for library in self.libraries:  # Already sorted by priority
       template = library.find_by_id(module_name, files, template_id)
       if template:
-        logger.debug(f"Found template '{template_id}' in library '{library.name}' (priority: {library.priority})")
+        logger.info(f"Retrieved template '{template_id}' from library '{library.name}' (priority: {library.priority})")
         return template
+    
+    logger.warning(f"Template '{template_id}' not found in any library")
     return None

cli/core/module.py

@@ -26,10 +26,13 @@ class Module(ABC):
         f"Module {self.__class__.__name__} must define name, description, and files"
       )
     
+    logger.info(f"Initializing module '{self.name}'")
+    logger.debug(f"Module '{self.name}' configuration: files={self.files}, description='{self.description}'")
     self.libraries = LibraryManager()
     
     # Initialize variables if the subclass defines _init_variables method
     if hasattr(self, '_init_variables'):
+      logger.debug(f"Module '{self.name}' has variable initialization method")
       self._init_variables()
       
       # Validate module variable registry consistency after initialization
@@ -37,12 +40,18 @@ class Module(ABC):
       # The registry defines parent-child relationships where child variables like 'traefik.tls.certresolver' can only be used
       # when their parents ('traefik' and 'traefik.tls') are enabled. This prevents invalid module configurations.
       if hasattr(self, 'variables') and self.variables:
+        var_count = len(self.variables.get_all_variables())
+        logger.info(f"Module '{self.name}' registered {var_count} variables")
+        
         registry_errors = self.variables.validate_parent_child_relationships()
         if registry_errors:
           error_msg = f"Module '{self.name}' has invalid variable registry:\n" + "\n".join(f"  - {e}" for e in registry_errors)
+          logger.error(error_msg)
           raise ValueError(error_msg)
+        logger.debug(f"Module '{self.name}' variable registry validation completed successfully")
     
     self.metadata = self._build_metadata()
+    logger.info(f"Module '{self.name}' initialization completed successfully")
   
   def _build_metadata(self) -> Dict[str, Any]:
     """Build metadata from class attributes."""
@@ -58,21 +67,31 @@ class Module(ABC):
     
     return metadata
 
-
   def list(self):
     """List all templates."""
+    logger.debug(f"Listing templates for module '{self.name}'")
     templates = self.libraries.find(self.name, self.files, sorted=True)
     
-    # Enrich each template with module variables
+    if templates:
+      logger.info(f"Listing {len(templates)} templates for module '{self.name}'")
+    else:
+      logger.info(f"No templates found for module '{self.name}'")
+    
+    # Display templates without enrichment (enrichment only needed for generation)
     for template in templates:
-      self._enrich_template_with_variables(template)
       console.print(f"[cyan]{template.id}[/cyan] - {template.name}")
     
     return templates
 
   def show(self, id: str = Argument(..., help="Template ID")):
     """Show template details."""
-    template = self._get_template(id)
+    logger.debug(f"Showing template '{id}' from module '{self.name}'")
+    # Get template directly from library without enrichment (not needed for display)
+    template = self.libraries.find_by_id(self.name, self.files, id)
+    
+    if not template:
+      logger.debug(f"Template '{id}' not found in module '{self.name}'")
+      raise FileNotFoundError(f"Template '{id}' not found in module '{self.name}'")
 
     # Header
     version = f" v{template.version}" if template.version else ""
@@ -90,7 +109,7 @@ class Module(ABC):
       if value:
         console.print(f"{label}: [cyan]{value}[/cyan]")
     
-    # Variables
+    # Variables (show raw template variables without module enrichment)
     if template.vars:
       console.print(f"Variables: [cyan]{', '.join(sorted(template.vars))}[/cyan]")
     
@@ -98,17 +117,6 @@ class Module(ABC):
     if template.content:
       print(f"\n{template.content}")
 
-  def _get_template(self, template_id: str):
-    """Get template by ID with unified error handling and variable enrichment."""
-    template = self.libraries.find_by_id(self.name, self.files, template_id)
-    
-    if not template:
-      raise FileNotFoundError(f"Template '{template_id}' not found in module '{self.name}'")
-    
-    # Enrich template with module variables if available
-    self._enrich_template_with_variables(template)
-    
-    return template
 
   def _enrich_template_with_variables(self, template):
     """Enrich template with module variable registry defaults (optimized).
@@ -121,9 +129,12 @@ class Module(ABC):
     """
     # Skip if already enriched or no variables
     if template._is_enriched or not hasattr(self, 'variables') or not self.variables:
+      if template._is_enriched:
+        logger.debug(f"Template '{template.id}' already enriched, skipping")
+      else:
+        logger.debug(f"Module '{self.name}' has no variables, skipping enrichment for '{template.id}'")
       return
     
-    logger = logging.getLogger('boilerplates')
     logger.debug(f"Enriching template '{template.id}' with {len(self.variables.get_all_variables())} module variables")
     
     # Get template variables first (this is cached)
@@ -145,7 +156,8 @@ class Module(ABC):
           module_defaults[var_name] = var_obj.default
     
     if module_defaults:
-      logger.debug(f"Module provides {len(module_defaults)} defaults for used variables: {module_defaults}")
+      logger.debug(f"Module provides {len(module_defaults)} defaults for used variables")
+      logger.debug(f"Module default values: {module_defaults}")
     
     # Merge with template taking precedence
     final_vars = dict(module_vars)
@@ -166,7 +178,10 @@ class Module(ABC):
     template.vars = final_vars
     template._is_enriched = True
     
-    logger.debug(f"Template '{template.id}' enriched with {len(final_vars)} final variables")
+    if final_vars:
+      logger.info(f"Template '{template.id}' enriched with {len(final_vars)} variables from module '{self.name}'")
+    else:
+      logger.debug(f"Template '{template.id}' has no variables after enrichment")
 
   def _check_template_readiness(self, template):
     """Check if template is ready for generation (replaces complex validation).
@@ -177,7 +192,7 @@ class Module(ABC):
     Raises:
         ValueError: If template has critical issues preventing generation
     """
-    logger = logging.getLogger('boilerplates')
+    logger.debug(f"Checking template readiness for '{template.id}'")
     errors = []
     
     # Check for basic template issues
@@ -208,8 +223,11 @@ class Module(ABC):
       errors.append(f"Template has Jinja2 syntax errors: {str(e)}")
     
     if errors:
+      logger.error(f"Template '{template.id}' failed readiness check with {len(errors)} errors")
       error_msg = f"Template '{template.id}' is not ready for generation:\n" + "\n".join(f"  - {e}" for e in errors)
       raise ValueError(error_msg)
+    
+    logger.debug(f"Template '{template.id}' passed readiness check")
 
   def generate(
     self,
@@ -218,18 +236,29 @@ class Module(ABC):
   ):
     """Generate from template."""
 
+    logger.info(f"Starting generation for template '{id}' from module '{self.name}'")
     # Fetch template from library
-    template = self._get_template(id)
+    template = self.libraries.find_by_id(self.name, self.files, id)
+    
+    if not template:
+      logger.error(f"Template '{id}' not found for generation in module '{self.name}'")
+      raise FileNotFoundError(f"Template '{id}' not found in module '{self.name}'")
+    
+    # Enrich template with module variables if available
+    self._enrich_template_with_variables(template)
     
-    # Check for critical template issues during enrichment
+    # Check for critical template issues after enrichment
     self._check_template_readiness(template)
     
+    logger.info(f"Template '{id}' generation completed successfully for module '{self.name}'")
     print("TEST SUCCESSFUL")
   
   def register_cli(self, app: Typer):
     """Register module commands with the main app."""
+    logger.debug(f"Registering CLI commands for module '{self.name}'")
     module_app = Typer()
     module_app.command()(self.list)
     module_app.command()(self.show)
     module_app.command()(self.generate)
     app.add_typer(module_app, name=self.name, help=self.description)
+    logger.info(f"Module '{self.name}' CLI commands registered")

cli/core/registry.py

@@ -1,4 +1,7 @@
 """Module registry system."""
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 class ModuleRegistry:
@@ -6,20 +9,43 @@ class ModuleRegistry:
   
   def __init__(self):
     self._modules = {}
+    logger.debug("Initializing module registry")
   
   def register(self, module_class):
     """Register a module class."""
     # Module class defines its own name attribute
+    logger.debug(f"Attempting to register module class '{module_class.name}'")
+    
+    if module_class.name in self._modules:
+      logger.warning(f"Module '{module_class.name}' already registered, replacing with new implementation")
+    
     self._modules[module_class.name] = module_class
+    logger.info(f"Registered module '{module_class.name}' (total modules: {len(self._modules)})")
+    logger.debug(f"Module '{module_class.name}' details: description='{module_class.description}', files={module_class.files}")
   
   def create_instances(self):
     """Create instances of all registered modules."""
+    logger.info(f"Creating instances for {len(self._modules)} registered modules")
     instances = []
+    failed_modules = []
+    
     for name in sorted(self._modules.keys()):
       try:
-        instances.append(self._modules[name]())
+        logger.debug(f"Attempting to create instance of module '{name}'")
+        instance = self._modules[name]()
+        instances.append(instance)
+        logger.debug(f"Successfully instantiated module '{name}'")
       except Exception as e:
+        logger.error(f"Failed to instantiate module '{name}': {e}")
+        failed_modules.append(name)
         print(f"Warning: Could not instantiate {name}: {e}")
+    
+    if failed_modules:
+      logger.warning(f"Failed to instantiate {len(failed_modules)} modules: {failed_modules}")
+    
+    logger.info(f"Successfully created {len(instances)} module instances out of {len(self._modules)} registered")
+    if instances:
+      logger.debug(f"Active modules: {[inst.name for inst in instances]}")
     return instances
 
 # Global registry

cli/core/template.py

@@ -83,12 +83,14 @@ class Template:
       template.frontmatter_variables = frontmatter_data.get('variables', {})
       
       if template.frontmatter_variables:
-        logger.debug(f"Template '{template.id}' has frontmatter variables: {list(template.frontmatter_variables.keys())}")
+        logger.debug(f"Template '{template.id}' has {len(template.frontmatter_variables)} frontmatter variables: {list(template.frontmatter_variables.keys())}")
       
-      logger.debug(f"Successfully loaded template '{template.id}' from {file_path}")
+      logger.info(f"Loaded template '{template.id}' (v{template.version or 'unversioned'}, {template.size} bytes)")
+      logger.debug(f"Template details: author='{template.author}', tags={template.tags}")
       return template
-    except Exception:
+    except Exception as e:
       # If frontmatter parsing fails, create a basic Template object
+      logger.warning(f"Failed to parse frontmatter for {file_path}: {e}. Creating basic template.")
       return cls(file_path=file_path)
   
   @staticmethod
@@ -113,8 +115,8 @@ class Template:
     """Create standardized Jinja2 environment for consistent template processing."""
     return Environment(
       loader=BaseLoader(),
-      trim_blocks=True,           # Remove first newline after block tags
-      lstrip_blocks=True,         # Strip leading whitespace from block tags  
+      trim_blocks=True,  # Remove first newline after block tags
+      lstrip_blocks=True,  # Strip leading whitespace from block tags
       keep_trailing_newline=False  # Remove trailing newlines
     )
   
@@ -129,12 +131,18 @@ class Template:
     """Get variables actually used in template (cached)."""
     ast = self._get_ast()
     used_variables = meta.find_undeclared_variables(ast)
+    initial_count = len(used_variables)
     
     # Handle dotted notation variables
+    dotted_vars = []
     for node in ast.find_all(nodes.Getattr):
       dotted_name = Template._build_dotted_name(node)
       if dotted_name:
         used_variables.add(dotted_name)
+        dotted_vars.append(dotted_name)
+    
+    if dotted_vars:
+      logger.debug(f"Found {len(dotted_vars)} dotted variables in addition to {initial_count} simple variables")
     
     return used_variables
   
@@ -145,25 +153,31 @@ class Template:
       post = frontmatter.load(f)
     return post.metadata, post.content
 
-
   def render(self, variable_values: Dict[str, Any]) -> str:
     """Render the template with the provided variable values."""
     logger = logging.getLogger('boilerplates')
     
     try:
+      logger.debug(f"Rendering template '{self.id}' with {len(variable_values)} provided variables")
       env = self._create_jinja_env()
       jinja_template = env.from_string(self.content)
       # Merge template vars (with defaults) with provided values
       # All variables should be defined at this point due to validation
       merged_variable_values = {**self.vars, **variable_values}
+      logger.debug(f"Final render context has {len(merged_variable_values)} variables")
+      
       rendered_content = jinja_template.render(**merged_variable_values)
+      initial_size = len(rendered_content)
       
       # Clean up excessive blank lines and whitespace
       rendered_content = re.sub(r'\n\s*\n\s*\n+', '\n\n', rendered_content)
-      return rendered_content.strip()
+      final_content = rendered_content.strip()
+      
+      logger.info(f"Successfully rendered template '{self.id}' ({initial_size} -> {len(final_content)} bytes)")
+      return final_content
       
     except Exception as e:
-      logger.error(f"Jinja2 template rendering failed: {e}")
+      logger.error(f"Failed to render template '{self.id}': {e}")
       raise ValueError(f"Failed to render template: {e}")
 
   def _parse_template_variables(self, template_content: str, frontmatter_vars: Dict[str, Any] = None) -> Dict[str, Any]:
@@ -191,7 +205,10 @@ class Template:
       
       # Get all variables used in template
       all_variables = self._get_used_variables()
-      logger.debug(f"Template uses {len(all_variables)} variables: {sorted(all_variables)}")
+      if all_variables:
+        logger.debug(f"Template uses {len(all_variables)} variables: {sorted(all_variables)}")
+      else:
+        logger.debug("Template does not use any variables")
       
       # Initialize vars dict with all variables (default to None)
       vars_dict = {var_name: None for var_name in all_variables}
@@ -212,7 +229,8 @@ class Template:
               vars_dict[dotted_name] = node.args[0].value
       
       if template_defaults:
-        logger.debug(f"Template defines {len(template_defaults)} defaults: {template_defaults}")
+        logger.info(f"Template defines {len(template_defaults)} variable defaults")
+        logger.debug(f"Template default values: {template_defaults}")
       
       # Process frontmatter variables (frontmatter takes precedence)
       if frontmatter_vars:
@@ -230,7 +248,8 @@ class Template:
             vars_dict[var_name] = var_config
         
         if frontmatter_overrides:
-          logger.debug(f"Frontmatter overrides {len(frontmatter_overrides)} variables: {frontmatter_overrides}")
+          logger.info(f"Frontmatter defines/overrides {len(frontmatter_overrides)} variables")
+          logger.debug(f"Frontmatter variable values: {frontmatter_overrides}")
       
       # Cache result if no frontmatter (pure template parsing)
       if not frontmatter_vars:
@@ -240,7 +259,3 @@ class Template:
     except Exception as e:
       logger.debug(f"Error parsing template variables: {e}")
       return {}
-
-
-
-

cli/core/variables.py

@@ -1,6 +1,9 @@
 from typing import Any, Dict, List, Optional
 from dataclasses import dataclass, field
 from enum import Enum
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 class VariableType(Enum):
@@ -44,27 +47,53 @@ class VariableRegistry:
   def register_variable(self, variable: Variable) -> Variable:
     """Register a variable in the registry."""
     full_name = variable.get_full_name()
+    logger.debug(f"Attempting to register variable '{full_name}' of type '{variable.type}'")
     
     # Convert string type to enum if needed
     if isinstance(variable.type, str):
       try:
+        original_type = variable.type
         variable.type = VariableType(variable.type.lower())
+        logger.debug(f"Converted string type '{original_type}' to VariableType.{variable.type.name} for '{full_name}'")
       except ValueError:
+        logger.warning(f"Unknown variable type '{variable.type}' for '{full_name}', defaulting to STR")
         variable.type = VariableType.STR
     
     # Validate enum options
     if variable.type == VariableType.ENUM and not variable.options:
+      logger.error(f"Variable '{full_name}' of type 'enum' must have options")
       raise ValueError(f"Variable '{full_name}' of type 'enum' must have options")
     
+    if variable.type == VariableType.ENUM:
+      logger.debug(f"Variable '{full_name}' has {len(variable.options)} enum options: {variable.options}")
+    
+    if variable.default is not None:
+      logger.debug(f"Variable '{full_name}' has default value: {variable.default}")
+    
+    # Check if already registered
+    if full_name in self._variables:
+      logger.debug(f"Variable '{full_name}' already registered, replacing")
+    
     self._variables[full_name] = variable
+    logger.info(f"Registered variable '{full_name}' (type: {variable.type.name}, parent: {variable.parent or 'none'})")
     return variable
   
   def get_variable(self, name: str) -> Optional[Variable]:
     """Get variable by full name."""
-    return self._variables.get(name)
+    variable = self._variables.get(name)
+    if variable:
+      logger.debug(f"Retrieved variable '{name}' from registry (type: {variable.type.name})")
+    else:
+      logger.debug(f"Variable '{name}' not found in registry (available: {list(self._variables.keys())})")
+    return variable
   
   def get_all_variables(self) -> Dict[str, Variable]:
     """Get all registered variables."""
+    count = len(self._variables)
+    if count > 0:
+      logger.debug(f"Retrieved {count} variables from registry: {sorted(self._variables.keys())}")
+    else:
+      logger.debug("No variables registered in registry")
     return self._variables.copy()
   
   def get_parent_variables(self) -> List[Variable]:
@@ -74,25 +103,49 @@ class VariableRegistry:
       if var.parent:
         parent_names.add(var.parent)
     
-    return [self._variables[name] for name in parent_names if name in self._variables]
+    parent_vars = [self._variables[name] for name in parent_names if name in self._variables]
+    logger.debug(f"Found {len(parent_vars)} parent variables: {sorted(parent_names)}")
+    return parent_vars
   
   def get_children_of(self, parent_name: str) -> List[Variable]:
     """Get all child variables of a specific parent."""
-    return [var for var in self._variables.values() if var.parent == parent_name]
+    children = [var for var in self._variables.values() if var.parent == parent_name]
+    logger.debug(f"Found {len(children)} children for parent '{parent_name}'")
+    return children
   
   def validate_parent_child_relationships(self) -> List[str]:
     """Validate that all parent-child relationships are consistent."""
+    logger.debug(f"Starting validation of parent-child relationships for {len(self._variables)} variables")
     errors = []
+    parent_count = 0
+    child_count = 0
     
     for var in self._variables.values():
       if var.parent:
+        child_count += 1
         # Check if parent exists
         if var.parent not in self._variables:
-          errors.append(f"Variable '{var.get_full_name()}' references non-existent parent '{var.parent}'")
+          error_msg = f"Variable '{var.get_full_name()}' references non-existent parent '{var.parent}'"
+          logger.warning(f"Validation error: {error_msg}")
+          errors.append(error_msg)
         else:
           parent_var = self._variables[var.parent]
           # Parent should generally be boolean if it has children
           if parent_var.type != VariableType.BOOL:
+            warning_msg = f"Parent variable '{var.parent}' is type '{parent_var.type.name}' but has children"
+            logger.warning(f"Validation warning: {warning_msg}")
             errors.append(f"Parent variable '{var.parent}' should be boolean type (has children)")
+      else:
+        # Count root/parent variables
+        children = self.get_children_of(var.name)
+        if children:
+          parent_count += 1
+    
+    if errors:
+      logger.error(f"Variable registry validation failed with {len(errors)} errors")
+      for error in errors:
+        logger.debug(f"  - {error}")
+    else:
+      logger.info(f"Variable registry validation passed ({parent_count} parents, {child_count} children)")
     
     return errors