# Development: See everything
logger.setLevel(logging.DEBUG)

# Production: Only errors and critical issues
logger.setLevel(logging.ERROR)

# No code changes needed - configure once, control globally

# Same log message goes to multiple places simultaneously
logger.debug("Processing asset X")
# → Console (for developer watching)
# → File (for post-mortem analysis)
# → Network (for centralized monitoring)
# → UI widget (for user feedback)

# Automatic metadata
[2026-02-25 14:32:15,123] [DEBUG] [high_to_game_ready.tool:245] Processing asset X
#  ^timestamp              ^level    ^module:line             ^your message

# Compare to print():
Processing asset X  # What? When? Where? Why?

# JSON logging for machine parsing
{"timestamp": "2026-02-25T14:32:15.123", "level": "DEBUG",
 "module": "high_to_game_ready.tool", "message": "Processing asset X"}

# Try that with print statements

# Logging is lazy - expensive operations only happen if the level is enabled
logger.debug("Expensive data: %s", expensive_function())  # Only called if DEBUG enabled

# Print always executes
print(f"Data: {expensive_function()}")  # Always called, always slow

# Bad
logger.error("File not found")

# Good
logger.error(f"Failed to load config file: {config_path} (working dir: {os.getcwd()})")

# Bad
logger.error("Asset validation failed")

# Good
logger.error(f"Asset '{asset_name}' missing required UV set 'UVChannel_0'. "
             f"Ensure asset is unwrapped before export.")

# Bad
logger.debug("Processing asset")

# Good
logger.debug(f"Processing asset {asset_index}/{total_assets}: {asset_path} "
             f"(resolution={resolution}, quality={quality})")

# Entry
logger.info(f"Starting texture bake: {len(assets)} assets, output={output_dir}")

# Progress (for long operations)
logger.info(f"Texture bake progress: {completed}/{total} ({percent:.1f}%)")

# Exit with result
logger.info(f"Texture bake completed: {success_count} succeeded, {fail_count} failed "
            f"(duration={elapsed:.2f}s)")

root_logger = logging.getLogger()  # Root
app_logger = logging.getLogger("myapp")  # Top-level
module_logger = logging.getLogger("myapp.module")  # Child
submodule_logger = logging.getLogger("myapp.module.submodule")  # Grandchild

# Module A
logger = logging.getLogger("myapp.moduleA")

# Module B (different file, no import needed)
logger = logging.getLogger("myapp.moduleA")  # Gets same logger instance

# They're the same object

logger = logging.getLogger("myapp")
logger.addHandler(logging.FileHandler("app.log"))  # To file
logger.addHandler(logging.StreamHandler())  # To console
logger.addHandler(custom_ui_handler)  # To UI widget

# One log call, multiple destinations
logger.info("Started")  # Goes to all three handlers

# Same log record, different formatting
file_handler.setFormatter(logging.Formatter(
    '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
))
# → 2026-02-25 14:32:15 - myapp.module - INFO - Started

console_handler.setFormatter(logging.Formatter(
    '[%(levelname)s] %(message)s'
))
# → [INFO] Started

logger.debug("Detailed diagnostic")    # DEBUG (10)
logger.info("Normal operation")        # INFO (20)
logger.warning("Something unexpected") # WARNING (30)
logger.error("Operation failed")       # ERROR (40)
logger.critical("System unstable")     # CRITICAL (50)

import logging

# Module-level logger
logger = logging.getLogger(__name__)  # Or explicit name
logger.info("Module loaded")

# Get same logger instance elsewhere
same_logger = logging.getLogger("myapp.module")  # Same object

# ❌ WRONG - Don't instantiate directly
logger = logging.Logger("mylogger")  # Breaks singleton pattern

import logging

logger = logging.getLogger(__name__)  # Automatic module path

import logging as _logging  # Avoid namespace collisions

_MODULE_NAME = "myapp.module"
_LOGGER = _logging.getLogger(_MODULE_NAME)

# mylib/module.py
import logging

logger = logging.getLogger(__name__)

def process_data(data):
    logger.debug("Processing data")  # Just emit, don't configure
    # ... do work ...
    logger.info("Processing complete")

# app.py
import logging
import mylib.module

# Configure logging at application entry point
logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    handlers=[
        logging.FileHandler('app.log'),
        logging.StreamHandler()
    ]
)

# Now library logs go to configured handlers
mylib.module.process_data([1, 2, 3])

# ❌ WRONG - Don't configure in library code
# mylib/module.py
import logging

logger = logging.getLogger(__name__)
handler = logging.FileHandler('mylib.log')  # BAD!
logger.addHandler(handler)  # BAD!

def process_data(data):
    logger.info("Processing")  # Now library controls its own output

import logging

# Create parent logger with handler
parent = logging.getLogger("myapp")
parent.setLevel(logging.DEBUG)
parent.addHandler(logging.StreamHandler())

# Create child loggers (no handlers needed)
module_logger = logging.getLogger("myapp.module")
submodule_logger = logging.getLogger("myapp.module.submodule")

# Messages automatically propagate up the hierarchy
submodule_logger.info("Hello")  # Goes to parent's StreamHandler
module_logger.warning("Warning")  # Also goes to parent's StreamHandler

# Sometimes you want to isolate a hierarchy
tool_logger = logging.getLogger("mytool")
tool_logger.propagate = False  # Don't leak to root logger

# Useful for:
# - Separate UI console logging
# - Isolated subsystems
# - Preventing library logs from polluting your output

import logging

logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)  # Logger accepts all levels

# Different handlers filter differently
file_handler = logging.FileHandler("debug.log")
file_handler.setLevel(logging.DEBUG)  # File gets everything

console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)  # Console gets INFO and above

logger.addHandler(file_handler)
logger.addHandler(console_handler)

# Now one log call goes to multiple destinations with different filtering
logger.debug("Detailed trace")  # Only to file
logger.info("User message")     # To both file and console
logger.error("Something broke")  # To both file and console

# ❌ Less flexible - logger level filters for ALL handlers
logger.setLevel(logging.INFO)  # Can't get DEBUG anywhere now

# ❌ WRONG - Passing loggers creates tight coupling
class DataProcessor:
    def __init__(self, logger):
        self.logger = logger  # Dependency on caller

