Adding debugging

FinnConnor · Sep 9, 2024 · f52c6ac · f52c6ac
1 parent dc9a555
commit f52c6ac
Show file tree

Hide file tree

Showing 3 changed files with 113 additions and 4 deletions.
diff --git a/fastapi_app.log b/fastapi_app.log
@@ -0,0 +1,47 @@
+2024-09-09 09:28:30,608 - fastapi_app - INFO - GET /docs - Status: 200 - Time: 0.00s
+2024-09-09 09:28:44,955 - fastapi_app - INFO - GET /openapi.json - Status: 200 - Time: 0.04s
+2024-09-09 09:28:53,444 - fastapi_app - INFO - Handling root request
+2024-09-09 09:28:53,446 - fastapi_app - INFO - GET / - Status: 200 - Time: 0.00s
+2024-09-09 09:57:13,426 - fastapi_app - INFO - Uploading file with filename: amazon.pdf with file_id: Ren and metadata: {"source":"Earnings report"}
+2024-09-09 09:59:21,254 - fastapi_app - INFO - Uploading file with filename: amazon.pdf with file_id: Ren and metadata: {"source":"Earnings report"}
+2024-09-09 09:59:28,892 - fastapi_app - INFO - Processing list of documents of length: 38
+2024-09-09 09:59:28,892 - fastapi_app - INFO - Sending batch 0 to 20 / 38
+2024-09-09 09:59:28,892 - fastapi_app - INFO - Sending batch 20 to 38 / 38
+2024-09-09 09:59:30,171 - fastapi_app - INFO - POST /document - Status: 200 - Time: 9.09s
+2024-09-09 10:02:43,033 - fastapi_app - INFO - Uploading list of links with metadata: 
+2024-09-09 10:02:43,034 - fastapi_app - INFO - Uploading link(0/2: https://www.desiringgod.org/interviews/the-pitfalls-of-being-a-thinker with file_id: FirstID metadata: 
+2024-09-09 10:02:48,930 - fastapi_app - INFO - Uploading link(1/2: https://www.desiringgod.org/interviews/teens-and-screens with file_id: 2ndID metadata: 
+2024-09-09 10:02:49,247 - fastapi_app - INFO - Processing list of documents of length: 15
+2024-09-09 10:02:49,247 - fastapi_app - INFO - Sending batch 0 to 15 / 15
+2024-09-09 10:02:49,247 - fastapi_app - INFO - Processing list of documents of length: 29
+2024-09-09 10:02:49,247 - fastapi_app - INFO - Sending batch 0 to 20 / 29
+2024-09-09 10:02:49,248 - fastapi_app - INFO - Sending batch 20 to 29 / 29
+2024-09-09 10:02:50,198 - fastapi_app - INFO - POST /links - Status: 200 - Time: 7.17s
+2024-09-09 10:04:14,144 - fastapi_app - INFO - Uploading list of links with metadata: 
+2024-09-09 10:04:14,144 - fastapi_app - INFO - Uploading link(2/2: https://www.desiringgod.org/interviews/the-pitfalls-of-being-a-thinker with file_id:  metadata: 
+2024-09-09 10:04:14,875 - fastapi_app - INFO - Processing list of documents of length: 15
+2024-09-09 10:04:14,876 - fastapi_app - INFO - Sending batch 0 to 15 / 15
+2024-09-09 10:07:44,493 - fastapi_app - INFO - Uploading multiple files with metadata: 
+2024-09-09 10:07:44,493 - fastapi_app - INFO - Uploading file in group of files (1/1) with filename: superbowl.txt 
+2024-09-09 10:07:44,498 - fastapi_app - INFO - Processing list of documents of length: 39
+2024-09-09 10:07:44,498 - fastapi_app - INFO - Sending batch 0 to 20 / 39
+2024-09-09 10:07:44,499 - fastapi_app - INFO - Sending batch 20 to 39 / 39
+2024-09-09 10:07:45,370 - fastapi_app - INFO - POST /documents - Status: 200 - Time: 0.95s
+2024-09-09 10:11:45,178 - fastapi_app - INFO - Uploading multiple files with metadata: 
+2024-09-09 10:11:45,180 - fastapi_app - INFO - Uploading file in group of files (1/1) with filename: superbowl.txt 
+2024-09-09 10:11:45,184 - fastapi_app - INFO - Processing list of documents of length: 39
+2024-09-09 10:11:45,185 - fastapi_app - INFO - Sending batch 0 to 20 / 39
+2024-09-09 10:11:45,185 - fastapi_app - INFO - Sending batch 20 to 39 / 39
+2024-09-09 10:11:45,984 - fastapi_app - INFO - POST /documents - Status: 200 - Time: 0.88s
+2024-09-09 10:15:20,763 - fastapi_app - INFO - Uploading multiple files with metadata: 
+2024-09-09 10:15:20,764 - fastapi_app - INFO - Uploading file in group of files (1/1) with filename: superbowl.txt 
+2024-09-09 10:15:20,769 - fastapi_app - INFO - Processing list of documents of length: 39
+2024-09-09 10:15:20,769 - fastapi_app - INFO - Sending batch 0 to 20 / 39
+2024-09-09 10:15:20,769 - fastapi_app - INFO - Sending batch 20 to 39 / 39
+2024-09-09 10:15:21,592 - fastapi_app - INFO - POST /documents - Status: 200 - Time: 0.90s
+2024-09-09 10:51:20,979 - fastapi_app - INFO - Uploading multiple files with metadata: 
+2024-09-09 10:51:20,981 - fastapi_app - INFO - Uploading file in group of files (1/1) with filename: superbowl.txt 
+2024-09-09 10:51:20,986 - fastapi_app - INFO - Processing list of documents of length: 39
+2024-09-09 10:51:20,986 - fastapi_app - INFO - Sending batch 0 to 20 / 39
+2024-09-09 10:51:20,987 - fastapi_app - INFO - Sending batch 20 to 39 / 39
+2024-09-09 10:51:21,793 - fastapi_app - INFO - POST /documents - Status: 200 - Time: 0.88s
diff --git a/logger.py b/logger.py
@@ -0,0 +1,43 @@
+import logging
+from fastapi import Request, Response
+from starlette.middleware.base import BaseHTTPMiddleware
+import time, os
+
+
+def setup_logger(name: str, level=logging.INFO):
+    logger = logging.getLogger(name)
+    env = os.getenv("DEBUG_MODE","false")
+    if env.lower() == "true":
+        logger.setLevel(level)
+    else:
+        logger.setLevel(0)
+    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
+
+    console_handler = logging.StreamHandler()
+    console_handler.setFormatter(formatter)
+    logger.addHandler(console_handler)
+
+    file_handler = logging.FileHandler(f"{name}.log")
+    file_handler.setFormatter(formatter)
+    logger.addHandler(file_handler)
+
+    return logger
+def get_env_variable(var_name: str, default_value: str = None, required: bool = False) -> str:
+    value = os.getenv(var_name)
+    if value is None:
+        if default_value is None and required:
+            raise ValueError(f"Environment variable '{var_name}' not found.")
+        return default_value
+    return value
+
+class LogMiddleware(BaseHTTPMiddleware):
+    def __init__(self, app, logger):
+        super().__init__(app)
+        self.logger = logger
+
+    async def dispatch(self, request: Request, call_next):
+        start_time = time.time()
+        response = await call_next(request)
+        process_time = time.time() - start_time
+        self.logger.info(f"{request.method} {request.url.path} - Status: {response.status_code} - Time: {process_time:.2f}s")
+        return response
diff --git a/main.py b/main.py
@@ -27,10 +27,18 @@
 import shutil
 from pathlib import Path
 from functools import lru_cache
+from logger import setup_logger, LogMiddleware
+from starlette.middleware.base import BaseHTTPMiddleware
+from langchain.globals import set_verbose
+
+
 
 load_dotenv()
+
+logger = setup_logger(name="fastapi_app")
 # uvicorn main:app --reload
 app = FastAPI()
+app.add_middleware(LogMiddleware, logger=logger)
 
 # Global Variables
 embed_model = OpenAIEmbeddings(model="text-embedding-3-small")
@@ -41,9 +49,6 @@
     model='gpt-4o-mini-2024-07-18'
 )
 
-class MetaFile(BaseModel):
-    file_id: str
-    metaJson: dict | None = None
 
 # New function to get file_id requirement from environment
 @lru_cache()
@@ -66,12 +71,15 @@ def file_id_validator(
 
 @app.get("/")
 async def root() -> dict[str,str]:
+    logger.info("Handling root request")
     return {"message": "Hello World"}
 
 @app.get("/rag/llm/")
 async def sendAI(query: str = Query(...,description="User questions for LLM")) -> dict[str,str]:
+    logger.info(f"Handling sendAI request with query: {query}")
     messages = [HumanMessage(content=query)]
     res = await chat.ainvoke(messages)
+    logger.info(f"AI response generated for query: {query} with AI Response: {res.content}")
     return {"AI Response": res.content}
 
 @app.get("/rag/")
@@ -80,6 +88,7 @@ async def getContext(query: str = Query(..., description="The query to process t
                      filterJson: Annotated[ str  | None, Query(description="Json of metadata to search for")] = "",
                      file_ids: Annotated[List[str]| None, Query(description="file_id to search for")] = []
                      ) -> dict[str,str]:
+    logger.info(f"Handling RAG request with query: {query}, k: {k}, MetaData: {filterJson}, file_ids: {file_ids}")
     filter = {} 
     if filterJson :
         try:
@@ -90,7 +99,7 @@ async def getContext(query: str = Query(..., description="The query to process t
         context = await similarDocs(query, k)
     else:
         context = await similarDocs(query,k,filter,file_ids )
-
+    logger.info(f"The query: {query} returned context: \n\n {context}")
     return {"Context": context}
 
 #ADD: upload multiple documents, more than text files 
@@ -101,6 +110,7 @@ async def upload_file(
     vector_store_id: Annotated[str | None, Form()] = "",
     metaJson: Annotated[str| None, Form()] = "" 
 ) -> dict[str, str]:
+    logger.info(f"Uploading file with filename: {file.filename} with file_id: {file_id} and metadata: {metaJson}")
     metaData = {}
     if vector_store_id:
         metaData["vector_store_id"] = vector_store_id
@@ -137,6 +147,9 @@ async def upload_files(
     vector_store_id: Annotated[str | None, Form()] = "",
     metaJson: Annotated[str | None, Form()] = "" 
 ) -> dict[str, str]:
+
+    logger.info(f"Uploading multiple files with metadata: {metaJson}")
+
     strict_requirement = get_file_id_requirement()
 
     if strict_requirement and (not file_ids or len(files) != len(file_ids)):
@@ -168,6 +181,7 @@ async def upload_files(
     }
 
     for i, file in enumerate(files):
+        logger.info(f"Uploading file in group of files ({i+1}/{len(files)}) with filename: {file.filename} ")
         if file.content_type not in allowed_types:
             raise HTTPException(status_code=400, detail=f"{file.content_type} is an Invalid file type")
 
@@ -190,6 +204,7 @@ async def upload_url(url: Annotated[str,Form(...,description="Link to pull data
                      vector_store_id: Annotated[str | None, Form(description="Insert string vector id optional")] = "", 
                      metaJson: Annotated[str | None, Form(description="Insert JSON metadata opptional")] = ""
                      ) -> dict[str,str]:
+    logger.info(f"Uploading link: {url} with file_id: {file_id} metadata: {metaJson}")
     metaData = {}
     if vector_store_id:
         metaData["vector_store_id"] = vector_store_id
@@ -209,6 +224,7 @@ async def upload_urls(url_list: Annotated[List[str],Form(...,description="Links
                      vector_store_id: Annotated[str | None, Form(description="Insert string vector id optional")] = "", 
                      metaJson: Annotated[str | None, Form(description="Insert JSON metadata opptional")] = ""
                      ) -> dict[str,str]:
+    logger.info(f"Uploading list of links with metadata: {metaJson}")
     metaData = {}
     url_list = url_list[0].split(',')
     if file_ids[0] != '':
@@ -224,6 +240,7 @@ async def upload_urls(url_list: Annotated[List[str],Form(...,description="Links
             return {"error":"Invalid JSON"}
     tasks = []
     for i in range(len(url_list)):
+        logger.info(f"Uploading link({i+2}/{len(url_list)}: {url_list[i]} metadata: {metaJson}")
         if file_ids[0] != '':
             docData = await load_link(url_list[i], metaData, file_ids[i])
         else:
@@ -237,8 +254,10 @@ async def process_documents(docData: list[Document],
                              batch_size: int = 20, concurrent_max: int = 10):
     semaphore = asyncio.Semaphore(concurrent_max)
     tasks = [] 
+    logger.info(f"Processing list of documents of length: {len(docData)}")
     for i in range(0, len(docData), batch_size):
         batch = docData[i: min(i+batch_size, len(docData))]
+        logger.info(f"Sending batch {i} to {i+len(batch)} / {len(docData)}")
         task = asyncio.create_task(process_batch(batch, semaphore))
         tasks.append(task)
     await asyncio.gather(*tasks)