From 351344ecbb1edabdc1475450d0f80d440d392e8a Mon Sep 17 00:00:00 2001 From: Nikhil <118773738+pablohashescobar@users.noreply.github.com> Date: Tue, 3 Mar 2026 19:35:34 +0530 Subject: [PATCH] [WEB-5225] feat: enhance authentication logging with detailed error and info message (#7998) * feat: enhance authentication logging with detailed error and info messages - Added logging for various authentication events in the Adapter and its subclasses, including email validation, user existence checks, and password strength validation. - Implemented error handling for GitHub OAuth email retrieval, ensuring proper logging of unexpected responses and missing primary emails. - Updated logging configuration in local and production settings to include a dedicated logger for authentication events. * chore: address copilot comments * chore: addressed some additional comments * chore: update log * fix: lint --- apps/api/plane/api/views/project.py | 1 - apps/api/plane/authentication/adapter/base.py | 29 +++-- .../api/plane/authentication/adapter/oauth.py | 20 ++- .../provider/credentials/email.py | 63 +++++---- .../authentication/provider/oauth/github.py | 120 +++++++++++------- apps/api/plane/db/models/estimate.py | 2 +- apps/api/plane/settings/local.py | 5 + apps/api/plane/settings/production.py | 5 + 8 files changed, 146 insertions(+), 99 deletions(-) diff --git a/apps/api/plane/api/views/project.py b/apps/api/plane/api/views/project.py index b7bfd603a..5ab0fd1c1 100644 --- a/apps/api/plane/api/views/project.py +++ b/apps/api/plane/api/views/project.py @@ -23,7 +23,6 @@ from drf_spectacular.utils import OpenApiResponse, OpenApiRequest from plane.db.models import ( Cycle, Intake, - ProjectUserProperty, Module, Project, DeployBoard, diff --git a/apps/api/plane/authentication/adapter/base.py b/apps/api/plane/authentication/adapter/base.py index 7be6b8f68..b80dfa500 100644 --- a/apps/api/plane/authentication/adapter/base.py +++ b/apps/api/plane/authentication/adapter/base.py @@ -3,29 +3,33 @@ # See the LICENSE file for details. # Python imports +import logging import os import uuid -import requests from io import BytesIO +import requests +from django.conf import settings +from django.core.exceptions import ValidationError +from django.core.validators import validate_email + # Django imports from django.utils import timezone -from django.core.validators import validate_email -from django.core.exceptions import ValidationError -from django.conf import settings # Third party imports from zxcvbn import zxcvbn -# Module imports -from plane.db.models import Profile, User, WorkspaceMemberInvite, FileAsset -from plane.license.utils.instance_value import get_configuration_value -from .error import AuthenticationException, AUTHENTICATION_ERROR_CODES from plane.bgtasks.user_activation_email_task import user_activation_email + +# Module imports +from plane.db.models import FileAsset, Profile, User, WorkspaceMemberInvite +from plane.license.utils.instance_value import get_configuration_value +from plane.settings.storage import S3Storage +from plane.utils.exception_logger import log_exception from plane.utils.host import base_host from plane.utils.ip_address import get_client_ip -from plane.utils.exception_logger import log_exception -from plane.settings.storage import S3Storage + +from .error import AUTHENTICATION_ERROR_CODES, AuthenticationException class Adapter: @@ -37,6 +41,7 @@ class Adapter: self.callback = callback self.token_data = None self.user_data = None + self.logger = logging.getLogger("plane.authentication") def get_user_token(self, data, headers=None): raise NotImplementedError @@ -59,6 +64,7 @@ class Adapter: def sanitize_email(self, email): # Check if email is present if not email: + self.logger.error("Email is not present") raise AuthenticationException( error_code=AUTHENTICATION_ERROR_CODES["INVALID_EMAIL"], error_message="INVALID_EMAIL", @@ -72,6 +78,7 @@ class Adapter: try: validate_email(email) except ValidationError: + self.logger.warning(f"Email is not valid: {email}") raise AuthenticationException( error_code=AUTHENTICATION_ERROR_CODES["INVALID_EMAIL"], error_message="INVALID_EMAIL", @@ -84,6 +91,7 @@ class Adapter: """Validate password strength""" results = zxcvbn(self.code) if results["score"] < 3: + self.logger.warning("Password is not strong enough") raise AuthenticationException( error_code=AUTHENTICATION_ERROR_CODES["PASSWORD_TOO_WEAK"], error_message="PASSWORD_TOO_WEAK", @@ -101,6 +109,7 @@ class Adapter: # Check if sign up is disabled and invite is present or not if ENABLE_SIGNUP == "0" and not WorkspaceMemberInvite.objects.filter(email=email).exists(): + self.logger.warning("Sign up is disabled and invite is not present") # Raise exception raise AuthenticationException( error_code=AUTHENTICATION_ERROR_CODES["SIGNUP_DISABLED"], diff --git a/apps/api/plane/authentication/adapter/oauth.py b/apps/api/plane/authentication/adapter/oauth.py index 0ae02f212..0bef76b24 100644 --- a/apps/api/plane/authentication/adapter/oauth.py +++ b/apps/api/plane/authentication/adapter/oauth.py @@ -4,20 +4,21 @@ # Python imports import requests +from django.db import DatabaseError, IntegrityError # Django imports from django.utils import timezone -from django.db import DatabaseError, IntegrityError + +from plane.authentication.adapter.error import ( + AUTHENTICATION_ERROR_CODES, + AuthenticationException, +) # Module imports from plane.db.models import Account +from plane.utils.exception_logger import log_exception from .base import Adapter -from plane.authentication.adapter.error import ( - AuthenticationException, - AUTHENTICATION_ERROR_CODES, -) -from plane.utils.exception_logger import log_exception class OauthAdapter(Adapter): @@ -78,6 +79,7 @@ class OauthAdapter(Adapter): response.raise_for_status() return response.json() except requests.RequestException: + self.logger.warning("Error getting user token") code = self.authentication_error_code() raise AuthenticationException(error_code=AUTHENTICATION_ERROR_CODES[code], error_message=str(code)) @@ -88,6 +90,12 @@ class OauthAdapter(Adapter): response.raise_for_status() return response.json() except requests.RequestException: + self.logger.warning( + "Error getting user response", + extra={ + "headers": headers, + }, + ) code = self.authentication_error_code() raise AuthenticationException(error_code=AUTHENTICATION_ERROR_CODES[code], error_message=str(code)) diff --git a/apps/api/plane/authentication/provider/credentials/email.py b/apps/api/plane/authentication/provider/credentials/email.py index b23b3405e..e2c424588 100644 --- a/apps/api/plane/authentication/provider/credentials/email.py +++ b/apps/api/plane/authentication/provider/credentials/email.py @@ -7,11 +7,11 @@ import os # Module imports from plane.authentication.adapter.credential import CredentialAdapter -from plane.db.models import User from plane.authentication.adapter.error import ( AUTHENTICATION_ERROR_CODES, AuthenticationException, ) +from plane.db.models import User from plane.license.utils.instance_value import get_configuration_value @@ -24,14 +24,12 @@ class EmailProvider(CredentialAdapter): self.code = code self.is_signup = is_signup - (ENABLE_EMAIL_PASSWORD,) = get_configuration_value( - [ - { - "key": "ENABLE_EMAIL_PASSWORD", - "default": os.environ.get("ENABLE_EMAIL_PASSWORD"), - } - ] - ) + (ENABLE_EMAIL_PASSWORD,) = get_configuration_value([ + { + "key": "ENABLE_EMAIL_PASSWORD", + "default": os.environ.get("ENABLE_EMAIL_PASSWORD"), + } + ]) if ENABLE_EMAIL_PASSWORD == "0": raise AuthenticationException( @@ -43,29 +41,29 @@ class EmailProvider(CredentialAdapter): if self.is_signup: # Check if the user already exists if User.objects.filter(email=self.key).exists(): + self.logger.warning("User already exists") raise AuthenticationException( error_message="USER_ALREADY_EXIST", error_code=AUTHENTICATION_ERROR_CODES["USER_ALREADY_EXIST"], ) - super().set_user_data( - { - "email": self.key, - "user": { - "avatar": "", - "first_name": "", - "last_name": "", - "provider_id": "", - "is_password_autoset": False, - }, - } - ) + super().set_user_data({ + "email": self.key, + "user": { + "avatar": "", + "first_name": "", + "last_name": "", + "provider_id": "", + "is_password_autoset": False, + }, + }) return else: user = User.objects.filter(email=self.key).first() # User does not exists if not user: + self.logger.warning("User does not exist") raise AuthenticationException( error_message="USER_DOES_NOT_EXIST", error_code=AUTHENTICATION_ERROR_CODES["USER_DOES_NOT_EXIST"], @@ -74,6 +72,7 @@ class EmailProvider(CredentialAdapter): # Check user password if not user.check_password(self.code): + self.logger.warning("Authentication failed - invalid credentials") raise AuthenticationException( error_message=( "AUTHENTICATION_FAILED_SIGN_UP" if self.is_signup else "AUTHENTICATION_FAILED_SIGN_IN" @@ -84,16 +83,14 @@ class EmailProvider(CredentialAdapter): payload={"email": self.key}, ) - super().set_user_data( - { - "email": self.key, - "user": { - "avatar": "", - "first_name": "", - "last_name": "", - "provider_id": "", - "is_password_autoset": False, - }, - } - ) + super().set_user_data({ + "email": self.key, + "user": { + "avatar": "", + "first_name": "", + "last_name": "", + "provider_id": "", + "is_password_autoset": False, + }, + }) return diff --git a/apps/api/plane/authentication/provider/oauth/github.py b/apps/api/plane/authentication/provider/oauth/github.py index d3e202c09..363cd722e 100644 --- a/apps/api/plane/authentication/provider/oauth/github.py +++ b/apps/api/plane/authentication/provider/oauth/github.py @@ -10,13 +10,14 @@ from urllib.parse import urlencode import pytz import requests +from plane.authentication.adapter.error import ( + AUTHENTICATION_ERROR_CODES, + AuthenticationException, +) + # Module imports from plane.authentication.adapter.oauth import OauthAdapter from plane.license.utils.instance_value import get_configuration_value -from plane.authentication.adapter.error import ( - AuthenticationException, - AUTHENTICATION_ERROR_CODES, -) class GitHubOAuthProvider(OauthAdapter): @@ -30,22 +31,20 @@ class GitHubOAuthProvider(OauthAdapter): organization_scope = "read:org" def __init__(self, request, code=None, state=None, callback=None): - GITHUB_CLIENT_ID, GITHUB_CLIENT_SECRET, GITHUB_ORGANIZATION_ID = get_configuration_value( - [ - { - "key": "GITHUB_CLIENT_ID", - "default": os.environ.get("GITHUB_CLIENT_ID"), - }, - { - "key": "GITHUB_CLIENT_SECRET", - "default": os.environ.get("GITHUB_CLIENT_SECRET"), - }, - { - "key": "GITHUB_ORGANIZATION_ID", - "default": os.environ.get("GITHUB_ORGANIZATION_ID"), - }, - ] - ) + GITHUB_CLIENT_ID, GITHUB_CLIENT_SECRET, GITHUB_ORGANIZATION_ID = get_configuration_value([ + { + "key": "GITHUB_CLIENT_ID", + "default": os.environ.get("GITHUB_CLIENT_ID"), + }, + { + "key": "GITHUB_CLIENT_SECRET", + "default": os.environ.get("GITHUB_CLIENT_SECRET"), + }, + { + "key": "GITHUB_ORGANIZATION_ID", + "default": os.environ.get("GITHUB_ORGANIZATION_ID"), + }, + ]) if not (GITHUB_CLIENT_ID and GITHUB_CLIENT_SECRET): raise AuthenticationException( @@ -90,32 +89,46 @@ class GitHubOAuthProvider(OauthAdapter): "redirect_uri": self.redirect_uri, } token_response = self.get_user_token(data=data, headers={"Accept": "application/json"}) - super().set_token_data( - { - "access_token": token_response.get("access_token"), - "refresh_token": token_response.get("refresh_token", None), - "access_token_expired_at": ( - datetime.fromtimestamp(token_response.get("expires_in"), tz=pytz.utc) - if token_response.get("expires_in") - else None - ), - "refresh_token_expired_at": ( - datetime.fromtimestamp(token_response.get("refresh_token_expired_at"), tz=pytz.utc) - if token_response.get("refresh_token_expired_at") - else None - ), - "id_token": token_response.get("id_token", ""), - } - ) + super().set_token_data({ + "access_token": token_response.get("access_token"), + "refresh_token": token_response.get("refresh_token", None), + "access_token_expired_at": ( + datetime.fromtimestamp(token_response.get("expires_in"), tz=pytz.utc) + if token_response.get("expires_in") + else None + ), + "refresh_token_expired_at": ( + datetime.fromtimestamp(token_response.get("refresh_token_expired_at"), tz=pytz.utc) + if token_response.get("refresh_token_expired_at") + else None + ), + "id_token": token_response.get("id_token", ""), + }) def __get_email(self, headers): try: # Github does not provide email in user response emails_url = "https://api.github.com/user/emails" emails_response = requests.get(emails_url, headers=headers).json() + # Ensure the response is a list before iterating + if not isinstance(emails_response, list): + self.logger.error("Unexpected response format from GitHub emails API") + raise AuthenticationException( + error_code=AUTHENTICATION_ERROR_CODES["GITHUB_OAUTH_PROVIDER_ERROR"], + error_message="GITHUB_OAUTH_PROVIDER_ERROR", + ) email = next((email["email"] for email in emails_response if email["primary"]), None) + if not email: + self.logger.error("No primary email found for user") + raise AuthenticationException( + error_code=AUTHENTICATION_ERROR_CODES["GITHUB_OAUTH_PROVIDER_ERROR"], + error_message="GITHUB_OAUTH_PROVIDER_ERROR", + ) return email except requests.RequestException: + self.logger.warning( + "Error getting email from GitHub", + ) raise AuthenticationException( error_code=AUTHENTICATION_ERROR_CODES["GITHUB_OAUTH_PROVIDER_ERROR"], error_message="GITHUB_OAUTH_PROVIDER_ERROR", @@ -138,22 +151,33 @@ class GitHubOAuthProvider(OauthAdapter): if self.organization_id: if not self.is_user_in_organization(user_info_response.get("login")): + self.logger.warning( + "User is not in organization", + extra={ + "organization_id": self.organization_id, + "user_login": user_info_response.get("login"), + }, + ) raise AuthenticationException( error_code=AUTHENTICATION_ERROR_CODES["GITHUB_USER_NOT_IN_ORG"], error_message="GITHUB_USER_NOT_IN_ORG", ) email = self.__get_email(headers=headers) - super().set_user_data( - { + self.logger.debug( + "Email found", + extra={ "email": email, - "user": { - "provider_id": user_info_response.get("id"), - "email": email, - "avatar": user_info_response.get("avatar_url"), - "first_name": user_info_response.get("name"), - "last_name": user_info_response.get("family_name"), - "is_password_autoset": True, - }, - } + }, ) + super().set_user_data({ + "email": email, + "user": { + "provider_id": user_info_response.get("id"), + "email": email, + "avatar": user_info_response.get("avatar_url"), + "first_name": user_info_response.get("name"), + "last_name": user_info_response.get("family_name"), + "is_password_autoset": True, + }, + }) diff --git a/apps/api/plane/db/models/estimate.py b/apps/api/plane/db/models/estimate.py index aa1e66be1..ded6f97bc 100644 --- a/apps/api/plane/db/models/estimate.py +++ b/apps/api/plane/db/models/estimate.py @@ -3,7 +3,7 @@ # See the LICENSE file for details. # Django imports -from django.core.validators import MaxValueValidator, MinValueValidator +from django.core.validators import MinValueValidator from django.db import models from django.db.models import Q diff --git a/apps/api/plane/settings/local.py b/apps/api/plane/settings/local.py index 1f636df49..dc4135bc1 100644 --- a/apps/api/plane/settings/local.py +++ b/apps/api/plane/settings/local.py @@ -80,6 +80,11 @@ LOGGING = { "handlers": ["console"], "propagate": False, }, + "plane.authentication": { + "level": "INFO", + "handlers": ["console"], + "propagate": False, + }, "plane.migrations": { "level": "INFO", "handlers": ["console"], diff --git a/apps/api/plane/settings/production.py b/apps/api/plane/settings/production.py index 268ad7277..7f3f90d65 100644 --- a/apps/api/plane/settings/production.py +++ b/apps/api/plane/settings/production.py @@ -90,6 +90,11 @@ LOGGING = { "handlers": ["console"], "propagate": False, }, + "plane.authentication": { + "level": "DEBUG" if DEBUG else "INFO", + "handlers": ["console"], + "propagate": False, + }, "plane.migrations": { "level": "DEBUG" if DEBUG else "INFO", "handlers": ["console"],