Fix logging (#1874)

* Fix logging

* Fix

Author: pamelafox

app/backend/app.py

@@ -128,13 +128,13 @@ async def content_file(path: str, auth_claims: Dict[str, Any]):
     if path.find("#page=") > 0:
         path_parts = path.rsplit("#page=", 1)
         path = path_parts[0]
-    logging.info("Opening file %s", path)
+    current_app.logger.info("Opening file %s", path)
     blob_container_client: ContainerClient = current_app.config[CONFIG_BLOB_CONTAINER_CLIENT]
     blob: Union[BlobDownloader, DatalakeDownloader]
     try:
         blob = await blob_container_client.get_blob_client(path).download_blob()
     except ResourceNotFoundError:
-        logging.info("Path not found in general Blob container: %s", path)
+        current_app.logger.info("Path not found in general Blob container: %s", path)
         if current_app.config[CONFIG_USER_UPLOAD_ENABLED]:
             try:
                 user_oid = auth_claims["oid"]
@@ -143,7 +143,7 @@ async def content_file(path: str, auth_claims: Dict[str, Any]):
                 file_client = user_directory_client.get_file_client(path)
                 blob = await file_client.download_file()
             except ResourceNotFoundError:
-                logging.exception("Path not found in DataLake: %s", path)
+                current_app.logger.exception("Path not found in DataLake: %s", path)
                 abort(404)
         else:
             abort(404)
@@ -314,7 +314,7 @@ async def speech():
             current_app.logger.error("Unexpected result reason: %s", result.reason)
             raise Exception("Speech synthesis failed. Check logs for details.")
     except Exception as e:
-        logging.exception("Exception in /speech")
+        current_app.logger.exception("Exception in /speech")
         return jsonify({"error": str(e)}), 500
 
 
@@ -453,6 +453,7 @@ async def setup_clients():
     # Set up authentication helper
     search_index = None
     if AZURE_USE_AUTHENTICATION:
+        current_app.logger.info("AZURE_USE_AUTHENTICATION is true, setting up search index client")
         search_index_client = SearchIndexClient(
             endpoint=f"https://{AZURE_SEARCH_SERVICE}.search.windows.net",
             credential=azure_credential,
@@ -516,6 +517,7 @@ async def setup_clients():
     openai_client: AsyncOpenAI
 
     if USE_SPEECH_OUTPUT_AZURE:
+        current_app.logger.info("USE_SPEECH_OUTPUT_AZURE is true, setting up Azure speech service")
         if not AZURE_SPEECH_SERVICE_ID or AZURE_SPEECH_SERVICE_ID == "":
             raise ValueError("Azure speech resource not configured correctly, missing AZURE_SPEECH_SERVICE_ID")
         if not AZURE_SPEECH_SERVICE_LOCATION or AZURE_SPEECH_SERVICE_LOCATION == "":
@@ -530,28 +532,36 @@ async def setup_clients():
     if OPENAI_HOST.startswith("azure"):
         api_version = os.getenv("AZURE_OPENAI_API_VERSION") or "2024-03-01-preview"
         if OPENAI_HOST == "azure_custom":
+            current_app.logger.info("OPENAI_HOST is azure_custom, setting up Azure OpenAI custom client")
             if not AZURE_OPENAI_CUSTOM_URL:
                 raise ValueError("AZURE_OPENAI_CUSTOM_URL must be set when OPENAI_HOST is azure_custom")
             endpoint = AZURE_OPENAI_CUSTOM_URL
         else:
+            current_app.logger.info("OPENAI_HOST is azure, setting up Azure OpenAI client")
             if not AZURE_OPENAI_SERVICE:
                 raise ValueError("AZURE_OPENAI_SERVICE must be set when OPENAI_HOST is azure")
             endpoint = f"https://{AZURE_OPENAI_SERVICE}.openai.azure.com"
         if api_key := os.getenv("AZURE_OPENAI_API_KEY"):
+            current_app.logger.info("AZURE_OPENAI_API_KEY found, using as value for api_key for Azure OpenAI client")
             openai_client = AsyncAzureOpenAI(api_version=api_version, azure_endpoint=endpoint, api_key=api_key)
         else:
+            current_app.logger.info("Using Azure credential (passwordless authentication) for Azure OpenAI client")
             token_provider = get_bearer_token_provider(azure_credential, "https://cognitiveservices.azure.com/.default")
             openai_client = AsyncAzureOpenAI(
                 api_version=api_version,
                 azure_endpoint=endpoint,
                 azure_ad_token_provider=token_provider,
             )
     elif OPENAI_HOST == "local":
+        current_app.logger.info("OPENAI_HOST is local, setting up local OpenAI client for OPENAI_BASE_URL with no key")
         openai_client = AsyncOpenAI(
             base_url=os.environ["OPENAI_BASE_URL"],
             api_key="no-key-required",
         )
     else:
+        current_app.logger.info(
+            "OPENAI_HOST is not azure, setting up OpenAI client using OPENAI_API_KEY and OPENAI_ORGANIZATION environment variables"
+        )
         openai_client = AsyncOpenAI(
             api_key=OPENAI_API_KEY,
             organization=OPENAI_ORGANIZATION,
@@ -660,6 +670,7 @@ def create_app():
     app.register_blueprint(bp)
 
     if os.getenv("APPLICATIONINSIGHTS_CONNECTION_STRING"):
+        app.logger.info("APPLICATIONINSIGHTS_CONNECTION_STRING is set, enabling Azure Monitor")
         configure_azure_monitor()
         # This tracks HTTP requests made by aiohttp:
         AioHttpClientInstrumentor().instrument()
@@ -670,13 +681,14 @@ def create_app():
         # This middleware tracks app route requests:
         app.asgi_app = OpenTelemetryMiddleware(app.asgi_app)  # type: ignore[assignment]
 
-    # Level should be one of https://docs.python.org/3/library/logging.html#logging-levels
-    default_level = "INFO"  # In development, log more verbosely
-    if os.getenv("WEBSITE_HOSTNAME"):  # In production, don't log as heavily
-        default_level = "WARNING"
-    logging.basicConfig(level=os.getenv("APP_LOG_LEVEL", default_level))
+    # Log levels should be one of https://docs.python.org/3/library/logging.html#logging-levels
+    # Set root level to WARNING to avoid seeing overly verbose logs from SDKS
+    logging.basicConfig(level=logging.WARNING)
+    # Set the app logger level to INFO by default
+    default_level = "INFO"
+    app.logger.setLevel(os.getenv("APP_LOG_LEVEL", default_level))
 
     if allowed_origin := os.getenv("ALLOWED_ORIGIN"):
-        app.logger.info("CORS enabled for %s", allowed_origin)
+        app.logger.info("ALLOWED_ORIGIN is set, enabling CORS for %s", allowed_origin)
         cors(app, allow_origin=allowed_origin, allow_methods=["GET", "POST"])
     return app

app/backend/custom_uvicorn_worker.py

@@ -0,0 +1,47 @@
+from uvicorn.workers import UvicornWorker
+
+logconfig_dict = {
+    "version": 1,
+    "disable_existing_loggers": False,
+    "formatters": {
+        "default": {
+            "()": "uvicorn.logging.DefaultFormatter",
+            "format": "%(asctime)s - %(levelname)s - %(message)s",
+        },
+        "access": {
+            "()": "uvicorn.logging.AccessFormatter",
+            "format": "%(asctime)s - %(message)s",
+        },
+    },
+    "handlers": {
+        "default": {
+            "formatter": "default",
+            "class": "logging.StreamHandler",
+            "stream": "ext://sys.stderr",
+        },
+        "access": {
+            "formatter": "access",
+            "class": "logging.StreamHandler",
+            "stream": "ext://sys.stdout",
+        },
+    },
+    "loggers": {
+        "root": {"handlers": ["default"]},
+        "uvicorn.error": {
+            "level": "INFO",
+            "handlers": ["default"],
+            "propagate": False,
+        },
+        "uvicorn.access": {
+            "level": "INFO",
+            "handlers": ["access"],
+            "propagate": False,
+        },
+    },
+}
+
+
+class CustomUvicornWorker(UvicornWorker):
+    CONFIG_KWARGS = {
+        "log_config": logconfig_dict,
+    }

app/backend/gunicorn.conf.py

@@ -15,4 +15,4 @@
     workers = 1
 else:
     workers = (num_cpus * 2) + 1
-worker_class = "uvicorn.workers.UvicornWorker"
+worker_class = "custom_uvicorn_worker.CustomUvicornWorker"