refactor: improve logging format and exception handling across multiple modules

a-klos · a-klos · commit 4ea3e96d4c29 · 2025-10-24T09:00:01.000+02:00
diff --git a/libs/admin-api-lib/src/admin_api_lib/impl/file_services/s3_service.py b/libs/admin-api-lib/src/admin_api_lib/impl/file_services/s3_service.py
@@ -125,7 +125,7 @@ def delete_file(self, file_name: str) -> None:
         try:
             file_name = f"/{file_name}" if not file_name.startswith("/") else file_name
             self._s3_client.delete_object(Bucket=self._s3_settings.bucket, Key=file_name)
-            logger.info(f"File {file_name} successfully deleted.")
-        except Exception as e:
-            logger.error("Error deleting file %s: %s %s" % (file_name, e, traceback.format_exc()))
+            logger.info("File %s successfully deleted.", file_name)
+        except Exception:
+            logger.exception("Error deleting file %s", file_name)
             raise
diff --git a/libs/extractor-api-lib/src/extractor_api_lib/impl/extractors/file_extractors/pdf_extractor.py b/libs/extractor-api-lib/src/extractor_api_lib/impl/extractors/file_extractors/pdf_extractor.py
@@ -154,8 +154,9 @@ async def aextract_content(self, file_path: Path, name: str) -> list[InternalInf
                     )
                     pdf_elements += new_pdf_elements
 
