Stop Using "print()" for Debugging: A 5 Minute Quickstart Guide to Python’s logging Module
Fri 06 April 2012 Al Sweigart
To debug your program, you may be tempted to pepper your source code with print()
calls to display the values of variables as your program runs. It's quick and easy to do this, but the problem is that once you see the values in the variables, that'll give you ideas for more places to put print()
calls, then you run the program again to learn where to put other print()
calls. The "quick" solution of adding print()
eats up a lot of time as you get sucked into this add print()
/run/add more print()
s loop.
To become a better programmer, you should learn how to use the debugger and Python's logging
module. Nina Zakharenko's PyCon US 2020 talk, "Goodbye Print, Hello Debugger" is an excellent introduction to the debugger. This blog post covers Python's built-in logging
module.
The logging
is better than printing because:
- You can save the log to a text file instead of just on the screen where you could easily lose it.
- It's easy to put a timestamp in each message, which is very handy.
- You can have different levels of urgency for messages, and filter out less urgent messages.
- When you want to later find log messages in or remove log messages from your source code, you won't get them confused with the real
print()
calls used for program output. - If you just print to a log file, it's easy to leave the log function calls in and just ignore them when you don't need them. (You don't have to constantly pull out and add in
print()
calls.)
The logging
Code to Copy and Paste
To print log messages to the screen, copy and paste this code:
import logging logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s') logging.debug('This log message appears on the screen.')
To write log messages to a file, you can copy and paste this code (the only difference is in bold):
import logging logging.basicConfig(filename='log_filename.txt', level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s') logging.debug('This log message appears in log_filename.txt.')
Later runs of the program will append to the end of the log file, rather than overwrite the file.
To log messages to a file AND printed to the screen, copy and paste the following:
import logging logger = logging.getLogger() logger.setLevel(logging.DEBUG) formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s') fh = logging.FileHandler('log_filename.txt') fh.setLevel(logging.DEBUG) fh.setFormatter(formatter) logger.addHandler(fh) sh = logging.StreamHandler() sh.setLevel(logging.DEBUG) sh.setFormatter(formatter) logger.addHandler(sh) logger.debug('This log message appears on the screen and in log_filename.txt.')
The logging.Formatter
object determines how the log messages are displayed. The handlers specify the destination for the log message: FileHandler
send them to a text file and StreamHandler
sends them to the stderr stream which often means the screen.
Make sure that the logger
variable is global, so that you can use it in functions. (You don't need the "global logger
" at the top of the function, because the logger
variable is only read, not modified.)
The different levels of logging, from highest urgency to lowest urgency, are:
- CRITICAL - For errors that cannot be recovered from or cause a system to fail.
- ERROR - For preventable errors that happen.
- WARNING - For situations where nothing has gone wrong yet, but could potentially cause errors in the future.
- INFO - For general informative messages about something that happened in the program. (Examples: A file being read, an email being sent, etc.)
- DEBUG - For low-level details that concern the source code. (Examples: A function being called, the value in a particular variable, etc.)
The setLevel()
call sets the minimum log level of messages it actually logs. So if you fh.setLevel(logging.ERROR)
, then WARNING, INFO, and DEBUG log messages will not be written to the log file (since fh
is the log handler for the log file, as opposed to ch
which is the handler for the console screen.)
To write a log message in one of these five levels, use the following functions:
logger.critical('The system encountered an unknown error and cannot continue.')
logger.error('No response from server.')
logger.warning('Protocol problem. Connection was reset.')
logger.info('System started at ' + str(datetime.datetime.now()))
logger.debug('accountID = ' + str(accountID))
There's plenty more you can do, but this all you need to know to never again use print()
calls to do your debugging work.
The Python documentation has more info, including a Basic Tutorial, an Advanced Tutorial, and a Logging Cookbook.
Also, the pprint.pprint() function is great for "pretty printing" dictionaries and lists that have nested dictionaries and lists in them. The pprint.pformat() function returns the string of this content, rather than printing it to the screen.
One final tip: You can use the tail -f logfile.txt
command to show a file as it is being written to. The -f stands for "follow". Just leave a terminal/console window open with this command running, and new text in the log file will appear as it is written. This way, you don't have to keep opening/reloading a text editor to view the latest text in the log file.
The tail command comes on Mac OS X and Linux OSes. On Windows, you can download the Cygwin project to get the tail command.
(But also: you can still use print()
for quick debugging if you really want to. Just remember that short cuts often make longer trips.)
UPDATED 2021/12/17: Rewrote large parts of the blog post. Added link to Nina's PyCon talk.