Add CI/CD pipeline, logging enhancements, and release management

- Create a GitHub Actions workflow for testing with Python 3.12 and 3.13.
- Update Makefile to include release management commands and pipeline checks.
- Document the CI/CD pipeline structure and usage in PIPELINE.md.
- Add structlog for structured logging and enhance logging utilities.
- Implement release management script for automated versioning and tagging.
- Modify logging configuration to support structured logging and improved formatting.
- Update dependencies in pyproject.toml and poetry.lock to include structlog.
- Enhance access logging in server and middleware to include structured data.

pyserve/logging_utils.py

@@ -2,14 +2,15 @@ import logging
 import logging.handlers
 import sys
 import time
-import json
 from pathlib import Path
-from typing import Dict, Any, List
+from typing import Dict, Any, List, cast, Callable
+import structlog
+from structlog.types import FilteringBoundLogger, EventDict
 
 from . import __version__
 
 
-class LoggerFilter(logging.Filter):
+class StructlogFilter(logging.Filter):
     def __init__(self, logger_names: List[str]):
         super().__init__()
         self.logger_names = logger_names
@@ -22,11 +23,10 @@ class LoggerFilter(logging.Filter):
         for logger_name in self.logger_names:
             if record.name == logger_name or record.name.startswith(logger_name + '.'):
                 return True
-
         return False
 
 
-class UvicornLogFilter(logging.Filter):
+class UvicornStructlogFilter(logging.Filter):
     def filter(self, record: logging.LogRecord) -> bool:
         if hasattr(record, 'name') and 'uvicorn.access' in record.name:
             if hasattr(record, 'getMessage'):
@@ -39,113 +39,75 @@ class UvicornLogFilter(logging.Filter):
                         if len(request_part) >= 2:
                             method_path = request_part[0]
                             status_part = request_part[1]
-                            record.msg = f"Access: {client_info} - {method_path} - {status_part}"
-
+                            record.client = client_info
+                            record.request = method_path
+                            record.status = status_part
         return True
 
 
-class PyServeFormatter(logging.Formatter):
-    COLORS = {
-        'DEBUG': '\033[36m',      # Cyan
-        'INFO': '\033[32m',       # Green
-        'WARNING': '\033[33m',    # Yellow
-        'ERROR': '\033[31m',      # Red
-        'CRITICAL': '\033[35m',   # Magenta
-        'RESET': '\033[0m'        # Reset
-    }
-
-    def __init__(self, use_colors: bool = True, show_module: bool = True,
-                 timestamp_format: str = "%Y-%m-%d %H:%M:%S", *args: Any, **kwargs: Any):
-        super().__init__(*args, **kwargs)
-        self.use_colors = use_colors and hasattr(sys.stderr, 'isatty') and sys.stderr.isatty()
-        self.show_module = show_module
-        self.timestamp_format = timestamp_format
-
-    def format(self, record: logging.LogRecord) -> str:
-        if self.use_colors:
-            levelname = record.levelname
-            if levelname in self.COLORS:
-                record.levelname = f"{self.COLORS[levelname]}{levelname}{self.COLORS['RESET']}"
-
-        if self.show_module and hasattr(record, 'name'):
-            name = record.name
-            if name.startswith('uvicorn'):
-                record.name = 'uvicorn'
-            elif name.startswith('pyserve'):
-                pass
-            elif name.startswith('starlette'):
-                record.name = 'starlette'
-
-        return super().format(record)
+def add_timestamp(logger: FilteringBoundLogger, method_name: str, event_dict: EventDict) -> EventDict:
+    event_dict["timestamp"] = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime())
+    return event_dict
 
 
-class PyServeJSONFormatter(logging.Formatter):
-    def __init__(self, timestamp_format: str = "%Y-%m-%d %H:%M:%S", *args: Any, **kwargs: Any):
-        super().__init__(*args, **kwargs)
-        self.timestamp_format = timestamp_format
-
-    def format(self, record: logging.LogRecord) -> str:
-        log_entry = {
-            'timestamp': time.strftime(self.timestamp_format, time.localtime(record.created)),
-            'level': record.levelname,
-            'logger': record.name,
-            'message': record.getMessage(),
-            'module': record.module,
-            'function': record.funcName,
-            'line': record.lineno,
-            'thread': record.thread,
-            'thread_name': record.threadName,
-        }
-
-        if record.exc_info:
-            log_entry['exception'] = self.formatException(record.exc_info)
-
-        for key, value in record.__dict__.items():
-            if key not in ['name', 'msg', 'args', 'levelname', 'levelno', 'pathname',
-                           'filename', 'module', 'lineno', 'funcName', 'created',
-                           'msecs', 'relativeCreated', 'thread', 'threadName',
-                           'processName', 'process', 'getMessage', 'exc_info', 'exc_text', 'stack_info']:
-                log_entry[key] = value
-
-        return json.dumps(log_entry, ensure_ascii=False, default=str)
+def add_log_level(logger: FilteringBoundLogger, method_name: str, event_dict: EventDict) -> EventDict:
+    event_dict["level"] = method_name.upper()
+    return event_dict
 
 
-class AccessLogHandler(logging.Handler):
-    def __init__(self, logger_name: str = 'pyserve.access'):
-        super().__init__()
-        self.access_logger = logging.getLogger(logger_name)
+def add_module_info(logger: FilteringBoundLogger, method_name: str, event_dict: EventDict) -> EventDict:
+    if hasattr(logger, '_context') and 'logger_name' in logger._context:
+        logger_name = logger._context['logger_name']
+        if logger_name.startswith('pyserve'):
+            event_dict["module"] = logger_name
+        elif logger_name.startswith('uvicorn'):
+            event_dict["module"] = 'uvicorn'
+        elif logger_name.startswith('starlette'):
+            event_dict["module"] = 'starlette'
+        else:
+            event_dict["module"] = logger_name
+    return event_dict
 
