After asgi-correlation-id is used, the log cannot be printed when creating fastapi app

[slowchen]

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

[JonasKs]

Hi!

This is probably a question you should ask over at loguru, since it is not really related to this package. I am not a loguru user, and I'm not sure why you have to write logger.remove(), but this is the source of your problem. Remove that line and the log is printed. Uvicorn also takes log arguments, so maybe you should look into that?

I'll close this issue, but we'll still get notified if you reply in it. Have a good weekend 😊

[slowchen]

Thank you for your answer. And according to your picture, why is there no correlation id in the start app output log

[JonasKs]

The correlation ID is generated when a request is done to FastAPI, and then that ID attached to all other log messages for that request. In other words, if there is just a normal log that is not triggered through a request, it won’t have a correlation ID. Using loguru it seems to be completely gone, normally it would be None.

[slowchen]

OK, I probably understand what you mean. This may be the problem of loguru. If you use python logging, even normal log can be printed success. Is that right?

[JonasKs]

I mean, the ID is generated on an incoming request. So any log generated on startup/shutdown is not triggered by an incoming request, and won’t have an ID.

[slowchen]

I see. Thank you very much for your reply. Have a nice weekend

[JonasKs]

You’re welcome. Thank you, you too!😊