From 8c3af666fef698a0d11a6f4a68251dc4389401aa Mon Sep 17 00:00:00 2001
From: kun98-liu <81949316+kun98-liu@users.noreply.github.com>
Date: Tue, 10 Dec 2024 12:01:03 +0900
Subject: [PATCH] Add log config and custom API logger to log requests (#6)

uvicorn log access of API like

```sh
api-server-1  | INFO:     192.168.65.1:41988 - "GET /swagger HTTP/1.1" 200 OK
```

but it's not helping, because it does not log the request body.

- Following this issue https://github.com/encode/uvicorn/issues/491, I
made a custom log config to add logger name in log and adjust log format
- Add a `middleware` of fastapi to log the request in a more detailed
way.
- Override HTTPExceptionHandler to create error log when API is not
responding 200.
https://fastapi.tiangolo.com/tutorial/handling-errors/#override-the-httpexception-error-handler
- Hide uvicorn access log

Now the log looks like:
```sh
api-server-1  | 2024-12-09 09:35:13,363 - INFO     - app.api_logger       - [request_id: 7608958e-36a6-428e-8427-83ced6b9d7c3, method:POST, path: http://0.0.0.0:8000/login/] Request body: {"e_mail":"123","password":"string"}.
api-server-1  | 2024-12-09 09:35:13,367 - INFO     - app.routers.login    - e_mail='123' password='string'
api-server-1  | 2024-12-09 09:35:13,367 - ERROR    - app.http_exc_handler - [request_id: 7608958e-36a6-428e-8427-83ced6b9d7c3, method:POST, path: http://0.0.0.0:8000/login/] Failed to handle request. status_code=404, detail=asdasdas
```


**What can be improved in the future:**
- Instead of only outputting logs to console, we should also keep logs
as files in disk and use logstash to send logs to es like real-world
application does.
- Response is not logged, but we may want to add it. APILoggerMiddleware
has to build a dummy Response from the outgoing bytestreams, which is
not good. So we may want to find another way to do so.
---
 api-server/Dockerfile                         |  2 +-
 api-server/app/main.py                        |  9 +++++
 api-server/app/routers/login.py               | 10 +++---
 api-server/app/routers/user.py                |  5 +--
 api-server/app/server/__init__.py             |  0
 .../app/server/api_logger_middleware.py       | 35 +++++++++++++++++++
 .../app/server/http_exception_handler.py      | 18 ++++++++++
 api-server/log_conf.yaml                      | 34 ++++++++++++++++++
 api-server/requirements.txt                   |  1 +
 9 files changed, 107 insertions(+), 7 deletions(-)
 create mode 100644 api-server/app/server/__init__.py
 create mode 100644 api-server/app/server/api_logger_middleware.py
 create mode 100644 api-server/app/server/http_exception_handler.py
 create mode 100644 api-server/log_conf.yaml

diff --git a/api-server/Dockerfile b/api-server/Dockerfile
index d2f54bf..6eb6fba 100644
--- a/api-server/Dockerfile
+++ b/api-server/Dockerfile
@@ -2,4 +2,4 @@ FROM python:3.9-slim
 WORKDIR /app
 COPY .. .
 RUN pip install -r requirements.txt
-CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "8000"]
\ No newline at end of file
+CMD ["uvicorn", "app.main:app", "--host", "0.0.0.0", "--port", "8000", "--log-config", "log_conf.yaml"]
\ No newline at end of file
diff --git a/api-server/app/main.py b/api-server/app/main.py
index fb36695..4abc977 100644
--- a/api-server/app/main.py
+++ b/api-server/app/main.py
@@ -1,5 +1,9 @@
 from fastapi import FastAPI
+from starlette.exceptions import HTTPException
+
 from app.routers import student, login, user
