What is the Coralogix Security Traffic Analyzer (STA), and Why Do I Need It?
The wide-spread adoption of cloud infrastructure has proven to be highly beneficial, but has also introduced new challenges and added costs – especially when it comes…
In the vast computing world, there are different programming languages that include facilities for logging. From our previous posts, you can learn best practices about Node logging, Java logging, and Ruby logging. As part of the ongoing logging series, this post describes what you need to discover about Python logging best practices.
Considering that “log” has the double meaning of a (single) log-record and a log-file, this post assumes that “log” refers to a log-file.
So, why learn about logging in Python? One of Python’s striking features is its capacity to handle high traffic sites, with an emphasis on code readability. Other advantages of logging in Python is its own dedicated library for this purpose, the various outputs where the log records can be directed, such as console, file, rotating file, Syslog, remote server, email, etc., and the large number of extensions and plugins it supports. In this post, you’ll find out examples of different outputs.
The Python standard library provides a logging module as a solution to log events from applications and libraries. Once the Python JSON logger is configured, it becomes part of the Python interpreter process that is running the code. In other words, it is global. You can also configure Python logging subsystem using an external configuration file. The specifications for the logging configuration format are found in the Python standard library.
The logging library is based on a modular approach and includes categories of components: loggers, handlers, filters, and formatters. Basically:
These multiple logger objects are organized into a tree that represents various parts of your system and different third-party libraries that you have installed. When you send a message into one of the loggers, the message gets output on all of that logger’s handlers, using a formatter that’s attached to each handler. The message then propagates up the logger tree until it hits the root logger, or a logger up in the tree that is configured with propagate=False.
This is an example of a basic logger in Python:
import logging logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(levelname)s %(message)s', filename='/tmp/myapp.log', filemode='w') logging.debug("Debug message") logging.info("Informative message") logging.error("Error message")
Line 1: import the logging module.
Line 2: create a basicConf function and pass some arguments to create the log file. In this case, we indicate the severity level, date format, filename and file mode to have the function overwrite the log file.
Line 3 to 5: messages for each logging level.
The default format for log records is SEVERITY: LOGGER: MESSAGE. Hence, if you run the code above as is, you’ll get this output:
2021-07-02 13:00:08,743 DEBUG Debug message 2021-07-02 13:00:08,743 INFO Informative message 2021-07-02 13:00:08,743 ERROR Error message
Regarding the output, you can set the destination of the log messages. As a first step, you can print messages to the screen using this sample code:
import logging logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s') logging.debug('This is a log message.')
If your goals are aimed at the Cloud, you can take advantage of Python’s set of logging handlers to redirect content. Currently in beta release, you can write logs to Stackdriver Logging from Python applications by using Google’s Python logging handler included with the Stackdriver Logging client library, or by using the client library to access the API directly. When developing your logger, take into account that the root logger doesn’t use your log handler. Since the Python Client for Stackdriver Logging library also does logging, you may get a recursive loop if the root logger uses your Python log handler.
The possibilities with Python logging are endless and you can customize them to your needs. The following are some tips for web application logging best practices, so you can take the most from Python logging:
Setting level names: This supports you in maintaining your own dictionary of log messages and reduces the possibility of typo errors.
LogWithLevelName = logging.getLogger('myLoggerSample') level = logging.getLevelName('INFO') LogWithLevelName.setLevel(level)
logging.getLevelName(logging_level) returns the textual representation of the severity called logging_level. The predefined values include, from highest to lowest severity:
Logging from multiple modules: if you have various modules, and you have to perform the initialization in every module before logging messages, you can use cascaded logger naming:
logging.getLogger(“coralogix”) logging.getLogger(“coralogix.database”) logging.getLogger(“coralogix.client”)
Making coralogix.client and coralogix.database descendants of the logger coralogix, and propagating their messages to it, it thereby enables easy multi-module logging. This is one of the positive side-effects of name in case the library structure of the modules reflects the software architecture.
Logging with Django and uWSGI: To deploy web applications you can use StreamHandler as logger which sends all logs to For Django you have:
'handlers': { 'stderr': { 'level': 'INFO', 'class': 'logging.StreamHandler', 'formatter': 'your_formatter', }, },
Next, uWSGI forwards all of the app output, including prints and possible tracebacks, to syslog with the app name attached:
$ uwsgi --log-syslog=yourapp …
Logging with Nginx: In case you need having additional features not supported by uWSGI — for example, improved handling of static resources (via any combination of Expires or E-Tag headers, gzip compression, pre-compressed gzip, etc.), access logs and their format can be customized in conf. You can use the combined format, such the example for a Linux system:
access_log /var/log/nginx/access.log;
This line is similar to explicitly specifying the combined format as this:
# note that the log_format directly below is a single line log_format mycombined '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent"'server_port'; access_log /var/log/nginx/access.log mycombinedplus;
Log analysis and filtering: after writing proper logs, you might want to analyze them and obtain useful insights. First, open files using blocks, so you won’t have to worry about closing them. Moreover, avoid reading everything into memory at once. Instead, read a line at a time and use it to update the cumulative statistics. The use of the combined log format can be practical if you are thinking on using log analysis tools because they have pre-built filters for consuming these logs.
If you need to parse your log output for analysis you might want to use the code below:
with open(logfile, "rb") as f: for line in csv.reader(f, delimiter=' '): self._update(**self._parse(line))
Python’s CSV module contains code the read CSV files and other files with a similar format. In this way, you can combine Python’s logging library to register the logs and the CSV library to parse them.
And of course, the Coralogix way for python logging, using the Coralogix Python appender allows sending all Python written logs directly to Coralogix for search, live tail, alerting, and of course, machine learning powered insights such as new error detection and flow anomaly detection.
The rest of this guide is focused on how to log in Python using the built-in support for logging. It introduces various concepts that are relevant to understanding Python logging, discusses the corresponding logging APIs in Python and how to use them, and presents best practices and performance considerations for using these APIs.
We will introduce various concepts relevant to understanding logging in Python, discuss the corresponding logging APIs in Python and how to use them, and present best practices and performance considerations for using these APIs.
This Python tutorial assumes the reader has a good grasp of programming in Python; specifically, concepts and constructs pertaining to general programming and object-oriented programming. The information and Python logging examples in this article are based on Python version 3.8.
Python has offered built-in support for logging since version 2.3. This support includes library APIs for common concepts and tasks that are specific to logging and language-agnostic. This article introduces these concepts and tasks as realized and supported in Python’s logging library.
When we use a logging library, we perform/trigger the following common tasks while using the associated concepts (highlighted in bold).
Independent of the logging library, the above tasks are performed in an order similar to that shown in Figure 1.
Figure 1: The flow of tasks when logging via a logging library
Python’s standard library offers support for logging via logging, logging.config, and logging.handlers modules.
logging
module provides the primary client-facing API.logging.config
module provides the API to configure logging in a client.logging.handlers
module provides different handlers that cover common ways of processing and storing log records.We collectively refer to these Python log modules as Python’s logging library.
These Python log modules realize the concepts introduced in the previous section as classes, a set of module-level functions, or a set of constants. Figure 2 shows these classes and the associations between them.
Figure 2: Python classes and constants representing various logging concepts
Out of the box, the Python logging library supports five logging levels: critical, error, warning, info, and debug. These levels are denoted by constants with the same name in the logging module, i.e., logging.CRITICAL
, logging.ERROR
, logging.WARNING
, logging.INFO
, and logging.DEBUG
. The values of these constants are 50, 40, 30, 20, and 10, respectively.
At runtime, the numeric value of a logging level determines the meaning of a logging level. Consequently, clients can introduce new logging levels by using numeric values that are greater than 0 and not equal to pre-defined logging levels as logging levels.
Logging levels can have names. When names are available, logging levels appear by their names in log entries. Every pre-defined logging level has the same name as the name of the corresponding constant; hence, they appear by their names in log entries, e.g., logging.WARNING
and 30 levels appear as ‘WARNING’
. In contrast, custom logging levels are unnamed by default. So, an unnamed custom logging level with numeric value n
appears as ‘Level n’
in log entries, and this results in inconsistent and human-unfriendly log entries. To address this, clients can name a custom logging level using the module-level function logging.addLevelName(level, levelName)
. For example, by using logging.addLevelName(33, 'CUSTOM1')
, level 33
will be recorded as ‘CUSTOM1’
.
The Python logging library adopts the community-wide applicability rules for logging levels, i.e., when should logging level X be used?
logging.DEBUG
to log detailed information, typically of interest only when diagnosing problems, e.g., when the app starts.logging.INFO
to confirm the software is working as expected, e.g., when the app initializes successfully.logging.WARNING
to report behaviors that are unexpected or are indicative of future problems but do not affect the current functioning of the software, e.g., when the app detects low memory, and this could affect the future performance of the app.logging.ERROR
to report the software has failed to perform some function, e.g., when the app fails to save the data due to insufficient permission.logging.CRITICAL
to report serious errors that may prevent the continued execution of the software, e.g., when the app fails to allocate memory.The logging.Logger
objects offer the primary interface to the logging library. These objects provide the logging methods to issue log requests along with the methods to query and modify their state. From here on out, we will refer to Logger objects as loggers.
The factory
function logging.getLogger(name)
is typically used to create loggers. By using the factory
function, clients can rely on the library to manage loggers and to access loggers via their names instead of storing and passing references to loggers.
The name
argument in the factory function is typically a dot-separated hierarchical name, e.g., a.b.c. This naming convention enables the library to maintain a hierarchy of loggers. Specifically, when the factory
function creates a logger, the library ensures a logger exists for each level of the hierarchy specified by the name, and every logger in the hierarchy is linked to its parent and child loggers.
Each logger has a threshold logging level that determines if a log request should be processed. A logger processes a log request if the numeric value of the requested logging level is greater than or equal to the numeric value of the logger’s threshold logging level. Clients can retrieve and change the threshold logging level of a logger via Logger.getEffectiveLevel()
and Logger.setLevel(level)
methods, respectively.
When the factory
function is used to create a logger, the function sets a logger’s threshold logging level to the threshold logging level of its parent logger as determined by its name
.
Every logger offers the following logging methods to issue log requests.
Logger.critical(msg, *args, **kwargs)
Logger.error(msg, *args, **kwargs)
Logger.debug(msg, *args, **kwargs)
Logger.info(msg, *args, **kwargs)
Logger.warn(msg, *args, **kwargs)
Each of these methods is a shorthand to issue log requests with corresponding pre-defined logging levels as the requested logging level.
In addition to the above methods, loggers also offer the following two methods:
Logger.log(level, msg, *args, **kwargs)
issues log requests with explicitly specified logging levels. This method is useful when using custom logging levels.Logger.exception(msg, *args, **kwargs)
issues log requests with the logging level ERROR
and that capture the current exception as part of the log entries. Consequently, clients should invoke this method only from an exception handler.msg
and args
arguments in the above methods are combined to create log messages captured by log entries. All of the above methods support the keyword argument exc_info
to add exception information to log entries and stack_info
and stacklevel
to add call stack information to log entries. Also, they support the keyword argument extra
, which is a dictionary, to pass values relevant to filters, handlers, and formatters.
When executed, the above methods perform/trigger all of the tasks shown in Figure 1 and the following two tasks:
LogRecord
object to represent the log request in the downstream processing of the request. LogRecord
objects capture the msg
and args
arguments of logging methods and the exception and call stack information along with source code information. They also capture the keys and values in the extra argument of the logging method as fields.Logger.propagate
field controls this aspect, which is True
by default.Beyond logging levels, filters provide a finer means to filter log requests based on the information in a log record, e.g., ignore log requests issued in a specific class. Clients can add and remove filters to/from loggers using Logger.addFilter(filter)
and Logger.removeFilter(filter)
methods, respectively.
Any function or callable that accepts a log record argument and returns zero to reject the record and a non-zero value to admit the record can serve as a filter
. Any object that offers a method with the signature filter(record: LogRecord) ->
int can also serve as a filter.
A subclass of logging.Filter(name: str)
that optionally overrides the logging.Filter.filter(record)
method can also serve as a filter. Without overriding the filter method, such a filter will admit records emitted by loggers that have the same name as the filter and are children of the filter (based on the name of the loggers and the filter). If the name of the filter is empty, then the filter admits all records. If the method is overridden, then it should return zero value to reject the record and a non-zero value to admit the record.
The logging.Handler
objects perform the final processing of log records, i.e., logging log requests. This final processing often translates into storing the log record, e.g., writing it into system logs or files. It can also translate it to communicate the log record data to specific entities (e.g., send an email) or passing the log record to other entities for further processing (e.g., provide the log record to a log collection process or a log collection service).
Like loggers, handlers have a threshold logging level, which can be set via theHandler.setLevel(level)
method. They also support filters via Handler.addFilter(filter)
and Handler.removeFilter(filter)
methods.
The handlers use their threshold logging level and filters to filter log records for processing. This additional filtering allows context-specific control over logging, e.g., a notifying handler should only process log requests that are critical or from a flaky module.
While processing the log records, handlers format log records into log entries using their formatters. Clients can set the formatter for a handler via Handler.setFormatter(formatter) method. If a handler does not have a formatter, then it uses the default formatter provided by the library.
The logging.handler module provides a rich collection of 15 useful handlers that cover many common use cases (including the ones mentioned above). So, instantiating and configuring these handlers suffices in many situations.
In situations that warrant custom handlers, developers can extend the Handler
class or one of the pre-defined Handler classes by implementing the Handler.emit(record)
method to log the provided log record.
The handlers use logging.Formatter
objects to format a log record into a string-based log entry.
Note: Formatters do not control the creation of log messages.
A formatter works by combining the fields/data in a log record with the user-specified format string.
Unlike handlers, the logging library only provides a basic formatter that logs the requested logging level, the logger’s name, and the log message. So, beyond simple use cases, clients need to create new formatters by creating logging.Formatter
objects with the necessary format strings.
Formatters support three styles of format strings:
printf
, e.g., ‘%(levelname)s:%(name)s:%(message)s’
str.format()
, e.g., ‘{levelname}:{name}:{message}’
str.template
, e.g., ‘$levelname:$name:$message’
The format string of a formatter can refer to any field of LogRecord
objects, including the fields based on the keys of the extra
argument of the logging
method.
Before formatting a log record, the formatter uses the LogRecord.getMessage()
method to construct the log message by combining the msg
and args
arguments of the logging method (stored in the log record) using the string formatting operator (%)
. The formatter then combines the resulting log message with the data in the log record using the specified format string to create the log entry.
To maintain a hierarchy of loggers, when a client uses the logging library, the library creates a root logger that serves as the root of the hierarchy of loggers. The default threshold logging level of the root logger is logging.WARNING
.
The module offers all of the logging methods offered by the Logger
class as module-level
functions with identical names and signature, e.g., logging.debug(msg, *args, **kwargs)
. Clients can use these functions to issue log requests without creating loggers, and the root logger services these requests. If the root logger has no handlers when servicing log requests issued via these methods, then the logging library adds a logging.StreamHandler
instance based on the sys.stderr
stream as a handler to the root logger.
When loggers without handlers receive log requests, the logging library directs such log requests to the last resort handler, which is a logging.StreamHandler
instance based on sys.stderr stream
. This handler is accessible via the logging.lastResort
attribute.
Here are a few code snippets illustrating how to use the Python logging library.
# main.py import lo gging, sys def _init_logger(): logger = logging.getLogger('app') #1 logger.setLevel(logging.INFO) #2 handler = logging.StreamHandler(sys.stderr) #3 handler.setLevel(logging.INFO) #4 formatter = logging.Formatter( '%(created)f:%(levelname)s:%(name)s:%(module)s:%(message)s') #5 handler.setFormatter(formatter) #6 logger.addHandler(handler) #7 _init_logger() _logger = logging.getLogger('app')
This snippet does the following.
By changing the handler created in step 3, we can redirect the log entries to different locations or processors.
# main.py _logger.info('App started in %s', os.getcwd())
This snippet logs informational messages stating the app has started.
When the app is started in the folder /home/kali with the logger created using snippet 1, this snippet will generate the log entry 1586147623.484407:INFO:app:main:App started in /home/kali/
in standard error stream.
# app/io.py import logging def _init_logger(): logger = logging.getLogger('app.io') logger.setLevel(logging.INFO) _init_logger() _logger = logging.getLogger('app.io') def write_data(file_name, data): try: # write data _logger.info('Successfully wrote %d bytes into %s', len(data), file_name) except FileNotFoundError: _logger.exception('Failed to write data into %s', file_name)
This snippet logs an informational message every time data is written successfully via write_data
. If a write fails, then the snippet logs an error message that includes the stack trace in which the exception occurred.
With the logger created using snippet 1, if the execution of app.write_data('/tmp/tmp_data.txt', image_data)
succeeds, then this snippet will generate a log entry similar to 1586149091.005398:INFO:app.io:io:Successfully wrote 134 bytes into /tmp/tmp_data.txt
. If the execution of app.write_data('/tmp/tmp_data.txt', image_data)
fails, then this snippet will generate the following log entry:
1586149219.893821:ERROR:app:io:Failed to write data into /tmp1/tmp_data.txt Traceback (most recent call last): File "/home/kali/program/app/io.py", line 12, in write_data print(open(file_name), data) FileNotFoundError: [Errno 2] No such file or directory: '/tmp1/tmp_data.txt'
Instead of using positional arguments in the format string in the logging method, we could achieve the same output by using the arguments via their names as follows:
_logger.info('Successfully wrote %(data_size)s bytes into %(file_name)s', {'data_size': len(data), 'file_name': file_name})
# main.py import logging, os, sys import app.io def _init_logger(): logger = logging.getLogger('app') logger.setLevel(logging.INFO) formatter = logging.Formatter( '%(created)f:%(levelname)s:%(name)s:%(module)s:%(message)s') handler = logging.StreamHandler(sys.stderr) handler.setLevel(logging.INFO) handler.setFormatter(formatter) handler.addFilter(lambda record: record.version > 5 or #1 record.levelno >= logging.ERROR) #1 logger.addHandler(handler) _init_logger() _logger = logging.LoggerAdapter(logging.getLogger('app'), {'version': 6}) #2
This snippet modifies Snippet 1 as follows.
logging.ERROR
or they are from a component whose version is higher than 4.logging.LoggerAdapter
object to inject version information into log records.The logging.LoggerAdapter
class provides a mechanism to inject contextual information into log records. We discuss other mechanisms to inject contextual information in the Good Practices and Gotchas section.
# app/io.py import logging def _init_logger(): logger = logging.getLogger('app.io') logger.setLevel(logging.INFO) _init_logger() _logger = logging.LoggerAdapter(logging.getLogger('app.io'), {'version': 3}) # 1 def write_data(file_name, data): try: # write data _logger.info('Successfully wrote %d bytes into %s', len(data), file_name) except FileNotFoundError: _logger.exception('Failed to write data into %s', file_name)
This snippet modifies Snippet 3 by wrapping the logger in a LoggerAdapter
object to inject version information.
All of the above changes affect the logging behavior of the app described in Snippet 2 and Snippet 3 as follows.
What do you suppose would have happened if the filter was added to the logger instead of the handler? See Gotchas for the answer.
The logging classes introduced in the previous section provide methods to configure their instances and, consequently, customize the use of the logging library. Snippet 1 demonstrates how to use configuration methods. These methods are best used in simple single-file programs.
When involved programs (e.g., apps, libraries) use the logging library, a better option is to externalize the configuration of the logging library. Such externalization allows users to customize certain facets of logging in a program (e.g., specify the location of log files, use custom loggers/handlers/formatters/filters) and, hence, ease the deployment and use of the program. We refer to this approach to configuration as data-based approach.
Clients can configure the logging library by invoking logging.config.dictConfig(config: Dict)
function. The config
argument is a dictionary and the following optional keys can be used to specify a configuration.
filters key maps to a dictionary of strings and dictionaries. The strings serve as filter ids used to refer to filters in the configuration (e.g., adding a filter to a logger) while the mapped dictionaries serve as filter configurations. The string value of the name key in filter configurations is used to construct logging.Filter instances
.
"filters": { "io_filter": { "name": "app.io" } }
This configuration snippet results in the creation of a filter that admits all records created by the logger named ‘app.io’ or its descendants.
formatters key maps to a dictionary of strings and dictionaries. The strings serve as formatter ids used to refer to formatters in the configuration (e.g., adding a formatter to a handler) while the mapped dictionaries serve as formatter configurations. The string values of the datefmt and format keys in formatter configurations are used as the date and log entry formatting strings, respectively, to construct logging.Formatter
instances. The boolean value of the (optional) validate key controls the validation of the format strings during the construction of a formatter.
"formatters": { "simple": { "format": "%(asctime)s - %(message)s", "datefmt": "%y%j-%H%M%S" }, "detailed": { "format": "%(asctime)s - %(pathname):%(lineno) - %(message)s" } }
This configuration snippet results in the creation of two formatters. A simple formatter with the specified log entry and date formatting strings and detailed formatter with specified log entry formatting string and default date formatting string.
handlers key maps to a dictionary of strings and dictionaries. The strings serve as handler ids used to refer to handlers in the configuration (e.g., adding a handler to a logger) while the mapped dictionaries serve as handler configurations. The string value of the class key in a handler configuration names the class to instantiate to construct a handler. The string value of the (optional) level key specifies the logging level of the instantiated handler. The string value of the (optional) formatter key specifies the id of the formatter of the handler. Likewise, the list of values of the (optional) filters key specifies the ids of the filters of the handler. The remaining keys are passed as keyword arguments to the handler’s constructor.
"handlers": { "stderr": { "class": "logging.StreamHandler", "level": "INFO", "filters": ["io_filter"], "formatter": "simple", "stream": "ext://sys.stderr" }, "alert": { "class": "logging.handlers.SMTPHandler", "level": "ERROR", "formatter": "detailed", "mailhost": "smtp.skynet.com", "fromaddr": "[email protected]", "toaddrs": [ "[email protected]", "[email protected]" ], "subject": "System Alert" } }
This configuration snippet results in the creation of two handlers:
stderr
handler that formats log requests with INFO and higher logging level log via the simple
formatter and emits the resulting log entry into the standard error stream. The stream
key is passed as keyword arguments to logging.StreamHandler
constructor.stream
key illustrates how to access objects external to the configuration. The ext://
prefixed string refers to the object that is accessible when the string without the ext:// prefix (i.e., sys.stderr) is processed via the normal importing mechanism. Refer to Access to external objects for more details. Refer to Access to internal objects for details about a similar mechanism based on cfg://
prefix to refer to objects internal to a configuration.detailed
formatter and emails the resulting log entry to the given email addresses. The keys mailhost
, formaddr
, toaddrs
, and subject are passed as keyword arguments to logging.handlers.SMTPHandler
’s constructor.loggers key maps to a dictionary of strings that serve as logger names and dictionaries that serve as logger configurations. The string value of the (optional) level
key specifies the logging level of the logger. The boolean value of the (optional) propagate
key specifies the propagation setting of the logger. The list of values of the (optional) filters
key specifies the ids of the filters of the logger. Likewise, the list of values of the (optional) handlers
key specifies the ids of the handlers of the logger.
"loggers": { "app": { "handlers": ["stderr", "alert"], "level": "WARNING" }, "app.io": { "level": "INFO" } }
This configuration snippet results in the creation of two loggers. The first logger is named app, its threshold logging level is set to WARNING, and it is configured to forward log requests to stderr
and alert
handlers. The second logger is named app.io, and its threshold logging level is set to INFO. Since a log request is propagated to the handlers associated with every ascendant logger, every log request with INFO or a higher logging level made via the app.io logger will be propagated to and handled by both stderr
and alert
handlers.
root key maps to a dictionary of configuration for the root logger. The format of the mapped dictionary is the same as the mapped dictionary for a logger.
incremental key maps to either True or False (default). If True, then only logging levels and propagate options of loggers, handlers, and root loggers are processed, and all other bits of the configuration is ignored. This key is useful to alter existing logging configuration. Refer to Incremental Configuration for more details.
disable_existing_loggers key maps to either True
(default) or False
. If False
, then all existing non-root loggers are disabled as a result of processing this configuration.
Also, the config
argument should map the version
key to 1.
Here’s the complete configuration composed of the above snippets.
{ "version": 1, "filters": { "io_filter": { "name": "app.io" } }, "formatters": { "simple": { "format": "%(asctime)s - %(message)s", "datefmt": "%y%j-%H%M%S" }, "detailed": { "format": "%(asctime)s - %(pathname):%(lineno) - %(message)s" } }, "handlers": { "stderr": { "class": "logging.StreamHandler", "level": "INFO", "filters": ["io_filter"], "formatter": "simple", "stream": "ext://sys.stderr" }, "alert": { "class": "logging.handlers.SMTPHandler", "level": "ERROR", "formatter": "detailed", "mailhost": "smtp.skynet.com", "fromaddr": "[email protected]", "toaddrs": [ "[email protected]", "[email protected]" ], "subject": "System Alert" } }, "loggers": { "app": { "handlers": ["stderr", "alert"], "level": "WARNING" }, "app.io": { "level": "INFO" } } }
The configuration schema for filters supports a pattern to specify a factory
function to create a filter. In this pattern, a filter configuration maps the () key to the fully qualified name of a filter creating factory function along with a set of keys and values to be passed as keyword arguments to the factory function. In addition, attributes and values can be added to custom filters by mapping the .
key to a dictionary of attribute names and values.
For example, the below configuration will cause the invocation of app.logging.customFilterFactory(startTime='6PM', endTime='6AM')
to create a custom filter and the addition of local attribute with the value True
to this filter.
"filters": { "time_filter": { "()": "app.logging.create_custom_factory", "startTime": "6PM", "endTime": "6PM", ".": { "local": true } } }
Configuration schemas for formatters, handlers, and loggers also support the above pattern. In the case of handlers/loggers, if this pattern and the class
key occur in the configuration dictionary, then this pattern is used to create handlers/loggers. Refer to User-defined Objects for more details.
The logging library also supports loading configuration from a configparser
-format file via the <a href="https://docs.python.org/3/library/logging.config.html#logging.config.fileConfig" target="_blank" rel="noopener noreferrer">logging.config.fileConfig()
function. Since this is an older API that does not provide all of the functionalities offered by the dictionary-based configuration scheme, the use of the dictConfig()
function is recommended; hence, we’re not discussing the fileConfig()
function and the configparser
file format in this tutorial.
While the above APIs can be used to update the logging configuration when the client is running (e.g., web services), programming such update mechanisms from scratch can be cumbersome. The logging.config.listen()
function alleviates this issue. This function starts a socket server that accepts new configurations over the wire and loads them via dictConfig()
or fileConfig()
functions. Refer to logging.config.listen()
for more details.
Since the configuration provided to dictConfig()
is nothing but a collection of nested dictionaries, a logging configuration can be easily represented in JSON and YAML format. Consequently, programs can use the json
module in Python’s standard library or external YAML processing libraries to read and write logging configurations from files.
For example, the following snippet suffices to load the logging configuration stored in JSON format.
import json, logging.config with open('logging-config.json', 'rt') as f: config = json.load(f) logging.config.dictConfig(config)
In the supported configuration scheme, we cannot configure filters to filter beyond simple name-based filtering. For example, we cannot create a filter that admits only log requests created between 6 PM and 6 AM. We need to program such filters in Python and add them to loggers and handlers via factory functions or the addFilter()
method.
In this section, we will list a few good practices and gotchas related to the logging library. This list stems from our experience, and we intend it to complement the extensive information available in the Logging HOWTO and Logging Cookbook sections of Python’s documentation.
Since there are no silver bullets, all good practices and gotchas have exceptions that are almost always contextual. So, before using the following good practices and gotchas, consider their applicability in the context of your application and ascertain whether they are appropriate in your application’s context.
The logging.getLogger()
factory function helps the library manage the mapping from logger names to logger instances and maintain a hierarchy of loggers. In turn, this mapping and hierarchy offer the following benefits:
factory
function to access the same logger in different parts of the program by merely retrieving the logger by its name.level
of a logger can be inferred from its ascendants.Use the logging.<logging level>()
function or the Logger.<logging level>()
methods to log at pre-defined logging levels
Besides making the code a bit shorter, the use of these functions/methods helps partition the logging statements in a program into two sets:
As described in the Logging Level section in the Concepts and API chapter, the pre-defined logging levels offered by the library capture almost all logging scenarios that occur in programs. Further, since most developers are familiar with pre-defined logging levels (as most logging libraries across different programming languages offer very similar levels), the use of pre-defined levels can help lower deployment, configuration, and maintenance burden. So, unless required, use pre-defined logging levels.
While creating loggers, we can create a logger for each class or create a logger for each module. While the first option enables fine-grained configuration, it leads to more loggers in a program, i.e., one per class. In contrast, the second option can help reduce the number of loggers in a program. So, unless such fine-grained configuration is necessary, create module-level loggers.
Since the logger names are string values that are not part of the namespace of a Python program, they will not clash with module names. Hence, use the name of a module as the name of the corresponding module-level logger. With this naming, logger naming piggybacks on the dot notation based module naming and, consequently, simplifies referring to loggers.
As demonstrated in Snippet 4, we can use logging.LoggerAdapter
to inject contextual information into log records. LoggerAdapter
can also be used to modify the log message and the log data provided as part of a log request.
Since the logging library does not manage these adapters, they cannot be accessed via common names. For this reason, use them to inject contextual information that is local to a module or a class.
logging.setLogRecordFactory()
to inject global contextual informationThere are two options to seamlessly inject global contextual information (that is common across an app) into log records.
The first option is to use the filter support to modify the log record arguments provided to filters. For example, the following filter injects version information into incoming log records.
def version_injecting_filter(logRecord): logRecord.version = '3' return True
There are two downsides to this option. First, if filters depend on the data in log records, then filters that inject data into log records should be executed before filters that use the injected data. Hence, the order of filters added to loggers and handlers becomes crucial. Second, the option “abuses” the support to filter log records to extend log records.
The second option is to initialize the logging library with a log record creating factory function via logging.setLogRecordFactory()
. Since the injected contextual information is global, it can be injected into log records when they are created in the factory
function and be sure the data will be available to every filter, formatter, logger, and handler in the program.
The downside of this option is that we have to ensure factory
functions contributed by different components in a program play nicely with each other. While log record factory functions could be chained, such chaining increases the complexity of programs.
If your program involves multiple modules and possibly third-party components, then use the data-based approach described in the Configuration chapter to configure the logging library.
If a handler is common to two loggers of which one is the descendant of the other, then attach the handler to the ascendant logger and rely on the logging library to propagate the log requests from the descendant logger to the handlers of the ascendant logger. If the propagate
attribute of loggers has not been modified, this pattern helps avoid duplicate messages.
logging.disable()
function to inhibit the processing of log requests below a certain logging level across all loggersA logger processes a log request if the logging level of the log request is at least as high as the logger’s effective logging level. A logger’s effective logging level is the higher of two logging levels: the logger’s threshold logging level and the library-wide logging level. We can set the library-wide logging level via the logging.disable(level)
function. By default, the library-wide logging level is 0, i.e., log requests of every logging level will be processed.
Using this function, we can throttle the logging output of an app by increasing the logging level across the entire app.
Before moving on to gotchas, let’s consider the goodness of the common practice of caching references to loggers and accessing loggers via cached references, e.g., this is how the _logger
attribute was used in the previous code snippets.
This coding pattern avoids repeated invocations of the logging.getLogger()
function to retrieve the same module-level logger; hence, it helps eliminate redundant retrievals. However, such eliminations can lead to lost log requests if retrievals are not redundant. For example, suppose the logging library configuration in a long-running web service is updated with this disabling_existing_loggers
option. Since such an update would disable cached loggers, none of the logging statements that use cached loggers would log any requests. While we can remedy this situation by updating cached references to loggers, a simpler solution would be to use the logging.getLogger()
function instead of caching references.
In short, caching references to loggers is not always a good practice. So, consider the context of the program while deciding to cache references to loggers.
When the logging library invokes the filters associated with handlers and loggers, the library assumes the filters will always execute to completion, i.e., not fail on errors. So, there is no error handling logic in the library to deal with failing filters. Consequently, when a filter fails (to execute to completion), the corresponding log request will not be logged.
Ensure filters will execute to completion. More so, when using custom filters and using additional data in filtering.
The logging library makes a similar assumption about formatters, i.e., formatters will always execute to completion. Consequently, when a formatter fails to execute to completion, the corresponding log request will not be logged.
Ensure formatters will execute to completion.
extra
argumentIf the filters/formatters refer to keys of the extra
argument provided as part of logging methods, then the filters/formatters can fail when the extra
argument does not provide a referred
key.
Ensure every key of the extra
argument used in a filter or a formatter are available in every triggering logging statement.
extra
argument clash with required attributesThe logging library adds the keys of the extra
argument (to various logging methods) as attributes to log records. However, if asctime
and message
occur as keys in the extra
argument, then the creation of log records will fail, and the corresponding log request will not be logged.
Similar failure occurs if args
, exc_info
, lineno
, msg
, name
, or pathname
occur as keys in the extra
argument; these are attributes of the LogRecord
class.
Ensure asctime
, message
, and certain attributes of LogRecord
do not appear as keys in the extra
argument of logging methods.
When a program and its dependent libraries use the logging library, their logging requirements are combined by the underlying logging library that services these requirements. In this case, if the components of a program use custom logging levels that are mutually inconsistent, then the logging outcome can be unpredictable.
Don’t use custom logging levels, specifically, in libraries.
By default, log requests are propagated up the logger hierarchy to be processed by the handlers of ancestor loggers. While the filters of the handlers process such log requests, the filters of the corresponding loggers do not process such log requests.
To apply a filter to all log requests submitted to a logger, add the filter to the logger.
If multiple handlers share the same handler id in a configuration, then the handler id refers to the handler that is created last when the configuration is processed. The same happens amongst filters and formatters that share ids.
When a client terminates, the logging library will execute the cleanup logic of the handler associated with each handler id. So, if multiple handlers have the same id in a configuration, then the cleanup logic of all but the handler created last will not be executed and, hence, result in resource leaks.
Use unique ids for objects of a kind in a configuration.
While logging statements help capture information at locations in a program, they contribute to the cost of the program in terms of execution time (e.g., logging statements in loops) and storage (e.g., logging lots of data). Although cost-free yet useful logging is impossible, we can reduce the cost of logging by making choices that are informed by performance considerations.
After adding logging statements to a program, we can use the support to configure logging (described earlier) to control the execution of logging statements and the associated execution time. In particular, consider the following configuration capabilities when making decisions about logging-related performance.
The above changes the range over coarser to finer aspects of logging support in Python.
While the support to configure logging is powerful, it cannot help control the performance impact of implementation choices baked into the source code. Here are a few such logging-related implementation choices and the reasons why you should consider them when making decisions about logging-related performance.
Upon adding the logging module to Python’s standard library, there were concerns about the execution cost associated with inactive logging statements — logging statements that issue log requests with logging level lower than the threshold logging level of the target logger. For example, how much extra time will a logging statement that invokes logger.debug(...)
add to a program’s execution time when the threshold logging level of logger is logging.WARN
? This concern led to client-side coding patterns (as shown below) that used the threshold logging level of the target logger to control the execution of the logging statement.
# client code ... if logger.isEnabledFor(logging.DEBUG): logger.debug(msg) ...
Today, this concern is not valid because the logging methods in the logging.Logger
class perform similar checks and process the log requests only if the checks pass. For example, as shown below, the above check is performed in the logging.Logger.debug
method.
# client code ... logger.debug(msg) ... # logging library code class Logger: ... def debug(self, msg, *args, **kwargs): if self.isEnabledFor(DEBUG): self._log(DEBUG, msg, args, **kwargs)
Consequently, inactive logging statements effectively turn into no-op statements and do not contribute to the execution cost of the program.
Even so, one should consider the following two aspects when adding logging statements.
logger.debug(...)
when threshold logging level of logger was logging.WARN
took half a second on a typical laptop. So, while the cost of an inactive logging statement is trivial, the total execution cost of numerous inactive logging statements can quickly add up to be non-trivial.Clients can construct log messages in two ways: eagerly and lazily.
logging
method, e.g., logger.debug(f'Entering method Foo: {x=}, {y=}')
.f-strings
and the format()
method, but it involves the eager construction of log messages, i.e., before the logging statements are deemed as active.printf
-style message format string (as a msg
argument) and the values (as a args
argument) to construct the log message to the logging method, e.g., logger.debug('Entering method %s: x=%d, y=%f', 'Foo', x, y)
. After the logging statement is deemed as active, the logger constructs the log message using the string formatting operator %
.While both approaches result in the same outcome, they exhibit different performance characteristics due to the eagerness and laziness of message construction.
For example, on a typical laptop, a million inactive invocations of logger.debug('Test message {0}'.format(t))
takes 2197ms while a million inactive invocations of logger.debug('Test message %s', t)
takes 1111ms when t
is a list of four integers. In the case of a million active invocations, the first approach takes 11061ms and the second approach took 10149ms. A savings of 9–50% of the time taken for logging!
So, the second (lazy) approach is more performant than the first (eager) approach in cases of both inactive and active logging statements. Further, the gains would be larger when the message construction is non-trivial, e.g., use of many arguments, conversion of complex arguments to strings.
By default, when a log record is created, the following data is captured in the log record:
Unless these bits of data are logged, gathering them unnecessarily increases the execution cost. So, if these bits of data will not be logged, then configure the logging framework to not gather them by setting the following flags.
logging.logProcesses = False
logging.logThreads = False
logging.logMultiProcessing = False
logging._srcFile = None
There are situations where we may want to log data in the main thread of execution without spending almost any time logging the data. Such situations are common in web services, e.g., a request processing thread needs to log incoming web requests without significantly increasing its response time. We can tackle these situations by separating concerns across threads: a client/main thread creates a log record while a logging thread logs the record. Since the task of logging is often slower as it involves slower resources (e.g., secondary storage) or other services (e.g., logging services such as Coralogix, pub-sub systems such as Kafka), this separation of concerns helps minimize the effort of logging on the execution time of the main/client thread.
The Python logging library helps handle such situations via the QueueHandler
and QueueListener
classes as follows.
QueueHandler
and QueueListener
instances are initialized with a queue.QueueHandler
instance receives a log record from the client, it merely places the log request in its queue while executing in the client’s thread. Given the simplicity of the task performed by the QueueHandler
, the client thread hardly pauses.QueueListener
queue, the listener retrieves the log record and executes the handlers registered with the listener to handle the log record. In terms of execution, the listener and the registered handlers execute in a dedicated thread that is different from the client thread.Note: While QueueListener
comes with a default threading strategy, developers are not required to use this strategy to use QueueHandler
. Instead, developers can use alternative threading strategies that meet their needs.
That about wraps it up for this Python logging guide. If you’re looking for a log management solution to centralize your Python logs, check out our easy-to-configure Python integration.