Logging

Implementierung eines strukturierten Logging-Systems mit Unterstützung für SQL-Fehlerprotokollierung und Anwendungsprotokollierung. Hinzufügen von Logging-Konfigurationen in der Hauptanwendung und Middleware für HTTP-Anfragen. Verbesserung der SQL-Abfrageprotokollierung durch Verwendung von `execution_options`. Integration von Logging in CLI-Tools und Tests zur Sicherstellung der Protokollierung in verschiedenen Kontexten. Aktualisierung der Abhängigkeiten für `concurrent-log-handler`.

.env.example

@@ -21,3 +21,10 @@ LDAP_START_TLS=false
 
 LOCAL_STORAGE=C:\\Data\\GCEPIC
 UPLOAD_MAX_FILE_SIZE_MB=50
+
+LOG_LEVEL=INFO
+LOG_DIR=logs
+LOG_TO_FILE=true
+LOG_TO_CONSOLE=true
+LOG_RETENTION_DAYS=30
+LOG_SQL_STATEMENT=true

README.md

@@ -288,3 +288,72 @@ anpassen. Genügend temporären Speicher auch für den Multipart-Parser des Serv
 
 Uploadtests verwenden ausschließlich temporäre Verzeichnisse:
 `python -m unittest discover -s tests -q`.
+
+## Zentrales Logging
+
+Webanwendung und Hilfsprogramme verwenden dieselbe idempotente Logging-Konfiguration.
+Entwicklung: `python server.py`; Dienstbetrieb: `python server.py --no-reload`.
+`webservice/webservice.bat` verwendet diesen Einstieg ohne zusätzliche Dateiumleitung.
+Nach Änderungen an Konfiguration oder Dienstskript den Dienst neu starten.
+
+```dotenv
+LOG_LEVEL=INFO
+LOG_DIR=logs
+LOG_TO_FILE=true
+LOG_TO_CONSOLE=true
+LOG_RETENTION_DAYS=30
+LOG_SQL_STATEMENT=true
+```
+
+Relative Logverzeichnisse beziehen sich auf den Projektstamm. `application.log` enthält
+je Ereignis eine JSON-Zeile; die Konsole zeigt dieselben Ereignisse lesbar an. `LOG_LEVEL`
+akzeptiert DEBUG, INFO, WARNING, ERROR und CRITICAL. Beide Ausgaben lassen sich unabhängig
+abschalten. Die Zeitstempel enthalten Millisekunden und den Europe/Berlin-Offset.
+Die tägliche Rotation erfolgt dagegen um Mitternacht UTC. Eigene Archive heißen
+`application.log.YYYY-MM-DD`; Archive älter als die konfigurierte Aufbewahrungsdauer
+werden beim Start und bei Rotation entfernt. Frühere Dienstlogs bleiben erhalten.
+
+Alle Prozesse müssen dasselbe Verzeichnis und dieselben Rotationseinstellungen verwenden.
+`concurrent-log-handler` koordiniert Schreiben und Rotation über Dateisperren, auch unter
+Windows. Das Dienstkonto benötigt Auflisten, Anlegen, Lesen, Schreiben, Umbenennen und
+Löschen für Logdateien, Archive und Sperrdateien im Logverzeichnis. Fehlende Schreibrechte,
+Rotations- oder Schreibfehler erzeugen eine datenarme Konsolenmeldung; bei Dateiausfall
+bleibt die Konsole als Fallback verfügbar. Deshalb auch die Dienstkonsole erfassbar halten.
+Logs nur den erforderlichen Betriebskonten zugänglich machen.
+
+HTTP-Abschlüsse enthalten `event=http_completed`, eine eigene `event_id`, `request_id`,
+Benutzerkennung (soweit angemeldet), Methode, Pfad, Status und Laufzeit in Millisekunden.
+Die Antwort liefert dieselbe Request-ID als `X-Request-ID`. Zur Fehlersuche beispielsweise:
+
+```powershell
+Select-String -LiteralPath .\logs\application.log -Pattern 'REQUEST-ID-AUS-DER-ANTWORT'
+```
+
+4xx werden als WARNING, 5xx als ERROR und andere Anfragen als INFO erfasst. Erfolgreiche
+Abrufe unter `/static/` und `/health` erscheinen nur mit DEBUG. Loginanforderungen haben
+zusätzlich `event=auth_login_required`, auch bei HTMX-Antworten mit HTTP 200. Uvicorns
+separates Zugriffslog ist abgeschaltet. Unerwartete Exceptions werden einmal technisch
+erfasst; der HTTP-Abschluss bleibt ein eigenes, über die Request-ID zugeordnetes Ereignis.
+Fehler nach Beginn einer Streamingantwort behalten den tatsächlich gesendeten Status.
+Fehler, die IIS oder ein vorgeschalteter Proxy vor Python erzeugt, stehen weiterhin in
+den jeweiligen Serverlogs.
+
+Datenbankfehler haben `event=database_error` mit Operation, Abfrageherkunft,
+`query_fingerprint`, Exceptiontyp, verfügbaren technischen Fehlercodes und Stackframes
+(Dateiname, Funktion, Zeile). Templateabfragen tragen ihren SQL-Dateinamen als Herkunft.
+SQL-Parameter, lokale Variablen und ungeprüfte Exceptiontexte werden nicht ausgegeben.
+SQL-Kommentare werden entfernt und Zeichenketten- sowie Zahlenliterale maskiert; der
+SQL-Text wird auf 8192 Zeichen begrenzt. Mit `LOG_SQL_STATEMENT=false` entfällt auch diese
+bereinigte Anweisung; Fingerabdruck und Herkunft bleiben erhalten. Abgefangene
+Datenbankfehler werden ebenfalls erfasst, weitere Logger erzeugen für dieselbe Exception
+keinen zweiten technischen Datensatz. Ein zusätzlicher Rollbackfehler bleibt sichtbar.
+Neue Logaufrufe dürfen keine Passwörter, Tokens, Header, Queryparameter, Formularinhalte,
+Mailbetreffzeilen oder Datei-/PDF-Inhalte enthalten. Binärdaten nur über ihre Größe erfassen.
+
+Hilfsskripte mit Paketimporten starten: `python -m app.imap`,
+`python -m app.cleanup_comments`, `python -m app.docuware_search` beziehungsweise
+`python filter_export.py`. Diese Programme behalten ihre fachlichen Aktionen bei;
+ein Import allein führt sie nicht aus. Nicht zu Logging-Testzwecken produktiv starten.
+Loggingtests nutzen ausschließlich temporäre Verzeichnisse und isolierte SQLite-Engines:
+`python -m unittest tests.test_logging -q`. Die vollständige Prüfung erfolgt mit
+`python -m unittest discover -s tests -q`.

app/auth.py

@@ -131,6 +131,7 @@ class AuthenticationMiddleware(BaseHTTPMiddleware):
 
         principal = getattr(request.state, "principal", None)
         if not principal and not is_public:
+            logger.info('Anmeldung erforderlich', extra={'event': 'auth_login_required', 'reason': 'invalid_or_expired_session' if token else 'missing_session'})
             next_url = request.url.path
             if request.url.query:
                 next_url += "?" + request.url.query

app/cleanup_comments.py

@@ -1,68 +1,71 @@
 import re
+import logging
 from datetime import date, timedelta
 
-from db import get_session
+from .db import SessionLocal
+from .logging_setup import run_cli
 from sqlalchemy import text
 
+logger = logging.getLogger(__name__)
+
 
 def main():
