feat(oidc): add debug logging and migrate client secret hashing to Flask-Bcrypt
- Add comprehensive debug logging across OIDC endpoints and services for development troubleshooting - Implement backward-compatible password hash checking with automatic migration from raw bcrypt to Flask-Bcrypt format - Refactor logging configuration to ensure proper propagation across all app modules - Configure root logger and disable Werkzeug duplication for cleaner log output - Initialize OIDC JWKS service on application startup - Update seed script to use Flask-Bcrypt for client secret hashing - Fix audit service to use correct event_metadata parameter BREAKING CHANGE: Client secrets created with old raw bcrypt format will be automatically migrated to Flask-Bcrypt format on first successful authentication
This commit is contained in:
+52
-3
@@ -1,12 +1,18 @@
|
||||
"""Application factory."""
|
||||
import os
|
||||
import logging
|
||||
|
||||
# Test debug logging - this should appear when running `flask run --debug`
|
||||
_root_logger = logging.getLogger(__name__)
|
||||
_root_logger.debug("[TEST] Debug logging is working!")
|
||||
|
||||
from flask import Flask
|
||||
from config import get_config
|
||||
from app.extensions import db, migrate, bcrypt, ma, limiter, session
|
||||
from app.middleware import RequestIDMiddleware, SecurityHeadersMiddleware, setup_cors
|
||||
from app.exceptions.base import BaseAPIException
|
||||
from app.utils.response import api_response
|
||||
from app.services.oidc_jwks_service import OIDCJWKSService
|
||||
import redis
|
||||
|
||||
# Configure SQLAlchemy logging BEFORE any database operations
|
||||
@@ -50,6 +56,9 @@ def create_app(config_name=None):
|
||||
# Setup logging
|
||||
setup_logging(app)
|
||||
|
||||
# Initialize OIDC JWKS service with a signing key
|
||||
initialize_oidc_jwks(app)
|
||||
|
||||
return app
|
||||
|
||||
|
||||
@@ -167,16 +176,32 @@ def setup_logging(app):
|
||||
|
||||
# Create formatter
|
||||
formatter = logging.Formatter(
|
||||
"[%(asctime)s] %(levelname)s in %(module)s: %(message)s"
|
||||
"[%(asctime)s] [%(levelname)s] %(name)s: %(message)s"
|
||||
)
|
||||
|
||||
# Configure root logger
|
||||
# Configure root logger - this ensures all module loggers (like app.services.oidc_service)
|
||||
# will output DEBUG level logs when in development mode
|
||||
root_logger = logging.getLogger()
|
||||
root_logger.setLevel(log_level)
|
||||
|
||||
if app.config.get("LOG_TO_STDOUT"):
|
||||
stream_handler = logging.StreamHandler()
|
||||
stream_handler.setFormatter(formatter)
|
||||
stream_handler.setLevel(log_level)
|
||||
app.logger.addHandler(stream_handler)
|
||||
root_logger.addHandler(stream_handler)
|
||||
|
||||
# Disable Werkzeug's default logger to avoid log duplication and interference
|
||||
werkzeug_logger = logging.getLogger('werkzeug')
|
||||
werkzeug_logger.setLevel(logging.INFO)
|
||||
|
||||
# Ensure child loggers propagate to root logger
|
||||
# This is the key fix - explicitly enable propagation for common app loggers
|
||||
for logger_name in ['app', 'app.api', 'app.api.oidc', 'app.services', 'app.models']:
|
||||
child_logger = logging.getLogger(logger_name)
|
||||
child_logger.propagate = True
|
||||
child_logger.setLevel(log_level)
|
||||
|
||||
# Configure Flask app logger
|
||||
app.logger.setLevel(log_level)
|
||||
|
||||
# Configure SQLAlchemy logging level (also set at module level before DB init)
|
||||
@@ -187,3 +212,27 @@ def setup_logging(app):
|
||||
logging.getLogger('sqlalchemy.pool').setLevel(sqlalchemy_log_level)
|
||||
|
||||
app.logger.info("Application startup")
|
||||
|
||||
# Test debug log after logging is configured
|
||||
app.logger.debug("[TEST] Debug logging is working!")
|
||||
|
||||
|
||||
def initialize_oidc_jwks(app):
|
||||
"""Initialize OIDC JWKS service with a signing key.
|
||||
|
||||
This ensures that signing keys are available for token generation.
|
||||
|
||||
Args:
|
||||
app: Flask application instance
|
||||
"""
|
||||
with app.app_context():
|
||||
try:
|
||||
jwks_service = OIDCJWKSService()
|
||||
signing_key = jwks_service.get_signing_key()
|
||||
if not signing_key:
|
||||
signing_key = jwks_service.initialize_with_key()
|
||||
app.logger.info(f"[OIDC] Generated new signing key: kid={signing_key.kid}")
|
||||
else:
|
||||
app.logger.info(f"[OIDC] Using existing signing key: kid={signing_key.kid}")
|
||||
except Exception as e:
|
||||
app.logger.error(f"[OIDC] Failed to initialize JWKS: {e}")
|
||||
|
||||
+164
-5
@@ -1,18 +1,22 @@
|
||||
"""OIDC (OpenID Connect) API endpoints - Root level blueprint."""
|
||||
import base64
|
||||
import json
|
||||
import logging
|
||||
import secrets
|
||||
from urllib.parse import urlencode, urlparse, parse_qs
|
||||
|
||||
import bcrypt
|
||||
from flask import Blueprint, request, redirect, jsonify, session, g, current_app, Response
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
from app.utils.response import api_response
|
||||
from app.services.oidc_service import (
|
||||
OIDCService, InvalidClientError, InvalidGrantError, InvalidRequestError
|
||||
)
|
||||
from app.services.auth_service import AuthService
|
||||
from app.extensions import db
|
||||
from app.extensions import bcrypt as flask_bcrypt
|
||||
from app.models import User, OIDCClient
|
||||
from app.models.organization import Organization
|
||||
from app.exceptions.auth_exceptions import InvalidCredentialsError
|
||||
@@ -62,12 +66,21 @@ def authenticate_client(client_id, client_secret=None):
|
||||
Raises:
|
||||
InvalidClientError: If authentication fails
|
||||
"""
|
||||
# Debug logging for client validation (controlled by LOG_LEVEL)
|
||||
logger.debug(f"[OIDC] Client validation: client_id={client_id}, confidential={client_secret is not None}")
|
||||
|
||||
client = OIDCClient.query.filter_by(client_id=client_id, is_active=True).first()
|
||||
if not client:
|
||||
logger.debug(f"[OIDC] Client validation: client_id={client_id}, exists=False")
|
||||
raise InvalidClientError("Invalid client")
|
||||
|
||||
logger.debug(f"[OIDC] Client validation: client_id={client_id}, client_id_db={client.id}, exists=True")
|
||||
|
||||
if client.is_confidential and client_secret:
|
||||
if not bcrypt.check_password_hash(client.client_secret_hash, client_secret):
|
||||
# Try Flask-Bcrypt first (new format)
|
||||
secret_match = _check_password_hash(client, client_secret)
|
||||
logger.debug(f"[OIDC] Client secret validation: client_id={client_id}, match={secret_match}")
|
||||
if not secret_match:
|
||||
raise InvalidClientError("Invalid client credentials")
|
||||
|
||||
return client
|
||||
@@ -96,6 +109,40 @@ def require_valid_token():
|
||||
g.current_user = user
|
||||
|
||||
|
||||
def _check_password_hash(client, password):
|
||||
"""Check password hash with backward compatibility for old bcrypt format.
|
||||
|
||||
Tries Flask-Bcrypt first (new format), then falls back to raw bcrypt (old format).
|
||||
If old format matches, re-hashes with new format for migration.
|
||||
"""
|
||||
pw_hash = client.client_secret_hash
|
||||
|
||||
# Try Flask-Bcrypt first (new format)
|
||||
try:
|
||||
return flask_bcrypt.check_password_hash(pw_hash, password)
|
||||
except ValueError:
|
||||
# Invalid salt - try raw bcrypt (old format)
|
||||
pass
|
||||
|
||||
# Try raw bcrypt (old format) as fallback
|
||||
try:
|
||||
match = bcrypt.checkpw(
|
||||
pw_hash.encode('utf-8') if isinstance(pw_hash, str) else pw_hash,
|
||||
password.encode('utf-8') if isinstance(password, str) else password
|
||||
)
|
||||
if match:
|
||||
# Migrate to new format
|
||||
new_hash = flask_bcrypt.generate_password_hash(
|
||||
password.decode('utf-8') if isinstance(password, bytes) else password
|
||||
).decode('utf-8')
|
||||
client.client_secret_hash = new_hash
|
||||
db.session.commit()
|
||||
logger.info(f"[OIDC] Migrated client secret hash to new format: client_id={client.client_id}")
|
||||
return match
|
||||
except Exception:
|
||||
return False
|
||||
|
||||
|
||||
def parse_basic_auth():
|
||||
"""Parse Basic authentication from Authorization header.
|
||||
|
||||
@@ -170,13 +217,18 @@ def oidc_authorize():
|
||||
200: Login page (GET when not authenticated)
|
||||
400: Invalid request
|
||||
"""
|
||||
logger.debug("[OIDC] oidc_authorize called")
|
||||
|
||||
|
||||
# Parse request parameters
|
||||
if request.method == "GET":
|
||||
params = request.args.to_dict()
|
||||
else:
|
||||
params = request.form.to_dict()
|
||||
|
||||
logger.debug("[OIDC] Raw request params: %s", params)
|
||||
# Extract required parameters
|
||||
logger.debug("[OIDC] Extracting request parameters...")
|
||||
client_id = params.get("client_id")
|
||||
redirect_uri = params.get("redirect_uri")
|
||||
response_type = params.get("response_type")
|
||||
@@ -186,7 +238,12 @@ def oidc_authorize():
|
||||
code_challenge = params.get("code_challenge")
|
||||
code_challenge_method = params.get("code_challenge_method")
|
||||
|
||||
logger.debug("[OIDC] Extracted parameters: client_id=%s, redirect_uri=%s, response_type=%s", client_id, redirect_uri, response_type)
|
||||
logger.debug("[OIDC] Extracted parameters: scope=%s, state=%s, nonce=%s", scope, state, nonce)
|
||||
logger.debug("[OIDC] Extracted parameters: code_challenge=%s, code_challenge_method=%s", code_challenge, code_challenge_method)
|
||||
|
||||
# Validate required parameters
|
||||
logger.debug("[OIDC] Validating required parameters...")
|
||||
errors = []
|
||||
if not client_id:
|
||||
errors.append("client_id is required")
|
||||
@@ -195,42 +252,76 @@ def oidc_authorize():
|
||||
if not response_type:
|
||||
errors.append("response_type is required")
|
||||
|
||||
logger.debug("[OIDC] Parameter validation errors: %s", errors)
|
||||
if errors:
|
||||
logger.debug("[OIDC] Redirecting with error: invalid_request")
|
||||
return _redirect_with_error(redirect_uri, "invalid_request", "; ".join(errors), state)
|
||||
|
||||
# Validate response_type
|
||||
logger.debug("[OIDC] Validating response_type: %s", response_type)
|
||||
if response_type != "code":
|
||||
logger.debug("[OIDC] Redirecting with error: unsupported_response_type")
|
||||
return _redirect_with_error(
|
||||
redirect_uri, "unsupported_response_type",
|
||||
redirect_uri, "unsupported_response_type",
|
||||
"Only response_type=code is supported", state
|
||||
)
|
||||
logger.debug("[OIDC] response_type validation passed")
|
||||
|
||||
# Validate client
|
||||
logger.debug("[OIDC] Validating client: client_id=%s", client_id)
|
||||
client = OIDCClient.query.filter_by(client_id=client_id, is_active=True).first()
|
||||
|
||||
logger.debug("[OIDC] Client query result: client=%s", client)
|
||||
logger.debug("[OIDC] Client validation: client_id=%s, exists=%s, is_confidential=%s",
|
||||
client_id, client is not None, client.is_confidential if client else None)
|
||||
|
||||
if not client:
|
||||
logger.debug("[OIDC] Redirecting with error: unauthorized_client (client not found)")
|
||||
return _redirect_with_error(redirect_uri, "unauthorized_client", "Invalid client", state)
|
||||
logger.debug("[OIDC] Client validation passed")
|
||||
|
||||
# Validate redirect URI
|
||||
if not client.is_redirect_uri_allowed(redirect_uri):
|
||||
logger.debug("[OIDC] Validating redirect_uri: %s", redirect_uri)
|
||||
logger.debug("[OIDC] Client allowed redirect_uris: %s", client.redirect_uris)
|
||||
is_redirect_allowed = client.is_redirect_uri_allowed(redirect_uri)
|
||||
logger.debug("[OIDC] Redirect URI validation result: %s", is_redirect_allowed)
|
||||
|
||||
if not is_redirect_allowed:
|
||||
logger.debug("[OIDC] Redirecting with error: invalid_request (redirect_uri not allowed)")
|
||||
return _redirect_with_error(redirect_uri, "invalid_request", "Invalid redirect_uri", state)
|
||||
logger.debug("[OIDC] Redirect URI validation passed")
|
||||
|
||||
# Validate scopes
|
||||
logger.debug("[OIDC] Validating scopes...")
|
||||
requested_scopes = scope.split() if scope else []
|
||||
allowed_scopes = client.scopes or []
|
||||
valid_scopes = [s for s in requested_scopes if s in allowed_scopes]
|
||||
|
||||
logger.debug("[OIDC] Requested scopes: %s", requested_scopes)
|
||||
logger.debug("[OIDC] Allowed scopes: %s", allowed_scopes)
|
||||
logger.debug("[OIDC] Valid scopes: %s", valid_scopes)
|
||||
|
||||
if not valid_scopes:
|
||||
logger.debug("[OIDC] Redirecting with error: invalid_scope (no valid scopes)")
|
||||
return _redirect_with_error(redirect_uri, "invalid_scope", "Invalid or no scopes requested", state)
|
||||
logger.debug("[OIDC] Scope validation passed")
|
||||
|
||||
# Check if user is already authenticated via session
|
||||
logger.debug("[OIDC] Checking session for existing authentication...")
|
||||
user_id = session.get("oidc_user_id")
|
||||
logger.debug("[OIDC] Session oidc_user_id: %s", user_id)
|
||||
|
||||
# Handle POST with credentials
|
||||
if request.method == "POST" and not user_id:
|
||||
logger.debug("[OIDC] POST request with credentials (user not authenticated)")
|
||||
email = params.get("email")
|
||||
password = params.get("password")
|
||||
|
||||
logger.debug("[OIDC] Email provided: %s", email is not None)
|
||||
logger.debug("[OIDC] Password provided: %s", password is not None)
|
||||
|
||||
if not email or not password:
|
||||
logger.debug("[OIDC] Showing login page: missing credentials")
|
||||
return _show_login_page(
|
||||
client_id=client_id,
|
||||
redirect_uri=redirect_uri,
|
||||
@@ -241,11 +332,15 @@ def oidc_authorize():
|
||||
error="Invalid credentials"
|
||||
)
|
||||
|
||||
logger.debug("[OIDC] Attempting user authentication for email: %s", email)
|
||||
try:
|
||||
user = AuthService.authenticate(email, password)
|
||||
user_id = user.id
|
||||
session["oidc_user_id"] = user_id
|
||||
|
||||
logger.debug("[OIDC] User authentication successful: user_id=%s, email=%s", user_id, email)
|
||||
except InvalidCredentialsError:
|
||||
logger.debug("[OIDC] User authentication failed: invalid credentials for email=%s", email)
|
||||
return _show_login_page(
|
||||
client_id=client_id,
|
||||
redirect_uri=redirect_uri,
|
||||
@@ -258,6 +353,7 @@ def oidc_authorize():
|
||||
|
||||
# If no user, show login page
|
||||
if not user_id:
|
||||
logger.debug("[OIDC] No authenticated user, showing login page")
|
||||
return _show_login_page(
|
||||
client_id=client_id,
|
||||
redirect_uri=redirect_uri,
|
||||
@@ -267,11 +363,22 @@ def oidc_authorize():
|
||||
response_type=response_type
|
||||
)
|
||||
|
||||
logger.debug("[OIDC] User authenticated: user_id=%s", user_id)
|
||||
|
||||
# User is authenticated, generate authorization code
|
||||
logger.debug("[OIDC] User is authenticated, fetching user from database...")
|
||||
user = User.query.get(user_id)
|
||||
logger.debug("[OIDC] User query result: %s", user)
|
||||
|
||||
if not user:
|
||||
logger.debug("[OIDC] Redirecting with error: server_error (user not found)")
|
||||
return _redirect_with_error(redirect_uri, "server_error", "User not found", state)
|
||||
|
||||
logger.debug("[OIDC] Generating authorization code...")
|
||||
logger.debug("[OIDC] Authorization code params: client_id=%s, user_id=%s, redirect_uri=%s", client_id, user_id, redirect_uri)
|
||||
logger.debug("[OIDC] Authorization code params: scopes=%s, state=%s, nonce=%s", valid_scopes, state, nonce)
|
||||
logger.debug("[OIDC] Authorization code params: code_challenge=%s, code_challenge_method=%s", code_challenge, code_challenge_method)
|
||||
|
||||
try:
|
||||
code = OIDCService.generate_authorization_code(
|
||||
client_id=client_id,
|
||||
@@ -285,15 +392,23 @@ def oidc_authorize():
|
||||
ip_address=request.remote_addr,
|
||||
user_agent=request.headers.get("User-Agent"),
|
||||
)
|
||||
logger.debug("[OIDC] Authorization code generated successfully: %s...", code[:20] if code else None)
|
||||
except Exception as e:
|
||||
logger.debug("[OIDC] Authorization code generation failed: %s", str(e))
|
||||
return _redirect_with_error(redirect_uri, "server_error", str(e), state)
|
||||
|
||||
# Redirect with authorization code
|
||||
logger.debug("[OIDC] Redirecting with authorization code...")
|
||||
redirect_params = {"code": code}
|
||||
if state:
|
||||
redirect_params["state"] = state
|
||||
|
||||
return redirect(f"{redirect_uri}?{urlencode(redirect_params)}")
|
||||
redirect_url = f"{redirect_uri}?{urlencode(redirect_params)}"
|
||||
logger.debug("[OIDC] Redirect URL: %s...", redirect_url[:100] if redirect_url else None)
|
||||
logger.debug("[OIDC] oidc_authorize completed successfully")
|
||||
logger.debug("[OIDC] ===========================================")
|
||||
|
||||
return redirect(redirect_url)
|
||||
|
||||
|
||||
def _redirect_with_error(redirect_uri, error, error_description, state=None):
|
||||
@@ -414,10 +529,22 @@ def oidc_token():
|
||||
else:
|
||||
data = request.json or {}
|
||||
|
||||
# Debug: Log all incoming request parameters
|
||||
logger.debug("[OIDC] oidc_token incoming request params:")
|
||||
logger.debug("[OIDC] content_type: %s", request.content_type)
|
||||
logger.debug("[OIDC] method: %s", request.method)
|
||||
logger.debug("[OIDC] headers: %s", dict(request.headers))
|
||||
logger.debug("[OIDC] data: %s", data)
|
||||
logger.debug("[OIDC] raw_data: %s", request.get_data(as_text=True))
|
||||
|
||||
grant_type = data.get("grant_type")
|
||||
|
||||
# Debug: Log grant_type and client info
|
||||
logger.debug("[OIDC] grant_type: %s", grant_type)
|
||||
|
||||
# Validate grant_type
|
||||
if not grant_type:
|
||||
logger.error("[OIDC] grant_type is requred")
|
||||
return api_response(
|
||||
success=False,
|
||||
message="grant_type is required",
|
||||
@@ -444,8 +571,17 @@ def oidc_token():
|
||||
return response, 401
|
||||
|
||||
try:
|
||||
# Development-only debug logging for token endpoint client authentication
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Token endpoint client authentication: client_id={client_id}")
|
||||
|
||||
client = authenticate_client(client_id, client_secret)
|
||||
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Token endpoint client validation: client_id={client_id}, client_db_id={client.id}, success=True")
|
||||
except InvalidClientError:
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Token endpoint client validation: client_id={client_id}, success=False")
|
||||
response = jsonify({
|
||||
"error": "invalid_client",
|
||||
"error_description": "Invalid client credentials"
|
||||
@@ -454,6 +590,7 @@ def oidc_token():
|
||||
|
||||
# Handle authorization_code grant
|
||||
if grant_type == "authorization_code":
|
||||
logger.debug(f"[OIDC] Handling authorization_code")
|
||||
return _handle_authorization_code_grant(data, client)
|
||||
|
||||
# Handle refresh_token grant
|
||||
@@ -462,6 +599,7 @@ def oidc_token():
|
||||
|
||||
# Unsupported grant type
|
||||
else:
|
||||
logger.error("[OIDC] Unsupported grant_type")
|
||||
return api_response(
|
||||
success=False,
|
||||
message="Unsupported grant_type",
|
||||
@@ -478,6 +616,7 @@ def _handle_authorization_code_grant(data, client):
|
||||
code_verifier = data.get("code_verifier")
|
||||
|
||||
if not code:
|
||||
logger.error("[OIDC] code is required")
|
||||
return api_response(
|
||||
success=False,
|
||||
message="code is required",
|
||||
@@ -487,6 +626,7 @@ def _handle_authorization_code_grant(data, client):
|
||||
)
|
||||
|
||||
if not redirect_uri:
|
||||
logger.error("[OIDC] redirect_uri is required")
|
||||
return api_response(
|
||||
success=False,
|
||||
message="redirect_uri is required",
|
||||
@@ -496,6 +636,10 @@ def _handle_authorization_code_grant(data, client):
|
||||
)
|
||||
|
||||
try:
|
||||
# Development-only debug logging for authorization code validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Authorization code validation: client_id={client.client_id}, code_provided=True")
|
||||
|
||||
claims, user = OIDCService.validate_authorization_code(
|
||||
code=code,
|
||||
client_id=client.client_id,
|
||||
@@ -505,6 +649,16 @@ def _handle_authorization_code_grant(data, client):
|
||||
user_agent=request.headers.get("User-Agent"),
|
||||
)
|
||||
except InvalidGrantError as e:
|
||||
logger.error(f"[OIDC] INVALID_GRANT: {str(e)}")
|
||||
return api_response(
|
||||
success=False,
|
||||
message=str(e),
|
||||
status=400,
|
||||
error_type="INVALID_GRANT",
|
||||
error_details={"error": "invalid_grant", "error_description": str(e)},
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"[OIDC] Authorization code validation error: {type(e).__name__}: {str(e)}")
|
||||
return api_response(
|
||||
success=False,
|
||||
message=str(e),
|
||||
@@ -515,6 +669,10 @@ def _handle_authorization_code_grant(data, client):
|
||||
|
||||
# Generate tokens
|
||||
try:
|
||||
# Development-only debug logging for token generation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Token generation: client_id={client.client_id}, user_id={claims['user_id']}, scope={claims['scope']}")
|
||||
|
||||
tokens = OIDCService.generate_tokens(
|
||||
client_id=client.client_id,
|
||||
user_id=claims["user_id"],
|
||||
@@ -525,6 +683,7 @@ def _handle_authorization_code_grant(data, client):
|
||||
auth_time=int(__import__("time").time()),
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"[OIDC] Failed to generate tokens {str(e)}")
|
||||
return api_response(
|
||||
success=False,
|
||||
message="Failed to generate tokens",
|
||||
@@ -906,7 +1065,7 @@ def oidc_register():
|
||||
# Generate client credentials
|
||||
client_id = f"oidc_{secrets.token_urlsafe(16)}"
|
||||
client_secret = f"secret_{secrets.token_urlsafe(24)}"
|
||||
client_secret_hash = bcrypt.generate_password_hash(client_secret).decode("utf-8")
|
||||
client_secret_hash = flask_bcrypt.generate_password_hash(client_secret).decode("utf-8")
|
||||
|
||||
# Get organization from request or default
|
||||
org_id = data.get("organization_id")
|
||||
|
||||
@@ -1,6 +1,8 @@
|
||||
"""Authentication service."""
|
||||
import logging
|
||||
import secrets
|
||||
from datetime import datetime, timedelta
|
||||
from flask import request, g
|
||||
from flask import request, g, current_app
|
||||
from app.extensions import db, bcrypt
|
||||
from app.models.user import User
|
||||
from app.models.authentication_method import AuthenticationMethod
|
||||
@@ -9,7 +11,8 @@ from app.utils.constants import AuthMethodType, SessionStatus, UserStatus, Audit
|
||||
from app.exceptions.auth_exceptions import InvalidCredentialsError, AccountSuspendedError, AccountInactiveError
|
||||
from app.exceptions.validation_exceptions import EmailAlreadyExistsError
|
||||
from app.services.audit_service import AuditService
|
||||
import secrets
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class AuthService:
|
||||
@@ -85,27 +88,45 @@ class AuthService:
|
||||
"""
|
||||
# Find user
|
||||
user = User.query.filter_by(email=email.lower(), deleted_at=None).first()
|
||||
|
||||
# Development-only debug logging for user existence check
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Auth] User lookup: email={email}, exists={user is not None}")
|
||||
|
||||
if not user:
|
||||
raise InvalidCredentialsError()
|
||||
|
||||
|
||||
# Check account status
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Auth] Account status: user_id={user.id}, status={user.status}")
|
||||
|
||||
if user.status == UserStatus.SUSPENDED:
|
||||
raise AccountSuspendedError()
|
||||
if user.status == UserStatus.INACTIVE:
|
||||
raise AccountInactiveError()
|
||||
|
||||
|
||||
# Find password auth method
|
||||
auth_method = AuthenticationMethod.query.filter_by(
|
||||
user_id=user.id,
|
||||
method_type=AuthMethodType.PASSWORD,
|
||||
deleted_at=None,
|
||||
).first()
|
||||
|
||||
|
||||
# Development-only debug logging for auth method lookup
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Auth] Auth method lookup: user_id={user.id}, has_password_auth={auth_method is not None and auth_method.password_hash is not None}")
|
||||
|
||||
if not auth_method or not auth_method.password_hash:
|
||||
raise InvalidCredentialsError()
|
||||
|
||||
|
||||
# Verify password
|
||||
if not bcrypt.check_password_hash(auth_method.password_hash, password):
|
||||
password_valid = bcrypt.check_password_hash(auth_method.password_hash, password)
|
||||
|
||||
# Development-only debug logging for password validation (without logging actual password)
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Auth] Password validation: user_id={user.id}, valid={password_valid}")
|
||||
|
||||
if not password_valid:
|
||||
raise InvalidCredentialsError()
|
||||
|
||||
# Update last login
|
||||
|
||||
@@ -84,7 +84,7 @@ class OIDCAuditService:
|
||||
ip_address=context["ip_address"],
|
||||
user_agent=context["user_agent"],
|
||||
request_id=context["request_id"],
|
||||
metadata=metadata,
|
||||
event_metadata=metadata,
|
||||
)
|
||||
|
||||
return log
|
||||
|
||||
@@ -1,4 +1,5 @@
|
||||
"""OIDC Service - Main OIDC service layer."""
|
||||
import logging
|
||||
import secrets
|
||||
import hashlib
|
||||
from datetime import datetime, timedelta
|
||||
@@ -6,6 +7,8 @@ from typing import Dict, List, Optional, Tuple
|
||||
|
||||
from flask import current_app, g
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
from app.extensions import db
|
||||
from app.models import (
|
||||
User, OIDCClient, OIDCAuthCode, OIDCRefreshToken,
|
||||
@@ -120,13 +123,24 @@ class OIDCService:
|
||||
"""
|
||||
# Validate client exists and is active
|
||||
client = OIDCClient.query.filter_by(client_id=client_id).first()
|
||||
|
||||
# Development-only debug logging for client validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Generate auth code - Client validation: client_id={client_id}, exists={client is not None}")
|
||||
|
||||
if not client:
|
||||
raise NotFoundError("Client not found")
|
||||
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Generate auth code - Client active validation: client_id={client_id}, is_active={client.is_active}")
|
||||
|
||||
if not client.is_active:
|
||||
raise ValidationError("Client is not active")
|
||||
|
||||
# Validate redirect URI
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Generate auth code - Redirect URI validation: client_id={client_id}, redirect_uri={redirect_uri}")
|
||||
|
||||
if not client.is_redirect_uri_allowed(redirect_uri):
|
||||
raise ValidationError("Invalid redirect_uri")
|
||||
|
||||
@@ -141,6 +155,10 @@ class OIDCService:
|
||||
code = cls._generate_code()
|
||||
code_hash = cls._hash_value(code)
|
||||
|
||||
# Development-only debug logging for PKCE in code creation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Generate auth code - PKCE: code_challenge={code_challenge is not None}, code_challenge_method={code_challenge_method}")
|
||||
|
||||
# Create auth code record
|
||||
auth_code = OIDCAuthCode.create_code(
|
||||
client_id=client.id,
|
||||
@@ -195,7 +213,13 @@ class OIDCService:
|
||||
"""
|
||||
# Get client
|
||||
client = OIDCClient.query.filter_by(client_id=client_id).first()
|
||||
|
||||
# Development-only debug logging for client validation in code validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Validate auth code - Client validation: client_id={client_id}, exists={client is not None}")
|
||||
|
||||
if not client:
|
||||
logger.error(f"[OIDC] Validate auth code - Client not found: client_id={client_id}")
|
||||
raise InvalidGrantError("Invalid client")
|
||||
|
||||
# Hash the provided code and find matching auth code
|
||||
@@ -206,7 +230,11 @@ class OIDCService:
|
||||
deleted_at=None
|
||||
).first()
|
||||
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Validate auth code - Code lookup: code_hash={code_hash[:20]}..., found={auth_code is not None}")
|
||||
|
||||
if not auth_code:
|
||||
logger.error(f"[OIDC] Validate auth code - Code not found or deleted: code_hash={code_hash[:20]}...")
|
||||
OIDCAuditService.log_authorization_event(
|
||||
client_id=client_id,
|
||||
success=False,
|
||||
@@ -217,6 +245,7 @@ class OIDCService:
|
||||
|
||||
# Check if already used
|
||||
if auth_code.is_used:
|
||||
logger.error(f"[OIDC] Validate auth code - Code already used: code_hash={code_hash[:20]}..., user_id={auth_code.user_id}")
|
||||
OIDCAuditService.log_authorization_event(
|
||||
client_id=client_id,
|
||||
user_id=auth_code.user_id,
|
||||
@@ -228,6 +257,7 @@ class OIDCService:
|
||||
|
||||
# Check expiration
|
||||
if auth_code.is_expired():
|
||||
logger.error(f"[OIDC] Validate auth code - Code expired: code_hash={code_hash[:20]}..., expires_at={auth_code.expires_at}")
|
||||
OIDCAuditService.log_authorization_event(
|
||||
client_id=client_id,
|
||||
user_id=auth_code.user_id,
|
||||
@@ -239,16 +269,22 @@ class OIDCService:
|
||||
|
||||
# Validate redirect URI
|
||||
if auth_code.redirect_uri != redirect_uri:
|
||||
logger.error(f"[OIDC] Validate auth code - Redirect URI mismatch: expected={auth_code.redirect_uri}, got={redirect_uri}")
|
||||
raise InvalidGrantError("Invalid redirect_uri")
|
||||
|
||||
# Validate PKCE if required
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Validate auth code - PKCE: require_pkce={client.require_pkce}, has_verifier={bool(auth_code.code_verifier)}, provided_verifier={bool(code_verifier)}")
|
||||
|
||||
if client.require_pkce and auth_code.code_verifier:
|
||||
if not code_verifier:
|
||||
logger.error(f"[OIDC] Validate auth code - PKCE required but no code_verifier provided")
|
||||
raise ValidationError("code_verifier is required")
|
||||
|
||||
# Verify code verifier
|
||||
expected_challenge = cls._compute_code_challenge(code_verifier, "S256")
|
||||
if expected_challenge != auth_code.code_verifier:
|
||||
logger.error(f"[OIDC] Validate auth code - Invalid code_verifier: expected={expected_challenge[:20]}..., got={auth_code.code_verifier[:20]}...")
|
||||
OIDCAuditService.log_authorization_event(
|
||||
client_id=client_id,
|
||||
user_id=auth_code.user_id,
|
||||
@@ -263,7 +299,13 @@ class OIDCService:
|
||||
|
||||
# Get user
|
||||
user = User.query.get(auth_code.user_id)
|
||||
|
||||
# Development-only debug logging for user validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Validate auth code - User validation: user_id={auth_code.user_id}, exists={user is not None}")
|
||||
|
||||
if not user:
|
||||
logger.error(f"[OIDC] Validate auth code - User not found: user_id={auth_code.user_id}")
|
||||
raise InvalidGrantError("User not found")
|
||||
|
||||
claims = {
|
||||
@@ -326,6 +368,11 @@ class OIDCService:
|
||||
|
||||
# Get client
|
||||
client = OIDCClient.query.filter_by(client_id=client_id).first()
|
||||
|
||||
# Development-only debug logging for token generation client validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Generate tokens - Client validation: client_id={client_id}, exists={client is not None}")
|
||||
|
||||
if not client:
|
||||
raise InvalidClientError()
|
||||
|
||||
@@ -466,6 +513,11 @@ class OIDCService:
|
||||
|
||||
# Get client
|
||||
client = OIDCClient.query.filter_by(client_id=client_id).first()
|
||||
|
||||
# Development-only debug logging for refresh token client validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Refresh token - Client validation: client_id={client_id}, exists={client is not None}")
|
||||
|
||||
if not client:
|
||||
raise InvalidClientError()
|
||||
|
||||
@@ -476,6 +528,10 @@ class OIDCService:
|
||||
deleted_at=None
|
||||
).first()
|
||||
|
||||
# Development-only debug logging for refresh token validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Refresh token - Token validation: user_id={refresh_token_obj.user_id if refresh_token_obj else None}, found={refresh_token_obj is not None}")
|
||||
|
||||
if not refresh_token_obj:
|
||||
OIDCAuditService.log_token_event(
|
||||
client_id=client_id,
|
||||
@@ -497,6 +553,9 @@ class OIDCService:
|
||||
raise InvalidGrantError("Refresh token expired or revoked")
|
||||
|
||||
# Validate client matches
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[OIDC] Refresh token - Client match validation: expected={client.id}, actual={refresh_token_obj.client_id}, match={refresh_token_obj.client_id == client.id}")
|
||||
|
||||
if refresh_token_obj.client_id != client.id:
|
||||
raise InvalidGrantError("Client mismatch")
|
||||
|
||||
|
||||
@@ -1,5 +1,7 @@
|
||||
"""Organization service."""
|
||||
import logging
|
||||
from datetime import datetime
|
||||
from flask import current_app
|
||||
from app.extensions import db
|
||||
from app.models.organization import Organization
|
||||
from app.models.organization_member import OrganizationMember
|
||||
@@ -7,6 +9,8 @@ from app.exceptions.validation_exceptions import OrganizationNotFoundError, Conf
|
||||
from app.utils.constants import OrganizationRole, AuditAction
|
||||
from app.services.audit_service import AuditService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class OrganizationService:
|
||||
"""Service for organization operations."""
|
||||
@@ -80,6 +84,11 @@ class OrganizationService:
|
||||
OrganizationNotFoundError: If organization not found
|
||||
"""
|
||||
org = Organization.query.filter_by(id=org_id, deleted_at=None).first()
|
||||
|
||||
# Development-only debug logging for organization validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Org] Get organization by ID: org_id={org_id}, exists={org is not None}")
|
||||
|
||||
if not org:
|
||||
raise OrganizationNotFoundError()
|
||||
return org
|
||||
@@ -95,7 +104,13 @@ class OrganizationService:
|
||||
Returns:
|
||||
Organization instance or None
|
||||
"""
|
||||
return Organization.query.filter_by(slug=slug, deleted_at=None).first()
|
||||
org = Organization.query.filter_by(slug=slug, deleted_at=None).first()
|
||||
|
||||
# Development-only debug logging for organization validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Org] Get organization by slug: slug={slug}, exists={org is not None}")
|
||||
|
||||
return org
|
||||
|
||||
@staticmethod
|
||||
def update_organization(org, user_id, **kwargs):
|
||||
@@ -180,6 +195,10 @@ class OrganizationService:
|
||||
deleted_at=None,
|
||||
).first()
|
||||
|
||||
# Development-only debug logging for membership validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Org] Member check: org_id={org.id}, user_id={user_id}, already_member={existing is not None}")
|
||||
|
||||
if existing:
|
||||
raise ConflictError("User is already a member of this organization")
|
||||
|
||||
@@ -223,6 +242,10 @@ class OrganizationService:
|
||||
deleted_at=None,
|
||||
).first()
|
||||
|
||||
# Development-only debug logging for membership removal validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[Org] Member removal: org_id={org.id}, user_id={user_id}, found={member is not None}")
|
||||
|
||||
if member:
|
||||
member.delete(soft=True)
|
||||
|
||||
|
||||
@@ -1,10 +1,14 @@
|
||||
"""User service."""
|
||||
import logging
|
||||
from flask import current_app
|
||||
from app.extensions import db
|
||||
from app.models.user import User
|
||||
from app.exceptions.validation_exceptions import UserNotFoundError
|
||||
from app.utils.constants import AuditAction
|
||||
from app.services.audit_service import AuditService
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
class UserService:
|
||||
"""Service for user operations."""
|
||||
@@ -24,6 +28,11 @@ class UserService:
|
||||
UserNotFoundError: If user not found
|
||||
"""
|
||||
user = User.query.filter_by(id=user_id, deleted_at=None).first()
|
||||
|
||||
# Development-only debug logging for user validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[User] Get user by ID: user_id={user_id}, exists={user is not None}")
|
||||
|
||||
if not user:
|
||||
raise UserNotFoundError()
|
||||
return user
|
||||
@@ -39,7 +48,13 @@ class UserService:
|
||||
Returns:
|
||||
User instance or None
|
||||
"""
|
||||
return User.query.filter_by(email=email.lower(), deleted_at=None).first()
|
||||
user = User.query.filter_by(email=email.lower(), deleted_at=None).first()
|
||||
|
||||
# Development-only debug logging for user validation
|
||||
if current_app.config.get('ENV') == 'development':
|
||||
logger.debug(f"[User] Get user by email: email={email}, exists={user is not None}")
|
||||
|
||||
return user
|
||||
|
||||
@staticmethod
|
||||
def update_user(user, **kwargs):
|
||||
|
||||
Reference in New Issue
Block a user