Logging and format

caddy_chatbot/src/app.py

@@ -3,6 +3,7 @@
 
 from caddy_core import components as caddy
 from caddy_core.services import enrolment
+from caddy_core.utils.monitoring import logger
 
 from integrations.google_chat.structures import GoogleChat
 from integrations.google_chat.verification import (
@@ -16,6 +17,7 @@
 
 app = FastAPI(docs_url=None)
 
+
 @app.get("/health")
 def health():
     return JSONResponse(status_code=status.HTTP_200_OK, content={"status": "Online"})
@@ -26,17 +28,22 @@ def google_chat_endpoint(event=Depends(verify_google_chat_request)) -> dict:
     """
     Handles inbound requests from Google Chat for Caddy
     """
+    logger.info("New Google Chat Request")
     google_chat = GoogleChat()
     user = event["user"]["email"]
     domain = user.split("@")[1]
 
     domain_enrolled, office = enrolment.check_domain_status(domain)
     if domain_enrolled is not True:
+        logger.info("Domain not enrolled")
         return google_chat.responses.DOMAIN_NOT_ENROLLED
+    logger.info("Domain is enrolled")
 
     user_enrolled, user_record = enrolment.check_user_status(user)
     if user_enrolled is not True:
+        logger.info("User is not enrolled")
         return google_chat.responses.USER_NOT_ENROLLED
+    logger.info("User is enrolled")
 
     included_in_rct = enrolment.check_rct_status(office)
     if included_in_rct is True:
@@ -258,24 +265,24 @@ async def microsoft_teams_endpoint(request: Request):
             query = microsoft_teams.format_message(event)
             caddy.temporary_teams_invoke(microsoft_teams, query, event)
         case "invoke":
-           match event["value"]["action"]["verb"]:
-               case "proceed": 
+            match event["value"]["action"]["verb"]:
+                case "proceed":
                     # TODO Handle Proceed Route
                     print("Adviser choice was to proceed")
                     microsoft_teams.update_card(event)
                     return microsoft_teams.responses.OK
-               case "redacted_query":
+                case "redacted_query":
                     # TODO Handle edit original query
                     print("Adviser choice was to edit original query")
-                    redacted_card = microsoft_teams.messages.create_redacted_card(event) 
+                    redacted_card = microsoft_teams.messages.create_redacted_card(event)
                     microsoft_teams.update_card(event, card=redacted_card)
                     return microsoft_teams.responses.OK
-               case "approved":
-                   microsoft_teams.handle_thumbs_up(event)
-                   return microsoft_teams.responses.OK
-               case "rejected":
-                   microsoft_teams.handle_thumbs_down(event)
-                   return microsoft_teams.responses.OK
+                case "approved":
+                    microsoft_teams.handle_thumbs_up(event)
+                    return microsoft_teams.responses.OK
+                case "rejected":
+                    microsoft_teams.handle_thumbs_down(event)
+                    return microsoft_teams.responses.OK
 
 
 @app.post("/microsoft-teams/supervision")

caddy_chatbot/src/caddy_core/components.py

@@ -20,6 +20,7 @@
     responses_table,
     users_table,
 )
+from caddy_core.utils.monitoring import logger
 from caddy_core.services.retrieval_chain import build_chain
 from caddy_core.services import enrolment
 from caddy_core.services.evaluation import execute_optional_modules
@@ -47,6 +48,7 @@ def rct_survey_reminder(event, user_record, chat_client):
 
 
 def handle_message(caddy_message, chat_client):
+    logger.info("Running message handler")
     module_values, survey_complete = check_existing_call(caddy_message)
 
     if survey_complete is True:
