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 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..f196191 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 @@ -11,7 +13,31 @@ } -def create_log(module): +# 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(), + ) + + return structlog.get_logger(module) + + +def standard_logger(module): logger = logging.getLogger(module) if logger.hasHandlers(): logger.handlers = [] @@ -28,5 +54,11 @@ 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(module) + else: + return standard_logger(module) diff --git a/tests/test_log_helper.py b/tests/test_log_helper.py index cf7f616..6d07669 100644 --- a/tests/test_log_helper.py +++ b/tests/test_log_helper.py @@ -1,13 +1,23 @@ +import json import logging import os import time 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: + def test_json_logging(self, capsys): + logger = create_log('test_log', json=True) + 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') 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')