Make the aiohttp-based SocketModeClient's debug logging more consistent with the built-in one (#1122) by seratch · Pull Request #1134 · slackapi/python-slack-sdk

seratch · 2021-11-15T04:51:50Z

Summary

This pull request fixes #1122 by improving the internals of the AIOHTTP-based Socket Mode client to be more consistent with the built-in client. Will add some context in line comments.

cc @eddyg

Category (place an `x` in each of the `[ ]`)

Requirements (place an `x` in each `[ ]`)

I've read and understood the Contributing Guidelines and have done my best effort to follow them.
I've read and agree to the Code of Conduct.
I've run python3 -m venv .venv && source .venv/bin/activate && ./scripts/run_validation.sh after making the changes.

…nt with the built-in one

seratch · 2021-11-15T04:52:40Z

slack_sdk/socket_mode/aiohttp/__init__.py

                    break
                try:
                    message: WSMessage = await session.receive()
-                    if self.trace_enabled and self.logger.level <= logging.DEBUG:


The main purpose of this PR is to remove trace_enabled check here. In the built-in client, message data logging does not require trace_enabled. This change makes the behavior more consistent.

seratch · 2021-11-15T04:53:24Z

slack_sdk/socket_mode/aiohttp/__init__.py

-                            f" ({session_id})"
-                        )
-                        self.logger.debug(log_message)
+                    if self.trace_enabled and self.logger.level <= logging.DEBUG:


This debug logging is mainly for this SDK maintainers. We can disable this for most developers. That's why I added trace_enabled here.

seratch · 2021-11-15T04:54:51Z

slack_sdk/socket_mode/aiohttp/__init__.py

-                                f"extra: {message.extra}, "
-                                f"session: {session_id})"
+                    # just in case, checking if the value is not None
+                    if message is not None:


According to the type hint provided by aiohttp, we can assume the data cannot be None but we should check if it's not None, just in case (the behavior can be changed on the aiohttp library side in the future). In this PR, I've moved this check to cover the debug logging parts as well.

seratch · 2021-11-15T04:55:42Z

slack_sdk/socket_mode/aiohttp/__init__.py

            and not await self.is_ping_pong_failing()
        )
-        if connected is False and self.logger.level <= logging.DEBUG:
+        if self.logger.level <= logging.DEBUG and connected is False:


This one and the following changes are minor improvements for readability

codecov · 2021-11-15T04:58:24Z

Codecov Report

Merging #1134 (24f05a6) into main (cf22599) will decrease coverage by 0.03%.
The diff coverage is 69.56%.

@@            Coverage Diff             @@
##             main    #1134      +/-   ##
==========================================
- Coverage   86.62%   86.58%   -0.04%     
==========================================
  Files         110      110              
  Lines       10749    10750       +1     
==========================================
- Hits         9311     9308       -3     
- Misses       1438     1442       +4

