Add additional logs and stop using root logger (#641)

adamdougal · web-flow · commit c3a4eb527640 · 2024-04-09T16:15:19.000Z
* Add additional logs and stop using root logger Required by #637 * Add test to increase coverage
diff --git a/code/backend/batch/AddURLEmbeddings.py b/code/backend/batch/AddURLEmbeddings.py
@@ -10,10 +10,12 @@
 
 bp_add_url_embeddings = func.Blueprint()
 
+logger = logging.getLogger(__name__)
+
 
 @bp_add_url_embeddings.route(route="AddURLEmbeddings")
 def add_url_embeddings(req: func.HttpRequest) -> func.HttpResponse:
-    logging.info("Python HTTP trigger function processed a request.")
+    logger.info("Python HTTP trigger function processed a request.")
     # Get Url from request
     url = req.params.get("url")
     if not url:
diff --git a/code/backend/batch/BatchPushResults.py b/code/backend/batch/BatchPushResults.py
@@ -12,6 +12,8 @@
 
 bp_batch_push_results = func.Blueprint()
 
+logger = logging.getLogger(__name__)
+
 
 def _get_file_name_from_message(msg: func.QueueMessage) -> str:
     message_body = json.loads(msg.get_body().decode("utf-8"))
@@ -27,7 +29,7 @@ def _get_file_name_from_message(msg: func.QueueMessage) -> str:
     arg_name="msg", queue_name="doc-processing", connection="AzureWebJobsStorage"
 )
 def batch_push_results(msg: func.QueueMessage) -> None:
-    logging.info(
+    logger.info(
         "Python queue trigger function processed a queue item: %s",
         msg.get_body().decode("utf-8"),
     )
diff --git a/code/backend/batch/BatchStartProcessing.py b/code/backend/batch/BatchStartProcessing.py
@@ -12,10 +12,12 @@
 bp_batch_start_processing = func.Blueprint()
 env_helper: EnvHelper = EnvHelper()
 
+logger = logging.getLogger(__name__)
+
 
 @bp_batch_start_processing.route(route="BatchStartProcessing")
 def batch_start_processing(req: func.HttpRequest) -> func.HttpResponse:
-    logging.info("Requested to start processing all documents received")
+    logger.info("Requested to start processing all documents received")
     # Set up Blob Storage Client
     azure_blob_storage_client = AzureBlobStorageClient()
     # Get all files from Blob Storage
diff --git a/code/backend/batch/GetConversationResponse.py b/code/backend/batch/GetConversationResponse.py
@@ -10,10 +10,12 @@
 bp_get_conversation_response = func.Blueprint()
 env_helper: EnvHelper = EnvHelper()
 
+logger = logging.getLogger(__name__)
+
 
 @bp_get_conversation_response.route(route="GetConversationResponse")
 def get_conversation_response(req: func.HttpRequest) -> func.HttpResponse:
-    logging.info("Python HTTP trigger function processed a request.")
+    logger.info("Python HTTP trigger function processed a request.")
 
     message_orchestrator = Orchestrator()
 
@@ -55,5 +57,5 @@ def get_conversation_response(req: func.HttpRequest) -> func.HttpResponse:
         return func.HttpResponse(json.dumps(response_obj), status_code=200)
 
     except Exception as e:
-        logging.exception("Exception in /api/GetConversationResponse")
+        logger.exception("Exception in /api/GetConversationResponse")
         return func.HttpResponse(json.dumps({"error": str(e)}), status_code=500)
diff --git a/code/backend/batch/utilities/helpers/DocumentProcessorHelper.py b/code/backend/batch/utilities/helpers/DocumentProcessorHelper.py
@@ -37,5 +37,5 @@ def process(self, source_url: str, processors: List[Processor]):
                 ]
                 return vector_store.add_documents(documents=documents, keys=keys)
             except Exception as e:
-                logging.error(f"Error adding embeddings for {source_url}: {e}")
+                logger.error(f"Error adding embeddings for {source_url}: {e}")
                 raise e
diff --git a/code/backend/batch/utilities/helpers/EnvHelper.py b/code/backend/batch/utilities/helpers/EnvHelper.py
@@ -178,7 +178,7 @@ def get_env_var_bool(self, var_name: str, default: str = "True") -> bool:
     def check_env():
         for attr, value in EnvHelper().__dict__.items():
             if value == "":
