Duplicate logging in some special cases

[smagafurov]

Python 3.10.5 (main, Jul 25 2022, 15:40:10) [Clang 13.1.6 (clang-1316.0.21.2.5)] on darwin
backoff==2.2.1

Run this example:

import sys

import backoff
import logging


logging.basicConfig()


retry_runtime_error = backoff.on_exception(
    backoff.constant,
    RuntimeError,
    max_tries=2,
    interval=0,
)


def func():
    raise RuntimeError()


if __name__ == '__main__':
    try:
        retry_runtime_error(func)()
    except RuntimeError:
        pass

    print('---------------', file=sys.stderr)

    try:
        retry_runtime_error(func)()
    except RuntimeError:
        pass

    print('---------------', file=sys.stderr)

    try:
        retry_runtime_error(func)()
    except RuntimeError:
        pass

Expected output:

INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
---------------
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
---------------
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)

Actually output:

INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
---------------
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
---------------
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
INFO:backoff:Backing off func(...) for 0.0s (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)
ERROR:backoff:Giving up func(...) after 2 tries (RuntimeError)

It's because of nonlocal here:

backoff/backoff/_decorator.py

Line 184 in a1e19d9

nonlocal logger, on_success, on_backoff, on_giveup

[smagafurov]

Solution (move _config_handlers(...) and _prepare_logger(...) from decorate scope to on_exception scope):

def on_exception(
    ...
    ) -> Callable[[_CallableT], _CallableT]:
    ...
    logger = _prepare_logger(logger)
    on_success = _config_handlers(on_success)
    on_backoff = _config_handlers(
        on_backoff,
        default_handler=_log_backoff,
        logger=logger,
        log_level=backoff_log_level,
    )
    on_giveup = _config_handlers(
        on_giveup,
        default_handler=_log_giveup,
        logger=logger,
        log_level=giveup_log_level,
    )

    def decorate(target):
        if asyncio.iscoroutinefunction(target):
            retry = _async.retry_exception
        else:
            retry = _sync.retry_exception
        ...