#443 Add reference code to errors for user and log

Enh/log requests

Author: PGijsbers

.github/ISSUE_TEMPLATE/bug-report.md

@@ -0,0 +1,24 @@
+---
+name: 🐛 Bug report
+about: Create a report to help us fix it!
+title: ''
+labels: bug, triage
+assignees: ''
+
+---
+
+**Describe the bug**
+A clear and concise description of what the bug is.
+
+**Error Reference**
+Please indicate which server you were connecting to (e.g., api.aiod.eu).
+If the server provided a reference code, please provide it (a hexidecimal string, like `d47cb85f6cf64c158dbb65e1a891903f`).
+
+**To Reproduce**
+Please provide a [minimal, reproducible example](https://stackoverflow.com/help/minimal-reproducible-example). Preferably a (set of) complete queries which do not behave as expected.
+
+**Expected behavior**
+A clear and concise description of what you expected to happen.
+
+**Additional context**
+Add any other context about the problem here.

docs/developer/troubleshooting.md

@@ -0,0 +1,26 @@
+## Logging
+The REST API uses the built-in [`logging`](https://docs.python.org/3/library/logging.html) module for its logging.
+The [log level](https://docs.python.org/3/library/logging.html#logging-levels) for the configuration can be configured
+in the `src/config.override.toml` file, as `dev.log_level`.
+
+## Navigating the logs
+The REST API will provide an error reference with each exception it raises.
+For example, trying to access a dataset that does not exist may result in:
+
+```json
+{
+  'detail': "Dataset '42' not found in the database.",
+  'reference': 'd47cb85f6cf64c158dbb65e1a891903f'
+}
+```
+
+To figure out what lead to this error, you can reference the logs.
+Unexpected errors, i.e., uncaught ones, are logged at `logging.ERROR` level.
+Other errors, such as the one above, are logged at `logging.DEBUG` level.
+By default, logging output is at `logging.INFO` level, so if you want to capture all warnings you
+must first set it to `logging.DEBUG`.
+
+You can find the error in the docker logs as `docker logs CONTAINER_NAME 2>&1 | grep -e "REFERENCE"`,
+e.g.,`docker logs apiserver 2>&1 | grep -e "d47cb85f6cf64c158dbb65e1a891903f"`. The log message will 
+contain information about the type of request (`GET`) the path and query (`/datasets/v1/42`), and 
+the body content (in the case of requests that have one).

mkdocs.yaml

@@ -26,6 +26,7 @@ nav:
       - 'Elastic Search': developer/elastic_search.md
       - 'Scripts': developer/scripts.md
       - 'Release Workflow': developer/releases.md
+      - 'Troubleshooting': developer/troubleshooting.md
   - 'Contributing': contributing.md
 
 markdown_extensions:

src/config.default.toml

@@ -13,6 +13,7 @@ password = "ok"
 [dev]
 reload = true
 request_timeout = 10  # seconds
+log_level = "INFO"  # Python log levels: https://docs.python.org/3/library/logging.html#logging-levels
 
 # Authentication and authorization
 [keycloak]

src/error_handling/__init__.py

@@ -1 +1 @@
-from error_handling.error_handling import as_http_exception  # noqa:F401
+from error_handling.error_handling import as_http_exception, http_exception_handler  # noqa:F401

src/error_handling/error_handling.py

@@ -1,5 +1,12 @@
+import json
+import logging
 import traceback
+import uuid
+from http import HTTPStatus
+
 from fastapi import HTTPException, status
+from pydantic import BaseModel
+from starlette.responses import JSONResponse
 
 
 def as_http_exception(exception: Exception) -> HTTPException:
@@ -13,3 +20,34 @@ def as_http_exception(exception: Exception) -> HTTPException:
             f"{exception}"
         ),
     )
+
+
+class ErrorSchema(BaseModel):
+    detail: str
+    reference: str
+
+
+async def http_exception_handler(request, exc):
+    reference = uuid.uuid4().hex
+    error = ErrorSchema(detail=exc.detail, reference=reference)
+    content = error.dict()
+
+    body_content = "<Data Stream with unknown content>"
+    if not request._stream_consumed:
+        body = await request.body()
+        body_content = json.dumps(json.loads(body)) if body else ""
+
+    log_message = str(
+        dict(
+            reference=reference,
+            exception=f"{str(exc)!r}",
+            method=request.scope["method"],
+            path=request.scope["path"],
+            body=body_content,
+        )
+    )
+    log_level = logging.DEBUG
+    if exc.status_code == HTTPStatus.INTERNAL_SERVER_ERROR:
+        log_level = logging.WARNING
+    logging.log(log_level, log_message)
+    return JSONResponse(content, status_code=exc.status_code)

src/main.py

@@ -10,7 +10,7 @@
 
 import pkg_resources
 import uvicorn
-from fastapi import Depends, FastAPI
+from fastapi import Depends, FastAPI, HTTPException
 from fastapi.responses import HTMLResponse
 from sqlmodel import select
 
@@ -22,6 +22,7 @@
 from database.model.platform.platform_names import PlatformName
 from database.session import EngineSingleton, DbSession
 from database.setup import create_database, database_exists
+from error_handling import http_exception_handler
 from routers import resource_routers, parent_routers, enum_routers, uploader_routers
 from routers import search_routers
 from setup_logger import setup_logger
@@ -101,17 +102,33 @@ def create_app() -> FastAPI:
     """Create the FastAPI application, complete with routes."""
     setup_logger()
     args = _parse_args()
+    if args.build_db == "never":
+        if not database_exists():
+            logging.warning(
+                "AI-on-Demand database does not exist on the MySQL server, "
+                "but `build_db` is set to 'never'. If you are not creating the "
+                "database through other means, such as MySQL group replication, "
+                "this likely means that you will get errors or undefined behavior."
+            )
+    else:
+        build_database(args)
+
     pyproject_toml = pkg_resources.get_distribution("aiod_metadata_catalogue")
+    app = build_app(args.url_prefix, pyproject_toml.version)
+    return app
+
+
+def build_app(url_prefix: str = "", version: str = "dev"):
     app = FastAPI(
-        openapi_url=f"{args.url_prefix}/openapi.json",
-        docs_url=f"{args.url_prefix}/docs",
+        openapi_url=f"{url_prefix}/openapi.json",
+        docs_url=f"{url_prefix}/docs",
         title="AIoD Metadata Catalogue",
         description="This is the Swagger documentation of the AIoD Metadata Catalogue. For the "
         "Changelog, refer to "
         '<a href="https://github.com/aiondemand/AIOD-rest-api/releases">https'
         "://github.com/aiondemand/AIOD-rest-api/releases</a>.",
-        version=pyproject_toml.version,
-        swagger_ui_oauth2_redirect_url=f"{args.url_prefix}/docs/oauth2-redirect",
+        version=version,
+        swagger_ui_oauth2_redirect_url=f"{url_prefix}/docs/oauth2-redirect",
         swagger_ui_init_oauth={
             "clientId": KEYCLOAK_CONFIG.get("client_id_swagger"),
             "realm": KEYCLOAK_CONFIG.get("realm"),
@@ -120,32 +137,25 @@ def create_app() -> FastAPI:
             "scopes": KEYCLOAK_CONFIG.get("scopes"),
         },
     )
-    if args.build_db == "never":
-        if not database_exists():
-            logging.warning(
-                "AI-on-Demand database does not exist on the MySQL server, "
-                "but `build_db` is set to 'never'. If you are not creating the "
-                "database through other means, such as MySQL group replication, "
-                "this likely means that you will get errors or undefined behavior."
-            )
-    else:
-
-        drop_database = args.build_db == "drop-then-build"
-        create_database(delete_first=drop_database)
-        AIoDConcept.metadata.create_all(EngineSingleton().engine, checkfirst=True)
-        with DbSession() as session:
-            triggers = create_delete_triggers(AIoDConcept)
-            for trigger in triggers:
-                session.execute(trigger)
-            existing_platforms = session.scalars(select(Platform)).all()
-            if not any(existing_platforms):
-                session.add_all([Platform(name=name) for name in PlatformName])
-                session.commit()
-
-    add_routes(app, url_prefix=args.url_prefix)
+    add_routes(app, url_prefix=url_prefix)
+    app.add_exception_handler(HTTPException, http_exception_handler)
     return app
 
 
+def build_database(args):
+    drop_database = args.build_db == "drop-then-build"
+    create_database(delete_first=drop_database)
+    AIoDConcept.metadata.create_all(EngineSingleton().engine, checkfirst=True)
+    with DbSession() as session:
+        triggers = create_delete_triggers(AIoDConcept)
+        for trigger in triggers:
+            session.execute(trigger)
+        existing_platforms = session.scalars(select(Platform)).all()
+        if not any(existing_platforms):
+            session.add_all([Platform(name=name) for name in PlatformName])
+            session.commit()
+
+
 def main():
     """Run the application. Placed in a separate function, to avoid having global variables"""
     args = _parse_args()

src/routers/resource_ai_asset_router.py

@@ -72,7 +72,7 @@ def get_resource_content(
                     detail=(
                         "Multiple distributions encountered. "
                         "Use another endpoint indicating the distribution index `distribution_idx` "
-                        "at the end of the url for a specific distribution.",
+                        "at the end of the url for a specific distribution."
                     ),
                 )
             elif distribution_idx >= len(distributions):

src/setup_logger.py

@@ -1,15 +1,30 @@
+# ruff: noqa: S101  # We want early fail on startup if logging is not configured correctly
 import logging
 from importlib.metadata import version
 
+from config import CONFIG
+
 format_string = (
     f"v{version('aiod_metadata_catalogue')}"
     + " %(asctime)s.%(msecs)03d %(levelname)s %(module)s - %(funcName)s: %(message)s"
 )
 
 
-def setup_logger():
+def setup_logger(config: dict | None = None):
+    config = config or CONFIG
+    assert "dev" in config, "There should be a [dev] section in the configuration.toml file."
+    assert (
+        "log_level" in config["dev"]
+    ), "Missing `log_level` setting in the [dev] section of the configuration.toml file."
+
+    log_level: str = config["dev"]["log_level"]
+    levels = logging.getLevelNamesMapping()
+    assert (
+        isinstance(log_level, str) and log_level.upper() in levels
+    ), f"The `dev.log_level` is set to {log_level!r} but should be one of {set(levels)!r}."
+
     logging.basicConfig(
-        level=logging.INFO,
+        level=levels[log_level],
         format=format_string,
         datefmt="%Y-%m-%d %H:%M:%S",
     )

src/tests/routers/ai_asset_routers/test_router_aiassets_retrieve_content.py

@@ -160,11 +160,11 @@ def test_endpoints_when_two_distributions(
 
     response = client.get(SAMPLE_ENDPOINT, allow_redirects=False)
     assert response.status_code == status.HTTP_409_CONFLICT, response.content
-    assert response.json()["detail"] == [
+    assert response.json()["detail"] == (
         "Multiple distributions encountered. "
         "Use another endpoint indicating the distribution index `distribution_idx` "
         "at the end of the url for a specific distribution."
-    ], response.content
+    ), response.content
 
     response0 = client.get(SAMPLE_ENDPOINT + "/0", allow_redirects=False)
     assert response0.status_code == status.HTTP_303_SEE_OTHER, response0.content