Recent logging change breaks under tests
asherf opened this issue · 8 comments
Describe the bug
We see this exception when using version 5.1.0 of the stripe sdk,
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/stripe/api_resources/customer.py:179: in search
return cls._search(search_url="/v1/customers/search", *args, **kwargs)
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/stripe/api_resources/abstract/searchable_api_resource.py:16: in _search
return cls._static_request(
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/stripe/api_resources/abstract/api_resource.py:139: in _static_request
response, api_key = requestor.request(method_, url_, params, headers)
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/stripe/api_requestor.py:119: in request
rbody, rcode, rheaders, my_api_key = self.request_raw(
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/stripe/api_requestor.py:350: in request_raw
util.log_info("Request to Stripe api", method=method, path=abs_url)
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/stripe/util.py:63: in log_info
logger.info(msg, params)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:1446: in info
self._log(INFO, msg, args, **kwargs)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:1589: in _log
self.handle(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:1599: in handle
self.callHandlers(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:1661: in callHandlers
hdlr.handle(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:952: in handle
self.emit(record)
/toolchain/caches/pex_root/venvs/s/3f701ead/venv/lib/python3.9/site-packages/_pytest/logging.py:343: in emit
super().emit(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:1091: in emit
self.handleError(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:1083: in emit
msg = self.format(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:927: in format
return fmt.format(record)
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:663: in format
record.message = record.getMessage()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self = <LogRecord: stripe, 20, stripe/util.py, 63, "message='Request to Stripe api' method=get path=https://jerry.not-stripe....v1/customers/search?query=metadata[%22toolchain_id%22]%3A%22george%22+AND+metadata[%22toolchain_env%22]%3A%22jerry%22">
def getMessage(self):
"""
Return the message for this LogRecord.
Return the message for this LogRecord after merging any user-supplied
arguments with the message.
"""
msg = str(self.msg)
if self.args:
> msg = msg % self.args
E ValueError: unsupported format character 't' (0x74) at index 116
/pyenv-docker-build/versions/3.9.15/lib/python3.9/logging/__init__.py:367: ValueError
I suspect this change: #913 caused the issue.
as you can see this happens when running under test so possibly something is broken in the interaction between stripe's logging wrappers and pytest caplog mechanism used to capture logs.
To Reproduce
this test will repo the exception when running under pytest.
import stripe
def test_stripe_api():
stripe.api_key = "no-soup-for-you"
stripe.api_base = "https://jerry.not-stripe.fake"
stripe.Customer.search(query='metadata["toolchain_id"]:"george" AND metadata["toolchain_env"]:"jerry"')
note that this test will fail because the network call is not mocked in this snippet, but w/ 5.1.0 it will fail before trying to make the network call.
Expected behavior
not to break/fail.
Code snippets
No response
OS
all platforms (linux/mac)
Language version
Python 3.9.12
Library version
5.1.0
API version
2022-11-15
Additional context
No response
Hello @asherf, thank you for the report. We will likely need to revert that change.
So far, I have been unable to reproduce:
$ python
Python 3.9.11 (main, Sep 22 2022, 13:08:52)
[Clang 14.0.0 (clang-1400.0.29.102)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import stripe
>>> stripe.version.VERSION
'5.1.0'
>>>
$ cat test_blah.py
import stripe
def test_stripe_api():
stripe.api_key = "sk_test_xyz"
stripe.api_base = "http://localhost:12111" # points to a locally running stripe-mock
stripe.Customer.search(query='metadata["toolchain_id"]:"george" AND metadata["toolchain_env"]:"jerry"')
$ python -m pytest test_blah.py
========================================= test session starts ==========================================
platform darwin -- Python 3.9.11, pytest-7.2.1, pluggy-1.0.0
rootdir: /Users/richardm/testbed/python
collected 1 item
test_blah.py . [100%]
========================================== 1 passed in 0.08s ===========================================
Would love to figure out how this is happening in your scenario but not this one.
Hello @asherf, thank you for the report. We will likely need to revert that change.
So far, I have been unable to reproduce:
$ python Python 3.9.11 (main, Sep 22 2022, 13:08:52) [Clang 14.0.0 (clang-1400.0.29.102)] on darwin Type "help", "copyright", "credits" or "license" for more information. >>> import stripe >>> stripe.version.VERSION '5.1.0' >>> $ cat test_blah.py import stripe def test_stripe_api(): stripe.api_key = "sk_test_xyz" stripe.api_base = "http://localhost:12111" # points to a locally running stripe-mock stripe.Customer.search(query='metadata["toolchain_id"]:"george" AND metadata["toolchain_env"]:"jerry"') $ python -m pytest test_blah.py ========================================= test session starts ========================================== platform darwin -- Python 3.9.11, pytest-7.2.1, pluggy-1.0.0 rootdir: /Users/richardm/testbed/python collected 1 item test_blah.py . [100%] ========================================== 1 passed in 0.08s ===========================================Would love to figure out how this is happening in your scenario but not this one.
hmm... maybe it has something to do with how our logging is configured under tests (we have a bunch of setup code that uses conftest).
let me check, I will update the ticket shortly with my findings.
Ah, I triggered it with
python -m pytest --log-level=INFO
I will spend some time investigating, and I will push either a fix or a revert shortly.
import stripe
import logging
def test_stripe_api():
logging.config.dictConfig(
{
"loggers": {
"": {"handlers": ["console"], "level": "INFO"},
},
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"default": {
"format": "[%(asctime)s %(levelname)s %(process)d %(pathname)s:%(lineno)s] %(message)s",
"datefmt": "%Y-%m-%d %H:%M:%S",
}
},
"handlers": {
"console": {
"class": "logging.StreamHandler",
"level": "DEBUG",
"formatter": "default",
}
},
}
)
stripe.api_key = "no-soup-for-you"
stripe.api_base = "https://jerry.not-stripe.fake"
stripe.Customer.search(query='metadata["toolchain_id"]:"george" AND metadata["toolchain_env"]:"jerry"')
This will also trigger it.
Ah, I triggered it with
python -m pytest --log-level=INFO
I will spend some time investigating, and I will push either a fix or a revert shortly.
awesome. thanks!
I can reproduce without pytest too :/
import stripe
import logging
logging.basicConfig(level=4)
stripe.api_key = "sk_test_xyz"
stripe.api_base = "http://localhost:12111"
stripe.Customer.search(query='metadata["toolchain_id"]:"george" AND metadata["toolchain_env"]:"jerry"')
print("done")
I've released 5.1.1 with the revert, and also yanked 5.1.0 from PyPi
thanks for the fast turnaround on this!