Want to Write Quality Code? Try Logging in Python

 

Contents

Introduction

Logging Module

Configurations

Basic Configuration

File Configuration

Logging from Multiple Modules

Logging from Multiple Threads

Context Logging and Filter

Best Practices

Conclusion

References

Introduction

Logging is an important part of software development, which can help endless hours of debugging. If used it right we can use it for different flow analysis, how and what to scale, health checks, issue analysis, performance checks, security scan, audit and so on. 

Calling log calls from the program, indicates certain events has occurred during the timestamp, from where, may be IP address and other additional information. Event will hold the descriptive message, eg: dynamic or static values, importance of message (debug, info, warn, error). 

Python provides a logging system as a part of its standard library, so you can quickly add logging to your application.

Logging Module

The logging module readily available, adding logs to your module is as easy as below.

Code:

import logging

logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

Output:

WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

As seen above by default, there are 5 levels of logging, which indicate the severity of events. Each levels have corresponding severity associated. Below is the levels defined based on the severity in increasing order:

Level	Used For
DEBUG	Detailed messages, usually for diagnosing problems
INFO	Confirmation or Facts of working as expected
WARNING	Alarming for future breaks, but until now the application is working
ERROR	Due to serious problem in the function
CRITICAL	Due to serious problem, the program failed to continue to execute

Table 1: Usage of each Log Levels

From the above you have noticed the debug and info messages are not logged. Because the default severity is set to WARNING. This will have messages printed of the level WARNING and above.

We will see below how to change the severity levels by changing the configurations. Also later how to change in format of the output.

Configurations

There are can be several configurations done. Such as, 

Parameter	Description
level	Root logger will be set to the specified severity level
filename	Name of the file logs should be stored
filemode	Mode in which the log file should be opened, default is “a” append mode
format	Pattern the log message to be written
datefmt	Format in which date should be written

Table 2: Commonly used log parameters

Basic Configuration

We can use the below method to configure the logging:

Code:

import logging
logging.basicConfig(level=logging.DEBUG, filename='/project/log/app.log', filemode='w', format='%(asctime)s - %(message)s', datefmt='%d-%b-%y %H:%M:%S')

logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

Output: (from app.log)

27-Nov-21 07:28:09 - This is a debug message
27-Nov-21 07:28:09 - This is an info message
27-Nov-21 07:28:09 - This is a warning message
27-Nov-21 07:28:09 - This is an error message
27-Nov-21 07:28:09 - This is a critical message

Here we could see below points:

• Debug and info message is logged, as the logging level is DEBUG and above

• Log contents are not displayed in stdout, rather saved in the file called app.log

• Message format is different from before, it works as per the format given by us in the format parameter

• Same applies to the date format

File Configuration

Before we get to know about file configuration, lets look how logging works:

Logging Flow:

So far, we have seen the default logger named root, which is used by the logging module whenever its functions are called directly like this: logging.debug(). But we can or should define your own logger.

The logging module, follows the modular approach and has split the functionalities in below components:

• Logger: 

  • This is exposed to application code to directly use.

  • Logging is performed by calling methods on instances of the Logger class.

  • Logger class performs three duties

    • Expose several methods to application code so that applications can log messages at runtime. A good convention is using the module name to name the loggers, as intuitively obvious where events are logged just from the logger name.

      • logger = logging.getLogger(__name__)

    • Logger objects determine which log messages to act upon based upon severity or filter objects.

      • Logger.setLevel()

      • Logger.addFilter()and Logger.removeFilter()

    • Logger objects pass along relevant log messages to all interested log handlers.

      • Logger.addFilter()and Logger.removeFilter()

• LogRecord: 

  • Loggers automatically create LogRecord objects that have all the information related to the event being logged, like the name of the logger, the function, the line number, the message, and more.

• Filter:

  • Provide a finer grained facility for determining which log records to output. Later we will see an example using Filters

