Merge pull request #36 from stuartcampbell/improve-logging

Small improvements to logging

.vscode/launch.json

@@ -11,7 +11,8 @@
             "module": "uvicorn",
             "args": [
                 "nsls2api.main:app",
-                "--reload"
+                "--reload",
+                "--log-config=uvicorn_log_config.yml"
             ],
             "jinja": true,
             "justMyCode": true

Dockerfile

@@ -9,5 +9,10 @@ RUN pip install --no-cache-dir --upgrade -r /code/requirements.txt
 COPY . . 
 RUN pip install '.'
 
-CMD ["uvicorn", "nsls2api.main:app", "--proxy-headers", "--host", "0.0.0.0", "--port", "8080", "--workers", "4", "--ssl-keyfile=/etc/nsls2/tls/server.key", "--ssl-certfile=/etc/nsls2/tls/server.cer"]
+CMD ["uvicorn", "nsls2api.main:app", "--proxy-headers", \ 
+                "--host", "0.0.0.0", "--port", "8080",  \
+                "--workers", "4", \ 
+                "--ssl-keyfile=/etc/nsls2/tls/server.key", \
+                "--ssl-certfile=/etc/nsls2/tls/server.cer", \
+                "--log-config=uvicorn_log_config.yml"]
 

src/nsls2api/api/models/stats_model.py

@@ -6,6 +6,7 @@ class StatsModel(pydantic.BaseModel):
     proposal_count: int
     beamline_count: int
     commissioning_proposal_count: int
+    facility_data_health: bool
 
 
 class AboutModel(pydantic.BaseModel):

src/nsls2api/api/v1/proposal_api.py

@@ -25,6 +25,7 @@
 @router.get("/proposals/recent/{count}", response_model=RecentProposalsList)
 async def get_recent_proposals(count: int, beamline: str | None = None):
     count = max(1, count)
