Merge pull request #1 from basit26374/overlap_request_ids

Centralized logging

Author: basit26374

.gitignore

@@ -0,0 +1 @@
+venv/*

README.md

@@ -1,2 +1,10 @@
 # FastAPI_centralized_logging
 Learn how to do centralized logging in FastAPI framework
+
+# How to run
+- `uvicorn main:app --workers 4`
+
+## Problem with this code
+Once we called four /wait api at the same time with few seconds of difference, we observe request_id in log message are overlap in those messages which are logged after waited_longer function
+
+![Alt text](Snap.png)

Snap.png

@@ -0,0 +1,14 @@
+import logging
+import asyncio
+
+
+logger = logging.getLogger('test-app')
+
+async def wait_longer():
+    logger.info('[INFO] Starting long process...')
+    await asyncio.sleep(10)
+    return None
+
+def quick():
+    logger.info('[INFO] Starting quick process¡...')
+    return None

__pycache__/common.cpython-311.pyc

@@ -0,0 +1,17 @@
+class SingletonLogger:
+
+    def __init__(self, cls):
+        self._cls = cls
+
+    def Instance(self):
+        try:
+            return self._instance
+        except AttributeError:
+            self._instance = self._cls()
+            return self._instance
+
+    def __call__(self):
+        raise TypeError('Singletons must be accessed through `Instance()`.')
+
+    def __instancecheck__(self, inst):
+        return isinstance(inst, self._cls)

__pycache__/logger_singleton.cpython-311.pyc

@@ -0,0 +1,64 @@
+import logging
+import uuid
+
+from logging import LogRecord
+from fastapi import FastAPI
+
+import common
+
+
+app = FastAPI()
+
+# Setup Logger
+class ContextInfo(logging.Filter):
+    def __init__(self, request_id: str=None):
+        self._request_id = request_id
+
+    def filter(self, record: LogRecord) -> bool:
+        record.request_id = self._request_id
+        return True
+
+logger = logging.getLogger('test-app')
+logger.setLevel(logging.DEBUG)
+
+formatter = logging.Formatter('%(name)-12s: %(asctime)s - %(levelname)-8s - request_id: %(request_id)-15s - %(funcName)s - %(message)s')
+
+stream_handler = logging.StreamHandler()
+stream_handler.setFormatter(formatter)
+
+logger.addHandler(stream_handler)
+
+# On default behaviour, we don't set any message_id
+# because we dont't have at the very begining
+context_info = ContextInfo()
+logger.addFilter(context_info)
+
+logger.propagate = False
+
+
+@app.get("/wait")
+async def wait():
+    # Generate random unique id for each and every request
+    ranGenReqId = str(uuid.uuid4())
+    context_info = ContextInfo(request_id=ranGenReqId)
+    logger.addFilter(context_info)
+
+    logger.info("[INFO] Request comes from client to get long-waited resource access")
+    await common.wait_longer()
+
+    logger.info("[INFO] Long-waited request process is completed now")
+    return {"message": "I am come afer long wait"}
+
+
+@app.get("/quick")
+async def quick():
+    # Generate random unique id for each and every request
+    ranGenReqId = str(uuid.uuid4())
+    context_info = ContextInfo(request_id=ranGenReqId)
+    logger.addFilter(context_info)
+
+    logger.info("[INFO] Request comes from client to get quick resource access")
+    common.quick()
+
+    logger.info("[INFO] Quick request process is completed now")
+    return {"message": "I come quickly"}