+from app.server.api_logger_middleware import APILoggerMiddleware
+from app.server.http_exception_handler import http_exception_handler
 
 app = FastAPI(
     docs_url="/swagger",
@@ -9,3 +13,8 @@
 app.include_router(student.router)
 app.include_router(login.router)
 app.include_router(user.router)
+
+app.add_middleware(APILoggerMiddleware)
+
+app.add_exception_handler(HTTPException, http_exception_handler)
+
diff --git a/api-server/app/routers/login.py b/api-server/app/routers/login.py
index 0a0c40c..8598505 100644
--- a/api-server/app/routers/login.py
+++ b/api-server/app/routers/login.py
@@ -1,16 +1,18 @@
+import logging
 from fastapi import APIRouter
-
 from app.schema.loginschema import LoginRequestSchema, LoginResponseSchema, SigninResponseSchema, SigninRequestSchema
 
 router = APIRouter(prefix="/login", tags=["login"])
+logger = logging.getLogger(__name__)
 
 
 @router.post("/", response_model=LoginResponseSchema)
 async def login(login_request: LoginRequestSchema):
-    print(f"{login_request}")
+    logger.info(f"{login_request}")
     return LoginResponseSchema(token="nidetoken", user_id="niyeye")
 
+
 @router.post("/signin", response_model=SigninResponseSchema)
 async def signin(signin_request: SigninRequestSchema):
-    print(f"{signin_request}")
-    return SigninResponseSchema(success=True)
\ No newline at end of file
+    logger.info(f"{signin_request}")
+    return SigninResponseSchema(success=True)
diff --git a/api-server/app/routers/user.py b/api-server/app/routers/user.py
index e1d363a..54cb560 100644
--- a/api-server/app/routers/user.py
+++ b/api-server/app/routers/user.py
@@ -1,17 +1,18 @@
+import logging
 from fastapi import APIRouter
 
 from app.schema.userschema import UpdateUserinfoRequestSchema, UpdateUserinfoResponseSchema, GetUserinfoResponseSchema
 
 router = APIRouter(prefix="/userinfo", tags=["userinfo"])
+logger = logging.getLogger(__name__)
 
 
 @router.post("/", response_model=UpdateUserinfoResponseSchema)
 async def update_user(userinfo_request: UpdateUserinfoRequestSchema):
-    print(f"{userinfo_request}")
+    logger.info(f"{userinfo_request}")
     return UpdateUserinfoResponseSchema(success=True)
 
 
 @router.get("/{user_id}", response_model=GetUserinfoResponseSchema)
 async def get_user(user_id: str):
     return GetUserinfoResponseSchema(display_name="lulu", tel="23", address="tutu")
-
diff --git a/api-server/app/server/__init__.py b/api-server/app/server/__init__.py
new file mode 100644
index 0000000..e69de29
diff --git a/api-server/app/server/api_logger_middleware.py b/api-server/app/server/api_logger_middleware.py
new file mode 100644
index 0000000..0c983c6
--- /dev/null
+++ b/api-server/app/server/api_logger_middleware.py
@@ -0,0 +1,35 @@
+import json
+import logging
+import uuid
+from fastapi import Request
+from starlette.middleware.base import BaseHTTPMiddleware
+import time
+
+# Initialize the logger
+logger = logging.getLogger("app.api_logger")
+
+
+# Custom Middleware for Logging on API request
+class APILoggerMiddleware(BaseHTTPMiddleware):
+    async def dispatch(self, request: Request, call_next):
+        # Generate a unique request_id
+        request_id = str(uuid.uuid4())
+        request.state.request_id = request_id  # Attach to the request state
+
+        # Log the incoming request
+        start_time = time.time()
+        body = await request.body()
+        try:
+            # Try to load JSON and log it in compact form
+            body_json = json.loads(body)
+            compact_body = json.dumps(body_json, separators=(",", ":"))
+        except json.JSONDecodeError:
+            # Fallback to plain text if not valid JSON
+            compact_body = body.decode("utf-8")
+        logger.info(
+            f"[request_id: {request_id}, method:{request.method}, path: {request.url}] "
+            f"Request body: {compact_body}."
+        )
+
+        response = await call_next(request)
+        return response
diff --git a/api-server/app/server/http_exception_handler.py b/api-server/app/server/http_exception_handler.py
new file mode 100644
index 0000000..8d2de07
--- /dev/null
+++ b/api-server/app/server/http_exception_handler.py
@@ -0,0 +1,18 @@
+import logging
+
+from fastapi.responses import JSONResponse
+
+logger = logging.getLogger("app.http_exc_handler")
+
+
+async def http_exception_handler(request, exc):
+    logger.error(
+        f"[request_id: {request.state.request_id}, method:{request.method}, path: {request.url}] "
+        f"Failed to handle request. "
+        f"status_code={exc.status_code}, detail={exc.detail}  "
+    )
+    # Return the original response to the client
+    return JSONResponse(
+        status_code=exc.status_code,
+        content={"detail": exc.detail},
+    )
diff --git a/api-server/log_conf.yaml b/api-server/log_conf.yaml
new file mode 100644
index 0000000..611d5e8
--- /dev/null
+++ b/api-server/log_conf.yaml
@@ -0,0 +1,34 @@
+version: 1
+disable_existing_loggers: False
+formatters:
+  default:
+    # "()": uvicorn.logging.DefaultFormatter
+    format: '%(asctime)s - %(levelname)-8s - %(name)-20s - %(message)s'
+  access:
+    # "()": uvicorn.logging.AccessFormatter
+    format: '%(asctime)s - %(levelname)-8s - %(name)-20s - %(message)s'
+handlers:
+  default:
+    formatter: default
+    class: logging.StreamHandler
+    stream: ext://sys.stderr
+  access:
+    formatter: access
+    class: logging.StreamHandler
+    stream: ext://sys.stdout
+loggers:
+  uvicorn.error:
+    level: INFO
+    handlers:
+      - default
+    propagate: no
+  uvicorn.access:
+    level: WARN # only log when access log is WARN level to reduce noise
+    handlers:
+      - access
+    propagate: no
+root:
+  level: INFO
+  handlers:
+    - default
+  propagate: no
\ No newline at end of file
diff --git a/api-server/requirements.txt b/api-server/requirements.txt
index c552c0f..9a81ef4 100644
--- a/api-server/requirements.txt
+++ b/api-server/requirements.txt
@@ -2,4 +2,5 @@ fastapi~=0.115.5
 pydantic~=2.10.2
 motor
 uvicorn
+PyYAML
 pytest
\ No newline at end of file