Recent logging change breaks under tests

[asherf]

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

[richardm-stripe]

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.

[asherf]

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.

[richardm-stripe]

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.

[asherf]

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.

[asherf]

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!

[richardm-stripe]

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")

[richardm-stripe]

I've released 5.1.1 with the revert, and also yanked 5.1.0 from PyPi

[asherf]

thanks for the fast turnaround on this!