class DataValidator:
    def __init__(self, logger):
        self.logger = logger  # More dependencies

# Caller must provide loggers
processor = DataProcessor(logger=some_logger)
validator = DataValidator(logger=some_logger)

# ✅ CORRECT - Each module gets its own logger by name
import logging

class DataProcessor:
    def __init__(self):
        self.logger = logging.getLogger(__name__)  # No dependency

class DataValidator:
    def __init__(self):
        self.logger = logging.getLogger(__name__)  # No dependency

# Just works, no logger passing needed
processor = DataProcessor()
validator = DataValidator()

# Framework base class
class BaseWindow:
    def __init__(self, logger=None):
        if logger:
            # Framework attaches UI console handler to specified logger
            console_handler = QTextEditHandler(self.console_widget)
            logger.addHandler(console_handler)

# Application tells framework which logger to enhance
class MyWindow(BaseWindow):
    def __init__(self):
        tool_root_logger = logging.getLogger("mytool")
        super().__init__(logger=tool_root_logger)  # Tell framework where to attach handler

# ❌ WRONG - Creating logger for each instance
class AssetProcessor:
    def __init__(self, asset_name):
        # Creates a new logger for EVERY instance
        self.logger = logging.getLogger(f"processor.{asset_name}")
        self.asset_name = asset_name

# Creates 1000 separate loggers!
processors = [AssetProcessor(f"asset_{i}") for i in range(1000)]

# ✅ CORRECT - One logger per module
import logging

class AssetProcessor:
    # Class-level logger (shared by all instances)
    logger = logging.getLogger(__name__)

    def __init__(self, asset_name):
        self.asset_name = asset_name

    def process(self):
        # Include instance context in message, not logger name
        self.logger.info(f"Processing asset: {self.asset_name}")

# ❌ WRONG - Using root logger
import logging

logging.debug("Processing started")  # Goes to root logger
logging.info("Step complete")        # Goes to root logger
logging.error("Failed")              # Goes to root logger

# ✅ CORRECT - Named logger
import logging

logger = logging.getLogger(__name__)

logger.debug("Processing started")
logger.info("Step complete")
logger.error("Failed")

# ✅ ACCEPTABLE - Early bootstrap logging
import logging

# Very early initialization - before custom logging is configured
logging.info("Application starting...")
logging.debug("Python version: %s", sys.version)

try:
    # Now set up proper logging infrastructure
    configure_logging()

    # From here on, use named loggers
    logger = logging.getLogger(__name__)
    logger.info("Logging infrastructure initialized")

except Exception as e:
    # Logging setup failed - root logger is all we have
    logging.critical("Failed to configure logging", exc_info=True)
    sys.exit(1)

# ❌ WRONG - Logging sensitive data
logger.debug(f"Connecting to database with password: {password}")
logger.info(f"API key: {api_key}")
logger.debug(f"User SSN: {ssn}")
logger.debug(f"Credit card: {card_number}")

# ✅ CORRECT - Log safely
logger.debug(f"Connecting to database at {host}:{port}")  # No password
logger.info(f"API authentication successful")  # No key
logger.debug(f"Processing user record ID: {user_id}")  # No PII

# If you must log something sensitive for debugging
import hashlib
logger.debug(f"Password hash: {hashlib.sha256(password.encode()).hexdigest()[:8]}...")

# ❌ WRONG - Logging every iteration
for i, item in enumerate(10000):
    logger.debug(f"Processing item {i}: {item}")  # 10,000 log messages!
    process(item)

# ✅ CORRECT - Log milestones and errors
items = list(range(10000))
logger.info(f"Starting batch processing: {len(items)} items")

for i, item in enumerate(items):
    try:
        process(item)
        # Log every 1000 items
        if (i + 1) % 1000 == 0:
            logger.info(f"Progress: {i + 1}/{len(items)} items processed")
    except Exception as e:
        logger.error(f"Failed to process item {i}: {item}", exc_info=True)

logger.info(f"Batch processing complete: {len(items)} items")

# ✅ ALSO CORRECT - Collect during loop, emit summary after
items = list(range(10000))
logger.info(f"Starting batch processing: {len(items)} items")

# Collect information during processing
processed_items = []
failed_items = []
timings = []

for i, item in enumerate(items):
    start_time = time.time()
    try:
        result = process(item)
        elapsed = time.time() - start_time

        # Collect, don't log
        processed_items.append(item)
        timings.append(elapsed)

    except Exception as e:
        # Immediate logging for errors still makes sense
        logger.error(f"Failed to process item {i}: {item}", exc_info=True)
        failed_items.append((item, str(e)))

# Now emit collected information as summary
logger.info(f"Batch processing complete: {len(processed_items)}/{len(items)} succeeded")
logger.debug(f"Average processing time: {sum(timings)/len(timings):.3f}s")
logger.debug(f"Min/Max time: {min(timings):.3f}s / {max(timings):.3f}s")

if failed_items:
    logger.warning(f"Failed items: {len(failed_items)}")
    for item, error in failed_items[:5]:  # Log first 5 failures
        logger.debug(f"  - {item}: {error}")
    if len(failed_items) > 5:
        logger.debug(f"  ... and {len(failed_items) - 5} more")

# ❌ WRONG - f-strings always evaluate
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.WARNING)  # DEBUG is disabled

# This ALWAYS calls expensive_function(), even when DEBUG is disabled!
for i in range(10000):
    logger.debug(f"Processing item {i}: {expensive_function(i)}")  # EXPENSIVE!

# ✅ CORRECT - Lazy evaluation with old-style formatting
import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.WARNING)  # DEBUG is disabled

# expensive_function() only called if DEBUG level is enabled
for i in range(10000):
    logger.debug("Processing item %s: %s", i, expensive_function(i))  # FAST!

import time
import logging

def expensive_function(x):
    sum(range(1000))  # Simulate work
    return x * 2

logger = logging.getLogger(__name__)
logger.setLevel(logging.WARNING)  # DEBUG disabled

# Test 1: f-strings (always evaluate)
start = time.time()
for i in range(10000):
    logger.debug(f"Item {i}: {expensive_function(i)}")
