Move log handlers call so it is only called once per function app

controller_function/controller/__init__.py

@@ -8,7 +8,7 @@
 
 from controller import models, settings
 from controller.auth import BearerAuth
-from controller.logutils import set_log_handler
+from controller.logutils import add_log_handler_once
 from controller.subscription import disable_subscription, enable_subscription
 
 logger = logging.getLogger(__name__)
@@ -86,7 +86,7 @@ def main(mytimer: func.TimerRequest) -> None:
         format="%(asctime)s %(message)s",
         datefmt="%d/%m/%Y %I:%M:%S %p",
     )
-    set_log_handler(__name__)
+    add_log_handler_once(__name__)
 
     logger.warning("Controller function starting.")
 

controller_function/controller/logutils.py

@@ -24,7 +24,7 @@ def filter(self, record: logging.LogRecord) -> bool:
         return True
 
 
-def set_log_handler(name: str = "controller") -> None:
+def add_log_handler_once(name: str = "controller") -> None:
     """Add an Azure log handler to the logger with provided name.
 
     The log data is sent to the Azure Application Insights instance associated
@@ -38,6 +38,11 @@ def set_log_handler(name: str = "controller") -> None:
     logger = logging.getLogger(name)
     log_settings = settings.get_settings()
     if log_settings.CENTRAL_LOGGING_CONNECTION_STRING:
+        for handler in logger.handlers:
+            # Only allow one AzureLogHandler per logger
+            if isinstance(handler, AzureLogHandler):
+                return
+
         custom_dimensions = {"logger_name": f"logger_{name}"}
         handler = AzureLogHandler(
             connection_string=log_settings.CENTRAL_LOGGING_CONNECTION_STRING

controller_function/run_tests.sh

@@ -30,10 +30,10 @@ status=$((status+$?))
 
 # Run our unit tests with code coverage
 echo "Running unit tests..."
-# shellcheck disable=SC2140
-python -m \
-  coverage run --omit=".venv/*","tests/*" -m \
-  unittest discover --start-directory=tests/
+python -m coverage run \
+  --omit=".venv/*,tests/*" \
+  -m unittest discover \
+  --start-directory=tests/
 status=$((status+$?))
 
 # Show the lines our tests miss

controller_function/tests/test_function_app.py

@@ -1,5 +1,6 @@
 """Tests for controller package."""
 import json
+import logging
 from unittest import TestCase, main
 from unittest.mock import MagicMock, call, patch
 from uuid import UUID
@@ -185,5 +186,18 @@ def test_bearer_auth(self):
             self.assertEqual("controller-app", username)
 
 
+class TestLoggingUtils(TestCase):
+    def test_called_twice(self):
+        """Adding multiple loggers could cause large storage bills."""
+        with patch("controller.settings.get_settings") as mock_get_settings:
+            mock_get_settings.return_value.CENTRAL_LOGGING_CONNECTION_STRING = "my-str"
+
+            with patch("controller.logutils.AzureLogHandler", new=MagicMock):
+                controller.logutils.add_log_handler_once("a")
+                controller.logutils.add_log_handler_once("a")
+        handlers = logging.getLogger("a").handlers
+        self.assertEqual(1, len(handlers))
+
+
 if __name__ == "__main__":
     main()

status_function/run_tests.sh

@@ -30,8 +30,10 @@ status=$((status+$?))
 
 # Run our unit tests with code coverage
 echo "Running unit tests..."
-# shellcheck disable=SC2140
-python -m coverage run --omit=".venv/*","tests/*" -m unittest discover --start-directory=tests/
+python -m coverage run \
+  --omit=".venv/*,tests/*" \
+  -m unittest discover \
+  --start-directory=tests/
 status=$((status+$?))
 
 # Show the lines our tests miss

status_function/status/__init__.py

@@ -24,7 +24,7 @@
 
 from status import models, settings
 from status.auth import BearerAuth
-from status.logutils import set_log_handler
+from status.logutils import add_log_handler_once
 from status.models import RoleAssignment
 from status.wrapper import CredentialWrapper
 
@@ -331,7 +331,7 @@ def main(mytimer: func.TimerRequest) -> None:
         format="%(asctime)s %(message)s",
         datefmt="%d/%m/%Y %I:%M:%S %p",
     )
-    set_log_handler(__name__)
+    add_log_handler_once(__name__)
     logger.warning("Status function starting.")
 
     if mytimer.past_due:

status_function/status/logutils.py

@@ -38,7 +38,7 @@ def filter(self, record: logging.LogRecord) -> bool:
         return True
 
 
-def set_log_handler(name: str = "status") -> None:
+def add_log_handler_once(name: str = "status") -> None:
     """Add an Azure log handler to the logger with provided name.
 
     The log data is sent to the Azure Application Insights instance associated
@@ -48,13 +48,15 @@ def set_log_handler(name: str = "status") -> None:
 
     Args:
         name: The name of the logger instance to which we add the log handler.
