Merge pull request #92 from OpenMined/fix/improve-500-exception-logging

shubham3121 · web-flow · commit d1ab2c4dbf84 · 2026-02-26T13:55:27.000+05:30
Improve logging with log rotation and configurable log level
diff --git a/Dockerfile b/Dockerfile
@@ -82,6 +82,7 @@ ENV PATH="/app/.venv/bin:$PATH" \
     PYTHONUNBUFFERED=1 \
     SYFT_PORT=8080 \
     SYFT_SQLITE_DB_PATH=/data/app.db \
+    SYFT_LOG_FILE=/data/logs/syft-space-server.log \
     DOCKER_NETWORK_HOST=host.docker.internal
 
 EXPOSE 8080
diff --git a/backend/syft_space/components/datasets/handlers.py b/backend/syft_space/components/datasets/handlers.py
@@ -121,7 +121,7 @@ async def _ensure_provisioner_running(
                 state=new_state_dict,
             )
         except Exception as e:
-            # Error already logged by provisioner, just update state and raise
+            logger.exception(f"Failed to start provisioner for '{dtype}': {e}")
             await self.provisioner_state_repository.upsert_status(
                 dtype=dtype,
                 status=ProvisionerStatus.ERROR,
@@ -181,7 +181,7 @@ async def _stop_provisioner(self, dtype: str) -> None:
                 status=ProvisionerStatus.STOPPED,
             )
         except Exception as e:
-            logger.error(f"Failed to stop provisioner for '{dtype}': {e}")
+            logger.exception(f"Failed to stop provisioner for '{dtype}': {e}")
             await self.provisioner_state_repository.upsert_status(
                 dtype=dtype,
                 status=ProvisionerStatus.ERROR,
@@ -273,7 +273,7 @@ async def shutdown_all_provisioners(self) -> None:
             try:
                 await self._stop_provisioner(state.dtype)
             except Exception as e:
-                logger.error(f"Failed to stop provisioner '{state.dtype}': {e}")
+                logger.exception(f"Failed to stop provisioner '{state.dtype}': {e}")
                 # Continue with other provisioners - best effort shutdown
 
     # ============== Dataset Type Methods ==============
@@ -533,7 +533,7 @@ async def delete_dataset(self, name: str, tenant: Tenant) -> dict:
                 f"Dataset type '{dataset.dtype}' not registered, skipping resource cleanup"
             )
         except Exception as e:
-            logger.error(f"Failed to clean up resources for dataset '{name}': {e}")
+            logger.exception(f"Failed to clean up resources for dataset '{name}': {e}")
 
         deleted = await self.repository.delete_by_name(name, tenant.id)
         if not deleted:
diff --git a/backend/syft_space/components/datasets/provisioner_manager.py b/backend/syft_space/components/datasets/provisioner_manager.py
@@ -48,7 +48,7 @@ async def _startup_provisioners_background(self) -> None:
             await self.dataset_handler.startup_all_provisioners()
             logger.info("Provisioner startup complete")
         except Exception as e:
-            logger.error(f"Error during provisioner startup: {e}")
+            logger.exception(f"Error during provisioner startup: {e}")
         finally:
             # Signal that provisioner startup is done (success or failure)
             # This allows ingestion to proceed even if provisioners failed
@@ -65,4 +65,4 @@ async def shutdown(self) -> None:
             await self.dataset_handler.shutdown_all_provisioners()
             logger.info("Provisioner shutdown complete")
         except Exception as e:
