Lesson 36:

Logging

Logging involves printing code output to a file that can be reviewed later.

The logging module contains tools for logging in Python.

logging.basicCongif() is the setup code for logging in python.


In [1]:
import logging

logging.basicConfig(level=logging.DEBUG, format = '%(asctime)s - %(levelname)s - %(message)s') # Format for basic logging

Factorial Program

Create a program that can return the n! of a number (5! = 1 * 2 * 3 * 4 * 5 = 120).


In [18]:
# Creating a buggy program for testing

def factorial(n):
    """
    A function for finding factorials.
    """
    total = 1
    for i in range(n+1):
        total *= i # Total = total multiplied by ever element i added to itself
    return total

print(factorial(5))


0

The factorial program is returning a 0 output, which is invalid. We can use a log to find the error(s).

Build a log framerwork:


In [19]:
import logging

# For iPython/Jupyter, logging is handled at the root level. There are two ways to reacces logging

# Way 1: (Easy way)
import imp # Import the 'import' internals module
imp.reload(logging) # Reload the logging module for this specific instance


# Way 2: (Less Easy Way)
# Must define a logging object for this instance:
# logger = logging.getLogger() # Logging object
# logger.setLevel(logging.DEBUG) # Setting logging level to the level defined in the program
# This can be used by passing the normal logging.debug('message') as usual

logging.basicConfig(level=logging.DEBUG, format = '%(asctime)s - %(levelname)s - %(message)s') # Format for basic logging

logging.debug('Start of Program') # Start of program in log

def factorial(n):
    """
    A function for finding factorials.
    """
    logging.debug('Start of the factorial(%s)' % (n)) # Start the program and pass the argument to the log 
    total = 1
    for i in range(n+1):
        total *= i # Total = total multiplied by ever element i added to itself
        logging.debug('i is the %s, total is %s' % (i, total)) # Pass the actual function arguments to the log
    
    logging.debug('Return value is %s' % (total)) # Return the total argument to the log
    return total
  

print(factorial(5))
logging.debug('End of Program') # End of program in log


2016-02-04 10:38:12,944 - DEBUG - Start of Program
2016-02-04 10:38:12,945 - DEBUG - Start of the factorial(5)
2016-02-04 10:38:12,945 - DEBUG - i is the 0, total is 0
2016-02-04 10:38:12,946 - DEBUG - i is the 1, total is 0
2016-02-04 10:38:12,946 - DEBUG - i is the 2, total is 0
2016-02-04 10:38:12,946 - DEBUG - i is the 3, total is 0
2016-02-04 10:38:12,947 - DEBUG - i is the 4, total is 0
2016-02-04 10:38:12,948 - DEBUG - i is the 5, total is 0
2016-02-04 10:38:12,948 - DEBUG - Return value is 0
2016-02-04 10:38:12,949 - DEBUG - End of Program
0

logging.debug() function calls are a lot like print() calls, but they can provide a lot more information:

  • They provide a timestamp via %(asctime)s.
  • A log level via %(levelname)s.
  • The given logging.debug() message via %(message)s.

From the log, it seems the issue is because the function starts at 0 and not 1, multiplying every following iteration by total = 0.

Fix this by passing the range() function a start of 1:


In [17]:
import logging

import imp # Import the 'import' internals module
imp.reload(logging) # Reload the logging module for this specific instance


logging.basicConfig(level=logging.DEBUG, format = '%(asctime)s - %(levelname)s - %(message)s') # Format for basic logging

logging.debug('Start of Program') # Start of program in log

def factorial(n):
    """
    A function for finding factorials.
    """
    logging.debug('Start of the factorial(%s)' % (n)) # Start the program and pass the argument to the log 
    total = 1
    for i in range(1, n+1):
        total *= i # Total = total multiplied by ever element i added to itself
        logging.debug('i is the %s, total is %s' % (i, total)) # Pass the actual function arguments to the log
    
    logging.debug('Return value is %s' % (total)) # Return the total argument to the log
    return total
  

print(factorial(5))
logging.debug('End of Program') # End of program in log


2016-02-04 10:36:52,309 - DEBUG - Start of Program
2016-02-04 10:36:52,310 - DEBUG - Start of the factorial(5)
2016-02-04 10:36:52,310 - DEBUG - i is the 1, total is 1
2016-02-04 10:36:52,311 - DEBUG - i is the 2, total is 2
2016-02-04 10:36:52,311 - DEBUG - i is the 3, total is 6
2016-02-04 10:36:52,312 - DEBUG - i is the 4, total is 24
2016-02-04 10:36:52,312 - DEBUG - i is the 5, total is 120
2016-02-04 10:36:52,312 - DEBUG - Return value is 120
2016-02-04 10:36:52,313 - DEBUG - End of Program
120

This is now returning the proper value.

logging.debug() is used instead of print() because when the program is complete, every print() debug statement to be removed (and normal print() methods have to be ignored.)

Meanwhile, removing the debug() messages is as simple as changing the log level:


In [20]:
import logging

import imp 
imp.reload(logging) 


logging.disable(logging.CRITICAL) # Switch the log level from 'DEBUG' to 'CRITICAL'; only show 'critical' level debugs


logging.basicConfig(level=logging.DEBUG, format = '%(asctime)s - %(levelname)s - %(message)s') # Format for basic logging

