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.

114-feature-image.png
Python FastAPI: Implementing Non-Blocking Logging with Built-In QueueHandler and QueueListener Classes

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

❶ 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:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46

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.

  1. For completeness, we log to both the console (stdout) and log files. The default formatter is for the console, where we retain the default colours. The colours_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 the ESC control character, whose ASCII code is 27. 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 that levelprefix and levelname both print out the text logging level such as DEBUG, INFO etc.; levelprefix prints out with colours while levelname does not.
    • For the rather unusual entry (): uvicorn.logging.DefaultFormatter, please refer to the official documentation on User-defined objects.
  2. 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 and backupCount are deliberately set low for debugging purposes.
  3. 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 the listener 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.

  4. We configure only one logger: fastapi_learning.debug. Its log messages are consumed by both the console and the queue_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.

  1. 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 the main.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 new common/queue_logging.py module. The actual code consists of only 4 lines:

    💥 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)

  2. 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, lines 67 to 69, 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.

  3. 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:

  1. logging — Logging facility for Python.
  2. Basic Logging Tutorial.
  3. Advanced Logging Tutorial.
  4. 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:

🐍 Index of the Complete Series.