Enhance logging with specific tags for better traceability and debugging. Log user query and bot's anwer for all requests.

Author: Yesid Cano Castro

pages/ask_uos_chat.py

@@ -92,7 +92,7 @@ def _validate_user_id(self, user_id: str) -> Optional[str]:
     def get_history(self, user_id: str) -> LimitedRedisChatMessageHistory:
         validated_user_id = self._validate_user_id(user_id)
         if not validated_user_id:
-            logger.warning(f"Invalid user_id attempted: {user_id!r}")
+            logger.warning(f"[AUTH] Invalid user_id attempted: {user_id!r}")
             st.warning(
                 "Invalid session. Please refresh the page or clear your browser cookies."
             )
@@ -105,7 +105,7 @@ def get_history(self, user_id: str) -> LimitedRedisChatMessageHistory:
             )
             return history
         except Exception as e:
-            logger.error(f"Error retrieving chat history for user: {e}")
+            logger.error(f"[REDIS] Error retrieving chat history for user: {e}")
             st.warning(
                 "There was an error while loading previous messages. If this issue persists, try using a different browser or contact support."
             )
@@ -255,7 +255,7 @@ def display_references():
 
             else:
                 logger.error(
-                    f"Unknown message type: {m.type}. Expected one of {ROLES}."
+                    f"[LANGGRAPH] Unknown message type: {m.type}. Expected one of {ROLES}."
                 )
 
     def handle_user_input(self):
@@ -449,7 +449,7 @@ def _get_stream():
 
             except GraphRecursionError as e:
                 # TODO handle recursion limit error
-                logger.exception(f"Recursion Limit reached: {e}")
+                logger.exception(f"[LANGGRAPH] Recursion Limit reached: {e}")
                 response = session_state["_"](
                     "I'm sorry, but I couldn't find enough information to fully answer your question. Could you please try rephrasing your query and ask again?"
                 )
@@ -478,7 +478,6 @@ def _get_stream():
 
         with st.chat_message(ROLES[0], avatar="./static/Icon-chatbot.svg"):
             with st.spinner(session_state["_"]("Generating response...")):
-                logger.info(f"User's query: {prompt}")
 
                 start_time = time.time()
                 settings.time_request_sent = start_time
@@ -492,7 +491,7 @@ def _get_stream():
                 time_taken = end_time - start_time
                 session_state["time_taken"] = time_taken
                 logger.info(
-                    f"Time taken to serve whole answer to the user: {time_taken} seconds"
+                    f"[METRICS]Time taken to serve whole answer to the user: {time_taken} seconds"
                 )
 
                 self.store_response(response, prompt, graph)
