Logging issues - before_log() and after_log()

[vpogrebi]

I am trying to use tenacity for the first time, and immediately ran into logging issues. I included before and after kwargs with @retry() decorator (using provided before_log() and after_log() procedures) - but resulting log messages are missing actual data (which are the sole purpose of having these logs). I end up having these messages in my log:

before_log(): Starting call to '%s', this is the %s time calling it. after_log(): Finished call to '%s' after %0.3f(s), this was the %s time calling it.

We are using structlog instead of logging library, but I do not think that would have any impact.

Just in case, here is the decorator I am using:

    @tenacity.retry(
        wait=tenacity.wait_random_exponential(multiplier=1, max=60),
        stop=(tenacity.stop_after_delay(600) | tenacity.stop_after_attempt(10)),
        before=tenacity.before_log(log, INFO),
        after=tenacity.after_log(log, INFO),
    )

Project's pyproject.toml sets tenacity version 6.3.1:

tenacity = "6.3.1"

Can someone advise what needs to be done for this missing metadata to show up in the logs (for _util procedures to work properly)?

BTW... tenacity package does not include __version__ attribute (standard package attribute) - which may well be additional request (to include __version__).

[xingdongzhe]

Can you provide more detail? like OS version, structlog version, python version, or mini program? I can not reproduce this issue on Mac, Python=3.8.13, structlog-23.1.0 and tenacity = 6.3.1(git tag)

from tenacity import *

import logging
import structlog

logger = structlog.getLogger()


@retry(stop=stop_after_attempt(3), before=before_log(logger, logging.INFO), after=after_log(logger, logging.INFO))
def raise_my_exception():
    raise Exception("Fail")

try:
    raise_my_exception()
except Exception:
    pass

output:

2023-07-19 09:54:28 [info     ] Starting call to '__main__.raise_my_exception', this is the 1st time calling it.
2023-07-19 09:54:28 [info     ] Finished call to '__main__.raise_my_exception' after 0.000(s), this was the 1st time calling it.
2023-07-19 09:54:28 [info     ] Starting call to '__main__.raise_my_exception', this is the 2nd time calling it.
2023-07-19 09:54:28 [info     ] Finished call to '__main__.raise_my_exception' after 0.001(s), this was the 2nd time calling it.
2023-07-19 09:54:28 [info     ] Starting call to '__main__.raise_my_exception', this is the 3rd time calling it.
2023-07-19 09:54:28 [info     ] Finished call to '__main__.raise_my_exception' after 0.001(s), this was the 3rd time calling it.

[vpogrebi]

Python: 3.10 OS: should not matter (but mine is MacOS Ventura 13.4 - M1 chip), this issue was happening in prior OS versions as well structlog: 23.10 tenacity: 8.2.2

This issue was happening for a long time, with earlier versions of each package. At the moment, we no longer use before_log and after_log so I cannot say if this issue still persists.