print(f"f-string time: {time.time() - start:.2f}s")  # ~5 seconds

# Test 2: Lazy evaluation
start = time.time()
for i in range(10000):
    logger.debug("Item %s: %s", i, expensive_function(i))
print(f"Lazy eval time: {time.time() - start:.2f}s")  # ~0.01 seconds

# Fine - simple, cheap operations
logger.info(f"Processing {asset_name}")  # Just a variable
logger.error(f"Failed after {attempts} attempts")  # Simple formatting

# Avoid - expensive operations
logger.debug(f"State: {serialize_entire_state()}")  # BAD!
logger.debug("State: %s", serialize_entire_state())  # GOOD (only if enabled)

# ❌ WRONG - Handler accumulation
class MyTool:
    def __init__(self):
        self.logger = logging.getLogger("mytool")
        handler = logging.FileHandler("tool.log")
        self.logger.addHandler(handler)  # Added every time tool loads!

# User loads tool, unloads it, loads it again...
# Each time: another handler added
# Result: Same log message appears 2x, 3x, 4x...

# ✅ CORRECT - Remove handlers on cleanup
import logging

class MyTool:
    def __init__(self):
        self.logger = logging.getLogger("mytool")
        self.handler = logging.FileHandler("tool.log")
        self.logger.addHandler(self.handler)

    def cleanup(self):
        """Call this when tool is closed/unloaded"""
        # Remove and close handler
        self.logger.removeHandler(self.handler)
        self.handler.close()
        self.handler = None

    def __del__(self):
        """Fallback cleanup (not always reliable)"""
        if hasattr(self, 'handler') and self.handler:
            try:
                self.logger.removeHandler(self.handler)
                self.handler.close()
            except:
                pass  # Might be called during shutdown

class MyToolWindow(QtWidgets.QMainWindow):
    def __init__(self):
        super().__init__()
        self.logger = logging.getLogger("mytool")
        self.file_handler = logging.FileHandler("tool.log")
        self.logger.addHandler(self.file_handler)

        self.console_handler = QTextEditLogger(self.console_widget)
        self.logger.addHandler(self.console_handler)

    def closeEvent(self, event):
        """Qt calls this when window closes"""
        # Clean up handlers
        for handler in [self.file_handler, self.console_handler]:
            try:
                self.logger.removeHandler(handler)
                handler.close()
            except Exception as e:
                print(f"Handler cleanup error: {e}")

        super().closeEvent(event)

def setup_logging():
    """Set up logging, clearing any existing handlers first"""
    logger = logging.getLogger("mytool")

    # Clear existing handlers (prevents accumulation)
    for handler in logger.handlers[:]:
        handler.close()
        logger.removeHandler(handler)

    # Now add fresh handlers
    logger.addHandler(logging.FileHandler("tool.log"))
    logger.setLevel(logging.DEBUG)

import logging
import warnings

# Redirect warnings to logging system
logging.captureWarnings(True)

# Configure the py.warnings logger
warnings_logger = logging.getLogger('py.warnings')
warnings_logger.setLevel(logging.WARNING)

# Now warnings go through your logging infrastructure
import numpy as np
np.array([1, 2, 3], dtype=np.int)  # Deprecated dtype
# → [WARNING] [py.warnings] DeprecationWarning: np.int is deprecated...

import logging
import warnings

def setup_logging():
    # Basic config
    logging.basicConfig(
        level=logging.DEBUG,
        format='[%(asctime)s] [%(levelname)s] [%(name)s] %(message)s',
        handlers=[
            logging.FileHandler('app.log'),
            logging.StreamHandler()
        ]
    )

    # Capture warnings
    logging.captureWarnings(True)

    # Optional: Set warnings logger level
    logging.getLogger('py.warnings').setLevel(logging.WARNING)

    # Optional: Control which warnings are shown
    warnings.filterwarnings('default')  # Show all
    # warnings.filterwarnings('ignore', category=DeprecationWarning)  # Hide deprecations

import logging as _logging

# Module metadata
_MODULE_NAME = "high_to_game_ready.tool"
_TOOL_NAME = "high_to_game_ready"
__version__ = "1.0"
__author__ = ["jGalloway"]

# 1. Module logger - technical logging for developers
_LOGGER = _logging.getLogger(_MODULE_NAME)
_LOGGER.setLevel(_logging.DEBUG)

# 2. Tool module logger - user-facing console messages
#    This automatically becomes a child of "high_to_game_ready" root logger
_TOOL_LOGGER = _logging.getLogger(f"{_TOOL_NAME}.tool")
_TOOL_LOGGER.setLevel(_logging.INFO)

class BP_HighToGameReadyTool(BP_BaseToolWindow):
    def __init__(self, parent=None, *args, **kwargs):
        super().__init__(
            parent=parent,
            logger=_TOOL_LOGGER,  # Pass tool logger to base class
            log_console=True,     # Enable UI console widget
            *args,
            **kwargs
        )

    def process_assets(self):
        # Technical logging - goes to file/terminal only
        _LOGGER.debug("Method: process_assets() entry")
        _LOGGER.debug(f"Asset list: {self.asset_list}")

        # User-facing logging - goes to UI console
        _TOOL_LOGGER.info("Starting asset processing...")

        try:
            result = self._run_houdini()

            # Technical
            _LOGGER.debug(f"Houdini subprocess exit code: {result}")

            # User-facing
            _TOOL_LOGGER.info("Houdini processing complete")

        except Exception as e:
            # Technical - full stack trace
            _LOGGER.exception("Houdini processing failed")

            # User-facing - actionable message
            _TOOL_LOGGER.error(f"Houdini failed: {e}. Check log file for details.")

        _LOGGER.debug("Method: process_assets() exit")

# bp_py/lib/bp_logging/ui_console_handler.py
import logging
from PySide6 import QtCore, QtWidgets

