Advanced Logging for Better Troubleshooting

Logging debug or error messages is crucial for any application as it helps developers supervise and troubleshoot the application efficiently.

Python provides a module named logging to log messages. These messages can be written to various destinations, including files, for better monitoring and debugging of programs.

In this article, you’ll learn:

• Logging a simple message using the logging module
• Severity level of the messages
• Configuring theloggingmodule to logINFOandDEBUGlevel messages and logging events to a file
• Logging the variable data
• Formatting the log messages using LogRecord attributes
• Advanced Configurations: Loggers, Handlers and Formatters
• Practical example

Logging Messages

Here’s an example of logging a simple message on the console using the logging module in Python.

# Imported logging module
import logging

num = 0
# Logs a warning message
logging.warning("Entering Infinite Loop")
while True:
    if num % 2 == 0:
        print(num)
    num += 1

The code above runs endlessly, thus when it runs, a warning message will be logged to alert the user.

Here, logging.warning() has been used to log the warning message to the console. The warning here is the severity level of the message.

WARNING:root:Entering Infinite Loop
0
2
4
.
.
.

As you can see, the output begins by logging the warning message “Entering Infinite Loop” in the pattern WARNING:root:<message>, indicating the severity level and name assigned by the logger respectively.

Similar to this, the logging module offers several levels to show the events' severity.

# Imported logging module
import logging

logging.info("Used to log info message")
logging.debug("Used to log debug message")
logging.warning("Used to log warning message")
logging.error("Used to log error message")
logging.critical("Used to log critical message")

There are 5 different levels to log messages of different severity levels.

• INFO
• DEBUG
• WARNING
• ERROR
• CRITICAL

WARNING:root:Used to log warning message
ERROR:root:Used to log error message
CRITICAL:root:Used to log critical message

You can observe that the output is missing the first two messages. Why is it so? The messages with a severity level of WARNING and above are logged by the logging module.

You can log INFO and DEBUG messages by applying some configurations.

Configuring Logging Module

The logging module can be configured to unleash more power to let you do more stuff when logging events.

Basic Configuration

The logging module includes a function called basicConfig() that helps in configuring the logging system. Here's an example of configuring logging module to log INFO level message.

import logging

# Configuring logging
logging.basicConfig(level=logging.INFO)
logging.info("This info will be printed")

The logging module is configured in the code above to log a INFO message by passing the keyword argument level to the basicConfig() function and setting it to logging.INFO.

When you run the above code, the severity level INFO message will now be printed.

INFO:root:This info will be printed

Similarly, you can log DEBUG messages by setting the level argument to the value logging.DEBUG.

import logging

# Configuring logging to log DEBUG msg
logging.basicConfig(level=logging.DEBUG)
logging.debug("This is a DEBUG message")

--------------------
DEBUG:root:This is a DEBUG message

Logging Event to a File

The basicConfig() function accepts a keyword argument called filename to specify the file in which the event will be logged.

 import logging

# Logging to a file
logging.basicConfig(filename='debug.log', level=logging.DEBUG)
logging.debug("This is a DEBUG message")

The message will be logged into the debug.log file and it will be the same as the previous output but in the file instead of the console.

By default, the mode of the file is set to append (a) mode and you can change this by specifying the filemode parameter. Additionally, you can use the encoding parameter to specify the file's encoding.

import logging

# Logging to a file
logging.basicConfig(filename='debug_new.log',
                    filemode='w',
                    encoding='utf-8',
                    level=logging.DEBUG)
logging.debug("Debugging starts from here.")

In this example, the file is set to write (filemode='w') mode and encoding is set to 'utf-8'. This time the message will be logged into the debug_new.log file.

How to Log Variable Data?

Logging variable data is similar to formatting a string using the % operator. This helps when you want to include dynamic data in logged messages.

import logging

# Logging variable data
logging.error("%s: Not found - Status: %s", 404, "Fail")

In this code, two placeholders (%s) are present in the string that will help Python interpolate the string with the specified values i.e., 404 and 'Fail', and they will be placed in the same position as they appear.

When you run the code, you’ll get the following output.

ERROR:root:404: Not found - Status: Fail

Formatting the Logged Messages

You now know how to log variable data; in this section, you’ll utilize it to format the logged messages.

You can choose the format of your logged message to be displayed in the console or a file.

import logging

logging.basicConfig(format='%(levelname)s - %(message)s')
logging.warning("Things are getting worse.")

--------------------
WARNING - Things are getting worse.

As you can see, the message is logged with the formatting that the format argument set. The severity (levelname) is shown first, then the event's description (message).

You may be wondering now where the message and levelname came from. Well, these are the attributes specified by the LogRecord. Similarly, LogRecord has more attributes.

import logging

logging.basicConfig(
    format='%(levelname)s: %(message)s - %(asctime)s', 
    level=logging.DEBUG
)
logging.debug("Debugging started at")

Now, this time a new attribute asctime is added to the message that logs the date and time of the event. The output looks like the following.

