Add Azure Monitor telemetry to backend (#483)

Author: sigurdp

backend/poetry.lock

@@ -25,6 +25,7 @@ psutil = "^5.9.5"
 vtk = "^9.2.6"
 fmu-sumo = "1.0.3"
 sumo-wrapper-python = "1.0.6"
+azure-monitor-opentelemetry = "^1.1.0"
 
 
 [tool.poetry.group.dev.dependencies]

backend/pyproject.toml

@@ -1,12 +1,15 @@
 import datetime
 import logging
+import os
 
 from fastapi import FastAPI
 from fastapi.routing import APIRoute
 from fastapi.responses import ORJSONResponse
 from uvicorn.middleware.proxy_headers import ProxyHeadersMiddleware
 
 from src.backend.utils.add_process_time_to_server_timing_middleware import AddProcessTimeToServerTimingMiddleware
+from src.backend.utils.azure_monitor_setup import setup_azure_monitor_telemetry
+from src.backend.utils.logging_setup import ensure_console_log_handler_is_configured, setup_normal_log_levels
 from src.backend.shared_middleware import add_shared_middlewares
 from src.backend.auth.auth_helper import AuthHelper
 from .routers.explore import router as explore_router
@@ -26,13 +29,14 @@
 from .routers.observations.router import router as observations_router
 from .routers.rft.router import router as rft_router
 
-logging.basicConfig(
-    level=logging.WARNING,
-    format="%(asctime)s %(levelname)-3s [%(name)s]: %(message)s",
-    datefmt="%H:%M:%S",
-)
-logging.getLogger("src.services.sumo_access").setLevel(level=logging.DEBUG)
-logging.getLogger("src.backend.primary.routers.surface").setLevel(level=logging.DEBUG)
+
+ensure_console_log_handler_is_configured()
+setup_normal_log_levels()
+
+# temporarily set some loggers to DEBUG
+logging.getLogger("src.services.sumo_access").setLevel(logging.DEBUG)
+
+LOGGER = logging.getLogger(__name__)
 
 
 def custom_generate_unique_id(route: APIRoute) -> str:
@@ -45,6 +49,13 @@ def custom_generate_unique_id(route: APIRoute) -> str:
     default_response_class=ORJSONResponse,
 )
 
+if os.environ.get("APPLICATIONINSIGHTS_CONNECTION_STRING"):
+    LOGGER.info("Configuring Azure Monitor telemetry for primary backend")
+    setup_azure_monitor_telemetry(app)
+else:
+    LOGGER.warning("Skipping telemetry configuration, APPLICATIONINSIGHTS_CONNECTION_STRING env variable not set.")
+
+
 # The tags we add here will determine the name of the frontend api service for our endpoints as well as
 # providing some grouping when viewing the openapi documentation.
 app.include_router(explore_router, tags=["explore"])

backend/src/backend/primary/main.py

