From 1398546dac6824d2b14fd07273c912e54c2087ab Mon Sep 17 00:00:00 2001 From: Dohyun Lim Date: Fri, 13 Feb 2026 17:41:27 +0900 Subject: [PATCH] add logs for token --- app/user/api/routers/v1/auth.py | 18 +- app/user/dependencies/auth.py | 37 ++- app/user/services/auth.py | 72 +++++- app/user/services/jwt.py | 37 ++- token_log_plan.md | 422 ++++++++++++++++++++++++++++++++ 5 files changed, 573 insertions(+), 13 deletions(-) create mode 100644 token_log_plan.md diff --git a/app/user/api/routers/v1/auth.py b/app/user/api/routers/v1/auth.py index a553a7b..002f1b6 100644 --- a/app/user/api/routers/v1/auth.py +++ b/app/user/api/routers/v1/auth.py @@ -254,10 +254,16 @@ async def refresh_token( 유효한 리프레시 토큰을 제출하면 새 액세스 토큰과 새 리프레시 토큰을 발급합니다. 사용된 기존 리프레시 토큰은 즉시 폐기(revoke)됩니다. """ - return await auth_service.refresh_tokens( + logger.info(f"[ROUTER] POST /auth/refresh - token: ...{body.refresh_token[-20:]}") + result = await auth_service.refresh_tokens( refresh_token=body.refresh_token, session=session, ) + logger.info( + f"[ROUTER] POST /auth/refresh 완료 - new_access: ...{result.access_token[-20:]}, " + f"new_refresh: ...{result.refresh_token[-20:]}" + ) + return result @router.post( @@ -281,11 +287,16 @@ async def logout( 현재 사용 중인 리프레시 토큰을 폐기합니다. 해당 토큰으로는 더 이상 액세스 토큰을 갱신할 수 없습니다. """ + logger.info( + f"[ROUTER] POST /auth/logout - user_id: {current_user.id}, " + f"user_uuid: {current_user.user_uuid}, token: ...{body.refresh_token[-20:]}" + ) await auth_service.logout( user_id=current_user.id, refresh_token=body.refresh_token, session=session, ) + logger.info(f"[ROUTER] POST /auth/logout 완료 - user_id: {current_user.id}") return Response(status_code=status.HTTP_204_NO_CONTENT) @@ -309,10 +320,15 @@ async def logout_all( 사용자의 모든 리프레시 토큰을 폐기합니다. 모든 기기에서 재로그인이 필요합니다. """ + logger.info( + f"[ROUTER] POST /auth/logout/all - user_id: {current_user.id}, " + f"user_uuid: {current_user.user_uuid}" + ) await auth_service.logout_all( user_id=current_user.id, session=session, ) + logger.info(f"[ROUTER] POST /auth/logout/all 완료 - user_id: {current_user.id}") return Response(status_code=status.HTTP_204_NO_CONTENT) diff --git a/app/user/dependencies/auth.py b/app/user/dependencies/auth.py index 5074a9d..8290f60 100644 --- a/app/user/dependencies/auth.py +++ b/app/user/dependencies/auth.py @@ -4,6 +4,7 @@ FastAPI 라우터에서 사용할 인증 관련 의존성을 정의합니다. """ +import logging from typing import Optional from fastapi import Depends @@ -22,6 +23,8 @@ from app.user.services.auth import ( ) from app.user.services.jwt import decode_token +logger = logging.getLogger(__name__) + security = HTTPBearer(auto_error=False) @@ -47,18 +50,28 @@ async def get_current_user( UserInactiveError: 비활성화된 계정인 경우 """ if credentials is None: + logger.info("[AUTH-DEP] 토큰 없음 - MissingTokenError") raise MissingTokenError() - payload = decode_token(credentials.credentials) + token = credentials.credentials + logger.debug(f"[AUTH-DEP] Access Token 검증 시작 - token: ...{token[-20:]}") + + payload = decode_token(token) if payload is None: + logger.warning(f"[AUTH-DEP] Access Token 디코딩 실패 - token: ...{token[-20:]}") raise InvalidTokenError() # 토큰 타입 확인 if payload.get("type") != "access": + logger.warning( + f"[AUTH-DEP] 토큰 타입 불일치 - expected: access, " + f"got: {payload.get('type')}, sub: {payload.get('sub')}" + ) raise InvalidTokenError("액세스 토큰이 아닙니다.") user_uuid = payload.get("sub") if user_uuid is None: + logger.warning(f"[AUTH-DEP] 토큰에 sub 클레임 없음 - token: ...{token[-20:]}") raise InvalidTokenError() # 사용자 조회 @@ -71,11 +84,18 @@ async def get_current_user( user = result.scalar_one_or_none() if user is None: + logger.warning(f"[AUTH-DEP] 사용자 미존재 - user_uuid: {user_uuid}") raise UserNotFoundError() if not user.is_active: + logger.warning( + f"[AUTH-DEP] 비활성 사용자 접근 - user_uuid: {user_uuid}, user_id: {user.id}" + ) raise UserInactiveError() + logger.debug( + f"[AUTH-DEP] Access Token 검증 성공 - user_uuid: {user_uuid}, user_id: {user.id}" + ) return user @@ -96,17 +116,24 @@ async def get_current_user_optional( User | None: 로그인한 사용자 또는 None """ if credentials is None: + logger.debug("[AUTH-DEP] 선택적 인증 - 토큰 없음") return None - payload = decode_token(credentials.credentials) + token = credentials.credentials + payload = decode_token(token) if payload is None: + logger.debug(f"[AUTH-DEP] 선택적 인증 - 디코딩 실패, token: ...{token[-20:]}") return None if payload.get("type") != "access": + logger.debug( + f"[AUTH-DEP] 선택적 인증 - 타입 불일치 (type={payload.get('type')})" + ) return None user_uuid = payload.get("sub") if user_uuid is None: + logger.debug("[AUTH-DEP] 선택적 인증 - sub 없음") return None result = await session.execute( @@ -118,8 +145,14 @@ async def get_current_user_optional( user = result.scalar_one_or_none() if user is None or not user.is_active: + logger.debug( + f"[AUTH-DEP] 선택적 인증 - 사용자 미존재 또는 비활성, user_uuid: {user_uuid}" + ) return None + logger.debug( + f"[AUTH-DEP] 선택적 인증 성공 - user_uuid: {user_uuid}, user_id: {user.id}" + ) return user diff --git a/app/user/services/auth.py b/app/user/services/auth.py index 9f964e8..31a071a 100644 --- a/app/user/services/auth.py +++ b/app/user/services/auth.py @@ -207,49 +207,91 @@ class AuthService: TokenExpiredError: 토큰이 만료된 경우 TokenRevokedError: 토큰이 폐기된 경우 """ - logger.info("[AUTH] 토큰 갱신 시작 (Refresh Token Rotation)") + logger.info(f"[AUTH] 토큰 갱신 시작 (Rotation) - token: ...{refresh_token[-20:]}") # 1. 토큰 디코딩 및 검증 payload = decode_token(refresh_token) if payload is None: + logger.warning(f"[AUTH] 토큰 갱신 실패 [1/8 디코딩] - token: ...{refresh_token[-20:]}") raise InvalidTokenError() if payload.get("type") != "refresh": + logger.warning( + f"[AUTH] 토큰 갱신 실패 [1/8 타입] - type={payload.get('type')}, " + f"sub: {payload.get('sub')}" + ) raise InvalidTokenError("리프레시 토큰이 아닙니다.") + logger.debug( + f"[AUTH] 토큰 갱신 [1/8] 디코딩 성공 - sub: {payload.get('sub')}, " + f"exp: {payload.get('exp')}" + ) + # 2. DB에서 리프레시 토큰 조회 token_hash = get_token_hash(refresh_token) db_token = await self._get_refresh_token_by_hash(token_hash, session) if db_token is None: + logger.warning( + f"[AUTH] 토큰 갱신 실패 [2/8 DB조회] - DB에 없음, " + f"token_hash: {token_hash[:16]}..." + ) raise InvalidTokenError() + logger.debug( + f"[AUTH] 토큰 갱신 [2/8] DB 조회 성공 - token_hash: {token_hash[:16]}..., " + f"user_uuid: {db_token.user_uuid}, is_revoked: {db_token.is_revoked}, " + f"expires_at: {db_token.expires_at}" + ) + # 3. 토큰 상태 확인 if db_token.is_revoked: + logger.warning( + f"[AUTH] 토큰 갱신 실패 [3/8 폐기됨] - 이미 폐기된 토큰 (replay attack 의심), " + f"token_hash: {token_hash[:16]}..., user_uuid: {db_token.user_uuid}, " + f"revoked_at: {db_token.revoked_at}" + ) raise TokenRevokedError() + # 4. 만료 확인 if db_token.expires_at < now().replace(tzinfo=None): + logger.info( + f"[AUTH] 토큰 갱신 실패 [4/8 만료] - expires_at: {db_token.expires_at}, " + f"user_uuid: {db_token.user_uuid}" + ) raise TokenExpiredError() - # 4. 사용자 확인 + # 5. 사용자 확인 user_uuid = payload.get("sub") user = await self._get_user_by_uuid(user_uuid, session) if user is None: + logger.warning( + f"[AUTH] 토큰 갱신 실패 [5/8 사용자] - 사용자 미존재, user_uuid: {user_uuid}" + ) raise UserNotFoundError() if not user.is_active: + logger.warning( + f"[AUTH] 토큰 갱신 실패 [5/8 비활성] - user_uuid: {user_uuid}, " + f"user_id: {user.id}" + ) raise UserInactiveError() - # 5. 기존 리프레시 토큰 폐기 (ORM 직접 수정 — _revoke_refresh_token_by_hash는 내부 commit이 있어 사용하지 않음) + # 6. 기존 리프레시 토큰 폐기 (ORM 직접 수정 — _revoke_refresh_token_by_hash는 내부 commit이 있어 사용하지 않음) db_token.is_revoked = True db_token.revoked_at = now().replace(tzinfo=None) + logger.debug(f"[AUTH] 토큰 갱신 [6/8] 기존 토큰 폐기 - token_hash: {token_hash[:16]}...") - # 6. 새 토큰 발급 + # 7. 새 토큰 발급 new_access_token = create_access_token(user.user_uuid) new_refresh_token = create_refresh_token(user.user_uuid) + logger.debug( + f"[AUTH] 토큰 갱신 [7/8] 새 토큰 발급 - new_access: ...{new_access_token[-20:]}, " + f"new_refresh: ...{new_refresh_token[-20:]}" + ) - # 7. 새 리프레시 토큰 DB 저장 (_save_refresh_token은 flush만 수행) + # 8. 새 리프레시 토큰 DB 저장 (_save_refresh_token은 flush만 수행) await self._save_refresh_token( user_id=user.id, user_uuid=user.user_uuid, @@ -257,10 +299,14 @@ class AuthService: session=session, ) - # 8. 폐기 + 저장을 하나의 트랜잭션으로 커밋 + # 폐기 + 저장을 하나의 트랜잭션으로 커밋 await session.commit() - logger.info(f"[AUTH] 토큰 갱신 완료 - user_uuid: {user.user_uuid}") + logger.info( + f"[AUTH] 토큰 갱신 완료 [8/8] - user_uuid: {user.user_uuid}, " + f"user_id: {user.id}, old_hash: {token_hash[:16]}..., " + f"new_refresh: ...{new_refresh_token[-20:]}" + ) return TokenResponse( access_token=new_access_token, @@ -284,7 +330,12 @@ class AuthService: session: DB 세션 """ token_hash = get_token_hash(refresh_token) + logger.info( + f"[AUTH] 로그아웃 - user_id: {user_id}, token_hash: {token_hash[:16]}..., " + f"token: ...{refresh_token[-20:]}" + ) await self._revoke_refresh_token_by_hash(token_hash, session) + logger.info(f"[AUTH] 로그아웃 완료 - user_id: {user_id}") async def logout_all( self, @@ -298,7 +349,9 @@ class AuthService: user_id: 사용자 ID session: DB 세션 """ + logger.info(f"[AUTH] 전체 로그아웃 - user_id: {user_id}") await self._revoke_all_user_tokens(user_id, session) + logger.info(f"[AUTH] 전체 로그아웃 완료 - user_id: {user_id}") async def _get_or_create_user( self, @@ -428,6 +481,11 @@ class AuthService: ) session.add(refresh_token) await session.flush() + + logger.debug( + f"[AUTH] Refresh Token DB 저장 - user_uuid: {user_uuid}, " + f"token_hash: {token_hash[:16]}..., expires_at: {expires_at}" + ) return refresh_token async def _get_refresh_token_by_hash( diff --git a/app/user/services/jwt.py b/app/user/services/jwt.py index ebcf2d6..39f0b5a 100644 --- a/app/user/services/jwt.py +++ b/app/user/services/jwt.py @@ -5,14 +5,18 @@ Access Token과 Refresh Token의 생성, 검증, 해시 기능을 제공합니 """ import hashlib +import logging from datetime import datetime, timedelta from typing import Optional from jose import JWTError, jwt +from jose.exceptions import ExpiredSignatureError, JWTClaimsError from app.utils.timezone import now from config import jwt_settings +logger = logging.getLogger(__name__) + def create_access_token(user_uuid: str) -> str: """ @@ -32,11 +36,16 @@ def create_access_token(user_uuid: str) -> str: "exp": expire, "type": "access", } - return jwt.encode( + token = jwt.encode( to_encode, jwt_settings.JWT_SECRET, algorithm=jwt_settings.JWT_ALGORITHM, ) + logger.debug( + f"[JWT] Access Token 발급 - user_uuid: {user_uuid}, " + f"expires: {expire}, token: ...{token[-20:]}" + ) + return token def create_refresh_token(user_uuid: str) -> str: @@ -57,11 +66,16 @@ def create_refresh_token(user_uuid: str) -> str: "exp": expire, "type": "refresh", } - return jwt.encode( + token = jwt.encode( to_encode, jwt_settings.JWT_SECRET, algorithm=jwt_settings.JWT_ALGORITHM, ) + logger.debug( + f"[JWT] Refresh Token 발급 - user_uuid: {user_uuid}, " + f"expires: {expire}, token: ...{token[-20:]}" + ) + return token def decode_token(token: str) -> Optional[dict]: @@ -80,8 +94,25 @@ def decode_token(token: str) -> Optional[dict]: jwt_settings.JWT_SECRET, algorithms=[jwt_settings.JWT_ALGORITHM], ) + logger.debug( + f"[JWT] 토큰 디코딩 성공 - type: {payload.get('type')}, " + f"sub: {payload.get('sub')}, exp: {payload.get('exp')}, " + f"token: ...{token[-20:]}" + ) return payload - except JWTError: + except ExpiredSignatureError: + logger.info(f"[JWT] 토큰 만료 - token: ...{token[-20:]}") + return None + except JWTClaimsError as e: + logger.warning( + f"[JWT] 클레임 검증 실패 - error: {e}, token: ...{token[-20:]}" + ) + return None + except JWTError as e: + logger.warning( + f"[JWT] 토큰 디코딩 실패 - error: {type(e).__name__}: {e}, " + f"token: ...{token[-20:]}" + ) return None diff --git a/token_log_plan.md b/token_log_plan.md new file mode 100644 index 0000000..b5f0fec --- /dev/null +++ b/token_log_plan.md @@ -0,0 +1,422 @@ +# 서버 JWT 토큰 라이프사이클 로깅 강화 계획 + +## 1. 토큰 라이프사이클 개요 + +서버가 직접 발급/관리하는 JWT 토큰의 전체 흐름: + +``` +[발급] kakao_login() / generate_test_token() + ├── Access Token 생성 (sub=user_uuid, type=access, exp=60분) + ├── Refresh Token 생성 (sub=user_uuid, type=refresh, exp=7일) + └── Refresh Token DB 저장 (token_hash, user_id, expires_at) + │ + ▼ +[검증] get_current_user() — 매 요청마다 Access Token 검증 + ├── Bearer 헤더에서 토큰 추출 + ├── decode_token() → payload (sub, type, exp) + ├── type == "access" 확인 + └── user_uuid로 사용자 조회/활성 확인 + │ + ▼ +[갱신] refresh_tokens() — Access Token 만료 시 Refresh Token으로 갱신 + ├── 기존 Refresh Token 디코딩 → payload + ├── token_hash로 DB 조회 → is_revoked / expires_at 확인 + ├── 기존 Refresh Token 폐기 (is_revoked=True) + ├── 새 Access Token + 새 Refresh Token 발급 + └── 새 Refresh Token DB 저장 + │ + ▼ +[폐기] logout() / logout_all() + ├── 단일: token_hash로 해당 Refresh Token 폐기 + └── 전체: user_id로 모든 Refresh Token 폐기 +``` + +--- + +## 2. 현황 분석 — 로깅 공백 지점 + +### 발급 단계 +| 위치 | 함수 | 현재 로깅 | 부족한 정보 | +|------|------|----------|------------| +| `jwt.py` | `create_access_token()` | 없음 | 발급 대상(user_uuid), 만료시간 | +| `jwt.py` | `create_refresh_token()` | 없음 | 발급 대상(user_uuid), 만료시간 | +| `auth.py` (service) | `_save_refresh_token()` | 없음 | DB 저장 결과(token_hash, expires_at) | +| `auth.py` (service) | `kakao_login()` | `debug`로 토큰 앞 30자 출력 | 충분 (변경 불필요) | + +### 검증 단계 +| 위치 | 함수 | 현재 로깅 | 부족한 정보 | +|------|------|----------|------------| +| `jwt.py` | `decode_token()` | 없음 | 디코딩 성공 시 payload 내용, 실패 시 원인 | +| `auth.py` (dependency) | `get_current_user()` | 없음 | 검증 각 단계 통과/실패 사유, 토큰 내 정보 | +| `auth.py` (dependency) | `get_current_user_optional()` | 없음 | 위와 동일 | + +### 갱신 단계 +| 위치 | 함수 | 현재 로깅 | 부족한 정보 | +|------|------|----------|------------| +| `auth.py` (router) | `refresh_token()` | 없음 | 수신 토큰 정보, 갱신 결과 | +| `auth.py` (service) | `refresh_tokens()` | 진입/완료 `info` 1줄씩 | 각 단계 실패 사유, DB 토큰 상태, 신규 토큰 정보 | + +### 폐기 단계 +| 위치 | 함수 | 현재 로깅 | 부족한 정보 | +|------|------|----------|------------| +| `auth.py` (router) | `logout()`, `logout_all()` | 없음 | 요청 수신, 대상 사용자 | +| `auth.py` (service) | `logout()`, `logout_all()` | 없음 | 폐기 대상, 폐기 결과 | + +--- + +## 3. 수정 대상 파일 + +| # | 파일 | 수정 내용 | +|---|------|----------| +| 1 | `app/user/services/jwt.py` | 토큰 발급 로그 + `decode_token()` 실패 원인 분류 | +| 2 | `app/user/dependencies/auth.py` | Access Token 검증 과정 로깅 | +| 3 | `app/user/services/auth.py` | `refresh_tokens()`, `_save_refresh_token()`, `logout()`, `logout_all()` 로깅 | +| 4 | `app/user/api/routers/v1/auth.py` | `refresh_token()`, `logout()`, `logout_all()` 라우터 로깅 | + +--- + +## 4. 상세 구현 계획 + +### 4-1. `jwt.py` — 토큰 발급 로그 + 디코딩 실패 원인 분류 + +**import 추가:** +```python +import logging +from jose import JWTError, ExpiredSignatureError, JWTClaimsError, jwt + +logger = logging.getLogger(__name__) +``` + +**`create_access_token()` — 발급 로그 추가:** +```python +def create_access_token(user_uuid: str) -> str: + expire = now() + timedelta(minutes=jwt_settings.JWT_ACCESS_TOKEN_EXPIRE_MINUTES) + to_encode = {"sub": user_uuid, "exp": expire, "type": "access"} + token = jwt.encode(to_encode, jwt_settings.JWT_SECRET, algorithm=jwt_settings.JWT_ALGORITHM) + logger.debug(f"[JWT] Access Token 발급 - user_uuid: {user_uuid}, expires: {expire}, token: ...{token[-20:]}") + return token +``` + +**`create_refresh_token()` — 발급 로그 추가:** +```python +def create_refresh_token(user_uuid: str) -> str: + expire = now() + timedelta(days=jwt_settings.JWT_REFRESH_TOKEN_EXPIRE_DAYS) + to_encode = {"sub": user_uuid, "exp": expire, "type": "refresh"} + token = jwt.encode(to_encode, jwt_settings.JWT_SECRET, algorithm=jwt_settings.JWT_ALGORITHM) + logger.debug(f"[JWT] Refresh Token 발급 - user_uuid: {user_uuid}, expires: {expire}, token: ...{token[-20:]}") + return token +``` + +**`decode_token()` — 성공/실패 분류 로그:** +```python +def decode_token(token: str) -> Optional[dict]: + try: + payload = jwt.decode(token, jwt_settings.JWT_SECRET, algorithms=[jwt_settings.JWT_ALGORITHM]) + logger.debug( + f"[JWT] 토큰 디코딩 성공 - type: {payload.get('type')}, " + f"sub: {payload.get('sub')}, exp: {payload.get('exp')}, " + f"token: ...{token[-20:]}" + ) + return payload + except ExpiredSignatureError: + logger.info(f"[JWT] 토큰 만료 - token: ...{token[-20:]}") + return None + except JWTClaimsError as e: + logger.warning(f"[JWT] 클레임 검증 실패 - error: {e}, token: ...{token[-20:]}") + return None + except JWTError as e: + logger.warning(f"[JWT] 토큰 디코딩 실패 - error: {type(e).__name__}: {e}, token: ...{token[-20:]}") + return None +``` + +### 4-2. `dependencies/auth.py` — Access Token 검증 로깅 + +**import 추가:** +```python +import logging +logger = logging.getLogger(__name__) +``` + +**`get_current_user()` — 검증 과정 로그:** +```python +async def get_current_user(...) -> User: + if credentials is None: + logger.info("[AUTH-DEP] 토큰 없음 - MissingTokenError") + raise MissingTokenError() + + token = credentials.credentials + logger.debug(f"[AUTH-DEP] Access Token 검증 시작 - token: ...{token[-20:]}") + + payload = decode_token(token) + if payload is None: + logger.warning(f"[AUTH-DEP] Access Token 디코딩 실패 - token: ...{token[-20:]}") + raise InvalidTokenError() + + if payload.get("type") != "access": + logger.warning(f"[AUTH-DEP] 토큰 타입 불일치 - expected: access, got: {payload.get('type')}, sub: {payload.get('sub')}") + raise InvalidTokenError("액세스 토큰이 아닙니다.") + + user_uuid = payload.get("sub") + if user_uuid is None: + logger.warning(f"[AUTH-DEP] 토큰에 sub 클레임 없음 - token: ...{token[-20:]}") + raise InvalidTokenError() + + # 사용자 조회 + result = await session.execute(...) + user = result.scalar_one_or_none() + + if user is None: + logger.warning(f"[AUTH-DEP] 사용자 미존재 - user_uuid: {user_uuid}") + raise UserNotFoundError() + + if not user.is_active: + logger.warning(f"[AUTH-DEP] 비활성 사용자 접근 - user_uuid: {user_uuid}, user_id: {user.id}") + raise UserInactiveError() + + logger.debug(f"[AUTH-DEP] Access Token 검증 성공 - user_uuid: {user_uuid}, user_id: {user.id}") + return user +``` + +**`get_current_user_optional()` — 동일 패턴, `debug` 레벨:** +```python +async def get_current_user_optional(...) -> Optional[User]: + if credentials is None: + logger.debug("[AUTH-DEP] 선택적 인증 - 토큰 없음") + return None + + token = credentials.credentials + payload = decode_token(token) + if payload is None: + logger.debug(f"[AUTH-DEP] 선택적 인증 - 디코딩 실패, token: ...{token[-20:]}") + return None + + if payload.get("type") != "access": + logger.debug(f"[AUTH-DEP] 선택적 인증 - 타입 불일치 (type={payload.get('type')})") + return None + + user_uuid = payload.get("sub") + if user_uuid is None: + logger.debug("[AUTH-DEP] 선택적 인증 - sub 없음") + return None + + result = await session.execute(...) + user = result.scalar_one_or_none() + + if user is None or not user.is_active: + logger.debug(f"[AUTH-DEP] 선택적 인증 - 사용자 미존재 또는 비활성, user_uuid: {user_uuid}") + return None + + logger.debug(f"[AUTH-DEP] 선택적 인증 성공 - user_uuid: {user_uuid}, user_id: {user.id}") + return user +``` + +### 4-3. `services/auth.py` — Refresh Token 갱신/폐기 로깅 + +**`refresh_tokens()` — 전체 흐름 로그:** +```python +async def refresh_tokens(self, refresh_token: str, session: AsyncSession) -> TokenResponse: + logger.info(f"[AUTH] 토큰 갱신 시작 (Rotation) - token: ...{refresh_token[-20:]}") + + # 1. 디코딩 + payload = decode_token(refresh_token) + if payload is None: + logger.warning(f"[AUTH] 토큰 갱신 실패 [1/8 디코딩] - token: ...{refresh_token[-20:]}") + raise InvalidTokenError() + + if payload.get("type") != "refresh": + logger.warning(f"[AUTH] 토큰 갱신 실패 [1/8 타입] - type={payload.get('type')}, sub: {payload.get('sub')}") + raise InvalidTokenError("리프레시 토큰이 아닙니다.") + + logger.debug(f"[AUTH] 토큰 갱신 [1/8] 디코딩 성공 - sub: {payload.get('sub')}, exp: {payload.get('exp')}") + + # 2. DB 조회 + token_hash = get_token_hash(refresh_token) + db_token = await self._get_refresh_token_by_hash(token_hash, session) + + if db_token is None: + logger.warning(f"[AUTH] 토큰 갱신 실패 [2/8 DB조회] - DB에 없음, token_hash: {token_hash[:16]}...") + raise InvalidTokenError() + + logger.debug(f"[AUTH] 토큰 갱신 [2/8] DB 조회 성공 - token_hash: {token_hash[:16]}..., user_uuid: {db_token.user_uuid}, is_revoked: {db_token.is_revoked}, expires_at: {db_token.expires_at}") + + # 3. 폐기 여부 + if db_token.is_revoked: + logger.warning(f"[AUTH] 토큰 갱신 실패 [3/8 폐기됨] - 이미 폐기된 토큰 (replay attack 의심), token_hash: {token_hash[:16]}..., user_uuid: {db_token.user_uuid}, revoked_at: {db_token.revoked_at}") + raise TokenRevokedError() + + # 4. 만료 확인 + if db_token.expires_at < now().replace(tzinfo=None): + logger.info(f"[AUTH] 토큰 갱신 실패 [4/8 만료] - expires_at: {db_token.expires_at}, user_uuid: {db_token.user_uuid}") + raise TokenExpiredError() + + # 5. 사용자 확인 + user_uuid = payload.get("sub") + user = await self._get_user_by_uuid(user_uuid, session) + + if user is None: + logger.warning(f"[AUTH] 토큰 갱신 실패 [5/8 사용자] - 사용자 미존재, user_uuid: {user_uuid}") + raise UserNotFoundError() + + if not user.is_active: + logger.warning(f"[AUTH] 토큰 갱신 실패 [5/8 비활성] - user_uuid: {user_uuid}, user_id: {user.id}") + raise UserInactiveError() + + # 6. 기존 토큰 폐기 + db_token.is_revoked = True + db_token.revoked_at = now().replace(tzinfo=None) + logger.debug(f"[AUTH] 토큰 갱신 [6/8] 기존 토큰 폐기 - token_hash: {token_hash[:16]}...") + + # 7. 새 토큰 발급 + new_access_token = create_access_token(user.user_uuid) + new_refresh_token = create_refresh_token(user.user_uuid) + logger.debug(f"[AUTH] 토큰 갱신 [7/8] 새 토큰 발급 - new_access: ...{new_access_token[-20:]}, new_refresh: ...{new_refresh_token[-20:]}") + + # 8. 새 Refresh Token DB 저장 + 커밋 + await self._save_refresh_token(user_id=user.id, user_uuid=user.user_uuid, token=new_refresh_token, session=session) + await session.commit() + + logger.info(f"[AUTH] 토큰 갱신 완료 [8/8] - user_uuid: {user.user_uuid}, user_id: {user.id}, old_hash: {token_hash[:16]}..., new_refresh: ...{new_refresh_token[-20:]}") + return TokenResponse(...) +``` + +**`_save_refresh_token()` — DB 저장 로그:** +```python +async def _save_refresh_token(self, ...) -> RefreshToken: + token_hash = get_token_hash(token) + expires_at = get_refresh_token_expires_at() + + refresh_token = RefreshToken(...) + session.add(refresh_token) + await session.flush() + + logger.debug(f"[AUTH] Refresh Token DB 저장 - user_uuid: {user_uuid}, token_hash: {token_hash[:16]}..., expires_at: {expires_at}") + return refresh_token +``` + +**`logout()` — 단일 로그아웃 로그:** +```python +async def logout(self, user_id: int, refresh_token: str, session: AsyncSession) -> None: + token_hash = get_token_hash(refresh_token) + logger.info(f"[AUTH] 로그아웃 - user_id: {user_id}, token_hash: {token_hash[:16]}..., token: ...{refresh_token[-20:]}") + await self._revoke_refresh_token_by_hash(token_hash, session) + logger.info(f"[AUTH] 로그아웃 완료 - user_id: {user_id}") +``` + +**`logout_all()` — 전체 로그아웃 로그:** +```python +async def logout_all(self, user_id: int, session: AsyncSession) -> None: + logger.info(f"[AUTH] 전체 로그아웃 - user_id: {user_id}") + await self._revoke_all_user_tokens(user_id, session) + logger.info(f"[AUTH] 전체 로그아웃 완료 - user_id: {user_id}") +``` + +### 4-4. `routers/v1/auth.py` — 라우터 진입/완료 로깅 + +```python +# POST /auth/refresh +async def refresh_token(body, session) -> TokenResponse: + logger.info(f"[ROUTER] POST /auth/refresh - token: ...{body.refresh_token[-20:]}") + result = await auth_service.refresh_tokens(refresh_token=body.refresh_token, session=session) + logger.info(f"[ROUTER] POST /auth/refresh 완료 - new_access: ...{result.access_token[-20:]}, new_refresh: ...{result.refresh_token[-20:]}") + return result + +# POST /auth/logout +async def logout(body, current_user, session) -> Response: + logger.info(f"[ROUTER] POST /auth/logout - user_id: {current_user.id}, user_uuid: {current_user.user_uuid}, token: ...{body.refresh_token[-20:]}") + await auth_service.logout(user_id=current_user.id, refresh_token=body.refresh_token, session=session) + logger.info(f"[ROUTER] POST /auth/logout 완료 - user_id: {current_user.id}") + return Response(status_code=status.HTTP_204_NO_CONTENT) + +# POST /auth/logout/all +async def logout_all(current_user, session) -> Response: + logger.info(f"[ROUTER] POST /auth/logout/all - user_id: {current_user.id}, user_uuid: {current_user.user_uuid}") + await auth_service.logout_all(user_id=current_user.id, session=session) + logger.info(f"[ROUTER] POST /auth/logout/all 완료 - user_id: {current_user.id}") + return Response(status_code=status.HTTP_204_NO_CONTENT) +``` + +--- + +## 5. 보안 원칙 + +| 원칙 | 적용 방법 | 이유 | +|------|----------|------| +| 토큰 전체 노출 금지 | 뒷 20자만: `...{token[-20:]}` | 토큰 탈취 시 세션 하이재킹 가능 | +| 해시값 부분 노출 | 앞 16자만: `{hash[:16]}...` | DB 레코드 식별에 충분 | +| user_uuid 전체 허용 | 전체 출력 | 내부 식별자, 토큰이 아님 | +| 페이로드 내용 출력 | `sub`, `type`, `exp` 출력 | 디버깅에 필수, 민감정보 아님 | +| DB 토큰 상태 출력 | `is_revoked`, `expires_at`, `revoked_at` | 토큰 라이프사이클 추적 | +| 로그 레벨 구분 | 하단 표 참조 | 운영 환경에서 불필요한 로그 억제 | + +### 로그 레벨 기준 + +| 레벨 | 사용 기준 | 예시 | +|------|----------|------| +| `debug` | 정상 처리 과정 상세 (운영환경에서 비활성) | 토큰 발급, 디코딩 성공, 검증 통과 | +| `info` | 주요 이벤트 (운영환경에서 활성) | 갱신 시작/완료, 로그아웃, 만료로 인한 실패 | +| `warning` | 비정상/의심 상황 | 디코딩 실패, 폐기된 토큰 사용, 사용자 미존재 | + +--- + +## 6. 구현 순서 + +| 순서 | 파일 | 이유 | +|------|------|------| +| 1 | `app/user/services/jwt.py` | 최하위 유틸리티. 토큰 발급/디코딩의 기본 로그 | +| 2 | `app/user/dependencies/auth.py` | 모든 인증 API의 공통 진입점 | +| 3 | `app/user/services/auth.py` | 갱신/폐기 비즈니스 로직 | +| 4 | `app/user/api/routers/v1/auth.py` | 라우터 진입/완료 + 응답 토큰 정보 | + +--- + +## 7. 기대 효과 — 시나리오별 로그 출력 예시 + +### 시나리오 1: 정상 토큰 갱신 +``` +[ROUTER] POST /auth/refresh - token: ...7d90-aac8-ecf1385c +[AUTH] 토큰 갱신 시작 (Rotation) - token: ...7d90-aac8-ecf1385c +[JWT] 토큰 디코딩 성공 - type: refresh, sub: 019c5452-b1cf-7d90-aac8-ecf1385c9dc4, exp: 1739450400 +[AUTH] 토큰 갱신 [1/8] 디코딩 성공 - sub: 019c5452-..., exp: 1739450400 +[AUTH] 토큰 갱신 [2/8] DB 조회 성공 - token_hash: a1b2c3d4e5f6g7h8..., is_revoked: False, expires_at: 2026-02-20 11:46:36 +[AUTH] 토큰 갱신 [6/8] 기존 토큰 폐기 - token_hash: a1b2c3d4e5f6g7h8... +[JWT] Access Token 발급 - user_uuid: 019c5452-..., expires: 2026-02-13 12:46:36 +[JWT] Refresh Token 발급 - user_uuid: 019c5452-..., expires: 2026-02-20 11:46:36 +[AUTH] 토큰 갱신 [7/8] 새 토큰 발급 - new_access: ...xNewAccess12345, new_refresh: ...xNewRefresh6789 +[AUTH] Refresh Token DB 저장 - user_uuid: 019c5452-..., token_hash: f8e9d0c1b2a3..., expires_at: 2026-02-20 11:46:36 +[AUTH] 토큰 갱신 완료 [8/8] - user_uuid: 019c5452-..., user_id: 42, old_hash: a1b2c3d4e5f6g7h8..., new_refresh: ...xNewRefresh6789 +[ROUTER] POST /auth/refresh 완료 - new_access: ...xNewAccess12345, new_refresh: ...xNewRefresh6789 +``` + +### 시나리오 2: 만료된 Refresh Token으로 갱신 시도 +``` +[ROUTER] POST /auth/refresh - token: ...expiredToken12345 +[AUTH] 토큰 갱신 시작 (Rotation) - token: ...expiredToken12345 +[JWT] 토큰 만료 - token: ...expiredToken12345 +[AUTH] 토큰 갱신 실패 [1/8 디코딩] - token: ...expiredToken12345 +→ 401 InvalidTokenError 응답 +``` + +### 시나리오 3: 이미 폐기된 Refresh Token 재사용 (Replay Attack) +``` +[ROUTER] POST /auth/refresh - token: ...revokedToken98765 +[AUTH] 토큰 갱신 시작 (Rotation) - token: ...revokedToken98765 +[JWT] 토큰 디코딩 성공 - type: refresh, sub: 019c5452-..., exp: 1739450400 +[AUTH] 토큰 갱신 [2/8] DB 조회 성공 - token_hash: c3d4e5f6..., is_revoked: True, expires_at: 2026-02-20 +[AUTH] 토큰 갱신 실패 [3/8 폐기됨] - replay attack 의심, token_hash: c3d4e5f6..., user_uuid: 019c5452-..., revoked_at: 2026-02-13 10:30:00 +→ 401 TokenRevokedError 응답 +``` + +### 시나리오 4: Access Token 검증 (매 API 요청) +``` +[AUTH-DEP] Access Token 검증 시작 - token: ...validAccess12345 +[JWT] 토큰 디코딩 성공 - type: access, sub: 019c5452-..., exp: 1739450400 +[AUTH-DEP] Access Token 검증 성공 - user_uuid: 019c5452-..., user_id: 42 +``` + +### 시나리오 5: 로그아웃 +``` +[ROUTER] POST /auth/logout - user_id: 42, user_uuid: 019c5452-..., token: ...refreshToRevoke99 +[AUTH] 로그아웃 - user_id: 42, token_hash: d5e6f7g8..., token: ...refreshToRevoke99 +[AUTH] 로그아웃 완료 - user_id: 42 +[ROUTER] POST /auth/logout 완료 - user_id: 42 +```