# Utils - Shared Utilities and Helpers

## Overview

Centralized utility functions and helpers used across the backend application. Provides logging configuration, authentication utilities, and shared helper functions.

## Purpose

- **Logging Setup**: Centralized logging configuration with rotating file handlers
- **Authentication**: JWT token creation and verification
- **Shared Helpers**: Common utility functions used throughout the application

## Module Structure

```
app/utils/
├── __init__.py          # Package marker
├── logging.py           # Logging configuration (rotating handlers)
└── auth.py              # JWT authentication utilities
```

## Key Components

### 1. Logging Module (`logging.py`)

Configures application-wide logging with both console and file handlers.

#### Features

**Rotating File Handlers**:
- Daily log files: `logs/app_YYYYMMDD.log`
- Max file size: 10MB per file
- Keep last 5 backup files
- Format: `YYYY-MM-DD HH:MM:SS - module.name - LEVEL - message`

**Dual Output**:
- Console (INFO level): For development monitoring
- File (DEBUG level): For detailed debugging

**Noisy Logger Silencing**:
- SQLAlchemy engine: WARNING level only
- Socket.io: INFO level only
- Engine.io: WARNING level only

#### Usage

**Application Startup** (`app/main.py`):
```python
from app.utils.logging import setup_logging

@asynccontextmanager
async def lifespan(app: FastAPI):
    """Startup and shutdown events"""
    logger.info("Starting Paper Dynasty Game Backend")
    setup_logging()  # Configure logging on startup
    await init_db()
    yield
    logger.info("Shutting down Paper Dynasty Game Backend")
```

**Module-Level Loggers** (Standard Pattern):
```python
import logging

# For classes - include class name
logger = logging.getLogger(f'{__name__}.ClassName')

# For modules without classes - just module name
logger = logging.getLogger(f'{__name__}')

# Usage examples
logger.info("User connected")
logger.warning("Invalid request received")
logger.error("Failed to process action", exc_info=True)
logger.debug("Processing state transition")
```

**Logging Pattern Examples Across Codebase**:
```python
# In game_engine.py
logger = logging.getLogger(f'{__name__}.GameEngine')

# In state_manager.py
logger = logging.getLogger(f'{__name__}.StateManager')

# In database operations
logger = logging.getLogger(f'{__name__}.DatabaseOperations')

# In WebSocket handlers
logger = logging.getLogger(f'{__name__}.handlers')

# In API routes
logger = logging.getLogger(f'{__name__}.games')
```

#### Configuration Details

**Log Directory**:
- Location: `backend/logs/` (auto-created)
- Gitignored: Yes
- Naming: `app_YYYYMMDD.log` using Pendulum for UTC timestamps

**Log Levels**:
- Root logger: DEBUG (captures everything)
- Console handler: INFO (important messages only)
- File handler: DEBUG (full detail)
- SQLAlchemy engine: WARNING (reduce noise)
- Socket.io/Engine.io: INFO/WARNING (reduce noise)

**Rotation**:
- Size-based: 10MB max file size
- Time-based: Daily file names with UTC timestamps
- Backup count: Keep 5 most recent files
- Older logs automatically deleted

**Log Format**:
```
2025-10-31 14:23:45 - app.core.game_engine.GameEngine - INFO - Starting new game abc123
2025-10-31 14:23:46 - app.database.operations.DatabaseOperations - DEBUG - Executing query: INSERT INTO games...
2025-10-31 14:23:47 - app.websocket.handlers - ERROR - Connection failed: timeout
```

#### Implementation Details

```python
def setup_logging() -> None:
    """Configure application logging"""

    # Create logs directory
    log_dir = "logs"
    os.makedirs(log_dir, exist_ok=True)

    # Log file name with date (Pendulum for UTC)
    now = pendulum.now('UTC')
    log_file = os.path.join(log_dir, f"app_{now.format('YYYYMMDD')}.log")

    # Formatter (consistent across handlers)
    formatter = logging.Formatter(
        '%(asctime)s - %(name)s - %(levelname)s - %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )

    # Console handler (INFO for development)
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    console_handler.setFormatter(formatter)

    # Rotating file handler (DEBUG for full detail)
    file_handler = logging.handlers.RotatingFileHandler(
        log_file,
        maxBytes=10 * 1024 * 1024,  # 10MB
        backupCount=5
    )
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(formatter)

    # Configure root logger
    root_logger = logging.getLogger()
    root_logger.setLevel(logging.DEBUG)
    root_logger.addHandler(console_handler)
    root_logger.addHandler(file_handler)

    # Silence noisy loggers
    logging.getLogger("sqlalchemy.engine").setLevel(logging.WARNING)
    logging.getLogger("socketio").setLevel(logging.INFO)
    logging.getLogger("engineio").setLevel(logging.WARNING)
```

