Sync from GitHub via hub-sync

Dockerfile

@@ -32,4 +32,6 @@ FROM app AS fastapi
 CMD ["uvicorn", "faceverification.interfaces.fastapi_app:app", "--host", "0.0.0.0", "--port", "8000"]
 
 FROM app AS gradio
+ENV GRADIO_SERVER_NAME=0.0.0.0 \
+    GRADIO_SERVER_PORT=7860
 CMD ["python", "-m", "faceverification.interfaces.gradio_app"]

README.md

@@ -49,14 +49,14 @@ Using uv:
 
 ```bash
 uv sync
-uv run python app.py
+uv run faceverification
 ```
 
 Using pip:
 
 ```bash
-pip install -r requirements.txt
-python app.py
+pip install -r requirements.txt -e .
+python -m faceverification.interfaces.gradio_app
 ```
 
 ## FastAPI Interface
@@ -65,7 +65,7 @@ The project includes an HTTP API for the same enroll-and-verify workflow.
 Run it locally with:
 
 ```bash
-uv run uvicorn faceverification.interfaces.fastapi_app:app --host 0.0.0.0 --port 8000
+uv run uvicorn faceverification.interfaces.fastapi_app:app --port 8000
 ```
 
 Interactive API documentation is available at:
@@ -86,8 +86,15 @@ FACEVERIFICATION_DEMO_PASSWORD=demo123
 FACEVERIFICATION_JWT_SECRET_KEY=replace-this-with-a-long-random-secret
 FACEVERIFICATION_JWT_ACCESS_TOKEN_EXPIRE_MINUTES=60
 FACEVERIFICATION_MAX_UPLOAD_BYTES=5242880
+FACEVERIFICATION_DEBUG=false
+FACEVERIFICATION_LOG_FORMAT=json
 ```
 
+`FACEVERIFICATION_DEBUG=true` raises application logging to debug level and uses
+a readable text formatter by default, which is useful for local troubleshooting.
+Keep it `false` in normal deployments; Container Apps sends stdout logs to Log
+Analytics, where the default JSON format is easier to query.
+
 ```bash
 curl -X POST http://localhost:8000/auth/login \
   -F "username=demo" \
@@ -195,6 +202,11 @@ unless `FACEVERIFICATION_VECTOR_DB_PERSIST_DIRECTORY` is explicitly provided.
 The default container configuration sets `FACEVERIFICATION_DEVICE=cpu` to keep
 deployment portable.
 
+Local Docker Compose defaults `FACEVERIFICATION_DEBUG=true` and
+`FACEVERIFICATION_LOG_FORMAT=text` for developer ergonomics. Azure Container
+Apps sets `FACEVERIFICATION_DEBUG=false` and `FACEVERIFICATION_LOG_FORMAT=json`
+for lower-volume structured logs in Log Analytics.
+
 The shared local ChromaDB volume is intended for a small demo deployment when a
 persist name is enabled. For a multi-container production setup with concurrent
 writers or multiple replicas, use an external database/vector-store service or

docker-compose.yml

@@ -11,6 +11,8 @@ services:
       FACEVERIFICATION_DEMO_USERNAME: ${FACEVERIFICATION_DEMO_USERNAME:-demo}
       FACEVERIFICATION_DEMO_PASSWORD: ${FACEVERIFICATION_DEMO_PASSWORD:-demo123}
       FACEVERIFICATION_JWT_SECRET_KEY: ${FACEVERIFICATION_JWT_SECRET_KEY:-change-me-in-production-demo-secret-32-bytes-min}
+      FACEVERIFICATION_DEBUG: ${FACEVERIFICATION_DEBUG:-true}
+      FACEVERIFICATION_LOG_FORMAT: ${FACEVERIFICATION_LOG_FORMAT:-text}
     healthcheck:
       test: [ "CMD", "python", "-c", "import urllib.request; urllib.request.urlopen('http://127.0.0.1:8000/health', timeout=5)" ]
       interval: 30s
@@ -29,5 +31,5 @@ services:
       - "7860:7860"
     environment:
       FACEVERIFICATION_DEVICE: cpu