-
-    Returns:
-        None
     """
     logger = logging.getLogger(name)
     log_settings = settings.get_settings()
     if log_settings.CENTRAL_LOGGING_CONNECTION_STRING:
+        for handler in logger.handlers:
+            # Only allow one AzureLogHandler per logger
+            if isinstance(handler, AzureLogHandler):
+                return
+
         custom_dimensions = {"logger_name": f"logger_{name}"}
         handler = AzureLogHandler(
             connection_string=log_settings.CENTRAL_LOGGING_CONNECTION_STRING

status_function/tests/test_function_app.py

@@ -1,4 +1,5 @@
 """Tests for status package."""
+import logging
 from datetime import datetime
 from types import SimpleNamespace
 from unittest import TestCase, main
@@ -611,5 +612,18 @@ def test_bearer_auth(self):
             self.assertEqual("status-app", username)
 
 
+class TestLoggingUtils(TestCase):
+    def test_called_twice(self):
+        """Adding multiple loggers could cause large storage bills."""
+        with patch("status.settings.get_settings") as mock_get_settings:
+            mock_get_settings.return_value.CENTRAL_LOGGING_CONNECTION_STRING = "my-str"
+
+            with patch("status.logutils.AzureLogHandler", new=MagicMock):
+                status.logutils.add_log_handler_once("a")
+                status.logutils.add_log_handler_once("a")
+        handlers = logging.getLogger("a").handlers
+        self.assertEqual(1, len(handlers))
+
+
 if __name__ == "__main__":
     main()

usage_function/costmanagement/__init__.py

@@ -11,7 +11,7 @@
 import utils.settings
 from utils import models
 from utils.auth import BearerAuth
-from utils.logutils import set_log_handler
+from utils.logutils import add_log_handler_once
 
 logging.basicConfig(
     level=logging.WARNING,
@@ -173,7 +173,7 @@ def main(mytimer: func.TimerRequest) -> None:
     and POST it the RCTab server.
     """
     # todo remove reference to EA group
-    set_log_handler(__name__)
+    add_log_handler_once(__name__)
 
     if mytimer.past_due:
         logger.warning(

usage_function/monthly_usage/__init__.py

@@ -7,7 +7,7 @@
 from azure.core.exceptions import HttpResponseError
 
 import utils.settings
-from utils.logutils import set_log_handler
+from utils.logutils import add_log_handler_once
 from utils.usage import date_range, get_all_usage, retrieve_usage, send_usage
 
 MAX_ATTEMPTS = 5
@@ -24,7 +24,7 @@ def main(mytimer: func.TimerRequest) -> None:
         format="%(asctime)s %(message)s",
         datefmt="%d/%m/%Y %I:%M:%S %p",
     )
-    set_log_handler(__name__)
+    add_log_handler_once(__name__)
     logger = logging.getLogger(__name__)
     logger.warning("Monthly usage function starting.")
 

usage_function/run_tests.sh

@@ -32,8 +32,10 @@ status=$((status+$?))
 
 # Run our unit tests with code coverage
 echo "Running unit tests..."
-# shellcheck disable=SC2140
-python -m coverage run --omit=".venv/*","tests/*","venv/*" -m unittest discover --start-directory=tests/
+python -m coverage run \
+  --omit=".venv/*,tests/*,venv/*" \
+  -m unittest discover \
+  --start-directory=tests/
 status=$((status+$?))
 
 # Show the lines our tests miss

usage_function/tests/test_utils.py

@@ -1,4 +1,5 @@
 """Tests for function app utils."""
+import logging
 from datetime import datetime, timedelta
 from unittest import TestCase, main
 from unittest.mock import MagicMock, call, patch
@@ -242,5 +243,18 @@ def test_key_validation(self):
         )
 
 
+class TestLoggingUtils(TestCase):
+    def test_called_twice(self):
+        """Adding multiple loggers could cause large storage bills."""
+        with patch("utils.settings.get_settings") as mock_get_settings:
+            mock_get_settings.return_value.CENTRAL_LOGGING_CONNECTION_STRING = "my-str"
+
+            with patch("utils.logutils.AzureLogHandler", new=MagicMock):
+                utils.logutils.add_log_handler_once("a")
+                utils.logutils.add_log_handler_once("a")
+        handlers = logging.getLogger("a").handlers
+        self.assertEqual(1, len(handlers))
+
+
 if __name__ == "__main__":
     main()

usage_function/usage/__init__.py

@@ -7,7 +7,7 @@
 from azure.core.exceptions import HttpResponseError
 
 import utils.settings
-from utils.logutils import set_log_handler
+from utils.logutils import add_log_handler_once
 from utils.usage import date_range, get_all_usage, retrieve_and_send_usage
 
 
@@ -23,7 +23,7 @@ def main(mytimer: func.TimerRequest) -> None:
         datefmt="%d/%m/%Y %I:%M:%S %p",
     )
 
-    set_log_handler(__name__)
+    add_log_handler_once(__name__)
     logger = logging.getLogger(__name__)
 
     logger.warning("Usage function starting.")

usage_function/utils/logutils.py

@@ -24,7 +24,7 @@ def filter(self, record: logging.LogRecord) -> bool:
         return True
 
 
-def set_log_handler(name: str = "usage_function") -> None:
+def add_log_handler_once(name: str = "usage_function") -> None:
     """Add an Azure log handler to the logger with provided name.
 
     The log data is sent to the Azure Application Insights instance associated
@@ -38,6 +38,11 @@ def set_log_handler(name: str = "usage_function") -> None:
     logger = logging.getLogger(name)
     settings = utils.settings.get_settings()
     if settings.CENTRAL_LOGGING_CONNECTION_STRING:
+        for handler in logger.handlers:
+            # Only allow one AzureLogHandler per logger
+            if isinstance(handler, AzureLogHandler):
+                return
+
         custom_dimensions = {"logger_name": f"logger_{name}"}
         handler = AzureLogHandler(
             connection_string=settings.CENTRAL_LOGGING_CONNECTION_STRING