feat: add logs

src/application/commands/create_kyc_command.py

@@ -25,8 +25,16 @@ class PassKycCommand:
 
 
     async def __call__(self,user_id: str) -> BeorgKycCreateResponse:
+        self._logger.info(f'KYC session creation started for user {user_id}')
+        self._logger.info(f'KYC Beorg identification request started for user {user_id}')
         result = await self._beorg_service.create_identification(client_user_token=user_id)
+        self._logger.info(
+            f'KYC Beorg identification request finished for user {user_id} '
+            f'status={result.status} user_token={result.user_token} client_user_token={result.client_user_token}'
+        )
         expires_at = _utc_now() + timedelta(seconds=KYC_SESSION_TTL)
+        self._logger.info(f'KYC session expiration calculated for user {user_id} ttl={KYC_SESSION_TTL} expires_at={expires_at.isoformat()}')
+        self._logger.info(f'KYC session database save started for user {user_id}')
         async with self._unit_of_work as unit_of_work:
             await unit_of_work.kyc_repository.create_started_session(
                 user_id=user_id,
@@ -37,7 +45,8 @@ class PassKycCommand:
                 expires_at=expires_at,
                 error=result.error,
             )
-        self._logger.info(f'KYC started for user {user_id}')
+        self._logger.info(f'KYC session database save finished for user {user_id}')
+        self._logger.info(f'KYC session creation finished for user {user_id}')
         return result
 
 

src/infrastructure/security/jwt.py

@@ -13,6 +13,7 @@ class JwtService(IJwtService):
         self._key_store = key_store
 
     async def decode_access_token(self, token: str) -> AccessTokenPayload:
+        self._logger.info('JWT access token decode started')
         payload = await self._decode_and_verify(token)
 
         if payload.get('type') != 'access':
@@ -20,7 +21,7 @@ class JwtService(IJwtService):
             raise InvalidTokenException('Invalid token type')
 
         try:
-            return AccessTokenPayload(
+            result = AccessTokenPayload(
                 sub=str(payload['sub']),
                 type='access',
                 sid=str(payload['sid']),
@@ -30,6 +31,8 @@ class JwtService(IJwtService):
                 iss=payload.get('iss'),
                 aud=payload.get('aud'),
             )
+            self._logger.info(f'JWT access token decode completed user_id={result.sub} sid={result.sid}')
+            return result
         except KeyError as exception:
             self._logger.warning(f'Access token missing claim error={str(exception)}')
             raise InvalidTokenException(f'Missing token claim: {exception}')
@@ -37,6 +40,7 @@ class JwtService(IJwtService):
     async def _decode_and_verify(self, token: str) -> dict:
         kid: str | None = None
         try:
+            self._logger.debug('JWT header parsing started')
             header = jwt.get_unverified_header(token)
 
             kid = header.get('kid')
@@ -49,6 +53,7 @@ class JwtService(IJwtService):
                 self._logger.warning(f'JWT invalid algorithm kid={kid} received_alg={received_alg} expected_alg={settings.JWT_ALGORITHM}')
                 raise InvalidTokenException('Invalid token algorithm')
 
+            self._logger.debug(f'JWT public key lookup started kid={kid}')
             public_pem = await self._key_store.get_public_key_for_kid(str(kid))
 
             if not public_pem:
@@ -60,6 +65,7 @@ class JwtService(IJwtService):
                 self._logger.warning(f'JWT unknown kid kid={kid}')
                 raise InvalidTokenException('Unknown token kid')
 
+            self._logger.debug(f'JWT signature verification started kid={kid}')
             options = {
                 'verify_signature': True,
                 'verify_exp': True,
@@ -91,6 +97,7 @@ class JwtService(IJwtService):
                 self._logger.warning(f'JWT missing type claim kid={kid}')
                 raise InvalidTokenException('Missing token claim: type')
 
+            self._logger.info(f'JWT signature verification completed kid={kid} user_id={payload.get("sub")} sid={payload.get("sid")}')
             return payload
 
         except ExpiredSignatureError as exception:

src/presentation/decorators/auth.py

@@ -4,6 +4,7 @@ from src.application.contracts import IJwtService
 from src.application.domain.exceptions import InvalidTokenException,NotAuthenticatedException
 from src.application.domain.dto import AccessTokenPayload, AuthContext
 from src.presentation.dependencies import get_jwt_service
+from src.presentation.dependencies.logger import get_logger
 
 
 def _extract_access_token(request: Request) -> str | None:
@@ -25,12 +26,17 @@ async def require_access_token(
     request: Request,
     jwt_service: IJwtService = Depends(get_jwt_service),
 ) -> AuthContext:
+    logger = get_logger()
+    logger.info(f'JWT auth started path={request.url.path}')
     token = _extract_access_token(request)
     if not token:
+        logger.warning(f'JWT auth failed path={request.url.path} reason=missing_token')
         raise NotAuthenticatedException()
 
     payload: AccessTokenPayload = await jwt_service.decode_access_token(token)
     if payload.type != 'access':
+        logger.warning(f'JWT auth failed path={request.url.path} user_id={payload.sub} reason=invalid_token_type type={payload.type}')
         raise InvalidTokenException('Invalid token type')
 
+    logger.info(f'JWT auth completed path={request.url.path} user_id={payload.sub} sid={payload.sid}')
     return AuthContext(user_id=payload.sub, sid=payload.sid, token=payload)

src/presentation/decorators/csrf.py

@@ -5,6 +5,7 @@ from typing import Callable, Awaitable, Any, Optional, Annotated
 from fastapi import Request, Header
 from src.application.domain.exceptions import CsrfRequestRequiredException
 from src.infrastructure.security import CsrfService
+from src.presentation.dependencies.logger import get_logger
 
 
 def csrf_protect(
@@ -31,6 +32,7 @@ def csrf_protect(
 
         @wraps(func)
         async def wrapper(*args, **kwargs):
+            logger = get_logger()
             request: Request | None = kwargs.get('request')
             if request is None:
                 for arg in args:
@@ -39,8 +41,10 @@ def csrf_protect(
                         break
 
             if request is None:
+                logger.warning('CSRF check failed reason=missing_request')
                 raise CsrfRequestRequiredException()
 
+            logger.info(f'CSRF check started path={request.url.path}')
             csrf = CsrfService()
 
             cookie_token, _ = csrf.extract(request.cookies, request.headers)
@@ -50,6 +54,7 @@ def csrf_protect(
             csrf.verify_pair(cookie_token, header_token, expected_subject)
 
             kwargs.pop('x_csrf_token', None)
+            logger.info(f'CSRF check completed path={request.url.path}')
             return await func(*args, **kwargs)
 
         wrapper.__signature__ = sig.replace(parameters=params)