-      GRADIO_SERVER_NAME: 0.0.0.0
-      GRADIO_SERVER_PORT: 7860
+      FACEVERIFICATION_DEBUG: ${FACEVERIFICATION_DEBUG:-true}
+      FACEVERIFICATION_LOG_FORMAT: ${FACEVERIFICATION_LOG_FORMAT:-text}

infra/bicep/main.bicep

@@ -133,6 +133,14 @@ resource app 'Microsoft.App/containerApps@2024-03-01' = {
               name: 'FACEVERIFICATION_DEVICE'
               value: 'cpu'
             }
+            {
+              name: 'FACEVERIFICATION_DEBUG'
+              value: 'false'
+            }
+            {
+              name: 'FACEVERIFICATION_LOG_FORMAT'
+              value: 'json'
+            }
             {
               name: 'FACEVERIFICATION_DEMO_USERNAME'
               secretRef: 'demo-username'

src/faceverification/config.py

@@ -4,6 +4,9 @@ from pydantic_settings import BaseSettings, SettingsConfigDict
 
 
 class Settings(BaseSettings):
+    debug: bool = False
+    log_format: Literal["json", "text"] = "json"
+
     vector_db_distance_metric: str = "l2"
     vector_db_collection: str = "face_embeddings"
     vector_db_persist_directory: str | None = None

src/faceverification/core/image_processor.py

@@ -1,5 +1,6 @@
 """Face detection and FaceNet embedding utilities."""
 
+import logging
 from collections.abc import Sequence
 
 import torch
@@ -9,6 +10,8 @@ from PIL import Image, ImageDraw
 
 from faceverification.config import settings
 
+logger = logging.getLogger(__name__)
+
 
 class FaceNotDetectedError(ValueError):
     """Raised when no face can be detected in an image."""
@@ -49,6 +52,17 @@ class ImageProcessor:
             thresholds=list(mtcnn_thresholds),
         )
         self.facenet = InceptionResnetV1(pretrained=facenet_pretrained).eval().to(self.device)
+        logger.info(
+            "image_processor_initialized",
+            extra={
+                "extra_fields": {
+                    "event": "image_processor_initialized",
+                    "device": self.device,
+                    "mtcnn_thresholds": list(mtcnn_thresholds),
+                    "facenet_pretrained": facenet_pretrained,
+                }
+            },
+        )
 
     def get_embedding(self, image: Image.Image) -> torch.Tensor:
         """Return a normalized FaceNet embedding for the detected face.
@@ -64,6 +78,10 @@ class ImageProcessor:
         """
         face_tensor = self.mtcnn(image)
         if face_tensor is None:
+            logger.debug(
+                "face_embedding_no_face",
+                extra={"extra_fields": {"event": "face_embedding_no_face"}},
+            )
             raise FaceNotDetectedError("No face detected in the image.")
 
         face_tensor = (face_tensor.unsqueeze(0) if face_tensor.ndim == 3 else face_tensor).to(
@@ -74,6 +92,16 @@ class ImageProcessor:
             features = self.facenet(face_tensor)
             features = F.normalize(features, p=2, dim=1)
 
+        logger.debug(
+            "face_embedding_created",
+            extra={
+                "extra_fields": {
+                    "event": "face_embedding_created",
+                    "shape": list(features.shape),
+                    "device": self.device,
+                }
+            },
+        )
         return features.squeeze(0)
 
     def detect_faces(self, image: Image.Image) -> tuple[Image.Image, bool]:
@@ -88,8 +116,25 @@ class ImageProcessor:
         boxes, probs = self.mtcnn.detect(image)
 
         if boxes is None:
+            logger.debug(
+                "face_detection_completed",
+                extra={"extra_fields": {"event": "face_detection_completed", "face_count": 0}},
+            )
             return image, False
 
+        probabilities = [float(prob) for prob in probs]
+        logger.debug(
+            "face_detection_completed",
+            extra={
+                "extra_fields": {
+                    "event": "face_detection_completed",
+                    "face_count": len(boxes),
+                    "min_probability": min(probabilities),
+                    "max_probability": max(probabilities),
+                }
+            },
+        )
+
         draw = ImageDraw.Draw(image)
         for box, prob in zip(boxes, probs, strict=True):
             x1, y1, x2, y2 = [int(v) for v in box]

src/faceverification/core/vectordb.py

@@ -1,5 +1,6 @@
 """Small ChromaDB adapter for face embedding storage and lookup."""
 
+import logging
 import uuid
 from collections.abc import Mapping
 from typing import Any
@@ -10,6 +11,8 @@ from chromadb.config import Settings as ChromaSettings
 
 from faceverification.config import settings
 
+logger = logging.getLogger(__name__)
+
 
 class VectorDB:
     """Store face embeddings and query the nearest known identity."""
@@ -43,6 +46,17 @@ class VectorDB:
         self.collection = self.client.get_or_create_collection(
             name=name_collection, metadata={"hnsw:space": distance_metric}
         )
+        logger.info(
+            "vector_db_initialized",
+            extra={
+                "extra_fields": {
+                    "event": "vector_db_initialized",
+                    "collection": name_collection,
+                    "distance_metric": distance_metric,
+                    "persistent": bool(persist_directory),
+                }
+            },
+        )
 
     def add_embedding(self, embedding: np.ndarray, metadata: Mapping[str, Any]) -> None:
         """Store one embedding with its metadata.
@@ -56,6 +70,16 @@ class VectorDB:
             metadatas=[metadata],
             ids=[str(uuid.uuid4())],
         )
+        logger.debug(
+            "vector_db_embedding_added",
+            extra={
+                "extra_fields": {
+                    "event": "vector_db_embedding_added",
+                    "embedding_shape": list(embedding.shape),
+                    "metadata_keys": sorted(metadata.keys()),
+                }
+            },
+        )
 
     def query_embedding(
         self,
@@ -79,6 +103,17 @@ class VectorDB:
         if n_results is None:
             n_results = settings.vector_db_n_results
 
+        logger.debug(
+            "vector_db_query_started",
+            extra={
+                "extra_fields": {
+                    "event": "vector_db_query_started",
+                    "threshold": threshold,
+                    "n_results": n_results,
+                    "embedding_shape": list(embedding.shape),
+                }
+            },
+        )
         result = self.collection.query(
             query_embeddings=[embedding],
             include=["metadatas", "distances", "embeddings"],
@@ -86,6 +121,10 @@ class VectorDB:
         )
         embeddings = result.get("embeddings")
         if not embeddings or embeddings[0] is None or len(embeddings[0]) == 0:
+            logger.warning(
+                "vector_db_query_empty",
+                extra={"extra_fields": {"event": "vector_db_query_empty"}},
+            )
             raise ValueError(
                 "No record found in the vector database. Add a person before verifying faces."
             )
@@ -98,7 +137,21 @@ class VectorDB:
                 best_dist = dist
                 best_idx = i
 
-        if best_dist <= threshold:
+        matched = best_dist <= threshold
+        logger.debug(
+            "vector_db_query_completed",
+            extra={
+                "extra_fields": {
+                    "event": "vector_db_query_completed",
+                    "matched": matched,
+                    "best_distance": float(best_dist),
+                    "threshold": threshold,
+                    "candidate_count": len(result["embeddings"][0]),
+                }
+            },
+        )
+
+        if matched:
             return result["metadatas"][0][best_idx], best_dist
         else:
             return None, best_dist

src/faceverification/interfaces/fastapi_app.py

@@ -4,7 +4,9 @@ from contextlib import asynccontextmanager
 from datetime import UTC, datetime, timedelta
 from io import BytesIO
 from secrets import compare_digest
+from time import perf_counter
 from typing import Annotated, Protocol
+from uuid import uuid4
 
 import jwt
 from fastapi import Depends, FastAPI, File, Form, HTTPException, Query, Request, UploadFile, status
@@ -15,8 +17,11 @@ from pydantic import BaseModel
 
 from faceverification.config import settings
 from faceverification.core.image_processor import FaceNotDetectedError
+from faceverification.logging_config import configure_logging, request_id_context
 from faceverification.services.face_verification import UNREGISTERED_PERSON
 
+configure_logging()
+
 bearer_scheme = HTTPBearer(auto_error=False)
 logger = logging.getLogger(__name__)
 
@@ -107,6 +112,48 @@ app = FastAPI(
 )
 
 
+@app.middleware("http")
+async def log_requests(request: Request, call_next):
+    request_id = request.headers.get("x-request-id") or str(uuid4())
+    context_token = request_id_context.set(request_id)
+    started_at = perf_counter()
+
+    try:
+        response = await call_next(request)
+    except Exception:
+        elapsed_ms = round((perf_counter() - started_at) * 1000, 2)
+        logger.exception(
+            "request_failed",
+            extra={
+                "extra_fields": {
+                    "event": "request_failed",
+                    "method": request.method,
+                    "path": request.url.path,
+                    "duration_ms": elapsed_ms,
+                }
+            },
+        )
+        raise
+    else:
+        elapsed_ms = round((perf_counter() - started_at) * 1000, 2)
+        response.headers["x-request-id"] = request_id
+        logger.info(
+            "request_completed",
+            extra={
+                "extra_fields": {
+                    "event": "request_completed",
+                    "method": request.method,
+                    "path": request.url.path,
+                    "status_code": response.status_code,
+                    "duration_ms": elapsed_ms,
+                }
+            },
+        )
+        return response
+    finally:
+        request_id_context.reset(context_token)
+
+
 class HealthResponse(BaseModel):
     status: str = "ok"
 
@@ -226,6 +273,16 @@ async def _read_image(upload: UploadFile) -> Image.Image:
         )
 
     contents = await upload.read()
+    logger.debug(
+        "upload_received",
+        extra={
+            "extra_fields": {
+                "event": "upload_received",
+                "content_type": upload.content_type,
+                "size_bytes": len(contents),
+            }
+        },
+    )
     if not contents:
         raise HTTPException(
             status_code=status.HTTP_400_BAD_REQUEST,
@@ -240,7 +297,19 @@ async def _read_image(upload: UploadFile) -> Image.Image:
     try:
         image = Image.open(BytesIO(contents))
         image = ImageOps.exif_transpose(image)
-        return image.convert("RGB")
+        rgb_image = image.convert("RGB")
+        logger.debug(
+            "upload_image_decoded",
+            extra={
+                "extra_fields": {
+                    "event": "upload_image_decoded",
+                    "width": rgb_image.width,
+                    "height": rgb_image.height,
+                    "mode": rgb_image.mode,
+                }
+            },
+        )
+        return rgb_image
     except (UnidentifiedImageError, OSError) as exc:
         raise HTTPException(
             status_code=status.HTTP_400_BAD_REQUEST,
@@ -269,8 +338,17 @@ def _bad_service_request(exc: ValueError) -> HTTPException:
     )
 
 
-def _unexpected_service_error(exc: Exception) -> HTTPException:
-    logger.exception("Face verification service failed")
+def _unexpected_service_error(exc: Exception, operation: str) -> HTTPException:
+    logger.exception(
+        "face_service_failed",
+        extra={
+            "extra_fields": {
+                "event": "face_service_failed",
+                "operation": operation,
+                "exception_type": type(exc).__name__,
+            }
+        },
+    )
     return HTTPException(
         status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
         detail="Face verification failed.",
@@ -314,8 +392,13 @@ def login(
     ],
 ) -> TokenResponse:
     if not _authenticate_demo_user(username, password):
+        logger.warning(
+            "auth_login_failed",
+            extra={"extra_fields": {"event": "auth_login_failed"}},
+        )
         raise _unauthorized_error("Incorrect username or password.")
 
+    logger.debug("auth_login_succeeded", extra={"extra_fields": {"event": "auth_login_succeeded"}})
     return TokenResponse(access_token=_create_access_token(username))
 
 
@@ -353,6 +436,16 @@ async def enroll_person(
         )
 
     pil_image = await _read_image(image)
+    logger.debug(
+        "face_enroll_started",
+        extra={
+            "extra_fields": {
+                "event": "face_enroll_started",
+                "name_length": len(cleaned_name),
+                "include_image": include_image,
+            }
+        },
+    )
     try:
         annotated_image = service.add_person(pil_image, cleaned_name)
     except FaceNotDetectedError as exc:
@@ -360,7 +453,17 @@ async def enroll_person(
     except ValueError as exc:
         raise _bad_service_request(exc) from exc
     except Exception as exc:
-        raise _unexpected_service_error(exc) from exc
+        raise _unexpected_service_error(exc, "enroll") from exc
+
+    logger.debug(
+        "face_enroll_completed",
+        extra={
+            "extra_fields": {
+                "event": "face_enroll_completed",
+                "include_image": include_image,
+            }
+        },
+    )
 
     return EnrollResponse(
         message="Person added to the embeddings database.",
@@ -391,6 +494,10 @@ async def verify_identity(
 ) -> VerifyResponse:
     _ = current_username
     pil_image = await _read_image(image)
+    logger.debug(
+        "face_verify_started",
+        extra={"extra_fields": {"event": "face_verify_started", "include_image": include_image}},
+    )
     try:
         name, annotated_image = service.verify_person(pil_image)
     except FaceNotDetectedError as exc:
@@ -398,11 +505,23 @@ async def verify_identity(
     except ValueError as exc:
         raise _bad_service_request(exc) from exc
     except Exception as exc:
-        raise _unexpected_service_error(exc) from exc
+        raise _unexpected_service_error(exc, "verify") from exc
+
+    matched = name != UNREGISTERED_PERSON
+    logger.debug(
+        "face_verify_completed",
+        extra={
+            "extra_fields": {
+                "event": "face_verify_completed",
+                "matched": matched,
+                "include_image": include_image,
+            }
+        },
+    )
 
     return VerifyResponse(
         name=name,
-        matched=name != UNREGISTERED_PERSON,
+        matched=matched,
         annotated_image=_image_to_data_url(annotated_image) if include_image else None,
     )
 

src/faceverification/interfaces/gradio_app.py

@@ -1,8 +1,20 @@
+from functools import cache
+from os import getenv
+
 import gradio as gr
 from PIL import Image
 
 from faceverification.core.image_processor import FaceNotDetectedError
-from faceverification.services.face_verification import add_person, verify_person
+from faceverification.logging_config import configure_logging
+
+configure_logging()
+
+
+@cache
+def _face_service():
+    from faceverification.services.face_verification import add_person, verify_person
+
+    return add_person, verify_person
 
 
 def add_person_ui(image: Image.Image | None, name: str) -> Image.Image:
@@ -12,6 +24,7 @@ def add_person_ui(image: Image.Image | None, name: str) -> Image.Image:
         if not name or not name.strip():
             raise gr.Error("Enter a name before adding the person.")
 
+        add_person, _ = _face_service()
         return add_person(image, name.strip())
     except FaceNotDetectedError as exc:
         raise gr.Error(str(exc)) from exc
@@ -24,6 +37,7 @@ def verify_person_ui(image: Image.Image | None) -> tuple[str, Image.Image]:
         if image is None:
             raise gr.Error("Upload an image before verifying an identity.")
 
+        _, verify_person = _face_service()
         name, annotated_image = verify_person(image)
         return name, annotated_image
     except FaceNotDetectedError as exc:
@@ -168,7 +182,8 @@ If a face is detected, the annotated image confirms what face was stored.
 
 def main():
     FV_gr.launch(
-        server_port=7860,
+        server_name=getenv("GRADIO_SERVER_NAME") or None,
+        server_port=int(getenv("GRADIO_SERVER_PORT", "7860")),
         theme=APP_THEME,
         css=APP_CSS,
     )

src/faceverification/logging_config.py

@@ -0,0 +1,66 @@
+import json
+import logging
+import sys
+from contextvars import ContextVar
+from datetime import UTC, datetime
+from typing import Any
+
+from faceverification.config import settings
+
+request_id_context: ContextVar[str | None] = ContextVar("request_id", default=None)
+
+
+class RequestContextFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        record.request_id = request_id_context.get()
+        return True
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        payload: dict[str, Any] = {
+            "timestamp": datetime.fromtimestamp(record.created, UTC).isoformat(),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+        }
+
+        request_id = getattr(record, "request_id", None)
+        if request_id:
+            payload["request_id"] = request_id
+
+        for key, value in getattr(record, "extra_fields", {}).items():
+            if value is not None:
+                payload[key] = value
+
+        if record.exc_info:
+            payload["exception"] = self.formatException(record.exc_info)
+
+        return json.dumps(payload, ensure_ascii=False, default=str)
+
+
+def _build_handler() -> logging.Handler:
+    handler = logging.StreamHandler(sys.stdout)
+    handler.addFilter(RequestContextFilter())
+
+    if settings.log_format == "text":
+        formatter = logging.Formatter(
+            "%(asctime)s %(levelname)s [%(name)s] request_id=%(request_id)s %(message)s"
+        )
+    else:
+        formatter = JsonFormatter()
+
+    handler.setFormatter(formatter)
+    return handler
+
+
+def configure_logging() -> None:
+    level = logging.DEBUG if settings.debug else logging.INFO
+    handler = _build_handler()
+
+    logging.basicConfig(level=level, handlers=[handler], force=True)
+    logging.getLogger("uvicorn.access").setLevel(logging.WARNING)
+    logging.getLogger("multipart").setLevel(logging.WARNING)
+
+    if not settings.debug:
+        logging.getLogger("PIL").setLevel(logging.WARNING)

src/faceverification/services/face_verification.py

@@ -1,11 +1,14 @@
 """Application service functions for face enrollment and verification."""
 
+import logging
+
 from PIL import Image
 
 from faceverification.core.image_processor import FaceNotDetectedError, ImageProcessor
 from faceverification.core.vectordb import VectorDB
 
 UNREGISTERED_PERSON = "Unregistered Person"
+logger = logging.getLogger(__name__)
 
 image_processor = ImageProcessor()
 
@@ -27,9 +30,17 @@ def add_person(image: Image.Image, name: str) -> Image.Image:
         TypeError: If embedding extraction returns an unexpected value.
     """
 
+    logger.debug(
+        "face_enrollment_started",
+        extra={"extra_fields": {"event": "face_enrollment_started", "name_length": len(name)}},
+    )
     img, presence = image_processor.detect_faces(image)
 
     if not presence:
+        logger.debug(
+            "face_enrollment_no_face",
+            extra={"extra_fields": {"event": "face_enrollment_no_face"}},
+        )
         raise FaceNotDetectedError("No faces were detected in the image.")
 
     faces_pt = image_processor.get_embedding(img)
@@ -37,6 +48,10 @@ def add_person(image: Image.Image, name: str) -> Image.Image:
         raise TypeError("The extracted face embedding is not a torch.Tensor.")
 
     vector_db.add_embedding(faces_pt.cpu().numpy(), {"name": name})
+    logger.debug(
+        "face_enrollment_completed",
+        extra={"extra_fields": {"event": "face_enrollment_completed"}},
+    )
 
     return img
 
@@ -54,18 +69,46 @@ def verify_person(image: Image.Image) -> tuple[str, Image.Image]:
         FaceNotDetectedError: If no face is detected.
         ValueError: If the vector database has no stored embeddings.
     """
+    logger.debug(
+        "face_verification_started",
+        extra={"extra_fields": {"event": "face_verification_started"}},
+    )
     detected_faces, presence = image_processor.detect_faces(image.copy())
 
     if not presence:
+        logger.debug(
+            "face_verification_no_face",
+            extra={"extra_fields": {"event": "face_verification_no_face"}},
+        )
         raise FaceNotDetectedError("No faces were detected in the image.")
 
     faces_pt = image_processor.get_embedding(image)
     if faces_pt is None:
         raise FaceNotDetectedError("No faces were detected in the image.")
 
-    metadata, _ = vector_db.query_embedding(faces_pt.cpu().numpy())
+    metadata, distance = vector_db.query_embedding(faces_pt.cpu().numpy())
 
     if metadata:
+        logger.debug(
+            "face_verification_completed",
+            extra={
+                "extra_fields": {
+                    "event": "face_verification_completed",
+                    "matched": True,
+                    "distance": distance,
+                }
+            },
+        )
         return metadata["name"], detected_faces
 
+    logger.debug(
+        "face_verification_completed",
+        extra={
+            "extra_fields": {
+                "event": "face_verification_completed",
+                "matched": False,
+                "distance": distance,
+            }
+        },
+    )
     return UNREGISTERED_PERSON, detected_faces