class QTextEditLogger(logging.Handler):
    """Custom handler that routes log messages to a Qt text widget"""

    class Emitter(QtCore.QObject):
        # Signal for thread-safe logging
        log = QtCore.Signal(str)

    def __init__(self, text_widget):
        super().__init__()

        if not isinstance(text_widget, (QtWidgets.QPlainTextEdit,
                                       QtWidgets.QTextBrowser)):
            raise TypeError("text_widget must be a Qt text widget")

        self.widget = text_widget
        self.widget.setReadOnly(True)

        # Emitter provides thread-safe signal-based logging
        self.emitter = QTextEditLogger.Emitter()
        self.emitter.log.connect(self.append_log)

    def append_log(self, msg):
        """Append log message to widget (runs in main thread)"""
        if self.widget is None:
            return

        try:
            # Limit buffer to prevent memory bloat in long-running sessions
            # Keep last 5000 lines, remove oldest 500 when limit reached
            if self.widget.document().blockCount() > 5000:
                cursor = self.widget.textCursor()
                cursor.movePosition(cursor.Start)
                # Select and remove first 500 lines
                for _ in range(500):
                    cursor.select(cursor.BlockUnderCursor)
                    cursor.removeSelectedText()
                    cursor.deleteChar()  # Remove the newline

            self.widget.appendPlainText(msg)
        except RuntimeError:
            # C++ widget deleted, nullify reference
            self.widget = None

    def emit(self, record):
        """Handler's emit method - formats and signals message"""
        try:
            msg = self.format(record)
            self.emitter.log.emit(msg)  # Thread-safe via Qt signal
        except Exception:
            self.handleError(record)  # Standard logging error handling

class BP_BaseToolWindow(QtWidgets.QMainWindow):
    def __init__(self, logger=None, log_console=True, *args, **kwargs):
        super().__init__(*args, **kwargs)

        if log_console:
            # Create console widget
            self.console_widget = QtWidgets.QPlainTextEdit()
            self.console_widget.setReadOnly(True)

            # Set monospace font
            font = QtGui.QFont("Courier New", 9)
            self.console_widget.setFont(font)

            # Add to UI layout
            self.layout.addWidget(self.console_widget)

            # Attach console handler to provided logger
            if logger:
                self._console_handler = QTextEditLogger(self.console_widget)

                # Format: [LEVEL][logger.name] >> message
                formatter = logging.Formatter(
                    '[%(levelname)s][%(name)s] >> %(message)s'
                )
                self._console_handler.setFormatter(formatter)
                self._console_handler.setLevel(logging.INFO)

                # Attach handler to the provided logger
                logger.addHandler(self._console_handler)

class BP_HighToGameReadyTool(BP_BaseToolWindow):
    def __init__(self, *args, **kwargs):
        # Get tool root logger
        tool_root_logger = logging.getLogger("high_to_game_ready")
        tool_root_logger.setLevel(logging.DEBUG)
        tool_root_logger.propagate = False  # Isolate from root logger

        # Pass to base class - it will attach console handler
        super().__init__(
            logger=tool_root_logger,  # Base class attaches handler here
            log_console=True,
            *args,
            **kwargs
        )

def validate_assets(self):
    _LOGGER.debug("Method: validate_assets() entry")  # Technical
    _TOOL_LOGGER.info("Validating assets...")         # User-facing

    if not self.asset_list:
        _LOGGER.warning("Asset list is empty (internal)")  # Technical
        _TOOL_LOGGER.error("No assets selected!")          # User-facing
        return False

    _LOGGER.debug(f"Validating {len(self.asset_list)} assets")  # Technical

    for asset in self.asset_list:
        _LOGGER.debug(f"Checking asset: {asset.path}")  # Technical

        if not asset.has_uv_set():
            msg = f"Asset '{asset.name}' missing UV set"
            _LOGGER.error(msg)           # Technical - with context
            _TOOL_LOGGER.error(msg)      # User-facing - same message
            return False

    _LOGGER.debug("All assets valid, returning True")  # Technical
    _TOOL_LOGGER.info("Asset validation successful")   # User-facing
    return True

def process_houdini(self):
    _LOGGER.info("Starting Houdini subprocess")  # Technical
    _TOOL_LOGGER.info("Starting Houdini processing...")  # User-facing

    try:
        _LOGGER.debug(f"Houdini executable: {self.houdini_path}")
        _LOGGER.debug(f"Hip file: {self.hip_file}")
        _LOGGER.debug(f"Asset count: {len(self.asset_list)}")

        result = subprocess.run([self.houdini_path, self.hip_file])

        _LOGGER.debug(f"Subprocess exit code: {result.returncode}")

        if result.returncode != 0:
            raise RuntimeError(f"Houdini failed with code {result.returncode}")

        _TOOL_LOGGER.info("Houdini processing complete")

    except Exception as e:
        # Technical log - full context
        _LOGGER.exception("Houdini subprocess failed")
        _LOGGER.error(f"Houdini path: {self.houdini_path}")
        _LOGGER.error(f"Hip file: {self.hip_file}")
        _LOGGER.error(f"Working directory: {os.getcwd()}")

        # User-facing log - actionable message
        _TOOL_LOGGER.error(
            f"Houdini processing failed: {e}\n"
            f"Check log file: {self.log_file_path}"
        )
        raise

class BP_HighToGameReadyTool(BP_BaseToolWindow):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)

        # Add debug mode checkbox
        self.debug_checkbox = QtWidgets.QCheckBox("Debug Mode")
        self.debug_checkbox.stateChanged.connect(self.toggle_debug_mode)
        self.toolbar.addWidget(self.debug_checkbox)

    def toggle_debug_mode(self, state):
        if state == QtCore.Qt.Checked:
            # Show technical logging in console
            self._console_handler.setLevel(logging.DEBUG)
            _TOOL_LOGGER.info("Debug mode enabled")
        else:
            # Back to user-facing only
            self._console_handler.setLevel(logging.INFO)
            _TOOL_LOGGER.info("Debug mode disabled")

# Tool module template
import logging as _logging
from logging.handlers import RotatingFileHandler
import os

_MODULE_NAME = "my_tool.module"
_TOOL_NAME = "my_tool"
_LOGGER = _logging.getLogger(_MODULE_NAME)          # Technical
_TOOL_LOGGER = _logging.getLogger(f"{_TOOL_NAME}.module")  # Console

