diff --git a/slack_sdk/socket_mode/aiohttp/__init__.py b/slack_sdk/socket_mode/aiohttp/__init__.py index 5fb1d1171..a1dce6dca 100644 --- a/slack_sdk/socket_mode/aiohttp/__init__.py +++ b/slack_sdk/socket_mode/aiohttp/__init__.py @@ -143,7 +143,7 @@ async def monitor_current_session(self) -> None: session: ClientWebSocketResponse = self.current_session # type: ignore[assignment] session_id: str = self.build_session_id(session) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new monitor_current_session() execution loop for {session_id} started") try: logging_interval = 100 @@ -151,11 +151,11 @@ async def monitor_current_session(self) -> None: while not self.closed: if session != self.current_session: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The monitor_current_session task for {session_id} is now cancelled") break try: - if self.trace_enabled and self.logger.level <= logging.DEBUG: + if self.trace_enabled and self.logger.isEnabledFor(logging.DEBUG): # The logging here is for detailed investigation on potential issues in this client. # If you don't see this log for a while, it means that # this receive_messages execution is no longer working for some reason. @@ -207,7 +207,7 @@ async def monitor_current_session(self) -> None: f"(error: {type(e).__name__}, message: {e})" ) except asyncio.CancelledError: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The monitor_current_session task for {session_id} is now cancelled") raise @@ -217,7 +217,7 @@ async def receive_messages(self) -> None: # To avoid such, we access only the session that is active when this loop starts. session = self.current_session session_id = self.build_session_id(session) # type: ignore[arg-type] - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new receive_messages() execution loop with {session_id} started") try: consecutive_error_count = 0 @@ -226,14 +226,14 @@ async def receive_messages(self) -> None: while not self.closed: if session != self.current_session: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The running receive_messages task for {session_id} is now cancelled") break try: message: WSMessage = await session.receive() # type: ignore[union-attr] # just in case, checking if the value is not None if message is not None: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): # The following logging prints every single received message # except empty message data ones. m_type = WSMsgType(message.type) @@ -308,7 +308,7 @@ async def receive_messages(self) -> None: else: await asyncio.sleep(consecutive_error_count) except asyncio.CancelledError: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The running receive_messages task for {session_id} is now cancelled") raise @@ -326,7 +326,7 @@ async def is_connected(self) -> bool: and not self.current_session.closed and not await self.is_ping_pong_failing() ) - if self.logger.level <= logging.DEBUG and connected is False: + if self.logger.isEnabledFor(logging.DEBUG) and connected is False: # Prints more detailed information about the inactive connection is_ping_pong_failing = await self.is_ping_pong_failing() session_id = await self.session_id() @@ -387,7 +387,7 @@ async def connect(self): self.logger.info(f"A new session ({session_id}) has been established") # The first ping from the new connection - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Sending a ping message with the newly established connection ({session_id})...") t = time.time() await self.current_session.ping(f"sdk-ping-pong:{t}".encode("utf-8")) @@ -395,18 +395,18 @@ async def connect(self): if self.current_session_monitor is not None: self.current_session_monitor.cancel() self.current_session_monitor = asyncio.ensure_future(self.monitor_current_session()) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new monitor_current_session() executor has been recreated for {session_id}") if self.message_receiver is not None: self.message_receiver.cancel() self.message_receiver = asyncio.ensure_future(self.receive_messages()) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new receive_messages() executor has been recreated for {session_id}") break except Exception as e: if self.closed: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Stopped connecting because the client is closed (error: {e})") return self.logger.exception(f"Failed to connect (error: {e}); Retrying...") @@ -420,14 +420,14 @@ async def disconnect(self): async def send_message(self, message: str): session_id = await self.session_id() - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Sending a message: {message} from session: {session_id}") try: await self.current_session.send_str(message) # type: ignore[union-attr] except ConnectionError as e: # We rarely get this exception while replacing the underlying WebSocket connections. # We can do one more try here as the self.current_session should be ready now. - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Failed to send a message (error: {e}, message: {message}, session: {session_id})" " as the underlying connection was replaced. Retrying the same request only one time..." diff --git a/slack_sdk/socket_mode/async_client.py b/slack_sdk/socket_mode/async_client.py index 32e60ae3d..31b0dcb78 100644 --- a/slack_sdk/socket_mode/async_client.py +++ b/slack_sdk/socket_mode/async_client.py @@ -106,7 +106,7 @@ async def send_socket_mode_response(self, response: Union[Dict[str, Any], Socket async def enqueue_message(self, message: str): await self.message_queue.put(message) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): queue_size = self.message_queue.qsize() session_id = await self.session_id() self.logger.debug(f"A new message enqueued (current queue size: {queue_size}, session: {session_id})") @@ -140,7 +140,7 @@ async def process_message(self): async def run_message_listeners(self, message: dict, raw_message: str) -> None: session_id = await self.session_id() type, envelope_id = message.get("type"), message.get("envelope_id") - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Message processing started (type: {type}, envelope_id: {envelope_id}, session: {session_id})" ) @@ -166,7 +166,7 @@ async def run_message_listeners(self, message: dict, raw_message: str) -> None: except Exception as e: self.logger.exception(f"Failed to run message listeners: {e}, session: {session_id}") finally: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Message processing completed (type: {type}, envelope_id: {envelope_id}, session: {session_id})" ) diff --git a/slack_sdk/socket_mode/builtin/client.py b/slack_sdk/socket_mode/builtin/client.py index 132de10db..6701cf6f0 100644 --- a/slack_sdk/socket_mode/builtin/client.py +++ b/slack_sdk/socket_mode/builtin/client.py @@ -197,14 +197,14 @@ def disconnect(self) -> None: self.current_session.close() def send_message(self, message: str) -> None: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Sending a message (session id: {self.session_id()}, message: {message})") try: self.current_session.send(message) # type: ignore[union-attr] except SlackClientNotConnectedError as e: # We rarely get this exception while replacing the underlying WebSocket connections. # We can do one more try here as the self.current_session should be ready now. - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Failed to send a message (session id: {self.session_id()}, error: {e}, message: {message})" " as the underlying connection was replaced. Retrying the same request only one time..." @@ -235,7 +235,7 @@ def close(self) -> None: self.message_workers.shutdown() def _on_message(self, message: str): - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"on_message invoked: (message: {debug_redacted_message_string(message)})") self.enqueue_message(message) for listener in self.on_message_listeners: @@ -254,7 +254,7 @@ def _on_error(self, error: Exception): listener(error) def _on_close(self, code: int, reason: Optional[str] = None): - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"on_close invoked (session id: {self.session_id()})") if self.auto_reconnect_enabled: self.logger.info(f"Received CLOSE event. Reconnecting... (session id: {self.session_id()})") diff --git a/slack_sdk/socket_mode/client.py b/slack_sdk/socket_mode/client.py index 90127dd74..ea7591b41 100644 --- a/slack_sdk/socket_mode/client.py +++ b/slack_sdk/socket_mode/client.py @@ -97,13 +97,13 @@ def send_socket_mode_response(self, response: Union[Dict[str, Any], SocketModeRe def enqueue_message(self, message: str): self.message_queue.put(message) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new message enqueued (current queue size: {self.message_queue.qsize()})") def process_message(self): try: raw_message = self.message_queue.get(timeout=1) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A message dequeued (current queue size: {self.message_queue.qsize()})") if raw_message is not None: @@ -123,7 +123,7 @@ def _run_message_listeners(): def run_message_listeners(self, message: dict, raw_message: str) -> None: type, envelope_id = message.get("type"), message.get("envelope_id") - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Message processing started (type: {type}, envelope_id: {envelope_id})") try: # just in case, adding the same logic to reconnect here @@ -148,7 +148,7 @@ def run_message_listeners(self, message: dict, raw_message: str) -> None: except Exception as e: self.logger.exception(f"Failed to run message listeners: {e}") finally: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Message processing completed (type: {type}, envelope_id: {envelope_id})") def process_messages(self) -> None: diff --git a/slack_sdk/socket_mode/websocket_client/__init__.py b/slack_sdk/socket_mode/websocket_client/__init__.py index 16e037194..acc6a26a7 100644 --- a/slack_sdk/socket_mode/websocket_client/__init__.py +++ b/slack_sdk/socket_mode/websocket_client/__init__.py @@ -143,13 +143,13 @@ def is_connected(self) -> bool: def connect(self) -> None: def on_open(ws: WebSocketApp): - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug("on_open invoked") for listener in self.on_open_listeners: listener(ws) def on_message(ws: WebSocketApp, message: str): - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"on_message invoked: (message: {debug_redacted_message_string(message)})") self.enqueue_message(message) for listener in self.on_message_listeners: @@ -165,7 +165,7 @@ def on_close( close_status_code: Optional[int] = None, close_msg: Optional[str] = None, ): - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"on_close invoked: (code: {close_status_code}, message: {close_msg})") if self.auto_reconnect_enabled: self.logger.info("Received CLOSE event. Reconnecting...") @@ -201,14 +201,14 @@ def disconnect(self) -> None: self.current_session.close() def send_message(self, message: str) -> None: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Sending a message: {message}") try: self.current_session.send(message) # type: ignore[union-attr] except WebSocketException as e: # We rarely get this exception while replacing the underlying WebSocket connections. # We can do one more try here as the self.current_session should be ready now. - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Failed to send a message (error: {e}, message: {message})" " as the underlying connection was replaced. Retrying the same request only one time..." diff --git a/slack_sdk/socket_mode/websockets/__init__.py b/slack_sdk/socket_mode/websockets/__init__.py index 3b217e4eb..d1c8d30f4 100644 --- a/slack_sdk/socket_mode/websockets/__init__.py +++ b/slack_sdk/socket_mode/websockets/__init__.py @@ -123,12 +123,12 @@ async def monitor_current_session(self) -> None: # To avoid such, we access only the session that is active when this loop starts. session: ClientConnection = self.current_session # type: ignore[assignment] session_id: str = await self.session_id() - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new monitor_current_session() execution loop for {session_id} started") try: while not self.closed: if session != self.current_session: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The monitor_current_session task for {session_id} is now cancelled") break await asyncio.sleep(self.ping_interval) @@ -142,7 +142,7 @@ async def monitor_current_session(self) -> None: f"(error: {type(e).__name__}, message: {e}, session: {session_id})" ) except asyncio.CancelledError: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The monitor_current_session task for {session_id} is now cancelled") raise @@ -153,12 +153,12 @@ async def receive_messages(self) -> None: session: ClientConnection = self.current_session # type: ignore[assignment] session_id: str = await self.session_id() consecutive_error_count = 0 - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new receive_messages() execution loop with {session_id} started") try: while not self.closed: if session != self.current_session: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The running receive_messages task for {session_id} is now cancelled") break try: @@ -166,7 +166,7 @@ async def receive_messages(self) -> None: if message is not None: if isinstance(message, bytes): message = message.decode("utf-8") - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Received message: {debug_redacted_message_string(message)}, session: {session_id}" ) @@ -182,7 +182,7 @@ async def receive_messages(self) -> None: else: await asyncio.sleep(consecutive_error_count) except asyncio.CancelledError: - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"The running receive_messages task for {session_id} is now cancelled") raise @@ -209,14 +209,14 @@ async def connect(self): self.current_session_monitor.cancel() self.current_session_monitor = asyncio.ensure_future(self.monitor_current_session()) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new monitor_current_session() executor has been recreated for {session_id}") if self.message_receiver is not None: self.message_receiver.cancel() self.message_receiver = asyncio.ensure_future(self.receive_messages()) - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"A new receive_messages() executor has been recreated for {session_id}") if old_session is not None: @@ -231,14 +231,14 @@ async def disconnect(self): async def send_message(self, message: str): session = self.current_session session_id = self.build_session_id(session) # type: ignore[arg-type] - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug(f"Sending a message: {message}, session: {session_id}") try: await session.send(message) # type: ignore[union-attr] except WebSocketException as e: # We rarely get this exception while replacing the underlying WebSocket connections. # We can do one more try here as the self.current_session should be ready now. - if self.logger.level <= logging.DEBUG: + if self.logger.isEnabledFor(logging.DEBUG): self.logger.debug( f"Failed to send a message (error: {e}, message: {message}, session: {session_id})" " as the underlying connection was replaced. Retrying the same request only one time..." diff --git a/tests/slack_sdk/socket_mode/test_builtin.py b/tests/slack_sdk/socket_mode/test_builtin.py index a1780a7e0..6ba64c9a3 100644 --- a/tests/slack_sdk/socket_mode/test_builtin.py +++ b/tests/slack_sdk/socket_mode/test_builtin.py @@ -3,7 +3,7 @@ import ssl import time import unittest -from unittest.mock import sentinel +from unittest.mock import patch, sentinel from threading import Thread from slack_sdk import WebClient @@ -48,6 +48,23 @@ def test_init_close(self): finally: client.close() + def test_debug_message_follows_the_effective_log_level(self): + parent = logging.getLogger(f"{__name__}.debug_guard") + logger = logging.getLogger(f"{__name__}.debug_guard.client") + client = SocketModeClient(app_token="xapp-A111-222-xyz", logger=logger) + try: + with patch("slack_sdk.socket_mode.builtin.client.debug_redacted_message_string") as redact: + parent.setLevel(logging.INFO) + client._on_message("{}") + redact.assert_not_called() + + parent.setLevel(logging.DEBUG) + client._on_message("{}") + redact.assert_called_once_with("{}") + finally: + parent.setLevel(logging.NOTSET) + client.close() + def test_issue_new_wss_url(self): client = SocketModeClient( app_token="xapp-A111-222-xyz",