Logging Python Tutorial

Welcome to part 22 of the intermediate Python programming tutorial series. We're going to be covering logging in Python .

The idea of Python's logging module is to make your life easier. Have you ever maybe added print functions/statements in your code at various places to note where your code is and what's running? Then maybe commented it out? Maybe you got fancy and created a constant like debug = True, then had some lines like if debug: print(something). If this sounds like you, or if it sounds like something that you might find useful, chances are, you should be using logging instead. Maybe you haven't yet needed to do such things, but, eventually you may find yourself in a situation where you do want to temporarily track what your code is doing, but not always. Using print can help in a pinch, but your life will be easier in the long run if you bake logging into your code early on. With logging, you can both output to console as well as saving to a file, all depending on varying debugging levels you can choose from.

To use logging, you start by importing it, and then setting the basic config:

import logging

logging.basicConfig(level=logging.INFO)

In this case, we're saying we want information on anything from INFO or higher in importance. Your choices are:

DEBUG	Detailed information, typically of interest only when diagnosing problems.
INFO	Confirmation that things are working as expected.
WARNING	An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.
ERROR	Due to a more serious problem, the software has not been able to perform some function.
CRITICAL	A serious error, indicating that the program itself may be unable to continue running.

You can also add in your own levels and ranking if you like. Check out the logging documentation if you want to do this.

This will just output to the console, but you can also save the output to a file, which can be helpful for automated processes, as well as for things like creating logfiles that your users could possibly send to you if they experience issues with your program:

import logging

logging.basicConfig(filename='logfile.log',level=logging.INFO)

To show some examples of logging in use, we're going to use the code that we've been using up to this point in this series. Feel free to apply this to your own code, or the provided code.

blobworld.py:

import pygame
import random
from blob import Blob
import numpy as np

STARTING_BLUE_BLOBS = 15
STARTING_RED_BLOBS = 15
STARTING_GREEN_BLOBS = 15

WIDTH = 800
HEIGHT = 600
WHITE = (255, 255, 255)
BLUE = (0, 0, 255)
RED = (255, 0, 0)

game_display = pygame.display.set_mode((WIDTH, HEIGHT))
pygame.display.set_caption("Blob World")
clock = pygame.time.Clock()

class BlueBlob(Blob):
    
    def __init__(self, x_boundary, y_boundary):
        Blob.__init__(self, (0, 0, 255), x_boundary, y_boundary)

    def __add__(self, other_blob):
        if other_blob.color == (255, 0, 0):
            self.size -= other_blob.size
            other_blob.size -= self.size
            
        elif other_blob.color == (0, 255, 0):
            self.size += other_blob.size
            other_blob.size = 0
            
        elif other_blob.color == (0, 0, 255):
            pass
        else:
            raise Exception('Tried to combine one or multiple blobs of unsupported colors!')
            
        
class RedBlob(Blob):
    def __init__(self, x_boundary, y_boundary):
        Blob.__init__(self, (255, 0, 0), x_boundary, y_boundary)


class GreenBlob(Blob):
    def __init__(self, x_boundary, y_boundary):
        Blob.__init__(self, (0, 255, 0), x_boundary, y_boundary)


def is_touching(b1,b2):
    return np.linalg.norm(np.array([b1.x,b1.y])-np.array([b2.x,b2.y])) < (b1.size + b2.size)

def handle_collisions(blob_list):
    blues, reds, greens = blob_list
    new_blob_dicts = []
    for blue_id, blue_blob in blues.copy().items():
        for other_blobs in blues, reds, greens:
            for other_blob_id, other_blob in other_blobs.copy().items():
                if blue_blob == other_blob:
                    pass
                else:
                    if is_touching(blue_blob, other_blob):
                        blue_blob + other_blob
                        if other_blob.size <= 0:
                            del other_blobs[other_blob_id]
                        if blue_blob.size <= 0:
                            del blues[blue_id]
                            
    return blues, reds, greens
                     
def draw_environment(blob_list):
    game_display.fill(WHITE)
    blues, reds, greens = handle_collisions(blob_list)
    for blob_dict in blob_list:
        for blob_id in blob_dict:
            blob = blob_dict[blob_id]
            pygame.draw.circle(game_display, blob.color, [blob.x, blob.y], blob.size)
            blob.move()
            blob.check_bounds()

    pygame.display.update()
    return blues, reds, greens

