How to configure asgi-correlation with loguru ?

[sorasful]

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 !

[sondrelg]

Based on the documentation it looks like you should be able to do this:

from asgi_correlation_id.log_filters import correlation_id_filter

logger.add(
    "...", 
    level="...", 
    format=..., 
    filter=correlation_id_filter(32)
)

Where the first three attributes are the same, and the filter attribute is the only new addition.

For the formatter, I think you just need to add {correlation_id} to your fmt variable.

In other words, if you add a filter to line 17 I believe it should work. Let me know how it goes 🙂 I have more time to help you debug later tonight if you're not able to resolve it.

[sorasful]

@sondrelg Thanks for the quick reply !

So I tried to it like you said, but to avoid any confusion here's the code :

import logging
import sys

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

app = FastAPI()

app.add_middleware(CorrelationIdMiddleware)

# remove default handler
logger.remove()

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

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

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

But unfortunately, I've got the same error e.g :

...
Traceback (most recent call last):
  File "C:\Users\Utilisateur\User\x\venv\lib\site-packages\loguru\_handler.py", line 155, in emit
formatted = precomputed_format.format_map(formatter_record)
KeyError: 'correlation_id'

[sondrelg]

Ok, I'll take a closer look at this after work, in a few hours, and see if I can set up a working example 😊

[JonasKs]

I only had a few minutes to spare, and I've never touched loguru, so this might not be the correct solution. How ever, according to their documentation, filter functions are a bit different.

Using their syntax works:

from asgi_correlation_id.context import correlation_id

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

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

[2021-11-17T16:42:29.407337+0100] [application_name] [5b55244994af4247a015e707582b38ee] [INFO] - app.main:index:29 - Request with id 

[sorasful]

Wow, this works great! I wouldn't have thought about this.

I just post this full example so people will know.

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

app = FastAPI()
app.add_middleware(CorrelationIdMiddleware)

# remove default handler
logger.remove()

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

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

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

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

Thank you for your precious help and your time, I'll close this now :)

[ponponon]

Here's my example

import logging
import sys

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

app = FastAPI()

app.add_middleware(CorrelationIdMiddleware)

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)

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

输出如下：

2022-01-17 16:14:09.973 | INFO     |  4a4395d4ff4648e6bdcaa09de74a7139  | main:index:32 - Request with id 
INFO:     127.0.0.1:55324 - "GET / HTTP/1.1" 200 OK
2022-01-17 16:14:10.823 | INFO     |  23acbd0ed8724888a516c3cfb6b5fef7  | main:index:32 - Request with id 
INFO:     127.0.0.1:55326 - "GET / HTTP/1.1" 200 OK
2022-01-17 16:14:11.420 | INFO     |  9456154f756a4894bc470148e430acb2  | main:index:32 - Request with id 
INFO:     127.0.0.1:55328 - "GET / HTTP/1.1" 200 OK
2022-01-17 16:14:11.995 | INFO     |  8e89a4b6cd3747c4a2a479f26f9e6051  | main:index:32 - Request with id 
INFO:     127.0.0.1:55330 - "GET / HTTP/1.1" 200 OK
2022-01-17 16:14:12.657 | INFO     |  e4050d68717d4709983fa733683bef99  | main:index:32 - Request with id 
INFO:     127.0.0.1:55332 - "GET / HTTP/1.1" 200 OK
2022-01-17 16:14:13.202 | INFO     |  5b34d75b2fa54a0ebf95b84af949ceda  | main:index:32 - Request with id 
INFO:     127.0.0.1:55334 - "GET / HTTP/1.1" 200 OK