Looking for advice on ThreadPool separation for middleware and actual event, looking for ContextVars to be passed

A issue não nomeia arquivos nem testes do repositório; comece rastreando como o middleware e os handlers de eventos/ações/views são despachados entre os workers do thread pool. Compare os caminhos de execução relevantes com o comportamento de Python ContextVar e determine o limite de propagação pretendido. O trabalho estará concluído quando houver um design acordado e a cobertura correspondente para IDs de correlação entre middleware e handlers.

Looking for advice on ThreadPool separation for middleware and actual event, looking for ContextVars to be passed

Reproducible in:

pip freeze | grep slack
python --version
sw_vers && uname -v # or `ver`

The slack_bolt version

slack_bolt==1.20.1
slack_sdk==3.34.0
slackclient==2.9.4

Python runtime version

Python 3.11.10

OS info

ProductName: macOS
ProductVersion: 15.3.1
BuildVersion: 24D70
Darwin Kernel Version 24.3.0: Thu Jan 2 20:24:16 PST 2025; root:xnu-11215.81.4~3/RELEASE_ARM64_T6000

Steps to reproduce:

I am attempting to create a trace_id/correlation_id for all slack events/actions/views etc to help with tracking in our structured logs.

1. Create Global middleware, contextvar, and LogFilter

Context

from contextvars import ContextVar
from typing import Optional

from slack_bolt import BoltContext

# Middleware
correlation_id: ContextVar[Optional[str]] = ContextVar("correlation_id", default=None)

LogFilter

from logging import Filter, LogRecord
from typing import Optional

from.modules.logging import correlation_id


def _trim_string(string: Optional[str], string_length: Optional[int]) -> Optional[str]:
    return string[:string_length] if string_length is not None and string else string


class CorrelationIdFilter(Filter):
    """Logging filter to attached correlation IDs to log records"""

    def __init__(
        self,
        name: str = "",
        uuid_length: int | None = None,
        default_value: str | None = None,
    ):
        super().__init__(name=name)
        self.uuid_length = uuid_length
        self.default_value = default_value

    def filter(self, record: "LogRecord") -> bool:
        """
        Attach a correlation ID to the log record.

        Since the correlation ID is defined in the middleware layer, any
        log generated from a request after this point can easily be searched
        for, if the correlation ID is added to the message, or included as
        metadata.
        """
        cid = correlation_id.get(self.default_value)
        record.correlation_id = _trim_string(cid, self.uuid_length)
        return True

Middleware

    from.modules.logging import correlation_id

    def call(context: BoltContext, logger: Logger, next: Callable[[], None]) -> None:
        # Capture the current context
        current_context = copy_context()
        current_thread = threading.current_thread()

        id_value: str | None = correlation_id.get()
        if id_value is not None:
            logger.info(
                f"{__name__} {id_value=} found id in contextvar {current_thread=}"
            )
        elif context.get("correlation_id", None) is not None:
            id_value = context["correlation_id"]
            token = correlation_id.set(id_value)
            logger.info(f"{__name__} {id_value=} found id in context {current_thread=}")
        else:
            id_value = uuid4().hex
            context["correlation_id"] = id_value
            token = correlation_id.set(id_value)
            logger.info(f"{__name__} {id_value=} generated new id {current_thread=}")

        try:
            current_context.run(next)
        finally:
            if token:
                correlation_id.reset(token)

3. Since middleware is ran in a separate threadpool worker as the action/event/view, the contextvar isn't shared between them.
4. Log filter always print None from the ContextVar due to this...

Expected result:

{"levelname": "INFO", "correlation_id": "34a110e2ba6d4100a099e18fd2fb4c74", "name": "module_name", "message": "log message here", "lineno": 44, "asctime": "2025-03-07 13:47:16,182", "exc_info": null}

Actual result:

{"levelname": "INFO", "correlation_id": null, "name": "module_name", "message": "log message here", "lineno": 44, "asctime": "2025-03-07 13:47:16,182", "exc_info": null}

Requirements

Please read the Contributing guidelines and Code of Conduct before creating this issue or pull request. By submitting, you are agreeing to those rules.