class MyTool(BP_BaseToolWindow):
    def __init__(self, *args, **kwargs):
        # Set up tool root logger with file handler
        tool_root = _logging.getLogger(_TOOL_NAME)
        tool_root.propagate = False
        tool_root.setLevel(_logging.DEBUG)

        # Clear any existing handlers (prevents accumulation)
        for handler in tool_root.handlers[:]:
            handler.close()
            tool_root.removeHandler(handler)

        # Add rotating file handler (10MB max, keep 5 old logs)
        log_dir = os.path.join(os.path.expanduser("~"), "logs")
        os.makedirs(log_dir, exist_ok=True)
        log_file = os.path.join(log_dir, f"{_TOOL_NAME}.log")

        file_handler = RotatingFileHandler(
            log_file,
            maxBytes=10*1024*1024,  # 10MB
            backupCount=5,
            encoding='utf-8'
        )
        file_handler.setLevel(_logging.DEBUG)
        file_handler.setFormatter(_logging.Formatter(
            '[%(asctime)s] [%(levelname)s] [%(name)s:%(lineno)d] %(message)s'
        ))
        tool_root.addHandler(file_handler)

        # Capture Python warnings
        _logging.captureWarnings(True)

        # Pass to base class for console handler attachment
        super().__init__(logger=tool_root, log_console=True, *args, **kwargs)

        # Log startup
        _TOOL_LOGGER.info(f"{_TOOL_NAME} initialized")
        _LOGGER.debug(f"Log file: {log_file}")

    def closeEvent(self, event):
        """Clean up handlers when tool closes"""
        _LOGGER.debug("Tool closing, cleaning up handlers")

        tool_root = _logging.getLogger(_TOOL_NAME)
        for handler in tool_root.handlers[:]:
            try:
                handler.close()
                tool_root.removeHandler(handler)
            except Exception as e:
                print(f"Error cleaning up handler: {e}")

        super().closeEvent(event)

import logging

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

# Just use the logger
logger.info("Script complete")

import logging

_LOGGER = logging.getLogger(__name__)

# Configure at application entry point
if __name__ == "__main__":
    logging.basicConfig(
        level=logging.DEBUG,
        format='[%(asctime)s] [%(levelname)s] [%(name)s:%(lineno)d] %(message)s',
        handlers=[
            logging.FileHandler("app.log"),
            logging.StreamHandler()
        ]
    )

import logging

_MODULE_NAME = "mytool.module"
_TOOL_NAME = "mytool"
_LOGGER = logging.getLogger(_MODULE_NAME)
_TOOL_LOGGER = logging.getLogger(f"{_TOOL_NAME}.module")

class MyTool(BaseWindow):
    def __init__(self):
        tool_root = logging.getLogger(_TOOL_NAME)
        tool_root.propagate = False
        super().__init__(logger=tool_root, log_console=True)

from logging.handlers import RotatingFileHandler

handler = RotatingFileHandler(
    "app.log",
    maxBytes=10*1024*1024,  # 10MB
    backupCount=5            # Keep 5 old logs
)

# Test error paths explicitly
try:
    result = risky_operation()
except ExpectedError as e:
    logger.error("Expected failure case", exc_info=True)
    # Verify: Does log have stack trace? Context? Error details?
except UnexpectedError as e:
    logger.critical("Unexpected failure!", exc_info=True)
    # Verify: Is this loud enough? Will I notice?

"""
Logging Architecture:
- _LOGGER: Technical logging for developers (DEBUG+, file + terminal)
- _TOOL_LOGGER: User-facing console (INFO+, UI widget only)
- Tool root: Infrastructure attachment point for console handler

See docs/logging.md for details.
"""

import logging
import unittest

class TestLogging(unittest.TestCase):
    def test_error_logged(self):
        """Verify error messages are logged"""
        with self.assertLogs('myapp', level='ERROR') as cm:
            logger = logging.getLogger('myapp')
            logger.error('Something went wrong')

        # Check log was captured
        self.assertEqual(len(cm.output), 1)
        self.assertIn('Something went wrong', cm.output[0])
        self.assertIn('ERROR', cm.output[0])

def test_log_levels(self):
    """Verify only appropriate levels are logged"""
    with self.assertLogs('myapp', level='WARNING') as cm:
        logger = logging.getLogger('myapp')
        logger.setLevel(logging.WARNING)

        logger.debug('Debug message')    # Should not appear
        logger.info('Info message')      # Should not appear
        logger.warning('Warning message') # Should appear
        logger.error('Error message')    # Should appear

    self.assertEqual(len(cm.output), 2)  # Only WARNING and ERROR
    self.assertIn('Warning message', cm.output[0])
    self.assertIn('Error message', cm.output[1])

def test_exception_logging(self):
    """Verify exceptions are logged with tracebacks"""
    with self.assertLogs('myapp', level='ERROR') as cm:
        logger = logging.getLogger('myapp')

        try:
            raise ValueError("Test error")
        except ValueError:
            logger.exception("Caught error")

    # Should have exception info
    output = ''.join(cm.output)
    self.assertIn('ValueError', output)
    self.assertIn('Test error', output)
    self.assertIn('Traceback', output)

import io

def test_custom_handler_output(self):
    """Verify custom handler formats correctly"""
    logger = logging.getLogger('test_handler')
    logger.setLevel(logging.DEBUG)

    # Capture to buffer
    buffer = io.StringIO()
    handler = logging.StreamHandler(buffer)
    handler.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
    logger.addHandler(handler)

    try:
        logger.info('Test message')
        output = buffer.getvalue()
        self.assertEqual(output.strip(), 'INFO: Test message')
    finally:
        logger.removeHandler(handler)
        handler.close()

from PySide6 import QtWidgets, QtCore
import sys

class TestQtHandler(unittest.TestCase):
    @classmethod
    def setUpClass(cls):
        """Create QApplication (needed for Qt widgets)"""
        if not QtWidgets.QApplication.instance():
            cls.app = QtWidgets.QApplication(sys.argv)

    def test_qt_logger_appends_text(self):
        """Verify QTextEditLogger writes to widget"""
        widget = QtWidgets.QPlainTextEdit()
        handler = QTextEditLogger(widget)

        logger = logging.getLogger('qt_test')
        logger.addHandler(handler)
        logger.setLevel(logging.INFO)

        try:
            logger.info('Test message')

            # Process Qt events (signal delivery)
            QtCore.QCoreApplication.processEvents()

            # Check widget has text
            text = widget.toPlainText()
            self.assertIn('Test message', text)
        finally:
            logger.removeHandler(handler)
            handler.close()