Impacted Files	Coverage Δ
slack_sdk/socket_mode/aiohttp/__init__.py	`81.34% <69.56%> (-0.55%)`	⬇️
slack_sdk/socket_mode/builtin/internals.py	`70.66% <0.00%> (-1.34%)`	⬇️
slack_sdk/models/blocks/blocks.py	`96.26% <0.00%> (ø)`
slack_sdk/models/blocks/basic_components.py	`87.12% <0.00%> (ø)`
slack_sdk/models/blocks/block_elements.py	`92.51% <0.00%> (+0.20%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update cf22599...24f05a6. Read the comment docs.

filmaj

LGTM!

eddyg · 2021-11-15T17:50:10Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        # 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.
+                        counter_for_logging = (


I usually try to avoid the modulo operator (for performance reasons, unless the modulo operator can be a power of 2). In this case, it would be easy to avoid it, and possibly a bit clearer, by doing:

counter_for_logging += 1 if counter_for_logging >= logging_interval: ... counter_for_logging = 0

yeah, this sounds better

eddyg · 2021-11-15T17:55:05Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        ) % logging_interval
+                        if counter_for_logging == 0:
+                            log_message = (
+                                f"{logging_interval} session verification executed after the previous same log"


As a Bolt user, this message is still unclear to me. 😐

I think what it's trying to say might be something like this:

Checkpoint: 100 session verification messages received (session={session_id})

One thing I was wondering if there would be a value in not resetting the counter_for_logging variable, (which means my previous comment about avoiding modulo would need to ignored, since we'd need to check it to log this message every logging_interval times):

Checkpoint: Session verification message received (count={counter_for_logging} session={session_id})

This would have the benefit of providing log-insight in to how many messages have been processed since the Bolt application started since the counter would accumulate instead of being reset to 0 and always simply logging the logging_interval.

Session verification message received

This suggested log message may not be accurate. In this method, all we do is just to monitor the current session is active. No communication with the server-side is involved here (ping-pong comms are done by aiohttp internals but it's not in this method).

Also, the intention of logging here is to periodically print some logs to tell the connection is alive even when the connection has not been receiving any incoming requests from Slack for a while. For this reason, I would like to avoid accumulating the count, which wont' be used for any purposes.

To make the log message clearer, I may want to revise it like:

monitor_current_session method has verified the session is active (session: {session_id}, logging interval: {logging_interval})

Thanks for taking the time to write a detailed explanation, @seratch. Your proposed wording sounds good to me, and is an improvement (in my opinion) over the original message. (Having the {logging_interval} at the beginning didn't make sense to me until I checked the code to see what it was indicating.)

eddyg · 2021-11-15T18:09:07Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                            # this receive_messages execution is no longer working for some reason.
+                            if self.trace_enabled and counter_for_logging == 0:
+                                log_message = (
+                                    f"{logging_interval} WebSocket messages received "


Similarly here, if my understanding of this message is correct, I would probably phrase it like what I suggested above:

Checkpoint: WebSocket message received (count={counter_for_logging} session={session_id})

I would like to avoid accumulating the number to avoid overflow errors in ultimate situations (say, a very busy app running for years without restart), just in case. Perhaps, we can say like this instead:

The receive_messages method has been working without any issues (session: {session_id}, logging interval: {logging_interval})

OK. I'd suggest removing the leading "The" at beginning for consistency with the earlier, similar message.

seratch

@eddyg Thanks for your review comments!

seratch · 2021-11-15T22:43:51Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        # 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.
+                        counter_for_logging = (


yeah, this sounds better

seratch · 2021-11-15T22:52:25Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                        ) % logging_interval
+                        if counter_for_logging == 0:
+                            log_message = (
+                                f"{logging_interval} session verification executed after the previous same log"


Session verification message received

This suggested log message may not be accurate. In this method, all we do is just to monitor the current session is active. No communication with the server-side is involved here (ping-pong comms are done by aiohttp internals but it's not in this method).

Also, the intention of logging here is to periodically print some logs to tell the connection is alive even when the connection has not been receiving any incoming requests from Slack for a while. For this reason, I would like to avoid accumulating the count, which wont' be used for any purposes.

To make the log message clearer, I may want to revise it like:

monitor_current_session method has verified the session is active (session: {session_id}, logging interval: {logging_interval})

seratch · 2021-11-15T22:57:20Z

slack_sdk/socket_mode/aiohttp/__init__.py

+                            # this receive_messages execution is no longer working for some reason.
+                            if self.trace_enabled and counter_for_logging == 0:
+                                log_message = (
+                                    f"{logging_interval} WebSocket messages received "


I would like to avoid accumulating the number to avoid overflow errors in ultimate situations (say, a very busy app running for years without restart), just in case. Perhaps, we can say like this instead:

The receive_messages method has been working without any issues (session: {session_id}, logging interval: {logging_interval})

Make the aiohttp-based SocketModeClient's debug logging more consiste…

a3b6a28

…nt with the built-in one

seratch added this to the 3.12.0 milestone Nov 15, 2021

seratch requested review from filmaj, srajiang and stevengill November 15, 2021 04:51

seratch self-assigned this Nov 15, 2021

seratch commented Nov 15, 2021

View reviewed changes

filmaj approved these changes Nov 15, 2021

View reviewed changes

eddyg reviewed Nov 15, 2021

View reviewed changes

mwbrooks approved these changes Nov 15, 2021

View reviewed changes

seratch commented Nov 15, 2021

View reviewed changes

seratch added 2 commits November 19, 2021 17:51

Fix

db7cdc6

Fix

24f05a6

seratch merged commit dd7a9be into slackapi:main Nov 19, 2021

seratch deleted the aiohttp-socket-mode-debug-log branch November 19, 2021 09:20

Conversation

seratch commented Nov 15, 2021

Summary

Category (place an x in each of the [ ])

Requirements (place an x in each [ ])

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov bot commented Nov 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

filmaj left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seratch Nov 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seratch left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

seratch Nov 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Category (place an `x` in each of the `[ ]`)

Requirements (place an `x` in each `[ ]`)

codecov bot commented Nov 15, 2021 •

edited

Loading

seratch Nov 15, 2021 •

edited

Loading

seratch Nov 15, 2021 •

edited

Loading