Refer to #50

Please review and I can address any requested changes :)

Added customizable generator options to celery extension to better match capabilities of the correlation id middleware

• Added optional "header_key" param to asgi_correlation_id.extensions.celery.load_correlation_id
• Added optional "generator" param to asgi_correlation_id.extensions.celery.load_correlation_id
• Added optional "generator" param to asgi_correlation_id.extensions.celery.load_celery_current_and_parent_ids

The current implementation provides log filter classes which can be used to enrich the log records with correlation IDs. This is a surprising use of a filter since it has a side effect and modifies a log record. For example, when attaching the filter to one handler, another handler may see the modified log record.

According to the documentation (just below https://docs.python.org/3/library/logging.html?highlight=logrecord#logging.LogRecord.getMessage), the intended pattern for custom log record generation is to use a modified log record factory function like this:

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.custom_attribute = 0xdecafbad
    return record

logging.setLogRecordFactory(record_factory)

The only annoying thing here is that this one-off setting of the factory cannot be done using logging.config.

Short of asking app developers to bootstrap the record factory, manually, there may be an alternative whereby the ASGI middleware could be responsible for this. When using a class-based middleware implementation, the middleware's __init__() constructor may be able to set the log record factory?

Starlette responses adds cookies as headers with the same key. self.raw_headers.append((b"set-cookie", cookie_val.encode("latin-1")))

In your middleware handle outgoing request over writes the same key with only the last value.

        async def handle_outgoing_request(message: Message) -> None:
            if message['type'] == 'http.response.start':
                headers = {k.decode(): v.decode() for (k, v) in message['headers']}
                headers[self.header_name] = correlation_id.get()
                headers['Access-Control-Expose-Headers'] = self.header_name
                response_headers = Headers(headers=headers)
                message['headers'] = response_headers.raw
            await send(message)

I want to use correlation_id.get() to get trace_id in my exception_handler but got empty, is there any wrong?

full code:

import uvicorn

from asgi_correlation_id import CorrelationIdMiddleware, correlation_id
from fastapi import FastAPI, Request, status
from fastapi.responses import JSONResponse

app = FastAPI()

@app.exception_handler(Exception)
async def unicorn_exception_handler(request: Request, exception: Exception):
    trace_id = correlation_id.get() or 'ccc'
    return JSONResponse(
        status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
        content={"code": config.errcode.INSIDE_ERROR, "msg": "error.", "data": [], "trace": trace_id}
    )

app.add_middleware(
    CorrelationIdMiddleware,
    header_name="X-Trace"
)

@app.get("/items")
async def read_item(request: Request):
    trace_id = correlation_id.get()
    print(trace_id)
    raise AttributeError
    return {"item_id": "100", "trace": trace_id}

if __name__ == '__main__':
    uvicorn.run(app='main:app', host="0.0.0.0", port=8000, reload=True)

request:

curl   -XGET  http://<server-ip>:8000/items

response:

Http Code: 500
{"code":99999,"msg":"error.","data":[],"trace":"ccc"}

Thanks

As in a typical micro-service architecture, I want the correlation Id to be automatically propagated to the outbound requests made from one API to other APIs. I'm using the HTTPX AsyncClient for the same. But unless I explicitly add the header to the client object, the other API services do not receive it inherently and they create their own header which ultimately defeats the purpose of having a correlation-id.

I configured loguru in fastapi according to the example, and the code is as follows.

import logging
import sys

import uvicorn
from asgi_correlation_id import CorrelationIdMiddleware
from asgi_correlation_id.context import correlation_id
from fastapi import FastAPI
from loguru import logger

logger.remove()


def correlation_id_filter(record):
    record['correlation_id'] = correlation_id.get()
    return record['correlation_id']


fmt = "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | <level>{level: <8}</level> | <red> {correlation_id} </red> | <cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> - <level>{message}</level>"

logger.add(sys.stderr, format=fmt, level=logging.DEBUG, filter=correlation_id_filter)


def start_app():
    logger.info('start app....')
    print('start app....')


app = FastAPI()

app.add_middleware(CorrelationIdMiddleware)

app.add_event_handler('startup', start_app)


@app.get('/')
def index():
    logger.info(f"Request with id ")
    return 'OK'


if __name__ == '__main__':
    uvicorn.run(app='mainw:app', host='0.0.0.0', port=8000, reload=False, debug=True)

After the project is started, logger did not print the log in start_app(), just print()

/Users/slowchen/.virtualenvs/fastapi/bin/python /Users/slowchen/workspace/FastApi/tianya-fastapi/app/mainw.py
INFO:     Will watch for changes in these directories: ['/Users/slowchen/workspace/FastApi/tianya-fastapi/app']
INFO:     Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [31627] using statreload
INFO:     Started server process [31629]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
start app....
INFO:     127.0.0.1:52057 - "GET / HTTP/1.1" 200 OK
2022-03-12 13:43:30.186 | INFO     |  048a508fb369425fb25a63631899b99c  | mainw:index:37 - Request with id 

How can I configure it to print the log correctly when fastapi, startup or adding middleware

Responses that are returned without error, or responses that are returned when an HTTPException is raised, include the correlation header name and the correlation id.

However, when an unhandled exception is raised, for example with this code:

@app.get("/")
async def root():
    a = 1/0
    return {"message": "Hello!"}

then a 500 error is returned to the client, and the correlation header is not included.

It seems like it would be especially nice to have the correlation id included in the response headers for such cases.

I use loguru for logging, saw your example for adding the correlation id for requests. But I am unable to add parent and current process id for celery tasks in loguru. Can you help?

Hey author, thanks for the amazing work! Our team is planning to onboard this library in our projects. I have been trying to retrieve the created correlation ID inside a view function in FastAPI but I am not able to query it somehow. I have tried querying the request.headers and request.body(), and am still not able to find it. How can I get that?

Hello there !

Loguru seems to get more popularity as time goes by, I've tried to setup a very minimal example to get your library working with it, but it seems it can't find the correlation id.

I've tried several things, and right now i'm doing this :

import logging
import sys

import uvicorn
from asgi_correlation_id import CorrelationIdMiddleware
from fastapi import FastAPI
from loguru import logger

app = FastAPI()

app.add_middleware(CorrelationIdMiddleware)

# remove default handler
logger.remove()

fmt = "[{time}] [application_name] [{extra[correlation_id]}] [{level}] - {name}:{function}:{line} - {message}"
logger.add(sys.stderr, format=fmt, level=logging.DEBUG)

@app.get('/')
def index():
    logger.info(f"Request with id ")
    return 'OK'



if __name__ == '__main__':
    uvicorn.run(app)

And I get a :

Record was: {'elapsed': datetime.timedelta(seconds=1, microseconds=1880), 'exception': None, 'extra': {}, 'file': (name='another_main.py', path='C:\\Users\\User\\PycharmProjects\\x\\y\\another_main.py'), 'function': 'index', 'level': (name='INFO', no=20, icon='ℹ️'), 'line': 21, 'message': 'Request with id ', 'module': 'another_main', 'name': '__main__', 'process': (id=3412, name='MainProcess'), 'thread': (id=9164, name='asyncio_0'), 'time': datetime(2021, 11, 17, 15, 7, 54, 443182, tzinfo=datetime.timezone(datetime.timedelta(seconds=3600), 'Paris, Madrid'))}
Traceback (most recent call last):
  File "C:\Users\User\PycharmProjects\x\venv\lib\site-packages\loguru\_handler.py", line 155, in emit
    formatted = precomputed_format.format_map(formatter_record)
KeyError: 'correlation_id'
--- End of logging error ---

Got any idea ? Thanks !

EDIT: Changed the name of the issue for better searchability; you can find the solution to the question here

Hey there!

I feel pretty stupid asking this question, but can you explain to me how I should create my logger instance to have a correlation_id?

Currently I create my logger at the top of the a router file:

import logging
from fastapi import APIRouter, HTTPException

LOG = logging.getLogger(__name__)

router = APIRouter(prefix="/my/route", responses={404: {"description": "Not found"}})

@router.get("/")
def handler():
   LOG.info("Hello!")

And I get

[2022-07-19T20:37:48] INFO [None] path.to.module | Hello

when my logging configuration is as follows:

    "formatters": {
        "default": {
            "format": "[%(asctime)s] %(levelname)s [%(correlation_id)s] %(name)s | %(message)s",
            "datefmt": "%Y-%m-%dT%H:%M:%S",
        }
    },

    app.add_middleware(
        CorrelationIdMiddleware,
        header_name='X-Request-ID',
        generator=lambda: uuid4().hex,
        validator=is_valid_uuid4,
        transformer=lambda a: a,
    )
 

-- I would like to have my correlation_id show up in my log like so:

[2022-07-19T20:37:48] INFO [8fe9728a] path.to.module | Hello

I can't get anything about it in both the Starlette and FastAPI documentation. It's like everybody knows this and it's not worth mentionning 🤔

Can you give me an example of how I should get a logger instance to have the request id show up?

Thanks for your help!