How to do logging at function entry, inside and exit in Python

Question

I'd like to be able to do simple and consistent logging in my code using the Python logging facility.

I am able to do the following:

1. I'd like all existing/future module and functions to have "Entering ..." and "Done ..." log messages.
2. I don't want to add the same code snippet to defining logging parameters (shown below don't want to add everywhere) in every function definition.
3. I want the log.info(...) etc constructs to work in any function I define in the project hierarchy.

What doesn't work / I don't know how to do it:

1. I'd like to avoid defining the same @log decorator in every existing/new module that I write.

# don't want to add everywhere
FORMAT = '%(asctime)s - %(name)-20s - %(levelname)-5s - %(message)s'
LEVEL = logging.DEBUG
logging.basicConfig(format=FORMAT, level=LEVEL)
log = logging.getLogger(__name__)

**Sample code from my Flask project:**

# app/__init__.py
from a import b  # various other imports required for app
import logging
FORMAT = '%(asctime)s - %(name)-20s - %(levelname)-5s - %(message)s'
LEVEL = logging.DEBUG
logging.basicConfig(format=FORMAT, level=LEVEL)
log = logging.getLogger(__name__)
# ... various other app init code
from app import views, models

#app/views.py
from c import d  # various other imports required for the module

def logger(fn):
    from functools import wraps
    import inspect
    @wraps(fn)
    def wrapper(*args, **kwargs):
        global log
        log = logging.getLogger(inspect.stack()[1][3])
        log.info('About to run %s' % fn.__name__)

        out = fn(*args, **kwargs)

        log.info('Done running %s' % fn.__name__)
        # Return the return value
        return out
    return wrapper

    @app.route('/this_func')
    @logger
    def this_func():
        log.info('I am doing logging without having to do bunch of definitions.')
        # some more code

    @app.route('/that_func')
    @logger
    def that_func():
        log.info('Yet more logging without having to do bunch of definitions.')
        log.info('I can simply refer to the log object and be done with it.')
        # some more code

Answer 1

The final setup that worked for me was the following:

# At the beginning of every .py file in the project
def logger(fn):
    from functools import wraps
    import inspect
    @wraps(fn)
    def wrapper(*args, **kwargs):
        log = logging.getLogger(fn.__name__)
        log.info('About to run %s' % fn.__name__)

        out = fn(*args, **kwargs)

        log.info('Done running %s' % fn.__name__)
        # Return the return value
        return out
    return wrapper

# Do the following section only in application's app/__init__.py
# Other files will pick it up from here.
FORMAT = '%(asctime)s - %(name)s - %(levelname)s - %(funcName)s - %(message)s'

# Change logging LEVEL according to debugging needs.
# Probably better to read this from a config or a launch parameter.
LEVEL = logging.DEBUG

logging.basicConfig(format=FORMAT, level=LEVEL)
# Up to here only for app/__init__.py

# This section again at the beginning of every .py file
log = logging.getLogger(__name__)
log.info('Entered module: %s' % __name__)

Now, add a @logger decorator to every function definition in the module:

@logger
def do_something():
    print('doing really useful stuff.')

Answer 2

Using contextlib with exception handling.

from contextlib import contextmanager
import logging
from time import time 
logging.basicConfig(level=logging.INFO, format='%(asctime)s | %(levelname)s | %(processName)s | %(thread)d | %(message)s')
log = logging.getLogger(__name__)

@contextmanager
def EEL(methodDescr, raiseExcp=False):
  '''EEL = Entry Exit Log'''
  log.info(f"Starting function: {methodDescr}")
  start = time()
  try:
    yield
  except Exception as ex:
    log.exception("Got exception")
  finally:
    end = time()
    log.info(f"Time taken by {methodDescr}: {end-start}")

Usage:

@EEL("Test method")
def test():
  x = 0
  for i in range(1,1000000):
    x = x + i

Output:

2020-09-22 11:09:17,418 | INFO | MainProcess | 139709531875200 | Starting function: Test method
2020-09-22 11:09:17,484 | INFO | MainProcess | 139709531875200 | Time taken by Test method: 0.06573295593261719