From a6474f55c15cf675041a13c695da755e558c6a8f Mon Sep 17 00:00:00 2001 From: Cory Hawkvelt Date: Fri, 9 Jan 2026 12:59:53 +1030 Subject: [PATCH] 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 --- app/__init__.py | 55 ++++++++- app/api/oidc.py | 169 ++++++++++++++++++++++++++- app/services/auth_service.py | 35 ++++-- app/services/oidc_audit_service.py | 2 +- app/services/oidc_service.py | 59 ++++++++++ app/services/organization_service.py | 25 +++- app/services/user_service.py | 17 ++- scripts/seed_data.py | 7 +- 8 files changed, 348 insertions(+), 21 deletions(-) diff --git a/app/__init__.py b/app/__init__.py index 91cd09a..1362484 100644 --- a/app/__init__.py +++ b/app/__init__.py @@ -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}") diff --git a/app/api/oidc.py b/app/api/oidc.py index 8d1d98a..175db2e 100644 --- a/app/api/oidc.py +++ b/app/api/oidc.py @@ -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") diff --git a/app/services/auth_service.py b/app/services/auth_service.py index aa20c05..fbda5a5 100644 --- a/app/services/auth_service.py +++ b/app/services/auth_service.py @@ -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 diff --git a/app/services/oidc_audit_service.py b/app/services/oidc_audit_service.py index 0524230..ceab815 100644 --- a/app/services/oidc_audit_service.py +++ b/app/services/oidc_audit_service.py @@ -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 diff --git a/app/services/oidc_service.py b/app/services/oidc_service.py index 89ecf09..462f612 100644 --- a/app/services/oidc_service.py +++ b/app/services/oidc_service.py @@ -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") diff --git a/app/services/organization_service.py b/app/services/organization_service.py index 719ebcc..bfbee5d 100644 --- a/app/services/organization_service.py +++ b/app/services/organization_service.py @@ -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) diff --git a/app/services/user_service.py b/app/services/user_service.py index 8474cd1..458a1be 100644 --- a/app/services/user_service.py +++ b/app/services/user_service.py @@ -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): diff --git a/scripts/seed_data.py b/scripts/seed_data.py index 4bd9aea..8cfa4c4 100644 --- a/scripts/seed_data.py +++ b/scripts/seed_data.py @@ -8,7 +8,6 @@ This script creates: """ import sys import secrets -import hashlib from dotenv import load_dotenv # Load environment variables FIRST before any app imports @@ -122,14 +121,16 @@ def create_or_get_oidc_client(org_id, name, client_id, client_secret, redirect_uris, grant_types, response_types, scopes, **kwargs): """Create an OIDC client if it doesn't exist, or return existing client.""" + from app.extensions import bcrypt + existing = OIDCClient.query.filter_by(client_id=client_id, deleted_at=None).first() if existing: print(f" → OIDC Client {name} already exists, skipping") return existing try: - # Hash the client secret - client_secret_hash = hashlib.sha256(client_secret.encode()).hexdigest() + # Hash the client secret using Flask-Bcrypt (same as oidc_register) + client_secret_hash = bcrypt.generate_password_hash(client_secret).decode("utf-8") client = OIDCClient( organization_id=org_id,