### 2. Authentication Module (`auth.py`)

JWT token creation and verification for user authentication.

#### Features

**Token Creation**:
- JWT with HS256 algorithm
- 7-day expiration (configurable)
- Embeds arbitrary user data
- Uses Pendulum for UTC timestamps

**Token Verification**:
- Validates signature and expiration
- Returns decoded payload
- Raises `JWTError` on failure

#### Dependencies

```python
from jose import jwt, JWTError  # Python-JOSE library
import pendulum                  # UTC timestamps
from app.config import get_settings  # Secret key from settings
```

#### Usage

**Creating Tokens**:
```python
from app.utils.auth import create_token

# Create token with user data
user_data = {
    "user_id": 123,
    "username": "player1",
    "discord_id": "987654321",
    "league": "sba"
}
token = create_token(user_data)
# Returns: "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9..."
```

**Verifying Tokens**:
```python
from app.utils.auth import verify_token
from jose import JWTError

try:
    payload = verify_token(token)
    user_id = payload["user_id"]
    username = payload["username"]
except JWTError:
    # Token invalid or expired
    return {"error": "Invalid token"}
```

**Integration with Discord OAuth** (`app/api/routes/auth.py`):
```python
from app.utils.auth import create_token

@router.post("/discord/callback")
async def discord_callback(code: str):
    # Exchange code for Discord token
    discord_token = await exchange_code_for_token(code)

    # Get Discord user info
    user_info = await get_discord_user(discord_token)

    # Create JWT for our application
    token = create_token({
        "user_id": user_info["id"],
        "username": user_info["username"],
        "discord_id": user_info["id"]
    })

    return {"token": token}
```

**WebSocket Authentication** (`app/websocket/handlers.py`):
```python
from app.utils.auth import verify_token
from jose import JWTError

@sio.event
async def connect(sid, environ, auth):
    """Authenticate WebSocket connection"""
    try:
        # Verify token from auth dict
        token = auth.get("token")
        if not token:
            raise ConnectionRefusedError("Missing token")

        payload = verify_token(token)

        # Store user info in session
        await sio.save_session(sid, {
            "user_id": payload["user_id"],
            "username": payload["username"]
        })

        logger.info(f"User {payload['username']} connected")
    except JWTError:
        logger.warning("Invalid token on connection attempt")
        raise ConnectionRefusedError("Invalid token")
```

#### Implementation Details

**Token Creation**:
```python
def create_token(user_data: Dict[str, Any]) -> str:
    """
    Create JWT token for user

    Args:
        user_data: User information to encode in token

    Returns:
        JWT token string
    """
    payload = {
        **user_data,
        "exp": pendulum.now('UTC').add(days=7).int_timestamp
    }
    token = jwt.encode(payload, settings.secret_key, algorithm="HS256")
    return token
```

**Token Verification**:
```python
def verify_token(token: str) -> Dict[str, Any]:
    """
    Verify and decode JWT token

    Args:
        token: JWT token string

    Returns:
        Decoded token payload

    Raises:
        JWTError: If token is invalid or expired
    """
    try:
        payload = jwt.decode(token, settings.secret_key, algorithms=["HS256"])
        return payload
    except JWTError as e:
        logger.warning(f"Invalid token: {e}")
        raise
```

**Configuration Requirements** (`.env`):
```bash
# Required for JWT signing
SECRET_KEY=your-secret-key-at-least-32-chars-long
```

## Patterns & Conventions

### Logging Pattern

**Standard Pattern** (Used Throughout Codebase):
```python
import logging

# Module-level logger with class name
logger = logging.getLogger(f'{__name__}.ClassName')

class ClassName:
    def some_method(self):
        logger.info("Method called")
        logger.debug("Processing details...")
        logger.error("Something went wrong", exc_info=True)
```