@@ -75,7 +75,7 @@ async def get_realization_surface_data(
     surf_data_response = converters.to_api_surface_data(xtgeo_surf)
     perf_metrics.record_lap("convert")
 
-    LOGGER.debug(f"Loaded realization surface in: {perf_metrics.to_string()}")
+    LOGGER.info(f"Loaded realization surface in: {perf_metrics.to_string()}")
 
     return surf_data_response
 
@@ -113,7 +113,7 @@ async def get_statistical_surface_data(
     surf_data_response: schemas.SurfaceData = converters.to_api_surface_data(xtgeo_surf)
     perf_metrics.record_lap("convert")
 
-    LOGGER.debug(f"Calculated statistical surface in: {perf_metrics.to_string()}")
+    LOGGER.info(f"Calculated statistical surface in: {perf_metrics.to_string()}")
 
     return surf_data_response
 
@@ -158,7 +158,7 @@ async def get_property_surface_resampled_to_static_surface(
     surf_data_response: schemas.SurfaceData = converters.to_api_surface_data(resampled_surface)
     perf_metrics.record_lap("convert")
 
-    LOGGER.debug(f"Loaded property surface in: {perf_metrics.to_string()}")
+    LOGGER.info(f"Loaded property surface in: {perf_metrics.to_string()}")
 
     return surf_data_response
 
@@ -200,6 +200,6 @@ async def get_property_surface_resampled_to_statistical_static_surface(
 
     surf_data_response = converters.to_api_surface_data(resampled_surface)
 
-    LOGGER.debug(f"Loaded property surface and created image, total time: {timer.elapsed_ms()}ms")
+    LOGGER.info(f"Loaded property surface and created image, total time: {timer.elapsed_ms()}ms")
 
     return surf_data_response

backend/src/backend/primary/routers/surface/router.py

@@ -1,15 +1,33 @@
+import logging
+import os
+
 from fastapi import FastAPI
 from fastapi.responses import ORJSONResponse
 
+from src.backend.utils.azure_monitor_setup import setup_azure_monitor_telemetry
+from src.backend.utils.logging_setup import ensure_console_log_handler_is_configured, setup_normal_log_levels
 from src.backend.shared_middleware import add_shared_middlewares
 from .inactivity_shutdown import InactivityShutdown
 from .routers.general import router as general_router
 
 # mypy: disable-error-code="attr-defined"
 from .routers.grid.router import router as grid_router
 
+
+ensure_console_log_handler_is_configured()
+setup_normal_log_levels()
+
+LOGGER = logging.getLogger(__name__)
+
+
 app = FastAPI(default_response_class=ORJSONResponse)
 
+if os.environ.get("APPLICATIONINSIGHTS_CONNECTION_STRING"):
+    LOGGER.info("Configuring Azure Monitor telemetry for user session server")
+    setup_azure_monitor_telemetry(app)
+else:
+    LOGGER.warning("Skipping telemetry configuration, APPLICATIONINSIGHTS_CONNECTION_STRING env variable not set.")
+
 app.include_router(general_router)
 app.include_router(grid_router, prefix="/grid")
 add_shared_middlewares(app)
@@ -18,4 +36,4 @@
 # minutes without receiving any new requests:
 InactivityShutdown(app, inactivity_limit_minutes=30)
 
-print("Succesfully completed user session server initialization.")
+LOGGER.info("Successfully completed user session server initialization.")

backend/src/backend/user_session/main.py

@@ -0,0 +1,62 @@
+import logging
+from azure.monitor.opentelemetry import configure_azure_monitor
+from fastapi import FastAPI
+from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
+from opentelemetry.sdk._logs import LoggingHandler
+
+
+# This is a custom logging handler that does formatting of log messages before passing them on to open telemetry.
+# Note that the class we're inheriting from here *is* an OpenTelemetry derived Python logger.
+class LoggingHandlerWithFormatting(LoggingHandler):
+    def emit(self, record: logging.LogRecord) -> None:
+        # Do a bit of a hack here to format the message before passing it onwards.
+        # At the same time make sure we restore record.msg in case there are other handlers in the chain.
+        original_msg = record.msg
+        original_args = record.args
+
+        formatted_msg = self.format(record)
+        record.msg = formatted_msg
+        record.args = None
+
+        # Note that the logger that we're calling emit on here is an Open Telemetry Logger, not a Python logger.
+        self._logger.emit(self._translate(record))
+
+        # For inspecting and debugging the actual telemetry payload, uncomment the following lines.
+        # log_record_as_json = self._translate(record).to_json()
+        # print(f"---- start payload ----\n{log_record_as_json}\n---- end payload -----", flush=True)
+
+        record.msg = original_msg
+        record.args = original_args
+
+
+# A lot of the configuration will be read from environment variables during the execution of this function.
+# Notable environment variables that are consumed are:
+# - APPLICATIONINSIGHTS_CONNECTION_STRING
+# - OTEL_SERVICE_NAME
+# - OTEL_RESOURCE_ATTRIBUTES
+def setup_azure_monitor_telemetry(fastapi_app: FastAPI) -> None:
+    # Under ideal circumstances, the below call to configure_azure_monitor() should be the only call needed
+    # to configure the entire telemetry stack. However, it seems that there are multiple glitches.
+    # - Supposedly, FastAPI instrumentation should be added automatically, but this only seems to work
+    #   if the call to configure_azure_monitor() happens very early in the module loading process, and
+    #   specifically it seems that it has to happen before any import of FastAPIP
+    # - The default log handler that is added does not obey the specified log message format string,
+    #   even if it is set using OTEL_PYTHON_LOG_FORMAT. It justs logs the raw message string.
+    #
+    # Note that this call will throw an exception if the APPLICATIONINSIGHTS_CONNECTION_STRING
+    # environment variable is not set or if it is invalid
+    configure_azure_monitor()
+
+    # The log handler that is added by configure_azure_monitor() does not obey the specified log message
+    # format string. We therefore replace it with a custom handler that does formatting and set a format string that ensures
+    # that the logger name is included in the log message.
+    handler_with_formatting = LoggingHandlerWithFormatting()
+    handler_with_formatting.setFormatter(logging.Formatter("[%(name)s] %(message)s"))
+
+    root_logger = logging.getLogger()
+
+    handler_installed_by_config = root_logger.handlers[-1]
+    root_logger.removeHandler(handler_installed_by_config)
+    root_logger.addHandler(handler_with_formatting)
+
+    FastAPIInstrumentor.instrument_app(fastapi_app)

backend/src/backend/utils/azure_monitor_setup.py

@@ -0,0 +1,30 @@
+import logging
+
+
+def ensure_console_log_handler_is_configured() -> None:
+    root_logger = logging.getLogger()
+
+    # Look for the default console handler that is added by the Python logging module
+    console_handler: logging.StreamHandler | None = None
+    for handler in root_logger.handlers:
+        if isinstance(handler, logging.StreamHandler):
+            console_handler = handler
+            break
+
+    if not console_handler:
+        console_handler = logging.StreamHandler()
+        root_logger.addHandler(console_handler)
+
+    # Set our default format string
+    formatter = logging.Formatter("%(asctime)s %(levelname)-3s [%(name)s]: %(message)s", datefmt="%H:%M:%S")
+    console_handler.setFormatter(formatter)
+
+
+def setup_normal_log_levels() -> None:
+    # Set baseline logging level to INFO
+    logging.getLogger().setLevel(logging.INFO)
+
+    # Make sure some of the more noisy loggers are limited to WARNING
+    logging.getLogger("xtgeo").setLevel(logging.WARNING)
+    logging.getLogger("httpx").setLevel(logging.WARNING)
+    logging.getLogger("azure").setLevel(logging.WARNING)

backend/src/backend/utils/logging_setup.py

@@ -32,6 +32,9 @@ services:
       - WEBVIZ_SMDA_RESOURCE_SCOPE
       - WEBVIZ_SMDA_SUBSCRIPTION_KEY
       - WEBVIZ_SUMO_ENV
+      - APPLICATIONINSIGHTS_CONNECTION_STRING
+      - OTEL_SERVICE_NAME=primary-backend
+      - OTEL_RESOURCE_ATTRIBUTES=service.namespace=local, service.version=dummy0.1.2
       - CODESPACE_NAME  # Automatically set env. variable by GitHub codespace
     volumes:
       - ./backend/src:/home/appuser/backend/src
@@ -56,6 +59,9 @@ services:
       - WEBVIZ_SMDA_RESOURCE_SCOPE
       - WEBVIZ_SMDA_SUBSCRIPTION_KEY
       - WEBVIZ_SUMO_ENV
+      - APPLICATIONINSIGHTS_CONNECTION_STRING
+      - OTEL_SERVICE_NAME=user-session
+      - OTEL_RESOURCE_ATTRIBUTES=service.namespace=local, service.version=dummy0.1.2
     volumes:
       - ./backend/src:/home/appuser/backend/src
 

docker-compose.yml

@@ -39,6 +39,14 @@ spec:
         UVICORN_ENTRYPOINT: src.backend.primary.main:app
       environmentConfig:
         - environment: prod
+          secretRefs:
+            azureKeyVaults:
+              - name: webviz
+                items:
+                  - name: WEBVIZ-INSIGHTS-CONNECTIONSTRING-PROD
+                    envVar: APPLICATIONINSIGHTS_CONNECTION_STRING
+          variables:
+            OTEL_RESOURCE_ATTRIBUTES: service.name=primary-backend, service.namespace=prod, service.version=tbd0.1.2
           resources:
             requests:
               memory: 8Gi
@@ -55,6 +63,14 @@ spec:
               cpu:
                 averageUtilization: 80
         - environment: review
+          secretRefs:
+            azureKeyVaults:
+              - name: webviz
+                items:
+                  - name: WEBVIZ-INSIGHTS-CONNECTIONSTRING-REVIEW
+                    envVar: APPLICATIONINSIGHTS_CONNECTION_STRING
+          variables:
+            OTEL_RESOURCE_ATTRIBUTES: service.name=primary-backend, service.namespace=review, service.version=tbd0.1.2
           resources:
             requests:
               memory: 4Gi
@@ -118,13 +134,29 @@ spec:
       environmentConfig:
         # As of October 2023 in radix, these settings need to be duplicated for both environments.
         - environment: prod
+          secretRefs:
+            azureKeyVaults:
+              - name: webviz
+                items:
+                  - name: WEBVIZ-INSIGHTS-CONNECTIONSTRING-PROD
+                    envVar: APPLICATIONINSIGHTS_CONNECTION_STRING
+          variables:
+            OTEL_RESOURCE_ATTRIBUTES: service.name=user-session, service.namespace=prod, service.version=tbd0.1.2
           volumeMounts:
             - name: webvizcache
               path: /tmp/webvizcache/
               blobfuse2:
                 container: cache
                 uid: 1234
         - environment: review
+          secretRefs:
+            azureKeyVaults:
+              - name: webviz
+                items:
+                  - name: WEBVIZ-INSIGHTS-CONNECTIONSTRING-REVIEW
+                    envVar: APPLICATIONINSIGHTS_CONNECTION_STRING
+          variables:
+            OTEL_RESOURCE_ATTRIBUTES: service.name=user-session, service.namespace=review, service.version=tbd0.1.2
           volumeMounts:
             - name: webvizcache
               path: /tmp/webvizcache/