From 9bd2507cb1366a31a18fd36a55fee0b7d572c036 Mon Sep 17 00:00:00 2001 From: duffyduck Date: Tue, 29 Sep 2026 10:21:32 +0200 Subject: [PATCH] fast, readable log: stop routine noise, keyset paging, token search MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The log had 6.45M rows, of which 434 were actual actions: every mail x every non-matching rule wrote "Keine Übereinstimmung" (5.3M rows, ~1 GB), plus "keine neuen Mails" per rule every 30s and a "Poll gestartet" row. Free-text searches took 50-70s. - Routine entries are only written with LOG_VERBOSE=true; the poll summary is logged only when there were new mails, actions or errors. "Why didn't my rule match" is now answered by the rule tester. - The scheduler commits every 25 evaluated mails and after each rule, since the dropped log calls used to be the implicit commit points. - Migration rebuilds filter_logs without the routine rows (live: 6.45M -> ~38k) via copy instead of DELETE. - /api/logs: keyset pagination (before_id) instead of OFFSET, count capped at 1000, since/until range, multi-level filter, per-field filters; ordner: also matches the move target stored in details. - New log page: one search field with shortcuts (von:, betreff:, regel:, ordner:, text:), live search with debounce and abort, active filters as removable chips, click on rule/sender/folder in a row to filter, time range (default 7 days), level quick filter, expandable row details, "Ältere laden", filters kept in the URL. - Disable Pico's colour transition on segmented buttons (they briefly flashed in the primary colour on load). Co-Authored-By: Claude Opus 5.5 --- .../9a3f5c1d7e42_purge_routine_logs.py | 62 ++ app/config.py | 3 + app/routers/logs.py | 135 ++-- app/services/scheduler.py | 34 +- app/templates/filters.html | 1 + app/templates/logs.html | 689 +++++++++++------- 6 files changed, 617 insertions(+), 307 deletions(-) create mode 100644 alembic/versions/9a3f5c1d7e42_purge_routine_logs.py diff --git a/alembic/versions/9a3f5c1d7e42_purge_routine_logs.py b/alembic/versions/9a3f5c1d7e42_purge_routine_logs.py new file mode 100644 index 0000000..51a1e0b --- /dev/null +++ b/alembic/versions/9a3f5c1d7e42_purge_routine_logs.py @@ -0,0 +1,62 @@ +"""purge routine entries from filter_logs + +Revision ID: 9a3f5c1d7e42 +Revises: 7d1e4a2b9c30 +Create Date: 2026-09-29 00:00:00.000000 + +""" +import re +from typing import Sequence, Union + +from alembic import op +from sqlalchemy import text + + +revision: str = "9a3f5c1d7e42" +down_revision: Union[str, Sequence[str], None] = "7d1e4a2b9c30" +branch_labels: Union[str, Sequence[str], None] = None +depends_on: Union[str, Sequence[str], None] = None + +# Routine-Einträge, die ab jetzt nur noch mit LOG_VERBOSE geschrieben werden. +# Sie machten >99% der Tabelle aus (Millionen Zeilen) und machten Suchen langsam. +NOISE = """ + message = 'Keine Übereinstimmung' + OR message LIKE 'Regel %keine neuen Mails%' + OR message LIKE 'Regel %Mail(s) in %prüfen%' + OR message LIKE 'Poll gestartet%' + OR (message LIKE 'Poll abgeschlossen%' AND message LIKE '%, 0 neu, 0 Treffer, 0 Aktion(en)') +""" + +INDEXES = { + "ix_filter_logs_created_at": "(created_at)", + "ix_filter_logs_level": "(level)", + "ix_filter_logs_account_created": "(account_id, created_at)", +} + + +def upgrade() -> None: + """Tabelle neu aufbauen statt DELETE: nur die relevanten Zeilen kopieren + ist bei Millionen Einträgen um ein Vielfaches schneller und erzeugt kein + riesiges WAL.""" + bind = op.get_bind() + ddl = bind.execute( + text("SELECT sql FROM sqlite_master WHERE type='table' AND name='filter_logs'") + ).scalar() + if not ddl: + return + new_ddl = re.sub(r'^CREATE TABLE\s+"?filter_logs"?', 'CREATE TABLE filter_logs_new', ddl, count=1) + + op.execute("DROP TABLE IF EXISTS filter_logs_new") + op.execute(new_ddl) + op.execute(f"INSERT INTO filter_logs_new SELECT * FROM filter_logs WHERE NOT ({NOISE})") + for name in INDEXES: + op.execute(f"DROP INDEX IF EXISTS {name}") + op.execute("DROP TABLE filter_logs") + op.execute("ALTER TABLE filter_logs_new RENAME TO filter_logs") + for name, cols in INDEXES.items(): + op.execute(f"CREATE INDEX {name} ON filter_logs {cols}") + + +def downgrade() -> None: + # Gelöschte Routine-Einträge lassen sich nicht wiederherstellen. + pass diff --git a/app/config.py b/app/config.py index 2e17ef8..02edcc5 100644 --- a/app/config.py +++ b/app/config.py @@ -9,6 +9,9 @@ class Settings(BaseSettings): encryption_key: str = "" yaml_sync_on_startup: bool = True log_level: str = "INFO" + # Ausführliches Verarbeitungslog (jede Nicht-Übereinstimmung, jede Regel pro + # Poll). Erzeugt Millionen Einträge — nur zur Fehlersuche einschalten. + log_verbose: bool = False model_config = {"env_file": ".env", "env_file_encoding": "utf-8"} diff --git a/app/routers/logs.py b/app/routers/logs.py index 2440504..8526af0 100644 --- a/app/routers/logs.py +++ b/app/routers/logs.py @@ -1,65 +1,118 @@ import logging +from datetime import datetime from fastapi import APIRouter, Depends, HTTPException, Query -from sqlalchemy import text +from sqlalchemy import or_, text from sqlalchemy.orm import Session from app.database import engine, get_db -from app.models.db_models import FilterLog +from app.models.db_models import FilterLog, LogLevel logger = logging.getLogger(__name__) router = APIRouter(prefix="/api/logs", tags=["logs"]) +# Obergrenze fürs Zählen: exakte Zahlen über Millionen Zeilen kosten Sekunden, +# für die Anzeige reicht "mehr als 1.000". +COUNT_CAP = 1000 + + +def _like(value: str) -> str: + escaped = value.replace("\\", "\\\\").replace("%", "\\%").replace("_", "\\_") + return f"%{escaped}%" + + +def _parse_ts(value: str | None) -> datetime | None: + if not value: + return None + try: + # Browser schickt ISO mit 'Z' (UTC) — DB speichert naive UTC + return datetime.fromisoformat(value.replace("Z", "+00:00")).replace(tzinfo=None) + except ValueError: + raise HTTPException(400, f"Ungültiges Datum: {value}") + @router.get("/") def get_logs( account_id: int | None = None, - level: str | None = None, - search: str | None = None, - search_subject: str | None = None, - search_from: str | None = None, - search_rule: str | None = None, - search_message: str | None = None, - search_details: str | None = None, - search_folder: str | None = None, - limit: int = Query(default=100, le=500), - offset: int = 0, + level: str | None = Query(default=None, description="Kommagetrennt: success,info,warning,error"), + q: str | None = Query(default=None, description="Freitext über alle Felder"), + sender: str | None = None, + subject: str | None = None, + rule: str | None = None, + folder: str | None = None, + message: str | None = None, + since: str | None = None, + until: str | None = None, + before_id: int | None = Query(default=None, description="Für 'Mehr laden': nur Einträge älter als diese ID"), + limit: int = Query(default=100, ge=1, le=500), db: Session = Depends(get_db), ): - query = db.query(FilterLog).order_by(FilterLog.created_at.desc()) + """Neueste zuerst, geblättert per before_id (Keyset) statt OFFSET: jede Seite + ist gleich schnell, egal wie weit man zurückblättert.""" + query = db.query(FilterLog) if account_id: query = query.filter(FilterLog.account_id == account_id) if level: - query = query.filter(FilterLog.level == level) - # Einfache Suche (ODER über alle Felder) - if search: - term = f"%{search}%" - query = query.filter( - FilterLog.message.ilike(term) - | FilterLog.mail_subject.ilike(term) - | FilterLog.mail_from.ilike(term) - | FilterLog.rule_name.ilike(term) - | FilterLog.details.ilike(term) - | FilterLog.folder.ilike(term) - ) - # Erweiterte Suche (UND pro Feld) - if search_subject: - query = query.filter(FilterLog.mail_subject.ilike(f"%{search_subject}%")) - if search_from: - query = query.filter(FilterLog.mail_from.ilike(f"%{search_from}%")) - if search_rule: - query = query.filter(FilterLog.rule_name.ilike(f"%{search_rule}%")) - if search_message: - query = query.filter(FilterLog.message.ilike(f"%{search_message}%")) - if search_details: - query = query.filter(FilterLog.details.ilike(f"%{search_details}%")) - if search_folder: - query = query.filter(FilterLog.folder.ilike(f"%{search_folder}%")) - total = query.count() - logs = query.offset(offset).limit(limit).all() + levels = [] + for part in level.split(","): + try: + levels.append(LogLevel(part.strip())) + except ValueError: + raise HTTPException(400, f"Unbekanntes Level: {part}") + query = query.filter(FilterLog.level.in_(levels)) + ts_since, ts_until = _parse_ts(since), _parse_ts(until) + if ts_since: + query = query.filter(FilterLog.created_at >= ts_since) + if ts_until: + query = query.filter(FilterLog.created_at < ts_until) + + # Freitext: jedes Wort muss in irgendeinem Feld vorkommen + if q: + for word in q.split(): + pat = _like(word) + query = query.filter(or_( + FilterLog.message.ilike(pat, escape="\\"), + FilterLog.mail_subject.ilike(pat, escape="\\"), + FilterLog.mail_from.ilike(pat, escape="\\"), + FilterLog.rule_name.ilike(pat, escape="\\"), + FilterLog.details.ilike(pat, escape="\\"), + FilterLog.folder.ilike(pat, escape="\\"), + )) + for column, value in ( + (FilterLog.mail_from, sender), + (FilterLog.mail_subject, subject), + (FilterLog.rule_name, rule), + (FilterLog.message, message), + ): + if value: + query = query.filter(column.ilike(_like(value), escape="\\")) + if folder: + # Quellordner steht in folder, das Ziel einer Verschiebe-Aktion in details + pat = _like(folder) + query = query.filter(or_( + FilterLog.folder.ilike(pat, escape="\\"), + (FilterLog.action_type == "move") & FilterLog.details.ilike(pat, escape="\\"), + )) + + count_query = query + if before_id: + query = query.filter(FilterLog.id < before_id) + + rows = query.order_by(FilterLog.id.desc()).limit(limit + 1).all() + has_more = len(rows) > limit + rows = rows[:limit] + + # Treffermenge nur bis COUNT_CAP zählen (und nur für die erste Seite) + total = None + if before_id is None: + total = count_query.with_entities(FilterLog.id).limit(COUNT_CAP + 1).count() + return { "total": total, + "total_capped": total is not None and total > COUNT_CAP, + "has_more": has_more, + "next_before_id": rows[-1].id if rows and has_more else None, "logs": [ { "id": log.id, @@ -76,7 +129,7 @@ def get_logs( "details": log.details, "created_at": log.created_at.isoformat() if log.created_at else None, } - for log in logs + for log in rows ], } diff --git a/app/services/scheduler.py b/app/services/scheduler.py index b239ffa..980040a 100644 --- a/app/services/scheduler.py +++ b/app/services/scheduler.py @@ -5,6 +5,7 @@ from datetime import datetime from apscheduler.schedulers.asyncio import AsyncIOScheduler from sqlalchemy.orm import Session +from app.config import settings from app.database import SessionLocal from app.models.db_models import Account, FilterRule, LogLevel, ProcessedMail from app.services.encryption import decrypt @@ -16,6 +17,17 @@ logger = logging.getLogger(__name__) scheduler = AsyncIOScheduler() +# Nach so vielen geprüften Mails wird zwischengespeichert, damit der Poll die +# SQLite-Schreibsperre nicht minutenlang hält (UI-Aktionen würden sonst warten). +COMMIT_EVERY = 25 + + +def _verbose_log(**kwargs) -> None: + """Routine-Einträge (Nicht-Übereinstimmung, 'keine neuen Mails', Poll-Start) + erzeugten Millionen Logzeilen ohne Nutzen — nur bei LOG_VERBOSE schreiben.""" + if settings.log_verbose: + write_log(**kwargs) + def _build_smtp_config(account: Account) -> dict | None: if account.smtp_host and account.smtp_username and account.smtp_password: @@ -42,7 +54,7 @@ def _poll_account_sync(account_id: int) -> None: .all() ) - write_log( + _verbose_log( message=f"Poll gestartet ({len(rules)} aktive Regel(n))", level=LogLevel.INFO, account_id=account.id, @@ -72,6 +84,7 @@ def _poll_account_sync(account_id: int) -> None: total_matched = 0 total_actions = 0 total_errors = 0 + evaluated_count = 0 # Mail-Cache: einmal geladene Mails pro Ordner/UID wiederverwenden mail_cache: dict[tuple[str, str], "MailMessage"] = {} @@ -126,7 +139,7 @@ def _poll_account_sync(account_id: int) -> None: new_uids.reverse() if not new_uids: - write_log( + _verbose_log( message=f"Regel '{rule.name}': keine neuen Mails in '{folder}' ({len(all_uids)} gesamt, alle bereits geprüft)", level=LogLevel.INFO, account_id=account.id, @@ -146,7 +159,7 @@ def _poll_account_sync(account_id: int) -> None: msg = f"Regel '{rule.name}': {len(batch_uids)} Mail(s) in '{folder}' prüfen ({len(processed_uids)} bereits geprüft)" if remaining > 0: msg += f" — {remaining} weitere beim nächsten Poll" - write_log( + _verbose_log( message=msg, level=LogLevel.INFO, account_id=account.id, @@ -247,8 +260,8 @@ def _poll_account_sync(account_id: int) -> None: db=db, ) else: - write_log( - message=f"Keine Übereinstimmung", + _verbose_log( + message="Keine Übereinstimmung", level=LogLevel.INFO, account_id=account.id, account_name=account.name, @@ -270,7 +283,11 @@ def _poll_account_sync(account_id: int) -> None: mail_subject=mail.subject[:500] if mail.subject else None, mail_from=mail.from_addr[:255] if mail.from_addr else None, )) - db.flush() + evaluated_count += 1 + if evaluated_count % COMMIT_EVERY == 0: + db.commit() + + db.commit() # Poll-Zusammenfassung summary_parts = [ @@ -282,7 +299,10 @@ def _poll_account_sync(account_id: int) -> None: if total_errors > 0: summary_parts.append(f"{total_errors} Fehler") - write_log( + # Nur loggen, wenn etwas passiert ist — ein Eintrag alle 30 s ohne + # Inhalt verdeckt die relevanten Zeilen. Letzter Poll steht im Dashboard. + summary_log = write_log if (total_new or total_actions or total_errors) else _verbose_log + summary_log( message=f"Poll abgeschlossen: {', '.join(summary_parts)}", level=LogLevel.ERROR if total_errors > 0 else LogLevel.SUCCESS if total_actions > 0 else LogLevel.INFO, account_id=account.id, diff --git a/app/templates/filters.html b/app/templates/filters.html index 62d5cf2..f02f17b 100644 --- a/app/templates/filters.html +++ b/app/templates/filters.html @@ -127,6 +127,7 @@ .toolbar { display:flex; gap:0.5rem; align-items:center; flex-wrap:wrap; margin-bottom:0.6rem; } .toolbar input[type=search] { flex:1 1 280px; margin:0; padding-top:0.3rem; padding-bottom:0.3rem; font-size:0.9rem; } .seg { display:inline-flex; flex-wrap:wrap; border:1px solid var(--app-border, #e3e6ea); border-radius:var(--pico-border-radius); overflow:hidden; background:#fff; } +.toolbar .seg button { transition:none; } .toolbar .seg button { --pico-background-color:transparent; --pico-border-color:transparent; --pico-color:#374151; margin:0; border-radius:0; padding:0.3rem 0.7rem; font-size:0.8rem; box-shadow:none; } .toolbar .seg button + button { border-left:1px solid var(--app-border, #e3e6ea); } diff --git a/app/templates/logs.html b/app/templates/logs.html index 578b49c..ac9c9dc 100644 --- a/app/templates/logs.html +++ b/app/templates/logs.html @@ -1,305 +1,476 @@ {% extends "base.html" %} -{% block title %}Verarbeitungslog — IMAP Mail Filter{% endblock %} +{% block title %}Log — IMAP Mail Filter{% endblock %} {% block content %} -

Verarbeitungslog

- -
- - - -
- - - -
-