- Add logging helper functions with automatic token redaction - Implement comprehensive logging throughout auth flow - Add production warning for DEBUG logging - Add 14 new tests for logging functionality - Update version to v0.7.0 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
843 lines
27 KiB
Markdown
843 lines
27 KiB
Markdown
# ADR-018: IndieAuth Detailed Logging Strategy
|
|
|
|
## Status
|
|
|
|
Accepted
|
|
|
|
## Context
|
|
|
|
StarPunk uses IndieLogin.com as a delegated IndieAuth provider for admin authentication. During development and production deployments, authentication issues can be difficult to debug because we lack visibility into the OAuth flow between StarPunk and IndieLogin.com.
|
|
|
|
### Authentication Flow Overview
|
|
|
|
The IndieAuth flow involves multiple HTTP requests:
|
|
|
|
1. **Authorization Request**: Browser redirects user to IndieLogin.com
|
|
2. **User Authentication**: IndieLogin.com verifies user identity
|
|
3. **Callback**: IndieLogin.com redirects back to StarPunk with authorization code
|
|
4. **Token Exchange**: StarPunk exchanges code for verified identity via POST to IndieLogin.com
|
|
5. **Session Creation**: StarPunk creates local session
|
|
|
|
### Current Logging Limitations
|
|
|
|
The current implementation (starpunk/auth.py) has minimal logging:
|
|
- Line 194: `current_app.logger.info(f"Auth initiated for {me_url}")`
|
|
- Line 232: `current_app.logger.error(f"IndieLogin request failed: {e}")`
|
|
- Line 235: `current_app.logger.error(f"IndieLogin returned error: {e}")`
|
|
- Line 299: `current_app.logger.info(f"Session created for {me}")`
|
|
|
|
**Problems**:
|
|
- No visibility into HTTP request/response details
|
|
- Cannot see what is being sent to IndieLogin.com
|
|
- Cannot see what IndieLogin.com responds with
|
|
- Difficult to debug state token issues
|
|
- Hard to troubleshoot OAuth flow problems
|
|
|
|
### Use Cases for Detailed Logging
|
|
|
|
1. **Debugging Authentication Failures**: See exact error responses from IndieLogin.com
|
|
2. **Verifying Request Format**: Ensure parameters are correctly formatted
|
|
3. **State Token Debugging**: Track state token lifecycle
|
|
4. **Production Troubleshooting**: Diagnose issues without exposing sensitive data
|
|
5. **Compliance Verification**: Confirm IndieAuth spec compliance
|
|
|
|
## Decision
|
|
|
|
**Implement structured, security-aware logging for IndieAuth authentication flows**
|
|
|
|
We will add detailed logging to the authentication module that captures HTTP requests and responses while protecting sensitive data through automatic redaction.
|
|
|
|
### Logging Architecture
|
|
|
|
#### 1. Log Level Strategy
|
|
|
|
```
|
|
DEBUG: Verbose HTTP details (requests, responses, headers, bodies)
|
|
INFO: Authentication flow milestones (initiate, callback, session created)
|
|
WARNING: Suspicious activity (unauthorized attempts, invalid states)
|
|
ERROR: Authentication failures and exceptions
|
|
```
|
|
|
|
#### 2. Configuration-Based Control
|
|
|
|
Logging verbosity controlled via `LOG_LEVEL` environment variable:
|
|
- `LOG_LEVEL=DEBUG`: Full HTTP request/response logging with redaction
|
|
- `LOG_LEVEL=INFO`: Flow milestones only (default)
|
|
- `LOG_LEVEL=WARNING`: Only warnings and errors
|
|
- `LOG_LEVEL=ERROR`: Only errors
|
|
|
|
#### 3. Security-First Design
|
|
|
|
**Automatic Redaction**:
|
|
- Authorization codes: Show first 6 and last 4 characters only
|
|
- State tokens: Show first 8 and last 4 characters only
|
|
- Session tokens: Never log (already hashed before storage)
|
|
- Authorization headers: Redact token values
|
|
|
|
**Production Warning**:
|
|
- Log clear warning if DEBUG logging enabled in production
|
|
- Recommend INFO level for production environments
|
|
|
|
### Implementation Specification
|
|
|
|
#### Files to Modify
|
|
|
|
1. **starpunk/auth.py** - Add logging to authentication functions
|
|
2. **starpunk/config.py** - Already has LOG_LEVEL configuration (line 58)
|
|
3. **starpunk/app.py** - Configure logger based on LOG_LEVEL (if not already done)
|
|
|
|
#### Where to Add Logging
|
|
|
|
**Function: `initiate_login(me_url: str)` (lines 148-196)**
|
|
- After line 163: DEBUG log validated URL
|
|
- After line 166: DEBUG log generated state token (redacted)
|
|
- After line 191: DEBUG log full authorization URL being constructed
|
|
- Before line 194: DEBUG log redirect URI and parameters
|
|
|
|
**Function: `handle_callback(code: str, state: str)` (lines 199-258)**
|
|
- After line 216: DEBUG log state token verification (redacted tokens)
|
|
- Before line 221: DEBUG log token exchange request preparation
|
|
- After line 229: DEBUG log complete HTTP request to IndieLogin.com
|
|
- After line 239: DEBUG log complete HTTP response from IndieLogin.com
|
|
- After line 240: DEBUG log parsed identity (me URL)
|
|
- After line 246: INFO log admin verification check
|
|
|
|
**Function: `create_session(me: str)` (lines 261-301)**
|
|
- After line 272: DEBUG log session token generation (do NOT log plaintext)
|
|
- After line 277: DEBUG log session expiry calculation
|
|
- After line 280: DEBUG log request metadata (IP, user agent)
|
|
|
|
#### Logging Helper Functions
|
|
|
|
Add these helper functions to starpunk/auth.py:
|
|
|
|
```python
|
|
def _redact_token(token: str, prefix_len: int = 6, suffix_len: int = 4) -> str:
|
|
"""
|
|
Redact sensitive token for logging
|
|
|
|
Shows first N and last M characters with asterisks in between.
|
|
|
|
Args:
|
|
token: Token to redact
|
|
prefix_len: Number of characters to show at start
|
|
suffix_len: Number of characters to show at end
|
|
|
|
Returns:
|
|
Redacted token string like "abc123...****...xyz9"
|
|
"""
|
|
if not token or len(token) <= (prefix_len + suffix_len):
|
|
return "***REDACTED***"
|
|
|
|
return f"{token[:prefix_len]}...{'*' * 8}...{token[-suffix_len:]}"
|
|
|
|
|
|
def _log_http_request(method: str, url: str, data: dict, headers: dict = None) -> None:
|
|
"""
|
|
Log HTTP request details at DEBUG level
|
|
|
|
Automatically redacts sensitive parameters (code, state, authorization)
|
|
|
|
Args:
|
|
method: HTTP method (GET, POST, etc.)
|
|
url: Request URL
|
|
data: Request data/parameters
|
|
headers: Optional request headers
|
|
"""
|
|
if not current_app.logger.isEnabledFor(logging.DEBUG):
|
|
return
|
|
|
|
# Redact sensitive data
|
|
safe_data = data.copy()
|
|
if 'code' in safe_data:
|
|
safe_data['code'] = _redact_token(safe_data['code'])
|
|
if 'state' in safe_data:
|
|
safe_data['state'] = _redact_token(safe_data['state'], 8, 4)
|
|
|
|
current_app.logger.debug(
|
|
f"IndieAuth HTTP Request:\n"
|
|
f" Method: {method}\n"
|
|
f" URL: {url}\n"
|
|
f" Data: {safe_data}"
|
|
)
|
|
|
|
if headers:
|
|
safe_headers = {k: v for k, v in headers.items()
|
|
if k.lower() not in ['authorization', 'cookie']}
|
|
current_app.logger.debug(f" Headers: {safe_headers}")
|
|
|
|
|
|
def _log_http_response(status_code: int, headers: dict, body: str) -> None:
|
|
"""
|
|
Log HTTP response details at DEBUG level
|
|
|
|
Automatically redacts sensitive response data
|
|
|
|
Args:
|
|
status_code: HTTP status code
|
|
headers: Response headers
|
|
body: Response body (JSON string or text)
|
|
"""
|
|
if not current_app.logger.isEnabledFor(logging.DEBUG):
|
|
return
|
|
|
|
# Parse and redact JSON body if present
|
|
safe_body = body
|
|
try:
|
|
import json
|
|
data = json.loads(body)
|
|
if 'access_token' in data:
|
|
data['access_token'] = _redact_token(data['access_token'])
|
|
if 'code' in data:
|
|
data['code'] = _redact_token(data['code'])
|
|
safe_body = json.dumps(data, indent=2)
|
|
except (json.JSONDecodeError, TypeError):
|
|
# Not JSON or parsing failed, log as-is (likely error message)
|
|
pass
|
|
|
|
# Redact sensitive headers
|
|
safe_headers = {k: v for k, v in headers.items()
|
|
if k.lower() not in ['set-cookie', 'authorization']}
|
|
|
|
current_app.logger.debug(
|
|
f"IndieAuth HTTP Response:\n"
|
|
f" Status: {status_code}\n"
|
|
f" Headers: {safe_headers}\n"
|
|
f" Body: {safe_body}"
|
|
)
|
|
```
|
|
|
|
#### Integration with httpx Requests
|
|
|
|
Modify the token exchange in `handle_callback()` (lines 221-236):
|
|
|
|
```python
|
|
# Before making request
|
|
_log_http_request(
|
|
method="POST",
|
|
url=f"{current_app.config['INDIELOGIN_URL']}/auth",
|
|
data={
|
|
"code": code,
|
|
"client_id": current_app.config["SITE_URL"],
|
|
"redirect_uri": f"{current_app.config['SITE_URL']}/auth/callback",
|
|
}
|
|
)
|
|
|
|
# Exchange code for identity
|
|
try:
|
|
response = httpx.post(
|
|
f"{current_app.config['INDIELOGIN_URL']}/auth",
|
|
data={
|
|
"code": code,
|
|
"client_id": current_app.config["SITE_URL"],
|
|
"redirect_uri": f"{current_app.config['SITE_URL']}/auth/callback",
|
|
},
|
|
timeout=10.0,
|
|
)
|
|
|
|
# Log response
|
|
_log_http_response(
|
|
status_code=response.status_code,
|
|
headers=dict(response.headers),
|
|
body=response.text
|
|
)
|
|
|
|
response.raise_for_status()
|
|
except httpx.RequestError as e:
|
|
current_app.logger.error(f"IndieLogin request failed: {e}")
|
|
raise IndieLoginError(f"Failed to verify code: {e}")
|
|
```
|
|
|
|
### Log Message Formats
|
|
|
|
#### DEBUG Level Examples
|
|
|
|
```
|
|
DEBUG - Auth: Validating me URL: https://example.com
|
|
DEBUG - Auth: Generated state token: a1b2c3d4...********...xyz9
|
|
DEBUG - Auth: Building authorization URL with params: {
|
|
'me': 'https://example.com',
|
|
'client_id': 'https://starpunk.example.com',
|
|
'redirect_uri': 'https://starpunk.example.com/auth/callback',
|
|
'state': 'a1b2c3d4...********...xyz9',
|
|
'response_type': 'code'
|
|
}
|
|
DEBUG - Auth: IndieAuth HTTP Request:
|
|
Method: POST
|
|
URL: https://indielogin.com/auth
|
|
Data: {
|
|
'code': 'abc123...********...def9',
|
|
'client_id': 'https://starpunk.example.com',
|
|
'redirect_uri': 'https://starpunk.example.com/auth/callback'
|
|
}
|
|
DEBUG - Auth: IndieAuth HTTP Response:
|
|
Status: 200
|
|
Headers: {'content-type': 'application/json', 'content-length': '42'}
|
|
Body: {
|
|
"me": "https://example.com"
|
|
}
|
|
```
|
|
|
|
#### INFO Level Examples
|
|
|
|
```
|
|
INFO - Auth: Authentication initiated for https://example.com
|
|
INFO - Auth: Verifying admin authorization for me=https://example.com
|
|
INFO - Auth: Session created for https://example.com
|
|
```
|
|
|
|
#### WARNING Level Examples
|
|
|
|
```
|
|
WARNING - Auth: Unauthorized login attempt: https://unauthorized.example.com (expected https://authorized.example.com)
|
|
WARNING - Auth: Invalid state token received (possible CSRF or expired token)
|
|
WARNING - Auth: Multiple failed authentication attempts from IP 192.168.1.100
|
|
```
|
|
|
|
#### ERROR Level Examples
|
|
|
|
```
|
|
ERROR - Auth: IndieLogin request failed: Connection timeout
|
|
ERROR - Auth: IndieLogin returned error: 400
|
|
ERROR - Auth: Invalid state error: Invalid or expired state token
|
|
```
|
|
|
|
### Configuration Approach
|
|
|
|
#### Environment Variable
|
|
|
|
Already implemented in config.py (line 58):
|
|
```python
|
|
app.config["LOG_LEVEL"] = os.getenv("LOG_LEVEL", "INFO")
|
|
```
|
|
|
|
#### Logger Configuration
|
|
|
|
Add to starpunk/app.py (or wherever Flask app is initialized):
|
|
|
|
```python
|
|
import logging
|
|
|
|
def configure_logging(app):
|
|
"""Configure application logging based on LOG_LEVEL"""
|
|
log_level = app.config.get("LOG_LEVEL", "INFO").upper()
|
|
|
|
# Set Flask logger level
|
|
app.logger.setLevel(getattr(logging, log_level, logging.INFO))
|
|
|
|
# Configure handler with detailed format for DEBUG
|
|
handler = logging.StreamHandler()
|
|
|
|
if log_level == "DEBUG":
|
|
formatter = logging.Formatter(
|
|
'[%(asctime)s] %(levelname)s - %(name)s: %(message)s',
|
|
datefmt='%Y-%m-%d %H:%M:%S'
|
|
)
|
|
|
|
# Warn if DEBUG enabled in production
|
|
if not app.debug and app.config.get("ENV") != "development":
|
|
app.logger.warning(
|
|
"=" * 70 + "\n"
|
|
"WARNING: DEBUG logging enabled in production!\n"
|
|
"This logs detailed HTTP requests/responses.\n"
|
|
"Sensitive data is redacted, but consider using INFO level.\n"
|
|
"Set LOG_LEVEL=INFO in production for normal operation.\n"
|
|
+ "=" * 70
|
|
)
|
|
else:
|
|
formatter = logging.Formatter(
|
|
'[%(asctime)s] %(levelname)s: %(message)s',
|
|
datefmt='%Y-%m-%d %H:%M:%S'
|
|
)
|
|
|
|
handler.setFormatter(formatter)
|
|
app.logger.addHandler(handler)
|
|
```
|
|
|
|
### Security Safeguards
|
|
|
|
#### 1. Automatic Redaction
|
|
- All logging helper functions redact sensitive data by default
|
|
- No way to log unredacted tokens (by design)
|
|
- Redaction applies even at DEBUG level
|
|
|
|
#### 2. Production Warning
|
|
- Clear warning logged if DEBUG enabled in non-development environment
|
|
- Recommends INFO level for production
|
|
- Does not prevent DEBUG (allows troubleshooting), just warns
|
|
|
|
#### 3. Minimal Data Exposure
|
|
- Only log what is necessary for debugging
|
|
- Prefer logging outcomes over raw data
|
|
- Session tokens never logged in plaintext (always hashed)
|
|
|
|
#### 4. Structured Logging
|
|
- Consistent format makes parsing easier
|
|
- Clear prefixes identify auth-related logs
|
|
- Machine-readable for log aggregation tools
|
|
|
|
#### 5. Level-Based Control
|
|
- DEBUG: Maximum visibility (development/troubleshooting)
|
|
- INFO: Normal operation (production default)
|
|
- WARNING: Security events only
|
|
- ERROR: Failures only
|
|
|
|
## Rationale
|
|
|
|
### Why This Approach?
|
|
|
|
**Simplicity Score: 8/10**
|
|
- Uses Python's built-in logging module
|
|
- No additional dependencies
|
|
- Helper functions are straightforward
|
|
- Configuration via single environment variable
|
|
|
|
**Fitness Score: 10/10**
|
|
- Solves exact problem: debugging IndieAuth flows
|
|
- Security-aware by design (automatic redaction)
|
|
- Developer-friendly output format
|
|
- Production-safe with appropriate configuration
|
|
|
|
**Maintenance Score: 9/10**
|
|
- Standard Python logging patterns
|
|
- Self-contained helper functions
|
|
- No external logging services required
|
|
- Easy to extend for future needs
|
|
|
|
**Standards Compliance: Pass**
|
|
- Follows Python logging best practices
|
|
- Compatible with standard log aggregation tools
|
|
- No proprietary logging formats
|
|
- OWASP-compliant sensitive data handling
|
|
|
|
### Why Redaction Over Disabling?
|
|
|
|
We choose to redact sensitive data rather than completely disable logging because:
|
|
|
|
1. **Partial visibility is valuable**: Seeing token prefixes/suffixes helps identify which token is being used
|
|
2. **Format verification**: Can verify tokens are properly formatted without seeing full value
|
|
3. **Troubleshooting**: Can track token lifecycle through redacted values
|
|
4. **Safe default**: Developers can enable DEBUG without accidentally exposing secrets
|
|
|
|
### Why Not Use External Logging Service?
|
|
|
|
For V1, we explicitly reject external logging services (Sentry, LogRocket, etc.) because:
|
|
|
|
1. **Simplicity**: Adds dependency and complexity
|
|
2. **Privacy**: Sends data to third-party service
|
|
3. **Self-hosting**: Violates principle of self-contained system
|
|
4. **Unnecessary**: Standard logging sufficient for single-user system
|
|
|
|
This could be reconsidered for V2 if needed.
|
|
|
|
## Consequences
|
|
|
|
### Positive
|
|
|
|
1. ✅ **Debuggability**: Easy to diagnose IndieAuth issues
|
|
2. ✅ **Security-Aware**: Automatic redaction prevents accidental exposure
|
|
3. ✅ **Configurable**: Single environment variable controls verbosity
|
|
4. ✅ **Production-Safe**: INFO level appropriate for production
|
|
5. ✅ **No Dependencies**: Uses built-in Python logging
|
|
6. ✅ **Developer-Friendly**: Clear, readable log output
|
|
7. ✅ **Standards-Compliant**: Follows logging best practices
|
|
8. ✅ **Maintainable**: Simple helper functions, easy to extend
|
|
|
|
### Negative
|
|
|
|
1. ⚠️ **Log Volume**: DEBUG level produces significant output
|
|
- Mitigation: Use INFO level in production, DEBUG only for troubleshooting
|
|
2. ⚠️ **Performance**: String formatting has minor overhead
|
|
- Mitigation: Logging helpers check if DEBUG enabled before formatting
|
|
3. ⚠️ **Partial Visibility**: Redaction means full tokens not visible
|
|
- Mitigation: Intentional trade-off for security; redacted portions still useful
|
|
|
|
### Neutral
|
|
|
|
1. **Storage Requirements**: DEBUG logs require more disk space
|
|
- Expected: Temporary DEBUG usage for troubleshooting only
|
|
- Production INFO logs are minimal
|
|
|
|
2. **Learning Curve**: Developers must understand log levels
|
|
- Documented in configuration and inline comments
|
|
- Standard Python logging concepts
|
|
|
|
## Examples
|
|
|
|
### Example 1: Successful Authentication Flow (DEBUG)
|
|
|
|
```
|
|
[2025-11-19 14:30:00] DEBUG - Auth: Validating me URL: https://thesatelliteoflove.com
|
|
[2025-11-19 14:30:00] DEBUG - Auth: Generated state token: a1b2c3d4...********...wxyz
|
|
[2025-11-19 14:30:00] DEBUG - Auth: Building authorization URL with params: {
|
|
'me': 'https://thesatelliteoflove.com',
|
|
'client_id': 'https://starpunk.thesatelliteoflove.com',
|
|
'redirect_uri': 'https://starpunk.thesatelliteoflove.com/auth/callback',
|
|
'state': 'a1b2c3d4...********...wxyz',
|
|
'response_type': 'code'
|
|
}
|
|
[2025-11-19 14:30:00] INFO - Auth: Authentication initiated for https://thesatelliteoflove.com
|
|
[2025-11-19 14:30:15] DEBUG - Auth: Verifying state token: a1b2c3d4...********...wxyz
|
|
[2025-11-19 14:30:15] DEBUG - Auth: State token valid and consumed
|
|
[2025-11-19 14:30:15] DEBUG - Auth: IndieAuth HTTP Request:
|
|
Method: POST
|
|
URL: https://indielogin.com/auth
|
|
Data: {
|
|
'code': 'xyz789...********...abc1',
|
|
'client_id': 'https://starpunk.thesatelliteoflove.com',
|
|
'redirect_uri': 'https://starpunk.thesatelliteoflove.com/auth/callback'
|
|
}
|
|
[2025-11-19 14:30:16] DEBUG - Auth: IndieAuth HTTP Response:
|
|
Status: 200
|
|
Headers: {
|
|
'content-type': 'application/json',
|
|
'content-length': '52'
|
|
}
|
|
Body: {
|
|
"me": "https://thesatelliteoflove.com"
|
|
}
|
|
[2025-11-19 14:30:16] DEBUG - Auth: Received identity from IndieLogin: https://thesatelliteoflove.com
|
|
[2025-11-19 14:30:16] INFO - Auth: Verifying admin authorization for me=https://thesatelliteoflove.com
|
|
[2025-11-19 14:30:16] DEBUG - Auth: Admin verification passed
|
|
[2025-11-19 14:30:16] DEBUG - Auth: Session token generated (hash will be stored)
|
|
[2025-11-19 14:30:16] DEBUG - Auth: Session expiry: 2025-12-19 14:30:16 (30 days)
|
|
[2025-11-19 14:30:16] DEBUG - Auth: Request metadata - IP: 192.168.1.100, User-Agent: Mozilla/5.0...
|
|
[2025-11-19 14:30:16] INFO - Auth: Session created for https://thesatelliteoflove.com
|
|
```
|
|
|
|
### Example 2: Failed Authentication (INFO Level)
|
|
|
|
```
|
|
[2025-11-19 14:35:00] INFO - Auth: Authentication initiated for https://unauthorized.example.com
|
|
[2025-11-19 14:35:15] WARNING - Auth: Unauthorized login attempt: https://unauthorized.example.com (expected https://thesatelliteoflove.com)
|
|
```
|
|
|
|
### Example 3: IndieLogin Service Error (DEBUG)
|
|
|
|
```
|
|
[2025-11-19 14:40:00] INFO - Auth: Authentication initiated for https://thesatelliteoflove.com
|
|
[2025-11-19 14:40:15] DEBUG - Auth: Verifying state token: def456...********...ghi9
|
|
[2025-11-19 14:40:15] DEBUG - Auth: State token valid and consumed
|
|
[2025-11-19 14:40:15] DEBUG - Auth: IndieAuth HTTP Request:
|
|
Method: POST
|
|
URL: https://indielogin.com/auth
|
|
Data: {
|
|
'code': 'pqr789...********...stu1',
|
|
'client_id': 'https://starpunk.thesatelliteoflove.com',
|
|
'redirect_uri': 'https://starpunk.thesatelliteoflove.com/auth/callback'
|
|
}
|
|
[2025-11-19 14:40:16] DEBUG - Auth: IndieAuth HTTP Response:
|
|
Status: 400
|
|
Headers: {
|
|
'content-type': 'application/json',
|
|
'content-length': '78'
|
|
}
|
|
Body: {
|
|
"error": "invalid_grant",
|
|
"error_description": "The authorization code is invalid or has expired"
|
|
}
|
|
[2025-11-19 14:40:16] ERROR - Auth: IndieLogin returned error: 400
|
|
```
|
|
|
|
## Testing Strategy
|
|
|
|
### Unit Tests
|
|
|
|
Add to `tests/test_auth.py`:
|
|
|
|
```python
|
|
def test_redact_token():
|
|
"""Test token redaction for logging"""
|
|
from starpunk.auth import _redact_token
|
|
|
|
# Normal token
|
|
assert _redact_token("abcdefghijklmnop", 6, 4) == "abcdef...********...mnop"
|
|
|
|
# Short token (fully redacted)
|
|
assert _redact_token("short", 6, 4) == "***REDACTED***"
|
|
|
|
# Empty token
|
|
assert _redact_token("", 6, 4) == "***REDACTED***"
|
|
|
|
|
|
def test_log_http_request_redacts_code(caplog):
|
|
"""Test that code parameter is redacted in request logs"""
|
|
import logging
|
|
from starpunk.auth import _log_http_request
|
|
|
|
with caplog.at_level(logging.DEBUG):
|
|
_log_http_request(
|
|
method="POST",
|
|
url="https://indielogin.com/auth",
|
|
data={"code": "sensitive_code_12345"}
|
|
)
|
|
|
|
# Should log but with redacted code
|
|
assert "sensitive_code_12345" not in caplog.text
|
|
assert "sensit...********...2345" in caplog.text
|
|
|
|
|
|
def test_log_http_response_redacts_tokens(caplog):
|
|
"""Test that response tokens are redacted"""
|
|
import logging
|
|
from starpunk.auth import _log_http_response
|
|
|
|
with caplog.at_level(logging.DEBUG):
|
|
_log_http_response(
|
|
status_code=200,
|
|
headers={"content-type": "application/json"},
|
|
body='{"access_token": "secret_token_xyz789"}'
|
|
)
|
|
|
|
# Should log but with redacted token
|
|
assert "secret_token_xyz789" not in caplog.text
|
|
assert "secret...********...x789" in caplog.text
|
|
```
|
|
|
|
### Integration Tests
|
|
|
|
Add to `tests/test_auth_integration.py`:
|
|
|
|
```python
|
|
def test_auth_flow_logging_at_debug(client, app, caplog):
|
|
"""Test that DEBUG logging captures full auth flow"""
|
|
import logging
|
|
|
|
# Set DEBUG logging
|
|
app.logger.setLevel(logging.DEBUG)
|
|
|
|
with caplog.at_level(logging.DEBUG):
|
|
# Initiate authentication
|
|
response = client.post('/admin/login', data={'me': 'https://example.com'})
|
|
|
|
# Should see DEBUG logs
|
|
assert "Validating me URL" in caplog.text
|
|
assert "Generated state token" in caplog.text
|
|
assert "Building authorization URL" in caplog.text
|
|
|
|
# Should NOT see full token values
|
|
assert any(
|
|
"...********..." in record.message
|
|
for record in caplog.records
|
|
if "state token" in record.message
|
|
)
|
|
|
|
|
|
def test_auth_flow_logging_at_info(client, app, caplog):
|
|
"""Test that INFO logging only shows milestones"""
|
|
import logging
|
|
|
|
# Set INFO logging
|
|
app.logger.setLevel(logging.INFO)
|
|
|
|
with caplog.at_level(logging.INFO):
|
|
# Initiate authentication
|
|
response = client.post('/admin/login', data={'me': 'https://example.com'})
|
|
|
|
# Should see INFO milestone
|
|
assert "Authentication initiated" in caplog.text
|
|
|
|
# Should NOT see DEBUG details
|
|
assert "Generated state token" not in caplog.text
|
|
assert "Building authorization URL" not in caplog.text
|
|
```
|
|
|
|
### Manual Testing
|
|
|
|
1. **Enable DEBUG Logging**:
|
|
```bash
|
|
export LOG_LEVEL=DEBUG
|
|
uv run flask run
|
|
```
|
|
|
|
2. **Attempt Authentication**:
|
|
- Go to `/admin/login`
|
|
- Enter your URL
|
|
- Observe console output
|
|
|
|
3. **Verify Logging**:
|
|
- ✅ State token is redacted
|
|
- ✅ Authorization code is redacted
|
|
- ✅ HTTP request details visible
|
|
- ✅ HTTP response details visible
|
|
- ✅ Identity (me URL) visible
|
|
- ✅ No plaintext session tokens
|
|
|
|
4. **Test Production Mode**:
|
|
```bash
|
|
export LOG_LEVEL=INFO
|
|
export FLASK_ENV=production
|
|
uv run flask run
|
|
```
|
|
- ✅ Warning appears if DEBUG was enabled
|
|
- ✅ Only milestone logs appear
|
|
- ✅ No HTTP details logged
|
|
|
|
## Alternatives Considered
|
|
|
|
### Alternative 1: No Redaction (Rejected)
|
|
|
|
**Approach**: Log everything including full tokens
|
|
|
|
**Rejected Because**:
|
|
- Security risk: Tokens in logs could be compromised
|
|
- OWASP violation: Sensitive data in logs
|
|
- Production unsafe: Cannot enable DEBUG safely
|
|
- Risk of accidental exposure if logs shared
|
|
|
|
### Alternative 2: Complete Disabling at DEBUG (Rejected)
|
|
|
|
**Approach**: Don't log sensitive data at all, even redacted
|
|
|
|
**Rejected Because**:
|
|
- Loses debugging value: Cannot track token lifecycle
|
|
- Harder to troubleshoot: No visibility into requests/responses
|
|
- Format issues invisible: Cannot verify parameter format
|
|
- Redaction provides good balance
|
|
|
|
### Alternative 3: External Logging Service (Rejected)
|
|
|
|
**Approach**: Use Sentry, LogRocket, or similar service
|
|
|
|
**Rejected Because**:
|
|
- Violates simplicity: Additional dependency
|
|
- Privacy concern: Data sent to third party
|
|
- Self-hosting principle: Requires external service
|
|
- Unnecessary complexity: Built-in logging sufficient
|
|
- Cost: Most services require payment
|
|
|
|
### Alternative 4: Separate Debug Module (Rejected)
|
|
|
|
**Approach**: Create separate debugging module that must be explicitly imported
|
|
|
|
**Rejected Because**:
|
|
- Extra complexity: Additional module to maintain
|
|
- Friction: Developer must remember to import
|
|
- Configuration better: Environment variable is simpler
|
|
- Built-in logging: Python logging module is standard
|
|
|
|
### Alternative 5: Conditional Compilation (Rejected)
|
|
|
|
**Approach**: Use environment variable to enable/disable debug code at startup
|
|
|
|
**Rejected Because**:
|
|
- Inflexible: Cannot change without restart
|
|
- Complexity: Conditional code paths
|
|
- Python idiom: Log level checking is standard pattern
|
|
- Testing harder: Multiple code paths to test
|
|
|
|
## Migration Path
|
|
|
|
No migration required:
|
|
- No database changes
|
|
- No configuration changes required (LOG_LEVEL already optional)
|
|
- Backward compatible: Existing code continues working
|
|
- Purely additive: New logging functions added
|
|
|
|
### Deployment Steps
|
|
|
|
1. Deploy updated code with logging helpers
|
|
2. Existing systems continue with INFO logging (default)
|
|
3. Enable DEBUG logging when troubleshooting needed
|
|
4. No restart required to change log level (if using dynamic config)
|
|
|
|
## Future Considerations
|
|
|
|
### V2 Potential Enhancements
|
|
|
|
1. **Structured JSON Logging**: Machine-readable format for log aggregation
|
|
2. **Request ID Tracking**: Trace requests across multiple log entries
|
|
3. **Performance Metrics**: Log timing for each auth step
|
|
4. **Log Rotation**: Automatic log file management
|
|
5. **Audit Trail**: Separate audit log for security events
|
|
6. **OpenTelemetry**: Distributed tracing support
|
|
|
|
### Logging Best Practices for Future Development
|
|
|
|
1. **Consistent Prefixes**: All auth logs start with "Auth:"
|
|
2. **Action-Oriented Messages**: Use verbs (Validating, Generated, Verifying)
|
|
3. **Context Included**: Include relevant identifiers (URLs, IPs)
|
|
4. **Error Details**: Include exception messages and stack traces
|
|
5. **Security Events**: Log all authentication attempts (success and failure)
|
|
|
|
## Compliance
|
|
|
|
### Security Standards
|
|
|
|
- ✅ OWASP Logging Cheat Sheet: Sensitive data redaction
|
|
- ✅ GDPR: No unnecessary PII in logs (IP addresses justified for security)
|
|
- ✅ OAuth 2.0 Security: Token redaction in logs
|
|
- ✅ IndieAuth Spec: No spec requirements violated by logging
|
|
|
|
### Project Standards
|
|
|
|
- ✅ ADR-001: No additional dependencies (uses built-in logging)
|
|
- ✅ "Every line of code must justify its existence": Logging justified for debugging
|
|
- ✅ Standards-first approach: Python logging standards followed
|
|
- ✅ Security-first: Automatic redaction protects sensitive data
|
|
|
|
## Configuration Documentation
|
|
|
|
### Environment Variables
|
|
|
|
```bash
|
|
# Logging configuration
|
|
LOG_LEVEL=INFO # Options: DEBUG, INFO, WARNING, ERROR (default: INFO)
|
|
|
|
# For development/troubleshooting
|
|
LOG_LEVEL=DEBUG # Enable detailed HTTP logging
|
|
|
|
# For production (recommended)
|
|
LOG_LEVEL=INFO # Standard operation logging
|
|
```
|
|
|
|
### Recommended Settings
|
|
|
|
**Development**:
|
|
```bash
|
|
LOG_LEVEL=DEBUG
|
|
```
|
|
|
|
**Staging**:
|
|
```bash
|
|
LOG_LEVEL=INFO
|
|
```
|
|
|
|
**Production**:
|
|
```bash
|
|
LOG_LEVEL=INFO
|
|
```
|
|
|
|
**Troubleshooting Production Issues**:
|
|
```bash
|
|
LOG_LEVEL=DEBUG
|
|
# Temporarily enable for debugging, then revert to INFO
|
|
```
|
|
|
|
## References
|
|
|
|
- [Python Logging Documentation](https://docs.python.org/3/library/logging.html)
|
|
- [OWASP Logging Cheat Sheet](https://cheatsheetseries.owasp.org/cheatsheets/Logging_Cheat_Sheet.html)
|
|
- [OAuth 2.0 Security Best Current Practice](https://datatracker.ietf.org/doc/html/draft-ietf-oauth-security-topics)
|
|
- [IndieAuth Specification](https://indieauth.spec.indieweb.org/)
|
|
- [Flask Logging Documentation](https://flask.palletsprojects.com/en/3.0.x/logging/)
|
|
|
|
## Related Documents
|
|
|
|
- ADR-005: IndieLogin Authentication (`docs/decisions/ADR-005-indielogin-authentication.md`)
|
|
- ADR-010: Authentication Module Design (`docs/decisions/ADR-010-authentication-module-design.md`)
|
|
- ADR-016: IndieAuth Client Discovery (`docs/decisions/ADR-016-indieauth-client-discovery.md`)
|
|
|
|
## Version Impact
|
|
|
|
**Classification**: Enhancement
|
|
**Version Increment**: Minor (v0.X.0 → v0.X+1.0)
|
|
**Reason**: New debugging capability, backward compatible, no breaking changes
|
|
|
|
---
|
|
|
|
**Decided**: 2025-11-19
|
|
**Author**: StarPunk Architect Agent
|
|
**Supersedes**: None
|
|
**Superseded By**: None (current)
|