Python Logger Best Practice

_python_logger_best_practice.md

Python Logger Best Practices

Situation

Depending on where the code runs (dev, staging or prod) and what the intention of the run (debug/dev, integration test, production runs), the called modules/components need to log differently.

Current Practices

Current practice includes some code snippets like this:

# in caller.py

import os
from callee import callee_func

debug=os.environ["debug"].lower() == "true"
callee_func(..., debug=debug)

# in callee.py

def callee_func(..., debug=False):
  if debug:
    print("callee called; next step is ...")
  pass

Shortfalls of the Current Practices

• We have certain branch (if/else branch) not unit-test properly
• Code readability is low

Action

1. In callee modules, initialize logger object as follow:

   import logging
   logger = logging.getLogger(__name__)

2. Use this logger object instead of print and logging calls.

   logger.debug("We have reached to this point")
   logger.info("So far so good")
   if error:
     logger.error("Oh O, not so good")

3. In the caller module, get the logger of each module/method as follow:

   import callee # module
   from another_callee import callee_func_2 # method
   
   logger_callee = logging.getLogger(callee.__name__)
   logger_another_callee = logging.getLogger(callee_func_2.__module__)

4. Then, set log level of these logger objects:

   logger_callee.setLevel(logging.DEBUG) # low level; will print almost all
   logger_another_callee.setLevel(logging.ERROR) #high level; will only print error

Results

With debug=true:

export debug="true"
python caller.py
DEBUG:callee:callee_func debug
INFO:callee:callee_func info
WARNING:callee:callee_func warn
ERROR:callee:callee_func exception occurred
Traceback (most recent call last):
  File "d:\projects\sandbox\callee.py", line 10, in callee_func
    raise("Exception in callee_func")
TypeError: exceptions must derive from BaseException
Stack (most recent call last):
  File "d:\projects\sandbox\caller.py", line 24, in <module>
    callee_func()
  File "d:\projects\sandbox\callee.py", line 12, in callee_func
    logger.exception("callee_func exception occurred", stack_info=True)
ERROR:callee:callee_func error
INFO:root:<------||------>
ERROR:another_callee:callee_func_2 exception occurred
Traceback (most recent call last):
  File "d:\projects\sandbox\another_callee.py", line 10, in callee_func_2
    raise("Exception in callee_func_2")
TypeError: exceptions must derive from BaseException
Stack (most recent call last):
  File "d:\projects\sandbox\caller.py", line 26, in <module>
    callee_func_2(whatever="whatever")
  File "d:\projects\sandbox\another_callee.py", line 12, in callee_func_2
    logger.exception("callee_func_2 exception occurred", stack_info=True)
ERROR:another_callee:callee_func_2 error

Notice, there is no debug, info and warning message from another_callee.

With debug=false:

debug="false"
python caller.py
INFO:root:debug is False
INFO:callee:callee_func info
WARNING:callee:callee_func warn
ERROR:callee:callee_func exception occurred
Traceback (most recent call last):
  File "D:\projects\sandbox\callee.py", line 10, in callee_func
    raise("Exception in callee_func")
TypeError: exceptions must derive from BaseException
Stack (most recent call last):
  File "D:\projects\sandbox\caller.py", line 24, in <module>
    callee_func()
  File "D:\projects\sandbox\callee.py", line 12, in callee_func
    logger.exception("callee_func exception occurred", stack_info=True)
ERROR:callee:callee_func error
INFO:root:<------||------>
WARNING:another_callee:callee_func_2 warn
ERROR:another_callee:callee_func_2 exception occurred
Traceback (most recent call last):
  File "D:\projects\sandbox\another_callee.py", line 10, in callee_func_2
    raise("Exception in callee_func_2")
TypeError: exceptions must derive from BaseException
Stack (most recent call last):
  File "D:\projects\sandbox\caller.py", line 26, in <module>
    callee_func_2(whatever="whatever")
  File "D:\projects\sandbox\another_callee.py", line 12, in callee_func_2
    logger.exception("callee_func_2 exception occurred", stack_info=True)
ERROR:another_callee:callee_func_2 error

Notice there is warning message from another_callee.

Reference

• Python Documentations on logging

another_callee.py

import logging

logger = logging.getLogger(__name__)

def callee_func_2(whatever:str=None):
    logger.debug("callee_func_2 debug")
    logger.info(f"callee_func_2 info : received whatever = {whatever}")
    logger.warn("callee_func_2 warn")
    try:
        raise("Exception in callee_func_2")
    except Exception as e:
        logger.exception("callee_func_2 exception occurred", stack_info=True)
        logger.error("callee_func_2 error")

callee.py

import logging

logger = logging.getLogger(__name__)

def callee_func(whatever:str=None):
    logger.debug("callee_func debug")
    logger.info("callee_func info")
    logger.warn("callee_func warn")
    try:
        raise("Exception in callee_func")
    except Exception as e:
        logger.exception("callee_func exception occurred", stack_info=True)
        logger.error("callee_func error")

caller.py

import os

import logging

import callee 
from another_callee import callee_func_2

callee_func = callee.callee_func

logger_callee = logging.getLogger(callee.__name__)
logger_another_callee = logging.getLogger(callee_func_2.__module__)

logger = logging.getLogger() # root logger for this script

if __name__ == "__main__":
    
    debug = os.environ.get("debug", "true") == "true"
    logging.basicConfig(level=logging.INFO) # mid level; won't print debug
    if debug:
        logger_callee.setLevel(logging.DEBUG) # low level; will print almost all
        logger_another_callee.setLevel(logging.ERROR) #high level; will only print error
    else:
        logger.info(f"debug is {debug}") 
        logger_another_callee.setLevel(logging.WARN) #high level; will only print warning and error

    callee_func()
    logger.info("<------||------>")
    callee_func_2(whatever="whatever")