feat: add structured JSON logging for all feature usage (Phase 2)

- Create feature_logger.py with JSON logging infrastructure
- Add log_feature_usage() calls to all 9 routers after check_feature_access()
- Logs written to /app/logs/feature-usage.log
- Tracks all usage (not just violations) for future analysis
- Phase 2: Non-blocking monitoring complete

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

backend/feature_logger.py

@@ -0,0 +1,76 @@
+"""
+Feature Usage Logger for Mitai Jinkendo
+
+Logs all feature access checks to a separate JSON log file for analysis.
+Phase 2: Non-blocking monitoring of feature usage.
+"""
+import logging
+import json
+from datetime import datetime
+from pathlib import Path
+
+
+# ── Setup Feature Usage Logger ───────────────────────────────────────────────
+feature_usage_logger = logging.getLogger('feature_usage')
+feature_usage_logger.setLevel(logging.INFO)
+feature_usage_logger.propagate = False  # Don't propagate to root logger
+
+# Ensure logs directory exists
+LOG_DIR = Path('/app/logs')
+LOG_DIR.mkdir(parents=True, exist_ok=True)
+
+# FileHandler for JSON logs
+log_file = LOG_DIR / 'feature-usage.log'
+file_handler = logging.FileHandler(log_file)
+file_handler.setLevel(logging.INFO)
+file_handler.setFormatter(logging.Formatter('%(message)s'))  # JSON only
+feature_usage_logger.addHandler(file_handler)
+
+# Also log to console in dev (optional)
+# console_handler = logging.StreamHandler()
+# console_handler.setFormatter(logging.Formatter('[FEATURE-USAGE] %(message)s'))
+# feature_usage_logger.addHandler(console_handler)
+
+
+# ── Logging Function ──────────────────────────────────────────────────────────
+def log_feature_usage(user_id: str, feature_id: str, access: dict, action: str):
+    """
+    Log feature usage in structured JSON format.
+
+    Args:
+        user_id: Profile UUID
+        feature_id: Feature identifier (e.g., 'weight_entries', 'ai_calls')
+        access: Result from check_feature_access() containing:
+            - allowed: bool
+            - limit: int | None
+            - used: int
+            - remaining: int | None
+            - reason: str
+        action: Type of action (e.g., 'create', 'export', 'analyze')
+
+    Example log entry:
+        {
+            "timestamp": "2026-03-20T15:30:45.123456",
+            "user_id": "abc-123",
+            "feature": "weight_entries",
+            "action": "create",
+            "used": 5,
+            "limit": 100,
+            "remaining": 95,
+            "allowed": true,
+            "reason": "within_limit"
+        }
+    """
+    entry = {
+        "timestamp": datetime.now().isoformat(),
+        "user_id": user_id,
+        "feature": feature_id,
+        "action": action,
+        "used": access.get('used', 0),
+        "limit": access.get('limit'),  # None for unlimited
+        "remaining": access.get('remaining'),  # None for unlimited
+        "allowed": access.get('allowed', True),
+        "reason": access.get('reason', 'unknown')
+    }
+
+    feature_usage_logger.info(json.dumps(entry))

backend/routers/activity.py

@@ -15,6 +15,7 @@ from db import get_db, get_cursor, r2d
 from auth import require_auth, check_feature_access, increment_feature_usage
 from models import ActivityEntry
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/activity", tags=["activity"])
 logger = logging.getLogger(__name__)
