From 1e93358d5101ae6931b90d662cbbe2805be5a493 Mon Sep 17 00:00:00 2001 From: Vera Kahn Date: Tue, 19 Aug 2025 15:38:54 -0400 Subject: [PATCH 1/7] optional json struct log --- pyproject.toml | 7 ++-- src/nypl_py_utils/functions/log_helper.py | 40 +++++++++++++++++++++-- 2 files changed, 43 insertions(+), 4 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 44fd78d..59df17f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] name = "nypl_py_utils" -version = "1.7.0" +version = "1.8.0" authors = [ { name="Aaron Friedman", email="aaronfriedman@nypl.org" }, ] @@ -38,6 +38,9 @@ kms-client = [ "boto3>=1.26.5", "botocore>=1.29.5" ] +log_helper = [ + "structlog>=25.4.0" +] mysql-client = [ "mysql-connector-python>=8.0.32" ] @@ -78,7 +81,7 @@ research-catalog-identifier-helper = [ "requests>=2.28.1" ] development = [ - "nypl_py_utils[avro-client,kinesis-client,kms-client,mysql-client,oauth2-api-client,postgresql-client,redshift-client,s3-client,secrets-manager-client,sftp-client,config-helper,obfuscation-helper,patron-data-helper,research-catalog-identifier-helper]", + "nypl_py_utils[avro-client,kinesis-client,kms-client,mysql-client,oauth2-api-client,postgresql-client,redshift-client,s3-client,secrets-manager-client,sftp-client,config-helper,obfuscation-helper,patron-data-helper,research-catalog-identifier-helper,log_helper]", "flake8>=6.0.0", "freezegun>=1.2.2", "mock>=4.0.3", diff --git a/src/nypl_py_utils/functions/log_helper.py b/src/nypl_py_utils/functions/log_helper.py index 7d7bf78..ead3685 100644 --- a/src/nypl_py_utils/functions/log_helper.py +++ b/src/nypl_py_utils/functions/log_helper.py @@ -1,3 +1,5 @@ +import structlog + import logging import os import sys @@ -10,8 +12,37 @@ 'critical': logging.CRITICAL } +# Configure structlog to be machine-readable first and foremost +# while still making it easy for humans to parse +# End result (without additional bindings) is JSON like this: +# +# { "logger": "module param" +# "message": "this is a test log event", +# "level": "info", +# "timestamp": "2023-11-01 18:50:47"} +# +def get_structlog(module): + structlog.configure( + processors=[ + structlog.processors.add_log_level, + structlog.processors.TimeStamper(fmt="iso"), + structlog.processors.EventRenamer("message"), + structlog.processors.JSONRenderer(), + ], + context_class=dict, + logger_factory=structlog.PrintLoggerFactory(), + ) + + # Import this to get an immutable common logger with the above format- you can further use + # + # custom_logger = common_logger.bind(some_key=some_value) + # + # to create your own logger with custom fields persisted on top of common ones. + # + # See https://www.structlog.org/en/stable/bound-loggers.html + return structlog.get_logger(module) -def create_log(module): +def standard_logger (module): logger = logging.getLogger(module) if logger.hasHandlers(): logger.handlers = [] @@ -28,5 +59,10 @@ def create_log(module): console_log.setFormatter(formatter) logger.addHandler(console_log) - return logger + +def create_log(module, json=False): + if(json): + return get_structlog() + else: + return standard_logger(module) From 7c1d49152345ee863ce5cb8c289f2a70536d5a29 Mon Sep 17 00:00:00 2001 From: Vera Kahn Date: Tue, 19 Aug 2025 15:39:26 -0400 Subject: [PATCH 2/7] update changelog --- CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 162dbdd..6d3e789 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,4 +1,7 @@ # Changelog +## v1.8.0 8/19/25 +- Add optional JSON structured logging + ## v1.7.0 6/13/25 - Use fastavro for avro encoding/decoding From 3206528b017930ab2aecc16f83d2f8838a964a38 Mon Sep 17 00:00:00 2001 From: Vera Kahn Date: Tue, 19 Aug 2025 16:43:42 -0400 Subject: [PATCH 3/7] testing wip --- src/nypl_py_utils/functions/log_helper.py | 2 +- tests/test_log_helper.py | 18 ++++++++++++++++++ 2 files changed, 19 insertions(+), 1 deletion(-) diff --git a/src/nypl_py_utils/functions/log_helper.py b/src/nypl_py_utils/functions/log_helper.py index ead3685..8fc26ec 100644 --- a/src/nypl_py_utils/functions/log_helper.py +++ b/src/nypl_py_utils/functions/log_helper.py @@ -63,6 +63,6 @@ def standard_logger (module): def create_log(module, json=False): if(json): - return get_structlog() + return get_structlog(module) else: return standard_logger(module) diff --git a/tests/test_log_helper.py b/tests/test_log_helper.py index cf7f616..cd5707e 100644 --- a/tests/test_log_helper.py +++ b/tests/test_log_helper.py @@ -1,13 +1,30 @@ import logging import os import time +import pytest +import structlog +from structlog.testing import ReturnLogger from freezegun import freeze_time + from nypl_py_utils.functions.log_helper import create_log @freeze_time('2023-01-01 19:00:00') class TestLogHelper: + @pytest.fixture + def mock_logger(self, mocker): + mocker.patch('src.nypl_py_utils.functions.log_helper.structlog.get_logger', return_value=ReturnLogger) + + def test_json_logging(self, mock_logger): + logger = create_log('test_log', json=True) + log = logger.info('testtt', some="json") + print('capture_logs', log) + assert False + # assert log.get("message") == 'test' + # assert log.get("some") == 'json' + # assert log.get('level') == 'info' + # assert log.get('timestamp') == '2023-01-01 19:00:00Z' def test_default_logging(self, caplog): logger = create_log('test_log') @@ -18,6 +35,7 @@ def test_default_logging(self, caplog): # freeze_time changes the utc time, while the logger uses local time by # default, so force the logger to use utc time logger.handlers[0].formatter.converter = time.gmtime + print(caplog.records) assert len(caplog.records) == 1 assert logger.handlers[0].format(caplog.records[0]) == \ '2023-01-01 19:00:00,000 | test_log | INFO: Test info message' From d81adde5d9fb47ebe65211894540facdb4c32201 Mon Sep 17 00:00:00 2001 From: Vera Kahn Date: Tue, 19 Aug 2025 16:48:15 -0400 Subject: [PATCH 4/7] rm comment --- src/nypl_py_utils/functions/log_helper.py | 7 ------- tests/test_log_helper.py | 2 +- 2 files changed, 1 insertion(+), 8 deletions(-) diff --git a/src/nypl_py_utils/functions/log_helper.py b/src/nypl_py_utils/functions/log_helper.py index 8fc26ec..8e94b2f 100644 --- a/src/nypl_py_utils/functions/log_helper.py +++ b/src/nypl_py_utils/functions/log_helper.py @@ -33,13 +33,6 @@ def get_structlog(module): logger_factory=structlog.PrintLoggerFactory(), ) - # Import this to get an immutable common logger with the above format- you can further use - # - # custom_logger = common_logger.bind(some_key=some_value) - # - # to create your own logger with custom fields persisted on top of common ones. - # - # See https://www.structlog.org/en/stable/bound-loggers.html return structlog.get_logger(module) def standard_logger (module): diff --git a/tests/test_log_helper.py b/tests/test_log_helper.py index cd5707e..72d4cc1 100644 --- a/tests/test_log_helper.py +++ b/tests/test_log_helper.py @@ -16,7 +16,7 @@ class TestLogHelper: def mock_logger(self, mocker): mocker.patch('src.nypl_py_utils.functions.log_helper.structlog.get_logger', return_value=ReturnLogger) - def test_json_logging(self, mock_logger): + def test_json_logging(self): logger = create_log('test_log', json=True) log = logger.info('testtt', some="json") print('capture_logs', log) From e2846f8299f80fc0c1fda1d7ee612b2461c8461b Mon Sep 17 00:00:00 2001 From: Vera Kahn Date: Wed, 20 Aug 2025 13:26:06 -0400 Subject: [PATCH 5/7] json logging test passing --- src/nypl_py_utils/functions/log_helper.py | 7 +++++-- tests/test_log_helper.py | 22 ++++++++-------------- 2 files changed, 13 insertions(+), 16 deletions(-) diff --git a/src/nypl_py_utils/functions/log_helper.py b/src/nypl_py_utils/functions/log_helper.py index 8e94b2f..f196191 100644 --- a/src/nypl_py_utils/functions/log_helper.py +++ b/src/nypl_py_utils/functions/log_helper.py @@ -12,6 +12,7 @@ 'critical': logging.CRITICAL } + # Configure structlog to be machine-readable first and foremost # while still making it easy for humans to parse # End result (without additional bindings) is JSON like this: @@ -35,7 +36,8 @@ def get_structlog(module): return structlog.get_logger(module) -def standard_logger (module): + +def standard_logger(module): logger = logging.getLogger(module) if logger.hasHandlers(): logger.handlers = [] @@ -54,8 +56,9 @@ def standard_logger (module): logger.addHandler(console_log) return logger + def create_log(module, json=False): - if(json): + if (json): return get_structlog(module) else: return standard_logger(module) diff --git a/tests/test_log_helper.py b/tests/test_log_helper.py index 72d4cc1..cd52e57 100644 --- a/tests/test_log_helper.py +++ b/tests/test_log_helper.py @@ -1,7 +1,7 @@ +import json import logging import os import time -import pytest import structlog from structlog.testing import ReturnLogger @@ -12,19 +12,14 @@ @freeze_time('2023-01-01 19:00:00') class TestLogHelper: - @pytest.fixture - def mock_logger(self, mocker): - mocker.patch('src.nypl_py_utils.functions.log_helper.structlog.get_logger', return_value=ReturnLogger) - - def test_json_logging(self): + def test_json_logging(self, capsys): logger = create_log('test_log', json=True) - log = logger.info('testtt', some="json") - print('capture_logs', log) - assert False - # assert log.get("message") == 'test' - # assert log.get("some") == 'json' - # assert log.get('level') == 'info' - # assert log.get('timestamp') == '2023-01-01 19:00:00Z' + logger.info('test', some="json") + output = json.loads(capsys.readouterr().out) + assert output.get("message") == 'test' + assert output.get("some") == 'json' + assert output.get('level') == 'info' + assert output.get('timestamp') == '2023-01-01T19:00:00Z' def test_default_logging(self, caplog): logger = create_log('test_log') @@ -35,7 +30,6 @@ def test_default_logging(self, caplog): # freeze_time changes the utc time, while the logger uses local time by # default, so force the logger to use utc time logger.handlers[0].formatter.converter = time.gmtime - print(caplog.records) assert len(caplog.records) == 1 assert logger.handlers[0].format(caplog.records[0]) == \ '2023-01-01 19:00:00,000 | test_log | INFO: Test info message' From 3277b42aa5bff07ee53cab2a4e8cfcf2a823dc7e Mon Sep 17 00:00:00 2001 From: Vera Kahn Date: Wed, 20 Aug 2025 13:26:29 -0400 Subject: [PATCH 6/7] rm unused deps --- tests/test_log_helper.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/test_log_helper.py b/tests/test_log_helper.py index cd52e57..6d07669 100644 --- a/tests/test_log_helper.py +++ b/tests/test_log_helper.py @@ -3,8 +3,6 @@ import os import time -import structlog -from structlog.testing import ReturnLogger from freezegun import freeze_time from nypl_py_utils.functions.log_helper import create_log From a259964203e267c990d4a9c524b4c0e0f507ebdf Mon Sep 17 00:00:00 2001 From: aaronfriedman Date: Thu, 28 Aug 2025 12:34:32 -0400 Subject: [PATCH 7/7] Fix Oauth2 tests --- tests/test_oauth2_api_client.py | 26 ++++++++++++++++++++------ 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/tests/test_oauth2_api_client.py b/tests/test_oauth2_api_client.py index b5fcd5c..3f67aa5 100644 --- a/tests/test_oauth2_api_client.py +++ b/tests/test_oauth2_api_client.py @@ -2,6 +2,7 @@ import time import json import pytest +from oauthlib.oauth2 import OAuth2Token from requests_oauthlib import OAuth2Session from requests import HTTPError, JSONDecodeError, Response @@ -110,7 +111,7 @@ def test_token_expiration(self, requests_mock, test_instance, .headers['Authorization'] == 'Bearer super-secret-token' # The token obtained above expires in 1s, so wait out expiration: - time.sleep(1.1) + time.sleep(2) # Register new token response: second_token_response = dict(_TOKEN_RESPONSE) @@ -138,7 +139,7 @@ def test_error_status_raises_error(self, requests_mock, test_instance, test_instance._do_http_method('GET', 'foo') def test_token_refresh_failure_raises_error( - self, requests_mock, test_instance, token_server_post): + self, requests_mock, test_instance, token_server_post, mocker): """ Failure to fetch a token can raise a number of errors including: - requests.exceptions.HTTPError for invalid access_token @@ -150,12 +151,25 @@ def test_token_refresh_failure_raises_error( a new valid token in response to token expiration. This test asserts that the client will not allow more than successive 3 retries. """ - requests_mock.get(f'{BASE_URL}/foo', json={'foo': 'bar'}) + test_instance._create_oauth_client() + + def set_token(*args, scope): + test_instance.oauth_client.token = OAuth2Token( + json.loads(args[0])) + test_instance.oauth_client._client.populate_token_attributes( + json.loads(args[0])) + requests_mock.get(f'{BASE_URL}/foo', json={'foo': 'bar'}) token_response = dict(_TOKEN_RESPONSE) - token_response['expires_in'] = 0 - token_server_post = requests_mock\ - .post(TOKEN_URL, text=json.dumps(token_response)) + token_response["expires_in"] = 0 + token_response["expires_at"] = 1000000000 + token_server_post = requests_mock.post( + TOKEN_URL, text=json.dumps(token_response)) + + test_instance.oauth_client._client.parse_request_body_response = ( + mocker.MagicMock(name="method", side_effect=set_token) + ) + test_instance._generate_access_token() with pytest.raises(Oauth2ApiClientError): test_instance._do_http_method('GET', 'foo')