-    def emit(self, record: logging.LogRecord) -> None:
-        self.access_logger.handle(record)
+
+def filter_module_info(show_module: bool) -> Callable[[FilteringBoundLogger, str, EventDict], EventDict]:
+    def processor(logger: FilteringBoundLogger, method_name: str, event_dict: EventDict) -> EventDict:
+        if not show_module and "module" in event_dict:
+            del event_dict["module"]
+        return event_dict
+    return processor
+
+
+def colored_console_renderer(use_colors: bool = True, show_module: bool = True) -> structlog.dev.ConsoleRenderer:
+    return structlog.dev.ConsoleRenderer(
+        colors=use_colors and hasattr(sys.stderr, 'isatty') and sys.stderr.isatty(),
+        level_styles={
+            "critical": "\033[35m",  # Magenta
+            "error": "\033[31m",     # Red
+            "warning": "\033[33m",   # Yellow
+            "info": "\033[32m",      # Green
+            "debug": "\033[36m",     # Cyan
+        },
+        pad_event=25,
+    )
+
+
+def plain_console_renderer(show_module: bool = True) -> structlog.dev.ConsoleRenderer:
+    return structlog.dev.ConsoleRenderer(
+        colors=False,
+        pad_event=25,
+    )
+
+
+def json_renderer() -> structlog.processors.JSONRenderer:
+    return structlog.processors.JSONRenderer(ensure_ascii=False, sort_keys=True)
 
 
 class PyServeLogManager:
     def __init__(self) -> None:
         self.configured = False
         self.handlers: Dict[str, logging.Handler] = {}
-        self.loggers: Dict[str, logging.Logger] = {}
         self.original_handlers: Dict[str, List[logging.Handler]] = {}
-
-    def _create_formatter(self, format_config: Dict[str, Any]) -> logging.Formatter:
-        format_type = format_config.get('type', 'standard').lower()
-        use_colors = format_config.get('use_colors', True)
-        show_module = format_config.get('show_module', True)
-        timestamp_format = format_config.get('timestamp_format', '%Y-%m-%d %H:%M:%S')
-
-        if format_type == 'json':
-            return PyServeJSONFormatter(timestamp_format=timestamp_format)
-        else:
-            if format_type == 'json':
-                fmt = None
-            else:
-                fmt = '%(asctime)s - %(name)s - %(levelname)s - [%(filename)s:%(lineno)d] - %(message)s'
-
-            return PyServeFormatter(
-                use_colors=use_colors,
-                show_module=show_module,
-                timestamp_format=timestamp_format,
-                fmt=fmt
-            )
+        self._structlog_configured = False
 
     def setup_logging(self, config: Dict[str, Any]) -> None:
         if self.configured:
@@ -192,25 +154,85 @@ class PyServeLogManager:
         self._save_original_handlers()
         self._clear_all_handlers()
 