def main():
    blue_blobs = dict(enumerate([BlueBlob(WIDTH,HEIGHT) for i in range(STARTING_BLUE_BLOBS)]))
    red_blobs = dict(enumerate([RedBlob(WIDTH,HEIGHT) for i in range(STARTING_RED_BLOBS)]))
    green_blobs = dict(enumerate([GreenBlob(WIDTH,HEIGHT) for i in range(STARTING_GREEN_BLOBS)]))

    while True:
        for event in pygame.event.get():
            if event.type == pygame.QUIT:
                pygame.quit()
                quit()
        blue_blobs, red_blobs, green_blobs = draw_environment([blue_blobs,red_blobs,green_blobs])
        clock.tick(60)

if __name__ == '__main__':
    main()

blob.py:

import random


class Blob:

    def __init__(self, color, x_boundary, y_boundary, size_range=(4,8), movement_range=(-1,2)):
        self.size = random.randrange(size_range[0],size_range[1])
        self.color = color
        self.x_boundary = x_boundary
        self.y_boundary = y_boundary
        self.x = random.randrange(0, self.x_boundary)
        self.y = random.randrange(0, self.y_boundary)
        self.movement_range = movement_range

    def move(self):
        self.move_x = random.randrange(self.movement_range[0],self.movement_range[1])
        self.move_y = random.randrange(self.movement_range[0],self.movement_range[1])
        self.x += self.move_x
        self.y += self.move_y

    def check_bounds(self):
        if self.x < 0: self.x = 0
        elif self.x > self.x_boundary: self.x = self.x_boundary
        
        if self.y < 0: self.y = 0
        elif self.y > self.y_boundary: self.y = self.y_boundary

Now, in general, any operation that might have a LOT of output should be DEBUG level only. If you're outputting to a console, doing a lot of outputting will cost processing. If you're logging to a file, it's even more imperative to be careful, since, logfiles can quickly grow and get out of hand, unbenknownst to the user. For example, on two occasions, I had MySQL log files that got so large that they exhausted all of my storage space, then, on new insert statements, the server would fail, and then, from here, the MySQL server can just entirely stop, and you won't even be able to connect. When that happens, it's not immediately clear that the real issue is you ran out of space. Anyway, that's just one example from my experience, back to the tutorial.

After picking the level of warning that you want, you can throw in logging wherever you please. For example, maybe we want to have just a simple informative notification whenever blobs are interacting with each other. We can modify the __add__ method:

    def __add__(self, other_blob):
        logging.info('Blob add op: {} + {}'.format(str(self.color), str(other_blob.color)))
        if other_blob.color == (255, 0, 0):
            self.size -= other_blob.size
            other_blob.size -= self.size
            
        elif other_blob.color == (0, 255, 0):
            self.size += other_blob.size
            other_blob.size = 0
            
        elif other_blob.color == (0, 0, 255):
            pass
        else:
            raise Exception('Tried to combine one or multiple blobs of unsupported colors!')

The message we put in here will be output to the console (assuming you've imported logging). After importing logging, you can begin using it, and the default logging level is WARNING. You can change it with logging.basicConfig(level=logging.DEBUG) for example.

To exemplify a fast-outputting DEBUG-only level task, let's modify a line in our handle_collisions function:

def handle_collisions(blob_list):
    blues, reds, greens = blob_list
    new_blob_dicts = []
    for blue_id, blue_blob in blues.copy().items():
        for other_blobs in blues, reds, greens:
            for other_blob_id, other_blob in other_blobs.copy().items():
                logging.debug('Checking if blobs touching {} + {}'.format(str(blue_blob.color), str(other_blob.color)))
                if blue_blob == other_blob:
                    pass
                else:
                    if is_touching(blue_blob, other_blob):
                        
                        blue_blob + other_blob
                        if other_blob.size <= 0:
                            del other_blobs[other_blob_id]
                        if blue_blob.size <= 0:
                            del blues[blue_id]

In that final for loop, the first line is a debug-level log. Set the debugging level to DEBUG: logging.basicConfig(level=logging.DEBUG), and go ahead and run it. It should be a bunch of output like:

DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 255, 0)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
INFO:root:Blob add op: (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)
DEBUG:root:Checking if blobs touching (0, 0, 255) + (0, 0, 255)

Let's raise the debugging to INFO: logging.basicConfig(level=logging.INFO). Now, once in a while, you should get: INFO:root:Blob add op: (0, 0, 255) + (255, 0, 0), but that's it. Now, let's add a logging file to log to: logging.basicConfig(filename='logfile.log',level=logging.INFO)

Now, rather than outputting to console, you will get the logging data sent to the file.

In the next tutorial, we're going to cover how to better handle and save information on errors when you're running programs automatically.

The next tutorial: Headless Error Handling Python Tutorial