-            logger.error(f"Error during provisioner shutdown: {e}")
+            logger.exception(f"Error during provisioner shutdown: {e}")
diff --git a/backend/syft_space/components/endpoints/handlers.py b/backend/syft_space/components/endpoints/handlers.py
@@ -406,6 +406,7 @@ async def _search_dataset(
         try:
             search_result = await dataset_instance.search(ctx, query, search_params)
         except Exception as e:
+            logger.exception(f"Dataset search failed: {e}")
             raise HTTPException(
                 status_code=500, detail=f"Dataset search failed: {str(e)}"
             ) from e
@@ -451,12 +452,16 @@ async def _chat_with_model(
             endpoint.model_id, endpoint.tenant_id
         )
         if not model:
+            logger.error(
+                f"Model not found: model_id={endpoint.model_id}, tenant_id={endpoint.tenant_id}"
+            )
             raise HTTPException(status_code=500, detail="Model not found")
 
         # Get model type
         try:
             model_type_cls = self.model_registry.get_model_type(model.dtype)
         except KeyError:
+            logger.exception(f"Model type '{model.dtype}' not registered")
             raise HTTPException(
                 status_code=500, detail=f"Model type '{model.dtype}' not registered"
             ) from None
@@ -500,6 +505,7 @@ async def _chat_with_model(
             # Chat with the model
             chat_result = await model_instance.chat(ctx, messages, chat_params)
         except Exception as e:
+            logger.exception(f"Model chat failed: {e}")
             raise HTTPException(
                 status_code=500, detail=f"Model chat failed: {str(e)}"
             ) from e
@@ -508,6 +514,11 @@ async def _chat_with_model(
         # For simplicity, take the last message
         last_message = chat_result.messages[-1] if chat_result.messages else None
         if not last_message:
+            logger.error(
+                "Model returned no messages: "
+                f"model_id={endpoint.model_id}, "
+                f"chat_result_id={chat_result.id}"
+            )
             raise HTTPException(status_code=500, detail="Model returned no messages")
 
         return SummaryResponse(
@@ -550,6 +561,7 @@ async def publish_endpoint(
             HTTPException: If endpoint not found or marketplace repository not configured
         """
         if not self.marketplace_repository:
+            logger.error("Marketplace publishing is not configured")
             raise HTTPException(
                 status_code=500,
                 detail="Marketplace publishing is not configured",
@@ -607,6 +619,7 @@ async def unpublish_endpoint(
     ) -> list[UnpublishResult]:
         """Unpublish an endpoint from all its marketplaces."""
         if not self.marketplace_repository:
+            logger.error("Marketplace unpublishing is not configured")
             raise HTTPException(
                 status_code=500,
                 detail="Marketplace publishing is not configured",
@@ -683,7 +696,7 @@ async def _unpublish_endpoint(
                 error=e.message,
             )
         except Exception as e:
-            logger.error(
+            logger.exception(
                 f"Failed to unpublish endpoint {endpoint.slug} from {marketplace.name}: {str(e)}"
             )
             return UnpublishResult(
@@ -798,6 +811,7 @@ async def check_slug_availability(
 
         # Check marketplace availability
         if not self.marketplace_repository:
+            logger.error("Marketplace checking is not configured")
             raise HTTPException(
                 status_code=500,
                 detail="Marketplace checking is not configured",
@@ -1017,7 +1031,7 @@ async def sync_endpoints_to_marketplaces(
                     f"Failed to sync to marketplace {marketplace_id}: {e.message}"
                 )
             except Exception as e:
-                logger.error(
+                logger.exception(
                     f"Unexpected error syncing to marketplace {marketplace_id}: {e}"
                 )
 
diff --git a/backend/syft_space/components/ingestion/manager.py b/backend/syft_space/components/ingestion/manager.py
@@ -286,14 +286,14 @@ async def _start_existing_dataset_watchers(self) -> None:
                     try:
                         await self.start_dataset_ingestion(dataset)
                     except Exception as e:
-                        logger.error(
+                        logger.exception(
                             f"Failed to start ingestion for '{dataset.name}': {e}"
                         )
             logger.info(
                 f"Background: Started ingestion for {len(all_datasets)} datasets"
             )
         except Exception as e:
-            logger.error(f"Failed to start existing dataset watchers: {e}")
+            logger.exception(f"Failed to start existing dataset watchers: {e}")
 
     async def shutdown(self) -> None:
         """Shutdown the ingestion manager."""
@@ -361,7 +361,7 @@ async def _event_processor_loop(self) -> None:
                 # Queue was closed during shutdown
                 break
             except Exception as e:
-                logger.error(f"Error processing file event: {e}")
+                logger.exception(f"Error processing file event: {e}")
 
         logger.info("Event processor stopped")
 
@@ -522,7 +522,7 @@ async def _process_single_job(self, job: IngestionJob) -> None:
             logger.info(f"Successfully ingested: {job.file_path}")
 
         except Exception as e:
-            logger.error(f"Failed to ingest {job.file_path}: {str(e)}")
+            logger.exception(f"Failed to ingest {job.file_path}: {str(e)}")
             await self._ingestion_repository.update_status(
                 job.id, IngestionJobStatus.FAILED, str(e)
             )
@@ -608,7 +608,7 @@ async def _start_watcher(self, dataset: Dataset) -> bool:
                     f"(recursive={recursive})"
                 )
             except Exception as e:
-                logger.error(f"Failed to watch path {watch_path}: {e}")
+                logger.exception(f"Failed to watch path {watch_path}: {e}")
 
         self._watches[dataset.id] = watches
         return len(watches) > 0
diff --git a/backend/syft_space/components/settings/handlers.py b/backend/syft_space/components/settings/handlers.py
@@ -168,7 +168,7 @@ async def configure_proxy(self, tenant: Tenant, token: str) -> ProxyStatusRespon
         try:
             public_url = await self.proxy_service.connect(token, marketplace.username)
         except Exception as e:
-            logger.error(f"Failed to connect to ngrok: {e}")
+            logger.exception(f"Failed to connect to ngrok: {e}")
             raise HTTPException(status_code=400, detail=str(e)) from e
 
         await self.sync_public_url_to_marketplace(marketplace, public_url)
diff --git a/backend/syft_space/components/shared/database.py b/backend/syft_space/components/shared/database.py
@@ -152,7 +152,7 @@ def do_run_migrations(connection) -> None:
                     except Exception as stamp_error:
                         logger.warning(f"Could not stamp database: {stamp_error}")
                 else:
-                    logger.error(f"Migration failed in production mode: {e}")
+                    logger.exception(f"Migration failed in production mode: {e}")
                     raise RuntimeError(
                         f"Database migration failed. This is fatal in production. "
                         f"Error: {e}"
diff --git a/backend/syft_space/components/shared/heartbeat_manager.py b/backend/syft_space/components/shared/heartbeat_manager.py
@@ -166,7 +166,7 @@ async def _heartbeat_loop(self) -> None:
             except asyncio.CancelledError:
                 break
             except Exception as e:
-                logger.error(f"Unexpected error in heartbeat loop: {e}")
+                logger.exception(f"Unexpected error in heartbeat loop: {e}")
                 # Wait before retrying
                 try:
                     await asyncio.wait_for(
@@ -297,7 +297,7 @@ async def _send_heartbeat_to_marketplace(
             )
         except Exception as e:
             self._update_state_on_failure(state)
-            logger.error(
+            logger.exception(
                 f"Unexpected error sending heartbeat to {marketplace.name}: {e}"
             )
 
diff --git a/backend/syft_space/components/shared/logging_config.py b/backend/syft_space/components/shared/logging_config.py
@@ -9,18 +9,35 @@
 import inspect
 import logging
 import sys
+from pathlib import Path
 
 from loguru import logger
 
+from syft_space.config import app_settings
+
 # Remove loguru's default handler
 logger.remove()
 
-# Add handler with simplified format
+# Console handler (stderr)
+# colorize=None lets loguru auto-detect TTY (colors in terminals, plain in Docker/pipes)
 logger.add(
     sys.stderr,
     format="<green>{time:YYYY-MM-DD HH:mm:ss}</green> | <level>{level: <5}</level> | <cyan>{name}</cyan> - <level>{message}</level>",
-    level="INFO",
-    colorize=True,
+    level=app_settings.log_level.upper(),
+    colorize=None,
+)
+
+# File handler
+log_path = Path(app_settings.log_file).expanduser()
+log_path.parent.mkdir(parents=True, exist_ok=True)
+logger.add(
+    str(log_path.resolve()),
+    format="{time:YYYY-MM-DD HH:mm:ss} | {level: <5} | {name} - {message}",
+    level=app_settings.log_level.upper(),
+    rotation="50 MB",
+    retention="7 days",
+    compression="gz",
+    colorize=False,
 )
 
 
diff --git a/backend/syft_space/components/shared/proxy_service.py b/backend/syft_space/components/shared/proxy_service.py
@@ -193,7 +193,7 @@ async def auto_connect_if_configured(self) -> None:
             await self._settings_repository.update_public_url(public_url)
             logger.info(f"Ngrok tunnel auto-connected: {public_url}")
         except Exception as e:
-            logger.error(f"Failed to auto-connect ngrok tunnel: {e}")
+            logger.exception(f"Failed to auto-connect ngrok tunnel: {e}")
             # Don't clear the token on auto-connect failure
             # User can retry or reconfigure
 
@@ -204,7 +204,7 @@ async def _auto_connect_background(self) -> None:
             await self.auto_connect_if_configured()
             self.log_connection_info()
         except Exception as e:
-            logger.error(f"Background proxy startup error: {e}")
+            logger.exception(f"Background proxy startup error: {e}")
         finally:
             # Always signal completion (success or failure)
             if self._ready_event:
@@ -288,7 +288,7 @@ async def _reconnect_loop(self) -> None:
                     delay = self.RECONNECT_INITIAL_DELAY  # Reset delay on success
                     logger.info("Ngrok tunnel reconnected successfully")
                 except Exception as e:
-                    logger.error(f"Reconnection failed: {e}")
+                    logger.exception(f"Reconnection failed: {e}")
                     # Exponential backoff
                     delay = min(
                         delay * self.RECONNECT_BACKOFF_FACTOR, self.RECONNECT_MAX_DELAY
diff --git a/backend/syft_space/components/shared/syfthub_client.py b/backend/syft_space/components/shared/syfthub_client.py
@@ -246,7 +246,7 @@ def _extract_validation_errors(response: httpx.Response) -> list[dict[str, Any]]
         if isinstance(data, dict) and isinstance(data.get("detail"), list):
             return data["detail"]
     except Exception as e:
-        logger.error(f"Error extracting validation errors: {e}")
+        logger.exception(f"Error extracting validation errors: {e}")
     return []
 
 
diff --git a/backend/syft_space/components/tenants/dependency.py b/backend/syft_space/components/tenants/dependency.py
@@ -6,6 +6,7 @@
 """
 
 from fastapi import HTTPException, Request
+from loguru import logger
 
 from syft_space.components.tenants.context import get_current_tenant
 from syft_space.components.tenants.entities import Tenant
@@ -37,6 +38,9 @@ async def list_datasets(tenant: Tenant = Depends(get_tenant_dependency)):
     """
     tenant = get_current_tenant()
     if tenant is None:
+        logger.error(
+            "Tenant context not set. Middleware may not be configured correctly."
+        )
         raise HTTPException(
             status_code=500,
             detail="Tenant context not set. Middleware may not be configured correctly.",
diff --git a/backend/syft_space/components/tenants/middleware.py b/backend/syft_space/components/tenants/middleware.py
@@ -73,6 +73,9 @@ async def dispatch(self, request: Request, call_next: Callable) -> Response:
 
             # Validate tenant exists
             if tenant is None:
+                logger.error(
+                    "Default tenant not found. Database may not be initialized."
+                )
                 return Response(
                     status_code=500,
                     content='{"detail":"Default tenant not found. Database may not be initialized."}',
diff --git a/backend/syft_space/config.py b/backend/syft_space/config.py
@@ -33,6 +33,16 @@ class AppSettings(BaseSettings):
     # Application settings
     debug: bool = False
 
+    # Logging settings
+    log_level: str = Field(
+        default="INFO",
+        description="Log level for all handlers (DEBUG, INFO, WARNING, ERROR)",
+    )
+    log_file: str = Field(
+        default="~/.syft-space/logs/syft-space-server.log",
+        description="Path to log file. If set, enables file logging with rotation. Example: /data/logs/syft-space.log",
+    )
+
     # Reset database settings
     reset_db: bool = Field(
         default=False,
diff --git a/backend/syft_space/main.py b/backend/syft_space/main.py
@@ -215,7 +215,7 @@ async def _setup_tenant_and_settings(
     try:
         await settings_hdlr.initialize_from_config(tenants=[default_tenant])
     except Exception as e:
-        logger.error(f"⚠️  Warning: Failed to initialize settings from config: {e}")
+        logger.exception(f"Failed to initialize settings from config: {e}")
 
     return default_tenant
 
@@ -260,7 +260,7 @@ async def lifespan(app: FastAPI):
         try:
             await service.startup()
         except Exception as e:
-            logger.error(f"Failed to start {name}: {e}")
+            logger.exception(f"Failed to start {name}: {e}")
 
     # 6. Fire-and-forget sync tasks (wait for proxy to be ready first)
     if default_tenant:
@@ -296,7 +296,7 @@ async def lifespan(app: FastAPI):
         try:
             await service.shutdown()
         except Exception as e:
-            logger.error(f"Error shutting down {name}: {e}")
+            logger.exception(f"Error shutting down {name}: {e}")
 
     # 9. Dispose database engine (close all pooled connections)
     await database.dispose()