-        root_logger = logging.getLogger()
-        root_logger.setLevel(logging.DEBUG)
+        self._configure_structlog(
+            main_level=main_level,
+            console_output=console_output,
+            console_format=console_format,
+            console_level=console_level,
+            files_config=files_config
+        )
+
+        self._configure_stdlib_loggers(main_level)
+
+        logger = self.get_logger('pyserve')
+        logger.info(
+            "PyServe logger initialized",
+            version=__version__,
+            level=main_level,
+            console_output=console_output,
+            console_format=console_format.get('type', 'standard')
+        )
+
+        for i, file_config in enumerate(files_config):
+            logger.info(
+                "File logging configured",
+                file_index=i,
+                path=file_config.get('path'),
+                level=file_config.get('level', main_level),
+                format_type=file_config.get('format', {}).get('type', 'standard')
+            )
+
+        self.configured = True
+
+    def _configure_structlog(
+        self,
+        main_level: str,
+        console_output: bool,
+        console_format: Dict[str, Any],
+        console_level: str,
+        files_config: List[Dict[str, Any]]
+    ) -> None:
+        shared_processors = [
+            structlog.stdlib.filter_by_level,
+            add_timestamp,
+            add_log_level,
+            add_module_info,
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.format_exc_info,
+        ]
 
         if console_output:
-            console_handler = logging.StreamHandler(sys.stdout)
-            console_handler.setLevel(getattr(logging, console_level))
+            console_show_module = console_format.get('show_module', True)
+            console_processors = shared_processors.copy()
+
+            console_processors.append(filter_module_info(console_show_module))
 
             if console_format.get('type') == 'json':
-                console_formatter = self._create_formatter(console_format)
+                console_processors.append(json_renderer())
             else:
-                console_formatter = PyServeFormatter(
-                    use_colors=console_format.get('use_colors', True),
-                    show_module=console_format.get('show_module', True),
-                    timestamp_format=console_format.get('timestamp_format', '%Y-%m-%d %H:%M:%S'),
-                    fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s'
+                console_processors.append(
+                    colored_console_renderer(
+                        console_format.get('use_colors', True),
+                        console_show_module
+                    )
                 )
 
+            console_handler = logging.StreamHandler(sys.stdout)
+            console_handler.setLevel(getattr(logging, console_level))
+            console_handler.addFilter(UvicornStructlogFilter())
+
+            console_formatter = structlog.stdlib.ProcessorFormatter(
+                processor=colored_console_renderer(
+                    console_format.get('use_colors', True),
+                    console_show_module
+                )
+                if console_format.get('type') != 'json'
+                else json_renderer(),
+            )
             console_handler.setFormatter(console_formatter)
-            console_handler.addFilter(UvicornLogFilter())
+
+            root_logger = logging.getLogger()
+            root_logger.setLevel(logging.DEBUG)
             root_logger.addHandler(console_handler)
             self.handlers['console'] = console_handler
 
@@ -220,7 +242,8 @@ class PyServeLogManager:
             file_loggers = file_config.get('loggers', [])
             max_bytes = file_config.get('max_bytes', 10 * 1024 * 1024)
             backup_count = file_config.get('backup_count', 5)
-            file_format = {**global_format, **file_config.get('format', {})}
+            file_format = file_config.get('format', {})
+            file_show_module = file_format.get('show_module', True)
 
             self._ensure_log_directory(file_path)
 
@@ -232,50 +255,58 @@ class PyServeLogManager:
             )
             file_handler.setLevel(getattr(logging, file_level))
 
-            if file_format.get('type') == 'json':
-                file_formatter = self._create_formatter(file_format)
-            else:
-                file_formatter = PyServeFormatter(
-                    use_colors=file_format.get('use_colors', False),
-                    show_module=file_format.get('show_module', True),
-                    timestamp_format=file_format.get('timestamp_format', '%Y-%m-%d %H:%M:%S'),
-                    fmt='%(asctime)s - %(name)s - %(levelname)s - [%(filename)s:%(lineno)d] - %(message)s'
-                )
-
-            file_handler.setFormatter(file_formatter)
-            file_handler.addFilter(UvicornLogFilter())
             if file_loggers:
-                logger_filter = LoggerFilter(file_loggers)
-                file_handler.addFilter(logger_filter)
+                file_handler.addFilter(StructlogFilter(file_loggers))
 
+            file_processors = shared_processors.copy()
+            file_processors.append(filter_module_info(file_show_module))
+
+            file_formatter = structlog.stdlib.ProcessorFormatter(
+                processor=json_renderer()
+                if file_format.get('type') == 'json'
+                else plain_console_renderer(file_show_module),
+            )
+            file_handler.setFormatter(file_formatter)
+
+            root_logger = logging.getLogger()
             root_logger.addHandler(file_handler)
             self.handlers[f'file_{i}'] = file_handler
 
