Merge pull request #236 from minvws/logging-proeftuin

Added additional logging

Author: jaytaph

app/auth.py

@@ -57,14 +57,17 @@ def get_auth_ctx(
         return ctx
 
     if creds is None or creds.scheme.lower() != "bearer":
-        logger.error("Missing or invalid bearer token")
+        logger.error("missing or invalid bearer token")
         raise HTTPException(status_code=401, detail="Missing bearer token")
 
     try:
         claims = client_oauth_service.verify(request)
     except OAuthError as e:
-        logger.error(f"OAuth verification failed: {e.description}")
-        raise HTTPException(status_code=e.status_code, detail=e.description) from e
+        desc = getattr(e, "description", None) or str(e)
+        status = getattr(e, "status_code", None) or 401
+
+        logger.exception("oauth verification failed (status=%s): %r", status, desc)
+        raise HTTPException(status_code=status, detail="Invalid or unauthorized request") from e
 
     ctx = AuthContext(
         claims=claims,

app/db/db.py

@@ -23,25 +23,25 @@ def __init__(self, dsn: str):
             else:
                 self.engine = create_engine(dsn, echo=False)
         except BaseException as e:
-            logger.error("Error while connecting to database: %s", e)
+            logger.error("error while connecting to database: %s", e)
             raise e
 
     def generate_tables(self) -> None:
-        logger.info("Generating tables...")
+        logger.info("generating tables...")
         Base.metadata.create_all(self.engine)
 
     def truncate_tables(self) -> None:
-        logger.info("Truncating all tables...")
+        logger.info("truncating all tables...")
         try:
             metadata = MetaData()
             metadata.reflect(bind=self.engine)
             with Session(self.engine) as session:
                 for table in reversed(metadata.sorted_tables):
                     session.execute(text(f"DELETE FROM {table.name}"))
                 session.commit()
-            logger.info("All tables truncated successfully.")
+            logger.info("all tables truncated successfully.")
         except Exception as e:
-            logger.error("Error while truncating tables: %s", e)
+            logger.error("error while truncating tables: %s", e)
             raise e
 
     def is_healthy(self) -> bool:
@@ -55,7 +55,7 @@ def is_healthy(self) -> bool:
                 session.execute(text("SELECT 1"))
             return True
         except Exception as e:
-            logger.info("Database is not healthy: %s", e)
+            logger.info("database is not healthy: %s", e)
             return False
 
     def get_db_session(self) -> DbSession:

app/db/entities/base.py

@@ -4,6 +4,9 @@
 
 
 class Base(DeclarativeBase):
+    """
+    Base class for all database entities.
+    """
     def to_dict(self) -> Dict[str, Any]:
         return {col.name: getattr(self, col.name) for col in self.__table__.columns}
 

app/db/entities/organization.py

@@ -9,6 +9,9 @@
 
 
 class Organization(Base):
+    """
+    Represents an organization in the database.
+    """
     __tablename__ = "organization"
 
     id: Mapped[uuid.UUID] = mapped_column(UUID(as_uuid=True), primary_key=True, default=uuid.uuid4)

app/db/entities/organization_key.py

@@ -9,6 +9,9 @@
 
 
 class OrganizationKey(Base):
+    """
+    Represents a key associated with an organization in the database.
+    """
     __tablename__ = "organization_key"
 
     id: Mapped[uuid.UUID] = mapped_column(UUID(as_uuid=True), primary_key=True, default=uuid.uuid4)

app/db/repositories/org_repository.py

@@ -32,6 +32,7 @@ def create(self, ura: str, name: str, max_usage_level: str) -> Organization:
         self.db_session.session.add(entry)
         self.db_session.session.flush()
 
+        logger.info("created organization with URA %s and name %r", ura, name)
         return entry
 
     def update(self, org_id: uuid.UUID, name: str, max_usage_level: str) -> Optional[Organization]:
@@ -40,6 +41,7 @@ def update(self, org_id: uuid.UUID, name: str, max_usage_level: str) -> Optional
         """
         org = self.get_by_id(org_id)
         if org is None:
+            logger.error(f"organization with ID {org_id} does not exist")
             raise ValueError("Organization not found")
 
         org.name = name # type: ignore
@@ -53,6 +55,7 @@ def delete(self, org_id: uuid.UUID) -> bool:
         """
         org = self.get_by_id(org_id)
         if org is None:
+            logger.error("organization with ID %s does not exist", org_id)
             return False
 
         self.db_session.session.delete(org)

app/db/repositories/repository_base.py

@@ -4,6 +4,9 @@
 
 
 class RepositoryBase:
+    """
+    Base class for all repositories, providing common functionality.
+    """
     def __init__(self, db_session: session.DbSession):
         self.db_session = db_session
 

app/db/session.py

@@ -129,21 +129,21 @@ def _retry(self, f: Callable[..., T], *args: Any, **kwargs: Any) -> T:
             try:
                 return f(*args, **kwargs)
             except PendingRollbackError as e:
-                logger.warning("Retrying operation due to PendingRollbackError: %s", e)
+                logger.warning("retrying operation due to PendingRollbackError: %s", e)
                 self.session.rollback()
             except OperationalError as e:
-                logger.warning("Retrying operation due to OperationalError: %s", e)
+                logger.warning("retrying operation due to OperationalError: %s", e)
             except DatabaseError as e:
-                logger.warning("Retrying operation due to DatabaseError: %s", e)
+                logger.warning("retrying operation due to DatabaseError: %s", e)
                 raise e
             except Exception as e:
-                logger.warning("Generic Exception during operation: %s", e)
+                logger.warning("generic Exception during operation: %s", e)
                 raise e
 
             if len(backoff) == 0:
-                logger.error("Operation failed after all retries")
+                logger.error("operation failed after all retries")
                 raise DatabaseError("Operation failed after all retries", None, BaseException())
 
-            logger.info("Retrying operation in %s seconds", backoff[0])
+            logger.info("retrying operation in %s seconds", backoff[0])
             sleep(backoff[0] + random.uniform(0, 0.1))
             backoff = backoff[1:]

app/models/requests.py

@@ -1,3 +1,4 @@
+import logging
 from typing import Any, Literal, List
 
 from pydantic import BaseModel, ConfigDict, model_validator, Field, field_validator
@@ -6,6 +7,7 @@
 from app.services.pseudonym_service import PseudonymType
 from app.rid import RidUsage
 
+logger = logging.getLogger(__name__)
 
 class RegisterRequest(BaseModel):
     scope: List[str]
@@ -18,6 +20,7 @@ class OrgRequest(BaseModel):
     @field_validator("ura")
     def ura_must_be_numbers(cls, v: Any) -> Any:
         if not v.isdigit():
+            logger.warning("URA must contain only digits (got %s)", v)
             raise ValueError("URA must contain 8 digits")
         return v
 
@@ -100,6 +103,7 @@ def validate_jwe(cls, data: dict[str, Any]) -> dict[str, Any]:
         # Check if JWE is actually a jwe token
         jwe_token = data.get("jwe")
         if not isinstance(jwe_token, str) or len(jwe_token.split('.')) != 5:
+            logger.warning("invalid JWE token format: %s", jwe_token)
             raise ValueError("Invalid JWE token")
         return data
 
@@ -108,6 +112,7 @@ def validate_jwe(cls, data: dict[str, Any]) -> dict[str, Any]:
     def validate_priv_key_pem(cls, data: dict[str, Any]) -> dict[str, Any]:
         priv_key_pem = data.get("priv_key_pem")
         if not isinstance(priv_key_pem, str) or not priv_key_pem.startswith("-----BEGIN PRIVATE KEY-----"):
+            logger.warning("invalid private key PEM format")
             raise ValueError("Invalid private key PEM format")
         return data
 
@@ -122,6 +127,7 @@ def validate_jwe(cls, data: dict[str, Any]) -> dict[str, Any]:
         # Check if JWE is actually a jwe token
         jwe_token = data.get("jwe")
         if not isinstance(jwe_token, str) or len(jwe_token.split('.')) != 5:
+            logger.warning("invalid JWE token format: %s", jwe_token)
             raise ValueError("Invalid JWE token")
         return data
 
@@ -130,5 +136,6 @@ def validate_jwe(cls, data: dict[str, Any]) -> dict[str, Any]:
     def validate_priv_key_pem(cls, data: dict[str, Any]) -> dict[str, Any]:
         priv_key_pem = data.get("priv_key_pem")
         if not isinstance(priv_key_pem, str) or not priv_key_pem.startswith("-----BEGIN PRIVATE KEY-----"):
+            logger.warning("invalid private key PEM format")
             raise ValueError("Invalid private key PEM format")
         return data

app/routers/default.py

@@ -28,7 +28,7 @@ def index() -> Response:
             content += "\nVersion: %s\nCommit: %s" % (data['version'], data['git_ref'])
     except BaseException as e:
         content += "\nNo version information found"
-        logger.info("Version info could not be loaded: %s" % e)
+        logger.info("version info could not be loaded: %s" % e)
 
     return Response(content)
 
@@ -39,7 +39,7 @@ def version_json() -> Response:
         with open(Path(__file__).parent.parent.parent / 'version.json', 'r') as file:
             content = file.read()
     except BaseException as e:
-        logger.info("Version info could not be loaded: %s" % e)
+        logger.info("version info could not be loaded: %s" % e)
         return Response(status_code=404)
 
     return Response(content)