Log appearing exceptions only once?

[afischer-opentext-com]

Assuming the situation that tenacity wraps methods calling a remote web service

import logging
import sys

from tenacity import Retrying, before_sleep_log, stop_after_attempt, wait_exponential

from service import CLIENT

logging.basicConfig(stream=sys.stderr, level=logging.DEBUG)


LOG = logging.getLogger(__name__)


RETRY = Retrying(
    reraise=True,
    stop=stop_after_attempt(7),
    wait=wait_exponential(multiplier=1, min=1, max=60),
    before_sleep=before_sleep_log(LOG, logging.DEBUG),
)


@RETRY.wraps
def some_service_call(*args, **kwargs):
    CLIENT.some_service_call(*args, **kwargs)

Now everything may go wrong, either network issues or illegal arguments/values on client or server side parsing.

Generally I do not want to log every kind of exception. I only want the exception to be logged only once.

The question is now: How can I handle situations in which the situation/exception type changes? I do not want duplicate exceptions logged but I want all appearing exceptions logged.

An example is that e.g. the web service raises an exception indicating further retries will be blocked after three illegal calls. I want the illegal call logged once and the final blocking exception logged once.

I played with a custom my_before_sleep(retry_state) call for the before_sleep argument but this is not fully satisfying. I need a better idea of what is possible.

[asqui]

I think a custom variant of before_sleep_log is exactly what you need. You can use a closure to maintain a set of "seen errors" between calls to the inner log_it function and only log them the first time.

If @jd thinks this is general-purpose enough it could even get included in the base library as an option.

I recently added an exc_info option to before_sleep_log so one idea would be to allow this option to log the full exception stack trace on the first time only, to avoid filling the logs with repeat stack traces.

The challenge I have encountered in this situation before is that it's hard to discern, in a generic manner, what constitutes a "different error". Are all exceptions of the same type the "same error"? What if they have different messages? What if they originate from different places in the code? Sometimes exceptions that include something like a session id in the message, which changes every time, but the error is materially the same.

These choices on how do differentiate "different errors" are likely specific to a particular use-case, so in practice it would be hard to include generic support for this in the library without some complicated mechanism to indicate your preferred "error differentiation mechanism" or similar.

Storing exceptions in a set might also have far-reaching consequences for memory-management so that's another reason for not including such functionality in a general-purpose library.

So back to my opening suggestion: I think a custom variant of before_sleep_log is exactly what you need.

Hope that helps? :-)

[afischer-opentext-com]

Thank you. My current shot is then as bellow. It only works python 3.5 up and it only compares the exception type but does not mess with the stack or message.

My issue with that is, that it logs the first occurrence of an exception (type). I would prefer it would log the last occurrence of an exception (type) to avoid logging issues which recover on in sub sequent calls. But so far, it seems to work.

LOG = logging.getLogger(__name__)


_FN_MEM = {}


def custom_before_sleep(retry_state):
    if retry_state.attempt_number < 3:
        loglevel = logging.DEBUG
    else:
        loglevel = logging.WARNING

    # Keep _FN_MEM flat
    if retry_state.fn in _FN_MEM:
        last_attempt_number = _FN_MEM[retry_state.fn][0]
        if last_attempt_number + 1 != retry_state.attempt_number:
            # new round
            del _FN_MEM[retry_state.fn]

    # Gather previous exception to compare
    previous_exception = None
    if retry_state.fn in _FN_MEM:
        previous_exception = _FN_MEM[retry_state.fn][1]

    log_exception = None
    if retry_state.outcome.failed:
        current_exception = retry_state.outcome.exception()
        # Compare only by type, not by message and/or stack
        if type(previous_exception) != type(current_exception):
            previous_exception = current_exception
            log_exception = current_exception
        _FN_MEM[retry_state.fn] = (retry_state.attempt_number, current_exception)

    if log_exception:
        formatted = "".join(traceback.TracebackException.from_exception(log_exception).format())
        LOG.log(
            loglevel,
            "Retrying %s: attempt %s ended with: %s",
            retry_state.fn,
            retry_state.attempt_number,
            formatted,
        )