-                logging.warning(f"{attr} is not set in the environment variables.")
+                logger.warning(f"{attr} is not set in the environment variables.")
 
 
 class SecretHelper:
diff --git a/code/backend/batch/utilities/orchestrator/LangChainAgent.py b/code/backend/batch/utilities/orchestrator/LangChainAgent.py
@@ -1,3 +1,4 @@
+import logging
 from typing import List
 from langchain.agents import Tool
 from langchain.memory import ConversationBufferMemory
@@ -14,6 +15,8 @@
 from ..parser.OutputParserTool import OutputParserTool
 from ..common.Answer import Answer
 
+logger = logging.getLogger(__name__)
+
 
 class LangChainAgent(OrchestratorBase):
     def __init__(self) -> None:
@@ -57,12 +60,14 @@ def orchestrate(
 
         # Call Content Safety tool
         if self.config.prompts.enable_content_safety:
+            logger.debug("Calling content safety with question")
             filtered_user_message = (
                 self.content_safety_checker.validate_input_and_replace_if_harmful(
                     user_message
                 )
             )
             if user_message != filtered_user_message:
+                logger.warning("Content safety detected harmful content in question")
                 messages = output_formatter.parse(
                     question=user_message,
                     answer=filtered_user_message,
@@ -115,6 +120,7 @@ def orchestrate(
             answer = Answer(question=user_message, answer=answer)
 
         if self.config.prompts.enable_post_answering_prompt:
+            logger.debug("Running post answering prompt")
             post_prompt_tool = PostPromptTool()
             answer = post_prompt_tool.validate_answer(answer)
             self.log_tokens(
@@ -124,12 +130,14 @@ def orchestrate(
 
         # Call Content Safety tool
         if self.config.prompts.enable_content_safety:
+            logger.debug("Calling content safety with answer")
             filtered_answer = (
                 self.content_safety_checker.validate_output_and_replace_if_harmful(
                     answer.answer
                 )
             )
             if answer.answer != filtered_answer:
+                logger.warning("Content safety detected harmful content in answer")
                 messages = output_formatter.parse(
                     question=user_message, answer=filtered_answer, source_documents=[]
                 )
diff --git a/code/backend/batch/utilities/orchestrator/OpenAIFunctions.py b/code/backend/batch/utilities/orchestrator/OpenAIFunctions.py
@@ -1,3 +1,4 @@
+import logging
 from typing import List
 import json
 
@@ -10,6 +11,8 @@
 from ..parser.OutputParserTool import OutputParserTool
 from ..common.Answer import Answer
 
+logger = logging.getLogger(__name__)
+
 
 class OpenAIFunctionsOrchestrator(OrchestratorBase):
     def __init__(self) -> None:
@@ -57,12 +60,14 @@ def orchestrate(
 
         # Call Content Safety tool
         if self.config.prompts.enable_content_safety:
+            logger.debug("Calling content safety with question")
             filtered_user_message = (
                 self.content_safety_checker.validate_input_and_replace_if_harmful(
                     user_message
                 )
             )
             if user_message != filtered_user_message:
+                logger.warning("Content safety detected harmful content in question")
                 messages = output_formatter.parse(
                     question=user_message,
                     answer=filtered_user_message,
@@ -95,7 +100,9 @@ def orchestrate(
         # TODO: call content safety if needed
 
         if result.choices[0].finish_reason == "function_call":
+            logger.info("Function call detected")
             if result.choices[0].message.function_call.name == "search_documents":
+                logger.info("search_documents function detected")
                 question = json.loads(
                     result.choices[0].message.function_call.arguments
                 )["question"]
@@ -110,13 +117,15 @@ def orchestrate(
 
                 # Run post prompt if needed
                 if self.config.prompts.enable_post_answering_prompt:
+                    logger.debug("Running post answering prompt")
                     post_prompt_tool = PostPromptTool()
                     answer = post_prompt_tool.validate_answer(answer)
                     self.log_tokens(
                         prompt_tokens=answer.prompt_tokens,
                         completion_tokens=answer.completion_tokens,
                     )
             elif result.choices[0].message.function_call.name == "text_processing":
+                logger.info("text_processing function detected")
                 text = json.loads(result.choices[0].message.function_call.arguments)[
                     "text"
                 ]
@@ -132,17 +141,20 @@ def orchestrate(
                     completion_tokens=answer.completion_tokens,
                 )
         else:
+            logger.info("No function call detected")
             text = result.choices[0].message.content
             answer = Answer(question=user_message, answer=text)
 
         # Call Content Safety tool
         if self.config.prompts.enable_content_safety:
+            logger.debug("Calling content safety with answer")
             filtered_answer = (
                 self.content_safety_checker.validate_output_and_replace_if_harmful(
                     answer.answer
                 )
             )
             if answer.answer != filtered_answer:
+                logger.warning("Content safety detected harmful content in answer")
                 messages = output_formatter.parse(
                     question=user_message, answer=filtered_answer, source_documents=[]
                 )
diff --git a/code/backend/batch/utilities/parser/OutputParserTool.py b/code/backend/batch/utilities/parser/OutputParserTool.py
@@ -5,6 +5,8 @@
 from .ParserBase import ParserBase
 from ..common.SourceDocument import SourceDocument
 
+logger = logging.getLogger(__name__)
+
 
 class OutputParserTool(ParserBase):
     def __init__(self) -> None:
@@ -55,7 +57,7 @@ def parse(
             idx = i - 1
 
             if idx >= len(source_documents):
-                logging.warning(f"Source document {i} not provided, skipping doc")
+                logger.warning(f"Source document {i} not provided, skipping doc")
                 continue
 
             doc = source_documents[idx]
diff --git a/code/create_app.py b/code/create_app.py
@@ -10,6 +10,9 @@
 from backend.batch.utilities.helpers.EnvHelper import EnvHelper
 
 
+logger = logging.getLogger(__name__)
+
+
 def prepare_body_headers_with_data(request, env_helper: EnvHelper):
     request_messages = request.json["messages"]
 
@@ -320,7 +323,7 @@ def conversation_azure_byod():
                 return conversation_without_data(request, env_helper)
         except Exception as e:
             errorMessage = str(e)
-            logging.exception(
+            logger.exception(
                 f"Exception in /api/conversation/azure_byod | {errorMessage}"
             )
             return (
@@ -365,7 +368,7 @@ def conversation_custom():
 
         except Exception as e:
             errorMessage = str(e)
-            logging.exception(f"Exception in /api/conversation/custom | {errorMessage}")
+            logger.exception(f"Exception in /api/conversation/custom | {errorMessage}")
             return (
                 jsonify(
                     {
diff --git a/code/tests/functional/backend_api/app_config.py b/code/tests/functional/backend_api/app_config.py
@@ -1,6 +1,8 @@
 import logging
 import os
 
+logger = logging.getLogger(__name__)
+
 
 class AppConfig:
     config: dict[str, str | None] = {
@@ -40,13 +42,13 @@ def get_all(self) -> dict[str, str | None]:
     def apply_to_environment(self) -> None:
         for key, value in self.config.items():
             if value is not None:
-                logging.info(f"Applying env var: {key}={value}")
+                logger.info(f"Applying env var: {key}={value}")
                 os.environ[key] = value
             else:
-                logging.info(f"Removing env var: {key}")
+                logger.info(f"Removing env var: {key}")
                 os.environ.pop(key, None)
 
     def remove_from_environment(self) -> None:
         for key in self.config.keys():
-            logging.info(f"Removing env var: {key}")
+            logger.info(f"Removing env var: {key}")
             os.environ.pop(key, None)
diff --git a/code/tests/functional/backend_api/common.py b/code/tests/functional/backend_api/common.py
@@ -6,14 +6,16 @@
 from threading import Thread
 from create_app import create_app
 
+logger = logging.getLogger(__name__)
+
 
 def start_app(app_port: int) -> Thread:
-    logging.info(f"Starting application on port {app_port}")
+    logger.info(f"Starting application on port {app_port}")
     app = create_app()
     app_process = threading.Thread(target=lambda: app.run(port=app_port), daemon=True)
     app_process.start()
     wait_for_app(app_port)
-    logging.info("Application started")
+    logger.info("Application started")
     return app_process
 
 
diff --git a/code/tests/functional/backend_api/tests/with_data/conftest.py b/code/tests/functional/backend_api/tests/with_data/conftest.py
@@ -3,10 +3,12 @@
 from tests.functional.backend_api.app_config import AppConfig
 from tests.functional.backend_api.common import get_free_port, start_app
 
+logger = logging.getLogger(__name__)
+
 
 @pytest.fixture(scope="package")
 def app_port() -> int:
-    logging.info("Getting free port")
+    logger.info("Getting free port")
     return get_free_port()
 
 
@@ -17,7 +19,7 @@ def app_url(app_port: int) -> str:
 
 @pytest.fixture(scope="package")
 def app_config(make_httpserver, ca):
-    logging.info("Creating APP CONFIG")
+    logger.info("Creating APP CONFIG")
     with ca.cert_pem.tempfile() as ca_temp_path:
         app_config = AppConfig(
             {
@@ -28,7 +30,7 @@ def app_config(make_httpserver, ca):
                 "CURL_CA_BUNDLE": ca_temp_path,
             }
         )
-        logging.info(f"Created app config: {app_config.get_all()}")
+        logger.info(f"Created app config: {app_config.get_all()}")
         yield app_config
 
 
diff --git a/code/tests/functional/backend_api/tests/without_data/conftest.py b/code/tests/functional/backend_api/tests/without_data/conftest.py
@@ -3,10 +3,12 @@
 from tests.functional.backend_api.app_config import AppConfig
 from tests.functional.backend_api.common import get_free_port, start_app
 
+logger = logging.getLogger(__name__)
+
 
 @pytest.fixture(scope="package")
 def app_port() -> int:
-    logging.info("Getting free port")
+    logger.info("Getting free port")
     return get_free_port()
 
 
@@ -17,7 +19,7 @@ def app_url(app_port: int) -> str:
 
 @pytest.fixture(scope="package")
 def app_config(make_httpserver, ca):
-    logging.info("Creating APP CONFIG")
+    logger.info("Creating APP CONFIG")
     with ca.cert_pem.tempfile() as ca_temp_path:
         app_config = AppConfig(
             {
@@ -27,7 +29,7 @@ def app_config(make_httpserver, ca):
                 "CURL_CA_BUNDLE": ca_temp_path,
             }
         )
-        logging.info(f"Created app config: {app_config.get_all()}")
+        logger.info(f"Created app config: {app_config.get_all()}")
         yield app_config
 
 
diff --git a/code/tests/utilities/test_EnvHelper.py b/code/tests/utilities/test_EnvHelper.py
@@ -59,3 +59,16 @@ def test_app_insights_enabled(monkeypatch: MonkeyPatch, value, expected):
 
     # then
     assert actual_appinsights_enabled == expected
+
+
+def test_keys_are_unset_when_auth_type_rbac(monkeypatch: MonkeyPatch):
+    # given
+    monkeypatch.setenv("AZURE_AUTH_TYPE", "rbac")
+
+    # when
+    env_helper = EnvHelper()
+
+    # then
+    assert env_helper.AZURE_SEARCH_KEY is None
+    assert env_helper.AZURE_OPENAI_API_KEY == ""
+    assert env_helper.AZURE_SPEECH_KEY is None

Original file line number	Diff line number	Diff line change
`@@ -12,6 +12,8 @@`
`12`	`12`
`13`	`13`	`bp_batch_push_results = func.Blueprint()`
`14`	`14`
	`15`	`+logger = logging.getLogger(__name__)`
	`16`	`+`
`15`	`17`
`16`	`18`	`def _get_file_name_from_message(msg: func.QueueMessage) -> str:`
`17`	`19`	`message_body = json.loads(msg.get_body().decode("utf-8"))`
`@@ -27,7 +29,7 @@ def _get_file_name_from_message(msg: func.QueueMessage) -> str:`
`27`	`29`	`arg_name="msg", queue_name="doc-processing", connection="AzureWebJobsStorage"`
`28`	`30`	`)`
`29`	`31`	`def batch_push_results(msg: func.QueueMessage) -> None:`
`30`		`- logging.info(`
	`32`	`+ logger.info(`
`31`	`33`	`"Python queue trigger function processed a queue item: %s",`
`32`	`34`	`msg.get_body().decode("utf-8"),`
`33`	`35`	`)`
Original file line number	Diff line number	Diff line change
`@@ -37,5 +37,5 @@ def process(self, source_url: str, processors: List[Processor]):`
`37`	`37`	`]`
`38`	`38`	`return vector_store.add_documents(documents=documents, keys=keys)`
`39`	`39`	`except Exception as e:`
`40`		`- logging.error(f"Error adding embeddings for {source_url}: {e}")`
	`40`	`+ logger.error(f"Error adding embeddings for {source_url}: {e}")`
`41`	`41`	`raise e`