From 5dd3e8d041ec0d6395c7860906ea4ca37bc38d8e Mon Sep 17 00:00:00 2001 From: Iain-S <25081046+Iain-S@users.noreply.github.com> Date: Mon, 5 Feb 2024 16:28:39 +0000 Subject: [PATCH 1/8] Move log handler call so it is only called once --- .pre-commit-config.yaml | 1 + status_function/run_tests.sh | 8 +++++++- status_function/status/__init__.py | 2 +- 3 files changed, 9 insertions(+), 2 deletions(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index f029b35..5cbd5c9 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -27,6 +27,7 @@ repos: rev: v8.16.1 hooks: - id: gitleaks + args: ["--config", ".gitleaks.toml"] - repo: 'https://github.com/PyCQA/pydocstyle' rev: 6.3.0 hooks: diff --git a/status_function/run_tests.sh b/status_function/run_tests.sh index 577136f..11d3cf7 100755 --- a/status_function/run_tests.sh +++ b/status_function/run_tests.sh @@ -31,7 +31,13 @@ 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/ +API_URL="http://some.api.url" \ +PRIVATE_KEY="-----BEGIN OPENSSH PRIVATE KEY-----mykey1234-----END OPENSSH PRIVATE KEY-----" \ # gitleaks:allow +AZURE_TENANT_ID="00000000-0000-0000-0000-000000000000" \ +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..cb2c0e6 100644 --- a/status_function/status/__init__.py +++ b/status_function/status/__init__.py @@ -34,6 +34,7 @@ datefmt="%d/%m/%Y %I:%M:%S %p", ) logger = logging.getLogger(__name__) +set_log_handler(__name__) # We should only need one set of credentials. CREDENTIALS = DefaultAzureCredential() @@ -331,7 +332,6 @@ def main(mytimer: func.TimerRequest) -> None: format="%(asctime)s %(message)s", datefmt="%d/%m/%Y %I:%M:%S %p", ) - set_log_handler(__name__) logger.warning("Status function starting.") if mytimer.past_due: From 6ca8c8ba7d512ed7b2663e35f2d563f47e5bde74 Mon Sep 17 00:00:00 2001 From: Iain-S <25081046+Iain-S@users.noreply.github.com> Date: Mon, 5 Feb 2024 17:22:26 +0000 Subject: [PATCH 2/8] Only allow AzureLogHandler to be added once to each logger --- .pre-commit-config.yaml | 1 - status_function/run_tests.sh | 1 + status_function/status/logutils.py | 4 ++++ status_function/tests/test_function_app.py | 8 ++++++++ 4 files changed, 13 insertions(+), 1 deletion(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 5cbd5c9..f029b35 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -27,7 +27,6 @@ repos: rev: v8.16.1 hooks: - id: gitleaks - args: ["--config", ".gitleaks.toml"] - repo: 'https://github.com/PyCQA/pydocstyle' rev: 6.3.0 hooks: diff --git a/status_function/run_tests.sh b/status_function/run_tests.sh index 11d3cf7..626033e 100755 --- a/status_function/run_tests.sh +++ b/status_function/run_tests.sh @@ -34,6 +34,7 @@ echo "Running unit tests..." API_URL="http://some.api.url" \ PRIVATE_KEY="-----BEGIN OPENSSH PRIVATE KEY-----mykey1234-----END OPENSSH PRIVATE KEY-----" \ # gitleaks:allow AZURE_TENANT_ID="00000000-0000-0000-0000-000000000000" \ +CENTRAL_LOGGING_CONNECTION_STRING="InstrumentationKey=00000000-0000-0000-0000-000000000000" \ python -m coverage run \ --omit=".venv/*","tests/*" \ -m unittest discover \ diff --git a/status_function/status/logutils.py b/status_function/status/logutils.py index 47a0608..9d18cd5 100644 --- a/status_function/status/logutils.py +++ b/status_function/status/logutils.py @@ -55,6 +55,10 @@ def set_log_handler(name: str = "status") -> None: logger = logging.getLogger(name) log_settings = settings.get_settings() if log_settings.CENTRAL_LOGGING_CONNECTION_STRING: + for handler in logger.handlers: + if isinstance(handler, AzureLogHandler): + raise RuntimeError("AzureLogHandler already added to logger.") + 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..f692f7f 100644 --- a/status_function/tests/test_function_app.py +++ b/status_function/tests/test_function_app.py @@ -611,5 +611,13 @@ def test_bearer_auth(self): self.assertEqual("status-app", username) +class TestLoggingUtils(TestCase): + def test_called_twice(self): + """Adding multiple loggers can cause large storage bills ££££.""" + with self.assertRaises(RuntimeError): + status.logutils.set_log_handler("a") + status.logutils.set_log_handler("a") + + if __name__ == "__main__": main() From 641bdf3b0944dbdd6df9341aed5cf870cb116f70 Mon Sep 17 00:00:00 2001 From: Iain-S <25081046+Iain-S@users.noreply.github.com> Date: Mon, 12 Feb 2024 11:07:25 +0000 Subject: [PATCH 3/8] Fix unit test command --- status_function/run_tests.sh | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/status_function/run_tests.sh b/status_function/run_tests.sh index 626033e..d038da1 100755 --- a/status_function/run_tests.sh +++ b/status_function/run_tests.sh @@ -30,13 +30,12 @@ status=$((status+$?)) # Run our unit tests with code coverage echo "Running unit tests..." -# shellcheck disable=SC2140 -API_URL="http://some.api.url" \ -PRIVATE_KEY="-----BEGIN OPENSSH PRIVATE KEY-----mykey1234-----END OPENSSH PRIVATE KEY-----" \ # gitleaks:allow -AZURE_TENANT_ID="00000000-0000-0000-0000-000000000000" \ -CENTRAL_LOGGING_CONNECTION_STRING="InstrumentationKey=00000000-0000-0000-0000-000000000000" \ +export API_URL="http://some.api.url" +export PRIVATE_KEY="-----BEGIN OPENSSH PRIVATE KEY-----mykey1234-----END OPENSSH PRIVATE KEY-----" # gitleaks:allow +export AZURE_TENANT_ID="00000000-0000-0000-0000-000000000000" +export CENTRAL_LOGGING_CONNECTION_STRING="InstrumentationKey=00000000-0000-0000-0000-000000000000" python -m coverage run \ - --omit=".venv/*","tests/*" \ + --omit=".venv/*,tests/*" \ -m unittest discover \ --start-directory=tests/ status=$((status+$?)) From 2df77e337d207bf140318b12723265e0a70623dc Mon Sep 17 00:00:00 2001 From: Iain-S <25081046+Iain-S@users.noreply.github.com> Date: Mon, 12 Feb 2024 12:29:56 +0000 Subject: [PATCH 4/8] Move log handler call back into main --- status_function/run_tests.sh | 4 ---- status_function/status/__init__.py | 4 ++-- status_function/status/logutils.py | 8 +++----- status_function/tests/test_function_app.py | 14 ++++++++++---- 4 files changed, 15 insertions(+), 15 deletions(-) diff --git a/status_function/run_tests.sh b/status_function/run_tests.sh index d038da1..2347ca2 100755 --- a/status_function/run_tests.sh +++ b/status_function/run_tests.sh @@ -30,10 +30,6 @@ status=$((status+$?)) # Run our unit tests with code coverage echo "Running unit tests..." -export API_URL="http://some.api.url" -export PRIVATE_KEY="-----BEGIN OPENSSH PRIVATE KEY-----mykey1234-----END OPENSSH PRIVATE KEY-----" # gitleaks:allow -export AZURE_TENANT_ID="00000000-0000-0000-0000-000000000000" -export CENTRAL_LOGGING_CONNECTION_STRING="InstrumentationKey=00000000-0000-0000-0000-000000000000" python -m coverage run \ --omit=".venv/*,tests/*" \ -m unittest discover \ diff --git a/status_function/status/__init__.py b/status_function/status/__init__.py index cb2c0e6..4bb2905 100644 --- a/status_function/status/__init__.py +++ b/status_function/status/__init__.py @@ -24,8 +24,8 @@ from status import models, settings from status.auth import BearerAuth -from status.logutils import set_log_handler from status.models import RoleAssignment +from status.logutils import add_log_handler_once from status.wrapper import CredentialWrapper logging.basicConfig( @@ -34,7 +34,6 @@ datefmt="%d/%m/%Y %I:%M:%S %p", ) logger = logging.getLogger(__name__) -set_log_handler(__name__) # We should only need one set of credentials. CREDENTIALS = DefaultAzureCredential() @@ -332,6 +331,7 @@ def main(mytimer: func.TimerRequest) -> None: format="%(asctime)s %(message)s", datefmt="%d/%m/%Y %I:%M:%S %p", ) + 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 9d18cd5..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,16 +48,14 @@ 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): - raise RuntimeError("AzureLogHandler already added to logger.") + return custom_dimensions = {"logger_name": f"logger_{name}"} handler = AzureLogHandler( diff --git a/status_function/tests/test_function_app.py b/status_function/tests/test_function_app.py index f692f7f..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 @@ -613,10 +614,15 @@ def test_bearer_auth(self): class TestLoggingUtils(TestCase): def test_called_twice(self): - """Adding multiple loggers can cause large storage bills ££££.""" - with self.assertRaises(RuntimeError): - status.logutils.set_log_handler("a") - status.logutils.set_log_handler("a") + """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__": From 8555a8d315cc3512a7bcadba542fab36b89ac2d7 Mon Sep 17 00:00:00 2001 From: Ese <17943860+dlpbc@users.noreply.github.com> Date: Wed, 14 Feb 2024 01:21:20 +0000 Subject: [PATCH 5/8] isort status/__init__.py --- status_function/status/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/status_function/status/__init__.py b/status_function/status/__init__.py index 4bb2905..987b586 100644 --- a/status_function/status/__init__.py +++ b/status_function/status/__init__.py @@ -24,8 +24,8 @@ from status import models, settings from status.auth import BearerAuth -from status.models import RoleAssignment from status.logutils import add_log_handler_once +from status.models import RoleAssignment from status.wrapper import CredentialWrapper logging.basicConfig( From 48c84e959629f424130c5166e4d7e7e264ec7267 Mon Sep 17 00:00:00 2001 From: Ese <17943860+dlpbc@users.noreply.github.com> Date: Wed, 14 Feb 2024 02:08:45 +0000 Subject: [PATCH 6/8] add logging handler once for status function app --- usage_function/costmanagement/__init__.py | 4 ++-- usage_function/monthly_usage/__init__.py | 4 ++-- usage_function/run_tests.sh | 5 ++++- usage_function/tests/test_utils.py | 14 ++++++++++++++ usage_function/usage/__init__.py | 4 ++-- usage_function/utils/logutils.py | 7 ++++++- 6 files changed, 30 insertions(+), 8 deletions(-) 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..a1c1880 100755 --- a/usage_function/run_tests.sh +++ b/usage_function/run_tests.sh @@ -33,7 +33,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 From f7cf26c9db5cf1ed6ece3421a09f620950c74796 Mon Sep 17 00:00:00 2001 From: Ese <17943860+dlpbc@users.noreply.github.com> Date: Wed, 14 Feb 2024 02:36:14 +0000 Subject: [PATCH 7/8] add logging handler once for controller app --- controller_function/controller/__init__.py | 4 ++-- controller_function/controller/logutils.py | 7 ++++++- controller_function/run_tests.sh | 8 ++++---- controller_function/tests/test_function_app.py | 14 ++++++++++++++ 4 files changed, 26 insertions(+), 7 deletions(-) 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() From 70da18dfe318ba1cff77ae40d86bbe94674a1551 Mon Sep 17 00:00:00 2001 From: Ese <17943860+dlpbc@users.noreply.github.com> Date: Wed, 14 Feb 2024 02:43:17 +0000 Subject: [PATCH 8/8] enable shellcheck: unit test in status/run_test.sh --- usage_function/run_tests.sh | 1 - 1 file changed, 1 deletion(-) diff --git a/usage_function/run_tests.sh b/usage_function/run_tests.sh index a1c1880..f1e2d1e 100755 --- a/usage_function/run_tests.sh +++ b/usage_function/run_tests.sh @@ -32,7 +32,6 @@ 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 \