-
Notifications
You must be signed in to change notification settings - Fork 273
Open
@EasyAsABC123
The
Description
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.
- 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)
- Since middleware is ran in a separate threadpool worker as the action/event/view, the contextvar isn't shared between them.
- 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.