airtai / faststream

FastStream is a powerful and easy-to-use Python framework for building asynchronous services interacting with event streams such as Apache Kafka, RabbitMQ, NATS and Redis.
https://faststream.airt.ai/latest/
Apache License 2.0
2.12k stars 99 forks source link

Bug: RedisBroker adds log_context to extra #1564

Open febus982 opened 2 days ago

febus982 commented 2 days ago

Describe the bug I use structlog in my application and extra metadata are handled in an inconsistent way which break my JSON schema:

https://github.com/airtai/faststream/issues/1227 was marked as resolved but I suspect it might need some more work maybe?

How to reproduce

Broker creation

    broker = RedisBroker(
        config.EVENTS.REDIS_BROKER_URL,
        middlewares=(RedisOtelMiddleware,),
        logger=structlog.getLogger("faststream.broker"),
    )

Structlog processor:

def faststream_context(_, __, event_dict: EventDict) -> EventDict:
    """
    Extract FastStream context information from extra and adds them to the event dict.
    """

    c = context.get_local("log_context") or {}
    event_context = event_dict.get(
        "event_context",
        c.copy(),
    )

    # Type check debug
    event_context["context_type"] = type(context.get_local("log_context"))

    if event_context:
        event_dict["event_context"] = event_context

    return event_dict

Expected behavior

Observed behavior Console output on startup (2nd line produces extra but nothing is available using context.get_local("log_context"))

event-consumer-1  | 30-06-2024 19:41:14 [info     ] FastStream app starting...     [faststream.app] event_context={'context_type': <class 'NoneType'>} process_name=MainProcess span=None thread_name=MainThread
event-consumer-1  | 30-06-2024 19:41:14 [info     ] `HandleMsg` waiting for messages [faststream.broker] event_context={'context_type': <class 'NoneType'>} extra={'channel': 'books_topic', 'message_id': ''} process_name=MainProcess span=None thread_name=MainThread
event-consumer-1  | 30-06-2024 19:41:14 [info     ] FastStream app started successfully! To exit, press CTRL+C [faststream.app] event_context={'context_type': <class 'NoneType'>} process_name=MainProcess span=None thread_name=MainThread

Console output on event received (here extra and event_context are consistent, except if I submit extra via a logger, 2nd log line)

event-consumer-1  | 30-06-2024 19:41:18 [info     ] Received                       [faststream.broker] event_context={'channel': 'books_topic', 'message_id': '80ef6ff6-908b-4e77-b856-1527937b45f1', 'context_type': <class 'dict'>} extra={'channel': 'books_topic', 'message_id': '80ef6ff6-908b-4e77-b856-1527937b45f1'} process_name=MainProcess span={'span_id': '0x6d614e67944f1da7', 'trace_id': '0xb509a452fea501d30508d3c95f31f250', 'parent_span_id': '0x95e16ac90ea1ff55'} thread_name=MainThread
event-consumer-1  | 30-06-2024 19:41:18 [info     ] Received message               [faststream.broker] event_context={'channel': 'books_topic', 'message_id': '80ef6ff6-908b-4e77-b856-1527937b45f1', 'context_type': <class 'dict'>} extra={'msg': 'some_extra_here'} process_name=MainProcess span={'span_id': '0x6d614e67944f1da7', 'trace_id': '0xb509a452fea501d30508d3c95f31f250', 'parent_span_id': '0x95e16ac90ea1ff55'} thread_name=MainThread
event-consumer-1  | 30-06-2024 19:41:18 [info     ] Processed                      [faststream.broker] event_context={'channel': 'books_topic', 'message_id': '80ef6ff6-908b-4e77-b856-1527937b45f1', 'context_type': <class 'dict'>} extra={'channel': 'books_topic', 'message_id': '80ef6ff6-908b-4e77-b856-1527937b45f1'} process_name=MainProcess span=None thread_name=MainThread

Screenshots N/A

Environment

Running FastStream 0.5.14 with CPython 3.11.9 on Darwin

Additional context N/A