@@ -105,10 +107,12 @@ def remove_role_played_responses(response: str) -> str:
     """
     adviser_index = response.find("Adviser: ")
     if adviser_index != -1:
+        logger.info("Removing role played response")
         return True, response[:adviser_index].strip()
 
     adviser_index = response.find("Advisor: ")
     if adviser_index != -1:
+        logger.info("Removing role played response")
         return True, response[:adviser_index].strip()
 
     return False, response.strip()
@@ -128,12 +132,12 @@ def format_chat_history(user_messages: List) -> List:
     for message in user_messages:
         human = message.get("llmPrompt")
         ai = message.get("llmAnswer")
-        
+
         if human and ai:
             history_langchain_format.append((human, ai))
         elif human:
             history_langchain_format.append((human, ""))
-    
+
     return history_langchain_format
 
 
@@ -150,9 +154,14 @@ def get_chat_history(message: UserMessage) -> List:
     response = responses_table.query(
         KeyConditionExpression=Key("threadId").eq(message.thread_id),
     )
-
-    sorted_items = sorted(response["Items"], key=lambda x: x.get("messageReceivedTimestamp", x.get("llmPromptTimestamp", "")))
-
+
+    sorted_items = sorted(
+        response["Items"],
+        key=lambda x: x.get(
+            "messageReceivedTimestamp", x.get("llmPromptTimestamp", "")
+        ),
+    )
+
     history = format_chat_history(sorted_items)
     return history
 
@@ -220,17 +229,16 @@ def store_message(message: UserMessage):
 
 def store_response(response: LlmResponse):
     responses_table.update_item(
-        Key={
-            "threadId": str(response.thread_id)
-        },
-        UpdateExpression="set responseId = :rId, llmAnswer = :la, llmResponseJSon = :lrj, llmPromptTimestamp = :lpt, llmResponseTimestamp = :lrt, route = :route",
+        Key={"threadId": str(response.thread_id)},
+        UpdateExpression="set responseId = :rId, llmAnswer = :la, llmResponseJSon = :lrj, llmPromptTimestamp = :lpt, llmResponseTimestamp = :lrt, route = :route, context = :context",
         ExpressionAttributeValues={
             ":rId": response.response_id,
             ":la": response.llm_answer,
             ":lrj": response.llm_response_json,
             ":lpt": str(response.llm_prompt_timestamp),
             ":lrt": str(response.llm_response_timestamp),
             ":route": response.route,
+            ":context": response.context,
         },
     )
 
@@ -340,7 +348,7 @@ def check_existing_call(caddy_message) -> Tuple[Dict[str, Any], bool]:
 
 def send_to_llm(caddy_query: UserMessage, chat_client):
     query = caddy_query.message
-    
+
     domain = caddy_query.user_email.split("@")[1]
 
     chat_history = get_chat_history(caddy_query)
@@ -493,7 +501,8 @@ def send_to_llm(caddy_query: UserMessage, chat_client):
         llm_prompt_timestamp=ai_prompt_timestamp,
         llm_response_json=json.dumps(response_card),
         llm_response_timestamp=ai_response_timestamp,
-        route=route or "no_route"
+        route=route or "no_route",
+        context=[doc_without_embeddings(doc) for doc in caddy_response["context"]],
     )
 
     store_response(llm_response)
@@ -543,6 +552,12 @@ def send_to_llm(caddy_query: UserMessage, chat_client):
     store_approver_received_timestamp(supervision_event)
 
 
+def doc_without_embeddings(doc):
+    doc_dict = doc.dict()
+    doc_dict.pop("state", None)
+    return doc_dict
+
+
 def store_approver_received_timestamp(event: SupervisionEvent):
     responses_table.update_item(
         Key={"threadId": event.thread_id},
@@ -567,6 +582,7 @@ def store_approver_event(thread_id: str, approval_event: ApprovalEvent):
         ReturnValues="UPDATED_NEW",
     )
 
+
 def temporary_teams_invoke(chat_client, query, event):
     """
     Temporary solution for Teams integration
@@ -591,11 +607,16 @@ def temporary_teams_invoke(chat_client, query, event):
 
     chain, ai_prompt_timestamp = build_chain(CADDY_PROMPT)
 
-    caddy_response = chain.invoke({
-        "input": query,
-        "chat_history": [],
-    })
+    caddy_response = chain.invoke(
+        {
+            "input": query,
+            "chat_history": [],
+        }
+    )
 
     _, caddy_response["answer"] = remove_role_played_responses(caddy_response["answer"])
 
-    chat_client.send_adviser_card(event, card=chat_client.messages.generate_response_card(caddy_response["answer"]))
+    chat_client.send_adviser_card(
+        event,
+        card=chat_client.messages.generate_response_card(caddy_response["answer"]),
+    )

caddy_chatbot/src/caddy_core/models.py

@@ -1,4 +1,4 @@
-from typing import Union
+from typing import Union, List, Any
 from datetime import datetime
 import uuid
 import pydantic
@@ -36,6 +36,7 @@ class LlmResponse(pydantic.BaseModel):
     llm_prompt_timestamp: datetime
     llm_response_timestamp: datetime
     route: str
+    context: Union[List[Any], None]
 
 
 class SupervisionEvent(pydantic.BaseModel):

caddy_chatbot/src/caddy_core/services/retrieval_chain.py

@@ -18,6 +18,8 @@
 from opensearchpy import RequestsHttpConnection
 from requests_aws4auth import AWS4Auth
 
+from caddy_core.utils.monitoring import logger
+
 import re
 import os
 from datetime import datetime
