How to do debugging prints in Python?

Question

I have a function like this....

def validate_phone(raw_number, debug=False):

I want the debug flag to control whether it outputs logging statements. For example:

if (debug):
  print('Before splitting numbers', file=sys.stderr)

split_version = raw_number.split('-')

if (debug):
  print('After splitting numbers', file=sys.stderr)

That code is very repetitive however. What is the cleanest (DRYest?) way to handle such if-flag-then-log logic?

Answer 1

I agree that using logging is the best solution for printing debugging information while running a python script. I wrote a DebugPrint module that helps facilitate using the logger more easily:

#DebugPrint.py
import logging
import os
import time

DEBUGMODE=True

logging.basicConfig(level=logging.DEBUG)
log=logging.getLogger('=>')    


#DebugPrint.py
#DbgPrint=logging.debug 
def DbgPrint(*args, **kwargs):
    if DEBUGMODE:
        #get module, class, function, linenumber information
        import inspect
        className = None
        try:
            className = inspect.stack()[2][0].f_locals['self'].__class__.__name__
        except:
            pass
        modName=None
        try:
            modName = os.path.basename(inspect.stack()[2][1])
        except:
            pass
        lineNo=inspect.stack()[2][2]
        fnName=None
        try:
            fnName = inspect.stack()[2][3]
        except:
            pass
        DbgText="line#{}:{}->{}->{}()".format(lineNo, modName,className, fnName)
        argCnt=len(args)
        kwargCnt=len(kwargs)
        #print("argCnt:{} kwargCnt:{}".format(argCnt,kwargCnt))
        fmt=""
        fmt1=DbgText+":"+time.strftime("%H:%M:%S")+"->"
        if argCnt > 0:
            fmt1+=(argCnt-1)*"%s,"
            fmt1+="%s"
            fmt+=fmt1

        if kwargCnt>0:
            fmt2="%s"
            args+=("{}".format(kwargs),)
            if len(fmt)>0:
                fmt+=","+fmt2
            else:
                fmt+=fmt2


        #print("fmt:{}".format(fmt))
        log.debug(fmt,*args)


if __name__=="__main__":
    def myTest():
        print("Running myTest()")
        DbgPrint("Hello","World")

myTest()

If the DEBUGMODE variable is false, nothing will be printed.
If it is true, the sample code above prints out:

DEBUG:=>:16:24:14:line#78:DebugPrint.py->None->myTest():->Hello,World

Now I'm going to test DebugPrint with a module that defines a class.

#testDebugPrint.py
from DebugPrint import DbgPrint


class myTestClass(object):
    def __init__(self):
        DbgPrint("Initializing the class")

    def doSomething(self, arg):
        DbgPrint("I'm doing something with {}".format(arg))

if __name__=='__main__':
    test=myTestClass()
    test.doSomething("a friend!")

When this script is run the output is as follows:

DEBUG:=>:16:25:02:line#7:testDebugPrint.py->myTestClass->__init__():->Initializing the class
DEBUG:=>:16:25:02:line#10:testDebugPrint.py->myTestClass->doSomething():->I'm doing something with a friend!

Note that the module name, class name, function name and line number printed on the console is correct as well as the time the statement was printed.

I hope that you will find this utility useful.

Answer 2

I would use the logging module for it. It's made for it.

> cat a.py       
import logging

log = logging.getLogger(__name__)


def main():
    log.debug('This is debug')
    log.info('This is info')
    log.warn('This is warn')
    log.fatal('This is fatal')
    try:
        raise Exception("this is exception")
    except Exception:
        log.warn('Failed with exception', exc_info=True)
        raise

if __name__ == '__main__':
    import argparse
    parser = argparse.ArgumentParser(description='something')
    parser.add_argument(
        '-v', '--verbose', action='count', default=0, dest='verbosity')
    args = parser.parse_args()

    logging.basicConfig()
    logging.getLogger().setLevel(logging.WARN - 10 * args.verbosity)

    main()
> python a.py 
WARNING:__main__:This is warn
CRITICAL:__main__:This is fatal
WARNING:__main__:Failed with exception
Traceback (most recent call last):
  File "a.py", line 12, in main
    raise Exception("this is exception")
Exception: this is exception
Traceback (most recent call last):
  File "a.py", line 27, in <module>
    main()
  File "a.py", line 12, in main
    raise Exception("this is exception")
Exception: this is exception
> python a.py -v
INFO:__main__:This is info
WARNING:__main__:This is warn
CRITICAL:__main__:This is fatal
WARNING:__main__:Failed with exception
Traceback (most recent call last):
  File "a.py", line 12, in main
    raise Exception("this is exception")
Exception: this is exception
Traceback (most recent call last):
  File "a.py", line 27, in <module>
    main()
  File "a.py", line 12, in main
    raise Exception("this is exception")
Exception: this is exception
> python a.py -vv
DEBUG:__main__:This is debug
INFO:__main__:This is info
WARNING:__main__:This is warn
CRITICAL:__main__:This is fatal
WARNING:__main__:Failed with exception
Traceback (most recent call last):
  File "a.py", line 12, in main
    raise Exception("this is exception")
Exception: this is exception
Traceback (most recent call last):
  File "a.py", line 27, in <module>
    main()
  File "a.py", line 12, in main
    raise Exception("this is exception")
Exception: this is exception

Answer 3

You ought to use the logging module:

import logging
import sys
# Get the "root" level logger.
root = logging.getLogger()
# Set the log level to debug.
root.setLevel(logging.DEBUG)
# Add a handler to output log messages as a stream (to a file/handle)
# in this case, sys.stderr
ch = logging.StreamHandler(sys.stderr)
# This handler can log debug messages - multiple handlers could log
# different "levels" of log messages.
ch.setLevel(logging.DEBUG)
# Format the output to include the time, etc.
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
# Add the formatter to the root handler...
root.addHandler(ch)
# Get a logger object - this is what we use to omit log messages.
logger=logging.getLogger(__name__)

# Generate a bunch of log messages as a demonstration
for i in xrange(100):
   logger.debug('The value of i is: %s', i)

# Demonstrate a useful example of logging full exception tracebacks
# if the logger will output debug, but a warning in other modes.
try:
   a='a'+12
except Exception as e:
   # Only log exceptions if debug is enabled..
   if logger.isEnabledFor(logging.DEBUG):
       # Log the traceback w/ the exception message.
       logger.exception('Something went wrong: %s', e)
   else:
       logger.warning('Something went wrong: %s', e)

Read more about it here: https://docs.python.org/2/library/logging.html

To disable logging just set the level (logging.DEBUG) to something else (like logging.INFO) . Note that it's also quite easy to redirect the messages elsewhere (like a file) or send some messages (debug) some place, and other messages (warning) to others.

Answer 4

import logging
logging.basicConfig(filename='example.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')

you can change the logging level to INFO/DEBUG/WARNING/ERROR/CRITICAL, and also logging module can record the timestamp for you and it is configurable as well.

Check the link python3 logging HowTo