• Handler: 

  • Sends the LogRecords (created by loggers) to the appropriate destination.

  • For example it could be file, stdout, http, etc. 

  • For each destination Handler is have sub class: such as file: FileHandler, stdout: StreamHandler, http: HTTPHandler.

  • Logger objects can add zero or more handler objects to themselves with an addHandler() method.

• Formatter:

  • Specify the format of LogRecord, by mentioning in the list attributes needs to be logged to be written in the final output.

Fig1: Logging Flow

Credits: https://docs.python.org/3/howto/logging.html

We can configure logging in three ways:

• Creating loggers, handlers, and formatters explicitly using Python code that calls the configuration methods.

  • In the below example:

    • Created a logger with the same module name.

    • Create a console handler with the debug level set

    • Create formatter with time, module name, level and message

Code:

import logging

# create logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Output:

$ python handlerconfig.py
2021-11-28 14:45:45,096 - __main__ - DEBUG - debug message
2021-11-28 14:45:45,097 - __main__ - INFO - info message
2021-11-28 14:45:45,097 - __main__ - WARNING - warn message
2021-11-28 14:45:45,097 - __main__ - ERROR - error message
2021-11-28 14:45:45,097 - __main__ - CRITICAL - critical message

• Creating a logging config file and reading it using the fileConfig() function.

  • In the below example:

    • Created a logger with the 'simpleExample' logger name.

    • Create a console handler with the debug level set, and file handler with info level set hence the debug log will not be printed

    • Both the configurations are taken from the logging.conf file

    • Its important to have the handler and logger set for 'root'

    • In file handler:

      • The propagate entry is set to 1 to indicate that messages must propagate to handlers higher up the logger hierarchy from this logger, or 0 to indicate that messages are not propagated to handlers up the hierarchy. 

      • The qualname entry is the hierarchical channel name of the logger, that is to say the name used by the application to get the logger.

    • FileRotateHandler

      • Here we have used file rotate handler, to avoid logging all the content in a single huge file

      • We have configured maxBytes=10, about 10bytes written the will be rotated

      • backupcount=5, it says how many rotated files needs to be kept rest will be cleaned.

    • Create formatter with time, module name, level and message 

Code:

fileconfig.py

import logging
import logging.config

logging.config.fileConfig('logging.conf')

# create logger
logger1 = logging.getLogger('simpleExample')
logger = logging.getLogger()

# 'application' code
logger.debug('debug message')
logger1.info('info message')
logger1.warning('warn message')
logger1.error('error message')
logger1.critical('critical message')

loggin.conf

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler,simpleFileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=INFO
handlers=simpleFileHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
formatter=simpleFormatter
args=(sys.stdout,)

[handler_simpleFileHandler]
class=handlers.RotatingFileHandler
formatter=simpleFormatter
maxBytes=10
args=('test.log','a',10,5)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

Output:

$ python fileconfig.py
2021-11-28 17:47:26,858 - root - DEBUG - debug message
$ tail test.log*

==> test.log <==

2021-11-28 18:48:38,520 - simpleExample - CRITICAL - critical message

==> test.log.1 <==

2021-11-28 18:48:38,519 - simpleExample - ERROR - error message

==> test.log.2 <==

2021-11-28 18:48:38,518 - simpleExample - WARNING - warn message

==> test.log.3 <==

2021-11-28 18:48:38,517 - simpleExample - INFO - info message

• Creating a dictionary of configuration information and passing it to the dictConfig() function.

  • This is the simple example by using yaml format as configuration

  • The dictConfig expects in input to be in the dict object, so we can have dict defined and call the logger method.

  • Below example creates a logger with the same module name.

  • Create a console handler with the debug level set

  • Create formatter with time, module name, level and message

Code:

dict_filelog.py

import logging

import logging.config

import yaml

with open('dict_config.yaml', 'r') as f:

config = yaml.safe_load(f.read())

logging.config.dictConfig(config)

logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

logger.info('This is a info message')

logger.error('This is a error message')

dict_config.yaml

version: 1

formatters:

simple:

format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'

handlers:

console:

class: logging.StreamHandler

level: INFO

formatter: simple

