Continuing with our Python FastAPI learning series, this post explores the implementation of non-blocking logging using Pythonβs built-in QueueHandler and QueueListener classes.
π Index of the Complete Series.
Starting from this post, the code will require Python 3.12.4. Please refer to the following discussion on how to upgrade to Python 3.12.4.
π Please note, complete code for this post can be downloaded from GitHub with:
git clone -b v0.5.0 https://github.com/behai-nguyen/fastapi_learning.git
Table Of Contents
-
βΆ Definition and Complete Working Example of
Non-Blocking Logging
- β· Structure of Logging
- βΈ Project Layout
-
βΉ Implementation of
Non-Blocking Logging
- βΊ Essential Official Documentation
- β» Concluding Remarks
βΆ In essence, non-blocking logging
means that the actual logging task does not hold up the thread performing the logging. This thread does not have to wait for the logging to complete and can move to the next instruction immediately.
Non-blocking logging
is achieved via three principal built-in classes: queue.Queue, QueueHandler, and QueueListener. An instance of queue.Queue
is accessible by both a non-blocking
QueueHandler
instance and a QueueListener
instance. The QueueListener
instance passes the logging messages to its own blocking
handler(s), such as a RotatingFileHandler.
According to the official documentation for QueueHandler and QueueListener, they have their own separate thread for logging. This frees the main thread from waiting for the logging to finish, thereby preventing it from being blocked.
The complete working example below, adapted from a Stack Overflow answer and a Medium post, illustrates how the aforementioned classes fit together to implement non-blocking logging
. Logging messages are written to the queue.log
file in the same directory as the Python script file:
from contextlib import asynccontextmanager
from fastapi import FastAPI, Request
import logging
import queue
from logging.handlers import QueueHandler, QueueListener, RotatingFileHandler
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
log_queue = queue.Queue()
# Non-blocking handler.
queue_handler = QueueHandler(log_queue)
queue_handler.setFormatter(logging.Formatter("%(asctime)s - %(levelname)s - %(message)s"))
# Attached to the root logger.
logger.addHandler(queue_handler)
# The blocking handler.
rot_handler = RotatingFileHandler('queue.log')
# Sitting comfortably in its own thread, isolated from async code.
queue_listener = QueueListener(log_queue, rot_handler)
# Start listening.
queue_listener.start()
@asynccontextmanager
async def lifespan(app: FastAPI):
yield
logger = logging.getLogger()
logger.info("Application is shutting down.")
# Should stop listening.
queue_listener.stop()
app = FastAPI(lifespan=lifespan)
@app.get("/")
async def root(request: Request):
logger.debug(f"I am {request.url}")
return {"message": "Hello World"}
I am not entirely sure if the above logging approach can also be classified as asynchronous logging
, because only one thread can control the Python interpreter at a time, as discussed in this article.
The final implementation for this post is slightly more complex than the example above, but the underlying technical principles remain the same.
β· Letβs discuss how the logging messages for each request should be structured.
-
When a request is being served, the application automatically logs the following message:
* Request Started [< Session Id not available >][UUID session Id]
- The request's endpoint handler can optionally log its own messages.
-
After a request has been served, the application automatically logs the following message:
* Request Finished [< Session Id not available >][UUID session Id]
We will refer to the two messages * Request Started ...
and * Request Finished ...
as a marker pair throughout the rest of this post.
As you may recall from the third post, we implemented the UUID session Id
. An authenticated session
is uniquely identified by a UUID session Id
. Thus, a UUID session Id
will be logged with the marker pair if one is available, otherwise the text < Session Id not available >
will be logged. Please see the following illustrative examples.
β΅ Logging where a UUID session Id
is not yet available, i.e., the request is from an un authenticated session
:
INFO: ... * Request Started < Session Id not available >
INFO: ... Path: http://192.168.0.16:5000/auth/login?state=0
DEBUG: ... Attempt to deliver the login page.
DEBUG: ... Delivering the login page.
INFO: ... * Request Finished < Session Id not available >
INFO: ... 192.168.0.2:61019 - "GET /auth/login?state=0 HTTP/1.1" 200
βΆ Logging with a UUID session Id
, i.e., the request is from an authenticated session
:
INFO: ... * Request Started f9b96bcdab8b5153c44ca02e0a489c7d
INFO: ... Path: http://192.168.0.16:5000/admin/me
DEBUG: ... Returning a valid logged-in user.
INFO: ... * Request Finished f9b96bcdab8b5153c44ca02e0a489c7d
INFO: ... 192.168.0.2:61016 - "GET /admin/me HTTP/1.1" 200
π₯ Please note the last line in each of the above two examples. It originates from the httptools_impl.py
module, specifically the method send
on line 466
. It is outside of the marker pair, and I did not attempt to have it logged within the marker pair. I believe that, together with the thread Id
(not shown) and the path, we can visually trace the originating request.
βΈ The changes to the code are quite minimal. Essentially, weβre adding a new YAML logging configuration file, a new Python module, and incorporating logging into other modules. The updated structure of the project is outlined below.
-- Please note, those marked with β
are updated, and those marked with β are new.
/home/behai/fastapi_learning/
.
βββ logger_config.yaml β
βββ main.py β
βββ pyproject.toml β
βββ pytest.ini
βββ README.md β
βββ src
β βββ fastapi_learning
β βββ common
β β βββ consts.py
β β βββ queue_logging.py β
β βββ controllers
β β βββ admin.py β
β β βββ auth.py β
β β βββ __init__.py
β βββ __init__.py
β βββ models
β β βββ employees.py
β βββ static
β β βββ styles.css
β βββ templates
β βββ admin
β β βββ me.html
β βββ auth
β β βββ home.html
β β βββ login.html
β βββ base.html
βββ tests
βββ conftest.py
βββ __init__.py
βββ integration
β βββ test_admin_itgt.py
β βββ test_api_itgt.py
β βββ test_auth_itgt.py
βββ README.md
βΉ In this section, we discuss the implementation of non-blocking logging
.
I have used RotatingFileHandler for logging via an external YAML configuration file before. I appreciate this approach because we can adjust the logging by tweaking the configuration file without having to refactor the code. I would like to adopt the same approach for this implementation. We will first examine the YAML configuration file and then the associated Python code.
β΅ The full content of the YAML configuration file, logger_config.yaml
, is listed below:
version: 1
disable_existing_loggers: False
formatters:
default:
(): uvicorn.logging.DefaultFormatter
format: '{levelprefix} [{asctime}] {thread} {filename} {funcName} {lineno} {message}'
style: '{'
datefmt: '%d-%m-%Y %H:%M:%S'
colours_removed:
(): uvicorn.logging.DefaultFormatter
format: '{levelname} [{asctime}] {thread} {filename} {funcName} {lineno} {message}'
style: '{'
handlers:
console:
formatter: default
class: logging.StreamHandler
stream: ext://sys.stdout
rotating_file:
formatter: colours_removed
class: logging.handlers.RotatingFileHandler
filename: ./logs/fastapi_learning.log
maxBytes: 4096
backupCount: 5 # Keep 5 old log files
encoding: utf-8
queue_rotating_file:
class: logging.handlers.QueueHandler
# queue: fastapi_learning.common.queue_logging.queue_factory
# listener: fastapi_learning.common.queue_logging.CustomListener
handlers:
- rotating_file
loggers:
# uvicorn.error is also valid. It is the equivalence of root.
# uvicorn.error:
# level: INFO
# handlers:
# - console
# - qhand
# propagate: no
fastapi_learning.debug:
level: DEBUG
handlers:
- console
- queue_rotating_file
propagate: no
root:
level: INFO
handlers:
- console
- queue_rotating_file
All aspects of the above configuration file are documented in the official Python logging documentation. We will discuss some implementation details below.
-
For completeness, we log to both the console (
stdout
) and log files. Thedefault
formatter is for the console, where we retain the default colours. Thecolours_removed
formatter is for the log file. Without removing the text colours, log files will have control codes written in place of text colours. For example,^[[32mINFO^[[0m:
, where^[
denotes theESC
control character, whose ASCII code is27
. Please refer to this screenshot for the exact printout. Please further note the following:-
Log attributes such as
levelname
,thread
etc., are covered by the official documentation on LogRecord attributes. -
I cannot find official documentation for
levelprefix
. However, it is mentioned and used in discussions about Python logging across the internet. I have observed thatlevelprefix
andlevelname
both print out the text logging level such asDEBUG
,INFO
etc.;levelprefix
prints out with colours whilelevelname
does not. -
For the rather unusual entry
(): uvicorn.logging.DefaultFormatter
, please refer to the official documentation on User-defined objects.
-
Log attributes such as
-
For the
rotating_file
handler, please note:-
π₯ For the
filename: ./logs/fastapi_learning.log
property, we configured the log files to be written to the./logs
sub-directory. This is not something supported out of the box. We will discuss this property in a later section. -
The values of
maxBytes
andbackupCount
are deliberately set low for debugging purposes.
-
π₯ For the
-
For the
queue_rotating_file
handler, please note:-
The YAML configuration is a copy of the snippet from the Python documentation on Configuring QueueHandler and QueueListener. We left both the
queue
key and thelistener
out. We use the standard implementations as documented.π₯ It is the applicationβs responsibility to start and stop any QueueListener instances in use. We will discuss this in a later section.
-
The QueueHandler is a special case: it has its own handlers, in this case, it is the
rotating_file
.It is worth noting that the structure of the
queue_rotating_file
is very similar to the non-blocking logging example presented in an earlier section.
-
-
We configure only one logger:
fastapi_learning.debug
. Its log messages are consumed by both the console and thequeue_rotating_file
handlers.
βΆ We will now discuss the new Python module, common/queue_logging.py
, which works in conjunction with the above YAML configuration file. This is a straightforward module, comprising less than 90 lines.
-
In the
rotating_file
handler section, we mentioned that the./logs
sub-directory is not supported out of the box. As it is configured, it is a sub-directory immediately under the directory where themain.py
module resides.We need to manage this sub-directory ourselves: we must ensure that this sub-directory exists before the YAML configuration file is loaded, otherwise Python will raise an exception.
π₯ Therefore, passing the YAML configuration file in the command line, such as
uvicorn main:app --log-config=logger_config.yaml
, is not possible, or more accurately, I donβt know how to enable that. I tried and failed to run my code before the configuration file was loaded.The next best option is to load the configuration file ourselves: we have full control. Please refer to the function
prepare_logging_and_start_listeners
, lines 57-65, in the newcommon/queue_logging.py
module. The actual code consists of only 4 lines:-
Always create the
./logs
sub-directory. - We then load the configuration file and pass it to logging.config.dictConfig.
π₯ Please note that, due to the above implementation, the loggers have not been configured yet when the application starts up. The startup messages below are not written to the current log file. The default existing loggers are still in use at this point.
INFO: Started server process [29204] INFO: Waiting for application startup. INFO: Application startup complete. INFO: Uvicorn running on http://0.0.0.0:5000 (Press CTRL+C to quit)
-
Always create the
-
In a previous section, we mentioned that it is the applicationβs responsibility to start and stop any QueueListener instances. The last part of the function
prepare_logging_and_start_listeners
, lines67
to69
, implements the code to get the listeners to start listening.We retrieve all listener instances and start each one. The private helper function
__retrieve_queue_listeners
should be self-explanatory.We currently have only one listener instance, but in the future, we might configure more, such as for sending out emails. In such a case, we would need to update only the private function
__retrieve_queue_listeners
.Before the application shuts down, it should call
logging_stop_listeners
to get the listeners to stop listening. - And finally, the
RequestLoggingMiddleware
class implements the request logging marker pair that was mentioned in an in an earlier section.
β· The changes in main.py
are straightforward and should be self-explanatory.
For information on the new lifespan
function, please refer to the official FastAPI documentation on Lifespan.
βΈ Having implemented all of the above, we are finally able to incorporate logging into the methods in the two modules, controllers/auth.py
and controllers/admin.py
.
βΊ Some of the referenced official documentation has already been mentioned throughout the discussion. However, I believe it is rather essential, so I would like to reiterate it in this separate section. I have personally read through all the Python documentation on logging. They include:
- logging β Logging facility for Python.
- Basic Logging Tutorial.
- Advanced Logging Tutorial.
- Logging Cookbook.
The last one is particularly interesting. Python logging is indeed a powerful library.
β» When I first started this logging process, I thought it was going to be simple. However, it took a bit longer than I anticipated. I encountered some problems, but I managed to find solutions. The code presented in this post has gone through several refactorings. This is the first time I have explored Python logging in detail. I learned a lot during the writing of this post. There is room for improvement, but overall, I think the implementation is acceptable.
Thank you for reading. I hope you find the information in this post useful. Stay safe, as always.
βΏβΏβΏ
Feature image source:
- https://www.omgubuntu.co.uk/2022/09/ubuntu-2210-kinetic-kudu-default-wallpaper
- https://in.pinterest.com/pin/337277459600111737/
- https://www.python.org/downloads/release/python-3124/
- https://fastapi.tiangolo.com/
- https://1000logos.net/download-image/
Top comments (0)