Files
GOV_QR_Codes_Management/logger_handler.py
T
2025-08-12 09:55:26 -04:00

725 lines
26 KiB
Python

#!/usr/bin/env python3
"""
Enhanced Logging Handler for QR Attendance Management System
==========================================================
This module provides comprehensive logging functionality for:
- User login/logout activities with session details
- QR code creation, modification, and deletion operations
- Database transaction errors and connection issues
- Flask application errors and exceptions
- Security events and unauthorized access attempts
Features:
- Structured JSON logging for better analytics
- Rotating log files to prevent disk space issues
- Different log levels for various event types
- Database logging table for critical events
- Performance monitoring and error tracking
"""
import logging
import logging.handlers
import json
import os
import traceback
from datetime import datetime, date
from functools import wraps
from flask import request, session, g
from sqlalchemy import text
from sqlalchemy.exc import SQLAlchemyError
import uuid
class AppLogger:
"""
Enhanced application logger with multiple output formats and destinations
"""
def __init__(self, app=None, db=None):
"""Initialize the logger with Flask app and database instances"""
self.app = app
self.db = db
self.logger = None
self.security_logger = None
if app:
self.init_app(app, db)
def init_app(self, app, db):
"""Initialize logging with Flask application context"""
self.app = app
self.db = db
# Create logs directory if it doesn't exist
log_dir = os.path.join(app.root_path, 'logs')
os.makedirs(log_dir, exist_ok=True)
# Configure main application logger
self.logger = logging.getLogger('qr_attendance_app')
self.logger.setLevel(logging.INFO)
# Configure security logger for sensitive events
self.security_logger = logging.getLogger('qr_attendance_security')
self.security_logger.setLevel(logging.WARNING)
# Remove existing handlers to avoid duplication
self.logger.handlers.clear()
self.security_logger.handlers.clear()
# Setup file handlers with rotation
self._setup_file_handlers(log_dir)
# Setup console handler for development
self._setup_console_handler()
# Create database logging table
self._create_log_table()
# Register error handlers with Flask
self._register_error_handlers()
app.logger_handler = self
def _setup_file_handlers(self, log_dir):
"""Setup rotating file handlers for different log types"""
# Main application log (rotates when 10MB, keeps 5 files)
app_handler = logging.handlers.RotatingFileHandler(
os.path.join(log_dir, 'application.log'),
maxBytes=10*1024*1024, # 10MB
backupCount=5
)
app_handler.setLevel(logging.INFO)
# Error log (rotates when 5MB, keeps 10 files)
error_handler = logging.handlers.RotatingFileHandler(
os.path.join(log_dir, 'errors.log'),
maxBytes=5*1024*1024, # 5MB
backupCount=10
)
error_handler.setLevel(logging.ERROR)
# Security log (rotates when 2MB, keeps 20 files for compliance)
security_handler = logging.handlers.RotatingFileHandler(
os.path.join(log_dir, 'security.log'),
maxBytes=2*1024*1024, # 2MB
backupCount=20
)
security_handler.setLevel(logging.WARNING)
# Create custom formatter with JSON structure
formatter = logging.Formatter(
'%(asctime)s | %(levelname)s | %(name)s | %(message)s',
datefmt='%Y-%m-%d %H:%M:%S'
)
app_handler.setFormatter(formatter)
error_handler.setFormatter(formatter)
security_handler.setFormatter(formatter)
# Add handlers to loggers
self.logger.addHandler(app_handler)
self.logger.addHandler(error_handler)
self.security_logger.addHandler(security_handler)
def _setup_console_handler(self):
"""Setup console handler for development environment"""
if self.app.debug:
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.DEBUG)
console_formatter = logging.Formatter(
'%(asctime)s [%(levelname)s] %(message)s',
datefmt='%H:%M:%S'
)
console_handler.setFormatter(console_formatter)
self.logger.addHandler(console_handler)
def _create_log_table(self):
"""Create database table for storing critical log events"""
try:
with self.app.app_context():
# Create log_events table if it doesn't exist
create_table_sql = """
CREATE TABLE IF NOT EXISTS log_events (
id INT AUTO_INCREMENT PRIMARY KEY,
event_id VARCHAR(36) UNIQUE NOT NULL,
event_type VARCHAR(50) NOT NULL,
event_category VARCHAR(30) NOT NULL,
user_id INT NULL,
username VARCHAR(80) NULL,
event_description TEXT NOT NULL,
event_data JSON NULL,
ip_address VARCHAR(45) NULL,
user_agent TEXT NULL,
request_path VARCHAR(500) NULL,
session_id VARCHAR(100) NULL,
severity_level VARCHAR(20) DEFAULT 'INFO',
created_timestamp DATETIME DEFAULT CURRENT_TIMESTAMP,
INDEX idx_event_type (event_type),
INDEX idx_event_category (event_category),
INDEX idx_user_id (user_id),
INDEX idx_created_timestamp (created_timestamp),
INDEX idx_severity_level (severity_level)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
"""
self.db.session.execute(text(create_table_sql))
self.db.session.commit()
except Exception as e:
print(f"Warning: Could not create log_events table: {e}")
def _register_error_handlers(self):
"""Register Flask error handlers for automatic logging"""
@self.app.errorhandler(500)
def handle_internal_error(error):
"""Log internal server errors automatically"""
self.log_flask_error(
error_type="InternalServerError",
error_message=str(error),
stack_trace=traceback.format_exc()
)
# Return user-friendly error page
if self.app.debug:
return None # Let Flask handle debug errors
return '''
<!DOCTYPE html>
<html>
<head><title>Server Error</title></head>
<body style="font-family: Arial; text-align: center; margin-top: 100px;">
<h1>🔧 Something went wrong</h1>
<p>We're working to fix this issue. Please try again later.</p>
<a href="/" style="color: #2563eb;">← Back to Home</a>
</body>
</html>
''', 500
@self.app.errorhandler(404)
def handle_not_found(error):
"""Log 404 errors for security monitoring"""
self.log_security_event(
event_type="page_not_found",
description=f"404 error: {request.path}",
severity="LOW"
)
return '''
<!DOCTYPE html>
<html>
<head><title>Page Not Found</title></head>
<body style="font-family: Arial; text-align: center; margin-top: 100px;">
<h1>🔍 Page Not Found</h1>
<p>The page you're looking for doesn't exist.</p>
<a href="/" style="color: #2563eb;">← Back to Home</a>
</body>
</html>
''', 404
def _get_request_context(self):
"""Get current request context information"""
if not request:
return {}
return {
'ip_address': request.environ.get('HTTP_X_FORWARDED_FOR', request.remote_addr),
'user_agent': request.headers.get('User-Agent', ''),
'request_path': request.path,
'request_method': request.method,
'session_id': session.get('_id', 'anonymous'),
'user_id': session.get('user_id'),
'username': session.get('username')
}
def _log_to_database(self, event_type, event_category, description, event_data=None, severity='INFO'):
"""Log critical events to database table"""
try:
context = self._get_request_context()
event_id = str(uuid.uuid4())
insert_sql = """
INSERT INTO log_events (
event_id, event_type, event_category, user_id, username,
event_description, event_data, ip_address, user_agent,
request_path, session_id, severity_level
) VALUES (
:event_id, :event_type, :event_category, :user_id, :username,
:description, :event_data, :ip_address, :user_agent,
:request_path, :session_id, :severity
)
"""
self.db.session.execute(text(insert_sql), {
'event_id': event_id,
'event_type': event_type,
'event_category': event_category,
'user_id': context.get('user_id'),
'username': context.get('username'),
'description': description,
'event_data': json.dumps(event_data) if event_data else None,
'ip_address': context.get('ip_address'),
'user_agent': context.get('user_agent'),
'request_path': context.get('request_path'),
'session_id': context.get('session_id'),
'severity': severity
})
self.db.session.commit()
except Exception as e:
# Don't let logging errors break the application
print(f"Database logging error: {e}")
try:
self.db.session.rollback()
except:
pass
# USER LOGIN/LOGOUT LOGGING METHODS
def log_user_login(self, user_id, username, success=True, failure_reason=None):
"""Log user login attempts with detailed session information"""
context = self._get_request_context()
event_data = {
'user_id': user_id,
'username': username,
'success': success,
'login_timestamp': datetime.now().isoformat(),
'session_info': {
'session_id': context.get('session_id'),
'ip_address': context.get('ip_address'),
'user_agent': context.get('user_agent')
}
}
if failure_reason:
event_data['failure_reason'] = failure_reason
if success:
message = f"User login successful: {username} (ID: {user_id})"
self.logger.info(json.dumps({
'event': 'user_login_success',
'data': event_data
}))
# Log to database for security monitoring
self._log_to_database(
event_type='user_login_success',
event_category='authentication',
description=message,
event_data=event_data,
severity='INFO'
)
else:
message = f"User login failed: {username} - {failure_reason}"
self.security_logger.warning(json.dumps({
'event': 'user_login_failure',
'data': event_data
}))
# Log failed logins to database for security analysis
self._log_to_database(
event_type='user_login_failure',
event_category='security',
description=message,
event_data=event_data,
severity='WARNING'
)
def log_user_logout(self, user_id, username, session_duration=None):
"""Log user logout events with session duration"""
context = self._get_request_context()
event_data = {
'user_id': user_id,
'username': username,
'logout_timestamp': datetime.now().isoformat(),
'session_duration_minutes': session_duration,
'session_info': {
'session_id': context.get('session_id'),
'ip_address': context.get('ip_address')
}
}
message = f"User logout: {username} (ID: {user_id})"
if session_duration:
message += f" - Session duration: {session_duration} minutes"
self.logger.info(json.dumps({
'event': 'user_logout',
'data': event_data
}))
# Log to database
self._log_to_database(
event_type='user_logout',
event_category='authentication',
description=message,
event_data=event_data
)
# QR CODE LOGGING METHODS
def log_qr_code_created(self, qr_code_id, qr_code_name, created_by_user_id, qr_data):
"""Log QR code creation events"""
event_data = {
'qr_code_id': qr_code_id,
'qr_code_name': qr_code_name,
'created_by_user_id': created_by_user_id,
'created_timestamp': datetime.now().isoformat(),
'qr_code_details': {
'location': qr_data.get('location'),
'location_address': qr_data.get('location_address'),
'location_event': qr_data.get('location_event'),
'has_coordinates': qr_data.get('has_coordinates', False)
}
}
if qr_data.get('has_coordinates'):
event_data['qr_code_details']['coordinates'] = {
'latitude': qr_data.get('latitude'),
'longitude': qr_data.get('longitude'),
'accuracy': qr_data.get('coordinate_accuracy')
}
message = f"QR code created: {qr_code_name} (ID: {qr_code_id}) by user {created_by_user_id}"
self.logger.info(json.dumps({
'event': 'qr_code_created',
'data': event_data
}))
# Log to database
self._log_to_database(
event_type='qr_code_created',
event_category='qr_management',
description=message,
event_data=event_data
)
def log_qr_code_updated(self, qr_code_id, qr_code_name, updated_by_user_id, changes):
"""Log QR code modification events"""
event_data = {
'qr_code_id': qr_code_id,
'qr_code_name': qr_code_name,
'updated_by_user_id': updated_by_user_id,
'updated_timestamp': datetime.now().isoformat(),
'changes': changes
}
message = f"QR code updated: {qr_code_name} (ID: {qr_code_id}) by user {updated_by_user_id}"
self.logger.info(json.dumps({
'event': 'qr_code_updated',
'data': event_data
}))
# Log to database
self._log_to_database(
event_type='qr_code_updated',
event_category='qr_management',
description=message,
event_data=event_data
)
def log_qr_code_deleted(self, qr_code_id, qr_code_name, deleted_by_user_id):
"""Log QR code deletion events"""
event_data = {
'qr_code_id': qr_code_id,
'qr_code_name': qr_code_name,
'deleted_by_user_id': deleted_by_user_id,
'deleted_timestamp': datetime.now().isoformat()
}
message = f"QR code deleted: {qr_code_name} (ID: {qr_code_id}) by user {deleted_by_user_id}"
self.logger.warning(json.dumps({
'event': 'qr_code_deleted',
'data': event_data
}))
# Log to database with higher severity
self._log_to_database(
event_type='qr_code_deleted',
event_category='qr_management',
description=message,
event_data=event_data,
severity='WARNING'
)
def log_qr_code_accessed(self, qr_code_id, qr_code_name, access_method='scan'):
"""Log QR code access/scan events"""
context = self._get_request_context()
event_data = {
'qr_code_id': qr_code_id,
'qr_code_name': qr_code_name,
'access_method': access_method,
'access_timestamp': datetime.now().isoformat(),
'access_info': {
'ip_address': context.get('ip_address'),
'user_agent': context.get('user_agent')
}
}
message = f"QR code accessed: {qr_code_name} (ID: {qr_code_id}) via {access_method}"
self.logger.info(json.dumps({
'event': 'qr_code_accessed',
'data': event_data
}))
# DATABASE ERROR LOGGING METHODS
def log_database_error(self, operation, error, query=None, parameters=None):
"""Log database operation errors"""
event_data = {
'operation': operation,
'error_type': type(error).__name__,
'error_message': str(error),
'error_timestamp': datetime.now().isoformat(),
'database_info': {
'query': query[:500] if query else None, # Truncate long queries
'parameters': str(parameters)[:200] if parameters else None
}
}
if isinstance(error, SQLAlchemyError):
event_data['sqlalchemy_error'] = True
if hasattr(error, 'orig'):
event_data['original_error'] = str(error.orig)
message = f"Database error in {operation}: {type(error).__name__} - {str(error)}"
self.logger.error(json.dumps({
'event': 'database_error',
'data': event_data
}))
# Log to database if possible (try/catch to avoid recursive errors)
try:
self._log_to_database(
event_type='database_error',
event_category='database',
description=message,
event_data=event_data,
severity='ERROR'
)
except:
# If database logging fails, just continue
pass
def log_database_connection_error(self, error):
"""Log database connection failures"""
event_data = {
'error_type': 'database_connection_failure',
'error_message': str(error),
'error_timestamp': datetime.now().isoformat()
}
message = f"Database connection error: {str(error)}"
self.logger.critical(json.dumps({
'event': 'database_connection_error',
'data': event_data
}))
# FLASK ERROR LOGGING METHODS
def log_flask_error(self, error_type, error_message, stack_trace=None, request_data=None):
"""Log Flask application errors"""
context = self._get_request_context()
event_data = {
'error_type': error_type,
'error_message': error_message,
'error_timestamp': datetime.now().isoformat(),
'request_context': context,
'stack_trace': stack_trace[:2000] if stack_trace else None # Truncate long traces
}
if request_data:
event_data['request_data'] = request_data
message = f"Flask error: {error_type} - {error_message}"
self.logger.error(json.dumps({
'event': 'flask_error',
'data': event_data
}))
# Log to database
self._log_to_database(
event_type='flask_error',
event_category='application',
description=message,
event_data=event_data,
severity='ERROR'
)
# SECURITY EVENT LOGGING METHODS
def log_security_event(self, event_type, description, severity='MEDIUM', additional_data=None):
"""Log security-related events"""
context = self._get_request_context()
event_data = {
'security_event_type': event_type,
'severity': severity,
'event_timestamp': datetime.now().isoformat(),
'request_context': context
}
if additional_data:
event_data['additional_data'] = additional_data
message = f"Security event: {event_type} - {description}"
self.security_logger.warning(json.dumps({
'event': 'security_event',
'data': event_data
}))
# Log to database with high priority
self._log_to_database(
event_type='security_event',
event_category='security',
description=message,
event_data=event_data,
severity='WARNING'
)
# UTILITY METHODS
def get_log_statistics(self, days=7):
"""Get logging statistics for the specified number of days"""
try:
cutoff_date = datetime.now() - timedelta(days=days)
stats_sql = """
SELECT
event_category,
severity_level,
COUNT(*) as event_count
FROM log_events
WHERE created_timestamp >= :cutoff_date
GROUP BY event_category, severity_level
ORDER BY event_count DESC
"""
result = self.db.session.execute(text(stats_sql), {
'cutoff_date': cutoff_date
}).fetchall()
stats = {}
for row in result:
category = row.event_category
if category not in stats:
stats[category] = {}
stats[category][row.severity_level] = row.event_count
return stats
except Exception as e:
self.log_database_error('get_log_statistics', e)
return {}
def cleanup_old_logs(self, days_to_keep=90):
"""Clean up old log entries from database"""
try:
cutoff_date = datetime.now() - timedelta(days=days_to_keep)
cleanup_sql = """
DELETE FROM log_events
WHERE created_timestamp < :cutoff_date
AND severity_level NOT IN ('ERROR', 'CRITICAL')
"""
result = self.db.session.execute(text(cleanup_sql), {
'cutoff_date': cutoff_date
})
deleted_count = result.rowcount
self.db.session.commit()
self.logger.info(f"Cleaned up {deleted_count} old log entries")
return deleted_count
except Exception as e:
self.log_database_error('cleanup_old_logs', e)
return 0
# DECORATOR FUNCTIONS FOR AUTOMATIC LOGGING
def log_user_activity(activity_type):
"""Decorator to automatically log user activities"""
def decorator(f):
@wraps(f)
def decorated_function(*args, **kwargs):
try:
result = f(*args, **kwargs)
# Log successful activity
if hasattr(g, 'app') and hasattr(g.app, 'logger_handler'):
logger = g.app.logger_handler
logger.logger.info(json.dumps({
'event': f'user_activity_{activity_type}',
'data': {
'user_id': session.get('user_id'),
'username': session.get('username'),
'activity': activity_type,
'timestamp': datetime.now().isoformat()
}
}))
return result
except Exception as e:
# Log error
if hasattr(g, 'app') and hasattr(g.app, 'logger_handler'):
logger = g.app.logger_handler
logger.log_flask_error(
error_type=f"activity_error_{activity_type}",
error_message=str(e),
stack_trace=traceback.format_exc()
)
raise
return decorated_function
return decorator
def log_database_operations(operation_name):
"""Decorator to automatically log database operations"""
def decorator(f):
@wraps(f)
def decorated_function(*args, **kwargs):
try:
result = f(*args, **kwargs)
return result
except Exception as e:
# Log database error
if hasattr(g, 'app') and hasattr(g.app, 'logger_handler'):
logger = g.app.logger_handler
logger.log_database_error(
operation=operation_name,
error=e
)
raise
return decorated_function
return decorator
# INITIALIZATION FUNCTION
def init_logging(app, db):
"""Initialize the logging system with the Flask app"""
logger_handler = AppLogger(app, db)
return logger_handler