stream: ext://sys.stdout

loggers:

sampleLogger:

level: DEBUG

handlers: [console]

propagate: no

root:

level: DEBUG

handlers: [console]

Output:

2021-11-28 19:25:00,508 - __main__ - DEBUG - This is a debug message

2021-11-28 19:25:00,508 - __main__ - INFO - This is a info message

2021-11-28 19:25:00,509 - __main__ - ERROR - This is a error message

Note:

• When no configuration is provided, the events are output using a handler of last resport, which is stored in logging.lastResort.

• This acts as StreamHandler, which writes the messages to sys.stderr.

• Handler's level is set to WARNING 

• The behaviour of the logging package in these circumstances is dependent on the Python version. We are seeing here for python 3.2 and above.

Logging from Multiple Modules

• Calling multiple times same getLogger(“NAME”) will return a reference to the same object.

• Can be used across modules to get the same object but it requires to be same Python interpreter process. 

• Also the application code can define and configure a parent logger in one module and create (but not configure) a child logger in a separate module, and all logger calls to the child will pass up to the parent.

• The parent and child mapping is done by the name of the logger, please find the example below in the getLogger method

  • parent: getLogger('test_app')

  • child: getLogger('test_app.sub_app') # here all the configuration is inherited from the parent

Code:

File: main_app.py

import sys

import logging

import sub_app

# Create a custom logger with "test_app"

logger = logging.getLogger("test_app")

logger.setLevel(logging.DEBUG)

# Create handlers

# create console handler with debug log level

c_handler = logging.StreamHandler(sys.stdout)

# create file handler with error log level

f_handler = logging.FileHandler('file.log', 'w')

f_handler.setLevel(logging.WARNING)

# Create formatters and add it to handlers

c_format = logging.Formatter('%(name)s - %(levelname)s - %(message)s')

f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

c_handler.setFormatter(c_format)

f_handler.setFormatter(f_format)

# Add handlers to the logger

logger.addHandler(c_handler)

logger.addHandler(f_handler)

print(c_handler)

print(logger)

logger.debug('This is a debug from main module')

logger.info('This is a info from main module')

logger.warning('This is a warning from main module')

logger.error('This is an error from main module')

logger.info("Before calling the sub_app_function")

sub_app.sub_app_function()

logger.info("After calling the sub_app_function")

File: sub_app.py

import logging

# create logger

module_logger = logging.getLogger('test_app.sub_app')

def sub_app_function():

module_logger.error("Debug message from sub_app")

Output:

% python multiple_modules_logger.py

<StreamHandler <stdout> (NOTSET)>

<Logger test_app (DEBUG)>

test_app - DEBUG - This is a debug from main module

test_app - INFO - This is a info from main module

test_app - WARNING - This is a warning from main module

test_app - ERROR - This is an error from main module

test_app - INFO - Before calling the sub_app_function

test_app.sub_app - ERROR - Debug message from sub_app

test_app - INFO - After calling the sub_app_function

% cat file.log

2021-11-28 23:26:04,332 - test_app - WARNING - This is a warning from main module

2021-11-28 23:26:04,332 - test_app - ERROR - This is an error from main module

2021-11-28 23:26:04,332 - test_app.sub_app - ERROR - Debug message from sub_app

Logging from Multiple Threads

• Logging from multiple threads is as simple as normal process

• To differentiate the logs generated from each thread, threadName can be used

• Below example shows the logging from the main thread and another one more thread

Code:

import logging

import threading

import time

def worker(arg):

while not arg['stop']:

logging.debug('Hi from thread 2')

time.sleep(0.5)

def main():

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(name)s - %(levelname)s - %(threadName)s - %(message)s')

info = {'stop': False}

thread = threading.Thread(target=worker, args=(info,))

thread.start()

while True:

try:

logging.debug('Hello from main thread')

time.sleep(1.0)

except KeyboardInterrupt:

info['stop'] = True

break

thread.join()

if __name__ == '__main__':

main()

Output:

% python threadlogger.py 