@@ -570,6 +569,11 @@ def store_response(
         #         "avatar": "./static/Icon-chatbot.svg",
         #     }
         # )
+
+        # Log user query and bot answer
+        logger.info(f"[USERQUERY] User's query: {prompt}")
+        logger.info(f"[BOTANSWER] Assistant's response: {output}")
+
         st.session_state.user_query = prompt
 
         # summarize the conversation
@@ -725,7 +729,7 @@ def show_feedback_faces(self):
             try:
                 st.markdown(msg.format(selected + 1))
             except Exception as e:
-                logger.error(f"Error displaying feedback message: {e}")
+                logger.error(f"[FEEDBACK] Error displaying feedback message: {e}")
 
     def ask_further_feedback(self):
         if (
@@ -787,7 +791,7 @@ def log_feedback(self):
                 feedback["response"] = st.session_state.messages[-1].content
                 feedback["time_taken"] = session_state.time_taken
 
-                logger.info(f"Feedback= {feedback}")
+                logger.info(f"[FEEDBACK] Feedback= {feedback}")
                 session_state.feedback_saved = True
 
     @st.dialog("ask.UOS")

src/chatbot/agents/agent_lang_graph.py

@@ -134,7 +134,7 @@ def grade_documents(self, state: State) -> Literal["generate", "rewrite"]:
 
         tool_messages = state.get("tool_messages", "")
         if len(tool_messages) < 10:
-            logger.debug("[GRADE DOCUMENTS EDGE] No tool messages found")
+            logger.debug("[LANGGRAPH] GRADE DOCUMENTS EDGE: No tool messages found")
             return "rewrite"
 
         tool_query = " ".join(state["search_query"])
@@ -172,7 +172,7 @@ class GradeResult(BaseModel):
                 # TODO Further process the relevant paragraphs
                 # self._clean_tool_message = scored_result.relevant_paragraphs
                 logger.debug(
-                    f"[GRADE DOCUMENTS EDGE] DECISION: DOCS RELEVANT. Reason: {scored_result.reason}"
+                    f"[LANGGRAPH][GRADE DOCUMENTS EDGE] DECISION: DOCS RELEVANT. Reason: {scored_result.reason}"
                 )
                 if state.get("teaching_degree", False):
                     return "generate_teaching_degree_node"
@@ -184,12 +184,12 @@ class GradeResult(BaseModel):
 
             else:
                 logger.debug(
-                    f"[GRADE DOCUMENTS EDGE] DECISION: DOCS NOT RELEVANT. Reason: {scored_result.reason}"
+                    f"[LANGGRAPH][GRADE DOCUMENTS EDGE] DECISION: DOCS NOT RELEVANT. Reason: {scored_result.reason}"
                 )
                 return "rewrite"
         except Exception as e:
             logger.error(
-                f"[GRADE DOCUMENTS EDGE] Error occurred while grading documents: {e}"
+                f"[LANGGRAPH][GRADE DOCUMENTS EDGE] Error occurred while grading documents: {e}"
             )
             raise e
 
@@ -315,7 +315,7 @@ def judge_node(self, state: State) -> Dict:
             Dict: Updated state with judgement result
         """
 
-        logger.debug("[JUDGE NODE] Evaluating agent's decision to use tools")
+        logger.debug("[LANGGRAPH][JUDGE NODE] Evaluating agent's decision to use tools")
 
         class JudgementResult(BaseModel):
             """Result of agent's tool usage judgement."""
@@ -363,7 +363,7 @@ class JudgementResult(BaseModel):
         if score.judgement_binary.lower() == "no":
             msg = [HumanMessage(content=translate_prompt()["use_tool_msg"])]
             logger.debug(
-                f"[JUGE NODE] The agent should have used a tool. Reason: {score.reason}"
+                f"[LANGGRAPH][JUGE NODE] The agent should have used a tool. Reason: {score.reason}"
             )
             return {
                 "messages": state["messages"] + msg,
@@ -429,11 +429,11 @@ def tool_node(self, state: Dict) -> Dict:
                         tool_call["args"]
                     )
                 logger.debug(
-                    f'[TOOL NODE] Successfully executed tool call:{tool_call["name"]}. Length of tool_resul: {len(tool_call)}'
+                    f'[LANGGRAPH][TOOL NODE] Successfully executed tool call:{tool_call["name"]}. Length of tool_resul: {len(tool_call)}'
                 )
             except Exception as e:
                 logger.exception(
-                    f"Error invoking tool: {tool_call['name']} with args: tool_call['args']: {e}"
+                    f"[LANGGRAPH]Error invoking tool: {tool_call['name']} with args: tool_call['args']: {e}"
                 )
                 raise e
 
@@ -523,7 +523,7 @@ def generate_helper(self, state, system_message_generate):
             response = self._llm.invoke(list(message_deque))
         else:
             logger.warning(
-                "No messages history found. Using system message only for generation."
+                "[LANGGRAPH] No messages history found. Using system message only for generation."
             )
             response = self._llm.invoke([system_message_generate])
         return {"messages": messages_history + [response]}
@@ -537,7 +537,7 @@ def generate(self, state: State) -> Dict:
         Returns:
             Dict: Updated state with generated response
         """
-        logger.debug("[GENERATE NODE] Generating answer")
+        logger.debug("[LANGGRAPH][GENERATE NODE] Generating answer")
 
         # tool_message = self._clean_tool_message or state.get("tool_messages", None)
         tool_message = state.get("tool_messages", None)
@@ -553,7 +553,7 @@ def generate(self, state: State) -> Dict:
 
     def generate_application(self, state: State) -> Dict:
 
-        logger.debug(["GENERATE APPLICATION NODE] Generating answer"])
+        logger.debug(["[LANGGRAPH][GENERATE APPLICATION NODE] Generating answer"])
         # tool_message = self._clean_tool_message or state.get("tool_messages", None)
         tool_message = state.get("tool_messages", None)
         system_message_generate = SystemMessage(
@@ -575,7 +575,7 @@ def generate_teaching_degree_node(self, state: State) -> Dict:
         Returns:
             Dict: Updated state with generated response
         """
-        logger.debug("[GENERATE TEACHING DEGREE NODE] Generating answer")
+        logger.debug("[LANGGRAPH][GENERATE TEACHING DEGREE NODE] Generating answer")
         # tool_message = self._clean_tool_message or state.get("tool_messages", None)
         tool_message = state.get("tool_messages", None)
         system_message_generate = SystemMessage(
@@ -593,7 +593,7 @@ def generate_teaching_degree_node(self, state: State) -> Dict:
     def juge_answer(self, state: State) -> Dict:
         """Judge the generated answer."""
 
-        logger.debug("[JUDGE ANSWER NODE] Judging the answer")
+        logger.debug("[LANGGRAPH][JUDGE ANSWER NODE] Judging the answer")
 
         class JudgeAnswerResult(BaseModel):
             """Result of answer judgement."""
@@ -720,7 +720,9 @@ def __init__(self, **data):
     def shorten_conversation_summary(self, summary: str) -> str:
         """Shorten the conversation summary if it exceeds the maximum token limit."""
 
-        logger.warning(f"[SHORTEN CONVERSATION SUMMARY] Summary length: {len(summary)}")
+        logger.warning(
+            f"[LANGGRAPH][SHORTEN CONVERSATION SUMMARY] Summary length: {len(summary)}"
+        )
         template = translate_prompt()["shorten_conversation_summary"]
 
         prompt = PromptTemplate(template=template, input_variables=["summary"])
@@ -879,7 +881,9 @@ def __call__(self, input: str) -> Union[str, Dict]:
             return response["messages"][-1].content
 
         except Exception as e:
-            logger.exception(f"An error occurred while generating response: {e}")
+            logger.exception(
+                f"[LANGGRAPH] An error occurred while generating response: {e}"
+            )
             return {
                 "output": "An error has occurred while trying to connect to the data source or APIs. Please try asking the question again."
             }

src/chatbot/tools/search_web_tool.py

@@ -134,13 +134,13 @@ def extract_cached_content(cached_content):
     try:
         return ast.literal_eval(cached_content)
     except Exception as e:
-        logger.exception(f"Could not extract cached content: {e}")
+        logger.exception(f"[CACHE] Could not extract cached content: {e}")
         return None
 
 
 async def generate_summary(text: str, query: str) -> str:
     """Generate a summary of the provided text."""
-    logger.info(f"Summarizing content, query: {query}")
+    logger.info(f"[LMM-OPERATION] Summarizing content, query: {query}")
 
     chunk_size = (settings.model.context_window * 4) // 2
     text_splitter = RecursiveCharacterTextSplitter(
@@ -230,7 +230,7 @@ async def get_web_content(
             return result_url, result_content
 
     except Exception as e:
-        logger.exception(f"Error while crawling the URL: {url}", exc_info=True)
+        logger.exception(f"[CRAWL] Error while crawling the URL: {url}", exc_info=True)
         return result_url, result_content
     finally:
         # Cache the result
@@ -240,7 +240,7 @@ async def get_web_content(
                 await client.setex(cache_key, TTL, cache_value)
             except Exception as e:
                 logger.exception(
-                    f"Error while caching content for URL: {url}", exc_info=True
+                    f"[REDIS] Error while caching content for URL: {url}", exc_info=True
                 )
 
 
@@ -277,11 +277,11 @@ async def visit_urls_extract(
             if int(total_results) > 0:
                 links_search = [item["link"] for item in dict_response["items"]]
                 logger.debug(
-                    f"[ProgrammableSearch] Search Engine returned {len(links_search)} results (links)"
+                    f"[SEARCH] Search Engine returned {len(links_search)} results (links)"
                 )
             else:
                 logger.warning(
-                    f"[ProgrammableSearch] No results found by the search engine while requesting this URL: {url}"
+                    f"[SEARCH] No results found by the search engine while requesting this URL: {url}"
                 )
                 return [], []
 
@@ -312,7 +312,7 @@ async def visit_urls_extract(
             if result_content:
                 if len(result_content) < 20:
                     logger.warning(
-                        f"[Crawling] The URL content could not be extracted. Make sure the content is contained in current target elements: {target_elements}. URL: {url}"
+                        f"[CRAWL] The URL content could not be extracted. Make sure the content is contained in current target elements: {target_elements}. URL: {url}"
                     )
                     continue
                 contents.append(
@@ -379,8 +379,10 @@ async def async_search(client, **kwargs) -> Tuple[str, List]:
             final_output_tokens, final_search_tokens = compute_tokens(
                 final_output, query, agent_executor
             )
-            logger.info(f"Search tokens: {final_search_tokens}")
-            logger.info(f"Final output (search + prompt): {final_output_tokens}")
+            logger.info(f"[SEARCH] Search tokens: {final_search_tokens}")
+            logger.info(
+                f"[SEARCH] Final output (search + prompt): {final_output_tokens}"
+            )
 
             # Cache results
             if len(final_output) > 20:
@@ -390,13 +392,13 @@ async def async_search(client, **kwargs) -> Tuple[str, List]:
         return (final_output, visited_urls) if contents else ([], [])
 
     except ProgrammableSearchException as e:
-        logger.exception(f"Error: search engine: {e}", exc_info=True)
+        logger.exception(f"[SEARCH] Error: search engine: {e}", exc_info=True)
         raise ProgrammableSearchException(
             f"Failed: Programmable Search Engine. Status: {e}"
         )
 
     except Exception as e:
-        logger.exception(f"Error while searching the web: {e}", exc_info=True)
+        logger.exception(f"[SEARCH] Error while searching the web: {e}", exc_info=True)
         return [], []
 
 
@@ -410,7 +412,7 @@ def search_uni_web(**kwargs) -> Tuple[str, List]:
         try:
             loop = asyncio.get_running_loop()
             nest_asyncio.apply()
-            logger.debug("Running within an existing event loop")
+            logger.debug("[SYSTEM] Running within an existing event loop")
             client = redis.Redis(host="redis", port=6379, decode_responses=True)
             return asyncio.run_coroutine_threadsafe(
                 async_search(client, **kwargs), loop
@@ -426,7 +428,7 @@ async def complete_search_flow():
 
             return asyncio.run(complete_search_flow())
     except Exception as e:
-        logger.exception(f"Error in search execution: {str(e)}")
+        logger.exception(f"[SEARCH] Error in search execution: {str(e)}")
         return [], []
 
     # try:

src/chatbot_log/log_tags.md

@@ -0,0 +1,29 @@
+# Log Tags
+
+- API: API called 
+- AUTH: Authentication
+- REDIS
+- LANGGRAPH
+- USERQUERY
+- BOTANSWER
+- FEEDBACK
+- CRAWL
+- SEARCH: e.g., Programmable search engine related logs
+- LMM-OPERATION
+- FILEIO: File input/output operations
+- SECURITY: Security-related events
+- METRICS: Performance or usage metrics
+- TASK: Background tasks or jobs
+- CONFIG: Configuration changes
+- SYSTEM: System-level events
+- CACHE: Caching operations
+
+
+## Example Usage
+```python
+logger.info("[API] Received GET request for /users")
+logger.error("[DB] Database connection failed")
+logger.debug("[AUTH] Token validation started")
+```
+
+