Logging strategy and updated base class

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

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)
+                    logger.error(f"  Type: {type(se)}")
-                    print(f"  Exception: {se}", flush=True)
+                    logger.error(f"  Exception: {se}", exc_info=se)
 
             except Exception as e:
-                print("Type:", type(e), flush=True)
+                logger.error(f"Type: {type(e)}")
-                print("Exception:", e, flush=True)
+                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)',
+        )