From 40f0eb89a90141c03c54660b8692519b025c81e8 Mon Sep 17 00:00:00 2001 From: smile Date: Mon, 8 Jun 2026 23:13:38 +0200 Subject: [PATCH] db fixing --- cteward_ng/__pycache__/config.cpython-313.pyc | Bin 1752 -> 1751 bytes cteward_ng/app.py | 25 +++++++++ cteward_ng/auth.py | 42 ++++++++++++-- cteward_ng/database.py | 53 +++++++++++++++++- 4 files changed, 113 insertions(+), 7 deletions(-) diff --git a/cteward_ng/__pycache__/config.cpython-313.pyc b/cteward_ng/__pycache__/config.cpython-313.pyc index ac9f7a1e861852d5be113be3ff94084cba703d7e..2227c5d8f8ddd664e16265b225214be4eeea9099 100644 GIT binary patch delta 66 zcmcb?d!3i}GcPX}0}!nKrk0hpk=K<`Tv|W1Bw0VXB(*%TC`C6fT|YTLFD)~Da~5L) TE1&5F29d995{yDc@<2@hu%{DC delta 47 zcmcc4dxMwvGcPX}0}#YqP|nKU$m`0;C^PYd%;r4CXjVS63k)J(*(4Z+isXSR06;|y A2><{9 diff --git a/cteward_ng/app.py b/cteward_ng/app.py index 3fa8aa7..1577a36 100644 --- a/cteward_ng/app.py +++ b/cteward_ng/app.py @@ -13,6 +13,7 @@ from flask_cors import CORS from flask_compress import Compress from config import load_config +import database as db # Bunyan level mapping _BUNYAN_LEVELS = { @@ -81,6 +82,9 @@ def create_app(config_path=None): app.cteward_config = load_config(config_path) _setup_logging(app) + + # Initialize database with MSSQL config (after logging so db logs work) + _init_database(app) _setup_extensions(app) _register_prehandlers(app) _register_blueprints(app) @@ -88,12 +92,33 @@ def create_app(config_path=None): return app +def _init_database(app): + """Initialize the database connection pool from config. + + Mirrors database.init(config.mssql) from startup.js. + """ + mssql_config = app.cteward_config.get('mssql', {}) + # Get logger from app, or use module-level logger as fallback + logger = getattr(app, 'logger', None) + if logger is None: + import logging + logger = logging.getLogger('cteward_ng.database') + + try: + db.init(mssql_config) + logger.info("Database initialized successfully") + except Exception as exc: + logger.error("Failed to initialize database: %s", exc) + raise + + def _setup_logging(app): """Setup structured JSON logging similar to bunyan.""" log_level_name = app.cteward_config.get('loglevel', 'info').lower() logfile = app.cteward_config.get('logfile') log_level = _LEVEL_NAMES.get(log_level_name, logging.INFO) + log_level = "DEBUG" handler = ( RotatingFileHandler(logfile) diff --git a/cteward_ng/auth.py b/cteward_ng/auth.py index 5e0a03c..be93168 100644 --- a/cteward_ng/auth.py +++ b/cteward_ng/auth.py @@ -31,8 +31,10 @@ def check_password(password, hash_value): Supports plaintext and apr1 (MD5 crypt) formats. Replaces Node.js apache-md5 module. """ + logger.debug("Verifying password for hash type: %s", hash_value[:5] if hash_value else 'None') # Plaintext if not hash_value.startswith('$'): + logger.debug("Plaintext password check") return password == hash_value # Parse algorithm tag: $apr1$... @@ -42,6 +44,7 @@ def check_password(password, hash_value): raise ValueError("Password hashing algorithm not selected") if algo == 'apr1': + logger.debug("apr1 MD5 crypt verification for hash %s...", hash_value[:8]) try: return apr_md5_crypt.verify(password, hash_value) except Exception as exc: @@ -58,15 +61,19 @@ def _parse_basic_auth(request): """ auth_header = request.headers.get('Authorization', '') if not auth_header: + logger.debug("No Authorization header present") return None parts = auth_header.split(' ', 1) if len(parts) != 2 or parts[0] != 'Basic': + logger.debug("Invalid Authorization header format") return None try: decoded = base64.b64decode(parts[1]).decode('utf-8') username, _, password = decoded.partition(':') + logger.debug("Basic auth parsed: username=%s", username) return (username, password) except Exception: + logger.warning("Failed to decode Basic auth header") return None @@ -79,10 +86,12 @@ def find_botuser(ctx): """ if ctx.get('username') is not None: # Already authenticated as bot or LDAP user + logger.debug("Username already set: %s, skipping bot auth", ctx.get('username')) return ctx auth = _parse_basic_auth(ctx['request']) if auth is None: + logger.debug("No Basic auth found, skipping bot auth") return ctx username, password = auth @@ -91,17 +100,21 @@ def find_botuser(ctx): if bot_pass is None: # Not a known bot — pass through to LDAP + logger.debug("User '%s' not found in bot config, trying LDAP", username) return ctx + logger.info("Attempting bot auth for user '%s'", username) try: match = check_password(password, bot_pass) except Exception as exc: - logger.error("Bot password check error: %s", exc) + logger.error("Bot password check error for user '%s': %s", username, exc) abort(500, description=str(exc)) if not match: + logger.warning("Bot auth failed for user '%s' - invalid password", username) abort(401, description="Not authorized. #2") + logger.info("Bot auth successful for user '%s'", username) ctx['username'] = username return ctx @@ -116,26 +129,32 @@ def find_ldapuser(ctx): it just means "not this identity"). """ if ctx.get('username') is not None: + logger.debug("Username already set: %s, skipping LDAP auth", ctx.get('username')) return ctx auth = _parse_basic_auth(ctx['request']) if auth is None: + logger.debug("No Basic auth found, skipping LDAP auth") return ctx ldap_config = ctx['config'].get('ldap') if ldap_config is None: # No LDAP configured — can't authenticate this way - logger.critical("NO LDAP") + logger.critical("NO LDAP configuration found") return ctx username, password = auth + logger.info("Attempting LDAP auth for user '%s'", username) try: authenticated = _authenticate_ldap(ldap_config, username, password) except ConnectionError as exc: - logger.error("LDAP connection failed: %s", exc) + logger.error("LDAP connection failed for user '%s': %s", username, exc) abort(500, description="LDAP connection failed.") if authenticated: + logger.info("LDAP auth successful for user '%s'", username) ctx['username'] = username + else: + logger.debug("LDAP auth failed for user '%s' - invalid credentials", username) return ctx @@ -148,6 +167,9 @@ def _authenticate_ldap(config, username, password): """ from ldap3 import Server, Connection, ALL, SUBTREE + server_url = config.get('url', 'ldap://localhost') + logger.debug("LDAP bind attempt: server=%s, bindDN=%s", server_url, config.get('bindDN', '').format(username=username)) + try: server = Server( config.get('url', 'ldap://localhost'), @@ -166,14 +188,15 @@ def _authenticate_ldap(config, username, password): if config.get('searchBase'): # Verify the user actually exists in the directory - logger.critical("searchBase: %s", config.get('searchFilter', '(uid={})').format(username=username)) + search_filter = config.get('searchFilter', '(uid={})').format(username=username) + logger.debug("LDAP search: base=%s, filter=%s", config['searchBase'], search_filter) conn.search( search_base=config['searchBase'], - search_filter=config.get('searchFilter', '(uid={})').format(username=username), + search_filter=search_filter, search_scope=SUBTREE, attributes=config.get('attributes', []), ) - logger.critical("search done") + logger.debug("LDAP search returned %d entries", len(conn.entries)) if not conn.entries: return False @@ -195,19 +218,25 @@ def authorize(ctx): perms = ctx.get('permissions', {}) auth = _parse_basic_auth(req) + logger.debug("Authorization started, credentials present: %s", auth is not None) + # No credentials at all — allow only if anonymous access is permitted if auth is None: if '_anonymous_' not in perms: + logger.warning("Authorization failed: no credentials and anonymous access prohibited") abort(401, description="Not authorized, anonymous access prohibited.") # Anonymous path — set a sentinel username + logger.info("Anonymous access granted") ctx['username'] = 'anonymous' ctx['flags'] = ['_anonymous_'] else: # Pipeline: bot → LDAP → config flags → DB flags → impersonate → permissions + logger.debug("Running auth pipeline for user '%s'", auth[0] if auth else 'unknown') find_botuser(ctx) find_ldapuser(ctx) if ctx.get('username') is None: + logger.warning("Authorization failed: authentication not successful") abort(401, description="Not authorized. #5") # Config-level flags @@ -217,4 +246,5 @@ def authorize(ctx): impersonate(ctx) effective_permissions(ctx) + logger.info("Authorization complete for user '%s'", ctx.get('username', 'unknown')) return ctx diff --git a/cteward_ng/database.py b/cteward_ng/database.py index 4d01092..115d7c5 100644 --- a/cteward_ng/database.py +++ b/cteward_ng/database.py @@ -29,17 +29,25 @@ def init(config=None): Args: config: dict with MSSQL connection parameters. If None, uses safe defaults that will fail on first query. + If config['fakedata'] is True, skips actual connection (for tests). """ global _pool if config is None: config = {} + # Support fake data mode for testing + if config.get('fakedata'): + logger.info("Fake data mode enabled - skipping database connection") + return + user = config.get('user', 'readonly') password = config.get('password', 'XXXXXXXXXXXXXXXX') server = config.get('server', 'localhost') port = str(config.get('port', '1433')) database = config.get('database', 'Linear') + logger.info("Initializing MSSQL connection pool: server=%s, database=%s", server, database) + dsn = ( f"DRIVER={{ODBC Driver 18 for SQL Server}};" f"SERVER={server},{port};" @@ -50,6 +58,8 @@ def init(config=None): "TrustServerCertificate=yes;" ) + logger.debug("ODBC DSN: %s...", dsn[:50]) + try: _pool = PooledDB( creator=pyodbc, @@ -78,13 +88,16 @@ def init(config=None): def _get_connection(): """Get a connection from the pool, creating it if needed.""" if _pool is None: + logger.error("Database not initialized. Call init() first.") raise RuntimeError("Database not initialized. Call init() first.") + logger.debug("Acquiring connection from pool") return _pool.connection() def connected(): """Check if the connection pool is alive and reachable.""" if _pool is None: + logger.debug("Connection pool not initialized") return False try: conn = _pool.connection() @@ -93,8 +106,10 @@ def connected(): cursor.fetchone() cursor.close() conn.close() + logger.debug("Database connectivity check passed") return True - except Exception: + except Exception as exc: + logger.error("Database connectivity check failed: %s", exc) return False @@ -107,6 +122,7 @@ def check_backend_okay(): - Member count >= 7 - No duplicate crewnames """ + logger.info("Running backend health check") conn = _get_connection() cursor = conn.cursor() @@ -114,6 +130,7 @@ def check_backend_okay(): # Member count check cursor.execute("SELECT COUNT(*) AS MemberCount FROM Adresse") row = cursor.fetchone() + logger.debug("Member count: %d", row.MemberCount) if row.MemberCount < 7: raise RuntimeError("Too few members.") @@ -125,12 +142,15 @@ def check_backend_okay(): "HAVING COUNT(*) > 1" ) duplicates = cursor.fetchall() + logger.debug("Duplicate crewname check returned %d results", len(duplicates)) if duplicates: raise RuntimeError("Duplicate membernames.") finally: cursor.close() conn.close() + logger.info("Backend health check passed") + def _exec_query(statement, params_list): """Execute a parameterized query and return rows as list of dicts. @@ -142,12 +162,14 @@ def _exec_query(statement, params_list): Returns: list of dict rows keyed by column name. """ + logger.debug("Executing query: %s with params %s", statement[:80], params_list) conn = _get_connection() cursor = conn.cursor() try: cursor.execute(statement, params_list) columns = [desc[0] for desc in cursor.description] rows = [dict(zip(columns, row)) for row in cursor.fetchall()] + logger.debug("Query returned %d rows", len(rows)) return rows finally: cursor.close() @@ -171,16 +193,21 @@ def run_query(query_def, params): RuntimeError: if query parameters are missing. Exception: on database errors. """ + logger.debug("run_query called with special=%s", query_def.get('special')) # Handle special stats queries special = query_def.get('special') if special: if special == QUERY_STATS_MEMBERS['special']: + logger.info("Executing stats query: members") return run_query_stats_members() if special == QUERY_STATS_CONTRACTS['special']: + logger.info("Executing stats query: contracts") return run_query_stats_contracts() if special == QUERY_STATS_GENDERS['special']: + logger.info("Executing stats query: genders") return run_query_stats_genders() if special == QUERY_STATS_AGES['special']: + logger.info("Executing stats query: ages") return run_query_stats_ages(params) raise ValueError(f"Unknown special query: {special}") @@ -188,14 +215,17 @@ def run_query(query_def, params): param_names = query_def.get('params', []) if not param_names: + logger.debug("Executing query with no params") return _exec_query(statement, []) # Validate all required params are provided missing = [p for p in param_names if p not in params] if missing: + logger.error("Missing query parameters: %s", missing) raise RuntimeError(f"Missing query parameters: {missing}") params_list = [params[p] for p in param_names] + logger.debug("Executing query with params: %s", params_list) return _exec_query(statement, params_list) @@ -211,6 +241,7 @@ def _get_date_range(table, min_col, max_col): Returns (mindate, maxdate) as datetime objects. """ + logger.debug("Getting date range for table=%s, min_col=%s, max_col=%s", table, min_col, max_col) conn = _get_connection() cursor = conn.cursor() try: @@ -220,7 +251,9 @@ def _get_date_range(table, min_col, max_col): ) row = cursor.fetchone() if not row: + logger.debug("No data found in %s, using epoch dates", table) return datetime(1970, 1, 1), datetime.now() + logger.debug("Date range for %s: %s to %s", table, row[0], row[1]) return row[0] or datetime(1970, 1, 1), row[1] or datetime.now() finally: cursor.close() @@ -238,7 +271,9 @@ def run_query_stats_members(): Returns list of dicts: [{'Year': int, 'Month': int, 'Members': int}, ...] Counts active members (joined before month-end, not yet left) per month. """ + logger.info("Starting members stats query") mindate, maxdate = _get_date_range('Adresse', 'Eintritt', 'Austritt') + logger.debug("Members date range: %s to %s", mindate, maxdate) results = [] year = mindate.year @@ -264,6 +299,7 @@ def run_query_stats_members(): month = 1 year += 1 + logger.info("Members stats query complete: %d months returned", len(results)) return results @@ -273,7 +309,9 @@ def run_query_stats_contracts(): Returns list of dicts: [{'Year': int, 'Month': int, 'Contracts': [{'Type': str, 'Count': int}, ...]}, ...] """ + logger.info("Starting contracts stats query") mindate, maxdate = _get_date_range('MgVert', 'VertragBegin', 'VertragEnde') + logger.debug("Contracts date range: %s to %s", mindate, maxdate) results = [] year = mindate.year @@ -306,6 +344,7 @@ def run_query_stats_contracts(): month = 1 year += 1 + logger.info("Contracts stats query complete: %d months returned", len(results)) return results @@ -315,7 +354,9 @@ def run_query_stats_genders(): Returns list of dicts: [{'Year': int, 'Month': int, 'Male': int, 'Female': int, 'Business': int, 'Other': int}, ...] """ + logger.info("Starting gender stats query") mindate, maxdate = _get_date_range('Adresse', 'Eintritt', 'Austritt') + logger.debug("Gender stats date range: %s to %s", mindate, maxdate) results = [] year = mindate.year @@ -367,6 +408,7 @@ def run_query_stats_genders(): month = 1 year += 1 + logger.info("Gender stats query complete: %d months returned", len(results)) return results @@ -379,10 +421,12 @@ def run_query_stats_ages(params=None): params: optional dict with query params 'step', 'min', 'max' for age bucket configuration. Defaults: step=10, min=20, max=60. """ + logger.info("Starting age stats query") if params is None: params = {} mindate, maxdate = _get_date_range('Adresse', 'Eintritt', 'Austritt') + logger.debug("Age stats date range: %s to %s", mindate, maxdate) # Parse age bucket parameters try: @@ -398,6 +442,8 @@ def run_query_stats_ages(params=None): except (ValueError, TypeError): limit_max = 60 + logger.debug("Age stats params: step=%d, min=%d, max=%d", step, limit_min, limit_max) + # Convert year-based limits to age-based thisyear = datetime.now().year if limit_min > 200: @@ -473,6 +519,7 @@ def run_query_stats_ages(params=None): month = 1 year += 1 + logger.info("Age stats query complete: %d months returned", len(results)) return results @@ -490,13 +537,17 @@ def member_lookup(crewname): Raises: RuntimeError: if not found or multiple rows returned. """ + logger.debug("Member lookup for crewname: %s", crewname) rows = _exec_query( "SELECT Kurzname, Kennung3, Eintritt, Austritt " "FROM Adresse WHERE Kurzname = ?", [crewname], ) + logger.debug("Member lookup returned %d rows", len(rows)) if len(rows) != 1: + logger.error("Member lookup for '%s': expected 1 row, got %d", crewname, len(rows)) raise RuntimeError(f"Member lookup for '{crewname}': expected 1 row, got {len(rows)}") + logger.info("Member lookup successful for '%s'", crewname) return rows[0]