-    db = next(get_session())
-    q = db.execute(text("SELECT * FROM dbo.Forderungen_Kommentar_Rohdaten"))
-
-    for row in q.fetchall():
-        for i, r in enumerate(row.Kommentar.split("\n"), 1):
-            comment_date = (row.Timestamp + timedelta(minutes=i)).strftime("%Y-%m-%dT%H:%M:%S")
-            comment_user = row.Benutzer_ID
-            r = r.replace("'", "").replace("?", "").replace(" :", "").replace("  ", " ").strip()
-            # d, u = get_date_and_user_from_comment(r)
-            db.execute(
-                text(
-                    "INSERT INTO dbo.Forderungen_Kommentar "
-                    f"VALUES ('{row.Client_DB}', '{row.Beleg_Nr}', '{comment_date}', '{comment_user}', '{r}')"
+    with SessionLocal() as db:
+        q = db.execute(text("SELECT * FROM dbo.Forderungen_Kommentar_Rohdaten"))
+
+        for row in q.fetchall():
+            for i, r in enumerate(row.Kommentar.split("\n"), 1):
+                comment_date = (row.Timestamp + timedelta(minutes=i)).strftime("%Y-%m-%dT%H:%M:%S")
+                comment_user = row.Benutzer_ID
+                r = r.replace("'", "").replace("?", "").replace(" :", "").replace("  ", " ").strip()
+                # d, u = get_date_and_user_from_comment(r)
+                db.execute(
+                    text("INSERT INTO dbo.Forderungen_Kommentar (Client_DB, Beleg_Nr, [Timestamp], Benutzer_ID, Kommentar) "
+                         "VALUES (:Client_DB, :Beleg_Nr, :Timestamp, :Benutzer_ID, :Kommentar)")
+                    .execution_options(query_name='cleanup_comments.import_comments'),
+                    dict(Client_DB=row.Client_DB, Beleg_Nr=row.Beleg_Nr, Timestamp=comment_date, Benutzer_ID=comment_user, Kommentar=r),
                 )
-            )
 
-    db.commit()
+        db.commit()
 
 
 def get_details_from_comments():
-    db = next(get_session())
-    q = db.execute(text("SELECT * FROM dbo.Forderungen_Kommentar_Rohdaten"))
-
-    for row in q.fetchall():
-        data = {}
-
-        az = re.search(r"^AZ\:?\s(\d+\/\d+)", row.Kommentar)
-        if az:
-            data["Rechtsanwalt_Aktenzeichen"] = az[1]
-
-        if "HP Schaden" in row.Kommentar:
-            data["Versicherung_Typ"] = "Haftpflicht"
-        if "Haftpflicht" in row.Kommentar:
-            data["Versicherung_Typ"] = "Haftpflicht"
-        if "VK Schaden" in row.Kommentar:
-            data["Versicherung_Typ"] = "Vollkasko"
-        if "VK-Schaden" in row.Kommentar:
-            data["Versicherung_Typ"] = "Vollkasko"
-        if "TK Schaden" in row.Kommentar:
-            data["Versicherung_Typ"] = "Teilkasko"
-        if "TK-Schaden" in row.Kommentar:
-            data["Versicherung_Typ"] = "Teilkasko"
-
-        s = re.search(r"Schaden (.*) bei (.*) eingereicht", row.Kommentar)
-        if s:
-            data["Schadennummer"] = s[1][:25]
-            data["Vers_Adresse_ID"] = s[2].replace("'", "").lower()[:25]
-
-        if data:
-            db.execute(
-                text(
-                    "UPDATE dbo.Forderungen_Details SET "
-                    + ", ".join([f"{k} = '{v}'" for k, v in data.items()])
-                    + f" WHERE Client_DB = '{row.Client_DB}' AND Beleg_Nr = '{row.Beleg_Nr}'"
+    with SessionLocal() as db:
+        q = db.execute(text("SELECT * FROM dbo.Forderungen_Kommentar_Rohdaten"))
+
+        for row in q.fetchall():
+            data = {}
+
+            az = re.search(r"^AZ\:?\s(\d+\/\d+)", row.Kommentar)
+            if az:
+                data["Rechtsanwalt_Aktenzeichen"] = az[1]
+
+            if "HP Schaden" in row.Kommentar:
+                data["Versicherung_Typ"] = "Haftpflicht"
+            if "Haftpflicht" in row.Kommentar:
+                data["Versicherung_Typ"] = "Haftpflicht"
+            if "VK Schaden" in row.Kommentar:
+                data["Versicherung_Typ"] = "Vollkasko"
+            if "VK-Schaden" in row.Kommentar:
+                data["Versicherung_Typ"] = "Vollkasko"
+            if "TK Schaden" in row.Kommentar:
+                data["Versicherung_Typ"] = "Teilkasko"
+            if "TK-Schaden" in row.Kommentar:
+                data["Versicherung_Typ"] = "Teilkasko"
+
+            s = re.search(r"Schaden (.*) bei (.*) eingereicht", row.Kommentar)
+            if s:
+                data["Schadennummer"] = s[1][:25]
+                data["Vers_Adresse_ID"] = s[2].replace("'", "").lower()[:25]
+
+            if data:
+                db.execute(
+                    text("UPDATE dbo.Forderungen_Details SET " + ", ".join(f"{key} = :{key}" for key in data)
+                         + " WHERE Client_DB = :Client_DB AND Beleg_Nr = :Beleg_Nr")
+                    .execution_options(query_name='cleanup_comments.parse_details'),
+                    dict(data, Client_DB=row.Client_DB, Beleg_Nr=row.Beleg_Nr),
                 )
-            )
-    db.commit()
+        db.commit()
 
 
 def get_date_and_user_from_comment(r: str) -> tuple[date, str]:
@@ -82,4 +85,4 @@ def get_date_and_user_from_comment(r: str) -> tuple[date, str]:
 
 if __name__ == "__main__":
     # main()
-    get_details_from_comments()
+    run_cli(get_details_from_comments)

app/comment_submission.py

@@ -61,7 +61,7 @@ async def submit_comment(request, pkey, db, scope):
                 query = templates.env.get_template('forderungen/details/queries/post/post_comments.sql').render(data=data)
                 for statement in query.split(';'):
                     if statement.strip():
-                        db.execute(text(statement), data)
+                        db.execute(text(statement).execution_options(query_name='forderungen/details/queries/post/post_comments.sql'), data)
                 db.commit()
                 comment_saved = True
             except Exception:

app/config.py

@@ -1,6 +1,6 @@
 from functools import lru_cache
 from ipaddress import ip_address, ip_network
-from typing import Annotated
+from typing import Annotated, Literal
 
 from pydantic import AliasChoices, BeforeValidator, Field, model_validator
 from pydantic_settings import BaseSettings, SettingsConfigDict
@@ -47,6 +47,12 @@ class Settings(BaseSettings):
     LDAP_START_TLS: bool = False
     LOCAL_STORAGE: str | None = None
     UPLOAD_MAX_FILE_SIZE_MB: int = Field(default=50, gt=0)
+    LOG_LEVEL: Annotated[Literal['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'], BeforeValidator(lambda value: str(value).upper())] = 'INFO'
+    LOG_DIR: str = 'logs'
+    LOG_TO_FILE: bool = True
+    LOG_TO_CONSOLE: bool = True
+    LOG_RETENTION_DAYS: int = Field(default=30, ge=1)
+    LOG_SQL_STATEMENT: bool = True
 
     @model_validator(mode="after")
     def validate_security_settings(self) -> "Settings":

app/db.py

@@ -1,13 +1,78 @@
-from sqlalchemy import create_engine
-from sqlalchemy.orm import declarative_base, sessionmaker
+from sqlalchemy import create_engine, event
+from sqlalchemy.orm import Session, declarative_base, sessionmaker
 
 from .config import settings
+from .logging_setup import db_operation, db_query, log_query_error, query_origin
+
+
+def install_engine_logging(engine):
+    if getattr(engine, '_gc_logging', False): return
+    engine._gc_logging = True
+
+    @event.listens_for(engine, 'before_cursor_execute')
+    def executing(conn, cursor, statement, parameters, context, executemany):
+        context._gc_operation = 'execute'
+
+    @event.listens_for(engine, 'after_cursor_execute')
+    def executed(conn, cursor, statement, parameters, context, executemany):
+        context._gc_operation = 'fetch'
+
+    @event.listens_for(engine, 'handle_error')
+    def query_failed(context):
+        # Observational only: never replace exceptions or affect connection invalidation.
+        error = context.sqlalchemy_exception or context.original_exception
+        options = getattr(context.execution_context, 'execution_options', {}) or {}
+        active = db_query.get() or {}
+        statement = context.statement if context.statement is not None else active.get('statement')
+        log_query_error(error, statement, options.get('query_name') or active.get('query_name'),
+                        db_operation.get() or getattr(context.execution_context, '_gc_operation', 'connect_or_transaction'))
+
+
+class LoggingSession(Session):
+    def execute(self, statement, params=None, *, execution_options=None, **kwargs):
+        options = dict(execution_options or {})
+        origin = options.setdefault('query_name', getattr(statement, '_execution_options', {}).get('query_name') or query_origin())
+        token = db_operation.set('execute')
+        query_token = db_query.set({'statement': statement, 'query_name': origin})
+        try:
+            return super().execute(statement, params, execution_options=options, **kwargs)
+        except Exception as error:
+            log_query_error(error, statement, origin, 'execute')
+            raise
+        finally:
+            db_query.reset(query_token)
+            db_operation.reset(token)
+
+    def _transaction_operation(self, operation):
+        token = db_operation.set(operation)
+        try:
+            return getattr(super(), operation)()
+        except Exception as error:
+            log_query_error(error, operation=operation)
+            raise
+        finally:
+            db_operation.reset(token)
+
+    def commit(self): return self._transaction_operation('commit')
+    def rollback(self): return self._transaction_operation('rollback')
+
+    def flush(self, objects=None):
+        token = db_operation.set('flush')
+        try:
+            return super().flush(objects)
+        except Exception as error:
+            log_query_error(error, operation='flush')
+            raise
+        finally:
+            db_operation.reset(token)
 
 engine = create_engine(
     settings.DATABASE_URL,
     connect_args={"check_same_thread": False} if settings.DATABASE_URL.startswith("sqlite") else {},
+    hide_parameters=True,
 )
-SessionLocal = sessionmaker(bind=engine, autoflush=False, autocommit=False)
+install_engine_logging(engine)
+SessionLocal = sessionmaker(bind=engine, class_=LoggingSession, autoflush=False, autocommit=False)
 Base = declarative_base()
 
 

app/docuware_search.py

@@ -1,8 +1,12 @@
 import json
 import os
+import logging
 
 import docuware
 from dotenv import load_dotenv
+from .logging_setup import run_cli
+
+logger = logging.getLogger(__name__)
 
 load_dotenv()
 
@@ -19,18 +23,11 @@ def main():
     dw = docuware.connect()
 
     for org in dw.organizations:
-        print(org)
+        logger.debug('DocuWare-Organisation verfügbar')
         for fc in org.file_cabinets:
-            print("   ", fc)
+            logger.debug('DocuWare-Ablage verfügbar')
         for b in org.baskets:
-            print("   ", b)
-        # dlg = fc.search_dialog()
-        # for field in dlg.fields.values():
-        #     print("Id    =", field.id)
-        #     print("Length=", field.length)
-        #     print("Name  =", field.name)
-        #     print("Type  =", field.type)
-        #     print("-------")
+            logger.debug('DocuWare-Briefkorb verfügbar')
 
 
 def get_file_cabinet(client_db: str) -> docuware.FileCabinet:
@@ -112,4 +109,7 @@ def get_invoice_pdf_by_document_no(client_db: str, document_no: str) -> bytes:
 if __name__ == "__main__":
     # main()
     # search_files(client_db="1", vehicle_no="WBA21FZ070FT19353")
-    print(get_invoice_pdf_by_document_no("1", "WRG25117581"))
+    def download_sample():
+        data = get_invoice_pdf_by_document_no('1', 'WRG25117581')
+        logger.info('PDF abgerufen', extra={'event': 'docuware_pdf_downloaded', 'size_bytes': len(data)})
+    run_cli(download_sample)

app/file_storage.py

@@ -220,7 +220,7 @@ def save_upload(primary_key: dict[str, str], name: str, stream, max_bytes: int)
                     try:
                         archive.rename(existing)
                     except OSError:
-                        logger.exception('Archivierte Datei konnte nicht zurückbenannt werden: %s', archive)
+                        logger.exception('Archivierte Datei konnte nicht zurückbenannt werden', extra={'event': 'file_archive_rollback_failed'})
                 raise
         return target.relative_to(root).as_posix()
     finally:

app/forderung_data.py

@@ -7,7 +7,7 @@ def read_invoices(db, username, clauses=(), values=None):
     query = templates.env.get_template('forderungen/liste/queries/forderungen_liste.sql').render()
     if clauses:
         query = query.replace('AND 1 = 1', 'AND 1 = 1 AND ' + ' AND '.join(clauses))
-    result = db.execute(text(query), dict(values or {}, auth_username=username))
+    result = db.execute(text(query).execution_options(query_name='forderungen/liste/queries/forderungen_liste.sql'), dict(values or {}, auth_username=username))
     columns = list(result.keys())
     tenant, number = columns.index('Client_DB'), columns.index('Beleg_Nr')
     seen, rows = set(), []

app/forderung_history.py

@@ -29,7 +29,7 @@ def section_context(db: Session, pkey: dict[str, str], invoice, section: str, sc
     rows = []
     if scope != "vehicle" or not vehicle_missing:
         query = templates.env.get_template(f"forderungen/details/queries/forderungen_{section}.sql").render(scope=scope)
-        rows = db.execute(text(query), values).fetchall()
+        rows = db.execute(text(query).execution_options(query_name=f'forderungen/details/queries/forderungen_{section}.sql'), values).fetchall()
     return {
         "forderungen_details": [invoice],
         f"forderungen_{section}": rows,

app/http_logging.py

@@ -0,0 +1,70 @@
+"""ASGI response logging outside authentication, without consuming request bodies."""
+import logging
+import time
+from uuid import uuid4
+
+from starlette.responses import PlainTextResponse
+
+from .logging_setup import request_context
+
+logger = logging.getLogger(__name__)
+
+
+class RequestLoggingMiddleware:
+    def __init__(self, app):
+        self.app = app
+
+    async def __call__(self, scope, receive, send):
+        if scope['type'] != 'http':
+            return await self.app(scope, receive, send)
+        request_id = uuid4().hex
+        scope.setdefault('state', {})['request_id'] = request_id
+        token = request_context.set({'request_id': request_id, 'scope': scope})
+        started = time.perf_counter()
+        status, completed, failed = None, False, False
+
+        def finish(outcome, level=None):
+            nonlocal completed
+            if completed: return
+            completed = True
+            level = level or (logging.ERROR if status and status >= 500 else logging.WARNING if status and status >= 400 else
+                              logging.DEBUG if scope['path'] == '/health' or scope['path'].startswith('/static/') else logging.INFO)
+            logger.log(level, 'HTTP-Anfrage abgeschlossen', extra={
+                'event': 'http_completed', 'status': status,
+                'duration_ms': round((time.perf_counter()-started)*1000, 2), 'outcome': outcome,
+            })
+
+        async def logged_send(message):
+            nonlocal status
+            if message['type'] == 'http.response.start':
+                message = dict(message, headers=[(key, value) for key, value in message.get('headers', [])
+                                                if key.lower() != b'x-request-id'] + [(b'x-request-id', request_id.encode('ascii'))])
+            await send(message)
+            if message['type'] == 'http.response.start': status = message['status']
+            if message['type'] == 'http.response.body' and not message.get('more_body', False):
+                finish('completed')
+
+        try:
+            await self.app(scope, receive, logged_send)
+        except Exception:
+            failed = True
+            streaming = status is not None
+            logger.exception('HTTP-Verarbeitung fehlgeschlagen', extra={'event': 'response_stream_error' if streaming else 'unhandled_exception'})
+            if status is None: status = 500
+            if not completed:
+                finish('stream_failed' if streaming else 'failed', logging.ERROR)
+            raise
+        finally:
+            if not completed and not failed: finish('aborted', logging.WARNING)
+            request_context.reset(token)
+
+
+async def unhandled_error_response(request, exc):
+    request_id = getattr(request.state, 'request_id', None)
+    return PlainTextResponse('Internal Server Error', status_code=500,
+                             headers={'X-Request-ID': request_id} if request_id else {})
+
+
+def install_request_logging(app):
+    app.add_middleware(RequestLoggingMiddleware)
+    app.add_exception_handler(Exception, unhandled_error_response)

app/imap.py

@@ -1,14 +1,17 @@
 import os
 import re
+import logging
 from dataclasses import dataclass
 from pathlib import Path
 
-from db import get_session
+from .db import SessionLocal
+from .logging_setup import run_cli
 from dotenv import load_dotenv
 from imap_tools import MailBox
 from sqlalchemy import text
 
 load_dotenv()
+logger = logging.getLogger(__name__)
 
 
 @dataclass
@@ -18,15 +21,13 @@ class ImapCredentials:
     password: str
 
 
-creds = ImapCredentials(
-    server=os.getenv("IMAP_SERVER"), username=os.getenv("IMAP_USERNAME"), password=os.getenv("IMAP_PASSWORD")
-)
-fileserver = Path(os.environ.get("LOCAL_STORAGE"))
-
-
 def main():
-    db = next(get_session())
-    q = db.execute(text("SELECT [Client_DB], [Beleg_Nr] FROM [dbo].[Forderungen_Kopf]")).fetchall()
+    creds = ImapCredentials(
+        server=os.getenv("IMAP_SERVER"), username=os.getenv("IMAP_USERNAME"), password=os.getenv("IMAP_PASSWORD")
+    )
+    fileserver = Path(os.environ.get("LOCAL_STORAGE"))
+    with SessionLocal() as db:
+        q = db.execute(text("SELECT [Client_DB], [Beleg_Nr] FROM [dbo].[Forderungen_Kopf]")).fetchall()
     lookup = {row[1]: row[0] for row in q}
 
     with MailBox(creds.server).login(creds.username, creds.password) as mb:
@@ -41,21 +42,21 @@ def main():
         for msg in messages:
             match = re.findall(r"([WV]\w+\d+)", msg.subject)
             if not match:
-                print(msg.subject)
+                logger.debug('E-Mail ohne Belegzuordnung übersprungen')
                 continue
-            print(match)
+            logger.debug('Belegkennung in E-Mail erkannt')
             invoice_no = match[0]
             if invoice_no not in lookup:
                 continue
             client_db = lookup[invoice_no]
-            print(invoice_no, client_db)
+            logger.debug('E-Mail einem Beleg zugeordnet')
             attachments = {att.filename: att.payload for att in msg.attachments if att.size > 0}
             for file, content in attachments.items():
                 filename: Path = fileserver / client_db / invoice_no / file
                 filename.parent.mkdir(exist_ok=True, parents=True)
                 filename.write_bytes(content)
-                print(filename)
+                logger.info('Mailanhang abgelegt', extra={'event': 'mail_attachment_saved', 'size_bytes': len(content)})
 
 
 if __name__ == "__main__":
-    main()
+    run_cli(main)

app/logging_setup.py

@@ -0,0 +1,265 @@
+"""Safe structured logging shared by HTTP, database and CLI entrypoints."""
+from contextvars import ContextVar
+from datetime import datetime, timedelta, timezone
+import hashlib
+import json
+import logging
+import os
+from pathlib import Path
+import re
+import sys
+import threading
+import time
+import traceback
+from uuid import uuid4
+from zoneinfo import ZoneInfo
+
+from concurrent_log_handler import ConcurrentTimedRotatingFileHandler
+
+request_context = ContextVar('request_logging_context', default=None)
+db_operation = ContextVar('database_logging_operation', default=None)
+db_query = ContextVar('database_logging_query', default=None)
+BERLIN = ZoneInfo('Europe/Berlin')
+PROJECT_ROOT = Path(__file__).resolve().parent.parent
+_lock = threading.RLock()
+_configuration = None
+_SAFE_FIELDS = ('event', 'operation', 'query_name', 'query_fingerprint', 'sql', 'sql_truncated',
+                'sqlstate', 'db_code', 'status', 'duration_ms', 'outcome', 'size_bytes', 'count',
+                'reason', 'error_type')
+
+
+def clean(value):
+    return str(value).replace('\r', '\\r').replace('\n', '\\n').replace('\x00', '\\0')[:8192]
+
+
+def sanitize_sql(statement):
+    """Lex T-SQL literals/comments without modifying quoted identifiers or bind names."""
+    source, output, i = str(statement), [], 0
+    while i < len(source):
+        char = source[i]
+        if source.startswith('--', i):
+            end = source.find('\n', i + 2); i = len(source) if end < 0 else end
+            output.append(' ')
+        elif source.startswith('/*', i):
+            depth = 1; i += 2
+            while i < len(source) and depth:
+                if source.startswith('/*', i): depth += 1; i += 2
+                elif source.startswith('*/', i): depth -= 1; i += 2
+                else: i += 1
+            output.append(' ')
+        elif char == "'" or (char in 'nN' and source[i:i+2].endswith("'") and (i == 0 or not source[i-1].isalnum())):
+            if char != "'": i += 1
+            i += 1
+            while i < len(source):
+                if source[i:i+2] == "''": i += 2
+                elif source[i] == "'": i += 1; break
+                else: i += 1
+            output.append('?')
+        elif char in '["':
+            end_char = ']' if char == '[' else '"'
+            start = i; i += 1
+            while i < len(source):
+                if source[i:i+2] == end_char * 2: i += 2
+                elif source[i] == end_char: i += 1; break
+                else: i += 1
+            output.append(source[start:i] if char == '[' else '?')
+        elif (char.isdecimal() or char == '.' and i+1 < len(source) and source[i+1].isdecimal()) and (i == 0 or not (source[i-1].isalnum() or source[i-1] in '_:@$')):
+            match = re.match(r'(?:0[xX][0-9a-fA-F]+|(?:\d+(?:\.\d*)?|\.\d+)(?:[eE][+-]?\d+)?)', source[i:])
+            output.append('?'); i += len(match[0])
+        else:
+            output.append(char); i += 1
+    return ' '.join(''.join(output).split())
+
+
+def exception_roots(error):
+    seen = set()
+    def visit(exc):
+        if id(exc) in seen: return []
+        seen.add(id(exc))
+        if isinstance(exc, BaseExceptionGroup):
+            return [root for child in exc.exceptions for root in visit(child)]
+        original = getattr(exc, 'orig', None) or exc.__cause__
+        return visit(original) if isinstance(original, BaseException) else [exc]
+    return visit(error)
+
+
+def frames(tb=None):
+    extracted = traceback.extract_tb(tb) if tb else traceback.extract_stack()[:-1]
+    return [dict(file=Path(item.filename).name, line=item.lineno, function=item.name) for item in extracted[-45:]]
+
+
+class ContextFilter(logging.Filter):
+    def filter(self, record):
+        if record.name.startswith('uvicorn.') and record.levelno < logging.INFO: return False
+        if not record.name.startswith(('app.', 'uvicorn.', '__main__', 'filter_export')) and record.levelno < logging.WARNING: return False
+        if not hasattr(record, 'event_id'): record.event_id = uuid4().hex
+        context = request_context.get()
+        request_id = context['request_id'] if context else None
+        if record.exc_info and record.exc_info[1]:
+            roots = exception_roots(record.exc_info[1])
+            fresh = [exc for exc in roots if getattr(exc, '_gc_log_event', None) in (None, record.event_id)
+                     or request_id is not None and getattr(exc, '_gc_log_request', None) != request_id]
+            if not fresh: return False
+            for exc in fresh:
+                exc._gc_log_event = record.event_id
+                exc._gc_log_request = request_id
+            record.safe_exceptions = [dict(type=type(exc).__module__ + '.' + type(exc).__name__,
+                                           frames=getattr(exc, '_gc_log_frames', None) or frames(exc.__traceback__)) for exc in fresh]
+        record.request_fields = {}
+        if context:
+            scope = context['scope']
+            principal = scope.get('state', {}).get('principal')
+            record.request_fields = dict(request_id=context['request_id'], user=getattr(principal, 'username', None),
+                                         method=scope['method'], path=scope.get('path', ''))
+        return True
+
+
+def record_data(record):
+    data = dict(timestamp=datetime.fromtimestamp(record.created, BERLIN).isoformat(timespec='milliseconds'),
+                level=record.levelname, logger=record.name, event_id=record.event_id,
+                event=getattr(record, 'event', 'application'),
+                message=clean(record.getMessage()) if record.name.startswith(('app.', 'uvicorn.', '__main__', 'filter_export')) else 'External logger event')
+    data.update({key: clean(value) if isinstance(value, str) else value for key, value in record.request_fields.items()})
+    data.update({key: getattr(record, key) for key in _SAFE_FIELDS if hasattr(record, key)})
+    if hasattr(record, 'safe_exceptions'): data['exceptions'] = record.safe_exceptions
+    return data
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record):
+        return json.dumps(record_data(record), ensure_ascii=True, separators=(',', ':'), default=lambda _: '[unsupported]')
+
+
+class ConsoleFormatter(logging.Formatter):
+    def format(self, record):
+        data = record_data(record)
+        suffix = {key: value for key, value in data.items() if key not in ('timestamp', 'level', 'logger', 'message')}
+        return f"{data['timestamp']} {data['level']} {data['logger']}: {data['message']} {json.dumps(suffix, ensure_ascii=True, separators=(',', ':'))}"
+
+
+class SafeConsoleHandler(logging.StreamHandler):
+    def emit(self, record):
+        super().emit(record)
+        record._gc_console_emitted = True
+
+    def handleError(self, record):
+        pass  # A broken console must not change application behavior or expose raw LogRecords.
+
+
+class ApplicationFileHandler(ConcurrentTimedRotatingFileHandler):
+    def __init__(self, filename, retention_days=30):
+        self.retention_days = retention_days
+        self.last_fallback = float('-inf')
+        super().__init__(filename=filename, when='midnight', interval=1, utc=True,
+                         backupCount=retention_days, encoding='utf-8', maxBytes=0)
+        self.cleanup_archives()
+
+    def cleanup_archives(self):
+        cutoff = datetime.now(timezone.utc).date() - timedelta(days=self.retention_days)
+        path = Path(self.baseFilename)
+        for candidate in path.parent.glob(path.name + '.*'):
+            suffix = candidate.name[len(path.name)+1:]
+            if not re.fullmatch(r'\d{4}-\d{2}-\d{2}', suffix): continue
+            try:
+                if datetime.strptime(suffix, '%Y-%m-%d').date() < cutoff: candidate.unlink(missing_ok=True)
+            except (OSError, ValueError):
+                self.fallback(None, 'log_cleanup_failed')
+
+    def doRollover(self):
+        try:
+            super().doRollover()
+        except Exception:
+            self.fallback(None, 'log_rotation_failed')
+            raise
+        self.cleanup_archives()
+
+    def fallback(self, record, event='log_file_unavailable'):
+        handler = SafeConsoleHandler(sys.stderr)
+        handler.setFormatter(ConsoleFormatter())
+        if time.monotonic() - self.last_fallback >= 60:
+            self.last_fallback = time.monotonic()
+            notice = logging.LogRecord('app.logging', logging.ERROR, __file__, 0, 'Logdatei nicht verfügbar; Konsolenfallback aktiv', (), None)
+            notice.event = event
+            ContextFilter().filter(notice); handler.handle(notice)
+        if record is not None and not getattr(record, '_gc_console_emitted', False): handler.handle(record)
+
+    def handleError(self, record):
+        self.fallback(record)
+
+
+def configure_logging(config=None, *, console_stream=None):
+    """Replace only our own handlers; repeated startup in one process is a no-op."""
+    global _configuration
+    if config is None:
+        from .config import settings
+        config = settings
+    directory = Path(config.LOG_DIR)
+    if not directory.is_absolute(): directory = PROJECT_ROOT / directory
+    signature = (os.getpid(), str(directory), config.LOG_LEVEL, config.LOG_TO_FILE, config.LOG_TO_CONSOLE,
+                 config.LOG_RETENTION_DAYS, config.LOG_SQL_STATEMENT, id(console_stream))
+    with _lock:
+        root = logging.getLogger()
+        if _configuration == signature and any(getattr(handler, '_gc_handler', False) for handler in root.handlers): return
+        for handler in list(root.handlers):
+            if getattr(handler, '_gc_handler', False): root.removeHandler(handler); handler.close()
+        handlers, file_failure = [], False
+        if config.LOG_TO_CONSOLE:
+            console = SafeConsoleHandler(console_stream or sys.stderr); console.setFormatter(ConsoleFormatter()); handlers.append(console)
+        if config.LOG_TO_FILE:
+            try:
+                directory.mkdir(parents=True, exist_ok=True)
+                file_handler = ApplicationFileHandler(str(directory / 'application.log'), config.LOG_RETENTION_DAYS)
+                file_handler.setFormatter(JsonFormatter()); handlers.append(file_handler)
+            except Exception:
+                file_failure = True
+                if not handlers:
+                    console = SafeConsoleHandler(console_stream or sys.stderr); console.setFormatter(ConsoleFormatter()); handlers.append(console)
+        if not handlers: handlers.append(logging.NullHandler())
+        for handler in handlers:
+            handler._gc_handler = True; handler.addFilter(ContextFilter()); root.addHandler(handler)
+        root.setLevel(config.LOG_LEVEL)
+        for name in ('uvicorn', 'uvicorn.error', 'uvicorn.access'):
+            logger = logging.getLogger(name); logger.handlers.clear(); logger.propagate = True
+            logger.setLevel(logging.INFO)
+        logging.getLogger('uvicorn.access').disabled = True
+        for name in ('sqlalchemy', 'urllib3', 'httpx', 'httpcore', 'ldap3', 'docuware'):
+            logging.getLogger(name).setLevel(logging.WARNING)
+        _configuration = signature
+        if file_failure: logging.getLogger('app.logging').error('Logverzeichnis nicht verfügbar; Konsolenfallback aktiv', extra={'event': 'log_file_unavailable'})
+
+
+def log_query_error(error, statement=None, query_name=None, operation=None):
+    from .config import settings
+    try:
+        sql = sanitize_sql(statement) if statement is not None else ''
+    except Exception:
+        sql = '[statement unavailable]'
+    metadata = dict(event='database_error', operation=operation or db_operation.get() or 'execute',
+                    query_name=query_name or query_origin(), query_fingerprint=hashlib.sha256(sql.encode()).hexdigest())
+    if settings.LOG_SQL_STATEMENT and sql:
+        metadata.update(sql=sql[:8192], sql_truncated=len(sql) > 8192)
+    roots = exception_roots(error)
+    for root in roots:
+        if not getattr(root, '_gc_log_frames', None): root._gc_log_frames = frames()
+        first = root.args[0] if root.args else None
+        if isinstance(first, str) and re.fullmatch(r'[A-Z0-9]{5}', first): metadata['sqlstate'] = first
+        code = getattr(root, 'sqlite_errorcode', None)
+        if isinstance(code, int): metadata['db_code'] = code
+    logging.getLogger('app.db').error('Datenbankoperation fehlgeschlagen', exc_info=(type(error), error, error.__traceback__), extra=metadata)
+
+
+def query_origin():
+    for item in reversed(traceback.extract_stack()[:-1]):
+        path = Path(item.filename)
+        if PROJECT_ROOT / 'app' in path.parents and path.name not in ('logging_setup.py', 'db.py'):
+            return f'{path.name}:{item.name}'
+    return 'database'
+
+
+def run_cli(callback):
+    configure_logging()
+    try:
+        callback()
+    except Exception:
+        logging.getLogger('app.cli').exception('Hilfsprogramm fehlgeschlagen', extra={'event': 'cli_failed'})
+        raise SystemExit(1) from None

app/main.py

@@ -5,10 +5,13 @@ from fastapi.staticfiles import StaticFiles
 
 from .auth import AuthenticationMiddleware
 from .routes import router
+from .http_logging import install_request_logging
+from .logging_setup import configure_logging
 
 
 @asynccontextmanager
 async def lifespan(_: FastAPI):
+    configure_logging()
     # Create tables for demo if they do not exist
     # Base.metadata.create_all(bind=engine)
     yield
@@ -17,6 +20,7 @@ async def lifespan(_: FastAPI):
 app = FastAPI(title="GCOutline", lifespan=lifespan)
 
 app.add_middleware(AuthenticationMiddleware)
+install_request_logging(app)
 app.include_router(router)
 
 app.mount("/static", StaticFiles(directory="static"), name="static")

app/routes.py

@@ -302,7 +302,7 @@ def get_template_context(request: Request, pkey: dict[str, str], db: Session) ->
             "utf-8"
         )
         values = {"client_db": pkey["Client_DB"], "beleg_nr": pkey["Beleg_Nr"]}
-        template_context[filename] = db.execute(text(query), values).fetchall()
+        template_context[filename] = db.execute(text(query).execution_options(query_name=f'forderungen/details/queries/{filename}.sql'), values).fetchall()
     for section in ("kommentare", "buchungen"):
         template_context.update(section_context(db, pkey, template_context["forderungen_details"][0], section))
     try:
@@ -395,7 +395,7 @@ async def post_forderungen_details(
     ).body.decode("utf-8")
     for subquery in query.split(";"):
         if subquery.strip():
-            db.execute(text(subquery), data)
+            db.execute(text(subquery).execution_options(query_name=f'forderungen/details/queries/post/post_{source}.sql'), data)
     db.commit()
 
     return_url = return_url_for_request(request, primary_key, return_to if return_to is not None else redirect)

filter_export.py

@@ -1,10 +1,15 @@
 import csv
+import logging
 from dataclasses import asdict
 
-from app.routes import FilterConfig, forderung_filter_config
+from app.query_filter import import_filter_config
+from app.logging_setup import run_cli
+
+logger = logging.getLogger(__name__)
 
 
 def export_filter_config():
+    forderung_filter_config = import_filter_config('forderungen')
     with open("filter_config.csv", "w", newline="", encoding="latin-1") as csvfile:
         writer = csv.DictWriter(csvfile, fieldnames=asdict(forderung_filter_config[0]).keys(), delimiter=";")
         writer.writeheader()
@@ -15,13 +20,9 @@ def export_filter_config():
 
 
 def import_filter_config2():
-    with open("forderungen\\liste\\config\\liste_filter.csv", "r", newline="", encoding="latin-1") as csvfile:
-        reader = csv.DictReader(csvfile, delimiter=";")
-        for row in reader:
-            # Convert the row dictionary to a FilterConfig object
-            config = FilterConfig.from_dict(*row.values())
-            print(config)
+    configs = import_filter_config('forderungen')
+    logger.info('Filterkonfiguration geladen', extra={'event': 'filter_config_loaded', 'count': len(configs)})
 
 
 if __name__ == "__main__":
-    import_filter_config2()
+    run_cli(import_filter_config2)

pyproject.toml

@@ -25,4 +25,5 @@ dependencies = [
 	"python-jose>=3.5.0",
 	"requests>=2.34.2",
 	"docuware-client>=0.9.0",
+	"concurrent-log-handler>=0.9.31,<1",
 ]

server.py

@@ -1,11 +1,22 @@
+import argparse
 import uvicorn
 
-if __name__ == "__main__":
+from app.logging_setup import run_cli
+
+def main():
+    parser = argparse.ArgumentParser()
+    parser.add_argument('--no-reload', action='store_true', help='Run without the development reloader')
+    args = parser.parse_args()
     uvicorn.run(
         "app.main:app",
         host="127.0.0.1",
         port=8094,
-        reload=True,
+        reload=not args.no_reload,
         proxy_headers=False,
-        log_level="info",
+        log_config=None,
+        access_log=False,
     )
+
+
+if __name__ == '__main__':
+    run_cli(main)

tests/__init__.py

@@ -0,0 +1,24 @@
+"""Keep application logging used by all test entrypoints in temporary storage."""
+import atexit
+import logging
+import os
+import sys
+import tempfile
+
+_logs = tempfile.TemporaryDirectory(prefix='gcepic-test-logs-')
+os.environ['LOG_DIR'] = _logs.name
+os.environ['LOG_TO_CONSOLE'] = 'false'
+if 'app.config' in sys.modules:
+    sys.modules['app.config'].settings.LOG_DIR = _logs.name
+    sys.modules['app.config'].settings.LOG_TO_CONSOLE = False
+
+
+def _cleanup_logs():
+    for handler in list(logging.getLogger().handlers):
+        if getattr(handler, '_gc_handler', False):
+            logging.getLogger().removeHandler(handler)
+            handler.close()
+    _logs.cleanup()
+
+
+atexit.register(_cleanup_logs)

tests/test_auth.py

@@ -1,3 +1,4 @@
+import tests  # Initialize temporary logging before importing the application.
 import unittest
 from datetime import timedelta
 from unittest.mock import patch

tests/test_debug_auth.py

@@ -1,3 +1,4 @@
+import tests  # Initialize temporary logging before importing the application.
 import unittest
 from html.parser import HTMLParser
 from unittest.mock import patch

tests/test_logging.py

@@ -0,0 +1,411 @@
+"""Logging is tested against isolated engines, ASGI apps and temporary files only."""
+import tests
+import ast
+import asyncio
+from datetime import datetime, timedelta, timezone
+import io
+import json
+import logging
+import multiprocessing
+from pathlib import Path
+import sqlite3
+import tempfile
+import unittest
+from types import SimpleNamespace
+from unittest.mock import MagicMock, patch
+
+import httpx
+from fastapi import FastAPI, HTTPException, Request
+from fastapi.responses import HTMLResponse, StreamingResponse
+from fastapi.staticfiles import StaticFiles
+from fastapi.testclient import TestClient
+from sqlalchemy import Column, Integer, create_engine, text
+from sqlalchemy.orm import declarative_base
+from sqlalchemy.pool import StaticPool
+
+from app.auth import AuthenticationMiddleware
+from app.config import settings, Settings
+from app.db import LoggingSession, install_engine_logging
+from app.http_logging import install_request_logging
+from app.logging_setup import (ApplicationFileHandler, configure_logging, request_context,
+                               run_cli, sanitize_sql)
+from app.oauth_token import create_access_token
+from app.permissions import Entitlement
+import app.logging_setup as setup
+
+SECRET = 'DO_NOT_LOG_SECRET_93'
+
+
+def config(directory, **kwargs):
+    values = dict(LOG_DIR=str(directory), LOG_LEVEL='INFO', LOG_TO_FILE=True, LOG_TO_CONSOLE=True,
+                  LOG_RETENTION_DAYS=30, LOG_SQL_STATEMENT=True)
+    values.update(kwargs)
+    return SimpleNamespace(**values)
+
+
+def process_writer(directory, worker):
+    configure_logging(config(directory, LOG_TO_CONSOLE=False))
+    for index in range(35):
+        logging.getLogger('app.worker').info('Worker event', extra={'event':'worker', 'count':worker*1000+index})
+    for handler in list(logging.getLogger().handlers):
+        if getattr(handler, '_gc_handler', False): handler.close()
+
+
+class LoggingTests(unittest.TestCase):
+    def setUp(self):
+        self.temp = tempfile.TemporaryDirectory(prefix='gcepic-logging-')
+        self.root = Path(self.temp.name)
+        root = logging.getLogger()
+        self.old_handlers, self.old_level = root.handlers[:], root.level
+        root.handlers.clear()
+        self.old_config = setup._configuration
+        self.logger_states = {name:(logger.level, logger.disabled, logger.propagate, logger.handlers[:])
+                              for name,logger in root.manager.loggerDict.items() if isinstance(logger, logging.Logger)}
+        self.console = io.StringIO()
+        self.configuration = config(self.root)
+        configure_logging(self.configuration, console_stream=self.console)
+        self.patch = patch.object(settings, 'LOG_SQL_STATEMENT', True)
+        self.patch.start()
+
+    def tearDown(self):
+        self.patch.stop()
+        root = logging.getLogger()
+        for handler in list(root.handlers):
+            root.removeHandler(handler)
+            if getattr(handler, '_gc_handler', False): handler.close()
+        root.handlers[:] = self.old_handlers; root.setLevel(self.old_level)
+        for name, state in self.logger_states.items():
+            logger = logging.getLogger(name)
+            logger.setLevel(state[0]); logger.disabled=state[1]; logger.propagate=state[2]; logger.handlers[:]=state[3]
+        setup._configuration = self.old_config
+        self.temp.cleanup()
+
+    def records(self):
+        file = self.root/'application.log'
+        return [json.loads(line) for line in file.read_text(encoding='utf-8').splitlines()] if file.exists() else []
+
+    def engine(self, **kwargs):
+        engine = create_engine('sqlite://', poolclass=StaticPool, connect_args={'check_same_thread':False}, hide_parameters=True, **kwargs)
+        install_engine_logging(engine)
+        self.addCleanup(engine.dispose)
+        return engine
+
+    def test_literals_comments_and_identifiers_are_sanitized(self):
+        sql = "SELECT [col1], :bind2, N'O''Brien', 123, -1.23e+4, 0xAFF, .5, \"private\" /* private /* nested */ end */ -- private\nFROM [table2]"
+        safe = sanitize_sql(sql)
+        self.assertNotIn('private', safe); self.assertNotIn('Brien', safe)
+        for value in ['123','1.23','0xAFF','.5']: self.assertNotIn(value, safe)
+        for name in ['[col1]', ':bind2', '[table2]']: self.assertIn(name, safe)
+
+    def test_idempotent_initialization_and_configured_outputs(self):
+        root = logging.getLogger()
+        count = len(root.handlers)
+        configure_logging(self.configuration, console_stream=self.console)
+        self.assertEqual(len(root.handlers), count)
+        logging.getLogger('app.test').info('Started', extra={'event':'started'})
+        self.assertEqual(len(self.records()), 1)
+        self.assertEqual(self.console.getvalue().count('Started'), 1)
+        self.assertRegex(self.records()[0]['timestamp'], r'\.\d{3}[+-]\d{2}:\d{2}$')
+        self.assertEqual(Settings(_env_file=None, LOG_LEVEL='debug').LOG_LEVEL, 'DEBUG')
+
+    def test_sql_error_logged_once_even_when_caught_and_logged_again(self):
+        engine = self.engine()
+        with LoggingSession(engine) as db:
+            for value in ['first-secret', 'second-secret']:
+                try:
+                    db.execute(text("SELECT :value FROM missing_table WHERE 91827=1 AND 'private-value'='private-value'").execution_options(query_name='test.missing'), {'value':value})
+                except Exception:
+                    logging.getLogger('app.service').exception('Operation failed')
+        records = self.records()
+        self.assertEqual(len(records), 2)
+        self.assertTrue(all(row['event']=='database_error' for row in records))
+        self.assertEqual(records[0]['query_fingerprint'], records[1]['query_fingerprint'])
+        self.assertEqual(records[0]['query_name'], 'test.missing')
+        self.assertIn('missing_table', records[0]['sql'])
+        self.assertTrue(records[0]['exceptions'][0]['frames'])
+        combined=json.dumps(records)+self.console.getvalue()
+        for value in ['first-secret','second-secret','private-value','91827','[parameters:']:
+            self.assertNotIn(value, combined)
+
+    def test_connect_and_fetch_errors_are_logged_without_driver_messages(self):
+        def unavailable(): raise sqlite3.OperationalError(SECRET)
+        engine = self.engine(creator=unavailable)
+        with LoggingSession(engine) as db, self.assertRaises(Exception):
+            db.execute(text('SELECT 1').execution_options(query_name='connect.test'))
+        self.assertEqual(len(self.records()), 1)
+        self.assertEqual(self.records()[0]['query_name'], 'connect.test')
+        class Cursor(sqlite3.Cursor):
+            def execute(self, sql, params=()):
+                self.bad_fetch = 'fetch_marker' in sql
+                return super().execute(sql, params)
+            def fetchall(self):
+                if getattr(self,'bad_fetch',False): raise sqlite3.OperationalError(SECRET)
+                return super().fetchall()
+        class Connection(sqlite3.Connection):
+            def cursor(self,*args,**kwargs): return super().cursor(factory=Cursor)
+        engine = self.engine(creator=lambda: sqlite3.connect(':memory:',factory=Connection))
+        with LoggingSession(engine) as db, self.assertRaises(Exception):
+            db.execute(text('SELECT 1 AS fetch_marker')).fetchall()
+        self.assertEqual(len(self.records()), 2)
+        self.assertEqual(self.records()[-1]['operation'], 'fetch')
+        self.assertNotIn(SECRET, json.dumps(self.records())+self.console.getvalue())
+
+    def test_commit_rollback_and_flush_errors_are_captured(self):
+        class Connection(sqlite3.Connection):
+            fail_commit=False; fail_rollback=False
+            def commit(self):
+                if self.fail_commit:
+                    self.fail_commit=False; raise sqlite3.OperationalError(SECRET)
+                return super().commit()
+            def rollback(self):
+                if self.fail_rollback:
+                    self.fail_rollback=False; raise sqlite3.OperationalError(SECRET)
+                return super().rollback()
+        engine=self.engine(creator=lambda:sqlite3.connect(':memory:',factory=Connection))
+        with LoggingSession(engine) as db:
+            db.execute(text('CREATE TABLE sample (id INTEGER PRIMARY KEY)')); db.commit()
+            db.execute(text('INSERT INTO sample VALUES (1)'))
+            db.connection().connection.driver_connection.fail_commit=True
+            with self.assertRaises(Exception): db.commit()
+            db.rollback()
+            db.execute(text('SELECT 1'))
+            db.connection().connection.driver_connection.fail_rollback=True
+            with self.assertRaises(Exception): db.rollback()
+        Base=declarative_base()
+        class Model(Base):
+            __tablename__='unique_sample'
+            id=Column(Integer, primary_key=True)
+        Base.metadata.create_all(engine)
+        with LoggingSession(engine) as db:
+            db.add_all([Model(id=1),Model(id=1)])
+            with self.assertRaises(Exception): db.flush()
+            db.rollback()
+        operations=[row['operation'] for row in self.records() if row.get('event')=='database_error']
+        self.assertIn('commit',operations); self.assertIn('rollback',operations); self.assertIn('flush',operations)
+        self.assertEqual(len(operations),3)
+        self.assertNotIn(SECRET, json.dumps(self.records())+self.console.getvalue())
+
+    def app(self):
+        app=FastAPI()
+        @app.get('/status/{code}')
+        async def response(code:int): return HTMLResponse(SECRET,status_code=code)
+        @app.get('/http-error')
+        async def http_error(): raise HTTPException(400, SECRET)
+        @app.get('/number')
+        async def number(value:int): return value
+        @app.get('/ok')
+        async def ok(request:Request):
+            request.state.principal=SimpleNamespace(username=request.headers.get('x-test-user','tester'))
+            logging.getLogger('app.service').info('Service event')
+            from starlette.concurrency import run_in_threadpool
+            await run_in_threadpool(lambda:logging.getLogger('app.service').info('Thread event'))
+            await asyncio.sleep(.01)
+            return {'ok':True}
+        @app.get('/health')
+        async def health(): return {'ok':True}
+        failure=RuntimeError(SECRET)
+        @app.get('/crash')
+        async def crash(): raise failure
+        @app.get('/stream')
+        async def stream():
+            async def chunks():
+                yield b'first'
+                raise RuntimeError(SECRET)
+            return StreamingResponse(chunks())
+        app.mount('/static',StaticFiles(directory=self.root),name='static')
+        install_request_logging(app)
+        return app, failure
+
+    def test_http_codes_validation_static_and_exception_deduplication(self):
+        app,failure=self.app()
+        with TestClient(app,raise_server_exceptions=False) as client:
+            for code in [400,401,403,404,405,422,500,503]:
+                response=client.get('/status/'+str(code)+'?token='+SECRET,headers={'Authorization':SECRET,'Cookie':'token='+SECRET})
+                self.assertEqual(response.status_code,code)
+                row=self.records()[-1]
+                self.assertEqual(row['level'],'ERROR' if code>=500 else 'WARNING')
+                self.assertEqual(row['request_id'],response.headers['X-Request-ID'])
+                self.assertNotIn('?',row['path'])
+            self.assertEqual(client.get('/number?value='+SECRET).status_code,422)
+            self.assertEqual(client.post('/ok',json={'password':SECRET}).status_code,405)
+            self.assertEqual(client.get('/static/missing.txt').status_code,404)
+            self.assertEqual(client.get('/http-error').status_code,400)
+            crash=client.get('/crash')
+            self.assertEqual(crash.status_code,500)
+            self.assertTrue(crash.headers['X-Request-ID'])
+            repeated=client.get('/crash')
+            self.assertNotEqual(crash.headers['X-Request-ID'],repeated.headers['X-Request-ID'])
+        logging.getLogger('uvicorn.error').error('Exception in ASGI application',exc_info=(RuntimeError,failure,failure.__traceback__))
+        technical=[row for row in self.records() if row.get('event')=='unhandled_exception']
+        self.assertEqual(len(technical),2)
+        self.assertNotIn(SECRET,json.dumps(self.records())+self.console.getvalue())
+
+    def test_caught_query_error_in_http_200_keeps_request_context(self):
+        app=FastAPI()
+        engine=self.engine()
+        @app.get('/caught-query')
+        def caught(request:Request):
+            request.state.principal=SimpleNamespace(username='tester')
+            with LoggingSession(engine) as db:
+                try:
+                    db.execute(text('SELECT :secret FROM missing_http_table').execution_options(query_name='http.caught'), {'secret':SECRET})
+                except Exception:
+                    logging.getLogger('app.service').exception('Query handled')
+            return HTMLResponse('Formularfehler',status_code=200)
+        install_request_logging(app)
+        with TestClient(app) as client:
+            response=client.get('/caught-query')
+        rows=self.records()
+        self.assertEqual([row['event'] for row in rows], ['database_error','http_completed'])
+        self.assertTrue(all(row['request_id']==response.headers['x-request-id'] for row in rows))
+        self.assertTrue(all(row['user']=='tester' for row in rows))
+        self.assertEqual(rows[-1]['status'],200)
+        self.assertNotIn(SECRET,json.dumps(rows)+self.console.getvalue())
+
+    def test_stream_error_keeps_sent_status_and_health_success_is_debug(self):
+        app,_=self.app()
+        with TestClient(app,raise_server_exceptions=False) as client:
+            client.get('/health'); self.assertEqual(self.records(),[])
+            response=client.get('/stream')
+        self.assertEqual(response.status_code,200)
+        summary=next(row for row in self.records() if row.get('event')=='http_completed')
+        self.assertEqual(summary['status'],200); self.assertEqual(summary['outcome'],'stream_failed')
+        self.assertEqual(summary['level'],'ERROR')
+        self.assertNotIn(SECRET,json.dumps(self.records()))
+
+    def test_parallel_request_and_thread_contexts_are_isolated(self):
+        app,_=self.app()
+        async def requests():
+            async with httpx.AsyncClient(transport=httpx.ASGITransport(app=app),base_url='http://test') as client:
+                return await asyncio.gather(*[client.get('/ok?secret='+SECRET,headers={'x-test-user':user,'X-Request-ID':SECRET}) for user in ['alpha','beta']])
+        responses=asyncio.run(requests())
+        ids={response.headers['x-request-id'] for response in responses}
+        self.assertEqual(len(ids),2); self.assertNotIn(SECRET,ids)
+        users={row['request_id']:row['user'] for row in self.records() if row.get('event')=='http_completed'}
+        self.assertEqual(set(users.values()),{'alpha','beta'})
+        for row in self.records(): self.assertEqual(row['user'],users[row['request_id']])
+        self.assertIsNone(request_context.get())
+
+    def test_early_auth_errors_and_htmx_login_are_observed(self):
+        app=FastAPI()
+        @app.post('/write')
+        def write(): return {'ok':True}
+        app.add_middleware(AuthenticationMiddleware)
+        install_request_logging(app)
+        entitlement=(Entitlement('1','10','SC','Mitarbeiter',100),)
+        with patch.multiple(settings,TRUSTED_PROXY_IPS=['testclient'],DEBUG_AUTH=False,COOKIE_SECURE=False), \
+             patch('app.auth.SessionLocal',return_value=MagicMock()), \
+             patch('app.auth.load_entitlements',return_value=entitlement), \
+             patch('app.auth.lookup_directory_user',return_value=None), TestClient(app) as client:
+            denied=client.post('/write',headers={'X-Remote-User':'invalid'})
+            self.assertEqual(denied.status_code,401)
+            login=client.post('/write',headers={'HX-Request':'true'})
+            self.assertEqual(login.status_code,200); self.assertIn('HX-Redirect',login.headers)
+            token=create_access_token(username='tester',name='Tester',email='',role='Mitarbeiter',auth_source='ldap',csrf='csrf')
+            client.cookies.set(settings.SESSION_COOKIE_NAME,token)
+            self.assertEqual(client.post('/write').status_code,403)
+        statuses=[row['status'] for row in self.records() if row.get('event')=='http_completed']
+        self.assertEqual(statuses,[401,200,403])
+        self.assertTrue(any(row.get('event')=='auth_login_required' for row in self.records()))
+
+    def test_retention_rotation_parallel_processes_and_fallback(self):
+        old=self.root/'application.log.2001-01-01'; old.write_text('expired',encoding='utf-8')
+        preserved=self.root/'webservice.log'; preserved.write_text('keep',encoding='utf-8')
+        handler=next(handler for handler in logging.getLogger().handlers if isinstance(handler,ApplicationFileHandler))
+        handler.cleanup_archives(); self.assertFalse(old.exists()); self.assertTrue(preserved.exists())
+        logging.getLogger('app.test').info('before rotation')
+        handler.clh._do_lock()
+        try: handler.doRollover()
+        finally: handler.clh._do_unlock()
+        logging.getLogger('app.test').info('after rotation')
+        self.assertEqual(self.records()[-1]['message'],'after rotation')
+        with patch.object(handler.clh,'do_write',side_effect=PermissionError(SECRET)), patch('sys.stderr',new=io.StringIO()) as fallback:
+            logging.getLogger('app.test').error('safe failure')
+        self.assertIn('Konsolenfallback',fallback.getvalue()); self.assertNotIn(SECRET,fallback.getvalue())
+        directory=self.root/'workers'; directory.mkdir()
+        seed=ApplicationFileHandler(str(directory/'application.log'))
+        seed.setFormatter(setup.JsonFormatter()); seed.addFilter(setup.ContextFilter())
+        seed.handle(logging.LogRecord('app.worker',logging.INFO,__file__,0,'Before shared rotation',(),None))
+        seed.clh._do_lock()
+        try:
+            seed.rolloverAt=int(datetime.now(timezone.utc).timestamp())-10
+            seed.write_rollover_time()
+        finally:
+            seed.clh._do_unlock()
+            seed.close()
+        processes=[multiprocessing.get_context('spawn').Process(target=process_writer,args=(str(directory),n)) for n in range(3)]
+        for process in processes: process.start()
+        for process in processes:
+            process.join(20)
+            if process.is_alive(): process.terminate(); self.fail('Logging worker timed out')
+            self.assertEqual(process.exitcode,0)
+        rows=[json.loads(line) for line in (directory/'application.log').read_text(encoding='utf-8').splitlines()]
+        self.assertEqual(len(rows),105); self.assertEqual(len({row['count'] for row in rows}),105)
+        archived=[json.loads(line) for archive in directory.glob('application.log.*') for line in archive.read_text(encoding='utf-8').splitlines()]
+        self.assertEqual([row['message'] for row in archived],['Before shared rotation'])
+
+    def test_cli_failure_and_disabled_sql_text(self):
+        with patch('app.logging_setup.configure_logging'), self.assertRaises(SystemExit):
+            run_cli(lambda: (_ for _ in ()).throw(RuntimeError(SECRET)))
+        self.assertEqual(self.records()[-1]['event'],'cli_failed')
+        with patch.object(settings,'LOG_SQL_STATEMENT',False), LoggingSession(self.engine()) as db:
+            with self.assertRaises(Exception): db.execute(text('SELECT * FROM missing'))
+        self.assertNotIn('sql',self.records()[-1]); self.assertNotIn(SECRET,self.console.getvalue())
+
+    def test_project_python_has_no_print_calls(self):
+        root=Path(__file__).resolve().parent.parent
+        paths=list((root/'app').rglob('*.py'))+list(root.glob('*.py'))+list((root/'tests').glob('*.py'))
+        for path in paths:
+            tree=ast.parse(path.read_text(encoding='utf-8-sig'))
+            for node in ast.walk(tree):
+                self.assertFalse(isinstance(node,ast.Call) and isinstance(node.func,ast.Name) and node.func.id=='print',str(path))
+
+    def test_file_configuration_failure_falls_back_without_exposing_exception(self):
+        output=io.StringIO()
+        with patch('app.logging_setup.ApplicationFileHandler',side_effect=PermissionError(SECRET)):
+            configure_logging(config(self.root/'denied',LOG_TO_CONSOLE=False),console_stream=output)
+        logging.getLogger('app.service').error('Still available')
+        self.assertIn('Konsolenfallback',output.getvalue())
+        self.assertIn('Still available',output.getvalue())
+        self.assertNotIn(SECRET,output.getvalue())
+
+    def test_cleanup_queries_are_parameterized_and_cli_imports_work(self):
+        import app.cleanup_comments as cleanup
+        import filter_export
+        rows=[SimpleNamespace(Client_DB='1',Beleg_Nr='R1',Timestamp=datetime(2026,1,1),
+                              Benutzer_ID='tester',Kommentar='AZ: 123/45 Schaden '+SECRET+' bei '+SECRET+' eingereicht')]
+        db=MagicMock()
+        db.execute.return_value.fetchall.return_value=rows
+        with patch('app.cleanup_comments.SessionLocal',return_value=db):
+            db.__enter__.return_value=db
+            cleanup.main()
+            cleanup.get_details_from_comments()
+        writes=[call for call in db.execute.call_args_list if 'INSERT' in str(call.args[0]) or 'UPDATE' in str(call.args[0])]
+        self.assertEqual(len(writes),2)
+        for call in writes:
+            self.assertNotIn(SECRET,str(call.args[0]))
+            self.assertIn(SECRET,str(call.args[1]))
+        filter_export.import_filter_config2()
+        self.assertNotIn(SECRET,self.console.getvalue())
+
+    def test_mail_and_docuware_metadata_never_dump_payloads(self):
+        import app.imap as imap
+        import app.docuware_search as docuware_search
+        payload=SECRET.encode()
+        message=SimpleNamespace(subject='WRG123456 '+SECRET,
+                                attachments=[SimpleNamespace(filename=SECRET+'.pdf',payload=payload,size=len(payload))])
+        db=MagicMock(); db.__enter__.return_value=db
+        db.execute.return_value.fetchall.return_value=[('1','WRG123456')]
+        mailbox=MagicMock(); mailbox.login.return_value.__enter__.return_value=mailbox
+        mailbox.fetch.return_value=[message]
+        with patch.dict('os.environ',{'LOCAL_STORAGE':str(self.root/'files')}), \
+             patch('app.imap.SessionLocal',return_value=db),patch('app.imap.MailBox',return_value=mailbox):
+            imap.main()
+        connection=SimpleNamespace(organizations=[SimpleNamespace(file_cabinets=[SECRET],baskets=[SECRET])])
+        with patch('app.docuware_search.docuware.connect',return_value=connection):
+            docuware_search.main()
+        self.assertTrue(any(row.get('event')=='mail_attachment_saved' and row['size_bytes']==len(payload) for row in self.records()))
+        self.assertNotIn(SECRET,json.dumps(self.records())+self.console.getvalue())
+
+
+if __name__=='__main__': unittest.main()

tests/test_navigation.py

@@ -1,3 +1,4 @@
+import tests  # Initialize temporary logging before importing the application.
 import unittest
 from unittest.mock import patch, MagicMock
 from urllib.parse import parse_qs, urlencode, urlsplit

uv.lock

@@ -150,6 +150,18 @@ wheels = [
     { url = "https://files.pythonhosted.org/packages/d1/d6/3965ed04c63042e047cb6a3e6ed1a63a35087b6a609aa3a15ed8ac56c221/colorama-0.4.6-py2.py3-none-any.whl", hash = "sha256:4f1d9991f5acc0ca119f9d443620b77f9d6b33703e51011c16baf57afb285fc6", size = 25335, upload-time = "2022-10-25T02:36:20.889Z" },
 ]
 
+[[package]]
+name = "concurrent-log-handler"
+version = "0.9.31"
+source = { registry = "https://pypi.org/simple" }
+dependencies = [
+    { name = "portalocker" },
+]
+sdist = { url = "https://files.pythonhosted.org/packages/51/e8/1f74620f511493a3e89b5dbfe9fccd55e6fa1de45ecc91bb1d6f5058acb0/concurrent_log_handler-0.9.31.tar.gz", hash = "sha256:2f973d574f083e5692dfef471931f416daf274bbde8b430ed5d9796c532b97cd", size = 47161, upload-time = "2026-10-21T20:09:58.755Z" }
+wheels = [
+    { url = "https://files.pythonhosted.org/packages/85/ea/f5593cecb8c0092ce8b5a28f0837c1b14b66dc463add1da6082031cefa24/concurrent_log_handler-0.9.31-py3-none-any.whl", hash = "sha256:b8c39896862e11bef707051af96bbe381b2e5deec662361076d696b4896dee95", size = 36337, upload-time = "2026-10-21T20:09:57.738Z" },
+]
+
 [[package]]
 name = "dnspython"
 version = "2.8.0"
@@ -349,6 +361,7 @@ source = { virtual = "." }
 dependencies = [
     { name = "aiofiles" },
     { name = "alembic" },
+    { name = "concurrent-log-handler" },
     { name = "docuware-client" },
     { name = "docxtpl" },
     { name = "fastapi", extra = ["standard"] },
@@ -373,6 +386,7 @@ dependencies = [
 requires-dist = [
     { name = "aiofiles", specifier = ">=23.1" },
     { name = "alembic", specifier = ">=1.11" },
+    { name = "concurrent-log-handler", specifier = ">=0.9.31,<1" },
     { name = "docuware-client", specifier = ">=0.9.0" },
     { name = "docxtpl", specifier = ">=0.20.2" },
     { name = "fastapi", extras = ["standard"], specifier = ">=0.95" },
@@ -823,6 +837,15 @@ wheels = [
     { url = "https://files.pythonhosted.org/packages/3b/a4/ab6b7589382ca3df236e03faa71deac88cae040af60c071a78d254a62172/passlib-1.7.4-py2.py3-none-any.whl", hash = "sha256:aa6bca462b8d8bda89c70b382f0c298a20b5560af6cbfa2dce410c0a2fb669f1", size = 525554, upload-time = "2020-10-08T19:00:49.856Z" },
 ]
 
+[[package]]
+name = "portalocker"
+version = "4.4.2"
+source = { registry = "https://pypi.org/simple" }
+sdist = { url = "https://files.pythonhosted.org/packages/7f/d9/586fb0510fdfbd95a86f9d5c5046463aca41a55f6573d1a5a082a62e0acb/portalocker-4.4.2.tar.gz", hash = "sha256:7ac85bb2aa3c7873bf2ac72586fc6154afa4671ac786994a16617a6b7ccb3e5e", size = 310698, upload-time = "2026-10-28T00:24:58.214Z" }
+wheels = [
+    { url = "https://files.pythonhosted.org/packages/e8/43/bca094221a0f9f592fe1e982d090a92075aa302ecaa92c94cc6268a39b2c/portalocker-4.4.2-py3-none-any.whl", hash = "sha256:e661b91af34fc1806740f8e0e42990fe55cd85cbae55675ac48a400a9656a51b", size = 129702, upload-time = "2026-10-28T00:24:56.625Z" },
+]
+
 [[package]]
 name = "pyasn1"
 version = "0.6.3"

webservice/webservice.bat

@@ -1,5 +1,6 @@
-cd %~dp0..
-call .venv\Scripts\activate.bat
+@echo off
+cd /d "%~dp0.."
+call ".venv\Scripts\activate.bat"
 
-uvicorn app.main:app --host 127.0.0.1 --port 8094 --no-proxy-headers > logs\webservice.log 2> logs\errors.log
+python server.py --no-reload
 rem pause