This article explains how request IDs can help improve your ability to debug failures. It uses asgi-correlation-id, which provides everything we need to get set up.
When are request IDs useful?
Let’s assume we’re writing an app with a user-creation endpoint, which involves some special handling dependent on inputs before returning a created user back to the client.
import logging
from fastapi import FastAPI
logger = logging.getLogger(__name__)
app = FastAPI()
async def create_user(user: UserModel):
if user.attribute_one == 'some_value':
logger.info('First log')
... # do something
if user.attribute_two == 'some_value':
logger.info('Second log')
... # do something else
if user.attribute_three == 'some_value':
logger.info('Third log')
... # do something else created_user = ... # finalize user creation return created_user
@app.post('/users', status_code=201)
async def important_view(user: UserModel):
try:
user = await create_user(user)
return user
except Exception:
logger.error('Something went wrong', exc_info=True)
raise
There is a chance user creation might fail, but in case this happens, we’ve added some logging to help us understand and/or replicate the issue.
So let’s assume a request to this endpoint fails. How do we use our logs?
The short answer is that with our current configuration we can only really benefit from our logs in cases where traffic is so infrequent that the timestamp of the error log is enough for us to identify which logs belong to the failed request. We would hope that our logs would look something like this:
INFO 11:19:25 app.main:13 First log
INFO 11:19:26 app.main:16 Second log
INFO 11:19:27 app.main:19 Third log
ERROR 11:19:28 app.main:31 Something went wrongBut what happens when we start handling more than one request per second?
We completely lose our ability to reason about which logs belong to what request. Here’s what the output of a server with a little more traffic might looks like:
INFO 11:19:25 app.main:13 First log
INFO 11:19:25 app.main:13 First log
INFO 11:19:25 app.main:13 First log
INFO 11:19:26 app.main:13 First log
INFO 11:19:26 app.main:13 First log
INFO 11:19:26 app.main:16 Second log
INFO 11:19:26 app.main:16 Second log
INFO 11:19:27 app.main:16 Second log
INFO 11:19:27 app.main:19 Third log
INFO 11:19:27 app.main:19 Third log
ERROR 11:19:26 app.main:31 Something went wrongSo we want to be able to rely on our logs for debugging, but they’re currently of no use, since we’re missing a mechanism for correlating our logs to a single request.
This is where request IDs can help!
With request ID logging configured, each of our logs will contain a unique ID tying them to a single request. With request IDs, our logs look like this:
INFO 11:19:25 app.main:13 [8a0321a1] First log
INFO 11:19:25 app.main:13 [39565b6d] First log
INFO 11:19:25 app.main:13 [04fcaf13] First log
INFO 11:19:26 app.main:13 [2ed1c3a6] First log
INFO 11:19:26 app.main:13 [e6c98288] First log
INFO 11:19:26 app.main:16 [04fcaf13] Second log
INFO 11:19:26 app.main:16 [8a0321a1] Second log
INFO 11:19:27 app.main:16 [2ed1c3a6] Second log
INFO 11:19:27 app.main:19 [39565b6d] Third log
INFO 11:19:27 app.main:19 [04fcaf13] Third log
ERROR 11:19:26 app.main:31 [e6c98288] Something went wrongNow we can tell that it’s request e6c98288 is failing, and we can see that it’s different from the other request in that it’s the only request where no second or third log was output. Now we have some idea about how we might replicate the error.
This is obviously just a simplified example, but it’s worth noting that when things get more complex, the value of request IDs goes up. The benefit of being able to correlate logs to requests will scale positively with the complexity of your project.
Setting up request IDs from scratch, using asgi-correlation-id
It only takes us around a minute to set up what we need, as there’s only two components we’ll need to add to a project to enable request ID logging.
- First we need to add a middleware. The middleware will read or generate request IDs for us, for each incoming request.
- Then we need to add a log filter, to make sure the IDs are included in our log output.
Adding the middleware
Adding the middleware is as easy as adding it to your FastAPI app:
from asgi_correlation_id import CorrelationIdMiddleware
from fastapi import FastAPI
app = FastAPI()
app.add_middleware(CorrelationIdMiddleware)Setting up logging
Setting up logging can be done in several ways. This section provides 3 separate examples, for different log configuration methods. To make things simple, all 3 examples have all configuration put into a single function you can copy into your project.
If your project has no existing logging configuration, just copy the second example.
1/3. Basic configuration
If you’re using - and want to keep using logging.basicConfig, here’s how you would add the necessary log filter and formatter.
import logging
from asgi_correlation_id import correlation_id_filter, CorrelationIdMiddleware
from fastapi import FastAPI
logger = logging.getLogger(__name__)
def configure_logging():
cid_filter = correlation_id_filter(uuid_length=32)
console_handler = logging.StreamHandler()
console_handler.addFilter(cid_filter())
logging.basicConfig(
handlers=[console_handler],
level=logging.DEBUG,
format='%(levelname)s: \t %(asctime)s %(name)s:%(lineno)d [%(correlation_id)s] %(message)s'
)
app = FastAPI(on_startup=[configure_logging])
app.add_middleware(CorrelationIdMiddleware)
@app.get('/')
def index():
logger.info('Log with correlation ID')2/3. Dictionary logging configuration
Perhaps a better way of configuring logging for larger projects is by using logging.dictConfig. This configuration is more or less the same as the basicConfig setup, but explicitly defines your entire logging configuration in a single data structure.
import logging
from logging.config import dictConfig
from asgi_correlation_id import correlation_id_filter, CorrelationIdMiddleware
from fastapi import FastAPI
logger = logging.getLogger(__name__)
def configure_logging() -> None:
dictConfig(
{
'version': 1,
'disable_existing_loggers': False,
'filters': {
'correlation_id': {'()': correlation_id_filter(32)},
},
'formatters': {
'console': {
'class': 'logging.Formatter',
'datefmt': '%H:%M:%S',
'format': '%(levelname)s: \t %(asctime)s %(name)s:%(lineno)d [%(correlation_id)s] %(message)s',
},
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'filters': ['correlation_id'],
'formatter': 'console',
},
},
'loggers': {
# project
'app': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
# third-party packages
'httpx': {'handlers': ['console'], 'level': 'INFO'},
'databases': {'handlers': ['console'], 'level': 'WARNING'},
'asgi_correlation_id': {'handlers': ['console'], 'level': 'WARNING'},
},
}
)
app = FastAPI(on_startup=[configure_logging])
app.add_middleware(CorrelationIdMiddleware)
@app.get('/')
def index():
logger.info('Log with correlation ID')3/3. Loguru
If you’re using a third-party logging library like Loguru, the built-in filter that asgi-correlation-id ships with, might not be compatible. In that case it’s very simple to write your own filter, like this:
import logging
import sys
from asgi_correlation_id import CorrelationIdMiddleware
from fastapi import FastAPI
from loguru import logger
def configure_logging():
from asgi_correlation_id.context import correlation_id
def correlation_id_filter(record):
record['correlation_id'] = correlation_id.get()
return record['correlation_id']
logger.remove()
fmt = "{level}: \t {time} {name}:{line} [{correlation_id}] - {message}"
logger.add(sys.stderr, format=fmt, level=logging.DEBUG, filter=correlation_id_filter)
app = FastAPI(on_startup=[configure_logging])
app.add_middleware(CorrelationIdMiddleware)
@app.get('/')
def index():
logger.info('Log with correlation ID')Integrating with Sentry
For projects which use the sentry-sdk package, asgi-correlation-id automatically integrates with Sentry by adding transaction IDs to events.
The transaction ID is displayed on the detail page of each event, and is set to the value of the request ID, making it simple to correlate logs related to individual Sentry errors.
Extending request IDs
Once a project is set up with request ID logging, the next thing to think about is passing request IDs between your projects, if you have several.
Let’s say you have a frontend which speaks to a primary backend, and that backend speaks to other microservices when handling requests. As long as each one of your projects catches and propagates request IDs via HTTP headers, it is possible to correlate logs across your services.
Most web frameworks either have request ID logging built-in, or have popular libraries that are easy to implement. For, e.g., Django projects, django-guid is a good alternative.
Everything beyond this point is centered more around asgi-correlation-id and its features. Feel free to read on if you’re curious, and feel free to open an issue on Github if you have questions not answered by this article or the package documentation.
Package internals
For anyone curious, the package middleware is very simple. Fundamentally, all it does it read an incoming HTTP header (‘X-Request-ID’ by default, but which header to look for is configurable) and set the HTTP header value to a contextvar. If no request ID was passed in with the request, the middleware generates one instead:
header_value = headers.get('X-Request-ID')
if not header_value:
id_value = uuid4().hex
else:
id_value = header_valueWhile the middleware is simple, the log filter is maybe even simpler. All we do is read the contextvar and assign a value to the log-record:
def filter(record):
record.correlation_id = correlation_id.get()
return TrueWith these two elements combined, your project now has a mechanism for correlating logs.
Other features
The middleware also has a few extra features:
Validating incoming request ID header values
By default, the middleware will validate incoming HTTP header values as valid UUIDs. Request IDs should be unique , so enforcing the use of UUIDs is a way to reduce the risk of collisions. Validation can be toggled off with a setting.
Request ID response headers
All request IDs are returned back to clients in returned responses, using the request ID HTTP key. By default the key used is ‘X-Request-ID’, but this is also configurable.
Access-Control-Expose-Headers
The request ID HTTP key is included in the ‘Access-Control-Expose-Headers’ response header.
Typed
The package is fully typed, and includes a PEP 561-style py.typed to indicate that its types should be made available to type checkers.
Tested
The package is fully tested with 100% test coverage.