**Log Level Guidelines**:
- `DEBUG`: Detailed diagnostic information (state changes, query details)
- `INFO`: General informational messages (connections, game events)
- `WARNING`: Warning messages (invalid input, deprecations)
- `ERROR`: Error messages (exceptions, failures)
- `CRITICAL`: Critical failures (system-level issues)

**Exception Logging**:
```python
try:
    # operation
except Exception as e:
    logger.error(f"Operation failed: {e}", exc_info=True)
    raise
```

### Authentication Pattern

**CURRENT: HttpOnly Cookie Auth** (Server-Side OAuth Flow):
```python
# Backend sets cookies with path="/" for SSR compatibility
# See backend/app/utils/cookies.py and COOKIE_AUTH_IMPLEMENTATION.md

response.set_cookie(
    key="pd_access_token",
    value=access_token,
    httponly=True,
    secure=is_production(),
    samesite="lax",
    path="/",  # CRITICAL: Must be "/" not "/api" for SSR
)
```

**Frontend API Calls** (use `credentials: 'include'`):
```typescript
// Browser automatically sends cookies
const response = await $fetch('/api/games/', {
  credentials: 'include',
})
```

**SSR Cookie Forwarding** (Nuxt middleware must forward cookies):
```typescript
if (import.meta.server) {
  const event = useRequestEvent()
  headers['Cookie'] = event?.node.req.headers.cookie
}
```

**WebSocket Auth** (cookies sent automatically with same-origin):
```typescript
// Socket.io connects with cookies (same-origin)
const socket = io(wsUrl, {
  withCredentials: true,  // Send cookies
})
```

**LEGACY: Token in HTTP Headers** (no longer used for web frontend):
```python
# Only used for API clients that can't use cookies
headers = {
    "Authorization": f"Bearer {token}"
}
```

**FastAPI Dependency**:
```python
from fastapi import Depends, HTTPException, Header
from app.utils.auth import verify_token
from jose import JWTError

async def get_current_user(authorization: str = Header(None)):
    """Extract and verify user from Bearer token"""
    if not authorization or not authorization.startswith("Bearer "):
        raise HTTPException(401, "Missing or invalid authorization header")

    token = authorization.split(" ")[1]
    try:
        payload = verify_token(token)
        return payload
    except JWTError:
        raise HTTPException(401, "Invalid or expired token")

# Use in routes
@router.get("/protected")
async def protected_route(user = Depends(get_current_user)):
    return {"user_id": user["user_id"]}
```

## Integration Points

### Application Startup

**main.py** - Initialize logging on application startup:
```python
from app.utils.logging import setup_logging

@asynccontextmanager
async def lifespan(app: FastAPI):
    logger.info("Starting application")
    setup_logging()  # Must be called early
    await init_db()
    yield
    logger.info("Shutting down")
```

### Module Initialization

**Every Module with Logging**:
```python
import logging

logger = logging.getLogger(f'{__name__}.ClassName')
```

**Modules Using Auth**:
```python
from app.utils.auth import create_token, verify_token
from jose import JWTError
```

### WebSocket Handlers

**Connection Authentication**:
```python
from app.utils.auth import verify_token

@sio.event
async def connect(sid, environ, auth):
    token = auth.get("token")
    payload = verify_token(token)  # Raises JWTError if invalid
    # Store session data
```

### API Routes

**Protected Endpoints**:
```python
from app.utils.auth import verify_token

@router.get("/games")
async def get_games(authorization: str = Header(None)):
    token = authorization.split(" ")[1]
    user = verify_token(token)
    # Use user data
```

## Common Tasks

### Adding a New Utility Module

1. **Create Module File**:
```bash
touch app/utils/new_utility.py
```

2. **Implement Utility Functions**:
```python
# app/utils/new_utility.py
import logging

logger = logging.getLogger(f'{__name__}.NewUtility')

def utility_function(param: str) -> str:
    """
    Utility function description

    Args:
        param: Parameter description

    Returns:
        Return value description
    """
    logger.debug(f"Processing {param}")
    result = process(param)
    return result
```

