diff --git a/.github/workflows/ci.yaml b/.github/workflows/ci.yaml index 2b8ec6b..dfa7a86 100644 --- a/.github/workflows/ci.yaml +++ b/.github/workflows/ci.yaml @@ -2,11 +2,11 @@ name: CI on: push: - branches: [main] - tags: [v*.*.*] + branches: [ main ] + tags: [ v*.*.* ] pull_request: - branches: [ "main" ] + branches: [ main ] types: - synchronize - opened diff --git a/context_logger/filter.py b/context_logger/filter.py index e73fc3c..2ecc018 100644 --- a/context_logger/filter.py +++ b/context_logger/filter.py @@ -5,14 +5,16 @@ import socket from importlib.metadata import version, PackageNotFoundError from logging import Filter, LogRecord +from typing import Any class ContextSetupFilter(Filter): - def __init__(self, application_name: str, message_field: str): + def __init__(self, application_name: str, message_field: str, global_context: dict[str, Any] | None = None): super().__init__() self._application_name = application_name self._message_field = message_field + self._global_context = global_context if global_context else {} def filter(self, record: LogRecord) -> bool: try: @@ -26,6 +28,11 @@ def filter(self, record: LogRecord) -> bool: if 'process_name' in record.msg: record.msg['process_name'] = record.processName + + for key, value in self._global_context.items(): + if key not in record.msg: + record.msg[key] = str(value) + except Exception as exception: print('Failed to handle log record:', exception) diff --git a/context_logger/logger.py b/context_logger/logger.py index effe98a..6e6714f 100644 --- a/context_logger/logger.py +++ b/context_logger/logger.py @@ -27,7 +27,8 @@ def get_logger(logger_name: str) -> Any: def setup_logging(application_name: str, log_level: str = 'INFO', log_file_path: Optional[str] = None, max_bytes: int = 1024 * 1024, backup_count: int = 5, - add_call_info: bool = False, warn_on_overwrite: bool = True, message_field: str = 'message') -> None: + add_call_info: bool = False, warn_on_overwrite: bool = True, message_field: str = 'message', + global_context: dict[str, Any] | None = None) -> None: global LOGGER if LOGGER: @@ -36,7 +37,8 @@ def setup_logging(application_name: str, log_level: str = 'INFO', LOGGER.cleanup() - LOGGER = Logger(application_name, log_level, log_file_path, max_bytes, backup_count, add_call_info, message_field) + LOGGER = Logger(application_name, log_level, log_file_path, max_bytes, backup_count, add_call_info, message_field, + global_context) LOGGER.setup() @@ -44,14 +46,16 @@ def setup_logging(application_name: str, log_level: str = 'INFO', class Logger(object): def __init__(self, application_name: str, log_level: str, log_file_path: Optional[str], max_bytes: int, - backup_count: int, add_call_info: bool, message_field: str) -> None: + backup_count: int, add_call_info: bool, message_field: str, + global_context: dict[str, Any] | None = None) -> None: self._application_name = application_name self._log_level = logging.getLevelName(log_level.upper()) self._log_file_path = log_file_path self._max_bytes = max_bytes self._backup_count = backup_count - self._message_field = message_field self._add_call_info = add_call_info + self._message_field = message_field + self._global_context = global_context self._handlers: list[Handler] = [] def setup(self) -> None: @@ -131,7 +135,7 @@ def _create_console_handler(self) -> Handler: handler = logging.StreamHandler(sys.stdout) handler.setFormatter(formatter) - handler.addFilter(ContextSetupFilter(self._application_name, self._message_field)) + handler.addFilter(ContextSetupFilter(self._application_name, self._message_field, self._global_context)) return handler @@ -146,7 +150,7 @@ def _create_file_handler(self, log_file_path: str) -> RotatingFileHandler: handler = RotatingFileHandler(log_file_path, maxBytes=self._max_bytes, backupCount=self._backup_count) handler.setFormatter(formatter) - handler.addFilter(ContextSetupFilter(self._application_name, self._message_field)) + handler.addFilter(ContextSetupFilter(self._application_name, self._message_field, self._global_context)) return handler diff --git a/pyproject.toml b/pyproject.toml new file mode 100644 index 0000000..11e0208 --- /dev/null +++ b/pyproject.toml @@ -0,0 +1,33 @@ +[project] +name = "python-context-logger" +description = "Contextual structured logging library for Python" +authors = [ + { name = "Ferenc Nandor Janky & Attila Gombos", email = "info@effective-range.com" } +] +maintainers = [ + { name = "Ferenc Nandor Janky & Attila Gombos", email = "info@effective-range.com" } +] +dependencies = [ + "structlog" +] +dynamic = ["version"] + +[tool.setuptools] +package-dir = {"" = "."} +packages = ["context_logger"] + +[tool.setuptools.package-data] +hello = ["py.typed"] + +[build-system] +requires = ["setuptools>=61", "setuptools_scm"] +build-backend = "setuptools.build_meta" + +[tool.setuptools_scm] +version_scheme = "guess-next-dev" +local_scheme = "node-and-date" + +[tool.pytest] +addopts = ["--verbose", "--capture=no"] +python_files = ["*Test.py"] +python_classes = ["*Test"] diff --git a/setup.cfg b/setup.cfg index b5d31c3..5451f94 100644 --- a/setup.cfg +++ b/setup.cfg @@ -1,3 +1,8 @@ +[pack-python] +packaging = + wheel + fpm-deb + [mypy] packages = context_logger strict = True @@ -22,6 +27,7 @@ python_classes = *Test [coverage:run] relative_files = true branch = True +source = context_logger [coverage:report] ; Regexes for lines to exclude from consideration @@ -49,8 +55,3 @@ directory = coverage/html [coverage:json] output = coverage/coverage.json - -[pack-python] -packaging = - wheel - fpm-deb diff --git a/setup.py b/setup.py deleted file mode 100644 index 58970e5..0000000 --- a/setup.py +++ /dev/null @@ -1,13 +0,0 @@ -from setuptools import setup - -setup( - name='python-context-logger', - description='Contextual structured logging library for Python', - author='Ferenc Nandor Janky & Attila Gombos', - author_email='info@effective-range.com', - packages=['context_logger'], - package_data={'context_logger': ['py.typed']}, - use_scm_version=True, - setup_requires=["setuptools_scm"], - install_requires=['structlog'] -) diff --git a/tests/filterTest.py b/tests/filterTest.py new file mode 100644 index 0000000..9f2395a --- /dev/null +++ b/tests/filterTest.py @@ -0,0 +1,100 @@ +import logging +import unittest +from importlib.metadata import PackageNotFoundError +from unittest import TestCase +from unittest.mock import patch + +from context_logger.filter import ContextSetupFilter + + +class FilterTest(TestCase): + + def test_filter_enriches_string_message_and_context(self): + # Given + filter_ = ContextSetupFilter('example-app', 'message', + global_context={'team': 'platform', 'application': 'ignored'}) + record = logging.LogRecord('ExampleClass', logging.INFO, __file__, 10, 'Hello %s', ('World',), None) + + with patch('context_logger.filter.socket.gethostname', return_value='test-host'), \ + patch.object(filter_, '_get_application_version', return_value='1.2.3'): + # When + result = filter_.filter(record) + + # Then + self.assertTrue(result) + self.assertEqual((), record.args) + self.assertEqual('Hello World', record.msg.get('message')) + self.assertEqual('test-host', record.msg.get('hostname')) + self.assertEqual('example-app', record.msg.get('application')) + self.assertEqual('1.2.3', record.msg.get('app_version')) + self.assertEqual('platform', record.msg.get('team')) + + def test_filter_updates_process_name_when_key_exists(self): + # Given + filter_ = ContextSetupFilter('example-app', 'message') + record = logging.LogRecord('ExampleClass', logging.INFO, __file__, 10, {'message': 'ok', 'process_name': 'x'}, + (), None) + + with patch('context_logger.filter.socket.gethostname', return_value='test-host'), \ + patch.object(filter_, '_get_application_version', return_value='1.2.3'): + # When + filter_.filter(record) + + # Then + self.assertEqual(record.processName, record.msg.get('process_name')) + + def test_filter_handles_string_format_error(self): + # Given + filter_ = ContextSetupFilter('example-app', 'message') + record = logging.LogRecord('ExampleClass', logging.INFO, __file__, 10, 'broken %s %s', ('format',), None) + + with patch('builtins.print') as print_mock: + # When + result = filter_.filter(record) + + # Then + self.assertTrue(result) + self.assertEqual('broken %s %s', record.msg) + print_mock.assert_called_once() + self.assertEqual('Failed to handle log record:', print_mock.call_args.args[0]) + + def test_filter_handles_non_mapping_message(self): + # Given + filter_ = ContextSetupFilter('example-app', 'message') + record = logging.LogRecord('ExampleClass', logging.INFO, __file__, 10, 123, (), None) + + with patch('builtins.print') as print_mock: + # When + result = filter_.filter(record) + + # Then + self.assertTrue(result) + self.assertEqual(123, record.msg) + print_mock.assert_called_once() + self.assertEqual('Failed to handle log record:', print_mock.call_args.args[0]) + + def test_get_application_version_returns_package_version(self): + # Given + filter_ = ContextSetupFilter('example-app', 'message') + + with patch('context_logger.filter.version', return_value='9.9.9'): + # When + version = filter_._get_application_version() + + # Then + self.assertEqual('9.9.9', version) + + def test_get_application_version_returns_none_when_package_is_missing(self): + # Given + filter_ = ContextSetupFilter('missing-package', 'message') + + with patch('context_logger.filter.version', side_effect=PackageNotFoundError): + # When + version = filter_._get_application_version() + + # Then + self.assertEqual('none', version) + + +if __name__ == '__main__': + unittest.main() diff --git a/tests/loggerFallbackTest.py b/tests/loggerFallbackTest.py new file mode 100644 index 0000000..4d504ba --- /dev/null +++ b/tests/loggerFallbackTest.py @@ -0,0 +1,138 @@ +import logging +import unittest +from unittest import TestCase +from unittest.mock import MagicMock, patch + +from context_logger.logger import Logger, setup_logging + + +class _LegacyProcessorFormatter: + def __init__(self, *args, **kwargs): + self.args = args + self.kwargs = kwargs + + # Simulate old API: no `processors` support. + if 'processors' in kwargs: + raise AttributeError('processors is not supported') + + +class LoggerFallbackTest(TestCase): + + def test_setup_logging_warns_and_cleans_up_on_overwrite(self): + # Given + previous_logger = MagicMock() + replacement_logger = MagicMock() + + with patch('context_logger.logger.LOGGER', previous_logger), \ + patch('context_logger.logger.Logger', return_value=replacement_logger) as logger_ctor, \ + patch('context_logger.logger.warnings.warn') as warn_mock: + # When + setup_logging('example-app') + + # Then + warn_mock.assert_called_once() + previous_logger.cleanup.assert_called_once() + logger_ctor.assert_called_once() + replacement_logger.setup.assert_called_once() + + def test_setup_logging_skips_warning_when_warn_on_overwrite_is_false(self): + # Given + previous_logger = MagicMock() + replacement_logger = MagicMock() + + with patch('context_logger.logger.LOGGER', previous_logger), \ + patch('context_logger.logger.Logger', return_value=replacement_logger), \ + patch('context_logger.logger.warnings.warn') as warn_mock: + # When + setup_logging('example-app', warn_on_overwrite=False) + + # Then + warn_mock.assert_not_called() + previous_logger.cleanup.assert_called_once() + replacement_logger.setup.assert_called_once() + + def test_setup_processors_ignores_missing_event_renamer(self): + # Given + logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message') + + with patch('context_logger.logger.structlog.processors.EventRenamer', side_effect=AttributeError): + # When + logger._setup_processors() + + # Then + self.assertIsInstance(logger._shared_processors, list) + self.assertGreater(len(logger._shared_processors), 0) + + def test_setup_processors_ignores_missing_callsite_parameter_adder(self): + # Given + logger = Logger('example-app', 'INFO', None, 1024, 1, True, 'message') + + with patch('context_logger.logger.structlog.processors.CallsiteParameterAdder', side_effect=AttributeError): + # When + logger._setup_processors() + + # Then + self.assertIsInstance(logger._shared_processors, list) + self.assertGreater(len(logger._shared_processors), 0) + + def test_create_console_handler_uses_legacy_formatter_fallback(self): + # Given + logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message') + logger._shared_processors = [] + + with patch('context_logger.logger.ProcessorFormatter', _LegacyProcessorFormatter): + # When + handler = logger._create_console_handler() + + # Then + self.assertIsInstance(handler, logging.Handler) + self.assertIn('processor', handler.formatter.kwargs) + + def test_create_file_handler_uses_legacy_formatter_fallback(self): + # Given + logger = Logger('example-app', 'INFO', '/tmp/unused.log', 1024, 1, False, 'message') + logger._shared_processors = [] + + fake_handler = MagicMock() + fake_handler.setFormatter = MagicMock() + fake_handler.addFilter = MagicMock() + + with patch('context_logger.logger.ProcessorFormatter', _LegacyProcessorFormatter), \ + patch.object(Logger, '_ensure_directory_exists') as ensure_directory_mock, \ + patch('context_logger.logger.RotatingFileHandler', return_value=fake_handler): + # When + handler = logger._create_file_handler('/tmp/test.log') + + # Then + self.assertIs(handler, fake_handler) + ensure_directory_mock.assert_called_once_with('/tmp/test.log') + fake_handler.setFormatter.assert_called_once() + fake_handler.addFilter.assert_called_once() + + def test_ensure_directory_exists_creates_directory_when_missing(self): + # Given + logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message') + + with patch('context_logger.logger.os.path.exists', return_value=False), \ + patch('context_logger.logger.os.makedirs') as makedirs_mock: + # When + logger._ensure_directory_exists('/tmp/new-dir/test.log') + + # Then + makedirs_mock.assert_called_once_with('/tmp/new-dir') + + def test_ensure_directory_exists_does_not_create_existing_directory(self): + # Given + logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message') + + with patch('context_logger.logger.os.path.exists', return_value=True), \ + patch('context_logger.logger.os.makedirs') as makedirs_mock: + # When + logger._ensure_directory_exists('/tmp/existing-dir/test.log') + + # Then + makedirs_mock.assert_not_called() + + +if __name__ == '__main__': + unittest.main() diff --git a/tests/loggerTest.py b/tests/loggerTest.py index ec68696..f7d6b09 100644 --- a/tests/loggerTest.py +++ b/tests/loggerTest.py @@ -19,7 +19,7 @@ def setUp(self): def test_structlog_logging(self): # Given - setup_logging('example-app', warn_on_overwrite=False) + setup_logging('example-app', warn_on_overwrite=False, global_context={'global1': 'value1'}) log = get_logger('ExampleClass') @@ -36,7 +36,7 @@ def test_structlog_logging(self): def test_stdlib_logging(self): # Given - setup_logging('example-app', warn_on_overwrite=False) + setup_logging('example-app', warn_on_overwrite=False, global_context={'global1': 'value1'}) stdlib_log = logging.getLogger('ExampleClass') @@ -54,7 +54,8 @@ def test_file_logging(self): # Given log_file_path = f'{TESTS_DIR_PATH}/logs/example.log' shutil.rmtree(os.path.dirname(log_file_path), ignore_errors=True) - setup_logging('example-app', 'INFO', log_file_path, add_call_info=True, warn_on_overwrite=False) + setup_logging('example-app', 'INFO', log_file_path, add_call_info=True, warn_on_overwrite=False, + global_context={'global1': 'value1'}) log = get_logger('ExampleClass') stdlib_log = logging.getLogger('ExampleClass') @@ -82,6 +83,7 @@ def test_file_logging(self): self.assertEqual('This is an error message', log_entry.get('message')) self.assertEqual('Something terrible happened', log_entry.get('error_message')) self.assertEqual(1234, log_entry.get('error_code')) + self.assertEqual('value1', log_entry.get('global1')) self.assertIsNotNone(log_entry.get('pathname')) self.assertIsNotNone(log_entry.get('func_name')) self.assertIsNotNone(log_entry.get('lineno')) @@ -99,7 +101,8 @@ def test_overwriting_setup(self): stdlib_log = logging.getLogger('ExampleClass') # When - setup_logging('example-app', 'ERROR', log_file_path, add_call_info=False, message_field='msg') + setup_logging('example-app', 'ERROR', log_file_path, add_call_info=False, message_field='msg', + global_context={'global1': 'value1'}) log.info('This is a simple message') stdlib_log.error('This is an error message') @@ -115,6 +118,7 @@ def test_overwriting_setup(self): self.assertEqual('This is an error message', log_entry.get('msg')) self.assertEqual('Something terrible happened', log_entry.get('error_message')) self.assertEqual(1234, log_entry.get('error_code')) + self.assertEqual('value1', log_entry.get('global1')) self.assertIsNone(log_entry.get('pathname')) self.assertIsNone(log_entry.get('func_name')) self.assertIsNone(log_entry.get('lineno'))