feat: Add detailed IndieAuth logging with security-aware token redaction
- 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>
This commit is contained in:
842
docs/decisions/ADR-018-indieauth-detailed-logging.md
Normal file
842
docs/decisions/ADR-018-indieauth-detailed-logging.md
Normal file
@@ -0,0 +1,842 @@
|
||||
# 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)
|
||||
Reference in New Issue
Block a user