3. **Export from __init__.py** (if needed for public API):
```python
# app/utils/__init__.py
from .logging import setup_logging
from .auth import create_token, verify_token
from .new_utility import utility_function

__all__ = [
    "setup_logging",
    "create_token",
    "verify_token",
    "utility_function"
]
```

4. **Add Tests**:
```python
# tests/unit/utils/test_new_utility.py
import pytest
from app.utils.new_utility import utility_function

def test_utility_function():
    result = utility_function("test")
    assert result == "expected"
```

### Modifying Logging Configuration

**Change Log Level**:
```python
# In setup_logging()
console_handler.setLevel(logging.DEBUG)  # Was INFO
```

**Add Custom Handler**:
```python
# In setup_logging()
# Add email handler for critical errors
from logging.handlers import SMTPHandler

email_handler = SMTPHandler(
    mailhost=("smtp.example.com", 587),
    fromaddr="alerts@example.com",
    toaddrs=["admin@example.com"],
    subject="Critical Error in Game Backend"
)
email_handler.setLevel(logging.CRITICAL)
email_handler.setFormatter(formatter)
root_logger.addHandler(email_handler)
```

**Change Rotation Policy**:
```python
# In setup_logging()
file_handler = logging.handlers.RotatingFileHandler(
    log_file,
    maxBytes=50 * 1024 * 1024,  # Change to 50MB
    backupCount=10              # Keep 10 backups
)
```

### Changing Token Expiration

**Modify create_token()**:
```python
# In auth.py
def create_token(user_data: Dict[str, Any]) -> str:
    payload = {
        **user_data,
        "exp": pendulum.now('UTC').add(days=30).int_timestamp  # 30 days instead of 7
    }
    token = jwt.encode(payload, settings.secret_key, algorithm="HS256")
    return token
```

### Adding Token Refresh

**Create refresh_token() utility**:
```python
# In auth.py
def refresh_token(old_token: str) -> str:
    """
    Refresh an existing token with new expiration

    Args:
        old_token: Existing valid token

    Returns:
        New token with extended expiration

    Raises:
        JWTError: If old token is invalid
    """
    # Verify old token
    payload = verify_token(old_token)

    # Remove old expiration
    payload.pop("exp", None)

    # Create new token
    return create_token(payload)
```

## Troubleshooting

### Logging Issues

**Problem**: No logs appearing
- **Check**: `setup_logging()` called in `main.py` lifespan?
- **Check**: `logs/` directory exists and is writable?
- **Check**: Using correct logger pattern: `logger = logging.getLogger(f'{__name__}.ClassName')`?

**Problem**: Too much SQLAlchemy noise in logs
- **Solution**: Already silenced in `setup_logging()` - check if being called
- **Alternative**: Increase SQLAlchemy logger level:
```python
logging.getLogger("sqlalchemy.engine").setLevel(logging.ERROR)
```

**Problem**: Logs not rotating
- **Check**: File size exceeding 10MB?
- **Check**: `RotatingFileHandler` configured correctly?
- **Debug**: Check `logs/` directory for backup files (`app_YYYYMMDD.log.1`, `.2`, etc.)

**Problem**: Daily log files not working
- **Solution**: Files are daily-named but don't auto-switch at midnight
- **Enhancement**: Use `TimedRotatingFileHandler` for true daily rotation:
```python
file_handler = logging.handlers.TimedRotatingFileHandler(
    "logs/app.log",
    when="midnight",
    interval=1,
    backupCount=30  # Keep 30 days
)
```

### Authentication Issues

**Problem**: `JWTError: Invalid token`
- **Check**: Token copied correctly (no whitespace)?
- **Check**: Token not expired (7-day limit)?
- **Check**: `SECRET_KEY` same on creation and verification?
- **Check**: Using correct algorithm (HS256)?

**Problem**: `ImportError: cannot import name 'jwt' from 'jose'`
- **Solution**: Install python-jose: `pip install python-jose[cryptography]`

**Problem**: Tokens working in Postman but not browser
- **Check**: CORS settings in `config.py`
- **Check**: Browser sending `Authorization: Bearer <token>` header?
- **Check**: Token not being stripped by middleware?

