From f7c20de5ac90992998e479fae9a9ed7dcf33241f Mon Sep 17 00:00:00 2001 From: jessikitty Date: Sun, 27 Sep 2026 10:42:49 +1000 Subject: [PATCH] Add owner-only logging and Brickset API call tracking LIM configured no logging at all, so the instruction fetcher had no trail to follow. Adds a rotating file handler on the root logger plus two owner-only admin pages. - Admin > Logs: filter by level, source and text; tracebacks kept with their error; auto-refresh, raw download, rotated-file browsing and rotate-now - Admin > Logs > Brickset API calls: every outbound call recorded with method, params, caller, duration, result count and error, plus daily quota accounting (only getSets counts) and a comparison against getKeyUsageStats - New owner concept (services/ownership.py): a single account, distinct from is_admin, since these pages expose other admins activity. Defaults to the first admin; flask owner show/set to change - Services now log through module loggers; retention setting and pruning for call records - New CLI: flask owner show/set, flask logs path/prune - New table brickset_api_calls, created automatically at boot; LOG_* env vars, /data/logs in Docker --- .env.docker.example | 10 + .env.example | 10 + README.md | 5 + app/__init__.py | 16 ++ app/cli.py | 87 ++++++ app/config.py | 11 + app/models/__init__.py | 3 +- app/models/api_call.py | 157 +++++++++++ app/models/site_setting.py | 4 + app/routes/__init__.py | 3 +- app/routes/logs.py | 223 +++++++++++++++ app/services/brickset_api.py | 127 +++++++-- app/services/fetch_worker.py | 12 +- app/services/instruction_fetcher.py | 20 +- app/services/logging_setup.py | 218 +++++++++++++++ app/services/ownership.py | 86 ++++++ app/services/schema_upgrade.py | 5 +- app/templates/admin/brickset_calls.html | 298 +++++++++++++++++++++ app/templates/admin/dashboard.html | 7 + app/templates/admin/instruction_fetch.html | 9 + app/templates/admin/logs.html | 222 +++++++++++++++ app/templates/admin/settings.html | 5 + diagnose_fetcher.py | 228 ++++++++++++++++ docker-compose.yml | 5 + docker/entrypoint.sh | 3 +- docs/LOGGING.md | 145 ++++++++++ install_instruction_fetcher.bat | 30 ++- 27 files changed, 1914 insertions(+), 35 deletions(-) create mode 100644 app/models/api_call.py create mode 100644 app/routes/logs.py create mode 100644 app/services/logging_setup.py create mode 100644 app/services/ownership.py create mode 100644 app/templates/admin/brickset_calls.html create mode 100644 app/templates/admin/logs.html create mode 100644 diagnose_fetcher.py create mode 100644 docs/LOGGING.md diff --git a/.env.docker.example b/.env.docker.example index 9e18170..a7e2e08 100644 --- a/.env.docker.example +++ b/.env.docker.example @@ -34,3 +34,13 @@ INSTRUCTION_FETCH_TICK_SECONDS=20 # Largest instruction PDF to accept, in megabytes. FETCH_MAX_FILE_MB=150 FETCH_TIMEOUT_SECONDS=60 + +# --- logging ---------------------------------------------------------------- +# The admin log viewer (owner only) reads these files. +LOG_FOLDER=/data/logs +LOG_LEVEL=INFO +# Rotate at this size, keeping LOG_BACKUP_COUNT old copies. +LOG_MAX_BYTES=2097152 +LOG_BACKUP_COUNT=5 +# 1 to include per-request access logging (noisy). +LOG_ACCESS=0 diff --git a/.env.example b/.env.example index 2a41740..1424426 100644 --- a/.env.example +++ b/.env.example @@ -38,3 +38,13 @@ INSTRUCTION_FETCH_TICK_SECONDS=20 # Largest instruction PDF to accept, in megabytes. FETCH_MAX_FILE_MB=150 FETCH_TIMEOUT_SECONDS=60 + +# --- logging ---------------------------------------------------------------- +# The admin log viewer (owner only) reads these files. +LOG_FOLDER=logs +LOG_LEVEL=INFO +# Rotate at this size, keeping LOG_BACKUP_COUNT old copies. +LOG_MAX_BYTES=2097152 +LOG_BACKUP_COUNT=5 +# 1 to include per-request access logging (noisy). +LOG_ACCESS=0 diff --git a/README.md b/README.md index 1a65f06..d4c52e4 100644 --- a/README.md +++ b/README.md @@ -18,6 +18,7 @@ A Python web application for organizing and managing your LEGO instruction manua - 🖼️ **Image Gallery**: View instruction images in an organized gallery - 📄 **PDF Support**: View and download PDF instructions directly - 💾 **Backup & Restore**: One-click archive of the database plus every uploaded file, ready to restore anywhere +- 📋 **Logging & API tracking**: Owner-only log viewer and a record of every Brickset call with daily quota accounting — see [docs/LOGGING.md](docs/LOGGING.md) - ⬇️ **Automatic Instruction Fetcher**: Downloads official instruction PDFs from LEGO (found via Brickset) for official sets, one every 10 minutes so nobody's API gets hammered — see [docs/INSTRUCTION_FETCHER.md](docs/INSTRUCTION_FETCHER.md) ## 🚀 Quick Start @@ -188,6 +189,10 @@ flask --app run.py shell - page_number, user_id, uploaded_at - sha256, source (set by the automatic fetcher; null for manual uploads) +### BricksetApiCall +- id, called_at, method, params, context, ok, http_status +- result_count, duration_ms, quota_counted, message, user_id + ### InstructionFetchJob - id, set_id, status, attempts, files_added, source, message - queued_at, not_before, started_at, finished_at, queued_by_id diff --git a/app/__init__.py b/app/__init__.py index 1e8098f..7fec860 100644 --- a/app/__init__.py +++ b/app/__init__.py @@ -19,6 +19,10 @@ def create_app(config_name='default'): # Load configuration app.config.from_object(config[config_name]) + + # Logging first, so anything below can report problems. + from app.services.logging_setup import configure_logging + configure_logging(app) # Initialize extensions db.init_app(app) @@ -48,6 +52,7 @@ def create_app(config_name='default'): from app.routes.moc import bp as moc_bp from app.routes.backup import backup_bp from app.routes.instruction_fetch import instruction_fetch_bp + from app.routes.logs import logs_bp app.register_blueprint(auth_bp) app.register_blueprint(main_bp) @@ -58,6 +63,7 @@ def create_app(config_name='default'): app.register_blueprint(moc_bp) app.register_blueprint(backup_bp) app.register_blueprint(instruction_fetch_bp) + app.register_blueprint(logs_bp) # Import models to ensure they're registered with SQLAlchemy from app.models.user import User @@ -67,6 +73,7 @@ def create_app(config_name='default'): from app.models.set_share import SetShare from app.models.site_setting import SiteSetting from app.models.instruction_fetch import InstructionFetchJob + from app.models.api_call import BricksetApiCall # Add any columns missing from an older database (additive only). if app.config.get('AUTO_SCHEMA_UPGRADE', True): @@ -103,6 +110,15 @@ def create_app(config_name='default'): from app.cli import register_cli register_cli(app) + # Templates need to know whether to show owner-only links. + @app.context_processor + def inject_ownership(): + from app.services.ownership import is_owner + try: + return {'current_user_is_owner': is_owner()} + except Exception: + return {'current_user_is_owner': False} + # Background ticker for the automatic instruction fetcher. It does # nothing at all until an admin enables it on the fetcher page. from app.services import fetch_worker diff --git a/app/cli.py b/app/cli.py index 760d237..f5df27d 100644 --- a/app/cli.py +++ b/app/cli.py @@ -12,6 +12,11 @@ Flask CLI commands for LIM backup and restore. flask instructions run [--count N] [--force] flask instructions status + flask owner show + flask owner set USERNAME + flask logs path [--tail N] + flask logs prune [--days N] + `restore` is the path to use on a fresh Docker instance: no login required, and it works before any admin user exists. @@ -267,6 +272,88 @@ def instructions_status(): f"{summary['sets_missing_pdfs']} without a PDF") +owner_cli = AppGroup('owner', help='Who owns this instance.') + + +@owner_cli.command('show') +def owner_show(): + """Show the owner account (the only one who can read the logs).""" + from app.services.ownership import get_owner + + owner = get_owner() + if owner is None: + click.secho('No users exist yet.', fg='yellow') + return + click.secho(f'Owner: {owner.username} <{owner.email}> (id {owner.id})', + fg='green') + + +@owner_cli.command('set') +@click.argument('username') +def owner_set(username): + """Hand ownership to USERNAME (promotes them to admin if needed).""" + from app.models.user import User + from app.services.ownership import set_owner + + user = User.query.filter_by(username=username).first() + if user is None: + click.secho(f'No user called {username!r}.', fg='red') + raise SystemExit(1) + + set_owner(user) + click.secho(f'{user.username} is now the owner.', fg='green') + + +logs_cli = AppGroup('logs', help='Application log file.') + + +@logs_cli.command('path') +@click.option('--tail', default=0, type=int, + help='Also print the last N lines.') +def logs_path(tail): + """Where the log lives, and optionally its tail.""" + import os + + from flask import current_app + + from app.services import logging_setup + + path = logging_setup.log_path(current_app) + exists = os.path.isfile(path) + click.echo(f' {path}') + click.echo(f' exists: {exists}' + + (f' size: {os.path.getsize(path)} bytes' if exists else '')) + click.echo(f' handler active: {logging_setup.get_handler() is not None}') + + if tail and exists: + entries, total = logging_setup.read_entries(path, max_entries=tail) + click.echo(f'\n last {len(entries)} of {total} entries:\n') + for entry in entries: + click.echo(f" {entry['time']} {entry['level']:<8} " + f"{entry['logger']} | {entry['message']}") + + +@logs_cli.command('prune') +@click.option('--days', default=None, type=int, + help='Override the configured retention.') +def logs_prune(days): + """Delete old Brickset API call records.""" + from app.models.api_call import BricksetApiCall + from app.models.site_setting import SiteSetting + + if days is None: + try: + days = int(SiteSetting.get('api_log_retention_days', '90')) + except (TypeError, ValueError): + days = 90 + + removed = BricksetApiCall.prune(days) + click.secho(f'Removed {removed} record(s) older than {days} days.', + fg='green') + + def register_cli(app): app.cli.add_command(backup_cli) app.cli.add_command(instructions_cli) + app.cli.add_command(owner_cli) + app.cli.add_command(logs_cli) diff --git a/app/config.py b/app/config.py index d2668ef..5b7ba3a 100644 --- a/app/config.py +++ b/app/config.py @@ -59,6 +59,17 @@ class Config: # stream straight to disk and never go through Flask's form parser. BACKUP_MAX_UPLOAD = int(os.environ.get('BACKUP_MAX_UPLOAD', 0)) + # Logging + # Rotating file handler; the admin log viewer reads these files. + # Docker points LOG_FOLDER at the mounted volume (/data/logs). + LOG_FOLDER = _resolve_path(os.environ.get('LOG_FOLDER'), + os.path.join(projectdir, 'logs')) + LOG_LEVEL = os.environ.get('LOG_LEVEL', 'INFO') + LOG_MAX_BYTES = int(os.environ.get('LOG_MAX_BYTES', 2097152)) # 2MB + LOG_BACKUP_COUNT = int(os.environ.get('LOG_BACKUP_COUNT', 5)) + # Per-request access logging is noisy; off unless you ask for it. + LOG_ACCESS = os.environ.get('LOG_ACCESS', '0') == '1' + # Automatic instruction fetcher # Pacing (interval, delays, on/off) lives in site_settings so it can be # changed from the admin page. These are the hard limits and the switch diff --git a/app/models/__init__.py b/app/models/__init__.py index 5c8676f..6cc3530 100644 --- a/app/models/__init__.py +++ b/app/models/__init__.py @@ -5,6 +5,7 @@ from app.models.extra_file import ExtraFile from app.models.set_share import SetShare from app.models.site_setting import SiteSetting from app.models.instruction_fetch import InstructionFetchJob +from app.models.api_call import BricksetApiCall __all__ = ['User', 'Set', 'Instruction', 'ExtraFile', 'SetShare', - 'SiteSetting', 'InstructionFetchJob'] + 'SiteSetting', 'InstructionFetchJob', 'BricksetApiCall'] diff --git a/app/models/api_call.py b/app/models/api_call.py new file mode 100644 index 0000000..46d36ec --- /dev/null +++ b/app/models/api_call.py @@ -0,0 +1,157 @@ +""" +A record of every call LIM makes to the Brickset API. + +Two reasons this exists. First, Brickset's daily key limit applies to getSets +and nothing else, so knowing how many of those went out today is the only +number that matters for staying under it — and Brickset's own +getKeyUsageStats only reports whole days, after the fact. Second, when the +instruction fetcher comes back empty it is useful to see exactly what was +asked and what came back. + +Rows are small and pruned on a retention setting (90 days by default). + +Created by: Jess Rogerson (yelling commands at Claude.AI) +""" + +from datetime import datetime, timedelta + +from app import db + +# The only method that counts against the daily API key quota. +QUOTA_METHODS = {'getSets'} + + +class BricksetApiCall(db.Model): + """One outbound request to brickset.com.""" + + __tablename__ = 'brickset_api_calls' + + id = db.Column(db.Integer, primary_key=True) + called_at = db.Column(db.DateTime, nullable=False, default=datetime.utcnow, + index=True) + + method = db.Column(db.String(40), nullable=False, index=True) + # Short human-readable summary of what was asked, never credentials. + params = db.Column(db.String(300), nullable=True) + # Which part of LIM made the call: fetcher, search, bulk-import, ... + context = db.Column(db.String(40), nullable=True, index=True) + + ok = db.Column(db.Boolean, nullable=False, default=True) + http_status = db.Column(db.Integer, nullable=True) + result_count = db.Column(db.Integer, nullable=True) + duration_ms = db.Column(db.Integer, nullable=True) + quota_counted = db.Column(db.Boolean, nullable=False, default=False, + index=True) + message = db.Column(db.Text, nullable=True) + + user_id = db.Column(db.Integer, db.ForeignKey('users.id'), nullable=True) + user = db.relationship('User', foreign_keys=[user_id]) + + def __repr__(self): + return f'' + + # -- writing ------------------------------------------------------------ + + @classmethod + def record(cls, method, params=None, ok=True, http_status=None, + result_count=None, duration_ms=None, message=None, + context=None, user_id=None): + """ + Log a call. Never raises — a logging failure must not break a fetch. + """ + try: + call = cls( + method=method, + params=(params or '')[:300] or None, + context=(context or '')[:40] or None, + ok=bool(ok), + http_status=http_status, + result_count=result_count, + duration_ms=duration_ms, + quota_counted=method in QUOTA_METHODS, + message=(message or None), + user_id=user_id, + ) + db.session.add(call) + db.session.commit() + return call + except Exception: + try: + db.session.rollback() + except Exception: + pass + return None + + # -- reading ------------------------------------------------------------ + + @classmethod + def stats(cls, days=7): + """Totals for the dashboard at the top of the Brickset log page.""" + from sqlalchemy import func + + now = datetime.utcnow() + midnight = datetime(now.year, now.month, now.day) + since = now - timedelta(days=days) + + def count(query): + return query.scalar() or 0 + + today = db.session.query(func.count(cls.id)).filter( + cls.called_at >= midnight) + today_quota = db.session.query(func.count(cls.id)).filter( + cls.called_at >= midnight, cls.quota_counted.is_(True)) + window = db.session.query(func.count(cls.id)).filter( + cls.called_at >= since) + window_failed = db.session.query(func.count(cls.id)).filter( + cls.called_at >= since, cls.ok.is_(False)) + + by_method = db.session.query( + cls.method, func.count(cls.id), func.avg(cls.duration_ms) + ).filter(cls.called_at >= since).group_by(cls.method).order_by( + func.count(cls.id).desc()).all() + + per_day = db.session.query( + func.date(cls.called_at), func.count(cls.id) + ).filter(cls.called_at >= since, cls.quota_counted.is_(True) + ).group_by(func.date(cls.called_at)).all() + + return { + 'days': days, + 'today': count(today), + 'today_quota': count(today_quota), + 'window': count(window), + 'window_failed': count(window_failed), + 'total': count(db.session.query(func.count(cls.id))), + 'by_method': [ + {'method': method, 'count': number, + 'avg_ms': int(avg) if avg else None} + for method, number, avg in by_method + ], + 'quota_per_day': [ + {'date': str(day), 'count': number} for day, number in per_day + ], + } + + @classmethod + def prune(cls, days=90): + """Delete records older than `days`. Returns how many went.""" + cutoff = datetime.utcnow() - timedelta(days=days) + removed = cls.query.filter(cls.called_at < cutoff).delete( + synchronize_session=False) + db.session.commit() + return removed + + def to_dict(self): + return { + 'id': self.id, + 'called_at': self.called_at.isoformat() if self.called_at else None, + 'method': self.method, + 'params': self.params, + 'context': self.context, + 'ok': self.ok, + 'http_status': self.http_status, + 'result_count': self.result_count, + 'duration_ms': self.duration_ms, + 'quota_counted': self.quota_counted, + 'message': self.message, + } diff --git a/app/models/site_setting.py b/app/models/site_setting.py index e446ac9..3479a1e 100644 --- a/app/models/site_setting.py +++ b/app/models/site_setting.py @@ -32,6 +32,10 @@ DEFAULTS = { 'fetch_skip_sets_with_pdfs': 'true', 'fetch_allow_setid_lookup': 'true', 'fetch_last_run': '', + + # Logging / API call history + 'owner_user_id': '', + 'api_log_retention_days': '90', } VISIBILITIES = ('private', 'shared', 'public') diff --git a/app/routes/__init__.py b/app/routes/__init__.py index b4e1738..a62612a 100644 --- a/app/routes/__init__.py +++ b/app/routes/__init__.py @@ -4,6 +4,7 @@ from app.routes.sets import sets_bp from app.routes.instructions import instructions_bp from app.routes.moc import bp as moc_bp from app.routes.instruction_fetch import instruction_fetch_bp +from app.routes.logs import logs_bp __all__ = ['auth_bp', 'main_bp', 'sets_bp', 'instructions_bp', 'moc_bp', - 'instruction_fetch_bp'] + 'instruction_fetch_bp', 'logs_bp'] diff --git a/app/routes/logs.py b/app/routes/logs.py new file mode 100644 index 0000000..a29b430 --- /dev/null +++ b/app/routes/logs.py @@ -0,0 +1,223 @@ +""" +Owner-only log viewer and Brickset API call history. + +These pages show everything happening inside the instance, including other +admins' activity, so they sit behind owner_required rather than +admin_required. + +Created by: Jess Rogerson (yelling commands at Claude.AI) +""" + +import os + +from flask import (Blueprint, current_app, flash, jsonify, redirect, + render_template, request, send_file, url_for) +from flask_login import login_required + +from app import db +from app.models.api_call import BricksetApiCall +from app.models.site_setting import SiteSetting +from app.services import logging_setup +from app.services.ownership import owner_required + +logs_bp = Blueprint('logs', __name__, url_prefix='/admin/logs') + +DEFAULT_LINES = 300 +MAX_LINES = 2000 + + +def _int_arg(name, default, low, high): + try: + value = int(request.args.get(name, default)) + except (TypeError, ValueError): + value = default + return max(low, min(high, value)) + + +def _retention_days(): + raw = SiteSetting.get('api_log_retention_days', '90') + try: + return max(1, min(3650, int(str(raw).strip()))) + except (TypeError, ValueError): + return 90 + + +# --------------------------------------------------------------------------- +# application log +# --------------------------------------------------------------------------- + +@logs_bp.route('/') +@login_required +@owner_required +def index(): + """Tail of the application log, filtered.""" + level = request.args.get('level', 'INFO') + search = request.args.get('q', '').strip() + source = request.args.get('source', '') + lines = _int_arg('lines', DEFAULT_LINES, 25, MAX_LINES) + filename = request.args.get('file', logging_setup.LOG_FILENAME) + + path = logging_setup.resolve_file(current_app, filename) + entries, total = logging_setup.read_entries( + path, max_entries=lines, level=level, search=search or None, + logger_prefix=source or None) + + files = logging_setup.available_files(current_app) + configured = logging_setup.get_handler() is not None + + return render_template( + 'admin/logs.html', + entries=list(reversed(entries)), # newest first on screen + shown=len(entries), + total=total, + level=level, + search=search, + source=source, + lines=lines, + filename=filename, + files=files, + levels=logging_setup.LEVELS, + configured=configured, + log_path=logging_setup.log_path(current_app), + ) + + +@logs_bp.route('/tail.json') +@login_required +@owner_required +def tail_json(): + """Same data as the page, for auto-refresh.""" + level = request.args.get('level', 'INFO') + search = request.args.get('q', '').strip() + source = request.args.get('source', '') + lines = _int_arg('lines', DEFAULT_LINES, 25, MAX_LINES) + path = logging_setup.resolve_file( + current_app, request.args.get('file', logging_setup.LOG_FILENAME)) + + entries, total = logging_setup.read_entries( + path, max_entries=lines, level=level, search=search or None, + logger_prefix=source or None) + + return jsonify({ + 'entries': list(reversed(entries)), + 'shown': len(entries), + 'total': total, + }) + + +@logs_bp.route('/download') +@login_required +@owner_required +def download(): + path = logging_setup.resolve_file( + current_app, request.args.get('file', logging_setup.LOG_FILENAME)) + if not path: + flash('No such log file.', 'warning') + return redirect(url_for('logs.index')) + return send_file(path, as_attachment=True, + download_name=os.path.basename(path)) + + +@logs_bp.route('/rotate', methods=['POST']) +@login_required +@owner_required +def rotate(): + """Start a fresh log file, keeping the current one as a backup.""" + if logging_setup.rotate_now(): + current_app.logger.info('Log rotated by the owner') + flash('Log rotated — the previous contents are now in lim.log.1.', + 'success') + else: + flash('No file handler is active, so there is nothing to rotate.', + 'warning') + return redirect(url_for('logs.index')) + + +# --------------------------------------------------------------------------- +# Brickset API calls +# --------------------------------------------------------------------------- + +@logs_bp.route('/brickset') +@login_required +@owner_required +def brickset(): + """Every call LIM has made to the Brickset API.""" + days = _int_arg('days', 7, 1, 90) + page = _int_arg('page', 1, 1, 10000) + method = request.args.get('method', '') + only_failed = request.args.get('failed') == '1' + + query = BricksetApiCall.query + if method: + query = query.filter(BricksetApiCall.method == method) + if only_failed: + query = query.filter(BricksetApiCall.ok.is_(False)) + + pagination = query.order_by(BricksetApiCall.id.desc()).paginate( + page=page, per_page=50, error_out=False) + + methods = [row[0] for row in db.session.query( + BricksetApiCall.method).distinct().order_by( + BricksetApiCall.method).all()] + + return render_template( + 'admin/brickset_calls.html', + stats=BricksetApiCall.stats(days), + calls=pagination.items, + pagination=pagination, + days=days, + method=method, + only_failed=only_failed, + methods=methods, + retention_days=_retention_days(), + quota_note=None, + ) + + +@logs_bp.route('/brickset/quota', methods=['POST']) +@login_required +@owner_required +def brickset_quota(): + """ + Ask Brickset what it thinks our usage has been. + + getKeyUsageStats is free — it doesn't count against the quota it reports. + """ + from app.services.brickset_api import BricksetAPI + + if not BricksetAPI.is_configured(): + flash('Brickset credentials are not configured.', 'warning') + return redirect(url_for('logs.brickset')) + + usage = BricksetAPI(context='quota-check').get_key_usage() + if not usage: + flash('Brickset returned no usage data.', 'warning') + else: + recent = ', '.join( + f"{row.get('dateStamp', '?')}: {row.get('count', 0)}" + for row in usage[:7]) + flash(f'Brickset reports (most recent first) — {recent}', 'info') + return redirect(url_for('logs.brickset')) + + +@logs_bp.route('/brickset/retention', methods=['POST']) +@login_required +@owner_required +def brickset_retention(): + try: + days = max(1, min(3650, int(request.form.get('days', 90)))) + except (TypeError, ValueError): + days = 90 + SiteSetting.set('api_log_retention_days', str(days)) + db.session.commit() + flash(f'API call records are now kept for {days} days.', 'success') + return redirect(url_for('logs.brickset')) + + +@logs_bp.route('/brickset/prune', methods=['POST']) +@login_required +@owner_required +def brickset_prune(): + removed = BricksetApiCall.prune(_retention_days()) + flash(f'Removed {removed} old API call record(s).', 'success') + return redirect(url_for('logs.brickset')) diff --git a/app/services/brickset_api.py b/app/services/brickset_api.py index 35baccd..261120d 100644 --- a/app/services/brickset_api.py +++ b/app/services/brickset_api.py @@ -17,10 +17,15 @@ Created by: Jess Rogerson (yelling commands at Claude.AI) """ import json +import logging +import time from typing import Any, Dict, List, Optional import requests -from flask import current_app +from flask import current_app, has_request_context, request +from flask_login import current_user + +logger = logging.getLogger(__name__) class BricksetAPI: @@ -28,11 +33,49 @@ class BricksetAPI: BASE_URL = 'https://brickset.com/api/v3.asmx' - def __init__(self): + def __init__(self, context: Optional[str] = None): self.api_key = current_app.config.get('BRICKSET_API_KEY') self.username = current_app.config.get('BRICKSET_USERNAME') self.password = current_app.config.get('BRICKSET_PASSWORD') self._user_hash = None + # Recorded against every call so the log shows which part of LIM + # was responsible. Falls back to the endpoint name in a request. + self.context = context or self._default_context() + + @staticmethod + def _default_context() -> str: + if has_request_context() and request.endpoint: + return request.endpoint.split('.')[-1][:40] + return 'background' + + def _log_call(self, method, params=None, ok=True, http_status=None, + result_count=None, started=None, message=None): + """Record one call. Never raises.""" + duration = None + if started is not None: + duration = int((time.monotonic() - started) * 1000) + + if ok: + logger.info('Brickset %s (%s) -> %s result(s) in %sms', + method, params or '-', + '?' if result_count is None else result_count, + duration) + else: + logger.warning('Brickset %s (%s) failed: %s', + method, params or '-', message) + + try: + from app.models.api_call import BricksetApiCall + user_id = None + if has_request_context() and getattr(current_user, + 'is_authenticated', False): + user_id = current_user.id + BricksetApiCall.record( + method=method, params=params, ok=ok, http_status=http_status, + result_count=result_count, duration_ms=duration, + message=message, context=self.context, user_id=user_id) + except Exception: + logger.debug('Could not record Brickset call', exc_info=True) @staticmethod def is_configured() -> bool: @@ -52,6 +95,7 @@ class BricksetAPI: current_app.logger.warning('Brickset API credentials not configured') return None + started = time.monotonic() try: response = requests.get( f'{self.BASE_URL}/login', @@ -67,13 +111,19 @@ class BricksetAPI: if data.get('status') == 'success': self._user_hash = data.get('hash') + self._log_call('login', self.username, ok=True, + http_status=response.status_code, + started=started) return self._user_hash - else: - current_app.logger.error(f"Brickset login failed: {data.get('message')}") - return None + + self._log_call('login', self.username, ok=False, + http_status=response.status_code, started=started, + message=str(data.get('message'))) + return None except Exception as e: - current_app.logger.error(f'Brickset API authentication error: {str(e)}') + self._log_call('login', self.username, ok=False, started=started, + message=f'{type(e).__name__}: {e}') return None def search_sets(self, @@ -123,6 +173,9 @@ class BricksetAPI: 'params': json.dumps(search_params), } + summary = json.dumps(search_params, separators=(',', ':')) + started = time.monotonic() + try: response = requests.get( f'{self.BASE_URL}/getSets', @@ -133,10 +186,16 @@ class BricksetAPI: data = response.json() if data.get('status') == 'success': - return data.get('sets', []) + sets = data.get('sets', []) + self._log_call('getSets', summary, ok=True, + http_status=response.status_code, + result_count=len(sets), started=started) + return sets message = data.get('message', 'unknown error') - current_app.logger.error(f'Brickset search failed: {message}') + self._log_call('getSets', summary, ok=False, + http_status=response.status_code, started=started, + message=message) if 'limit exceeded' in message.lower(): raise RuntimeError('Brickset API limit exceeded') return [] @@ -144,7 +203,8 @@ class BricksetAPI: except RuntimeError: raise except Exception as e: - current_app.logger.error(f'Brickset API search error: {str(e)}') + self._log_call('getSets', summary, ok=False, started=started, + message=f'{type(e).__name__}: {e}') return [] def get_set_by_number(self, set_number: str) -> Optional[Dict[str, Any]]: @@ -174,6 +234,7 @@ class BricksetAPI: if not user_hash: return [] + started = time.monotonic() try: response = requests.get( f'{self.BASE_URL}/getThemes', @@ -188,19 +249,31 @@ class BricksetAPI: if data.get('status') == 'success': themes = data.get('themes', []) - return [theme.get('theme') for theme in themes if theme.get('theme')] - else: - return [] + names = [theme.get('theme') for theme in themes + if theme.get('theme')] + self._log_call('getThemes', ok=True, + http_status=response.status_code, + result_count=len(names), started=started) + return names + + self._log_call('getThemes', ok=False, + http_status=response.status_code, started=started, + message=str(data.get('message'))) + return [] except Exception as e: - current_app.logger.error(f'Brickset API themes error: {str(e)}') + self._log_call('getThemes', ok=False, started=started, + message=f'{type(e).__name__}: {e}') return [] # -- instructions ------------------------------------------------------- def _instructions_request(self, method: str, params: Dict[str, Any]) -> List[Dict[str, Any]]: + summary = ', '.join(f'{k}={v}' for k, v in params.items()) params = dict(params, apiKey=self.api_key) + started = time.monotonic() + try: response = requests.get(f'{self.BASE_URL}/{method}', params=params, timeout=20) @@ -208,14 +281,20 @@ class BricksetAPI: data = response.json() if data.get('status') == 'success': - return data.get('instructions', []) or [] + instructions = data.get('instructions', []) or [] + self._log_call(method, summary, ok=True, + http_status=response.status_code, + result_count=len(instructions), started=started) + return instructions - current_app.logger.error( - f"Brickset {method} failed: {data.get('message')}") + self._log_call(method, summary, ok=False, + http_status=response.status_code, started=started, + message=str(data.get('message'))) return [] except Exception as e: - current_app.logger.error(f'Brickset {method} error: {str(e)}') + self._log_call(method, summary, ok=False, started=started, + message=f'{type(e).__name__}: {e}') return [] def get_instructions(self, set_number: str) -> List[Dict[str, Any]]: @@ -246,6 +325,7 @@ class BricksetAPI: """ if not self.api_key: return [] + started = time.monotonic() try: response = requests.get(f'{self.BASE_URL}/getKeyUsageStats', params={'apiKey': self.api_key}, @@ -253,8 +333,17 @@ class BricksetAPI: response.raise_for_status() data = response.json() if data.get('status') == 'success': - return data.get('apiKeyUsage', []) or [] + usage = data.get('apiKeyUsage', []) or [] + self._log_call('getKeyUsageStats', ok=True, + http_status=response.status_code, + result_count=len(usage), started=started) + return usage + + self._log_call('getKeyUsageStats', ok=False, + http_status=response.status_code, started=started, + message=str(data.get('message'))) return [] except Exception as e: - current_app.logger.error(f'Brickset key usage error: {str(e)}') + self._log_call('getKeyUsageStats', ok=False, started=started, + message=f'{type(e).__name__}: {e}') return [] diff --git a/app/services/fetch_worker.py b/app/services/fetch_worker.py index ff1e616..be13fc7 100644 --- a/app/services/fetch_worker.py +++ b/app/services/fetch_worker.py @@ -18,10 +18,13 @@ with `flask instructions run` instead. Created by: Jess Rogerson (yelling commands at Claude.AI) """ +import logging import os import sys import threading +logger = logging.getLogger(__name__) + _thread = None _stop = threading.Event() _lock = threading.Lock() @@ -38,7 +41,7 @@ def _is_cli_command(): def start(app): """Start the ticker unless it's disabled or already running.""" if not app.config.get('INSTRUCTION_FETCH_WORKER', True): - app.logger.info('Instruction fetch worker disabled by config') + logger.info('Instruction fetch worker disabled by config') return False # `flask instructions run`, `flask backup restore` and friends shouldn't @@ -61,7 +64,8 @@ def start(app): daemon=True) _thread.start() - app.logger.info('Instruction fetch worker started') + logger.info('Instruction fetch worker started (tick %ss)', + app.config.get('INSTRUCTION_FETCH_TICK_SECONDS', 20)) return True @@ -86,7 +90,7 @@ def _loop(app): with app.app_context(): fetcher.run_one() except Exception: - app.logger.exception('Instruction fetch worker tick failed') + logger.exception('Instruction fetch worker tick failed') def run_once_async(app, force=False): @@ -102,7 +106,7 @@ def run_once_async(app, force=False): from app.services import instruction_fetcher as fetcher fetcher.run_one(force=force) except Exception: - app.logger.exception('Manual instruction fetch failed') + logger.exception('Manual instruction fetch failed') thread = threading.Thread(target=_work, name='lim-fetch-once', daemon=True) thread.start() diff --git a/app/services/instruction_fetcher.py b/app/services/instruction_fetcher.py index 8f0729f..433ced8 100644 --- a/app/services/instruction_fetcher.py +++ b/app/services/instruction_fetcher.py @@ -21,6 +21,7 @@ Created by: Jess Rogerson (yelling commands at Claude.AI) """ import hashlib +import logging import os import re import tempfile @@ -30,6 +31,8 @@ from datetime import datetime, timedelta import requests from flask import current_app +logger = logging.getLogger(__name__) + from app import db from app.models.instruction import Instruction from app.models.instruction_fetch import InstructionFetchJob @@ -375,8 +378,11 @@ def fetch_for_set(lego_set, delay_between_files=None): pause = (file_delay_seconds() if delay_between_files is None else delay_between_files) - api = BricksetAPI() + api = BricksetAPI(context='fetcher') entries, source, note = _instruction_urls(api, lego_set) + logger.info('Set %s: Brickset lists %d instruction file(s)%s', + lego_set.set_number, len(entries), + f' ({note})' if note else '') if not entries: return 0, 0, source, note or 'no instructions listed on Brickset' @@ -395,6 +401,8 @@ def fetch_for_set(lego_set, delay_between_files=None): temp_path, size, sha = _download_pdf(entry['url'], max_bytes, timeout) except Exception as exc: + logger.warning('Set %s: download failed for %s - %s', + lego_set.set_number, entry['url'], exc) problems.append(f'{entry["description"] or entry["url"]}: {exc}') continue @@ -427,6 +435,8 @@ def fetch_for_set(lego_set, delay_between_files=None): known.add(sha) page += 1 added += 1 + logger.info('Set %s: saved %s (%d bytes)', + lego_set.set_number, filename, file_size or size) except Exception as exc: db.session.rollback() @@ -519,8 +529,8 @@ def run_one(force=False): job.status = 'empty' except Exception as exc: - current_app.logger.exception('Instruction fetch failed for %s', - lego_set.set_number) + logger.exception('Instruction fetch failed for %s', + lego_set.set_number) job.message = str(exc)[:500] if job.attempts >= max_attempts(): job.status = 'failed' @@ -533,8 +543,8 @@ def run_one(force=False): job.finished_at = datetime.utcnow() db.session.commit() - current_app.logger.info('Instruction fetch %s for %s: %s', job.status, - lego_set.set_number, job.message) + logger.info('Job #%s %s for %s: %s', job.id, job.status, + lego_set.set_number, job.message) return job.to_dict() diff --git a/app/services/logging_setup.py b/app/services/logging_setup.py new file mode 100644 index 0000000..782aa5f --- /dev/null +++ b/app/services/logging_setup.py @@ -0,0 +1,218 @@ +""" +Logging setup and log reading. + +LIM previously configured no logging at all, which left Flask's logger at +WARNING and wrote nothing to disk — so a quiet background feature like the +instruction fetcher had no trail to follow. This attaches a rotating file +handler to the root logger, so every module logger (app.services.*, and the +fetcher in particular) lands in one file, and provides the parsing the admin +log viewer needs. + +Rotation is by size, not date: LOG_MAX_BYTES per file, LOG_BACKUP_COUNT old +copies, so disk use is bounded no matter how chatty things get. + +Created by: Jess Rogerson (yelling commands at Claude.AI) +""" + +import io +import logging +import os +import re +from logging.handlers import RotatingFileHandler + +LOG_FILENAME = 'lim.log' + +LEVELS = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL') + +LEVEL_BADGES = { + 'DEBUG': 'secondary', + 'INFO': 'info', + 'WARNING': 'warning', + 'ERROR': 'danger', + 'CRITICAL': 'danger', +} + +# 2026-09-26 13:38:00 INFO app.services.instruction_fetcher | message +LINE_RE = re.compile( + r'^(?P