From 9dfa039a194ea0fb1fdb17aca30d0d2542ccc3e7 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Wed, 9 Oct 2024 16:57:29 -0400 Subject: [PATCH 01/17] Add elasticsearch requirement --- pyproject.toml | 3 ++- requirements/base/base.txt | 14 ++++++++++++-- requirements/dev/dev.txt | 14 ++++++++++++-- 3 files changed, 26 insertions(+), 5 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 279c1d4..63ecf3b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -23,7 +23,8 @@ dependencies = [ "pyodbc==5.1.0", "requests_oauthlib==1.3.1", "pydantic==2.6.4", - "pydantic[email]==2.6.4" + "pydantic[email]==2.6.4", + "elasticsearch==8.15.1" ] [project.optional-dependencies] diff --git a/requirements/base/base.txt b/requirements/base/base.txt index 3ea932e..1d50e11 100644 --- a/requirements/base/base.txt +++ b/requirements/base/base.txt @@ -4,10 +4,14 @@ # # pip-compile --output-file=requirements/base/base.txt pyproject.toml # +--extra-index-url https://pypi.ehps.ncsu.edu/ + annotated-types==0.6.0 # via pydantic certifi==2024.2.2 - # via requests + # via + # elastic-transport + # requests cffi==1.16.0 # via cryptography charset-normalizer==3.3.2 @@ -18,6 +22,10 @@ cx-oracle==8.3.0 # via sat-utils (pyproject.toml) dnspython==2.6.1 # via email-validator +elastic-transport==8.15.1 + # via elasticsearch +elasticsearch==8.15.1 + # via sat-utils (pyproject.toml) email-validator==2.1.1 # via pydantic idna==3.6 @@ -49,4 +57,6 @@ typing-extensions==4.10.0 # pydantic # pydantic-core urllib3==2.2.1 - # via requests + # via + # elastic-transport + # requests diff --git a/requirements/dev/dev.txt b/requirements/dev/dev.txt index 3849640..8633f5c 100644 --- a/requirements/dev/dev.txt +++ b/requirements/dev/dev.txt @@ -4,6 +4,8 @@ # # pip-compile --extra=dev --output-file=requirements/dev/dev.txt pyproject.toml # +--extra-index-url https://pypi.ehps.ncsu.edu/ + aiofiles==22.1.0 # via ypy-websocket aiosqlite==0.20.0 @@ -41,7 +43,9 @@ black==23.12.1 bleach==6.1.0 # via nbconvert certifi==2024.2.2 - # via requests + # via + # elastic-transport + # requests cffi==1.16.0 # via # argon2-cffi-bindings @@ -78,6 +82,10 @@ dnspython==2.6.1 # via email-validator docutils==0.20.1 # via flit +elastic-transport==8.15.1 + # via elasticsearch +elasticsearch==8.15.1 + # via sat-utils (pyproject.toml) email-validator==2.1.1 # via pydantic entrypoints==0.4 @@ -477,7 +485,9 @@ typing-extensions==4.10.0 uri-template==1.3.0 # via jsonschema urllib3==2.2.1 - # via requests + # via + # elastic-transport + # requests virtualenv==20.25.1 # via pre-commit watchdog==4.0.0 From c8629280d8fc4f934cff4beae7f0d88c97ef297e Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Wed, 9 Oct 2024 16:57:39 -0400 Subject: [PATCH 02/17] Add elastic handler to log utils --- sat/logs.py | 27 +++++++++++++++++++++++++++ tests/test_elastic_search.py | 28 ++++++++++++++++++++++++++++ 2 files changed, 55 insertions(+) create mode 100644 tests/test_elastic_search.py diff --git a/sat/logs.py b/sat/logs.py index 0ca8629..5650edd 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -1,6 +1,9 @@ import logging import os +import requests +from elasticsearch import Elasticsearch + class SATLogger: def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: @@ -42,3 +45,27 @@ def error(self, msg: str) -> None: def critical(self, msg: str) -> None: self.logger.critical(msg) + +def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> Elasticsearch: + return Elasticsearch( + elastic_url, + basic_auth=(username, password) + ) + + +class ElasticClientHandler(logging.Handler): + + def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET): + super().__init__(level) + self.client = client + self.index_name = index_name + self.document_labels = document_labels + + def emit(self, record): + formatted_data = self.format(record) + + document = {"log_message": formatted_data, "cid": record.extra.get('cid')} + if self.document_lables: + document.update(self.document_labels) + + self.client.index(index=self.index_name, document=document) diff --git a/tests/test_elastic_search.py b/tests/test_elastic_search.py new file mode 100644 index 0000000..c856789 --- /dev/null +++ b/tests/test_elastic_search.py @@ -0,0 +1,28 @@ +from unittest.mock import MagicMock + +import pytest + +from sat.logs import ElasticClientHandler, SATLogger + + +@pytest.fixture +def mock_elastic_client(): + mock_client = MagicMock() + return mock_client + +@pytest.fixture +def logger(): + logger = SATLogger(__name__) + return logger + +def test_log_sent(mock_elastic_client, logger): + + elastic_handler = ElasticClientHandler(mock_elastic_client, 'test-index', None) + logger.add_handlers([elastic_handler]) + logger.info('test message') + +def test_extra_handling(mock_elastic_client, logger): + + elastic_handler = ElasticClientHandler(mock_elastic_client, 'test-index', None) + logger.add_handlers([elastic_handler]) + logger.info('test message', extra={'cid': 'test_cid'}) From fed23158a783b09fbc606e8f762ee91273b70200 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Mon, 14 Oct 2024 16:12:35 -0400 Subject: [PATCH 03/17] Add examples of different implementations --- logger_examples/get_logger/README.md | 5 + .../get_logger/helpers/module_2.py | 7 + .../get_logger/helpers/some_module_1.py | 13 ++ logger_examples/get_logger/logging_scratch.py | 23 +++ .../get_logger/logging_scratch_mock.py | 22 +++ logger_examples/sat_logger_setup/README.md | 6 + .../logging_setup_ex_sat_logger.py | 19 +++ logger_examples/sat_logger_setup/module_2.py | 7 + .../sat_logger_setup/some_module_1.py | 13 ++ logger_examples/singleton/README.md | 15 ++ .../singleton/logging_setup_ex_singleton.py | 13 ++ logger_examples/singleton/singleton_module.py | 11 ++ sat/logs.py | 139 ++++++++++++++++-- sat/module_2.py | 7 + sat/some_module_1.py | 13 ++ tests/test_elastic_search.py | 40 ++++- 16 files changed, 335 insertions(+), 18 deletions(-) create mode 100644 logger_examples/get_logger/README.md create mode 100644 logger_examples/get_logger/helpers/module_2.py create mode 100644 logger_examples/get_logger/helpers/some_module_1.py create mode 100644 logger_examples/get_logger/logging_scratch.py create mode 100644 logger_examples/get_logger/logging_scratch_mock.py create mode 100644 logger_examples/sat_logger_setup/README.md create mode 100644 logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py create mode 100644 logger_examples/sat_logger_setup/module_2.py create mode 100644 logger_examples/sat_logger_setup/some_module_1.py create mode 100644 logger_examples/singleton/README.md create mode 100644 logger_examples/singleton/logging_setup_ex_singleton.py create mode 100644 logger_examples/singleton/singleton_module.py create mode 100644 sat/module_2.py create mode 100644 sat/some_module_1.py diff --git a/logger_examples/get_logger/README.md b/logger_examples/get_logger/README.md new file mode 100644 index 0000000..2dc0d0d --- /dev/null +++ b/logger_examples/get_logger/README.md @@ -0,0 +1,5 @@ +This is an example logging implementation using a setup function and the default `logging.getLogger` function. + +Requires the application to independently call the logger setup function once in the application entrypoint, +and then any method can be used in the individual modules to get their appropriate logger, +as these will inhereit the logging basicConfig. \ No newline at end of file diff --git a/logger_examples/get_logger/helpers/module_2.py b/logger_examples/get_logger/helpers/module_2.py new file mode 100644 index 0000000..adf1dfa --- /dev/null +++ b/logger_examples/get_logger/helpers/module_2.py @@ -0,0 +1,7 @@ +from logging import getLogger + +LOGGER = getLogger(__name__) + +def some_other_function(): + LOGGER.info('Did some stuff over here') + return None \ No newline at end of file diff --git a/logger_examples/get_logger/helpers/some_module_1.py b/logger_examples/get_logger/helpers/some_module_1.py new file mode 100644 index 0000000..2001af8 --- /dev/null +++ b/logger_examples/get_logger/helpers/some_module_1.py @@ -0,0 +1,13 @@ +from logging import getLogger + + +from logger_examples.get_logger.helpers.module_2 import some_other_function + + +logger = getLogger(__name__) + +def some_function(): + logger.info('Going to do some stuff') + some_other_function() + logger.info('Done with the stuff', extra={'cid': '00102301'}) + return None diff --git a/logger_examples/get_logger/logging_scratch.py b/logger_examples/get_logger/logging_scratch.py new file mode 100644 index 0000000..3691d08 --- /dev/null +++ b/logger_examples/get_logger/logging_scratch.py @@ -0,0 +1,23 @@ +import logging +import os + +from sat.logs import setup_sat_logging, get_elasticsearch_client +from logger_examples.get_logger.helpers.some_module_1 import some_function + + + +# This example uses a function that takes the elastic client and parameters as arguments +# We could also ues a `setup_sat_logging` function that defaults to pulling from specific +# env variables automatically so that the application entrypoints aren't as complex +# The benefit to this is that testing is much easier, since `setup_sat_logging` can be called with a mock client +elastic_client = get_elasticsearch_client(os.getenv('ELASTIC_URL'), username=os.getenv('ELASTIC_USERNAME'), password=os.getenv('ELASTIC_PASSWORD')) +setup_sat_logging(client=elastic_client, index_name='test', app_name='lol') + +logger = logging.getLogger(__name__) + + +logger.info('hello') + +a = some_function() + +logger.info('Finished with the stuff, shutting down') diff --git a/logger_examples/get_logger/logging_scratch_mock.py b/logger_examples/get_logger/logging_scratch_mock.py new file mode 100644 index 0000000..6e8a339 --- /dev/null +++ b/logger_examples/get_logger/logging_scratch_mock.py @@ -0,0 +1,22 @@ +import logging +import os +import pprint +from unittest.mock import MagicMock + +from sat.logs import setup_sat_logging +from logger_examples.get_logger.helpers.some_module_1 import some_function + + + +elastic_client = MagicMock() + +setup_sat_logging(client=elastic_client, index_name='test', app_name='lol') + +logger = logging.getLogger(__name__) + + +logger.info('hello') + +a = some_function() + +logger.info('Finished with the stuff, shutting down') \ No newline at end of file diff --git a/logger_examples/sat_logger_setup/README.md b/logger_examples/sat_logger_setup/README.md new file mode 100644 index 0000000..fa66b74 --- /dev/null +++ b/logger_examples/sat_logger_setup/README.md @@ -0,0 +1,6 @@ +This example uses a SATLogger class, but relies on a call to the logging setup function. + +Again, this relies on the applications to make a call to the logging setup function in their entrypoint, +but then the existing `SATLogger` class can be used to instantiate loggers throughout the app's modules. +They actually could just as easily use `logging.getLogger` to instantiate a logger; the `SATLogger` here doesn't +really do anything, all of the configuration is handled in the setup function. diff --git a/logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py b/logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py new file mode 100644 index 0000000..a4d520d --- /dev/null +++ b/logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py @@ -0,0 +1,19 @@ +import logging + +from sat.logs import setup_sat_logging_with_defaults, SATLoggerStripped +from sat.some_module_1 import some_function + + +setup_sat_logging_with_defaults() # Has to be called once in the project main file + +# Just use logging.getLogger(__name__) wherever to get an appropriate logger +# Any logger configured will use the correct handlers that were assigned in the setup function +logger = SATLoggerStripped(__name__) + + + +logger.info('hello') + +a = some_function() + +logger.info('Finished with the stuff, shutting down') diff --git a/logger_examples/sat_logger_setup/module_2.py b/logger_examples/sat_logger_setup/module_2.py new file mode 100644 index 0000000..031f2a1 --- /dev/null +++ b/logger_examples/sat_logger_setup/module_2.py @@ -0,0 +1,7 @@ +from sat.logs import SATLoggerStripped + +LOGGER = SATLoggerStripped(__name__) + +def some_other_function(): + LOGGER.info('Did some stuff over here') + return None diff --git a/logger_examples/sat_logger_setup/some_module_1.py b/logger_examples/sat_logger_setup/some_module_1.py new file mode 100644 index 0000000..e783f4b --- /dev/null +++ b/logger_examples/sat_logger_setup/some_module_1.py @@ -0,0 +1,13 @@ +from sat.logs import SATLoggerStripped + + +from logger_examples.sat_logger_setup.module_2 import some_other_function + + +logger = SATLoggerStripped(__name__) + +def some_function(): + logger.info('Going to do some stuff') + some_other_function() + logger.info('Done with the stuff', extra={'cid': '00102301'}) + return None diff --git a/logger_examples/singleton/README.md b/logger_examples/singleton/README.md new file mode 100644 index 0000000..5010336 --- /dev/null +++ b/logger_examples/singleton/README.md @@ -0,0 +1,15 @@ +This example uses a singleton mixin for the `SATLogger` class, so no setup function call is necessary. + +The first time the `SATLogger` is used to initiate a logger, the setup function is called by the Singleton mixin. +The benefit here is that the application entrypoint doesn't have to call a setup function; +every file in the application will just have `logger = SATLogger(__name__)` at the top, +which is how they currently work. + +The downsides to this approach are +- a bit of increased complexity +- less flexibiliy or visibility into how the basicConfig is being set. +- Not really a way to parameterize the setup function; have to rely on one that pulls from environment variables + implicitly instead of passing values in as arguments. + We could add parameterization to the class init, but that would not function in an obivous way, + since it would only pull those parameters in the first time the class was called, + and just ignore them every other time. diff --git a/logger_examples/singleton/logging_setup_ex_singleton.py b/logger_examples/singleton/logging_setup_ex_singleton.py new file mode 100644 index 0000000..9a7bd37 --- /dev/null +++ b/logger_examples/singleton/logging_setup_ex_singleton.py @@ -0,0 +1,13 @@ +import logging + +from sat.logs import SATLoggerSingleton +from logger_examples.singleton.singleton_module import singleton_example_function + +logger = SATLoggerSingleton(__name__) + + +logger.info('hello') + +a = singleton_example_function() + +logger.info('Finished with the stuff, shutting down') diff --git a/logger_examples/singleton/singleton_module.py b/logger_examples/singleton/singleton_module.py new file mode 100644 index 0000000..1605078 --- /dev/null +++ b/logger_examples/singleton/singleton_module.py @@ -0,0 +1,11 @@ +from sat.logs import SATLoggerSingleton + + +logger = SATLoggerSingleton(__name__) + +def singleton_example_function(): + + logger.info('Doing some module stuff', extra={'cid': 'test-cid'}) + + return 'lol' + diff --git a/sat/logs.py b/sat/logs.py index 5650edd..f8ac22f 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -1,10 +1,105 @@ import logging import os +from unittest.mock import MagicMock import requests -from elasticsearch import Elasticsearch +from elasticsearch import Elasticsearch, BadRequestError +class SingletonLoggerMixin(object): + _instance = None + client_mock = None + + def __new__(cls, *args, **kwargs): + + # Only call this setup block the first time a SATLoggerSingleton is instantiated + # Prevents multiple setup function calls + if not isinstance(cls._instance, cls): + cls._instance = object.__new__(cls) + cls.client_mock = MagicMock() + setup_sat_logging(client=cls.client_mock, index_name='test', app_name='test') + + return cls._instance + + +class SATLoggerSingleton(SingletonLoggerMixin): + def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: + self.logger = logging.getLogger(name) + + def debug(self, msg: str, *args, **kwargs) -> None: + self.logger.debug(msg, *args, **kwargs) + + def info(self, msg: str, *args, **kwargs) -> None: + self.logger.info(msg, *args, **kwargs) + + def warning(self, msg: str, *args, **kwargs) -> None: + self.logger.warning(msg, *args, **kwargs) + + def error(self, msg: str, *args, **kwargs) -> None: + self.logger.error(msg, *args, **kwargs) + + def critical(self, msg: str, *args, **kwargs) -> None: + self.logger.critical(msg, *args, **kwargs) + + +class SATLoggerStripped: + + def __init__(self, name: str = __name__,) -> None: + self.logger = logging.getLogger(name) + + + def debug(self, msg: str, *args, **kwargs) -> None: + self.logger.debug(msg, *args, **kwargs) + + def info(self, msg: str, *args, **kwargs) -> None: + self.logger.info(msg, *args, **kwargs) + + def warning(self, msg: str, *args, **kwargs) -> None: + self.logger.warning(msg, *args, **kwargs) + + def error(self, msg: str, *args, **kwargs) -> None: + self.logger.error(msg, *args, **kwargs) + + def critical(self, msg: str, *args, **kwargs) -> None: + self.logger.critical(msg, *args, **kwargs) + + + +class ElasticModuleFilter(logging.Filter): + + def filter(self, record): + return 'elastic' not in record.name + +def setup_sat_logging_with_defaults(): + + elastic_url = os.environ['ELASTIC_URL'] + elastic_username = os.environ['ELASTIC_USERNAME'] + elastic_password = os.environ['ELASTIC_PASSWORD'] + elastic_index = os.environ['ELASTIC_INDEX'] + + app_name = os.environ['APP_NAME'] + + elastic_client = get_elasticsearch_client(elastic_url, elastic_username, elastic_password) + + setup_sat_logging(elastic_client, elastic_index, app_name) + +def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, loglevel: int = logging.INFO): + + if os.getenv('DEBUG'): + loglevel = logging.DEBUG + + elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel) + elastic_handler.addFilter(ElasticModuleFilter()) + + logging.basicConfig( + level=loglevel, + format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", + handlers=[ + logging.StreamHandler(), + elastic_handler + ] + ) + class SATLogger: def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: self.logger = logging.getLogger(name) @@ -31,25 +126,26 @@ def add_handlers(self, handlers: list[(logging.Handler, logging.Formatter)]) -> handler.setFormatter(self.formatter) self.logger.addHandler(handler) - def debug(self, msg: str) -> None: - self.logger.debug(msg) + def debug(self, msg: str, *args, **kwargs) -> None: + self.logger.debug(msg, *args, **kwargs) - def info(self, msg: str) -> None: - self.logger.info(msg) + def info(self, msg: str, *args, **kwargs) -> None: + self.logger.info(msg, *args, **kwargs) - def warning(self, msg: str) -> None: - self.logger.warning(msg) + def warning(self, msg: str, *args, **kwargs) -> None: + self.logger.warning(msg, *args, **kwargs) - def error(self, msg: str) -> None: - self.logger.error(msg) + def error(self, msg: str, *args, **kwargs) -> None: + self.logger.error(msg, *args, **kwargs) - def critical(self, msg: str) -> None: - self.logger.critical(msg) + def critical(self, msg: str, *args, **kwargs) -> None: + self.logger.critical(msg, *args, **kwargs) def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> Elasticsearch: return Elasticsearch( elastic_url, - basic_auth=(username, password) + basic_auth=(username, password), + verify_certs=False ) @@ -61,11 +157,26 @@ def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict self.index_name = index_name self.document_labels = document_labels + self.addFilter(ElasticModuleFilter()) # Need a filter here to prevent the elasticsearch module from recursively sending logging calls + + # Create index if none exists + try: + self.client.indices.create(index=index_name) + except BadRequestError: + pass # Index already exists so one doesn't have to be created + def emit(self, record): formatted_data = self.format(record) - document = {"log_message": formatted_data, "cid": record.extra.get('cid')} - if self.document_lables: + # Explicitly handle messages where a CID field is not provided + try: + message_cid = record.cid + except AttributeError: + message_cid = None + + document = {"log_message": formatted_data, "cid": message_cid} + + if self.document_labels: document.update(self.document_labels) self.client.index(index=self.index_name, document=document) diff --git a/sat/module_2.py b/sat/module_2.py new file mode 100644 index 0000000..adf1dfa --- /dev/null +++ b/sat/module_2.py @@ -0,0 +1,7 @@ +from logging import getLogger + +LOGGER = getLogger(__name__) + +def some_other_function(): + LOGGER.info('Did some stuff over here') + return None \ No newline at end of file diff --git a/sat/some_module_1.py b/sat/some_module_1.py new file mode 100644 index 0000000..02e6eca --- /dev/null +++ b/sat/some_module_1.py @@ -0,0 +1,13 @@ +from logging import getLogger + + +from sat.module_2 import some_other_function + + +logger = getLogger(__name__) + +def some_function(): + logger.info('Going to do some stuff') + some_other_function() + logger.info('Done with the stuff', extra={'cid': '00102301'}) + return None diff --git a/tests/test_elastic_search.py b/tests/test_elastic_search.py index c856789..623ef71 100644 --- a/tests/test_elastic_search.py +++ b/tests/test_elastic_search.py @@ -1,8 +1,10 @@ from unittest.mock import MagicMock +import datetime +import logging import pytest -from sat.logs import ElasticClientHandler, SATLogger +from sat.logs import ElasticClientHandler, SATLogger, ActualSatLogger, setup_sat_logging @pytest.fixture @@ -12,17 +14,47 @@ def mock_elastic_client(): @pytest.fixture def logger(): - logger = SATLogger(__name__) + logger = ActualSatLogger(__name__) return logger +def mock_time(self, record, datefmt=None): + return datetime.datetime(2000,1,2,3,4,5,678).strftime('%Y-%m-%d %H:%M:%S,%f')[:-3] + + +def test_setup_log(mock_elastic_client): + setup_sat_logging(client=mock_elastic_client, index_name='test', app_name='test') + test_logger = logging.getLogger(__name__) + test_logger.info('lol', extra={'cid': 'test-cid'}) + + expected_log_document = { + "log_message": "2000-01-02 03:04:05,000 - tests.test_elastic_search - INFO - test message", + "cid": "test_cid" + } + + mock_elastic_client.index.assert_called_with(index='test-index', document=expected_log_document) + + def test_log_sent(mock_elastic_client, logger): elastic_handler = ElasticClientHandler(mock_elastic_client, 'test-index', None) - logger.add_handlers([elastic_handler]) + logger.add_handlers([(elastic_handler, None)]) + logger.formatter.formatTime = mock_time + logger.info('test message') def test_extra_handling(mock_elastic_client, logger): elastic_handler = ElasticClientHandler(mock_elastic_client, 'test-index', None) - logger.add_handlers([elastic_handler]) + formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") + formatter.formatTime = mock_time + elastic_handler.setFormatter(formatter) + + logger.addHandler(elastic_handler) logger.info('test message', extra={'cid': 'test_cid'}) + + expected_log_document = { + "log_message": "2000-01-02 03:04:05,000 - tests.test_elastic_search - INFO - test message", + "cid": "test_cid" + } + + mock_elastic_client.index.assert_called_with(index='test-index', document=expected_log_document) From d53f9b46daf1618179ec2987db4bad6627182e0e Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Tue, 15 Oct 2024 11:28:33 -0400 Subject: [PATCH 04/17] Remove example logging modules from utils module --- sat/module_2.py | 7 ------- sat/some_module_1.py | 13 ------------- 2 files changed, 20 deletions(-) delete mode 100644 sat/module_2.py delete mode 100644 sat/some_module_1.py diff --git a/sat/module_2.py b/sat/module_2.py deleted file mode 100644 index adf1dfa..0000000 --- a/sat/module_2.py +++ /dev/null @@ -1,7 +0,0 @@ -from logging import getLogger - -LOGGER = getLogger(__name__) - -def some_other_function(): - LOGGER.info('Did some stuff over here') - return None \ No newline at end of file diff --git a/sat/some_module_1.py b/sat/some_module_1.py deleted file mode 100644 index 02e6eca..0000000 --- a/sat/some_module_1.py +++ /dev/null @@ -1,13 +0,0 @@ -from logging import getLogger - - -from sat.module_2 import some_other_function - - -logger = getLogger(__name__) - -def some_function(): - logger.info('Going to do some stuff') - some_other_function() - logger.info('Done with the stuff', extra={'cid': '00102301'}) - return None From e0af883688894f3788bb9c4c5802b027c42ccae6 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Tue, 15 Oct 2024 15:19:55 -0400 Subject: [PATCH 05/17] Add feature flag for elastic log handler --- sat/logs.py | 54 +++++++++++++++++++++++++++++++++++------------------ 1 file changed, 36 insertions(+), 18 deletions(-) diff --git a/sat/logs.py b/sat/logs.py index f8ac22f..0801367 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -72,32 +72,49 @@ def filter(self, record): def setup_sat_logging_with_defaults(): - elastic_url = os.environ['ELASTIC_URL'] - elastic_username = os.environ['ELASTIC_USERNAME'] - elastic_password = os.environ['ELASTIC_PASSWORD'] - elastic_index = os.environ['ELASTIC_INDEX'] - app_name = os.environ['APP_NAME'] + # Elastic loging feature flag defaults to false, don't want to blow up local development if no environment variables are set + enable_elastic_string = os.getenv('ELASTIC_ENABLE_LOGGING', '') + if enable_elastic_string.lower() == 'true': + enable_elastic_logging = True + else: + enable_elastic_logging = False - elastic_client = get_elasticsearch_client(elastic_url, elastic_username, elastic_password) + if enable_elastic_logging: + elastic_url = os.environ['ELASTIC_URL'] + elastic_username = os.environ['ELASTIC_USERNAME'] + elastic_password = os.environ['ELASTIC_PASSWORD'] + elastic_index = os.environ['ELASTIC_INDEX'] + app_name = os.environ['APP_NAME'] + elastic_client = get_elasticsearch_client(elastic_url, elastic_username, elastic_password) + else: + app_name = os.getenv('APP_NAME') # If logging without elastic enabled, APP_NAME is optional + elastic_client = None + elastic_index = None - setup_sat_logging(elastic_client, elastic_index, app_name) -def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, loglevel: int = logging.INFO): + log_level_string = os.getenv('LOGLEVEL', 'INFO') + log_level = getattr(logging, log_level_string.upper()) + + + setup_sat_logging(elastic_client, elastic_index, app_name, enable_elastic_logging, log_level) + +def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO): + + log_handlers = [logging.StreamHandler()] if os.getenv('DEBUG'): loglevel = logging.DEBUG - elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel) - elastic_handler.addFilter(ElasticModuleFilter()) + if enable_elastic_logging: + elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel) + elastic_handler.addFilter(ElasticModuleFilter()) + log_handlers.append(elastic_handler) logging.basicConfig( level=loglevel, format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", - handlers=[ - logging.StreamHandler(), - elastic_handler - ] + handlers=log_handlers ) class SATLogger: @@ -107,10 +124,11 @@ def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: self.logger.setLevel(logging.DEBUG) else: self.logger.setLevel(level) - self.formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") - self.handler = logging.StreamHandler() - self.handler.setFormatter(self.formatter) - self.logger.addHandler(self.handler) + # self.formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") + # self.handler = logging.StreamHandler() + # self.handler.setFormatter(self.formatter) + # self.logger.addHandler(self.handler) + setup_sat_logging_with_defaults() def add_handlers(self, handlers: list[(logging.Handler, logging.Formatter)]) -> None: """ From da334c59fd137aa169d9f8531e0cb0004e36b895 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Tue, 15 Oct 2024 15:20:22 -0400 Subject: [PATCH 06/17] Add exampe with multiple elastic network clients --- logger_examples/old_school_logger/a_module.py | 11 +++++++++++ logger_examples/old_school_logger/b_module.py | 7 +++++++ logger_examples/old_school_logger/main.py | 11 +++++++++++ 3 files changed, 29 insertions(+) create mode 100644 logger_examples/old_school_logger/a_module.py create mode 100644 logger_examples/old_school_logger/b_module.py create mode 100644 logger_examples/old_school_logger/main.py diff --git a/logger_examples/old_school_logger/a_module.py b/logger_examples/old_school_logger/a_module.py new file mode 100644 index 0000000..8a3e4a0 --- /dev/null +++ b/logger_examples/old_school_logger/a_module.py @@ -0,0 +1,11 @@ +from sat.logs import SATLogger + +from logger_examples.old_school_logger.b_module import b_function + +logger = SATLogger(__name__) + +def a_function(): + logger.info('A message') + b_function() + + return \ No newline at end of file diff --git a/logger_examples/old_school_logger/b_module.py b/logger_examples/old_school_logger/b_module.py new file mode 100644 index 0000000..77c13d3 --- /dev/null +++ b/logger_examples/old_school_logger/b_module.py @@ -0,0 +1,7 @@ +from sat.logs import SATLogger + +logger = SATLogger(__name__) + +def b_function(): + logger.info('B message') + return \ No newline at end of file diff --git a/logger_examples/old_school_logger/main.py b/logger_examples/old_school_logger/main.py new file mode 100644 index 0000000..3aa0ec3 --- /dev/null +++ b/logger_examples/old_school_logger/main.py @@ -0,0 +1,11 @@ +from sat.logs import SATLogger +from logger_examples.old_school_logger.a_module import a_function + +logger = SATLogger(__name__) + +logger.info('start') + +a_function() + +logger.info('end') + From ac5bcff528846bea709f98e5c9defc3fd7ceb758 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Wed, 23 Oct 2024 17:35:26 -0400 Subject: [PATCH 07/17] Remove examples of unused implementations --- logger_examples/get_logger/README.md | 5 -- .../get_logger/helpers/module_2.py | 7 --- .../get_logger/helpers/some_module_1.py | 13 ---- logger_examples/get_logger/logging_scratch.py | 23 ------- .../get_logger/logging_scratch_mock.py | 22 ------- logger_examples/old_school_logger/a_module.py | 11 ---- logger_examples/old_school_logger/b_module.py | 7 --- logger_examples/old_school_logger/main.py | 11 ---- logger_examples/sat_logger_setup/README.md | 6 -- .../logging_setup_ex_sat_logger.py | 19 ------ logger_examples/sat_logger_setup/module_2.py | 7 --- .../sat_logger_setup/some_module_1.py | 13 ---- logger_examples/singleton/README.md | 15 ----- .../singleton/logging_setup_ex_singleton.py | 13 ---- logger_examples/singleton/singleton_module.py | 11 ---- tests/test_elastic_search.py | 60 ------------------- 16 files changed, 243 deletions(-) delete mode 100644 logger_examples/get_logger/README.md delete mode 100644 logger_examples/get_logger/helpers/module_2.py delete mode 100644 logger_examples/get_logger/helpers/some_module_1.py delete mode 100644 logger_examples/get_logger/logging_scratch.py delete mode 100644 logger_examples/get_logger/logging_scratch_mock.py delete mode 100644 logger_examples/old_school_logger/a_module.py delete mode 100644 logger_examples/old_school_logger/b_module.py delete mode 100644 logger_examples/old_school_logger/main.py delete mode 100644 logger_examples/sat_logger_setup/README.md delete mode 100644 logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py delete mode 100644 logger_examples/sat_logger_setup/module_2.py delete mode 100644 logger_examples/sat_logger_setup/some_module_1.py delete mode 100644 logger_examples/singleton/README.md delete mode 100644 logger_examples/singleton/logging_setup_ex_singleton.py delete mode 100644 logger_examples/singleton/singleton_module.py delete mode 100644 tests/test_elastic_search.py diff --git a/logger_examples/get_logger/README.md b/logger_examples/get_logger/README.md deleted file mode 100644 index 2dc0d0d..0000000 --- a/logger_examples/get_logger/README.md +++ /dev/null @@ -1,5 +0,0 @@ -This is an example logging implementation using a setup function and the default `logging.getLogger` function. - -Requires the application to independently call the logger setup function once in the application entrypoint, -and then any method can be used in the individual modules to get their appropriate logger, -as these will inhereit the logging basicConfig. \ No newline at end of file diff --git a/logger_examples/get_logger/helpers/module_2.py b/logger_examples/get_logger/helpers/module_2.py deleted file mode 100644 index adf1dfa..0000000 --- a/logger_examples/get_logger/helpers/module_2.py +++ /dev/null @@ -1,7 +0,0 @@ -from logging import getLogger - -LOGGER = getLogger(__name__) - -def some_other_function(): - LOGGER.info('Did some stuff over here') - return None \ No newline at end of file diff --git a/logger_examples/get_logger/helpers/some_module_1.py b/logger_examples/get_logger/helpers/some_module_1.py deleted file mode 100644 index 2001af8..0000000 --- a/logger_examples/get_logger/helpers/some_module_1.py +++ /dev/null @@ -1,13 +0,0 @@ -from logging import getLogger - - -from logger_examples.get_logger.helpers.module_2 import some_other_function - - -logger = getLogger(__name__) - -def some_function(): - logger.info('Going to do some stuff') - some_other_function() - logger.info('Done with the stuff', extra={'cid': '00102301'}) - return None diff --git a/logger_examples/get_logger/logging_scratch.py b/logger_examples/get_logger/logging_scratch.py deleted file mode 100644 index 3691d08..0000000 --- a/logger_examples/get_logger/logging_scratch.py +++ /dev/null @@ -1,23 +0,0 @@ -import logging -import os - -from sat.logs import setup_sat_logging, get_elasticsearch_client -from logger_examples.get_logger.helpers.some_module_1 import some_function - - - -# This example uses a function that takes the elastic client and parameters as arguments -# We could also ues a `setup_sat_logging` function that defaults to pulling from specific -# env variables automatically so that the application entrypoints aren't as complex -# The benefit to this is that testing is much easier, since `setup_sat_logging` can be called with a mock client -elastic_client = get_elasticsearch_client(os.getenv('ELASTIC_URL'), username=os.getenv('ELASTIC_USERNAME'), password=os.getenv('ELASTIC_PASSWORD')) -setup_sat_logging(client=elastic_client, index_name='test', app_name='lol') - -logger = logging.getLogger(__name__) - - -logger.info('hello') - -a = some_function() - -logger.info('Finished with the stuff, shutting down') diff --git a/logger_examples/get_logger/logging_scratch_mock.py b/logger_examples/get_logger/logging_scratch_mock.py deleted file mode 100644 index 6e8a339..0000000 --- a/logger_examples/get_logger/logging_scratch_mock.py +++ /dev/null @@ -1,22 +0,0 @@ -import logging -import os -import pprint -from unittest.mock import MagicMock - -from sat.logs import setup_sat_logging -from logger_examples.get_logger.helpers.some_module_1 import some_function - - - -elastic_client = MagicMock() - -setup_sat_logging(client=elastic_client, index_name='test', app_name='lol') - -logger = logging.getLogger(__name__) - - -logger.info('hello') - -a = some_function() - -logger.info('Finished with the stuff, shutting down') \ No newline at end of file diff --git a/logger_examples/old_school_logger/a_module.py b/logger_examples/old_school_logger/a_module.py deleted file mode 100644 index 8a3e4a0..0000000 --- a/logger_examples/old_school_logger/a_module.py +++ /dev/null @@ -1,11 +0,0 @@ -from sat.logs import SATLogger - -from logger_examples.old_school_logger.b_module import b_function - -logger = SATLogger(__name__) - -def a_function(): - logger.info('A message') - b_function() - - return \ No newline at end of file diff --git a/logger_examples/old_school_logger/b_module.py b/logger_examples/old_school_logger/b_module.py deleted file mode 100644 index 77c13d3..0000000 --- a/logger_examples/old_school_logger/b_module.py +++ /dev/null @@ -1,7 +0,0 @@ -from sat.logs import SATLogger - -logger = SATLogger(__name__) - -def b_function(): - logger.info('B message') - return \ No newline at end of file diff --git a/logger_examples/old_school_logger/main.py b/logger_examples/old_school_logger/main.py deleted file mode 100644 index 3aa0ec3..0000000 --- a/logger_examples/old_school_logger/main.py +++ /dev/null @@ -1,11 +0,0 @@ -from sat.logs import SATLogger -from logger_examples.old_school_logger.a_module import a_function - -logger = SATLogger(__name__) - -logger.info('start') - -a_function() - -logger.info('end') - diff --git a/logger_examples/sat_logger_setup/README.md b/logger_examples/sat_logger_setup/README.md deleted file mode 100644 index fa66b74..0000000 --- a/logger_examples/sat_logger_setup/README.md +++ /dev/null @@ -1,6 +0,0 @@ -This example uses a SATLogger class, but relies on a call to the logging setup function. - -Again, this relies on the applications to make a call to the logging setup function in their entrypoint, -but then the existing `SATLogger` class can be used to instantiate loggers throughout the app's modules. -They actually could just as easily use `logging.getLogger` to instantiate a logger; the `SATLogger` here doesn't -really do anything, all of the configuration is handled in the setup function. diff --git a/logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py b/logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py deleted file mode 100644 index a4d520d..0000000 --- a/logger_examples/sat_logger_setup/logging_setup_ex_sat_logger.py +++ /dev/null @@ -1,19 +0,0 @@ -import logging - -from sat.logs import setup_sat_logging_with_defaults, SATLoggerStripped -from sat.some_module_1 import some_function - - -setup_sat_logging_with_defaults() # Has to be called once in the project main file - -# Just use logging.getLogger(__name__) wherever to get an appropriate logger -# Any logger configured will use the correct handlers that were assigned in the setup function -logger = SATLoggerStripped(__name__) - - - -logger.info('hello') - -a = some_function() - -logger.info('Finished with the stuff, shutting down') diff --git a/logger_examples/sat_logger_setup/module_2.py b/logger_examples/sat_logger_setup/module_2.py deleted file mode 100644 index 031f2a1..0000000 --- a/logger_examples/sat_logger_setup/module_2.py +++ /dev/null @@ -1,7 +0,0 @@ -from sat.logs import SATLoggerStripped - -LOGGER = SATLoggerStripped(__name__) - -def some_other_function(): - LOGGER.info('Did some stuff over here') - return None diff --git a/logger_examples/sat_logger_setup/some_module_1.py b/logger_examples/sat_logger_setup/some_module_1.py deleted file mode 100644 index e783f4b..0000000 --- a/logger_examples/sat_logger_setup/some_module_1.py +++ /dev/null @@ -1,13 +0,0 @@ -from sat.logs import SATLoggerStripped - - -from logger_examples.sat_logger_setup.module_2 import some_other_function - - -logger = SATLoggerStripped(__name__) - -def some_function(): - logger.info('Going to do some stuff') - some_other_function() - logger.info('Done with the stuff', extra={'cid': '00102301'}) - return None diff --git a/logger_examples/singleton/README.md b/logger_examples/singleton/README.md deleted file mode 100644 index 5010336..0000000 --- a/logger_examples/singleton/README.md +++ /dev/null @@ -1,15 +0,0 @@ -This example uses a singleton mixin for the `SATLogger` class, so no setup function call is necessary. - -The first time the `SATLogger` is used to initiate a logger, the setup function is called by the Singleton mixin. -The benefit here is that the application entrypoint doesn't have to call a setup function; -every file in the application will just have `logger = SATLogger(__name__)` at the top, -which is how they currently work. - -The downsides to this approach are -- a bit of increased complexity -- less flexibiliy or visibility into how the basicConfig is being set. -- Not really a way to parameterize the setup function; have to rely on one that pulls from environment variables - implicitly instead of passing values in as arguments. - We could add parameterization to the class init, but that would not function in an obivous way, - since it would only pull those parameters in the first time the class was called, - and just ignore them every other time. diff --git a/logger_examples/singleton/logging_setup_ex_singleton.py b/logger_examples/singleton/logging_setup_ex_singleton.py deleted file mode 100644 index 9a7bd37..0000000 --- a/logger_examples/singleton/logging_setup_ex_singleton.py +++ /dev/null @@ -1,13 +0,0 @@ -import logging - -from sat.logs import SATLoggerSingleton -from logger_examples.singleton.singleton_module import singleton_example_function - -logger = SATLoggerSingleton(__name__) - - -logger.info('hello') - -a = singleton_example_function() - -logger.info('Finished with the stuff, shutting down') diff --git a/logger_examples/singleton/singleton_module.py b/logger_examples/singleton/singleton_module.py deleted file mode 100644 index 1605078..0000000 --- a/logger_examples/singleton/singleton_module.py +++ /dev/null @@ -1,11 +0,0 @@ -from sat.logs import SATLoggerSingleton - - -logger = SATLoggerSingleton(__name__) - -def singleton_example_function(): - - logger.info('Doing some module stuff', extra={'cid': 'test-cid'}) - - return 'lol' - diff --git a/tests/test_elastic_search.py b/tests/test_elastic_search.py deleted file mode 100644 index 623ef71..0000000 --- a/tests/test_elastic_search.py +++ /dev/null @@ -1,60 +0,0 @@ -from unittest.mock import MagicMock -import datetime -import logging - -import pytest - -from sat.logs import ElasticClientHandler, SATLogger, ActualSatLogger, setup_sat_logging - - -@pytest.fixture -def mock_elastic_client(): - mock_client = MagicMock() - return mock_client - -@pytest.fixture -def logger(): - logger = ActualSatLogger(__name__) - return logger - -def mock_time(self, record, datefmt=None): - return datetime.datetime(2000,1,2,3,4,5,678).strftime('%Y-%m-%d %H:%M:%S,%f')[:-3] - - -def test_setup_log(mock_elastic_client): - setup_sat_logging(client=mock_elastic_client, index_name='test', app_name='test') - test_logger = logging.getLogger(__name__) - test_logger.info('lol', extra={'cid': 'test-cid'}) - - expected_log_document = { - "log_message": "2000-01-02 03:04:05,000 - tests.test_elastic_search - INFO - test message", - "cid": "test_cid" - } - - mock_elastic_client.index.assert_called_with(index='test-index', document=expected_log_document) - - -def test_log_sent(mock_elastic_client, logger): - - elastic_handler = ElasticClientHandler(mock_elastic_client, 'test-index', None) - logger.add_handlers([(elastic_handler, None)]) - logger.formatter.formatTime = mock_time - - logger.info('test message') - -def test_extra_handling(mock_elastic_client, logger): - - elastic_handler = ElasticClientHandler(mock_elastic_client, 'test-index', None) - formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") - formatter.formatTime = mock_time - elastic_handler.setFormatter(formatter) - - logger.addHandler(elastic_handler) - logger.info('test message', extra={'cid': 'test_cid'}) - - expected_log_document = { - "log_message": "2000-01-02 03:04:05,000 - tests.test_elastic_search - INFO - test message", - "cid": "test_cid" - } - - mock_elastic_client.index.assert_called_with(index='test-index', document=expected_log_document) From 552ec9574f92eb420d8e15474788bb534e2c3816 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Wed, 23 Oct 2024 17:36:14 -0400 Subject: [PATCH 08/17] Update slack tests to account for new logger --- sat/slack.py | 5 +++-- tests/test_slack.py | 5 ++++- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/sat/slack.py b/sat/slack.py index 389235d..effdc2e 100644 --- a/sat/slack.py +++ b/sat/slack.py @@ -1,9 +1,10 @@ +import logging + from slack_sdk import WebClient from slack_sdk.errors import SlackApiError -from sat.logs import SATLogger -logger = SATLogger(name=__name__) +logger = logging.getLogger(__name__) class Slack: diff --git a/tests/test_slack.py b/tests/test_slack.py index 2ba8c6a..68229fc 100644 --- a/tests/test_slack.py +++ b/tests/test_slack.py @@ -1,6 +1,8 @@ -from unittest.mock import patch +import logging +from unittest.mock import patch, MagicMock from sat.slack import Slack, SlackApiError +from sat.logs import setup_sat_logging def mock_slack_response(): @@ -8,6 +10,7 @@ def mock_slack_response(): def test_send_message_error(caplog): + caplog.set_level(logging.INFO) with patch("sat.slack.WebClient.chat_postMessage") as mock: mock.side_effect = SlackApiError("test error", mock_slack_response()) slack = Slack("test") From a13b4823d4be2cd227fc7b833a4c607f06250a89 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Wed, 23 Oct 2024 17:36:33 -0400 Subject: [PATCH 09/17] Fix tests for Elastic Handler --- sat/logs.py | 113 +++++++++++++--------------------- tests/test_elk_integration.py | 96 +++++++++++++++++++++++++++++ 2 files changed, 138 insertions(+), 71 deletions(-) create mode 100644 tests/test_elk_integration.py diff --git a/sat/logs.py b/sat/logs.py index 0801367..fd8d0ab 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -1,9 +1,10 @@ import logging import os from unittest.mock import MagicMock +import time -import requests from elasticsearch import Elasticsearch, BadRequestError +from elasticsearch.helpers import bulk class SingletonLoggerMixin(object): @@ -16,37 +17,31 @@ def __new__(cls, *args, **kwargs): # Prevents multiple setup function calls if not isinstance(cls._instance, cls): cls._instance = object.__new__(cls) - cls.client_mock = MagicMock() - setup_sat_logging(client=cls.client_mock, index_name='test', app_name='test') + setup_sat_logging_with_defaults() return cls._instance -class SATLoggerSingleton(SingletonLoggerMixin): +class SATLogger(SingletonLoggerMixin): def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: self.logger = logging.getLogger(name) - def debug(self, msg: str, *args, **kwargs) -> None: - self.logger.debug(msg, *args, **kwargs) - - def info(self, msg: str, *args, **kwargs) -> None: - self.logger.info(msg, *args, **kwargs) - - def warning(self, msg: str, *args, **kwargs) -> None: - self.logger.warning(msg, *args, **kwargs) - - def error(self, msg: str, *args, **kwargs) -> None: - self.logger.error(msg, *args, **kwargs) - - def critical(self, msg: str, *args, **kwargs) -> None: - self.logger.critical(msg, *args, **kwargs) - - -class SATLoggerStripped: + def add_handlers(self, handlers: list[(logging.Handler, logging.Formatter)]) -> None: + """ + Add additional handlers to the logger. + Handlers should be a list of tuples with a logging.Handler and an + optional logging.Formatter. + """ - def __init__(self, name: str = __name__,) -> None: - self.logger = logging.getLogger(name) + self.logger.warning('Adding handlers to this instance of the logger only, will not persist throughout project. Update logging config to persist changes.') + for tup in handlers: + handler, formatter = tup + if formatter: + handler.setFormatter(formatter) + else: + handler.setFormatter(self.formatter) + self.logger.addHandler(handler) def debug(self, msg: str, *args, **kwargs) -> None: self.logger.debug(msg, *args, **kwargs) @@ -62,7 +57,6 @@ def error(self, msg: str, *args, **kwargs) -> None: def critical(self, msg: str, *args, **kwargs) -> None: self.logger.critical(msg, *args, **kwargs) - class ElasticModuleFilter(logging.Filter): @@ -99,15 +93,15 @@ def setup_sat_logging_with_defaults(): setup_sat_logging(elastic_client, elastic_index, app_name, enable_elastic_logging, log_level) -def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO): +def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO, batch_size: int=100, batch_time: float=2.): - log_handlers = [logging.StreamHandler()] + log_handlers = [logging.StreamHandler(), logging.StreamHandler(), logging.StreamHandler()] if os.getenv('DEBUG'): loglevel = logging.DEBUG if enable_elastic_logging: - elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel) + elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel, batch_size=batch_size, batch_time=batch_time) elastic_handler.addFilter(ElasticModuleFilter()) log_handlers.append(elastic_handler) @@ -117,47 +111,6 @@ def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, ena handlers=log_handlers ) -class SATLogger: - def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: - self.logger = logging.getLogger(name) - if os.getenv("DEBUG"): - self.logger.setLevel(logging.DEBUG) - else: - self.logger.setLevel(level) - # self.formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") - # self.handler = logging.StreamHandler() - # self.handler.setFormatter(self.formatter) - # self.logger.addHandler(self.handler) - setup_sat_logging_with_defaults() - - def add_handlers(self, handlers: list[(logging.Handler, logging.Formatter)]) -> None: - """ - Add additional handlers to the logger. - Handlers should be a list of tuples with a logging.Handler and an - optional logging.Formatter. - """ - for tup in handlers: - handler, formatter = tup - if formatter: - handler.setFormatter(formatter) - else: - handler.setFormatter(self.formatter) - self.logger.addHandler(handler) - - def debug(self, msg: str, *args, **kwargs) -> None: - self.logger.debug(msg, *args, **kwargs) - - def info(self, msg: str, *args, **kwargs) -> None: - self.logger.info(msg, *args, **kwargs) - - def warning(self, msg: str, *args, **kwargs) -> None: - self.logger.warning(msg, *args, **kwargs) - - def error(self, msg: str, *args, **kwargs) -> None: - self.logger.error(msg, *args, **kwargs) - - def critical(self, msg: str, *args, **kwargs) -> None: - self.logger.critical(msg, *args, **kwargs) def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> Elasticsearch: return Elasticsearch( @@ -166,14 +119,17 @@ def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> verify_certs=False ) - class ElasticClientHandler(logging.Handler): - def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET): + def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET, batch_size: int=10, batch_time: float=5.): super().__init__(level) self.client = client self.index_name = index_name self.document_labels = document_labels + self.batch_size = batch_size + self.batch_time = batch_time + self._queue = [] + self._batch_start_time = time.time() self.addFilter(ElasticModuleFilter()) # Need a filter here to prevent the elasticsearch module from recursively sending logging calls @@ -197,4 +153,19 @@ def emit(self, record): if self.document_labels: document.update(self.document_labels) - self.client.index(index=self.index_name, document=document) + self._queue.append(document) + + if len(self._queue) >= self.batch_size: + self.flush() + elif time.time() - self.batch_time >= self._batch_start_time: + self.flush() + + def flush(self): + upload_result = bulk(self.client, self._queue) + self._queue = [] + self._batch_start_time = time.time() + super().flush() + + def close(self): + self.flush() + super().close() diff --git a/tests/test_elk_integration.py b/tests/test_elk_integration.py new file mode 100644 index 0000000..c3216d0 --- /dev/null +++ b/tests/test_elk_integration.py @@ -0,0 +1,96 @@ +from unittest.mock import MagicMock, patch +import datetime +import logging + +import pytest + +from sat.logs import ElasticClientHandler + + +@pytest.fixture +def log_stuff(request): + with patch('sat.logs.bulk') as bulk_patch: + mock_client = MagicMock() + elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=1, batch_time=10.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(request.node.name) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + yield logger, mock_client, bulk_patch + + +def test_without_fixture(): + mock_client = MagicMock() + elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, + level=logging.INFO, batch_size=10, batch_time=10.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(__name__) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + logger.info('test 1 message 1') + logger.info('test 1 message 2') + + +def test_log_sent(log_stuff): + """Just assert that the bulk upload method is called if a single message is sent""" + test_logger, mock_elastic_client, bulk_patch = log_stuff + test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) + bulk_patch.assert_called() + + +def test_extra_handling(log_stuff): + + logger, mock_elastic_client, bulk_patch = log_stuff + + logger.info('test 3 message 1', extra={'cid': 'test 3 cid 1'}) + + expected_log_document = { + 'app': 'test', + "log_message": "test 3 message 1", + "cid": "test 3 cid 1" + } + + bulk_patch.assert_called_with(mock_elastic_client, [expected_log_document]) + +def test_bulk_handler(): + + with patch('sat.logs.bulk') as bulk_patch: + mock_client = MagicMock() + elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=3, batch_time=1000.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(__name__) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + logger.info('test_1') + logger.info('test_2') + bulk_patch.assert_not_called() + + logger.info('test_3') + bulk_patch.assert_called() + + + +def test_bulk_not_called(): + + with patch('sat.logs.bulk') as bulk_patch: + mock_client = MagicMock() + elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=10, batch_time=1000.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(__name__) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + logger.info('test_1') + logger.info('test_2') + logger.info('test_3') + bulk_patch.assert_called() From 1414e3120c229e6e0717182480918074f94b6c1e Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 13:26:53 -0400 Subject: [PATCH 10/17] Create separate handler for Elastic Bulk uploads Running into a bunch of issues implementing this, although it will be much simpler if I can change the app entrypoint stuff. Creating a separate bulk implementation to do that; if we need bulk for batch jobs like automations, we can just wrap their main with a try finally block to handle logger shutdown --- sat/logs.py | 117 +++++++++++++++++++++++++++++----- tests/test_elastic.py | 36 +++++++++++ tests/test_elk_integration.py | 68 ++++---------------- tests/test_logger.py | 3 + 4 files changed, 154 insertions(+), 70 deletions(-) create mode 100644 tests/test_elastic.py diff --git a/sat/logs.py b/sat/logs.py index fd8d0ab..1ea277c 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -2,10 +2,14 @@ import os from unittest.mock import MagicMock import time +import sys +from collections import deque from elasticsearch import Elasticsearch, BadRequestError from elasticsearch.helpers import bulk +logger = logging.getLogger(__name__) + class SingletonLoggerMixin(object): _instance = None @@ -62,9 +66,11 @@ def critical(self, msg: str, *args, **kwargs) -> None: class ElasticModuleFilter(logging.Filter): def filter(self, record): - return 'elastic' not in record.name + top_module_name = record.name.split('.')[0] + return top_module_name not in ['elastic', 'elastic_transport'] def setup_sat_logging_with_defaults(): + print('setting up sat logger with defaults') # Elastic loging feature flag defaults to false, don't want to blow up local development if no environment variables are set @@ -72,6 +78,7 @@ def setup_sat_logging_with_defaults(): if enable_elastic_string.lower() == 'true': enable_elastic_logging = True else: + logger.warning('Elastic logging disabled, continuing without') enable_elastic_logging = False if enable_elastic_logging: @@ -93,15 +100,54 @@ def setup_sat_logging_with_defaults(): setup_sat_logging(elastic_client, elastic_index, app_name, enable_elastic_logging, log_level) -def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO, batch_size: int=100, batch_time: float=2.): - log_handlers = [logging.StreamHandler(), logging.StreamHandler(), logging.StreamHandler()] +def shutdown_logging_on_exception(exc_type, exc_value, exc_traceback): + """Shuts down logger before calling normal exception handling + + This is required because if the ElasticClientHandler ends up having any other messages assigned to its queue + while the + + """ + root_logger = logging.getLogger() + elastic_handlers = [handler for handler in root_logger.handlers if isinstance(handler, ElasticClientBulkHandler)] + for elastic_handler in elastic_handlers: + elastic_handler.flush() + elastic_handler.set_use_bulk(False) + + + # logging.shutdown() + sys.__excepthook__(exc_type, exc_value, exc_traceback) + +def setup_sat_logging_bulk(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO, batch_size: int=100, batch_time: float=2.): + + log_handlers = [logging.StreamHandler()] + + # Set up custom exception hook + sys.excepthook = shutdown_logging_on_exception if os.getenv('DEBUG'): loglevel = logging.DEBUG if enable_elastic_logging: - elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel, batch_size=batch_size, batch_time=batch_time) + elastic_handler = ElasticClientBulkHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel, batch_size=batch_size, batch_time=batch_time) + elastic_handler.addFilter(ElasticModuleFilter()) + log_handlers.append(elastic_handler) + + logging.basicConfig( + level=loglevel, + format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", + handlers=log_handlers + ) + +def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO): + + log_handlers = [logging.StreamHandler()] + + if os.getenv('DEBUG'): + loglevel = logging.DEBUG + + if enable_elastic_logging: + elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel) elastic_handler.addFilter(ElasticModuleFilter()) log_handlers.append(elastic_handler) @@ -121,16 +167,11 @@ def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> class ElasticClientHandler(logging.Handler): - def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET, batch_size: int=10, batch_time: float=5.): + def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET): super().__init__(level) self.client = client self.index_name = index_name self.document_labels = document_labels - self.batch_size = batch_size - self.batch_time = batch_time - self._queue = [] - self._batch_start_time = time.time() - self.addFilter(ElasticModuleFilter()) # Need a filter here to prevent the elasticsearch module from recursively sending logging calls # Create index if none exists @@ -141,6 +182,41 @@ def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict def emit(self, record): formatted_data = self.format(record) + logger.debug('Elastic handler emitting') + + # Explicitly handle messages where a CID field is not provided + try: + message_cid = record.cid + except AttributeError: + message_cid = None + + document = {"log_message": formatted_data, "cid": message_cid} + + if self.document_labels: + document.update(self.document_labels) + + self.client.index(index=self.index_name, document=document) + + +class ElasticClientBulkHandler(ElasticClientHandler): + + def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET, batch_size: int=10, batch_time: float=5.): + super().__init__(client, index_name, document_labels, level) + self.batch_size = batch_size + self.batch_time = batch_time + self._queue = [] + self._batch_start_time = time.time() + + # Switching variable for using bulk, want to switch to single requests during shutdown to avoid weird + # hanging issues caused by leaving elastic messages on the bulk queue + self._use_bulk = False + + def set_use_bulk(self, use_bulk): + self._use_bulk = use_bulk + + def emit(self, record): + formatted_data = self.format(record) + logger.debug('Elastic handler emitting') # Explicitly handle messages where a CID field is not provided try: @@ -153,19 +229,28 @@ def emit(self, record): if self.document_labels: document.update(self.document_labels) - self._queue.append(document) + if self._use_bulk: + document.update({'_index': self.index_name}) + self._queue.append(document) - if len(self._queue) >= self.batch_size: - self.flush() - elif time.time() - self.batch_time >= self._batch_start_time: - self.flush() + if len(self._queue) >= self.batch_size: + self.flush() + elif time.time() - self.batch_time >= self._batch_start_time: + self.flush() + else: + self.client.index(index=self.index_name, document=document) def flush(self): - upload_result = bulk(self.client, self._queue) + logger.debug('Flushing') + if self._queue and self._use_bulk: + bulk(self.client, self._queue) + logger.debug('Finished uploading to elastic') self._queue = [] self._batch_start_time = time.time() super().flush() def close(self): + logger.debug('Closing') self.flush() + self.client.close() super().close() diff --git a/tests/test_elastic.py b/tests/test_elastic.py new file mode 100644 index 0000000..316ed2f --- /dev/null +++ b/tests/test_elastic.py @@ -0,0 +1,36 @@ +from unittest.mock import MagicMock, patch +import datetime +import logging + +import pytest + +from sat.logs import ElasticClientHandler + + +@pytest.fixture +def log_stuff(request): + mock_client = MagicMock() + elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(request.node.name) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + return logger, mock_client + +def test_similarly_named_module_log_sent(log_stuff): + """ + Ensure that elastic module filtering only targets the elastic library, not similarly named files + + The ElasticClientHandler has a filter on it that ignores anything in the elastic module. + This is done to prevent an infinite recursion that would arise by the elastic library itself + making logging calls while processing a log message, infinitely recursing with more log calls. + This test file is named similarly to the elastic library, + to ensure that the filter is only targeting what we want it to target and not + client code/other modules that have names like `elastic` + """ + test_logger, mock_elastic_client = log_stuff + test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) + mock_elastic_client.index.assert_called() diff --git a/tests/test_elk_integration.py b/tests/test_elk_integration.py index c3216d0..c0b3cfc 100644 --- a/tests/test_elk_integration.py +++ b/tests/test_elk_integration.py @@ -9,23 +9,22 @@ @pytest.fixture def log_stuff(request): - with patch('sat.logs.bulk') as bulk_patch: - mock_client = MagicMock() - elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=1, batch_time=10.) - elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') - elastic_handler.setFormatter(test_formatter) - logger = logging.getLogger(request.node.name) - logger.setLevel(logging.INFO) - logger.addHandler(elastic_handler) + mock_client = MagicMock() + elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(request.node.name) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) - yield logger, mock_client, bulk_patch + return logger, mock_client def test_without_fixture(): mock_client = MagicMock() elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, - level=logging.INFO, batch_size=10, batch_time=10.) + level=logging.INFO) elastic_handler.setLevel(logging.INFO) test_formatter = logging.Formatter('%(message)s') elastic_handler.setFormatter(test_formatter) @@ -38,14 +37,14 @@ def test_without_fixture(): def test_log_sent(log_stuff): """Just assert that the bulk upload method is called if a single message is sent""" - test_logger, mock_elastic_client, bulk_patch = log_stuff + test_logger, mock_elastic_client = log_stuff test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) - bulk_patch.assert_called() + mock_elastic_client.index.assert_called() def test_extra_handling(log_stuff): - logger, mock_elastic_client, bulk_patch = log_stuff + logger, mock_elastic_client = log_stuff logger.info('test 3 message 1', extra={'cid': 'test 3 cid 1'}) @@ -54,43 +53,4 @@ def test_extra_handling(log_stuff): "log_message": "test 3 message 1", "cid": "test 3 cid 1" } - - bulk_patch.assert_called_with(mock_elastic_client, [expected_log_document]) - -def test_bulk_handler(): - - with patch('sat.logs.bulk') as bulk_patch: - mock_client = MagicMock() - elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=3, batch_time=1000.) - elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') - elastic_handler.setFormatter(test_formatter) - logger = logging.getLogger(__name__) - logger.setLevel(logging.INFO) - logger.addHandler(elastic_handler) - - logger.info('test_1') - logger.info('test_2') - bulk_patch.assert_not_called() - - logger.info('test_3') - bulk_patch.assert_called() - - - -def test_bulk_not_called(): - - with patch('sat.logs.bulk') as bulk_patch: - mock_client = MagicMock() - elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=10, batch_time=1000.) - elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') - elastic_handler.setFormatter(test_formatter) - logger = logging.getLogger(__name__) - logger.setLevel(logging.INFO) - logger.addHandler(elastic_handler) - - logger.info('test_1') - logger.info('test_2') - logger.info('test_3') - bulk_patch.assert_called() + mock_elastic_client.index.assert_called_with(index='test', document=expected_log_document) diff --git a/tests/test_logger.py b/tests/test_logger.py index 615c0c4..27f3d03 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -9,6 +9,7 @@ def test_default_logger(caplog): """Test the default logger""" from sat.logs import SATLogger + caplog.set_level(logging.INFO) logger = SATLogger() logger.info("Test message") @@ -22,6 +23,7 @@ def test_default_logger(caplog): @mock.patch.dict(os.environ, {"DEBUG": "1"}, clear=True) def test_debug_logger(caplog): """Test the debug logger""" + caplog.set_level(logging.DEBUG) from sat.logs import SATLogger logger = SATLogger() @@ -31,6 +33,7 @@ def test_debug_logger(caplog): def test_add_handlers(caplog): """Test adding handlers to the logger""" + caplog.set_level(logging.INFO) from sat.logs import SATLogger logger = SATLogger() From 1b7a0ba85df835e876e80fa655751c61798e3d80 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 14:01:01 -0400 Subject: [PATCH 11/17] Fix bulk tests --- sat/logs.py | 2 +- tests/test_bullk_elk.py | 95 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 96 insertions(+), 1 deletion(-) create mode 100644 tests/test_bullk_elk.py diff --git a/sat/logs.py b/sat/logs.py index 1ea277c..b326a62 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -209,7 +209,7 @@ def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict # Switching variable for using bulk, want to switch to single requests during shutdown to avoid weird # hanging issues caused by leaving elastic messages on the bulk queue - self._use_bulk = False + self._use_bulk = True def set_use_bulk(self, use_bulk): self._use_bulk = use_bulk diff --git a/tests/test_bullk_elk.py b/tests/test_bullk_elk.py new file mode 100644 index 0000000..fbe6203 --- /dev/null +++ b/tests/test_bullk_elk.py @@ -0,0 +1,95 @@ +from unittest.mock import MagicMock, patch +import datetime +import logging + +import pytest + +from sat.logs import ElasticClientBulkHandler + + +@pytest.fixture +def log_stuff(request): + with patch('sat.logs.bulk') as bulk_patch: + mock_client = MagicMock() + elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=1, batch_time=10.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(request.node.name) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + yield logger, mock_client, bulk_patch + logging.shutdown() + +def test_without_fixture(): + mock_client = MagicMock() + elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, + level=logging.INFO, batch_size=10, batch_time=10.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(__name__) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + logger.info('test 1 message 1') + logger.info('test 1 message 2') + +def test_log_sent(log_stuff): + """Just assert that the bulk upload method is called if a single message is sent""" + test_logger, mock_elastic_client, bulk_patch = log_stuff + test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) + bulk_patch.assert_called() + +def test_extra_handling(log_stuff): + + logger, mock_elastic_client, bulk_patch = log_stuff + + logger.info('test 3 message 1', extra={'cid': 'test 3 cid 1'}) + + expected_log_document = { + '_index': 'test', + 'app': 'test', + "log_message": "test 3 message 1", + "cid": "test 3 cid 1" + } + + bulk_patch.assert_called_with(mock_elastic_client, [expected_log_document]) + +def test_bulk_handler(): + + with patch('sat.logs.bulk') as bulk_patch: + mock_client = MagicMock() + elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=3, batch_time=1000.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(__name__) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + logger.info('test_1') + logger.info('test_2') + bulk_patch.assert_not_called() + + logger.info('test_3') + bulk_patch.assert_called() + + + +def test_bulk_not_called(): + + with patch('sat.logs.bulk') as bulk_patch: + mock_client = MagicMock() + elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=10, batch_time=1000.) + elastic_handler.setLevel(logging.INFO) + test_formatter = logging.Formatter('%(message)s') + elastic_handler.setFormatter(test_formatter) + logger = logging.getLogger(__name__) + logger.setLevel(logging.INFO) + logger.addHandler(elastic_handler) + + logger.info('test_1') + logger.info('test_2') + logger.info('test_3') + bulk_patch.assert_called() From dae9413badda8d5211b0ab07a2dbb3c2e8e90548 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 14:23:50 -0400 Subject: [PATCH 12/17] Add test coverage for setup from env variables Also removes deprecated shutdown exception hook craziness --- sat/logs.py | 38 ++++++++++++++++------------------- tests/test_elk_integration.py | 24 ++++++++++++++++++++-- 2 files changed, 39 insertions(+), 23 deletions(-) diff --git a/sat/logs.py b/sat/logs.py index b326a62..b51c008 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -101,30 +101,10 @@ def setup_sat_logging_with_defaults(): setup_sat_logging(elastic_client, elastic_index, app_name, enable_elastic_logging, log_level) -def shutdown_logging_on_exception(exc_type, exc_value, exc_traceback): - """Shuts down logger before calling normal exception handling - - This is required because if the ElasticClientHandler ends up having any other messages assigned to its queue - while the - - """ - root_logger = logging.getLogger() - elastic_handlers = [handler for handler in root_logger.handlers if isinstance(handler, ElasticClientBulkHandler)] - for elastic_handler in elastic_handlers: - elastic_handler.flush() - elastic_handler.set_use_bulk(False) - - - # logging.shutdown() - sys.__excepthook__(exc_type, exc_value, exc_traceback) - def setup_sat_logging_bulk(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO, batch_size: int=100, batch_time: float=2.): log_handlers = [logging.StreamHandler()] - # Set up custom exception hook - sys.excepthook = shutdown_logging_on_exception - if os.getenv('DEBUG'): loglevel = logging.DEBUG @@ -162,10 +142,16 @@ def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> return Elasticsearch( elastic_url, basic_auth=(username, password), - verify_certs=False + verify_certs=True ) class ElasticClientHandler(logging.Handler): + """ + Log Handler that sends logs directly to an elastic index + + Does this by making an index call at the point of every logging call, + if more throughput is needed use the Bulk Elastic handler + """ def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET): super().__init__(level) @@ -199,6 +185,16 @@ def emit(self, record): class ElasticClientBulkHandler(ElasticClientHandler): + """ + Log Handler that sends log messages to an elastic server. + + This handler uses batch methods to increase performance for applications with a lot of logs. + Using this handler requires a call to `logging.shutdown` in your application entrypoint somewhere; + the best way to implment that is using a `Try: Finally` block. + If the logger isn't closed (either manually or via logging.shutdown), + then the application might not be able to exit since the Elastic bulk + client will continue to run a keep-alive thread until it is explicitly closed. + """ def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET, batch_size: int=10, batch_time: float=5.): super().__init__(client, index_name, document_labels, level) diff --git a/tests/test_elk_integration.py b/tests/test_elk_integration.py index c0b3cfc..c3aa9eb 100644 --- a/tests/test_elk_integration.py +++ b/tests/test_elk_integration.py @@ -1,10 +1,10 @@ from unittest.mock import MagicMock, patch -import datetime +import os import logging import pytest -from sat.logs import ElasticClientHandler +from sat.logs import ElasticClientHandler, setup_sat_logging_with_defaults @pytest.fixture @@ -20,6 +20,26 @@ def log_stuff(request): return logger, mock_client +@patch.dict(os.environ, {"ELASTIC_ENABLE_LOGGING": "False"}, clear=True) +def test_default_setup_no_elastic(): + setup_sat_logging_with_defaults() + +@patch.dict(os.environ, {"ELASTIC_ENABLE_LOGGING": "True", 'ELASTIC_URL': 'test-url', + 'ELASTIC_USERNAME': 'test-user', + 'ELASTIC_INDEX': 'test-index', 'APP_NAME': 'test-app-name'}, clear=True) +def test_fails_when_missing_required_env(): + """When Elastic is enabled, but username isn't defined, setup should raise a key error""" + with pytest.raises(KeyError): + setup_sat_logging_with_defaults() + +@patch.dict(os.environ, {"ELASTIC_ENABLE_LOGGING": "True", 'ELASTIC_URL': 'test-url', + 'ELASTIC_USERNAME': 'test-user', 'ELASTIC_PASSWORD': 'test-pass', + 'ELASTIC_INDEX': 'test-index', 'APP_NAME': 'test-app-name'}, clear=True) +def test_default_setup_with_elastic(): + with patch('sat.logs.Elasticsearch') as elastic_mock: + setup_sat_logging_with_defaults() + elastic_mock.assert_called_with('test-url', basic_auth=('test-user', 'test-pass'), verify_certs=True) + def test_without_fixture(): mock_client = MagicMock() From 84c22baf25ff4e44dde51ba1a365b78336180a33 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 14:35:27 -0400 Subject: [PATCH 13/17] Improved documentation --- sat/logs.py | 24 ++++++++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/sat/logs.py b/sat/logs.py index b51c008..5fb644d 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -27,6 +27,15 @@ def __new__(cls, *args, **kwargs): class SATLogger(SingletonLoggerMixin): + """ + Logging wrapper for SAT applications. + + The purpose for the mixin is to enable a logging.basicConfig setup to be called a single time, + but to allow all the application files to continue to use the same logging setup syntax. + The singleton mixin will check to see if the setup function has already been called in the runtime, + and if not it calls the setup (initializing the Elastic logging handler and formatters). + """ + def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: self.logger = logging.getLogger(name) @@ -70,10 +79,21 @@ def filter(self, record): return top_module_name not in ['elastic', 'elastic_transport'] def setup_sat_logging_with_defaults(): - print('setting up sat logger with defaults') + """ + Sets up a basic logging config with an Elastic Client Handler using values from environment variables + + Depends on the following Environment Variables + ELASTIC_ENABLE_LOGGING: string value for booleans, `'True'` or `'False'`: Decides whether Elastic log handler + should be used, and also controls whether other needed configuration is checked for. Defaults to False + ELASTIC_URL: str: url for the Elastic server including protocol and port, e.g. `'https://elk.example.com:9200` + ELASTIC_USERNAME: str: elastic username + ELASTIC_PASSWORD: str: elastic password + ELASTIC_INDEX: str: Name of the index this app should log to + APP_NAME: str: Name of the app label included in the logs + """ - # Elastic loging feature flag defaults to false, don't want to blow up local development if no environment variables are set + # Elastic loging feature flag defaults to false, don't want to blow up local development or tests if no environment variables are set enable_elastic_string = os.getenv('ELASTIC_ENABLE_LOGGING', '') if enable_elastic_string.lower() == 'true': enable_elastic_logging = True From 2a124781e7e5fd133dffe66bccefce46a4bf8139 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 14:44:00 -0400 Subject: [PATCH 14/17] Bump library version --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 63ecf3b..392827a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "flit_core.buildapi" [project] name = "sat-utils" -version = "1.6.0" +version = "1.7.0" authors = [ { name="Ryan Semmler", email="rsemmle@ncsu.edu" }, { name="Shawn Taylor", email="staylor8@ncsu.edu" }, From e4a7e97308c19599eac55c292b5b9861bb779342 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 14:45:26 -0400 Subject: [PATCH 15/17] Improve docstring, run linting --- tests/test_elk_integration.py | 73 +++++++++++++++++++++++------------ 1 file changed, 48 insertions(+), 25 deletions(-) diff --git a/tests/test_elk_integration.py b/tests/test_elk_integration.py index c3aa9eb..def1b47 100644 --- a/tests/test_elk_integration.py +++ b/tests/test_elk_integration.py @@ -1,18 +1,19 @@ -from unittest.mock import MagicMock, patch -import os import logging +import os +from unittest.mock import MagicMock, patch import pytest - from sat.logs import ElasticClientHandler, setup_sat_logging_with_defaults @pytest.fixture def log_stuff(request): mock_client = MagicMock() - elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO) + elastic_handler = ElasticClientHandler( + client=mock_client, index_name="test", document_labels={"app": "test"}, level=logging.INFO + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(request.node.name) logger.setLevel(logging.INFO) @@ -20,57 +21,79 @@ def log_stuff(request): return logger, mock_client + @patch.dict(os.environ, {"ELASTIC_ENABLE_LOGGING": "False"}, clear=True) def test_default_setup_no_elastic(): setup_sat_logging_with_defaults() -@patch.dict(os.environ, {"ELASTIC_ENABLE_LOGGING": "True", 'ELASTIC_URL': 'test-url', - 'ELASTIC_USERNAME': 'test-user', - 'ELASTIC_INDEX': 'test-index', 'APP_NAME': 'test-app-name'}, clear=True) + +@patch.dict( + os.environ, + { + "ELASTIC_ENABLE_LOGGING": "True", + "ELASTIC_URL": "test-url", + "ELASTIC_USERNAME": "test-user", + "ELASTIC_INDEX": "test-index", + "APP_NAME": "test-app-name", + }, + clear=True, +) def test_fails_when_missing_required_env(): - """When Elastic is enabled, but username isn't defined, setup should raise a key error""" + """When Elastic is enabled but username isn't defined, setup should raise a key error""" with pytest.raises(KeyError): setup_sat_logging_with_defaults() -@patch.dict(os.environ, {"ELASTIC_ENABLE_LOGGING": "True", 'ELASTIC_URL': 'test-url', - 'ELASTIC_USERNAME': 'test-user', 'ELASTIC_PASSWORD': 'test-pass', - 'ELASTIC_INDEX': 'test-index', 'APP_NAME': 'test-app-name'}, clear=True) + +@patch.dict( + os.environ, + { + "ELASTIC_ENABLE_LOGGING": "True", + "ELASTIC_URL": "test-url", + "ELASTIC_USERNAME": "test-user", + "ELASTIC_PASSWORD": "test-pass", + "ELASTIC_INDEX": "test-index", + "APP_NAME": "test-app-name", + }, + clear=True, +) def test_default_setup_with_elastic(): - with patch('sat.logs.Elasticsearch') as elastic_mock: + with patch("sat.logs.Elasticsearch") as elastic_mock: setup_sat_logging_with_defaults() - elastic_mock.assert_called_with('test-url', basic_auth=('test-user', 'test-pass'), verify_certs=True) + elastic_mock.assert_called_with( + "test-url", basic_auth=("test-user", "test-pass"), verify_certs=True + ) def test_without_fixture(): mock_client = MagicMock() - elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, - level=logging.INFO) + elastic_handler = ElasticClientHandler( + client=mock_client, index_name="test", document_labels={"app": "test"}, level=logging.INFO + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) logger.addHandler(elastic_handler) - logger.info('test 1 message 1') - logger.info('test 1 message 2') + logger.info("test 1 message 1") + logger.info("test 1 message 2") def test_log_sent(log_stuff): """Just assert that the bulk upload method is called if a single message is sent""" test_logger, mock_elastic_client = log_stuff - test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) + test_logger.info("test 2 message 1", extra={"cid": "test-cid"}) mock_elastic_client.index.assert_called() def test_extra_handling(log_stuff): - logger, mock_elastic_client = log_stuff - logger.info('test 3 message 1', extra={'cid': 'test 3 cid 1'}) + logger.info("test 3 message 1", extra={"cid": "test 3 cid 1"}) expected_log_document = { - 'app': 'test', + "app": "test", "log_message": "test 3 message 1", - "cid": "test 3 cid 1" + "cid": "test 3 cid 1", } - mock_elastic_client.index.assert_called_with(index='test', document=expected_log_document) + mock_elastic_client.index.assert_called_with(index="test", document=expected_log_document) From 00be126428d4da4176096c242272ac8b12d0f554 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 15:10:59 -0400 Subject: [PATCH 16/17] remove ehps pypi index that was automatically added by pip-utils --- requirements/base/base.txt | 1 - requirements/dev/dev.txt | 1 - 2 files changed, 2 deletions(-) diff --git a/requirements/base/base.txt b/requirements/base/base.txt index 1d50e11..dc493ed 100644 --- a/requirements/base/base.txt +++ b/requirements/base/base.txt @@ -4,7 +4,6 @@ # # pip-compile --output-file=requirements/base/base.txt pyproject.toml # ---extra-index-url https://pypi.ehps.ncsu.edu/ annotated-types==0.6.0 # via pydantic diff --git a/requirements/dev/dev.txt b/requirements/dev/dev.txt index 8633f5c..e011f22 100644 --- a/requirements/dev/dev.txt +++ b/requirements/dev/dev.txt @@ -4,7 +4,6 @@ # # pip-compile --extra=dev --output-file=requirements/dev/dev.txt pyproject.toml # ---extra-index-url https://pypi.ehps.ncsu.edu/ aiofiles==22.1.0 # via ypy-websocket From e08b2aabb967256dfac97c52ef266562a52b4dd5 Mon Sep 17 00:00:00 2001 From: Edward Brennan Date: Thu, 31 Oct 2024 15:19:41 -0400 Subject: [PATCH 17/17] Manually run pre-commit hooks --- sat/logs.py | 149 +++++++++++++++++++++++++--------------- sat/slack.py | 1 - tests/test_bullk_elk.py | 89 +++++++++++++++--------- tests/test_elastic.py | 13 ++-- tests/test_logger.py | 1 + tests/test_slack.py | 3 +- 6 files changed, 161 insertions(+), 95 deletions(-) diff --git a/sat/logs.py b/sat/logs.py index 5fb644d..9ba1112 100644 --- a/sat/logs.py +++ b/sat/logs.py @@ -1,22 +1,18 @@ import logging import os -from unittest.mock import MagicMock import time -import sys -from collections import deque -from elasticsearch import Elasticsearch, BadRequestError +from elasticsearch import BadRequestError, Elasticsearch from elasticsearch.helpers import bulk logger = logging.getLogger(__name__) -class SingletonLoggerMixin(object): +class SingletonLoggerMixin: _instance = None client_mock = None def __new__(cls, *args, **kwargs): - # Only call this setup block the first time a SATLoggerSingleton is instantiated # Prevents multiple setup function calls if not isinstance(cls._instance, cls): @@ -32,8 +28,9 @@ class SATLogger(SingletonLoggerMixin): The purpose for the mixin is to enable a logging.basicConfig setup to be called a single time, but to allow all the application files to continue to use the same logging setup syntax. - The singleton mixin will check to see if the setup function has already been called in the runtime, - and if not it calls the setup (initializing the Elastic logging handler and formatters). + The singleton mixin will check to see if the setup function has already been called in the + runtime, and if not it calls the setup + (initializing the Elastic logging handler and formatters). """ def __init__(self, name: str = __name__, level: int = logging.INFO) -> None: @@ -46,7 +43,10 @@ def add_handlers(self, handlers: list[(logging.Handler, logging.Formatter)]) -> optional logging.Formatter. """ - self.logger.warning('Adding handlers to this instance of the logger only, will not persist throughout project. Update logging config to persist changes.') + self.logger.warning( + "Adding handlers to this instance of the logger only, " + "will not persist throughout project. Update logging config to persist changes." + ) for tup in handlers: handler, formatter = tup @@ -73,97 +73,119 @@ def critical(self, msg: str, *args, **kwargs) -> None: class ElasticModuleFilter(logging.Filter): - def filter(self, record): - top_module_name = record.name.split('.')[0] - return top_module_name not in ['elastic', 'elastic_transport'] + top_module_name = record.name.split(".")[0] + return top_module_name not in ["elastic", "elastic_transport"] + def setup_sat_logging_with_defaults(): """ - Sets up a basic logging config with an Elastic Client Handler using values from environment variables + Sets up a basic logging config with an Elastic Client Handler using values + from environment variables Depends on the following Environment Variables - ELASTIC_ENABLE_LOGGING: string value for booleans, `'True'` or `'False'`: Decides whether Elastic log handler - should be used, and also controls whether other needed configuration is checked for. Defaults to False + ELASTIC_ENABLE_LOGGING: string value for booleans, + `'True'` or `'False'`: Decides whether Elastic log handler + should be used, and also controls whether other needed configuration is checked for. + Defaults to False - ELASTIC_URL: str: url for the Elastic server including protocol and port, e.g. `'https://elk.example.com:9200` + ELASTIC_URL: str: url for the Elastic server including protocol and port, + e.g. `'https://elk.example.com:9200` ELASTIC_USERNAME: str: elastic username ELASTIC_PASSWORD: str: elastic password ELASTIC_INDEX: str: Name of the index this app should log to APP_NAME: str: Name of the app label included in the logs """ - # Elastic loging feature flag defaults to false, don't want to blow up local development or tests if no environment variables are set - enable_elastic_string = os.getenv('ELASTIC_ENABLE_LOGGING', '') - if enable_elastic_string.lower() == 'true': + # Elastic loging feature flag defaults to false, don't want to blow up + # local development or tests if no environment variables are set + enable_elastic_string = os.getenv("ELASTIC_ENABLE_LOGGING", "") + if enable_elastic_string.lower() == "true": enable_elastic_logging = True else: - logger.warning('Elastic logging disabled, continuing without') + logger.warning("Elastic logging disabled, continuing without") enable_elastic_logging = False if enable_elastic_logging: - elastic_url = os.environ['ELASTIC_URL'] - elastic_username = os.environ['ELASTIC_USERNAME'] - elastic_password = os.environ['ELASTIC_PASSWORD'] - elastic_index = os.environ['ELASTIC_INDEX'] - app_name = os.environ['APP_NAME'] + elastic_url = os.environ["ELASTIC_URL"] + elastic_username = os.environ["ELASTIC_USERNAME"] + elastic_password = os.environ["ELASTIC_PASSWORD"] + elastic_index = os.environ["ELASTIC_INDEX"] + app_name = os.environ["APP_NAME"] elastic_client = get_elasticsearch_client(elastic_url, elastic_username, elastic_password) else: - app_name = os.getenv('APP_NAME') # If logging without elastic enabled, APP_NAME is optional + app_name = os.getenv("APP_NAME") # If logging without elastic enabled, APP_NAME is optional elastic_client = None elastic_index = None - - log_level_string = os.getenv('LOGLEVEL', 'INFO') + log_level_string = os.getenv("LOGLEVEL", "INFO") log_level = getattr(logging, log_level_string.upper()) - setup_sat_logging(elastic_client, elastic_index, app_name, enable_elastic_logging, log_level) -def setup_sat_logging_bulk(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO, batch_size: int=100, batch_time: float=2.): - +def setup_sat_logging_bulk( + client: Elasticsearch, + index_name: str, + app_name: str, + enable_elastic_logging, + loglevel: int = logging.INFO, + batch_size: int = 100, + batch_time: float = 2.0, +): log_handlers = [logging.StreamHandler()] - if os.getenv('DEBUG'): + if os.getenv("DEBUG"): loglevel = logging.DEBUG if enable_elastic_logging: - elastic_handler = ElasticClientBulkHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel, batch_size=batch_size, batch_time=batch_time) + elastic_handler = ElasticClientBulkHandler( + client, + index_name=index_name, + document_labels={"app": app_name}, + level=loglevel, + batch_size=batch_size, + batch_time=batch_time, + ) elastic_handler.addFilter(ElasticModuleFilter()) log_handlers.append(elastic_handler) logging.basicConfig( level=loglevel, format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", - handlers=log_handlers + handlers=log_handlers, ) -def setup_sat_logging(client: Elasticsearch, index_name: str, app_name: str, enable_elastic_logging, loglevel: int = logging.INFO): +def setup_sat_logging( + client: Elasticsearch, + index_name: str, + app_name: str, + enable_elastic_logging, + loglevel: int = logging.INFO, +): log_handlers = [logging.StreamHandler()] - if os.getenv('DEBUG'): + if os.getenv("DEBUG"): loglevel = logging.DEBUG if enable_elastic_logging: - elastic_handler = ElasticClientHandler(client, index_name=index_name, document_labels={"app": app_name}, level=loglevel) + elastic_handler = ElasticClientHandler( + client, index_name=index_name, document_labels={"app": app_name}, level=loglevel + ) elastic_handler.addFilter(ElasticModuleFilter()) log_handlers.append(elastic_handler) logging.basicConfig( level=loglevel, format="%(asctime)s - %(name)s - %(levelname)s - %(message)s", - handlers=log_handlers + handlers=log_handlers, ) def get_elasticsearch_client(elastic_url: str, username: str, password: str) -> Elasticsearch: - return Elasticsearch( - elastic_url, - basic_auth=(username, password), - verify_certs=True - ) + return Elasticsearch(elastic_url, basic_auth=(username, password), verify_certs=True) + class ElasticClientHandler(logging.Handler): """ @@ -173,12 +195,21 @@ class ElasticClientHandler(logging.Handler): if more throughput is needed use the Bulk Elastic handler """ - def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET): + def __init__( + self, + client: Elasticsearch, + index_name: str, + document_labels: dict = None, + level=logging.NOTSET, + ): super().__init__(level) self.client = client self.index_name = index_name self.document_labels = document_labels - self.addFilter(ElasticModuleFilter()) # Need a filter here to prevent the elasticsearch module from recursively sending logging calls + self.addFilter( + ElasticModuleFilter() + ) # Need a filter here to prevent the elasticsearch module + # from recursively sending logging calls # Create index if none exists try: @@ -188,7 +219,7 @@ def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict def emit(self, record): formatted_data = self.format(record) - logger.debug('Elastic handler emitting') + logger.debug("Elastic handler emitting") # Explicitly handle messages where a CID field is not provided try: @@ -209,21 +240,31 @@ class ElasticClientBulkHandler(ElasticClientHandler): Log Handler that sends log messages to an elastic server. This handler uses batch methods to increase performance for applications with a lot of logs. - Using this handler requires a call to `logging.shutdown` in your application entrypoint somewhere; + Using this handler requires a call to `logging.shutdown` + in your application entrypoint somewhere; the best way to implment that is using a `Try: Finally` block. If the logger isn't closed (either manually or via logging.shutdown), then the application might not be able to exit since the Elastic bulk client will continue to run a keep-alive thread until it is explicitly closed. """ - def __init__(self, client: Elasticsearch, index_name: str, document_labels: dict = None, level=logging.NOTSET, batch_size: int=10, batch_time: float=5.): + def __init__( + self, + client: Elasticsearch, + index_name: str, + document_labels: dict = None, + level=logging.NOTSET, + batch_size: int = 10, + batch_time: float = 5.0, + ): super().__init__(client, index_name, document_labels, level) self.batch_size = batch_size self.batch_time = batch_time self._queue = [] self._batch_start_time = time.time() - # Switching variable for using bulk, want to switch to single requests during shutdown to avoid weird + # Switching variable for using bulk, want to switch to single + # requests during shutdown to avoid weird # hanging issues caused by leaving elastic messages on the bulk queue self._use_bulk = True @@ -232,7 +273,7 @@ def set_use_bulk(self, use_bulk): def emit(self, record): formatted_data = self.format(record) - logger.debug('Elastic handler emitting') + logger.debug("Elastic handler emitting") # Explicitly handle messages where a CID field is not provided try: @@ -246,7 +287,7 @@ def emit(self, record): document.update(self.document_labels) if self._use_bulk: - document.update({'_index': self.index_name}) + document.update({"_index": self.index_name}) self._queue.append(document) if len(self._queue) >= self.batch_size: @@ -257,16 +298,16 @@ def emit(self, record): self.client.index(index=self.index_name, document=document) def flush(self): - logger.debug('Flushing') + logger.debug("Flushing") if self._queue and self._use_bulk: bulk(self.client, self._queue) - logger.debug('Finished uploading to elastic') + logger.debug("Finished uploading to elastic") self._queue = [] self._batch_start_time = time.time() super().flush() def close(self): - logger.debug('Closing') + logger.debug("Closing") self.flush() self.client.close() super().close() diff --git a/sat/slack.py b/sat/slack.py index effdc2e..731db3c 100644 --- a/sat/slack.py +++ b/sat/slack.py @@ -3,7 +3,6 @@ from slack_sdk import WebClient from slack_sdk.errors import SlackApiError - logger = logging.getLogger(__name__) diff --git a/tests/test_bullk_elk.py b/tests/test_bullk_elk.py index fbe6203..38058ab 100644 --- a/tests/test_bullk_elk.py +++ b/tests/test_bullk_elk.py @@ -1,19 +1,24 @@ -from unittest.mock import MagicMock, patch -import datetime import logging +from unittest.mock import MagicMock, patch import pytest - from sat.logs import ElasticClientBulkHandler @pytest.fixture def log_stuff(request): - with patch('sat.logs.bulk') as bulk_patch: + with patch("sat.logs.bulk") as bulk_patch: mock_client = MagicMock() - elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=1, batch_time=10.) + elastic_handler = ElasticClientBulkHandler( + client=mock_client, + index_name="test", + document_labels={"app": "test"}, + level=logging.INFO, + batch_size=1, + batch_time=10.0, + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(request.node.name) logger.setLevel(logging.INFO) @@ -22,74 +27,94 @@ def log_stuff(request): yield logger, mock_client, bulk_patch logging.shutdown() + def test_without_fixture(): mock_client = MagicMock() - elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, - level=logging.INFO, batch_size=10, batch_time=10.) + elastic_handler = ElasticClientBulkHandler( + client=mock_client, + index_name="test", + document_labels={"app": "test"}, + level=logging.INFO, + batch_size=10, + batch_time=10.0, + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) logger.addHandler(elastic_handler) - logger.info('test 1 message 1') - logger.info('test 1 message 2') + logger.info("test 1 message 1") + logger.info("test 1 message 2") + def test_log_sent(log_stuff): """Just assert that the bulk upload method is called if a single message is sent""" test_logger, mock_elastic_client, bulk_patch = log_stuff - test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) + test_logger.info("test 2 message 1", extra={"cid": "test-cid"}) bulk_patch.assert_called() -def test_extra_handling(log_stuff): +def test_extra_handling(log_stuff): logger, mock_elastic_client, bulk_patch = log_stuff - logger.info('test 3 message 1', extra={'cid': 'test 3 cid 1'}) + logger.info("test 3 message 1", extra={"cid": "test 3 cid 1"}) expected_log_document = { - '_index': 'test', - 'app': 'test', + "_index": "test", + "app": "test", "log_message": "test 3 message 1", - "cid": "test 3 cid 1" + "cid": "test 3 cid 1", } bulk_patch.assert_called_with(mock_elastic_client, [expected_log_document]) -def test_bulk_handler(): - with patch('sat.logs.bulk') as bulk_patch: +def test_bulk_handler(): + with patch("sat.logs.bulk") as bulk_patch: mock_client = MagicMock() - elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=3, batch_time=1000.) + elastic_handler = ElasticClientBulkHandler( + client=mock_client, + index_name="test", + document_labels={"app": "test"}, + level=logging.INFO, + batch_size=3, + batch_time=1000.0, + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) logger.addHandler(elastic_handler) - logger.info('test_1') - logger.info('test_2') + logger.info("test_1") + logger.info("test_2") bulk_patch.assert_not_called() - logger.info('test_3') + logger.info("test_3") bulk_patch.assert_called() - def test_bulk_not_called(): - - with patch('sat.logs.bulk') as bulk_patch: + with patch("sat.logs.bulk") as bulk_patch: mock_client = MagicMock() - elastic_handler = ElasticClientBulkHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO, batch_size=10, batch_time=1000.) + elastic_handler = ElasticClientBulkHandler( + client=mock_client, + index_name="test", + document_labels={"app": "test"}, + level=logging.INFO, + batch_size=10, + batch_time=1000.0, + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) logger.addHandler(elastic_handler) - logger.info('test_1') - logger.info('test_2') - logger.info('test_3') + logger.info("test_1") + logger.info("test_2") + logger.info("test_3") bulk_patch.assert_called() diff --git a/tests/test_elastic.py b/tests/test_elastic.py index 316ed2f..2138e16 100644 --- a/tests/test_elastic.py +++ b/tests/test_elastic.py @@ -1,18 +1,18 @@ -from unittest.mock import MagicMock, patch -import datetime import logging +from unittest.mock import MagicMock import pytest - from sat.logs import ElasticClientHandler @pytest.fixture def log_stuff(request): mock_client = MagicMock() - elastic_handler = ElasticClientHandler(client=mock_client, index_name='test', document_labels={'app': 'test'}, level=logging.INFO) + elastic_handler = ElasticClientHandler( + client=mock_client, index_name="test", document_labels={"app": "test"}, level=logging.INFO + ) elastic_handler.setLevel(logging.INFO) - test_formatter = logging.Formatter('%(message)s') + test_formatter = logging.Formatter("%(message)s") elastic_handler.setFormatter(test_formatter) logger = logging.getLogger(request.node.name) logger.setLevel(logging.INFO) @@ -20,6 +20,7 @@ def log_stuff(request): return logger, mock_client + def test_similarly_named_module_log_sent(log_stuff): """ Ensure that elastic module filtering only targets the elastic library, not similarly named files @@ -32,5 +33,5 @@ def test_similarly_named_module_log_sent(log_stuff): client code/other modules that have names like `elastic` """ test_logger, mock_elastic_client = log_stuff - test_logger.info('test 2 message 1', extra={'cid': 'test-cid'}) + test_logger.info("test 2 message 1", extra={"cid": "test-cid"}) mock_elastic_client.index.assert_called() diff --git a/tests/test_logger.py b/tests/test_logger.py index 27f3d03..7c6d819 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -9,6 +9,7 @@ def test_default_logger(caplog): """Test the default logger""" from sat.logs import SATLogger + caplog.set_level(logging.INFO) logger = SATLogger() diff --git a/tests/test_slack.py b/tests/test_slack.py index 68229fc..1a957ee 100644 --- a/tests/test_slack.py +++ b/tests/test_slack.py @@ -1,8 +1,7 @@ import logging -from unittest.mock import patch, MagicMock +from unittest.mock import patch from sat.slack import Slack, SlackApiError -from sat.logs import setup_sat_logging def mock_slack_response():