diff --git a/controller_function/controller/__init__.py b/controller_function/controller/__init__.py index ab0619e..9da0f1c 100644 --- a/controller_function/controller/__init__.py +++ b/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.") diff --git a/controller_function/controller/logutils.py b/controller_function/controller/logutils.py index 3c78b1c..579480b 100644 --- a/controller_function/controller/logutils.py +++ b/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 diff --git a/controller_function/run_tests.sh b/controller_function/run_tests.sh index 37260b2..219adc1 100755 --- a/controller_function/run_tests.sh +++ b/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 diff --git a/controller_function/tests/test_function_app.py b/controller_function/tests/test_function_app.py index 38b9b4c..95deea6 100644 --- a/controller_function/tests/test_function_app.py +++ b/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() diff --git a/status_function/run_tests.sh b/status_function/run_tests.sh index 577136f..2347ca2 100755 --- a/status_function/run_tests.sh +++ b/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 diff --git a/status_function/status/__init__.py b/status_function/status/__init__.py index 65425f1..987b586 100644 --- a/status_function/status/__init__.py +++ b/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: diff --git a/status_function/status/logutils.py b/status_function/status/logutils.py index 47a0608..0600b24 100644 --- a/status_function/status/logutils.py +++ b/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 diff --git a/status_function/tests/test_function_app.py b/status_function/tests/test_function_app.py index d406d45..6a891d7 100644 --- a/status_function/tests/test_function_app.py +++ b/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() diff --git a/usage_function/costmanagement/__init__.py b/usage_function/costmanagement/__init__.py index 7e7a757..630f5bf 100644 --- a/usage_function/costmanagement/__init__.py +++ b/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( diff --git a/usage_function/monthly_usage/__init__.py b/usage_function/monthly_usage/__init__.py index b26e658..e63a767 100644 --- a/usage_function/monthly_usage/__init__.py +++ b/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.") diff --git a/usage_function/run_tests.sh b/usage_function/run_tests.sh index d43fba5..f1e2d1e 100755 --- a/usage_function/run_tests.sh +++ b/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 diff --git a/usage_function/tests/test_utils.py b/usage_function/tests/test_utils.py index 844ecb5..7c7f6b3 100644 --- a/usage_function/tests/test_utils.py +++ b/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() diff --git a/usage_function/usage/__init__.py b/usage_function/usage/__init__.py index 958205a..e623fa0 100644 --- a/usage_function/usage/__init__.py +++ b/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.") diff --git a/usage_function/utils/logutils.py b/usage_function/utils/logutils.py index 7e6a3ac..8464108 100644 --- a/usage_function/utils/logutils.py +++ b/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