**Problem**: WebSocket auth failing
- **Check**: Token in `auth` object, not headers
- **Client Code**:
```javascript
const socket = io("http://localhost:8000", {
    auth: {
        token: "YOUR_TOKEN_HERE"
    }
});
```

### Pendulum Date Issues

**Problem**: `AttributeError: 'DateTime' object has no attribute 'int_timestamp'`
- **Check**: Using Pendulum 3.0+?
- **Solution**: `int_timestamp` is Pendulum 3.0 feature
- **Alternative** (Pendulum 2.x):
```python
"exp": int(pendulum.now('UTC').add(days=7).timestamp())
```

## Security Considerations

### JWT Security

**Secret Key Requirements**:
- Minimum 32 characters
- Cryptographically random
- Never commit to git
- Rotate periodically

**Generate Secure Key**:
```bash
# Using Python
python -c "import secrets; print(secrets.token_urlsafe(32))"

# Using OpenSSL
openssl rand -base64 32
```

**Token Best Practices**:
- Always use HTTPS in production (tokens visible in HTTP)
- Short expiration times (7 days or less)
- Implement refresh token flow for long-lived sessions
- Never log token values
- Validate all claims on decode

### Logging Security

**Never Log**:
- Passwords or secrets
- Complete JWT tokens
- Database credentials
- API keys
- User personal information

**Safe Logging**:
```python
# ❌ DON'T
logger.info(f"User logged in with token: {token}")

# ✅ DO
logger.info(f"User {user_id} logged in")
logger.debug(f"Token prefix: {token[:10]}...")
```

**Log Sanitization**:
```python
def sanitize_for_log(data: dict) -> dict:
    """Remove sensitive fields before logging"""
    sensitive_keys = ["password", "token", "secret", "api_key"]
    return {k: "***" if k in sensitive_keys else v for k, v in data.items()}

logger.info(f"Request data: {sanitize_for_log(request_data)}")
```

## Testing

### Unit Tests for Utilities

**Test Structure**:
```
tests/unit/utils/
├── test_logging.py      # Logging configuration tests
└── test_auth.py         # JWT creation/verification tests
```

**Example: Testing Token Creation**:
```python
# tests/unit/utils/test_auth.py
import pytest
from app.utils.auth import create_token, verify_token
from jose import JWTError

def test_create_token():
    """Test JWT token creation"""
    user_data = {"user_id": 123, "username": "test"}
    token = create_token(user_data)

    assert token is not None
    assert isinstance(token, str)
    assert len(token) > 0

def test_verify_token_valid():
    """Test verifying valid token"""
    user_data = {"user_id": 123, "username": "test"}
    token = create_token(user_data)

    payload = verify_token(token)
    assert payload["user_id"] == 123
    assert payload["username"] == "test"
    assert "exp" in payload

def test_verify_token_invalid():
    """Test verifying invalid token"""
    with pytest.raises(JWTError):
        verify_token("invalid.token.here")

def test_token_expiration():
    """Test token expiration"""
    # Would need to mock time or wait 7 days
    # Use freezegun or similar for time-based tests
    pass
```

**Example: Testing Logging Setup**:
```python
# tests/unit/utils/test_logging.py
import pytest
import logging
import os
from app.utils.logging import setup_logging

def test_setup_logging_creates_directory(tmp_path, monkeypatch):
    """Test that setup_logging creates logs directory"""
    monkeypatch.chdir(tmp_path)
    setup_logging()
    assert os.path.exists("logs")

def test_setup_logging_configures_handlers():
    """Test that handlers are configured"""
    setup_logging()
    root_logger = logging.getLogger()

    assert len(root_logger.handlers) >= 2
    assert any(isinstance(h, logging.StreamHandler) for h in root_logger.handlers)
    assert any(isinstance(h, logging.handlers.RotatingFileHandler) for h in root_logger.handlers)

def test_setup_logging_sets_levels():
    """Test that log levels are set correctly"""
    setup_logging()

    assert logging.getLogger("sqlalchemy.engine").level == logging.WARNING
    assert logging.getLogger("socketio").level == logging.INFO
    assert logging.getLogger("engineio").level == logging.WARNING
```

## Examples

### Complete Authentication Flow