-        logger.info(f"Extraction completed. Found {len(pdf_elements)} information pieces.")
-        return pdf_elements
+            
+            logger.info("Extraction completed. Found %d information pieces.", len(pdf_elements))
+            return pdf_elements
 
     def _is_text_based(self, page: Page) -> bool:
         """Classify whether a page is text-based, scanned.
@@ -200,8 +201,8 @@ def _extract_tables_from_text_page(
                 table_df = pd.DataFrame(table_data)
                 try:
                     converted_table = self._dataframe_converter.convert(table_df)
-                except TypeError as e:
-                    logger.error(f"Error while converting table to string: {e}")
+                except TypeError:
+                    logger.exception("Error while converting table to string")
                     continue
                 if not converted_table.strip():
                     continue
@@ -215,8 +216,8 @@ def _extract_tables_from_text_page(
                         information_id=hash_datetime(),
                     )
                 )
-        except Exception as e:
-            logger.warning(f"Failed to find tables on page {page_index}: {e}")
+        except Exception:
+            logger.warning("Failed to find tables on page %d", page_index, exc_info=True)
 
         return table_elements
 
@@ -321,19 +322,19 @@ def _extract_tables_from_scanned_page(
                                     },
                                 )
                             )
-                    except Exception as e:
-                        logger.warning(f"Failed to convert Camelot table {i + 1}: {e}")
+                    except Exception:
+                        logger.warning("Failed to convert Camelot table %d", i + 1, exc_info=True)
 
-        except Exception as e:
-            logger.debug(f"Camelot table extraction failed for page {page_index}: {e}")
+        except Exception:
+            logger.debug("Camelot table extraction failed for page %d", page_index, exc_info=True)
 
         return table_elements
 
     def _extract_text_from_text_page(self, page: Page) -> str:
         try:
             return page.extract_text() or ""
-        except Exception as e:
-            logger.warning(f"Failed to extract text with pdfplumber: {e}")
+        except Exception:
+            logger.warning("Failed to extract text with pdfplumber", exc_info=True)
             return ""
 
     def _extract_content_from_page(
diff --git a/libs/extractor-api-lib/tests/pdf_extractor_test.py b/libs/extractor-api-lib/tests/pdf_extractor_test.py
@@ -551,8 +551,8 @@ async def test_end_to_end_extraction(self, pdf_extractor, test_pdf_files):
             text_count = sum(1 for elem in result if elem.type == ContentType.TEXT)
             table_count = sum(1 for elem in result if elem.type == ContentType.TABLE)
 
-            logger.info(f"  Text elements: {text_count}")
-            logger.info(f"  Table elements: {table_count}")
+            logger.info("  Text elements: %d", text_count)
+            logger.info("  Table elements: %d", table_count)
 
             # Verify metadata completeness
             for i, element in enumerate(result):
diff --git a/libs/rag-core-api/src/rag_core_api/impl/answer_generation_chains/language_detection_chain.py b/libs/rag-core-api/src/rag_core_api/impl/answer_generation_chains/language_detection_chain.py
@@ -13,18 +13,12 @@
 
 from langchain_core.output_parsers import StrOutputParser
 from langchain_core.runnables import Runnable, RunnableConfig
+from pydantic import BaseModel, field_validator
+from langchain_core.output_parsers import PydanticOutputParser
 
 from rag_core_api.impl.graph.graph_state.graph_state import AnswerGraphState
 from rag_core_lib.runnables.async_runnable import AsyncRunnable
 from rag_core_lib.impl.langfuse_manager.langfuse_manager import LangfuseManager
-from pydantic import BaseModel, field_validator
-from langchain_core.output_parsers import PydanticOutputParser
-
-
-RunnableInput = AnswerGraphState
-RunnableOutput = str
-
-
 from rag_core_api.utils.utils import (
     strip_code_fences,
     norm_lang,
@@ -35,13 +29,69 @@
 )
 
 
+RunnableInput = AnswerGraphState
+RunnableOutput = str
+
+
 class LanguageDetectionChain(AsyncRunnable[RunnableInput, RunnableOutput]):
     """Base class for language detection of the input question."""
 
     def __init__(self, langfuse_manager: LangfuseManager):
         """Initialize LanguageDetectionChain with LangfuseManager."""
         self._langfuse_manager = langfuse_manager
 
+    @staticmethod
+    def _strict_json_parse(text: str) -> Optional[str]:
+        """Attempt to strictly parse JSON and extract the language code."""
+        try:
+            data = json.loads(text)
+            c = extract_lang_from_parsed(data)
+            if c:
+                return c
+        except (json.JSONDecodeError, TypeError, ValueError):
+            return None
+
+    @staticmethod
+    def _loose_json_parse(text: str) -> Optional[str]:
+        for pattern in (JSONISH_DQ_RE, JSONISH_SQ_RE, JSONISH_LOOSE_RE):
+            m = pattern.search(text)
+            if m:
+                c = norm_lang(m.group(1))
+                if c:
+                    return c
+        return None
+
+    @staticmethod
+    def _extract_language_code(raw_output: Any) -> str:
+        """Extract a two-letter ISO 639-1 language code; default to 'en' on failure."""
+        # 1) Already parsed structures
+        c = extract_lang_from_parsed(raw_output)
+        if c:
+            return c
+
+        # 2) Strings (common case)
+        if isinstance(raw_output, str):
+            text = raw_output.strip().lstrip("\ufeff")
+            text = strip_code_fences(text)
+
+            # a) Direct 'xx' or 'xx-YY'
+            c = norm_lang(text)
+            if c:
+                return c
+
+            # b) Try strict JSON parsing
+            c = LanguageDetectionChain._strict_json_parse(text)
+            if c:
+                return c
+
+            # c) JSON-ish fallbacks (handles single quotes, loose key/value, etc.)
+            c = LanguageDetectionChain._loose_json_parse(text)
+            if c:
+                return c
+
+        # Fallback
+        return "en"
+
     async def ainvoke(
         self, chain_input: RunnableInput, config: Optional[RunnableConfig] = None, **kwargs: Any
     ) -> RunnableOutput:
@@ -73,56 +123,15 @@ def two_letter_lower(cls, v: str) -> str:
         # when the model doesn't follow instructions. Instead, we keep a string parser and
         # parse defensively in ainvoke(). We still inject format instructions to guide the LLM.
         try:
-            fmt_instructions = PydanticOutputParser(
-                pydantic_object=_LangSchema
-            ).get_format_instructions()
+            fmt_instructions = PydanticOutputParser(pydantic_object=_LangSchema).get_format_instructions()
         except Exception:
             fmt_instructions = (
                 "Return a strict JSON object with a single field 'language' as a "
-                "lowercase two-letter ISO 639-1 code, e.g. {\"language\":\"de\"}."
+                'lowercase two-letter ISO 639-1 code, e.g. {"language":"de"}.'
             )
 
         prompt = self._langfuse_manager.get_base_prompt(self.__class__.__name__).partial(
             format_instructions=fmt_instructions
         )
 
         return prompt | self._langfuse_manager.get_base_llm(self.__class__.__name__) | StrOutputParser()
-
-    @staticmethod
-    def _extract_language_code(raw_output: Any) -> str:
-        """Extract a two-letter ISO 639-1 language code; default to 'en' on failure."""
-
-        # 1) Already parsed structures
-        c = extract_lang_from_parsed(raw_output)
-        if c:
-            return c
-
-        # 2) Strings (common case)
-        if isinstance(raw_output, str):
-            text = raw_output.strip().lstrip("\ufeff")
-            text = strip_code_fences(text)
-
-            # a) Direct 'xx' or 'xx-YY'
-            c = norm_lang(text)
-            if c:
-                return c
-
-            # b) Try strict JSON parsing
-            try:
-                data = json.loads(text)
-                c = extract_lang_from_parsed(data)
-                if c:
-                    return c
-            except Exception:
-                pass
-
-            # c) JSON-ish fallbacks (handles single quotes, loose key/value, etc.)
-            for pattern in (JSONISH_DQ_RE, JSONISH_SQ_RE, JSONISH_LOOSE_RE):
-                m = pattern.search(text)
-                if m:
-                    c = norm_lang(m.group(1))
-                    if c:
-                        return c
-
-        # Fallback
-        return "en"
diff --git a/libs/rag-core-api/src/rag_core_api/impl/api_endpoints/default_information_pieces_remover.py b/libs/rag-core-api/src/rag_core_api/impl/api_endpoints/default_information_pieces_remover.py
@@ -48,11 +48,11 @@ def remove_information_piece(self, delete_request: DeleteRequest) -> None:
             metadata = {}
             for key_value_pair in delete_request.metadata:
                 metadata["metadata." + key_value_pair.key] = json.loads(key_value_pair.value)
-        except Exception as e:
-            logger.error("Error while parsing metadata: %s", e)
+        except Exception:
+            logger.exception("Error while parsing metadata")
             raise HTTPException(
                 status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
-                detail="Error while parsing metadata: %s" % e,
+                detail="Error while parsing metadata.",
             )
         if not metadata:
             raise HTTPException(
@@ -61,9 +61,9 @@ def remove_information_piece(self, delete_request: DeleteRequest) -> None:
             )
         try:
             self._vector_database.delete(metadata)
-        except Exception as e:
-            logger.error("Error while deleting from vector db: %s", e)
+        except Exception:
+            logger.exception("Error while deleting from vector db")
             raise HTTPException(
                 status_code=status.HTTP_404_NOT_FOUND,
-                detail="Error while deleting %s from vector db" % delete_request.metadata,
+                detail="Error while deleting from vector db.",
             )
diff --git a/libs/rag-core-api/src/rag_core_api/impl/evaluator/langfuse_ragas_evaluator.py b/libs/rag-core-api/src/rag_core_api/impl/evaluator/langfuse_ragas_evaluator.py
@@ -139,8 +139,8 @@ async def aevaluate(self) -> None:
         try:
             evaluation_dataset = self._get_dataset(self._settings.evaluation_dataset_name)
             await self._aauto_answer_generation4evaluation_questions(evaluation_dataset)
-        except Exception as e:
-            logger.error("Failed to evaluate questions: %s", e)
+        except Exception:
+            logger.exception("Failed to evaluate questions")
 
     async def _aauto_answer_generation4evaluation_questions(self, dataset) -> tuple[int, Dataset]:
         session_id = str(uuid4())
@@ -171,8 +171,8 @@ async def _aevaluate_question(self, item, experiment_name: str, generation_time:
                 # Use langfuse.start_as_current_generation for generation
                 try:
                     response = await self._chat_endpoint.achat(config["metadata"]["session_id"], chat_request)
-                except Exception as e:
-                    logger.info("Error while answering question %s: %s", item.input, e)
+                except Exception:
+                    logger.exception("Error while answering question %s", item.input)
                     response = None
                 output = {
                     "answer": response.answer if response else None,
diff --git a/libs/rag-core-api/src/rag_core_api/impl/graph/chat_graph.py b/libs/rag-core-api/src/rag_core_api/impl/graph/chat_graph.py
@@ -220,7 +220,9 @@ async def _rephrase_node(self, state: dict, config: Optional[RunnableConfig] = N
         rephrased_question = await self._rephrasing_chain.ainvoke(chain_input=state, config=config)
         # Ensure rephrased_question is a string
         rephrased_question = getattr(rephrased_question, "content", rephrased_question)
-        rephrased_question = rephrased_question.strip() if isinstance(rephrased_question, str) else str(rephrased_question).strip()
+        rephrased_question = (
+            rephrased_question.strip() if isinstance(rephrased_question, str) else str(rephrased_question).strip()
+        )
         if not rephrased_question:
             rephrased_question = state["question"]
         return {"rephrased_question": rephrased_question}
@@ -249,7 +251,7 @@ async def _retrieve_node(self, state: dict) -> dict:
                 self.FINISH_REASONS: ["NoOrEmptyCollectionError"],
             }
         except Exception as e:
-            logger.error("Error while searching for documents in vector database: %s", e)
+            logger.exception("Error while searching for documents in vector database.")
             raise HTTPException(
                 status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
                 detail="Error while searching for documents in vector database: %s" % e,
diff --git a/libs/rag-core-api/src/rag_core_api/impl/vector_databases/qdrant_database.py b/libs/rag-core-api/src/rag_core_api/impl/vector_databases/qdrant_database.py
@@ -112,8 +112,8 @@ async def asearch(self, query: str, search_kwargs: dict, filter_kwargs: dict | N
                 related_results += self._get_related(res.metadata["related"])
             return results + related_results
 
-        except Exception as e:
-            logger.error(f"Search failed: {str(e)}")
+        except Exception:
+            logger.exception("Search failed")
             raise
 
     def get_specific_document(self, document_id: str) -> list[Document]:
diff --git a/libs/rag-core-api/tests/language_detection_chain_test.py b/libs/rag-core-api/tests/language_detection_chain_test.py
@@ -16,6 +16,7 @@
 
 @pytest.mark.asyncio
 async def test_language_detection_returns_iso_code_json():
+    """LLM returns strict JSON; chain extracts two-letter ISO code."""
     llm = FakeListLLM(responses=['{"language": "de"}'])
     mock_langfuse = MagicMock()
     manager = MockLangfuseManager(
@@ -40,8 +41,9 @@ async def test_language_detection_returns_iso_code_json():
 
 @pytest.mark.asyncio
 async def test_language_detection_fallback_to_en_on_garbage():
+    """Non-JSON response triggers fallback to 'en'."""
     # LLM returns non-JSON, the chain should fall back to 'en'
-    llm = FakeListLLM(responses=['I think it is German'])
+    llm = FakeListLLM(responses=["I think it is German"])
     mock_langfuse = MagicMock()
     manager = MockLangfuseManager(
         langfuse=mock_langfuse,
@@ -65,6 +67,7 @@ async def test_language_detection_fallback_to_en_on_garbage():
 
 @pytest.mark.asyncio
 async def test_language_detection_accepts_code_fenced_json():
+    """Code-fenced JSON is parsed after stripping fences."""
     llm = FakeListLLM(responses=['```json\n{"language": "fr"}\n```'])
     mock_langfuse = MagicMock()
     manager = MockLangfuseManager(
@@ -89,6 +92,7 @@ async def test_language_detection_accepts_code_fenced_json():
 
 @pytest.mark.asyncio
 async def test_language_detection_accepts_locale_variant_and_normalizes():
+    """Locale variants like de-DE normalize to base code 'de'."""
     llm = FakeListLLM(responses=['{"language": "de-DE"}'])
     mock_langfuse = MagicMock()
     manager = MockLangfuseManager(
@@ -113,6 +117,7 @@ async def test_language_detection_accepts_locale_variant_and_normalizes():
 
 @pytest.mark.asyncio
 async def test_language_detection_handles_single_quoted_jsonish():
+    """Single-quoted JSON-ish text is handled via regex fallback."""
     llm = FakeListLLM(responses=["{'language': 'es'}"])
     mock_langfuse = MagicMock()
     manager = MockLangfuseManager(
@@ -137,6 +142,7 @@ async def test_language_detection_handles_single_quoted_jsonish():
 
 @pytest.mark.asyncio
 async def test_language_detection_handles_loose_kv_format():
+    """Loose key-value format like language: "it" is parsed."""
     llm = FakeListLLM(responses=['language: "it"'])
     mock_langfuse = MagicMock()
     manager = MockLangfuseManager(
diff --git a/libs/rag-core-api/tests/utils_language_parsing_test.py b/libs/rag-core-api/tests/utils_language_parsing_test.py
@@ -1,11 +1,10 @@
 """Tests for rag_core_api.utils.utils language parsing helpers."""
 
-import pytest
-
 from rag_core_api.utils.utils import norm_lang, strip_code_fences, extract_lang_from_parsed
 
 
 def test_norm_lang_variants():
+    """Ensure various inputs normalize to ISO 639-1 codes or empty string."""
     assert norm_lang("de") == "de"
     assert norm_lang("DE") == "de"
     assert norm_lang("de-DE") == "de"
@@ -17,11 +16,13 @@ def test_norm_lang_variants():
 
 
 def test_strip_code_fences():
+    """Strip code fences and return clean JSON text."""
     fenced = """```json\n{\n  \"language\": \"de\"\n}\n```"""
     assert strip_code_fences(fenced) == '{\n  "language": "de"\n}'
 
 
 def test_extract_from_parsed():
+    """Extract language from parsed structures like dicts and lists."""
     assert extract_lang_from_parsed({"language": "de"}) == "de"
     assert extract_lang_from_parsed([{"language": "en-US"}]) == "en"
     assert extract_lang_from_parsed({}) == ""
diff --git a/libs/rag-core-lib/src/rag_core_lib/impl/langfuse_manager/langfuse_manager.py b/libs/rag-core-lib/src/rag_core_lib/impl/langfuse_manager/langfuse_manager.py
diff --git a/services/mcp-server/src/rag_mcp_server.py b/services/mcp-server/src/rag_mcp_server.py