from unittest.mock import patch, MagicMock

def process_data(data):
    logger = logging.getLogger(__name__)
    logger.info(f"Processing {len(data)} items")
    # ... process data ...
    logger.info("Processing complete")

def test_process_data_logging(self):
    """Verify process_data logs expected messages"""
    with patch('__main__.logging.getLogger') as mock_get_logger:
        mock_logger = MagicMock()
        mock_get_logger.return_value = mock_logger

        process_data([1, 2, 3])

        # Verify logging calls
        self.assertEqual(mock_logger.info.call_count, 2)
        mock_logger.info.assert_any_call('Processing 3 items')
        mock_logger.info.assert_any_call('Processing complete')

import logging
import maya.utils

def setup_maya_logging(logger_name='mytool', log_level=logging.INFO):
    """Configure logging to Maya Script Editor (preferred method)."""
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG)

    # Clear existing Maya GUI handlers (prevents accumulation on module reload)
    for handler in logger.handlers[:]:
        if isinstance(handler, maya.utils.MayaGuiLogHandler):
            logger.removeHandler(handler)
            handler.close()

    # Use Maya's native handler - respects Script Editor colors, tabs, preferences
    gui_handler = maya.utils.MayaGuiLogHandler()
    gui_handler.setLevel(log_level)
    gui_handler.setFormatter(logging.Formatter(
        '[%(levelname)s] [%(name)s] %(message)s'
    ))
    logger.addHandler(gui_handler)

    # Prevent double-logging to Script Editor
    logger.propagate = False

    return logger

# Usage
logger = setup_maya_logging('mytool')
logger.info("Tool initialized")  # Appears in Script Editor with proper formatting
logger.error("Something failed")  # Appears in red

# --- htgr/globals.py - Initialization module ---
import logging
import sys
from pathlib import Path

_INITIALIZED = False
_TOPNET_NAME = "high_to_game_ready"

def _initialize_module():
    """Initialize logging once for all TOP nodes"""
    global _INITIALIZED, HOUDINI_PROCESS_LOG_FILE

    if _INITIALIZED:
        return

    # 1. Set up root logger with console handler
    root_logger = logging.getLogger()
    root_logger.setLevel(logging.DEBUG)

    console_handler = logging.StreamHandler(sys.__stdout__)
    console_formatter = logging.Formatter(
        '[%(levelname)s][%(name)s] >> %(message)s'
    )
    console_handler.setFormatter(console_formatter)

    if not any(isinstance(h, logging.StreamHandler) for h in root_logger.handlers):
        root_logger.addHandler(console_handler)

    # 2. Debug log file (for developers)
    debug_log = Path.home() / 'logs' / f'{_TOPNET_NAME}_debug.log'
    debug_log.parent.mkdir(parents=True, exist_ok=True)

    debug_handler = logging.FileHandler(debug_log, mode='w')
    debug_handler.setFormatter(logging.Formatter(
        '%(asctime)s :: [%(levelname)s][%(name)s] >> %(message)s'
    ))
    root_logger.addHandler(debug_handler)

    # 3. Process log file (for GUI to read - live progress)
    HOUDINI_PROCESS_LOG_FILE = Path.home() / 'logs' / f'{_TOPNET_NAME}_process.log'
    HOUDINI_PROCESS_LOG_FILE.parent.mkdir(parents=True, exist_ok=True)

    # Clear process log at start (GUI reads this for progress)
    HOUDINI_PROCESS_LOG_FILE.write_text('', encoding='utf-8')

    _INITIALIZED = True

# Initialize on import
_initialize_module()


# --- htgr/validate.py - TOP node that validates ---
import logging
import htgr.globals as htgr_globals

_LOGGER = logging.getLogger(f"{htgr_globals._TOPNET_NAME}.validate")

def check_parsed_values(work_item):
    """Validate work item attributes"""
    success = True

    # Validation logic with logging
    filename = work_item.stringAttribValue('filename')
    _LOGGER.info(f"Validating: {filename}")

    if not filename:
        _LOGGER.error("Missing filename attribute")
        success = False

    if success:
        _LOGGER.info(f"{filename} PASSED")
    else:
        _LOGGER.error(f"{filename} FAILED")

    return success


# --- htgr/finish.py - Final TOP node ---
import logging
import htgr.globals as htgr_globals

_LOGGER = logging.getLogger(f"{htgr_globals._TOPNET_NAME}.finish")

# Add process log handler to this specific logger (GUI reads this)
for handler in _LOGGER.handlers[:]:
    _LOGGER.removeHandler(handler)
    handler.close()

process_handler = logging.FileHandler(htgr_globals.HOUDINI_PROCESS_LOG_FILE)
process_handler.setFormatter(htgr_globals.console_formatter)
_LOGGER.addHandler(process_handler)

def validate_work_item(work_item):
    """Final validation and result logging"""
    filename = work_item.stringAttribValue('filename')

    if work_item.isCooked:
        _LOGGER.info(f"{filename} processing complete")  # GUI sees this
        return True
    else:
        _LOGGER.error(f"{filename} processing failed")  # GUI sees this
        return False

# In your Qt tool that launches Houdini
class HighToGameReadyTool(QMainWindow):
    def monitor_houdini_progress(self):
        """Read process log and update UI"""
        process_log = Path.home() / 'logs' / 'high_to_game_ready_process.log'

        if process_log.exists():
            with open(process_log, 'r') as f:
                content = f.read()
                self.console_widget.setPlainText(content)  # Show in UI

# --- maya_export.py - Headless Maya subprocess ---
import logging
import sys

_MODULE_NAME = "high_to_game_ready.jobs.maya_export"
_LOGGER = logging.getLogger(_MODULE_NAME)
_LOGGER.setLevel(logging.DEBUG)

