2

I have a decorator to retry some operations for 3 times if a deadlock happens, and does some logging in the process:

def retry_on_deadlock(func):
    logger = logging.getLogger('test')

    @wraps(func)
    def decorated(*args, **kwargs):
        retry_count = 0

        while retry_count < 3:
            try:
                return func(*args, **kwargs)
            except DeadLockException:
                retry_count += 1

                if retry_count == 3:
                    raise

                logger.warning('We are in the decorated function here')

    return decorated

@retry_on_deadlock
def crucial_function(value):
    with value:
        do_something()

crucial_function(important_data)

Our logging format includes %(funcName)s which, in this specific case, will evaluate to decorated. Is there a way to make crucial_function appear in the logs instead?

I already tried implementing a logging filter, but the logic it needs became a bit cumbersome, as it needs to inspect the stack, and if the logging happened directly in the decorated function (ie. not in a function called by the original function) it will overwrite funcName on the log record. If this is the only way, though, i will sadly accept it.

Update: This is not the same as this question as i don’t really care about the functions signature (which, in fact, is preserved by the @wraps decorator). I want to instruct the logging library to skip one level from the stack trace when logging the function’s name via the %(funcName)s, %(filename)s, and %(lineno)s.

GergelyPolonkai
  • 6,230
  • 6
  • 35
  • 69
  • 1
    Well… the log *is* happening within `decorated`. It would be confusing if the log message would point to `crucial_function`, when `crucial_function` doesn't contain a single log statement, wouldn't it? You may instead want to adjust your log message: `logging.warning('The foo bared the baz for %r', func)`. – deceze May 17 '19 at 09:06
  • @HampusLarsson it’s not, as that question can easily be solved with the `@wraps` decorator. Here i want to skip a level from the stack trace during logging (although @deceze has a valid point that i should not do it at all). – GergelyPolonkai May 17 '19 at 09:40
  • @deceze in general you are right. However, in this specific case the fact that the logging happened in `retry_on_deadlock.decorated` is irrelevant. The actual code that triggered the deadlock is `crucial_function`. And yes, i can include that in the log message i compose in `decorated`, but somehow it didn’t feel right (until now; now i get back to the planning board). – GergelyPolonkai May 17 '19 at 09:41

1 Answers1

1

Just now face this problem while writing a logging wrapper. And accidentally found a solution.

As of Python3.8 you can now use stacklevel keyword which is available in all logging methods (debug, info, warning, error, critical)

From docs

The third optional keyword argument is stacklevel, which defaults to 1. If greater than 1, the corresponding number of stack frames are skipped when computing the line number and function name set in the LogRecord created for the logging event. This can be used in logging helpers so that the function name, filename and line number recorded are not the information for the helper function/method, but rather its caller. The name of this parameter mirrors the equivalent one in the warnings module

I hope this will be helpful for future researchers.

Alexandr
  • 11
  • 1