@@ -38,6 +39,8 @@ def create_activity(e: ActivityEntry, x_profile_id: Optional[str]=Header(default
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'activity_entries')
+    log_feature_usage(pid, 'activity_entries', access, 'create')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/caliper.py

@@ -13,6 +13,7 @@ from db import get_db, get_cursor, r2d
 from auth import require_auth, check_feature_access, increment_feature_usage
 from models import CaliperEntry
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/caliper", tags=["caliper"])
 logger = logging.getLogger(__name__)
@@ -36,6 +37,8 @@ def upsert_caliper(e: CaliperEntry, x_profile_id: Optional[str]=Header(default=N
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'caliper_entries')
+    log_feature_usage(pid, 'caliper_entries', access, 'create')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/circumference.py

@@ -13,6 +13,7 @@ from db import get_db, get_cursor, r2d
 from auth import require_auth, check_feature_access, increment_feature_usage
 from models import CircumferenceEntry
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/circumferences", tags=["circumference"])
 logger = logging.getLogger(__name__)
@@ -36,6 +37,8 @@ def upsert_circ(e: CircumferenceEntry, x_profile_id: Optional[str]=Header(defaul
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'circumference_entries')
+    log_feature_usage(pid, 'circumference_entries', access, 'create')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/exportdata.py

@@ -20,6 +20,7 @@ from fastapi.responses import StreamingResponse, Response
 from db import get_db, get_cursor, r2d
 from auth import require_auth, check_feature_access, increment_feature_usage
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/export", tags=["export"])
 logger = logging.getLogger(__name__)
@@ -34,6 +35,8 @@ def export_csv(x_profile_id: Optional[str]=Header(default=None), session: dict=D
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'data_export')
+    log_feature_usage(pid, 'data_export', access, 'export_csv')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "
@@ -103,6 +106,8 @@ def export_json(x_profile_id: Optional[str]=Header(default=None), session: dict=
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'data_export')
+    log_feature_usage(pid, 'data_export', access, 'export_json')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "
@@ -167,6 +172,8 @@ def export_zip(x_profile_id: Optional[str]=Header(default=None), session: dict=D
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'data_export')
+    log_feature_usage(pid, 'data_export', access, 'export_zip')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/importdata.py

@@ -19,6 +19,7 @@ from fastapi import APIRouter, HTTPException, UploadFile, File, Header, Depends
 from db import get_db, get_cursor
 from auth import require_auth, check_feature_access, increment_feature_usage
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/import", tags=["import"])
 logger = logging.getLogger(__name__)
@@ -45,6 +46,8 @@ async def import_zip(
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'data_import')
+    log_feature_usage(pid, 'data_import', access, 'import_zip')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/insights.py

@@ -16,6 +16,7 @@ from fastapi import APIRouter, HTTPException, Header, Depends
 from db import get_db, get_cursor, r2d
 from auth import require_auth, require_admin, check_feature_access, increment_feature_usage
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api", tags=["insights"])
 logger = logging.getLogger(__name__)
@@ -256,6 +257,8 @@ async def analyze_with_prompt(slug: str, x_profile_id: Optional[str]=Header(defa
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'ai_calls')
+    log_feature_usage(pid, 'ai_calls', access, 'analyze')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "
@@ -329,6 +332,8 @@ async def analyze_pipeline(x_profile_id: Optional[str]=Header(default=None), ses
 
     # Phase 2: Check pipeline feature access (boolean - enabled/disabled)
     access_pipeline = check_feature_access(pid, 'ai_pipeline')
+    log_feature_usage(pid, 'ai_pipeline', access_pipeline, 'pipeline')
+
     if not access_pipeline['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "
@@ -338,10 +343,12 @@ async def analyze_pipeline(x_profile_id: Optional[str]=Header(default=None), ses
 
     # Also check ai_calls (pipeline uses API calls too)
     access_calls = check_feature_access(pid, 'ai_calls')
+    log_feature_usage(pid, 'ai_calls', access_calls, 'pipeline_calls')
+
     if not access_calls['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "
-            f"ai_calls {access_calls['reason']} (used: {access_calls['used']}, limit: {access_calls['limit']})"
+            f"ai_calls {access_calls['reason']} (used: {access_calls['used']}, limit: {access['limit']})"
         )
 
     # Old check (keep for now)

backend/routers/nutrition.py

@@ -15,6 +15,7 @@ from fastapi import APIRouter, HTTPException, UploadFile, File, Header, Depends
 from db import get_db, get_cursor, r2d
 from auth import require_auth, check_feature_access, increment_feature_usage
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/nutrition", tags=["nutrition"])
 logger = logging.getLogger(__name__)
@@ -36,6 +37,8 @@ async def import_nutrition_csv(file: UploadFile=File(...), x_profile_id: Optiona
     # Phase 2: Check feature access (non-blocking, log only)
     # Note: CSV import can create many entries - we check once before import
     access = check_feature_access(pid, 'nutrition_entries')
+    log_feature_usage(pid, 'nutrition_entries', access, 'import_csv')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/photos.py

@@ -16,6 +16,7 @@ import aiofiles
 from db import get_db, get_cursor, r2d
 from auth import require_auth, require_auth_flexible, check_feature_access, increment_feature_usage
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/photos", tags=["photos"])
 logger = logging.getLogger(__name__)
@@ -32,6 +33,8 @@ async def upload_photo(file: UploadFile=File(...), date: str="",
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'photos')
+    log_feature_usage(pid, 'photos', access, 'upload')
+
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "

backend/routers/weight.py

@@ -13,6 +13,7 @@ from db import get_db, get_cursor, r2d
 from auth import require_auth, check_feature_access, increment_feature_usage
 from models import WeightEntry
 from routers.profiles import get_pid
+from feature_logger import log_feature_usage
 
 router = APIRouter(prefix="/api/weight", tags=["weight"])
 logger = logging.getLogger(__name__)
@@ -36,6 +37,11 @@ def upsert_weight(e: WeightEntry, x_profile_id: Optional[str]=Header(default=Non
 
     # Phase 2: Check feature access (non-blocking, log only)
     access = check_feature_access(pid, 'weight_entries')
+
+    # Structured logging (always)
+    log_feature_usage(pid, 'weight_entries', access, 'create')
+
+    # Warning if limit exceeded (legacy)
     if not access['allowed']:
         logger.warning(
             f"[FEATURE-LIMIT] User {pid} would be blocked: "