- Notifications
You must be signed in to change notification settings - Fork 281
Open
Labels
auto-triage-skipenhancementNew feature or requestNew feature or requestquestionFurther information is requestedFurther information is requested
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 TrueMiddleware
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.
Reactions are currently unavailable
Metadata
Metadata
Assignees
Labels
auto-triage-skipenhancementNew feature or requestNew feature or requestquestionFurther information is requestedFurther information is requested