The Ultimate Guide To Python Logging
Python has the wonderful package for recording logs called logging. You can find it in the standard library. Many developers think that it is overcomplicated and not pythonic. In this post I will try to convince you that it is not true. We are going to explore how this package is structured, discover its main concepts and see the code examples. At the end of this post you can find the code which sends log records to the Telegram. Let's get started.
Why Logs
Logs are X-Ray of your program runtime. The more detailed your logs are the easier is to debug non-standard cases. One of the most popular log example is webserver's access log. Take a look at the nginx's log output from this blog:
92.63.107.227 - - [04/Nov/2020:06:30:48 +0000] "GET /ru/hosted-open-vpn-server/ HTTP/1.1" 301 169 "-" "python-requests/2.11.1" "-"
92.63.107.227 - - [04/Nov/2020:06:30:49 +0000] "GET /ru/data-engineering-course/ HTTP/1.1" 301 169 "-" "python-requests/2.11.1" "-"
213.180.203.50 - - [04/Nov/2020:06:36:07 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (compatible; YandexMetrika/2.0; +http://yandex.com/bots yabs01)" "-"
114.119.160.75 - - [04/Nov/2020:06:36:41 +0000] "GET /robots.txt HTTP/1.1" 301 169 "-" "(compatible;PetalBot;+https://aspiegel.com/petalbot)" "10.179.80.67"
90.180.35.207 - - [04/Nov/2020:06:47:11 +0000] "GET / HTTP/1.0" 301 169 "-" "-" "-"
46.246.122.77 - - [04/Nov/2020:06:53:22 +0000] "GET / HTTP/1.1" 301 169 "<http://khashtamov.com>" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.181 Safari/537.36" "-"
66.249.76.16 - - [04/Nov/2020:06:53:30 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" "-"
66.102.9.118 - - [04/Nov/2020:07:11:19 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 Google Favicon" "46.159.204.234"
71.6.167.142 - - [04/Nov/2020:07:11:55 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2228.0 Safari/537.36" "-"
Nginx also has an error log which contains errors while processing HTTP requests. Your program's logs can also be divided into normal logs, debug logs or error logs.
Python logging
Python has a logging package perform log recordings. At first you may think that this package is complicated and not pythonic. But if you invest some time to explore its functionality you may change your mind. For me the logging package is the example of object oriented programming where composition dominates over inheritance, that is why there are lots of functional classes. The main idea of this post is to introduce you to those classes to make everything clear. Let's dive.
Logger
To start with logs in Python we have to import logging module and execute the getLogger function. This function returns the instance of Logger class which is the entrypoint into the world of log records.
import logging
logger = logging.getLogger('logger_name')
getLogger accepts a single argument, logger's name. You can provide whatever you want but I recommend using __name__. If you execute getLogger multiple times with the same name, function will return the same instance of Logger class.
>>> import logging
>>> x = logging.getLogger('same_name')
>>> y = logging.getLogger('same_name')
>>> y == x
0: True
>>> id(y) == id(x)
1: True
>>>
If you are gonna use the __name__ then you should not worry about name collisions between your packages & modules.
The Logger class provides methods which you can use to write logs with different message levels. Levels are useful because they provide additional information about the runtime's context. Logging has the following levels:
- DEBUG — useful while developing an application, usually provides information for developers (variable values, function names etc)
- INFO — additional information which can help you understand how program executes
- WARNING — useful for additional information like deprecation warnings, backwards compatibility issues
- ERROR — used when writing errors, e.g. a host is unavailable or file has wrong format or does not exist
- CRITICAL — the highest level of information, usually means that a script will be terminated
By default logging has a WARNING level which means that DEBUG & INFO will be ignored (because they have lower priority in comparison to WARNING). Developer can change the level by using setLevel method:
logger.setLevel(logging.DEBUG)
Log recording methods are named according to the corresponding level they represent:
logger.debug('debug info')
logger.info('info')
logger.warning('warning')
logger.error('debug info')
logger.critical('debug info')
Also Logger has the exception method which should be used in the except block in order to catch an exception and create a log record:
try:
1/0
except :
logger.exception('exception')
Handler
Handlers are responsible for writing log messages, they send logs to the appropriate destination (socket, file, stdout etc). The logging module exposes predefined handlers:
- SteamHandler — sends logs to stdout, stderr
- FileHandler — sends logs to the file (see also RotatingFileHandler, TimedRotatingFileHandler)
- SocketHandler — sends logs via TCP socket
- DatagramHandler — sends logs via UDP socket
- SysLogHandler — sends logs to the syslog
- HTTPHandler — sends logs via HTTP
If you want to explore more, please follow the link. In order to add a handler to a Logger instance you have to call addHandler method:
import sys
import logging
from logging import StreamHandler
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
logger.addHandler(handler)
logger.debug('debug information')
If you run this code the output will be:
debug information
Just a simple text message in a terminal is not enough, we need to add some context. Ask me how 😎
Formatter
Formatter specifies the layout of log messages in the final destination (stdout, files etc). By default if you do not specify a custom Formatter class, your log records will contain only the text you provided to the corresponding log methods (debug, info etc) as you have already seen in the example above. In order to specify a Formatter instance you have to call setFormatter method of Handler instance:
import sys
import logging
from logging import StreamHandler, Formatter
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s'))
logger.addHandler(handler)
logger.debug('debug information')
The output is
[2020-11-22 13:00:08,751: DEBUG] debug information
Pay your attention to the placeholders:
[%(asctime)s: %(levelname)s] %(message)s
Logging has a number of predefined placeholders (most of which are derived while constructing the LogRecord instance).
Filter
The class is responsible for filtering log records according to a specific condition. Let's assume that I want to exclude log records which do not contain the word python. If you want to add a filter, you have to call the method addFilter of Logger instance. This method accepts an instance of a class which defines filter method or any python callable:
import sys
import logging
from logging import StreamHandler, Formatter, LogRecord
def filter_python(record: LogRecord) -> bool:
return record.getMessage().find('python') != -1
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s'))
logger.addHandler(handler)
logger.addFilter(filter_python)
logger.debug('python debug information')
LoggerAdapter
If you want to add some extra contextual information to your log records but do not want to provide it everytime you call a log method, then LoggerAdapter is a way to go. Let's assume you are building a web app and want to log a username everytime you make a record:
class CustomLoggerAdapter(LoggerAdapter):
def process(self, msg, kwargs):
return f'{msg} from {self.extra["username"]}', kwargs
logger = logging.getLogger('adapter')
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s'))
adapter = CustomLoggerAdapter(logger, {'username': 'adilkhash'})
logger.addHandler(handler)
adapter.error('failed to save')
LoggerAdapter has the same interface as Logger instance, feel free to call the same log methods.
extra
You are building a cool app which sends requests to the remote API and want to log every response that you receive. See how it is done using the extra argument:
logger.debug('debug info', extra={"response": response.text})
In order to see it in the log record you have to update your formatter class:
Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s, response: %(response)s')
Quite simple and the code looks clean.
Logging Configuration
Official documentation recommends configuring logging via python dictionary. In order to do this you have to call logging.config.dictConfig which accepts a single argument — a dictionary. Its schema is described here:
- version — should be 1 for backwards compatibility
- disable_existing_loggers — disables the configuration for existing loggers (3rd party libararies etc), by default is True
- formatters — settings for formatters
- handlers — settings for handlers
- loggers — settings for loggers
Previously we were able to configure logging settings via python code, it is okay if you have a single module or 2 but in case of an application (e.g. Django app) it is better to have a separate (centralized) place where we can define the config. See the example:
import logging.config
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'default_formatter': {
'format': '[%(levelname)s:%(asctime)s] %(message)s'
},
},
'handlers': {
'stream_handler': {
'class': 'logging.StreamHandler',
'formatter': 'default_formatter',
},
},
'loggers': {
'my_logger': {
'handlers': ['stream_handler'],
'level': 'DEBUG',
'propagate': True
}
}
}
logging.config.dictConfig(LOGGING_CONFIG)
logger = logging.getLogger('my_logger')
logger.debug('debug log')
In a real-world application developers tend to separate logging configuration from the application's code by creating new module, e.g. settings.py or conf.py.
Inheritance in Logging
Loggers can inherit logging settings from their ancestors. The inheritance is defined by the . in logger's name. If you have the logger called my_package.logger1 it will inherit the settings defined for my_package.
If you have a specific logging setting for a particular logger and you don't want it to be handled by the parent's setting you have to set propagate attribute to False.
Implementing a Telegram Handler
In case if you did not work with telegram bots go ahead and read my post about Telegram bots. We are going to use pyTelegramBotAPI package. I assume that you are prepared:
- Created a telegram bot via BotFather
- You know the token
- You know your user id (you can get it via @userinfobot)
In order to create a custom handler you have to inherit your class from Handler and implement the emit method:
import telebot
from logging import Handler, LogRecord
class TelegramBotHandler(Handler):
def __init__(self, token: str, chat_id: str):
super().__init__()
self.token = token
self.chat_id = chat_id
def emit(self, record: LogRecord):
bot = telebot.TeleBot(self.token)
bot.send_message(
self.chat_id,
self.format(record)
)
Sensitive data like tokens & chat id can be provided via logging configuration, you should not store it in the code (e.g. use environment variables instead):
'handlers': {
'telegram_handler': {
'class': 'handlers.TelegramBotHandler',
'chat_id': '<CHAT_ID>',
'token': '<BOT_TOKEN>',
'formatter': 'default_formatter',
}
},
TelegramBotHandler is located in the handlers.py module. To activate it you have to update the corresponding setting in the config:
LOGGING_CONFIG['loggers'].update({
'my_package': {
'handlers': ['stream_handler', 'telegram_handler'],
'level': 'DEBUG',
'propagate': False
}
})
That's it 😎