Stop Printing - Start Logging

Posted on Sa 05 September 2020 in production-code

One Lesson that everyone will learn (maybe the hard way) is - that programs, once it leaves the development stage and your IDE - anything can happen to it. No matter how much effort you put into it, how many bugs you fixed, errors you anticipated - something will cause your program to behave differently from what you intended, maybe even breaking it completely. In this cases you will need to figure out:

  1. Is my program still alive
  2. What is it currently doing / what was it doing
  3. In some cases - what where it's last words ?

Since theory and everything is nice - lets make a little more practical by using an example that we will transform:

"""Start situation for Not-Logged-Code."""
import random
import time


def main():
    """Do some instable magic indefinetly and hope nothing breaks."""
    cycle = 0
    while True:

        print(f"{time.time()} - Start cycle {cycle}")
        do_unstable_magick(cycle)
        print(f"{time.time()} -  Finished cycle {cycle}")
        time.sleep(5)


def do_unstable_magick(counter: int):

    x = random.random()
    print(x)
    x -= counter / 10000
    if x <0.0001:
        raise EnvironmentError("Something went wrong")
    elif x <0.5:
        print("Cycle {counter} was unsuccessful")
    else:
        print("Cycle {counter} was unsuccessful")


if __name__ == '__main__':
    main()

Note that most of the output is due to print and the longer the code runs the more likely it becomes that the do_unstable_magic function will create an error - as in real life.

If now this programs crashes at some point and someone tells you to investigate and fix what went wrong. As you cannot recreate what has happened without any informations with this program you would be screwed and domed to make some try and error locally. As this is neither efficient, productive nor fun - we need to think about this scenarios already in the development stage. Seemingly the print function was not a good approach. It did work quite nicely while we were still in our local environment and executing the code manually but there are several disadvantages these statements do have:

  1. They write only to std.out - are only visible in an interactive session
  2. There is no way to differentiate base on severity or importance of information
  3. You cannot silence them easily if you create a library or similar

The proper way to handle this would be to use a so called Logger. These kind of object offer a more versatile way of handling information output by allowing for differentiation of information based on their priority ( e.g. debug, info, warning, error ...). Further we can also allow for multiple output-formats - also known as sinks. The most basic sink that we already used is the std.out - that is what print is using.

Let us look at a simple example:

import logging


logging.debug('This message will neither be visble nor in the file ')
logging.info('This messgae will printed and written to the file ')
logging.warning('And this, too')
logging.error('this as well')

Simply importing logging and configuring it with the baseConfig function enables us to directly replace any print with logging. The next best feature.

Let us take this to our example code an directly take the first step of improvement.

"""Step 1 of refactoring Not-Logged-Code.
1. We import the logging module.
2. We give it some basic config.
3. We replace prints with different levels of logs."""

import logging # added logging
import random
import time


def main():
    """Do some instable magic indefinetly and hope nothing breaks."""
    logging.basicConfig() # create a baseconfiguration s.t. we cann now log
    cycle = 0
    while True:

        logging.info(f"{time.now()} - Start cycle {cycle}") # changed from print to info
        do_unstable_magick(cycle)
        logging.info(f"{time.nos()} -  Finished cycle {cycle}")


def do_unstable_magick(counter: int):
    x = random.random()
    x -= counter / 10000
    logging.debug(x)
    if x <0.0001:
        raise EnvironmentError("Something went wrong")
    elif x <0.5:
        logging.debug("Cycle {counter} was unsuccessful") # changed from print to debug
    else:
        logging.debug("Cycle {counter} was unsuccessful")


if __name__ == '__main__':
    main()

Though that was easy and we now get more information like time and level - but it still would have prevented our lack of information.

So next we want save our output and therefor need to use a File-Sink. That way messages wont be lost but preserved in a log-file. To achieve this we only add the filename argument and set the respective level - done.

import logging

logging.basicConfig(filename='simple_logging.log',level=logging.INFO)
logging.debug('This message will neither be visble nor in the file ')
logging.info('This messgae will printed and written to the file ')
logging.warning('And this, too')
logging.error('this as well')

Now things start to get interesting from here. As we are able to differentiating between levels ( debug, etc) and sinks (std.out, files, etc.) we could combine both and filter which message should go where and even duplicate sinks for different levels. As an example we can save our information that we need for debugging to a log file that we can read later while only those on an error gets printed directly. This combination allows for many different combinations e.g. having multiple file-sinks one for errors and one for debug statements which you can then treat separately.

import logging

file_sink = logging.FileHandler("filehandler.log")
file_sink.setLevel(logging.DEBUG)

std_sink = logging.StreamHandler()
std_sink.setLevel(logging.WARNING)

logger = logging.getLogger("SinkLogger")
logger.addHandler(std_sink)
logger.addHandler(file_sink)