+
     proposals = await proposal_service.recently_updated(count, beamline=beamline)
 
     proposal_models = [

src/nsls2api/api/v1/stats_api.py

@@ -10,19 +10,21 @@
 
 router = fastapi.APIRouter()
 
-
 @router.get("/stats", response_model=StatsModel)
 async def stats():
     proposals = await proposal_service.proposal_count()
     beamlines = await beamline_service.beamline_count()
     facilities = await facility_service.facilities_count()
     commissioning = len(await proposal_service.commissioning_proposals())
 
+    faciltiy_data_health = await facility_service.is_healthy("nsls2")
+
     model = StatsModel(
         facility_count=facilities,
         beamline_count=beamlines,
         proposal_count=proposals,
         commissioning_proposal_count=commissioning,
+        facility_data_health=faciltiy_data_health,
     )
     return model
 

src/nsls2api/exception_handlers.py

@@ -0,0 +1,19 @@
+from nsls2api.main import app
+from asgi_correlation_id import correlation_id
+from fastapi import HTTPException, Request
+from fastapi.exception_handlers import http_exception_handler
+from fastapi.responses import JSONResponse
+
+
+# This is to make sure we add the request ID to the response headers for the case 
+# of unhandled server errors.
+@app.exception_handler(Exception)
+async def unhandled_exception_handler(request: Request, exc: Exception) -> JSONResponse:
+    return await http_exception_handler(
+        request,
+        HTTPException(
+            500,
+            "Internal server error - unhandled exception",
+            headers={"X-Request-ID": correlation_id.get() or ""},
+        ),
+    )

src/nsls2api/infrastructure/logging.py

@@ -0,0 +1,6 @@
+import logging
+
+import nsls2api
+
+# Grab the uvicorn logger so we can generate logs to the application log
+logger = logging.getLogger(f"uvicorn.error.{nsls2api.__name__}")

src/nsls2api/main.py

@@ -1,10 +1,11 @@
+import os
 from pathlib import Path
-import time
-from typing import Annotated
 
 import fastapi
 import uvicorn
-from fastapi import Depends
+from asgi_correlation_id import CorrelationIdMiddleware
+from fastapi.middleware.cors import CORSMiddleware
+from starlette.middleware import Middleware
 from starlette.staticfiles import StaticFiles
 
 from nsls2api.api.v1 import admin_api as admin_api_v1
@@ -13,31 +14,35 @@
 from nsls2api.api.v1 import proposal_api as proposal_api_v1
 from nsls2api.api.v1 import stats_api as stats_api_v1
 from nsls2api.api.v1 import user_api as user_api_v1
-from nsls2api.infrastructure import config
 from nsls2api.infrastructure import mongodb_setup
 from nsls2api.infrastructure.config import get_settings
-from nsls2api.views import diagnostics
-from nsls2api.views import home
+from nsls2api.infrastructure.logging import logger
 from nsls2api.middleware import ProcessTimeMiddleware
-from starlette.middleware import Middleware
+from nsls2api.views import diagnostics, home
 
 settings = get_settings()
 
-middleware = [Middleware(ProcessTimeMiddleware)]
-
-app = fastapi.FastAPI(title="NSLS-II API", middleware=middleware)
-
 current_file = Path(__file__)
 current_file_dir = current_file.parent
 current_file_dir_absolute = current_file_dir.absolute()
 project_root = current_file_dir.parent
 project_root_absolute = project_root.resolve()
 static_root_absolute = current_file_dir_absolute / "static"
 
+middleware = [Middleware(ProcessTimeMiddleware)]
 
-def main():
-    configure_routing()
-    uvicorn.run(app, port=8081)
+app = fastapi.FastAPI(
+    title="NSLS-II API", middleware=middleware
+)
+app.add_middleware(CorrelationIdMiddleware)
+
+app.add_middleware(
+    CORSMiddleware,
+    allow_origins=["*"],
+    allow_methods=["*"],
+    allow_headers=["X-Requested-With", "X-Request-ID"],
+    expose_headers=["X-Request-ID"],
+)
 
 
 def configure_routing():
@@ -48,14 +53,8 @@ def configure_routing():
     app.include_router(user_api_v1.router, prefix="/v1", tags=["user"])
     app.include_router(admin_api_v1.router, prefix="/v1", tags=["admin"])
 
-    # Add this for backwards compatibility (for now)
-    app.include_router(proposal_api_v1.router, include_in_schema=False)
-
-    import subprocess
-
-    cmd = "pwd"
-    output = subprocess.run(cmd, shell=True)
-    print(f"Current working directory: {output}")
+    # Just log the current working directory - useful is some of the static files are not found.
+    logger.info(f"Current working directory: {os.getcwd()}")
 
     # Also include our webpages
     app.include_router(home.router)
@@ -73,6 +72,11 @@ async def configure_db():
     await mongodb_setup.init_connection(settings.mongodb_dsn.unicode_string())
 
 
+def main():
+    configure_routing()
+    uvicorn.run(app, port=8081, log_config="uvicorn_log_config.yml")
+
+
 if __name__ == "__main__":
     main()
 else:

src/nsls2api/middleware.py

@@ -1,7 +1,8 @@
-from starlette.types import ASGIApp, Message, Receive, Scope, Send
-from starlette.datastructures import MutableHeaders
 import time
 
+from starlette.datastructures import MutableHeaders
+from starlette.types import ASGIApp, Message, Receive, Scope, Send
+
 
 class ProcessTimeMiddleware:
     app: ASGIApp
@@ -19,8 +20,8 @@ async def send_wrapper(message: Message) -> None:
             if message["type"] == "http.response.start":
                 headers = MutableHeaders(scope=message)
                 end_time = time.perf_counter()
-                lapsed_time = end_time - start_time
-                headers["Server-Timing"] = f"total;dur={lapsed_time:.3f}"
+                lapsed_time = (end_time - start_time) * 1000
+                headers["Server-Timing"] = f"total;dur={lapsed_time:.3f} ms"
             await send(message)
-        
+
         await self.app(scope, receive, send_wrapper)

src/nsls2api/services/facility_service.py

@@ -1,3 +1,5 @@
+from nsls2api.infrastructure.logging import logger
+
 from typing import Optional
 
 from beanie.odm.operators.find.comparison import In
@@ -6,6 +8,7 @@
 from nsls2api.models.facilities import Facility
 
 
+
 async def facilities_count() -> int:
     """
     Count the number of facilities in the database.
@@ -51,5 +54,40 @@ async def current_operating_cycle(facility: str) -> Optional[str]:
 
     if cycle is None:
         return None
-
+    
     return cycle.name
+
+
+async def is_healthy(facility: str) -> bool:
+    """
+    Database Health Check
+
+    This method checks the health of the information in the database.
+    Basically, is the database populated with the correct information?
+    e.g. Is there only one current operating cycle for a facility?
+
+    :param facility: The facility name (str).
+    :return: True if the database is healthy, False otherwise.
+    """
+
+    # Let's start with assuming the database is healthy.
+    health_status = True
+
+    logger.info(f"Checking the health of the {facility} facility data.")
+
+    # TODO: Check that the facility exists in the database.
+
+
+    # Check that there is only one current operating cycle for the facility.
+    cycles = await Cycle.find(Cycle.is_current_operating_cycle == facility).to_list()
+    if len(cycles) > 1:
+        logger.warning(
+            f"There is more than one current operating cycle for the {facility}."
+        )
+        health_status = False
+    elif len(cycles) == 0:
+        logger.warning(f"There is not an operating cycle for the {facility}.")
+        health_status = False
+
+    return health_status
+

src/nsls2api/services/proposal_service.py

@@ -2,10 +2,11 @@
 from typing import Optional
 
 from beanie.odm.operators.find.array import ElemMatch
-from beanie.operators import And, In, Text, RegEx
+from beanie.operators import And, In, RegEx, Text
 
-from nsls2api.models.proposals import Proposal, User, ProposalIdView
 from nsls2api.api.models.proposal_model import ProposalFullDetails
+from nsls2api.infrastructure.logging import logger
+from nsls2api.models.proposals import Proposal, ProposalIdView, User
 from nsls2api.services import beamline_service, pass_service
 
 
@@ -259,19 +260,23 @@ async def directories(proposal_id: int):
     error_msg = []
 
     if proposal.data_session is None:
-        error_msg.append(
+        error_text = (
             f"Proposal {str(proposal.proposal_id)} does not contain a data_session."
         )
+        logger.error(error_text)
+        error_msg.append(error_text)
 
     if not await has_valid_cycle(proposal):
-        error_msg.append(
-            f"Proposal {str(proposal.proposal_id)} does not contain any cycle information."
-        )
+        error_text = f"Proposal {str(proposal.proposal_id)} does not contain any cycle information."
+        logger.error(error_text)
+        error_msg.append(error_text)
 
     if len(proposal.instruments) == 0:
-        error_msg.append(
+        error_text = (
             f"Proposal {str(proposal.proposal_id)} does not contain any beamlines."
         )
+        logger.error(error_text)
+        error_msg.append(error_text)
 
     if len(error_msg) > 0:
         raise Exception(error_msg)

uvicorn_log_config.yml

@@ -0,0 +1,41 @@
+version: 1
+disable_existing_loggers: False
+filters:
+  correlation_id:
+    "()": asgi_correlation_id.CorrelationIdFilter
+    uuid_length: 16
+    default_value: '-'
+formatters:
+  default:
+    "()": uvicorn.logging.DefaultFormatter
+    datefmt: "%Y-%m-%dT%H:%M:%S"
+    format:  '[%(asctime)s.%(msecs)03dZ] [%(correlation_id)s] %(levelprefix)s %(message)s'
+    use_colors: True
+  access:
+    "()": uvicorn.logging.AccessFormatter
+    datefmt: "%Y-%m-%dT%H:%M:%S"
+    format: '[%(asctime)s.%(msecs)03dZ] [%(correlation_id)s] %(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s'
+handlers:
+  default:
+    formatter: default
+    class: logging.StreamHandler
+    filters: 
+      - correlation_id
+    stream: ext://sys.stderr
+  access:
+    formatter: access
+    class: logging.StreamHandler
+    filters: 
+      - correlation_id
+    stream: ext://sys.stdout
+loggers:
+  uvicorn.error:
+    level: INFO
+    handlers:
+      - default
+    propagate: no
+  uvicorn.access:
+    level: INFO
+    handlers:
+      - access
+    propagate: no