From 1298bd235f64cacb15ba4955e26a3515da0ae241 Mon Sep 17 00:00:00 2001 From: Lars Date: Fri, 20 Mar 2026 22:18:12 +0100 Subject: [PATCH] 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 --- backend/feature_logger.py | 76 ++++++++++++++++++++++++++++++++ backend/routers/activity.py | 3 ++ backend/routers/caliper.py | 3 ++ backend/routers/circumference.py | 3 ++ backend/routers/exportdata.py | 7 +++ backend/routers/importdata.py | 3 ++ backend/routers/insights.py | 9 +++- backend/routers/nutrition.py | 3 ++ backend/routers/photos.py | 3 ++ backend/routers/weight.py | 6 +++ 10 files changed, 115 insertions(+), 1 deletion(-) create mode 100644 backend/feature_logger.py diff --git a/backend/feature_logger.py b/backend/feature_logger.py new file mode 100644 index 0000000..7698397 --- /dev/null +++ b/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)) diff --git a/backend/routers/activity.py b/backend/routers/activity.py index 5a1c012..2eb4889 100644 --- a/backend/routers/activity.py +++ b/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: " diff --git a/backend/routers/caliper.py b/backend/routers/caliper.py index 72037eb..6b0e1c2 100644 --- a/backend/routers/caliper.py +++ b/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: " diff --git a/backend/routers/circumference.py b/backend/routers/circumference.py index 90beea9..bca2a14 100644 --- a/backend/routers/circumference.py +++ b/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: " diff --git a/backend/routers/exportdata.py b/backend/routers/exportdata.py index 47a1dd5..fb32326 100644 --- a/backend/routers/exportdata.py +++ b/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: " diff --git a/backend/routers/importdata.py b/backend/routers/importdata.py index 1b572ab..75a3d41 100644 --- a/backend/routers/importdata.py +++ b/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: " diff --git a/backend/routers/insights.py b/backend/routers/insights.py index f4f11e4..aaba665 100644 --- a/backend/routers/insights.py +++ b/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) diff --git a/backend/routers/nutrition.py b/backend/routers/nutrition.py index f6b89aa..4b6af1a 100644 --- a/backend/routers/nutrition.py +++ b/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: " diff --git a/backend/routers/photos.py b/backend/routers/photos.py index 32778ac..6570f8a 100644 --- a/backend/routers/photos.py +++ b/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: " diff --git a/backend/routers/weight.py b/backend/routers/weight.py index 44ef971..414bd8b 100644 --- a/backend/routers/weight.py +++ b/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: "