o2o-castad-backend/token_log_plan.md

423 lines
19 KiB
Markdown

# 서버 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
```