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

[EasyAsABC123]

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.

[EasyAsABC123]

The context var gets set but then all events/actions/views need to update the ContextVar, which isn't ideal.

[WilliamBergamin]

Hi @EasyAsABC123 thanks for writing in 💯

I'm not familiar with ContextVar but if I'm understanding this correctly it may be easier to create an id for each request received by your app and then use it to use it in log statements, rather then creating an id for each context 🤔

You can assign this id to the context of a request in a global middleware. Something like the following should work, but there may be more elegant ways to do it

@app.use
def auth_acme(client, context, logger, next):
    id_value = uuid4().hex
    context["correlation_id"] = id_value
    logger.info(f"New request with id {id_value} started")
    
    # Pass control to the next middleware
    next()

# Update the view on submission 
@app.view("view_1")
def handle_submission(ack, body, context, logger):
    # The build_new_view() method returns a modal view
    ack(response_action="update", view=build_new_view(body))
    logger.info(f"{context['correlation_id']} view request acknowledged")

Would this be a viable workaround for you?

[EasyAsABC123]

I was hoping to avoid passing the correlation_id into each logging.info/error call, so I have a LogFilter where I am setting the result.correlation_id to the ContextVar, as a current workaround I wrote a function wrapper for each app.event or app.action function, those functions just have to take the context variable that slack bolt passes…

So flow wise

GlobalMiddleware - sets the correlation_id ContextVar and the context that slack bolt passes, because slack bold doesn’t execute the middleware in the same thread pool worker as the event function, I then have to wrap these functions and pull out the context[“correlation_id”] and set the ContextVar if it is there and not already set for this thread. With that done the LogFilter can pull the correlation_id: ContextVar and all logging gets the correlation_id in it. Since I put correlation_id into the log formatter as well…

Mainly curious if the middleware could be changed to execute in the same thread pool worker as the event functions, or at least for the thread executor if copy_context().run could wrap the calls to have the same ContextVar variables available from middleware to event function. The wrapper solution is working but just adds another layer where errors might occur.

It feels worth it for me to easily trace all logging gets messages to a single event trigger from slack. I get that switch thread executors might be too big of an ask though.