DEBUG: Debugging started at - 2024-06-12 16:37:55,996

You can take more control of formatting the date and time of the event by passing the datefmt argument in the basicConfig().

import logging

logging.basicConfig(
    format='%(levelname)s: %(message)s - %(asctime)s',
    datefmt='%d/%m/%Y %I:%M:%S %p', 
    level=logging.DEBUG
)
logging.debug("Debugging started at")

--------------------
DEBUG: Debugging started at - 12/06/2024 05:55:38 PM

The date and time looks more readable now due to the string ('%d/%m/%Y %I:%M:%S %p') set by the datefmt argument. You can experiment with the characters within the string just like you would do in the time.strftime(). Here's an example.

import logging

logging.basicConfig(
    format='%(levelname)s: %(message)s - %(asctime)s',
    datefmt='%d %b %Y %a %I:%M:%S %p', 
    level=logging.DEBUG
)
logging.debug("Debugging started at")

--------------------
DEBUG: Debugging started at - 12 Jun 2024 Wed 06:08:20 PM

You can add some more attributes such as file name, module name, process ID, name of the logger, and much more.

So far you’ve learned to log messages at the basic level. In the next section, you’ll learn to log messages at an advanced level such as configuring your logger, sending the log messages over multiple destinations, and much more.

Logging — Advanced Configurations

In this section, you’ll use classes and functions to log messages. The commonly used classes in the logging module are as follows:

• Logger — Used to create logger objects so that logging can be performed by calling different methods on its objects.
• Handler — Used to send log messages to appropriate destinations such as into the file, email, HTTP server, etc.
• Formatter — Used to set the format of the log records in the final output.

Creating Logger Object

import logging

# Create a logger
logger = logging.getLogger("custom_logger")
logger.warning("Warning... Warning...")

In this example, a custom logger named custom_logger is created using logging.getLogger(). When you run this code, you'll get the following output.

Warning... Warning...

This is a simple message without the severity level and logger name even though the name of the logger was specified. This is because the custom logger can’t be configured using basicConfig(). To format this output, you need to use Handlers and Formatters.

An important note:

It is a good practice to name your logger based on module like the following.

logger = logging.getLogger(__name__)

This will keep track of your module/package hierarchy. It means if you are using it in same module, the logger name will be __main__ and if you import this module into another module, then the logger name will the module_name, the name of the module in which it is defined.

The logger object doesn’t log messages of severity level DEBUG and INFO. To log DEBUG or INFO level messages using the custom logger, you need to create a handler.

Creating Handler

Handler objects are responsible for logging records to the specified destinations. There are several handler types such as StreamHandler, FileHandler, HTTPHandler, SMTPHandler and more.

The addHandler() method is used to add one or more handlers to the logger object. You need to add the individual handler to log messages based on categories to different destinations.

After creating a logger object in the previous section, the next step is to create the handler.

# adv_logging.py

import logging

# Create a logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)  # Set the logger's level

# Creating Handlers
# Console handler
cs_handler = logging.StreamHandler()
cs_handler.setLevel(logging.INFO)

# File handler
fl_handler = logging.FileHandler("info.log")
fl_handler.setLevel(logging.ERROR)

In this code, some modifications have been done to the logger object such as the logger’s name changed and the logger’s level has been set to INFO.

Two handlers have been created cs_handler and fl_handler. The first handler (cs_handler) is responsible for sending messages in the console and its level is set to INFO. The second handler (fl_handler) sends the messages to the file name info.log which is set to ERROR level.

Creating Formatters

Formatters are responsible for applying the formatting of the developer’s choice to the final output.

It is similar to the formatting you’ve learned while setting up the basic configurations of the messages using basicConfig(). But here, you need to use a Formatter class of the logging module.

Here’s the extension of the previous code.

...

# Creating Formatters
# Formatter for console
cs_formatter = logging.Formatter(
    '%(asctime)s: %(name)s - %(levelname)s: %(message)s',
    datefmt='%d %b %Y %a %I:%M:%S %p'
)
# Setting formatter to handler
cs_handler.setFormatter(cs_formatter)

# Formatter for file
fl_formatter = logging.Formatter(
    '%(asctime)s: %(name)s - %(levelname)s: %(message)s',
    datefmt='%d %b %Y %a %I:%M:%S %p'
)
# Setting formatter to handler
fl_handler.setFormatter(fl_formatter)

The formatters cs_formatter and fl_formatter have been created. The formatting style of both formatters is identical, and setFormatter() has been used to assign each formatter to its corresponding handler.

To log messages with applied configurations, the final step is to add these handlers (cs_handler and fl_handler) to the logger.

...

# Adding handler to logger
logger.addHandler(cs_handler)
logger.addHandler(fl_handler)

Now add messages to be logged.

...

logger.info("Process started...")
logger.warning("Warning... Warning...")
logger.error("Unusual activity detected...")
logger.critical("System security compromised...")

Output