2021-11-28 22:38:54,207 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:54,207 - root - DEBUG - MainThread - Hello from main thread

2021-11-28 22:38:54,712 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:55,212 - root - DEBUG - MainThread - Hello from main thread

2021-11-28 22:38:55,214 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:55,716 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:56,217 - root - DEBUG - MainThread - Hello from main thread

2021-11-28 22:38:56,220 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:56,725 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:57,221 - root - DEBUG - MainThread - Hello from main thread

2021-11-28 22:38:57,229 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:57,734 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:58,223 - root - DEBUG - MainThread - Hello from main thread

2021-11-28 22:38:58,236 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:58,738 - root - DEBUG - Thread-1 - Hi from thread 2

2021-11-28 22:38:59,226 - root - DEBUG - MainThread - Hello from main thread

2021-11-28 22:38:59,239 - root - DEBUG - Thread-1 - Hi from thread 

Context Logging and Filter

• LoggerAdapter

  • Sometimes you want logging output to contain contextual information in addition to the parameters passed to the logging call.

  • For example, in a networked application, it may be desirable to log client-specific information in the log (e.g. remote client’s username, or IP address). 

  • An easy way in which you can pass contextual information to be output along with logging event information is to use the LoggerAdapter class. 

  • In the below example we are adding the host_ip, to all the log events.

• Filter

  • Filter can be used for both at the logger level or by handler level.

  • Such as they can stop certain information to be passed to be logger

  • Also inject additional information into the LogRecord which will be logged

  • In our below example, we are using filter to allow only certain levels to be logged.

    • Though the log level is set to DEBUG, we are only allowing INFO and ERROR to be logged.

  • Note: These are cooked up examples, in real life the usecases varies.

Code:

import sys

import logging

host_ip = "localhost"

class StdoutFilter(logging.Filter):

def filter(self, record):

return record.levelno in (logging.INFO, logging.ERROR)

logger = logging.getLogger('sampleApp')

logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler(sys.stdout)

handler.addFilter(StdoutFilter())

formatter = logging.Formatter('%(host_ip)s - %(asctime)s - %(name)s - %(levelname)s - %(message)s')

handler.setFormatter(formatter)

logger.addHandler(handler)

logger = logging.LoggerAdapter(logger, {'host_ip': host_ip})

print(logger)

logger.debug('This is a debug from main module')

logger.info('This is a info from main module')

logger.warning('This is a warning from main module')

logger.error('This is an error from main module')

Output:

<LoggerAdapter sampleApp (DEBUG)>

localhost - 2021-11-29 00:26:18,566 - sampleApp - INFO - This is a info from main module

localhost - 2021-11-29 00:26:18,567 - sampleApp - ERROR - This is an error from main module

Best Practices

• Create loggers using getlogger function

• Using appropriate log levels in different regions

• Create module level loggers

• Use rotating file handler

• Include timestamp in logs, preferred to use standard format exists, and it’s called ISO-8601.

  • Eg:

import logging

logging.basicConfig(format='%(asctime)s %(message)s')

logging.info('Example of logging with ISO-8601 timestamp')

• Avoid opening same log file multiple times

• Do not pass logger as parameter in class or methods

Conclusion

As seen the logging module is very flexible, customisable and ease to use. There are much more features such as,

• context based logging

• customisable log records

• logging to multiple destination and servers

• multiple processes logging to same file log

• speaking logging messages

And many more, readymade code is available in the python cookbook URL: https://docs.python.org/3/howto/logging-cookbook.html.

It would be great to start using if you haven’t been using logging in your applications. You will see the difference and increase the code quality by adding this. Happy Logging!

References

https://realpython.com/python-logging/

https://docs.python.org/3/howto/logging.html

https://docs.python.org/3/howto/logging-cookbook.html

https://www.thepythoncode.com/media/articles/logging-in-python.PNG [credits for the header image]

Original Blog Posted in OSFY

https://www.opensourceforu.com/2022/04/an-introduction-to-low-code-and-no-code-test-automation-tools/

For further research and updates maintaining the blog here.