From b219d2ef303f8e2abf53db5250a7ebd3a4e0f18e Mon Sep 17 00:00:00 2001 From: Cyber MacGeddon Date: Wed, 30 Jul 2025 21:43:12 +0100 Subject: [PATCH] Logging strategy and updated base class --- docs/LOGGING_STRATEGY.md | 169 ++++++++++++++++++ .../trustgraph/base/async_processor.py | 55 ++++-- 2 files changed, 211 insertions(+), 13 deletions(-) create mode 100644 docs/LOGGING_STRATEGY.md diff --git a/docs/LOGGING_STRATEGY.md b/docs/LOGGING_STRATEGY.md new file mode 100644 index 00000000..b05b7c59 --- /dev/null +++ b/docs/LOGGING_STRATEGY.md @@ -0,0 +1,169 @@ +# TrustGraph Logging Strategy + +## Overview + +TrustGraph uses Python's built-in `logging` module for all logging operations. This provides a standardized, flexible approach to logging across all components of the system. + +## Default Configuration + +### Logging Level +- **Default Level**: `INFO` +- **Debug Mode**: `DEBUG` (enabled via command-line argument) +- **Production**: `WARNING` or `ERROR` as appropriate + +### Output Destination +All logs should be written to **standard output (stdout)** to ensure compatibility with containerized environments and log aggregation systems. + +## Implementation Guidelines + +### 1. Logger Initialization + +Each module should create its own logger using the module's `__name__`: + +```python +import logging + +logger = logging.getLogger(__name__) +``` + +### 2. Centralized Configuration + +The logging configuration should be centralized in `async_processor.py` (or a dedicated logging configuration module) since it's inherited by much of the codebase: + +```python +import logging +import argparse + +def setup_logging(log_level='INFO'): + """Configure logging for the entire application""" + logging.basicConfig( + level=getattr(logging, log_level.upper()), + format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', + handlers=[logging.StreamHandler()] + ) + +def parse_args(): + parser = argparse.ArgumentParser() + parser.add_argument( + '--log-level', + default='INFO', + choices=['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'], + help='Set the logging level (default: INFO)' + ) + return parser.parse_args() + +# In main execution +if __name__ == '__main__': + args = parse_args() + setup_logging(args.log_level) +``` + +### 3. Logging Best Practices + +#### Log Levels Usage +- **DEBUG**: Detailed information for diagnosing problems (variable values, function entry/exit) +- **INFO**: General informational messages (service started, configuration loaded, processing milestones) +- **WARNING**: Warning messages for potentially harmful situations (deprecated features, recoverable errors) +- **ERROR**: Error messages for serious problems (failed operations, exceptions) +- **CRITICAL**: Critical messages for system failures requiring immediate attention + +#### Message Format +```python +# Good - includes context +logger.info(f"Processing document: {doc_id}, size: {doc_size} bytes") +logger.error(f"Failed to connect to database: {error}", exc_info=True) + +# Avoid - lacks context +logger.info("Processing document") +logger.error("Connection failed") +``` + +#### Performance Considerations +```python +# Use lazy formatting for expensive operations +logger.debug("Expensive operation result: %s", expensive_function()) + +# Check log level for very expensive debug operations +if logger.isEnabledFor(logging.DEBUG): + debug_data = compute_expensive_debug_info() + logger.debug(f"Debug data: {debug_data}") +``` + +### 4. Structured Logging + +For complex data, use structured logging: + +```python +logger.info("Request processed", extra={ + 'request_id': request_id, + 'duration_ms': duration, + 'status_code': status_code, + 'user_id': user_id +}) +``` + +### 5. Exception Logging + +Always include stack traces for exceptions: + +```python +try: + process_data() +except Exception as e: + logger.error(f"Failed to process data: {e}", exc_info=True) + raise +``` + +### 6. Async Logging Considerations + +For async code, ensure thread-safe logging: + +```python +import asyncio +import logging + +async def async_operation(): + logger = logging.getLogger(__name__) + logger.info(f"Starting async operation in task: {asyncio.current_task().get_name()}") +``` + +## Environment Variables + +Support environment-based configuration as a fallback: + +```python +import os + +log_level = os.environ.get('TRUSTGRAPH_LOG_LEVEL', 'INFO') +``` + +## Testing + +During tests, consider using a different logging configuration: + +```python +# In test setup +logging.getLogger().setLevel(logging.WARNING) # Reduce noise during tests +``` + +## Monitoring Integration + +Ensure log format is compatible with monitoring tools: +- Include timestamps in ISO format +- Use consistent field names +- Include correlation IDs where applicable +- Structure logs for easy parsing (JSON format for production) + +## Security Considerations + +- Never log sensitive information (passwords, API keys, personal data) +- Sanitize user input before logging +- Use placeholders for sensitive fields: `user_id=****1234` + +## Migration Path + +For existing code using print statements: +1. Replace `print()` with appropriate logger calls +2. Choose appropriate log levels based on message importance +3. Add context to make logs more useful +4. Test logging output at different levels \ No newline at end of file diff --git a/trustgraph-base/trustgraph/base/async_processor.py b/trustgraph-base/trustgraph/base/async_processor.py index 545220c4..5496ca9b 100644 --- a/trustgraph-base/trustgraph/base/async_processor.py +++ b/trustgraph-base/trustgraph/base/async_processor.py @@ -9,6 +9,8 @@ import argparse import _pulsar import time import uuid +import logging +import os from prometheus_client import start_http_server, Info from .. schema import ConfigPush, config_push_queue @@ -20,6 +22,9 @@ from . metrics import ProcessorMetrics, ConsumerMetrics default_config_queue = config_push_queue +# Module logger +logger = logging.getLogger(__name__) + # Async processor class AsyncProcessor: @@ -113,7 +118,7 @@ class AsyncProcessor: version = message.value().version # Invoke message handlers - print("Config change event", version, flush=True) + logger.info(f"Config change event: version={version}") for ch in self.config_handlers: await ch(config, version) @@ -156,9 +161,23 @@ class AsyncProcessor: # This is here to output a debug message, shouldn't be needed. except Exception as e: - print("Exception, closing taskgroup", flush=True) + logger.error("Exception, closing taskgroup", exc_info=True) raise e + @classmethod + def setup_logging(cls, log_level='INFO'): + """Configure logging for the entire application""" + # Support environment variable override + env_log_level = os.environ.get('TRUSTGRAPH_LOG_LEVEL', log_level) + + # Configure logging + logging.basicConfig( + level=getattr(logging, env_log_level.upper()), + format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', + handlers=[logging.StreamHandler()] + ) + logger.info(f"Logging configured with level: {env_log_level}") + # Startup fabric. launch calls launch_async in async mode. @classmethod def launch(cls, ident, doc): @@ -183,8 +202,11 @@ class AsyncProcessor: args = parser.parse_args() args = vars(args) + # Setup logging before anything else + cls.setup_logging(args.get('log_level', 'INFO').upper()) + # Debug - print(args, flush=True) + logger.debug(f"Arguments: {args}") # Start the Prometheus metrics service if needed if args["metrics"]: @@ -193,7 +215,7 @@ class AsyncProcessor: # Loop forever, exception handler while True: - print("Starting...", flush=True) + logger.info("Starting...") try: @@ -203,30 +225,30 @@ class AsyncProcessor: )) except KeyboardInterrupt: - print("Keyboard interrupt.", flush=True) + logger.info("Keyboard interrupt.") return except _pulsar.Interrupted: - print("Pulsar Interrupted.", flush=True) + logger.info("Pulsar Interrupted.") return # Exceptions from a taskgroup come in as an exception group except ExceptionGroup as e: - print("Exception group:", flush=True) + logger.error("Exception group:") for se in e.exceptions: - print(" Type:", type(se), flush=True) - print(f" Exception: {se}", flush=True) + logger.error(f" Type: {type(se)}") + logger.error(f" Exception: {se}", exc_info=se) except Exception as e: - print("Type:", type(e), flush=True) - print("Exception:", e, flush=True) + logger.error(f"Type: {type(e)}") + logger.error(f"Exception: {e}", exc_info=True) # Retry occurs here - print("Will retry...", flush=True) + logger.warning("Will retry...") time.sleep(4) - print("Retrying...", flush=True) + logger.info("Retrying...") # The command-line arguments are built using a stack of add_args # invocations @@ -254,3 +276,10 @@ class AsyncProcessor: default=8000, help=f'Pulsar host (default: 8000)', ) + + parser.add_argument( + '--log-level', + default='INFO', + choices=['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'], + help='Set the logging level (default: INFO)', + )