# Custom formatter optimized for subprocess context
_MODULE_LOG_FORMATTER = logging.Formatter(
    fmt="[%(levelname)s][%(name)s] >> %(message)s ::(%(filename)s:%(lineno)d)",
    datefmt="%Y-%m-%d %H:%M:%S",
)

# Single StreamHandler for subprocess → stdout
_TEMP_CONSOLE_HANDLER = logging.StreamHandler(sys.stdout)
_TEMP_CONSOLE_HANDLER.setLevel(logging.DEBUG)
_TEMP_CONSOLE_HANDLER.setFormatter(_MODULE_LOG_FORMATTER)

# Get root logger and child package loggers
__ROOT_LOGGER = logging.getLogger()
__ROOT_LOGGER.setLevel(logging.DEBUG)

_BPMPY_LOGGER = logging.getLogger("BP_mPy")  # Maya utility library
_BPPY_LOGGER = logging.getLogger("bp_py")    # Studio library

# CRITICAL: Remove StreamHandlers from child loggers to prevent duplicate output
# (They might have handlers from initialization or previous runs)
for logger in [_BPMPY_LOGGER, _BPPY_LOGGER, _LOGGER]:
    for handler in list(logger.handlers):
        if isinstance(handler, logging.StreamHandler):
            logger.removeHandler(handler)
            handler.close()

# Attach single StreamHandler to root logger to collect everything
if not any(isinstance(h, logging.StreamHandler) for h in __ROOT_LOGGER.handlers):
    __ROOT_LOGGER.addHandler(_TEMP_CONSOLE_HANDLER)

_LOGGER.debug(f"Boot initialization complete for: {_MODULE_NAME}")


# --- Subprocess execution function ---
def execute(config=None):
    """Main execution function for Maya subprocess"""
    _LOGGER.info(f"Running: {__name__} execute()")

    # All logging from any module now goes to stdout via root logger
    _LOGGER.debug("Loading Maya scene...")

    # Even third-party code logs are captured
    from BP_mPy.lib.export.modelExport import exportBpModels
    exportBpModels()  # Its logging goes to stdout too

    cleanup()
    return 0  # Success


# --- Cleanup function (called on subprocess exit) ---
def cleanup():
    """Remove handler to prevent accumulation"""
    _LOGGER.info(f"Cleaning up {_MODULE_NAME} module.")

    if _TEMP_CONSOLE_HANDLER:
        __ROOT_LOGGER.removeHandler(_TEMP_CONSOLE_HANDLER)
        _TEMP_CONSOLE_HANDLER.close()

    _LOGGER.debug("Cleanup complete")


if __name__ == "__main__":
    try:
        exit_code = execute()
    except Exception as e:
        _LOGGER.exception(f"Fatal error: {e}")
        exit_code = 1

    cleanup()
    sys.exit(exit_code)

# --- tool.py - Qt GUI that launches Maya subprocess ---
from PySide6.QtCore import QProcess, Slot

class HighToGameReadyTool(QMainWindow):
    def __init__(self):
        super().__init__()
        self._maya_process = None

        # Console widget using QTextEditLogger from earlier pattern
        self.console = QTextEdit()
        self.console_logger = logging.getLogger("high_to_game_ready")  # Tool root

        handler = QTextEditLogger(self.console)
        handler.setLevel(logging.INFO)
        self.console_logger.addHandler(handler)

    def start_maya_subprocess(self):
        """Launch mayapy.exe as subprocess"""
        self._maya_process = QProcess(self)

        # Connect signals to capture subprocess output
        self._maya_process.readyReadStandardOutput.connect(self._on_maya_stdout)
        self._maya_process.readyReadStandardError.connect(self._on_maya_stderr)
        self._maya_process.finished.connect(self._on_maya_finished)

        # Launch subprocess
        mayapy_path = "C:/Program Files/Autodesk/Maya2024/bin/mayapy.exe"
        script_path = "d:/tools/high_to_game_ready/jobs/maya_export.py"

        self._maya_process.start(mayapy_path, [script_path, "--json-data", config])
        self.console_logger.info("Maya subprocess started...")

    @Slot()
    def _on_maya_stdout(self):
        """Capture subprocess stdout and display in GUI"""
        if self._maya_process:
            data = self._maya_process.readAllStandardOutput()
            text = bytes(data).decode('utf-8', errors='replace')

            # Parse subprocess log lines and route through console logger
            for line in text.strip().split('\n'):
                if line:
                    # Subprocess formatter already includes level/module
                    # Display directly in console (already formatted)
                    self.console.append(line)

    @Slot()
    def _on_maya_stderr(self):
        """Capture subprocess stderr (Maya's native errors)"""
        if self._maya_process:
            data = self._maya_process.readAllStandardError()
            text = bytes(data).decode('utf-8', errors='replace')

            if text.strip():
                self.console_logger.error(f"[Maya stderr]: {text}")

    @Slot(int, QProcess.ExitStatus)
    def _on_maya_finished(self, exit_code, exit_status):
        """Handle subprocess completion"""
        if exit_code == 0:
            self.console_logger.info("Maya processing complete!")
        else:
            self.console_logger.error(f"Maya process failed (exit code: {exit_code})")

# --- substance_bake.py - Subprocess wrapper for SAT operations ---
import logging
import sys
from pathlib import Path

_MODULE_NAME = "high_to_game_ready.jobs.substance_bake"
_LOGGER = logging.getLogger(_MODULE_NAME)
_LOGGER.setLevel(logging.DEBUG)

# 1. Console handler for parent QProcess capture (same as Maya pattern)
_TEMP_CONSOLE_HANDLER = logging.StreamHandler(sys.stdout)
_TEMP_CONSOLE_HANDLER.setLevel(logging.DEBUG)
_TEMP_CONSOLE_HANDLER.setFormatter(logging.Formatter(
    "[%(levelname)s][%(name)s] >> %(message)s ::(%(filename)s:%(lineno)d)"
))

# 2. File handler for persistent debugging (NEW - for SAT integration)
_TOOL_ROOT = Path(__file__).parents[1]  # high_to_game_ready/
_MODULE_FILE_LOG_PATH = (_TOOL_ROOT / ".temp" / "logs" / "substance_bake.log").resolve()
_MODULE_FILE_LOG_PATH.parent.mkdir(parents=True, exist_ok=True)

