Skip to content

fix(socket_mode): check the effective log level in debug guards #1965

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
Shubham-Padkonde wants to merge 1 commit into
base: main
Choose a base branch
from
Open

fix(socket_mode): check the effective log level in debug guards #1965

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 15 additions & 15 deletions slack_sdk/socket_mode/aiohttp/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -143,19 +143,19 @@ 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
counter_for_logging = 0

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.
Expand Down Expand Up @@ -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

Expand All @@ -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
Expand All @@ -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)
Expand Down Expand Up @@ -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

Expand All @@ -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()
Expand Down Expand Up @@ -387,26 +387,26 @@ 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"))

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...")
Expand All @@ -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..."
Expand Down
6 changes: 3 additions & 3 deletions slack_sdk/socket_mode/async_client.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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})")
Expand Down Expand Up @@ -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})"
)
Expand All @@ -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})"
)
8 changes: 4 additions & 4 deletions slack_sdk/socket_mode/builtin/client.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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..."
Expand Down Expand Up @@ -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:
Expand All @@ -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()})")
Expand Down
8 changes: 4 additions & 4 deletions slack_sdk/socket_mode/client.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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
Expand All @@ -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:
Expand Down
10 changes: 5 additions & 5 deletions slack_sdk/socket_mode/websocket_client/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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...")
Expand Down Expand Up @@ -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..."
Expand Down
22 changes: 11 additions & 11 deletions slack_sdk/socket_mode/websockets/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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

Expand All @@ -153,20 +153,20 @@ 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:
message = await session.recv()
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}"
)
Expand All @@ -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

Expand All @@ -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:
Expand All @@ -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..."
Expand Down
Loading