logging.debug('Start of Program') # Start of program in log

def factorial(n):
    """
    A function for finding factorials.
    """
    logging.debug('Start of the factorial(%s)' % (n)) # Start the program and pass the argument to the log 
    total = 1
    for i in range(1, n+1):
        total *= i # Total = total multiplied by ever element i added to itself
        logging.debug('i is the %s, total is %s' % (i, total)) # Pass the actual function arguments to the log
    
    logging.debug('Return value is %s' % (total)) # Return the total argument to the log
    return total
  

print(factorial(5))
logging.debug('End of Program') # End of program in log


120

There are 5 log levels defined in Python:

  • Debug: The lowest level, for testing, accessed via logging.debug().
  • Info: The information level, for informing the programmer, accessed via logging.info().
  • Warning: The warning level, where something could go wrong, accessed via logging.warnig().
  • Error: The error level, where something has gone wrong, accessed via logging.error().
  • Critical: The highest level, where something has gone wrong, and might stop the program, accessed via logging.critical().

logging.disable() disables that level and every element below it.

logging.disable(logging.WARNING) would therefore disable the Warning, Info and Debug levels. logging.disable(logging.CRITICAL) would disable all levels except Critical.

To put the log outputs in a text file, you can modify the logging.basicConfig() to take a filename parameter.

Formerly, the try and except statements were used to handle exceptions, but you can also create your own exceptions with raise.


In [26]:
import logging
import os

import imp 
imp.reload(logging) 


#logging.disable(logging.CRITICAL) # Switch the log level from 'DEBUG' to 'CRITICAL'; only show 'critical' level debugs

logging.basicConfig(filename = os.path.abspath('files/Factoriallog.txt'), level=logging.DEBUG, format = '%(asctime)s - %(levelname)s - %(message)s') # Format for basic logging


logging.debug('Start of Program') # Start of program in log

def factorial(n):
    """
    A function for finding factorials.
    """
    logging.debug('Start of the factorial(%s)' % (n)) # Start the program and pass the argument to the log 
    total = 1
    for i in range(1, n+1):
        total *= i # Total = total multiplied by ever element i added to itself
        logging.debug('i is the %s, total is %s' % (i, total)) # Pass the actual function arguments to the log
    
    logging.debug('Return value is %s' % (total)) # Return the total argument to the log
    return total
  

print(factorial(5))
logging.debug('End of Program') # End of program in log


120

In [27]:
print(open(os.path.abspath('files/Factoriallog.txt'), 'r').read()) # Open and read the created log file


2016-02-04 10:50:14,334 - DEBUG - Start of Program
2016-02-04 10:50:14,334 - DEBUG - Start of the factorial(5)
2016-02-04 10:50:14,334 - DEBUG - i is the 1, total is 1
2016-02-04 10:50:14,334 - DEBUG - i is the 2, total is 2
2016-02-04 10:50:14,334 - DEBUG - i is the 3, total is 6
2016-02-04 10:50:14,334 - DEBUG - i is the 4, total is 24
2016-02-04 10:50:14,335 - DEBUG - i is the 5, total is 120
2016-02-04 10:50:14,335 - DEBUG - Return value is 120
2016-02-04 10:50:14,335 - DEBUG - End of Program
2016-02-04 10:50:22,937 - DEBUG - Start of Program
2016-02-04 10:50:22,937 - DEBUG - Start of the factorial(5)
2016-02-04 10:50:22,937 - DEBUG - i is the 1, total is 1
2016-02-04 10:50:22,937 - DEBUG - i is the 2, total is 2
2016-02-04 10:50:22,937 - DEBUG - i is the 3, total is 6
2016-02-04 10:50:22,937 - DEBUG - i is the 4, total is 24
2016-02-04 10:50:22,938 - DEBUG - i is the 5, total is 120
2016-02-04 10:50:22,938 - DEBUG - Return value is 120
2016-02-04 10:50:22,938 - DEBUG - End of Program
2016-02-04 10:50:53,886 - DEBUG - Start of Program
2016-02-04 10:50:53,886 - DEBUG - Start of the factorial(5)
2016-02-04 10:50:53,886 - DEBUG - i is the 1, total is 1
2016-02-04 10:50:53,886 - DEBUG - i is the 2, total is 2
2016-02-04 10:50:53,886 - DEBUG - i is the 3, total is 6
2016-02-04 10:50:53,886 - DEBUG - i is the 4, total is 24
2016-02-04 10:50:53,886 - DEBUG - i is the 5, total is 120
2016-02-04 10:50:53,886 - DEBUG - Return value is 120
2016-02-04 10:50:53,886 - DEBUG - End of Program

Recap

  • The logging module lets you display logging messages.
  • Log messages create a breadcrumb trail of what your program is doing.
  • After calling basicConfig() to set up logging, call logging.debug() to create a log message.
  • When done, you can disable the log messages with logging.disable(logging.CRITICAL) (which disables every level below it.)
  • Don't use prin() for log messages; it's hard to remove them all when you're done debugging.
  • The five log levels are: DEBUG, INFO, WARNING, ERROR, and CRITICAL.
  • You can also log to a file instead of the screen with the filename paramater in the basicConfig() function.