```python
# 1. User logs in via Discord OAuth
@router.post("/auth/discord/callback")
async def discord_callback(code: str):
    # Exchange code for Discord access token
    discord_token = await exchange_discord_code(code)

    # Get Discord user info
    user_info = await get_discord_user(discord_token)

    # Create our JWT token
    token = create_token({
        "user_id": user_info["id"],
        "username": user_info["username"],
        "discriminator": user_info["discriminator"]
    })

    return {"token": token}

# 2. Client stores token and uses for API calls
# Client code (JavaScript):
# localStorage.setItem("token", response.token)

# 3. Client connects to WebSocket with token
@sio.event
async def connect(sid, environ, auth):
    try:
        token = auth.get("token")
        payload = verify_token(token)

        await sio.save_session(sid, {
            "user_id": payload["user_id"],
            "username": payload["username"]
        })

        logger.info(f"User {payload['username']} connected")
    except JWTError:
        raise ConnectionRefusedError("Invalid token")

# 4. Client makes authenticated API requests
@router.get("/games/my-games")
async def get_my_games(authorization: str = Header(None)):
    if not authorization:
        raise HTTPException(401, "Missing authorization")

    token = authorization.replace("Bearer ", "")
    payload = verify_token(token)

    user_id = payload["user_id"]
    games = await db.get_games_for_user(user_id)
    return games
```

### Custom Logger with Context

```python
import logging
from contextvars import ContextVar

# Context variable for request ID
request_id_var: ContextVar[str] = ContextVar("request_id", default="")

class ContextFilter(logging.Filter):
    """Add request ID to log records"""
    def filter(self, record):
        record.request_id = request_id_var.get()
        return True

def setup_logging():
    """Enhanced logging with request context"""
    # Standard setup...
    formatter = logging.Formatter(
        '%(asctime)s - %(request_id)s - %(name)s - %(levelname)s - %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )

    # Add context filter
    context_filter = ContextFilter()
    console_handler.addFilter(context_filter)
    file_handler.addFilter(context_filter)

    # ... rest of setup

# In middleware/handler
import uuid
from contextvars import ContextVar

@app.middleware("http")
async def request_id_middleware(request, call_next):
    request_id = str(uuid.uuid4())
    request_id_var.set(request_id)
    response = await call_next(request)
    return response

# Now all logs in that request context include request_id
```

## Performance Considerations

### Logging Performance

**Avoid String Formatting Before Logging**:
```python
# ❌ DON'T - always formats even if not logged
logger.debug("Processing: " + expensive_operation())

# ✅ DO - only formats if debug enabled
logger.debug("Processing: %s", expensive_operation())

# ✅ ALSO GOOD - f-strings are evaluated lazily in some cases
logger.debug(f"Processing: {expensive_operation()}")  # But still evaluates
```

**Use Lazy Evaluation**:
```python
if logger.isEnabledFor(logging.DEBUG):
    expensive_data = generate_debug_info()
    logger.debug(f"Debug info: {expensive_data}")
```

### Token Verification Performance

**Cache Decoded Tokens** (for repeated verifications):
```python
from functools import lru_cache

@lru_cache(maxsize=1000)
def verify_token_cached(token: str) -> Dict[str, Any]:
    """Cached token verification (use with caution)"""
    return verify_token(token)

# Clear cache periodically or on logout
verify_token_cached.cache_clear()
```

**Note**: Be careful with caching - can't invalidate specific tokens, and cache may return expired tokens if not cleared.

## Related Documentation

- **Main Backend CLAUDE.md**: `../CLAUDE.md` - Application architecture
- **Config Module**: `../config/CLAUDE.md` - Settings and configuration
- **WebSocket Module**: `../websocket/CLAUDE.md` - WebSocket integration
- **API Routes**: `../api/routes/CLAUDE.md` - REST endpoint patterns

---

**Key Principles**:
1. **Centralized Logging**: All logging configuration in one place
2. **Consistent Patterns**: Use `f'{__name__}.ClassName'` everywhere
3. **Security First**: Never log sensitive data, use strong secret keys
4. **Simple Utilities**: Small, focused, reusable functions
5. **Type Safety**: Full type hints on all public functions

**Testing**: All utilities should have comprehensive unit tests covering normal and edge cases.