13 Jun 2024 Thu 03:55:24 PM: __main__ - INFO: Process started...
13 Jun 2024 Thu 03:55:24 PM: __main__ - WARNING: Warning... Warning...
13 Jun 2024 Thu 03:55:24 PM: __main__ - ERROR: Unusual activity detected...
13 Jun 2024 Thu 03:55:24 PM: __main__ - CRITICAL: System security compromised...

Here, the logging.info(), logging.warning(), logging.error(), logging.critical() passed the information to the handlers (cs_haldler and fl_handler).

Since the logger’s level is set to INFO and cs_handler is a StreamHandler set to INFO level printed the messages with specified formatting of INFO level and above in the console.

The fl_handler is a FileHandler which is set to ERROR level will log the messages in the info.log file of the level ERROR and above.

13 Jun 2024 Thu 03:55:24 PM: __main__ - ERROR: Unusual activity detected...
13 Jun 2024 Thu 03:55:24 PM: __main__ - CRITICAL: System security compromised...

You can see that the name of the logger is logged as __main__ which means the source file is executed directly. If you import this module to another file and then run it, the name of the logger will change.

Create a new Python file, in this case, sample_log.py. Import the source file into it, and then run the file.

# sample_log.py
import adv_logging

When you run this file, your output will look like the following.

13 Jun 2024 Thu 03:58:12 PM: adv_logging - INFO: Process started...
13 Jun 2024 Thu 03:58:12 PM: adv_logging - WARNING: Warning... Warning...
13 Jun 2024 Thu 03:58:12 PM: adv_logging - ERROR: Unusual activity detected...
13 Jun 2024 Thu 03:58:12 PM: adv_logging - CRITICAL: System security compromised...

The info.log file will look like the following.

13 Jun 2024 Thu 03:55:24 PM: __main__ - ERROR: Unusual activity detected...
13 Jun 2024 Thu 03:55:24 PM: __main__ - CRITICAL: System security compromised...
13 Jun 2024 Thu 03:58:12 PM: adv_logging - ERROR: Unusual activity detected...
13 Jun 2024 Thu 03:58:12 PM: adv_logging - CRITICAL: System security compromised...

Practical Example

You’ve learned to create the logger and handlers with specified formatting. Now you can create a template for logging the messages and include it in your project code to log messages dynamically.

Here’s a practical example of creating a logger with advanced configurations and then including it in the main script to log messages in a file.

First, create a Python file, in this case, log_temp.py. This file holds a template for logging a message.

# log_temp.py
import logging

# Create a logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

# File handler
fl_handler = logging.FileHandler("log_file.log")
fl_handler.setLevel(logging.INFO)

# Formatter for file
fl_formatter = logging.Formatter(
    '%(name)s - %(levelname)s: %(message)s'
)
# Setting formatter to handler
fl_handler.setFormatter(fl_formatter)

# Adding handler to logger
logger.addHandler(fl_handler)

# Function to log INFO level msg
def info_msg(msg):
    logger.info(msg)
# Function to log WARNING level msg
def warning_msg(msg):
    logger.warning(msg)
# Function to log ERROR level msg
def error_msg(msg):
    logger.error(msg)

This code is pretty much the same as you saw in the previous sections but this time three functions are added: info_msg(), warning_msg(), and error_msg().

These functions log INFO, WARNING, and ERROR level messages. The messages will be provided by the developer.

This template uses FileHandler to log messages in a file of level INFO and above.

Now, create another Python file, in this case, script.py, and dump the following code or write your own Python program.

# Imported template
import log_temp

try:
    num = 0
    # Logs a warning message
    log_temp.warning_msg("Entering Infinite Loop")
    while True:
        if num % 2 == 0:
            print(num)
        num += 1

except KeyboardInterrupt:
    # Logs an error message
    log_temp.error_msg("Program Interrupted")

# Logs an info
log_temp.info_msg("Program continued")
print("Exited infinite loop")

This code runs infinitely and when it runs, it logs a warning message and if the loop is interrupted, it logs an error message followed by the info that the program continued after exiting the loop.

When you run the script.py file, you'll get these details logged into the log_file.log file.

log_temp - WARNING: Entering Infinite Loop
log_temp - ERROR: Program Interrupted
log_temp - INFO: Program continued

When the code starts executing, a warning message is logged, and then when the program gets interrupted, an error message is logged followed by the info message that provides info that the program continued after interruption.

Conclusion

Keeping log records of the applications can help better supervise and troubleshoot them. Python provides a standard library named logging for recording log messages for your applications.

You can apply basic and advanced configurations to the logging module to unleash more power. You can log messages in the console as well as to various destinations like inside a file, email, HTTP connection, etc.

🏆Other articles you might be interested in if you liked this one

✅Type hints in Python — Callable objects, Return values, and more?

✅Best Practices: Positional and Keyword Arguments in Python

✅Yield Keyword in Python with Examples?

✅Create a WebSocket Server and Client in Python.

✅Create and Interact with MySQL Database in Python.

✅Understanding the use of global keyword in Python.

That’s all for now

Keep Coding✌✌