-        self._configure_library_loggers(main_level)
-        self._intercept_uvicorn_logging()
+        base_processors = [
+            structlog.stdlib.filter_by_level,
+            add_timestamp,
+            add_log_level,
+            add_module_info,
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.format_exc_info,
+        ]
 
-        pyserve_logger = logging.getLogger('pyserve')
-        pyserve_logger.setLevel(getattr(logging, main_level))
-        self.loggers['pyserve'] = pyserve_logger
+        structlog.configure(
+            processors=cast(Any, base_processors + [structlog.stdlib.ProcessorFormatter.wrap_for_formatter]),
+            context_class=dict,
+            logger_factory=structlog.stdlib.LoggerFactory(),
+            wrapper_class=structlog.stdlib.BoundLogger,
+            cache_logger_on_first_use=True,
+        )
 
-        pyserve_logger.info(f"PyServe v{__version__} - Logger initialized")
-        pyserve_logger.info(f"Logging level: {main_level}")
-        pyserve_logger.info(f"Console output: {'enabled' if console_output else 'disabled'}")
-        pyserve_logger.info(f"Console format: {console_format.get('type', 'standard')}")
+        self._structlog_configured = True
 
-        for i, file_config in enumerate(files_config):
-            file_path = file_config.get('path', './logs/pyserve.log')
-            file_loggers = file_config.get('loggers', [])
-            file_format = file_config.get('format', {})
+    def _configure_stdlib_loggers(self, main_level: str) -> None:
+        library_configs = {
+            'uvicorn': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
+            'uvicorn.access': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
+            'uvicorn.error': 'DEBUG' if main_level == 'DEBUG' else 'ERROR',
+            'uvicorn.asgi': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
+            'starlette': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
+            'asyncio': 'WARNING',
+            'concurrent.futures': 'WARNING',
+            'multiprocessing': 'WARNING',
+        }
 
-            pyserve_logger.info(f"Log file[{i}]: {file_path}")
-            pyserve_logger.info(f"File format[{i}]: {file_format.get('type', 'standard')}")
-            if file_loggers:
-                pyserve_logger.info(f"File loggers[{i}]: {', '.join(file_loggers)}")
-            else:
-                pyserve_logger.info(f"File loggers[{i}]: all loggers")
-
-        self.configured = True
+        for logger_name, level in library_configs.items():
+            logger = logging.getLogger(logger_name)
+            logger.setLevel(getattr(logging, level))
+            logger.propagate = True
 
     def _save_original_handlers(self) -> None:
         logger_names = ['', 'uvicorn', 'uvicorn.access', 'uvicorn.error', 'starlette']
@@ -288,14 +319,12 @@ class PyServeLogManager:
         root_logger = logging.getLogger()
         for handler in root_logger.handlers[:]:
             root_logger.removeHandler(handler)
-            handler.close()
 
         logger_names = ['uvicorn', 'uvicorn.access', 'uvicorn.error', 'starlette']
         for name in logger_names:
             logger = logging.getLogger(name)
             for handler in logger.handlers[:]:
                 logger.removeHandler(handler)
-                handler.close()
 
         self.handlers.clear()
 
@@ -303,57 +332,29 @@ class PyServeLogManager:
         log_dir = Path(log_file).parent
         log_dir.mkdir(parents=True, exist_ok=True)
 
