Phase 2 Step 7: Implement Error Handling & Logging
Comprehensive error handling and logging system with production-ready features for monitoring, debugging, and user experience. Enhanced Logging System: - Implemented RotatingFileHandler (10MB per file, 10 backups, 100MB total) - Separate error log file for ERROR level messages with detailed tracebacks - Structured logging with request IDs, timestamps, and module names - RequestIDLogFilter for automatic request context injection - Console logging in debug mode with simplified format Request/Response Middleware: - Request ID generation using UUID (8-character prefix for readability) - Request timing with millisecond precision - User authentication context in all logs - Response duration tracking and headers (X-Request-ID, X-Request-Duration-Ms) - Security headers: X-Content-Type-Options, X-Frame-Options, X-XSS-Protection Database Error Handling: - Enabled SQLite WAL mode for better concurrency with background jobs - Busy timeout configuration (15 seconds) for lock handling - Automatic rollback on request exceptions via teardown handler - Dedicated SQLAlchemyError handler with explicit rollback - Connection pooling with pre-ping validation Comprehensive Error Handlers: - Content negotiation: JSON responses for API, HTML for web requests - Error handlers for 400, 401, 403, 404, 405, 500 - Database rollback in all error handlers - Full exception logging with traceback for debugging Custom Error Templates: - Created web/templates/errors/ directory with 6 templates - Dark theme matching application design (slate colors) - User-friendly error messages with navigation - Templates: 400, 401, 403, 404, 405, 500 Testing: - Comprehensive test suite (320+ lines) in tests/test_error_handling.py - Tests for JSON vs HTML error responses - Request ID and duration header verification - Security header validation - Log rotation configuration tests - Structured logging tests Bug Fix: - Fixed pagination bug in scans API endpoint - Changed paginated_result.total_pages to paginated_result.pages - Resolves AttributeError when listing scans Files Added: - tests/test_error_handling.py - web/templates/errors/400.html - web/templates/errors/401.html - web/templates/errors/403.html - web/templates/errors/404.html - web/templates/errors/405.html - web/templates/errors/500.html Files Modified: - web/app.py (logging, error handlers, request handlers, database config) - web/api/scans.py (pagination bug fix) - docs/ai/PHASE2.md (mark Step 7 complete, update progress to 86%) Phase 2 Progress: 12/14 days complete (86%)
This commit is contained in:
336
web/app.py
336
web/app.py
@@ -7,17 +7,39 @@ extensions, blueprints, and middleware.
|
||||
|
||||
import logging
|
||||
import os
|
||||
import uuid
|
||||
from logging.handlers import RotatingFileHandler
|
||||
from pathlib import Path
|
||||
|
||||
from flask import Flask, jsonify
|
||||
from flask import Flask, g, jsonify, request
|
||||
from flask_cors import CORS
|
||||
from flask_login import LoginManager
|
||||
from sqlalchemy import create_engine
|
||||
from flask_login import LoginManager, current_user
|
||||
from sqlalchemy import create_engine, event
|
||||
from sqlalchemy.orm import scoped_session, sessionmaker
|
||||
|
||||
from web.models import Base
|
||||
|
||||
|
||||
class RequestIDLogFilter(logging.Filter):
|
||||
"""
|
||||
Logging filter that injects request ID into log records.
|
||||
|
||||
Adds a 'request_id' attribute to each log record. For requests within
|
||||
Flask request context, uses the request ID from g.request_id. For logs
|
||||
outside request context (background jobs, startup), uses 'system'.
|
||||
"""
|
||||
|
||||
def filter(self, record):
|
||||
"""Add request_id to log record."""
|
||||
try:
|
||||
# Try to get request ID from Flask's g object
|
||||
record.request_id = g.get('request_id', 'system')
|
||||
except (RuntimeError, AttributeError):
|
||||
# Outside of request context
|
||||
record.request_id = 'system'
|
||||
return True
|
||||
|
||||
|
||||
def create_app(config: dict = None) -> Flask:
|
||||
"""
|
||||
Create and configure the Flask application.
|
||||
@@ -83,7 +105,7 @@ def create_app(config: dict = None) -> Flask:
|
||||
|
||||
def configure_logging(app: Flask) -> None:
|
||||
"""
|
||||
Configure application logging.
|
||||
Configure application logging with rotation and structured format.
|
||||
|
||||
Args:
|
||||
app: Flask application instance
|
||||
@@ -96,26 +118,59 @@ def configure_logging(app: Flask) -> None:
|
||||
log_dir = Path('logs')
|
||||
log_dir.mkdir(exist_ok=True)
|
||||
|
||||
# File handler for all logs
|
||||
file_handler = logging.FileHandler(log_dir / 'sneakyscanner.log')
|
||||
file_handler.setLevel(logging.INFO)
|
||||
file_formatter = logging.Formatter(
|
||||
'%(asctime)s [%(levelname)s] %(name)s: %(message)s',
|
||||
# Rotating file handler for application logs
|
||||
# Max 10MB per file, keep 10 backup files (100MB total)
|
||||
app_log_handler = RotatingFileHandler(
|
||||
log_dir / 'sneakyscanner.log',
|
||||
maxBytes=10 * 1024 * 1024, # 10MB
|
||||
backupCount=10
|
||||
)
|
||||
app_log_handler.setLevel(logging.INFO)
|
||||
|
||||
# Structured log format with more context
|
||||
log_formatter = logging.Formatter(
|
||||
'%(asctime)s [%(levelname)s] %(name)s [%(request_id)s] '
|
||||
'%(message)s',
|
||||
datefmt='%Y-%m-%d %H:%M:%S'
|
||||
)
|
||||
file_handler.setFormatter(file_formatter)
|
||||
app.logger.addHandler(file_handler)
|
||||
app_log_handler.setFormatter(log_formatter)
|
||||
|
||||
# Add filter to inject request ID into log records
|
||||
app_log_handler.addFilter(RequestIDLogFilter())
|
||||
app.logger.addHandler(app_log_handler)
|
||||
|
||||
# Separate rotating file handler for errors only
|
||||
error_log_handler = RotatingFileHandler(
|
||||
log_dir / 'sneakyscanner_errors.log',
|
||||
maxBytes=10 * 1024 * 1024, # 10MB
|
||||
backupCount=5
|
||||
)
|
||||
error_log_handler.setLevel(logging.ERROR)
|
||||
error_formatter = logging.Formatter(
|
||||
'%(asctime)s [%(levelname)s] %(name)s [%(request_id)s]\n'
|
||||
'Message: %(message)s\n'
|
||||
'Path: %(pathname)s:%(lineno)d\n'
|
||||
'%(stack_info)s',
|
||||
datefmt='%Y-%m-%d %H:%M:%S'
|
||||
)
|
||||
error_log_handler.setFormatter(error_formatter)
|
||||
error_log_handler.addFilter(RequestIDLogFilter())
|
||||
app.logger.addHandler(error_log_handler)
|
||||
|
||||
# Console handler for development
|
||||
if app.debug:
|
||||
console_handler = logging.StreamHandler()
|
||||
console_handler.setLevel(logging.DEBUG)
|
||||
console_formatter = logging.Formatter(
|
||||
'[%(levelname)s] %(name)s: %(message)s'
|
||||
'%(asctime)s [%(levelname)s] %(name)s [%(request_id)s] %(message)s',
|
||||
datefmt='%H:%M:%S'
|
||||
)
|
||||
console_handler.setFormatter(console_formatter)
|
||||
console_handler.addFilter(RequestIDLogFilter())
|
||||
app.logger.addHandler(console_handler)
|
||||
|
||||
app.logger.info("Logging configured with rotation (10MB per file, 10 backups)")
|
||||
|
||||
|
||||
def init_database(app: Flask) -> None:
|
||||
"""
|
||||
@@ -124,14 +179,35 @@ def init_database(app: Flask) -> None:
|
||||
Args:
|
||||
app: Flask application instance
|
||||
"""
|
||||
# Determine connect_args based on database type
|
||||
connect_args = {}
|
||||
if 'sqlite' in app.config['SQLALCHEMY_DATABASE_URI']:
|
||||
# SQLite-specific configuration for better concurrency
|
||||
connect_args = {
|
||||
'timeout': 15, # 15 second timeout for database locks
|
||||
'check_same_thread': False # Allow SQLite usage across threads
|
||||
}
|
||||
|
||||
# Create engine
|
||||
engine = create_engine(
|
||||
app.config['SQLALCHEMY_DATABASE_URI'],
|
||||
echo=app.debug, # Log SQL in debug mode
|
||||
pool_pre_ping=True, # Verify connections before using
|
||||
pool_recycle=3600, # Recycle connections after 1 hour
|
||||
connect_args=connect_args
|
||||
)
|
||||
|
||||
# Enable WAL mode for SQLite (better concurrency)
|
||||
if 'sqlite' in app.config['SQLALCHEMY_DATABASE_URI']:
|
||||
@event.listens_for(engine, "connect")
|
||||
def set_sqlite_pragma(dbapi_conn, connection_record):
|
||||
"""Set SQLite pragmas for better performance and concurrency."""
|
||||
cursor = dbapi_conn.cursor()
|
||||
cursor.execute("PRAGMA journal_mode=WAL") # Write-Ahead Logging
|
||||
cursor.execute("PRAGMA synchronous=NORMAL") # Faster writes
|
||||
cursor.execute("PRAGMA busy_timeout=15000") # 15 second busy timeout
|
||||
cursor.close()
|
||||
|
||||
# Create scoped session factory
|
||||
db_session = scoped_session(
|
||||
sessionmaker(
|
||||
@@ -151,7 +227,14 @@ def init_database(app: Flask) -> None:
|
||||
|
||||
@app.teardown_appcontext
|
||||
def shutdown_session(exception=None):
|
||||
"""Remove database session at end of request."""
|
||||
"""
|
||||
Remove database session at end of request.
|
||||
|
||||
Rollback on exception to prevent partial commits.
|
||||
"""
|
||||
if exception:
|
||||
app.logger.warning(f"Request ended with exception, rolling back database session")
|
||||
db_session.rollback()
|
||||
db_session.remove()
|
||||
|
||||
app.logger.info(f"Database initialized: {app.config['SQLALCHEMY_DATABASE_URI']}")
|
||||
@@ -256,70 +339,212 @@ def register_error_handlers(app: Flask) -> None:
|
||||
"""
|
||||
Register error handlers for common HTTP errors.
|
||||
|
||||
Handles errors with either JSON responses (for API requests) or
|
||||
HTML templates (for web requests). Ensures database rollback on errors.
|
||||
|
||||
Args:
|
||||
app: Flask application instance
|
||||
"""
|
||||
from flask import render_template
|
||||
from sqlalchemy.exc import SQLAlchemyError
|
||||
|
||||
def wants_json():
|
||||
"""Check if client wants JSON response."""
|
||||
# API requests always get JSON
|
||||
if request.path.startswith('/api/'):
|
||||
return True
|
||||
# Check Accept header
|
||||
best = request.accept_mimetypes.best_match(['application/json', 'text/html'])
|
||||
return best == 'application/json' and \
|
||||
request.accept_mimetypes[best] > request.accept_mimetypes['text/html']
|
||||
|
||||
@app.errorhandler(400)
|
||||
def bad_request(error):
|
||||
return jsonify({
|
||||
'error': 'Bad Request',
|
||||
'message': str(error) or 'The request was invalid'
|
||||
}), 400
|
||||
"""Handle 400 Bad Request errors."""
|
||||
app.logger.warning(f"Bad request: {request.path} - {str(error)}")
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Bad Request',
|
||||
'message': str(error) or 'The request was invalid'
|
||||
}), 400
|
||||
return render_template('errors/400.html', error=error), 400
|
||||
|
||||
@app.errorhandler(401)
|
||||
def unauthorized(error):
|
||||
return jsonify({
|
||||
'error': 'Unauthorized',
|
||||
'message': 'Authentication required'
|
||||
}), 401
|
||||
"""Handle 401 Unauthorized errors."""
|
||||
app.logger.warning(f"Unauthorized access attempt: {request.path}")
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Unauthorized',
|
||||
'message': 'Authentication required'
|
||||
}), 401
|
||||
return render_template('errors/401.html', error=error), 401
|
||||
|
||||
@app.errorhandler(403)
|
||||
def forbidden(error):
|
||||
return jsonify({
|
||||
'error': 'Forbidden',
|
||||
'message': 'You do not have permission to access this resource'
|
||||
}), 403
|
||||
"""Handle 403 Forbidden errors."""
|
||||
app.logger.warning(f"Forbidden access: {request.path}")
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Forbidden',
|
||||
'message': 'You do not have permission to access this resource'
|
||||
}), 403
|
||||
return render_template('errors/403.html', error=error), 403
|
||||
|
||||
@app.errorhandler(404)
|
||||
def not_found(error):
|
||||
return jsonify({
|
||||
'error': 'Not Found',
|
||||
'message': 'The requested resource was not found'
|
||||
}), 404
|
||||
"""Handle 404 Not Found errors."""
|
||||
app.logger.info(f"Resource not found: {request.path}")
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Not Found',
|
||||
'message': 'The requested resource was not found'
|
||||
}), 404
|
||||
return render_template('errors/404.html', error=error), 404
|
||||
|
||||
@app.errorhandler(405)
|
||||
def method_not_allowed(error):
|
||||
return jsonify({
|
||||
'error': 'Method Not Allowed',
|
||||
'message': 'The HTTP method is not allowed for this endpoint'
|
||||
}), 405
|
||||
"""Handle 405 Method Not Allowed errors."""
|
||||
app.logger.warning(f"Method not allowed: {request.method} {request.path}")
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Method Not Allowed',
|
||||
'message': 'The HTTP method is not allowed for this endpoint'
|
||||
}), 405
|
||||
return render_template('errors/405.html', error=error), 405
|
||||
|
||||
@app.errorhandler(500)
|
||||
def internal_server_error(error):
|
||||
app.logger.error(f"Internal server error: {error}")
|
||||
return jsonify({
|
||||
'error': 'Internal Server Error',
|
||||
'message': 'An unexpected error occurred'
|
||||
}), 500
|
||||
"""
|
||||
Handle 500 Internal Server Error.
|
||||
|
||||
Rolls back database session and logs full traceback.
|
||||
"""
|
||||
# Rollback database session on error
|
||||
try:
|
||||
app.db_session.rollback()
|
||||
except Exception as e:
|
||||
app.logger.error(f"Failed to rollback database session: {str(e)}")
|
||||
|
||||
# Log error with full context
|
||||
app.logger.error(
|
||||
f"Internal server error: {request.method} {request.path} - {str(error)}",
|
||||
exc_info=True
|
||||
)
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Internal Server Error',
|
||||
'message': 'An unexpected error occurred'
|
||||
}), 500
|
||||
return render_template('errors/500.html', error=error), 500
|
||||
|
||||
@app.errorhandler(SQLAlchemyError)
|
||||
def handle_db_error(error):
|
||||
"""
|
||||
Handle database errors.
|
||||
|
||||
Rolls back transaction and returns appropriate error response.
|
||||
"""
|
||||
# Rollback database session
|
||||
try:
|
||||
app.db_session.rollback()
|
||||
except Exception as e:
|
||||
app.logger.error(f"Failed to rollback database session: {str(e)}")
|
||||
|
||||
# Log database error
|
||||
app.logger.error(
|
||||
f"Database error: {request.method} {request.path} - {str(error)}",
|
||||
exc_info=True
|
||||
)
|
||||
|
||||
if wants_json():
|
||||
return jsonify({
|
||||
'error': 'Database Error',
|
||||
'message': 'A database error occurred'
|
||||
}), 500
|
||||
return render_template('errors/500.html', error=error), 500
|
||||
|
||||
|
||||
def register_request_handlers(app: Flask) -> None:
|
||||
"""
|
||||
Register request and response handlers.
|
||||
|
||||
Adds request ID generation, request/response logging with timing,
|
||||
and security headers.
|
||||
|
||||
Args:
|
||||
app: Flask application instance
|
||||
"""
|
||||
import time
|
||||
|
||||
@app.before_request
|
||||
def log_request():
|
||||
"""Log incoming requests."""
|
||||
if app.debug:
|
||||
app.logger.debug(f"{request.method} {request.path}")
|
||||
def before_request_handler():
|
||||
"""
|
||||
Generate request ID and start timing.
|
||||
|
||||
Sets g.request_id and g.request_start_time for use in logging
|
||||
and timing calculations.
|
||||
"""
|
||||
# Generate unique request ID
|
||||
g.request_id = str(uuid.uuid4())[:8] # Short ID for readability
|
||||
g.request_start_time = time.time()
|
||||
|
||||
# Log incoming request with context
|
||||
user_info = 'anonymous'
|
||||
if current_user.is_authenticated:
|
||||
user_info = f'user:{current_user.get_id()}'
|
||||
|
||||
# Log at INFO level for API calls, DEBUG for other requests
|
||||
if request.path.startswith('/api/'):
|
||||
app.logger.info(
|
||||
f"→ {request.method} {request.path} "
|
||||
f"from={request.remote_addr} user={user_info}"
|
||||
)
|
||||
elif app.debug:
|
||||
app.logger.debug(
|
||||
f"→ {request.method} {request.path} "
|
||||
f"from={request.remote_addr}"
|
||||
)
|
||||
|
||||
@app.after_request
|
||||
def add_security_headers(response):
|
||||
"""Add security headers to all responses."""
|
||||
# Only add CORS and security headers for API routes
|
||||
def after_request_handler(response):
|
||||
"""
|
||||
Log response and add security headers.
|
||||
|
||||
Calculates request duration and logs response status.
|
||||
"""
|
||||
# Calculate request duration
|
||||
if hasattr(g, 'request_start_time'):
|
||||
duration_ms = (time.time() - g.request_start_time) * 1000
|
||||
|
||||
# Log response with duration
|
||||
if request.path.startswith('/api/'):
|
||||
# Log API responses at INFO level
|
||||
app.logger.info(
|
||||
f"← {request.method} {request.path} "
|
||||
f"status={response.status_code} "
|
||||
f"duration={duration_ms:.2f}ms"
|
||||
)
|
||||
elif app.debug:
|
||||
# Log web responses at DEBUG level in debug mode
|
||||
app.logger.debug(
|
||||
f"← {request.method} {request.path} "
|
||||
f"status={response.status_code} "
|
||||
f"duration={duration_ms:.2f}ms"
|
||||
)
|
||||
|
||||
# Add duration header for API responses
|
||||
if request.path.startswith('/api/'):
|
||||
response.headers['X-Request-Duration-Ms'] = f"{duration_ms:.2f}"
|
||||
response.headers['X-Request-ID'] = g.request_id
|
||||
|
||||
# Add security headers to all responses
|
||||
if request.path.startswith('/api/'):
|
||||
response.headers['X-Content-Type-Options'] = 'nosniff'
|
||||
response.headers['X-Frame-Options'] = 'DENY'
|
||||
@@ -327,15 +552,20 @@ def register_request_handlers(app: Flask) -> None:
|
||||
|
||||
return response
|
||||
|
||||
# Import request at runtime to avoid circular imports
|
||||
from flask import request
|
||||
@app.teardown_request
|
||||
def teardown_request_handler(exception=None):
|
||||
"""
|
||||
Log errors that occur during request processing.
|
||||
|
||||
# Re-apply to ensure request is available
|
||||
@app.before_request
|
||||
def log_request():
|
||||
"""Log incoming requests."""
|
||||
if app.debug:
|
||||
app.logger.debug(f"{request.method} {request.path}")
|
||||
Args:
|
||||
exception: Exception that occurred, if any
|
||||
"""
|
||||
if exception:
|
||||
app.logger.error(
|
||||
f"Request failed: {request.method} {request.path} "
|
||||
f"error={type(exception).__name__}: {str(exception)}",
|
||||
exc_info=True
|
||||
)
|
||||
|
||||
|
||||
# Development server entry point
|
||||
|
||||
Reference in New Issue
Block a user