db fixing

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)

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

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]