-    def _configure_library_loggers(self, main_level: str) -> None:
-        library_configs = {
-            # Uvicorn and related - only in DEBUG mode
-            'uvicorn': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
-            'uvicorn.access': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
-            'uvicorn.error': 'DEBUG' if main_level == 'DEBUG' else 'ERROR',
-            'uvicorn.asgi': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
+    def get_logger(self, name: str) -> structlog.stdlib.BoundLogger:
+        if not self._structlog_configured:
+            structlog.configure(
+                processors=cast(Any, [
+                    structlog.stdlib.filter_by_level,
+                    add_timestamp,
+                    add_log_level,
+                    structlog.processors.StackInfoRenderer(),
+                    structlog.processors.format_exc_info,
+                    structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+                ]),
+                context_class=dict,
+                logger_factory=structlog.stdlib.LoggerFactory(),
+                wrapper_class=structlog.stdlib.BoundLogger,
+                cache_logger_on_first_use=True,
+            )
+            self._structlog_configured = True
 
-            # Starlette - only in DEBUG mode
-            'starlette': 'DEBUG' if main_level == 'DEBUG' else 'WARNING',
-
-            'asyncio': 'WARNING',
-            'concurrent.futures': 'WARNING',
-            'multiprocessing': 'WARNING',
-            'pyserve': main_level,
-            'pyserve.server': main_level,
-            'pyserve.routing': main_level,
-            'pyserve.extensions': main_level,
-            'pyserve.config': main_level,
-        }
-
-        for logger_name, level in library_configs.items():
-            logger = logging.getLogger(logger_name)
-            logger.setLevel(getattr(logging, level))
-            if logger_name.startswith('uvicorn') and logger_name != 'uvicorn':
-                logger.propagate = False
-            self.loggers[logger_name] = logger
-
-    def _intercept_uvicorn_logging(self) -> None:
-        uvicorn_logger = logging.getLogger('uvicorn')
-        uvicorn_access_logger = logging.getLogger('uvicorn.access')
-
-        for handler in uvicorn_logger.handlers[:]:
-            uvicorn_logger.removeHandler(handler)
-
-        for handler in uvicorn_access_logger.handlers[:]:
-            uvicorn_access_logger.removeHandler(handler)
-
-        uvicorn_logger.propagate = True
-        uvicorn_access_logger.propagate = True
-
-    def get_logger(self, name: str) -> logging.Logger:
-        if name not in self.loggers:
-            logger = logging.getLogger(name)
-            self.loggers[name] = logger
-
-        return self.loggers[name]
+        return cast(structlog.stdlib.BoundLogger, structlog.get_logger(name).bind(logger_name=name))
 
     def set_level(self, logger_name: str, level: str) -> None:
-        if logger_name in self.loggers:
-            self.loggers[logger_name].setLevel(getattr(logging, level.upper()))
+        logger = logging.getLogger(logger_name)
+        logger.setLevel(getattr(logging, level.upper()))
 
     def add_handler(self, name: str, handler: logging.Handler) -> None:
         if name not in self.handlers:
@@ -363,20 +364,32 @@ class PyServeLogManager:
 
     def remove_handler(self, name: str) -> None:
         if name in self.handlers:
+            handler = self.handlers[name]
             root_logger = logging.getLogger()
-            root_logger.removeHandler(self.handlers[name])
-            self.handlers[name].close()
+            root_logger.removeHandler(handler)
+            handler.close()
             del self.handlers[name]
 
-    def create_access_log(self, method: str, path: str, status_code: int,
-                          response_time: float, client_ip: str, user_agent: str = "") -> None:
+    def create_access_log(
+        self,
+        method: str,
+        path: str,
+        status_code: int,
+        response_time: float,
+        client_ip: str,
+        user_agent: str = ""
+    ) -> None:
         access_logger = self.get_logger('pyserve.access')
-
-        log_message = f'{client_ip} - - [{time.strftime("%d/%b/%Y:%H:%M:%S %z")}] ' \
-                      f'"{method} {path} HTTP/1.1" {status_code} - ' \
-                      f'"{user_agent}" {response_time:.3f}s'
-
-        access_logger.info(log_message)
+        access_logger.info(
+            "HTTP access",
+            method=method,
+            path=path,
+            status_code=status_code,
+            response_time_ms=round(response_time * 1000, 2),
+            client_ip=client_ip,
+            user_agent=user_agent,
+            timestamp_format="access"
+        )
 
     def shutdown(self) -> None:
         for handler in self.handlers.values():
@@ -388,8 +401,8 @@ class PyServeLogManager:
             for handler in handlers:
                 logger.addHandler(handler)
 
-        self.loggers.clear()
         self.configured = False
+        self._structlog_configured = False
 
 
 log_manager = PyServeLogManager()
@@ -399,12 +412,18 @@ def setup_logging(config: Dict[str, Any]) -> None:
     log_manager.setup_logging(config)
 
 
-def get_logger(name: str) -> logging.Logger:
+def get_logger(name: str) -> structlog.stdlib.BoundLogger:
     return log_manager.get_logger(name)
 
 
-def create_access_log(method: str, path: str, status_code: int,
-                      response_time: float, client_ip: str, user_agent: str = "") -> None:
+def create_access_log(
+    method: str,
+    path: str,
+    status_code: int,
+    response_time: float,
+    client_ip: str,
+    user_agent: str = ""
+) -> None:
     log_manager.create_access_log(method, path, status_code, response_time, client_ip, user_agent)