logging.debug('This message will neither be visble nor in the file ')
logging.info('This messgae written to the file ')
logging.warning('This message will be printed and written')
logging.error('this as well')

Now we can take the next big step with our project and enable the mechanism that can save us time and motivation in case of an issues:

"""Step 2 of refactoring Not-Logged-Code.
1. We now add sinks to differentiate which information should be seen where.
2. we use the created logger explicitly and not the genereal module anymore."""

import logging # added logging
import random
import time


def main():
    """Do some instable magic indefinetly and hope nothing breaks."""
    logger = configure_logger() # create a baseconfiguration s.t. we cann now log
    cycle = 0
    while True:

        logger.info(f"{time.now()} - Start cycle {cycle}") # changed from print to info
        do_unstable_magick(cycle, logger)
        logger.info(f"{time.nos()} -  Finished cycle {cycle}")

def configure_logger() -> logging.Logger:
    file_sink = logging.FileHandler("debug.log")
    file_sink.setLevel(logging.DEBUG)

    file_sink = logging.FileHandler("info.log")
    file_sink.setLevel(logging.INFO)

    std_sink = logging.StreamHandler()
    std_sink.setLevel(logging.WARNING)

    logger = logging.getLogger("SinkLogger")
    logger.addHandler(std_sink)
    logger.addHandler(file_sink)
    return logger

def do_unstable_magick(counter: int, logger: logging.Logger):
    x = random.random()
    x -= counter / 10000
    logger.debug(x)
    if x <0.0001:
        raise EnvironmentError("Something went wrong")
    elif x <0.5:
        logger.debug("Cycle {counter} was unsuccessful") # changed from print to debug
    else:
        logger.debug("Cycle {counter} was unsuccessful")


if __name__ == '__main__':
    main()

Now all we need to do is to deploy the project and we will automatically keep a long history of errors to analyze the reliability or debugging. But writing every single debug information might cause the file to explode?! If we let this project run for weeks or month we will run into two issues if the file will grow tremendously large:

  1. reading, copying or filtering it will become slow if not impossible
  2. the file might grow too large for the file system and cause the system to crash

Therefore we need to start thinking about a cleanup. We can either do that on the system level or within our code. But as most of the obvious task in python this is already wrapped together in an (awesome) library called loguru. Personally, i haven been working with it since a long time and it is part of nearly all my productional services as it is easy to use and reduces the boilerplate code to a minimum. Moreover it ensures that my logging-practice stays homogeneous through out my projects. This library was original developed by delgan and i highly recommend you to check the repo out.

All we need to do now is to install loguru using pip install loguru and specify two arguments - one for rotation and one for retention - done.

import time
from loguru import logger

logger.add("debug.log",rotation="10MB", retention=5, level="DEBUG")
logger.add("error.log",rotation="100MB", retention="100 days", level="ERROR")


while True:
    logger.debug(""" This log will only show up in the debug log which has a shorter retention time
        As such we do not need to worry that this script will create too many log file and the hard drive might get to crowded
        Even if we print this  way to often """)
    logger.info(""" Same goes for this - so we do not need to worry too much about the filesize - even with the loop
     As we only keep five files with this much data we can log to our hearts content without worry """)
    logger.warning("Moreover we could also fill the compress argument which then  compresses all files rotations (or after close) in e.g. gzip or lzma ( or many more) ")
    logger.error("This message will pop up in the error log and as such be available for way longer - so we can see long passt error ")
    time.sleep(1)

Now our log file will automatically rotate every day and as such create a daily debug log. This ensures that the file itself does not grow to big to handle it properly while the retention keeps deleting files older than a week s.t. the do not take too much space on disk.

Finally we can now finish our project by refactoring our code using loguru as following:

"""Step 4 of refactoring Not-Logged-Code.
0. We realized that this is to much boilerplate code that noone wants to read. .
1. Import the loguru model ( after pip-installing it).
2. We finish this by adding a retention and rotation """

import random
import time

from loguru import logger
from loguru._logger import Logger

def main():
    """Do some instable magic indefinetly and hope nothing breaks."""
    logger.add("debug.log", level="DEBUG", retention="2 weeks", rotation="1 day")
    logger.add("info.log", level="INFO", retention="2 month", rotation="1 week")
    cycle = 0
    while True:

        logger.info(f"{time.now()} - Start cycle {cycle}") # changed from print to info
        do_unstable_magick(cycle, logger)
        logger.info(f"{time.nos()} -  Finished cycle {cycle}")


def do_unstable_magick(counter: int, logger: Logger):
    x = random.random()
    x -= counter / 10000
    logger.debug(x)
    if x <0.0001:
        raise EnvironmentError("Something went wrong")
    elif x <0.5:
        logger.debug("Cycle {counter} was unsuccessful") # changed from print to debug
    else:
        logger.debug("Cycle {counter} was unsuccessful")


if __name__ == '__main__':
    main()

python logging loguru