@@ -62,6 +64,7 @@ def find_most_recent_caddy_vector_index():
 
     # Initialize most_recent_index with the original index name as a fallback
     most_recent_index = opensearch_index
+    logger.info(f"Index initalised with: {opensearch_index}")
 
     # Pattern to match indexes of interest
     pattern = re.compile(opensearch_index + r"_(\d{8})$")
@@ -70,21 +73,25 @@ def find_most_recent_caddy_vector_index():
     index_list = client.indices.get("*")
     most_recent_date = None
 
+    logger.info(f"Checking through {len(index_list)} indexes")
     for index_name in index_list:
         match = pattern.match(index_name)
         if match:
             # Extract date from the index name
             extracted_date_str = match.group(1)
             try:
                 extracted_date = datetime.strptime(extracted_date_str, "%Y%m%d")
+                logger.info(f"Date extracted from index: {extracted_date}")
                 # Update most recent date and index name if this index is more recent
                 if most_recent_date is None or extracted_date > most_recent_date:
+                    logger.info(f"Setting as most recent date: {extracted_date}")
                     most_recent_date = extracted_date
                     most_recent_index = index_name
             except ValueError:
                 # If the date is not valid, ignore this index
                 continue
 
+    logger.info(f"Most recent index is: {most_recent_index}")
     return most_recent_index
 
 
@@ -142,7 +149,7 @@ def build_chain(CADDY_PROMPT):
     )
 
     llm = BedrockChat(
-        model_id=os.environ.get("LLM"),
+        model_id=os.getenv("LLM"),
         region_name=alternate_region,
         model_kwargs={"temperature": 0.3, "top_k": 5, "max_tokens": 2000},
     )

caddy_chatbot/src/caddy_core/services/router.py

@@ -1,7 +1,8 @@
-import os 
+import os
 import boto3
 from semantic_router import Route, RouteLayer
 from semantic_router.encoders import BedrockEncoder
+from caddy_core.utils.monitoring import logger
 
 session = boto3.Session()
 credentials = session.get_credentials()
@@ -12,23 +13,24 @@
     region="eu-west-3",
 )
 
-dynamodb = boto3.resource('dynamodb')
+dynamodb = boto3.resource("dynamodb")
 table = dynamodb.Table(os.getenv("ROUTES_TABLE_NAME"))
 
+
 def get_routes_dynamically():
+    logger.info("Fetching routes")
     response = table.scan()
     routes = []
-    for item in response['Items']:
-        utterances = item['utterances']
+    for item in response["Items"]:
+        utterances = item["utterances"]
         if isinstance(utterances[0], list):
             utterances = utterances[0]
-        route = Route(
-            name=item['name'],
-            utterances=utterances
-        )
+        route = Route(name=item["name"], utterances=utterances)
         routes.append(route)
+    logger.info(f"Fetched {len(routes)} routes")
     return routes
 
+
 routes = get_routes_dynamically()
 
-get_route = RouteLayer(encoder=embeddings, routes=routes)
+get_route = RouteLayer(encoder=embeddings, routes=routes)

caddy_chatbot/src/caddy_core/utils/monitoring.py

@@ -0,0 +1,48 @@
+import logging
+import sys
+
+
+class Colours:
+    RESET = "\033[0m"
+    BOLD = "\033[1m"
+    BLACK = "\033[30m"
+    RED = "\033[31m"
+    GREEN = "\033[32m"
+    YELLOW = "\033[33m"
+    BLUE = "\033[34m"
+    MAGENTA = "\033[35m"
+    CYAN = "\033[36m"
+    WHITE = "\033[37m"
+
+
+class ColourFormatter(logging.Formatter):
+    COLOURS = {
+        "DEBUG": Colours.BLUE,
+        "INFO": Colours.MAGENTA,
+        "WARNING": Colours.YELLOW,
+        "ERROR": Colours.RED,
+        "CRITICAL": Colours.BOLD + Colours.RED,
+    }
+
+    def format(self, record):
+        log_message = super().format(record)
+        return f"{self.COLOURS.get(record.levelname, '')}{log_message}{Colours.RESET}"
+
+
+def setup_logger(name, level=logging.INFO):
+    """
+    Function to setup a colour-coded logger
+    """
+    logger = logging.getLogger(name)
+    logger.setLevel(level)
+
+    formatter = ColourFormatter("%(name)s | %(asctime)s | %(levelname)s | %(message)s")
+
+    handler = logging.StreamHandler(sys.stdout)
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+
+    return logger
+
+
+logger = setup_logger("CADDY")