_MODULE_FILE_HANDLER = logging.FileHandler(_MODULE_FILE_LOG_PATH, mode='w')
_MODULE_FILE_HANDLER.setFormatter(logging.Formatter(
    '%(asctime)s :: [%(levelname)s][%(name)s] >> %(message)s'
))
_MODULE_FILE_HANDLER.setLevel(logging.DEBUG)

# Get root logger
__ROOT_LOGGER = logging.getLogger()
__ROOT_LOGGER.setLevel(logging.DEBUG)

# Remove StreamHandlers from child loggers (prevent duplicates)
for logger in [_LOGGER]:
    for handler in list(logger.handlers):
        if isinstance(handler, logging.StreamHandler):
            logger.removeHandler(handler)

# Attach BOTH handlers to root logger
if not any(isinstance(h, logging.StreamHandler) for h in __ROOT_LOGGER.handlers):
    __ROOT_LOGGER.addHandler(_TEMP_CONSOLE_HANDLER)  # Stdout → parent GUI

if not any(isinstance(h, logging.FileHandler) and h.baseFilename == str(_MODULE_FILE_LOG_PATH)
           for h in __ROOT_LOGGER.handlers):
    __ROOT_LOGGER.addHandler(_MODULE_FILE_HANDLER)  # File → persistent debug log

_LOGGER.debug(f"Boot initialization complete for: {_MODULE_NAME}")


# --- Main execution wrapping SAT operations ---
def main():
    """Substance texture baking workflow"""
    _LOGGER.info("Starting Substance texture baking process...")

    # Import SAT Python API (pysbs)
    from pysbs import batchtools, context, substance

    # Your SAT operations here
    _LOGGER.debug(f"Loading Substance baker settings from: {settings_path}")

    # Launch SAT subprocess applet (sbsbaker)
    # SAT applet stdout/stderr is captured and logged
    process = subprocess.Popen(
        [sat_executable, "--input", mesh_path, "--output", texture_path],
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        text=True
    )

    # Route SAT applet output through your logging
    for line in process.stdout:
        _LOGGER.info(f"[sbsbaker] {line.strip()}")  # SAT output visible in parent GUI

    for line in process.stderr:
        _LOGGER.error(f"[sbsbaker stderr] {line.strip()}")

    process.wait()

    if process.returncode == 0:
        _LOGGER.info("Substance baking completed successfully")
    else:
        _LOGGER.error(f"Substance baking failed (exit code: {process.returncode})")

    cleanup()
    return process.returncode


# --- Cleanup removes BOTH handlers ---
def cleanup():
    """Remove handlers to prevent accumulation"""
    _LOGGER.info(f"Cleaning up {_MODULE_NAME} module.")

    if _MODULE_FILE_HANDLER:
        __ROOT_LOGGER.removeHandler(_MODULE_FILE_HANDLER)
        _MODULE_FILE_HANDLER.close()

    if _TEMP_CONSOLE_HANDLER:
        __ROOT_LOGGER.removeHandler(_TEMP_CONSOLE_HANDLER)
        _TEMP_CONSOLE_HANDLER.close()


if __name__ == "__main__":
    try:
        exit_code = main()
    except Exception as e:
        _LOGGER.exception(f"Fatal error: {e}")
        exit_code = 1

    cleanup()
    sys.exit(exit_code)

# Console (stdout) → Parent QProcess → GUI console widget
[INFO][high_to_game_ready.jobs.substance_bake] >> Starting Substance texture baking...
[INFO][high_to_game_ready.jobs.substance_bake] >> [sbsbaker] Processing rock_01_low.fbx
[INFO][high_to_game_ready.jobs.substance_bake] >> [sbsbaker] Baking normal map...
[INFO][high_to_game_ready.jobs.substance_bake] >> Baking completed successfully

# File (.temp/logs/substance_bake.log) → Post-mortem debugging
2026-02-25 15:45:10,123 :: [INFO][high_to_game_ready.jobs.substance_bake] >> Starting Substance texture baking...
2026-02-25 15:45:10,456 :: [DEBUG][high_to_game_ready.jobs.substance_bake] >> Loading settings: bp_designer_smm_baker.json
2026-02-25 15:45:11,789 :: [INFO][high_to_game_ready.jobs.substance_bake] >> [sbsbaker] Processing rock_01_low.fbx
2026-02-25 15:45:15,234 :: [INFO][high_to_game_ready.jobs.substance_bake] >> [sbsbaker] Baking normal map...
2026-02-25 15:45:18,567 :: [INFO][high_to_game_ready.jobs.substance_bake] >> Baking completed successfully

# Problem: Handlers accumulate on reload
import logging

logger = logging.getLogger(__name__)
logger.addHandler(logging.FileHandler('tool.log'))  # Added every reload!

# Solution: Always clear handlers first
def setup_logger():
    logger = logging.getLogger(__name__)

    # Clear existing handlers
    for handler in logger.handlers[:]:
        handler.close()
        logger.removeHandler(handler)

    # Add fresh handler
    logger.addHandler(logging.FileHandler('tool.log'))
    return logger

logger = setup_logger()

from logging.handlers import RotatingFileHandler

# Automatic log rotation
handler = RotatingFileHandler(
    'maya_tool.log',
    maxBytes=10*1024*1024,  # 10MB per file
    backupCount=3           # Keep 3 old files
)

# For UI console widgets - limit buffer (see QTextEditLogger.append_log example)

# Python logging module is thread-safe
# But be careful with custom handlers that touch Houdini state

import logging
import hou

class HoudiniHandler(logging.Handler):
    def emit(self, record):
        # DON'T call hou.ui methods from non-main threads!
        # Use Qt signals or executeDeferred patterns
        pass

# Risky - might get wrong module in DCC
logger = logging.getLogger(__name__)

# Safer - explicit namespace
logger = logging.getLogger('mystudio.mytool.module')

class MyToolWindow(QtWidgets.QMainWindow):
    def closeEvent(self, event):
        """Always cleanup handlers on close"""
        for handler in self.logger.handlers[:]:
            handler.close()
            self.logger.removeHandler(handler)
        super().closeEvent(event)