filmaj
commented
1 month ago Thank you for catching this! I can confirm this behaviour as well 🤔 looking into it 🙇
Closed zimeg closed 1 month ago
filmaj
commented
1 month ago Thank you for catching this! I can confirm this behaviour as well 🤔 looking into it 🙇
filmaj
commented
1 month ago I set up a test app that has a simple message listener that only logs out some of the payload bits - no extra responding or use of bolt's say or anything like that. The logs look like this upon startup:
[DEBUG] socket-mode:SocketModeClient:0 Received a message on the WebSocket: {"type":"hello","num_connections":1,"debug_info":{"host":"applink-4","build_number":98,"approximate_connection_time":18060},"connection_info":{"app_id":"A0601REQL93"}}
⚡️ Bolt app started
[DEBUG] socket-mode:SocketModeClient:0 Received a message on the WebSocket: {"envelope_id":"58fc957a-28bf-4d8b-90aa-85cb13568917","payload":{"token":"1P40lDckJcCwYTZ4TcT2swIc","team_id":"T029V6468RL","context_team_id":"T029V6468RL","context_enterprise_id":null,"api_app_id":"A0601REQL93","event":{"user":"U02AEHE4KG9","type":"message","ts":"1727873848.229749","client_msg_id":"8ce15601-05c7-48e2-a631-5928210c0749","text":"broadcast","team":"T029V6468RL","blocks":[{"type":"rich_text","block_id":"O7\/Op","elements":[{"type":"rich_text_section","elements":[{"type":"text","text":"broadcast"}]}]}],"channel":"C029YT5KEMB","event_ts":"1727873848.229749","channel_type":"channel"},"type":"event_callback","event_id":"Ev07Q1FQRE0K","event_time":1727873848,"authorizations":[{"enterprise_id":null,"team_id":"T029V6468RL","user_id":"U0604PD417C","is_bot":true,"is_enterprise_install":false}],"is_ext_shared_channel":false,"event_context":"4-eyJldCI6Im1lc3NhZ2UiLCJ0aWQiOiJUMDI5VjY0NjhSTCIsImFpZCI6IkEwNjAxUkVRTDkzIiwiY2lkIjoiQzAyOVlUNUtFTUIifQ"},"type":"events_api","accepts_response_payload":false,"retry_attempt":0,"retry_reason":""}
[DEBUG] socket-mode:SocketModeClient:0 Received a message on the WebSocket: [object Object]
[DEBUG] socket-mode:SocketModeClient:0 Unable to parse an incoming WebSocket message (will ignore): SyntaxError: Unexpected token o in JSON at position 1, [object Object]
[DEBUG] bolt-app {"token":"1P40lDckJcCwYTZ4TcT2swIc","team_id":"T029V6468RL","context_team_id":"T029V6468RL","context_enterprise_id":null,"api_app_id":"A0601REQL93","event":{"user":"U02AEHE4KG9","type":"message","ts":"1727873848.229749","client_msg_id":"8ce15601-05c7-48e2-a631-5928210c0749","text":"broadcast","team":"T029V6468RL","blocks":[{"type":"rich_text","block_id":"O7/Op","elements":[{"type":"rich_text_section","elements":[{"type":"text","text":"broadcast"}]}]}],"channel":"C029YT5KEMB","event_ts":"1727873848.229749","channel_type":"channel"},"type":"event_callback","event_id":"Ev07Q1FQRE0K","event_time":1727873848,"authorizations":[{"enterprise_id":null,"team_id":"T029V6468RL","user_id":"U0604PD417C","is_bot":true,"is_enterprise_install":false}],"is_ext_shared_channel":false,"event_context":"4-eyJldCI6Im1lc3NhZ2UiLCJ0aWQiOiJUMDI5VjY0NjhSTCIsImFpZCI6IkEwNjAxUkVRTDkzIiwiY2lkIjoiQzAyOVlUNUtFTUIifQ"}
[DEBUG] socket-mode:SocketModeClient:0 Calling ack() - type: events_api, envelope_id: 58fc957a-28bf-4d8b-90aa-85cb13568917, data: undefined
[DEBUG] socket-mode:SocketModeClient:0 send() method was called (WebSocket state: OPEN)
[DEBUG] socket-mode:SlackWebSocket:1 isActive(): websocket ready state is OPEN
[DEBUG] socket-mode:SocketModeClient:0 Sending a WebSocket message: {"envelope_id":"58fc957a-28bf-4d8b-90aa-85cb13568917","payload":{}}The automatic bolt ack here looks fine. The functionality works fine, too! Rather, the rogue error log / problem seems to be when the message event comes in, the socket mode client logs out two messages for each incoming payload. Very weird!
filmaj
commented
1 month ago I was able to reproduce this issue in just the socket-mode client. I think it has to do with the fact the event listener for message is overloaded: there is both a websocket-specific event called message as well as the Slack event message.
The web socket will raise a message event to the main SocketModeClient:
filmaj
commented
1 month ago I think I see the issue.
First, a weird thing I noticed: why do Slack message events seem to raise two incoming WebSocket messages? See the following logs as an example:
[DEBUG] socket-mode:SocketModeClient:0 Received a message on the WebSocket: {"envelope_id":"8a4dcdd4-c008-4fba-80f7-d99a9b79f80c","payload":{"token":"1P40lDckJcCwYTZ4TcT2swIc","team_id":"T029V6468RL","context_team_id":"T029V6468RL","context_enterprise_id":null,"api_app_id":"A0601REQL93","event":{"user":"U02AEHE4KG9","type":"message","ts":"1727886043.611539","client_msg_id":"056cd3ca-a89c-4185-a1e0-4a663c50b392","text":"h","team":"T029V6468RL","blocks":[{"type":"rich_text","block_id":"8m0Ei","elements":[{"type":"rich_text_section","elements":[{"type":"text","text":"h"}]}]}],"channel":"C029YT5KEMB","event_ts":"1727886043.611539","channel_type":"channel"},"type":"event_callback","event_id":"Ev07PNCPG05D","event_time":1727886043,"authorizations":[{"enterprise_id":null,"team_id":"T029V6468RL","user_id":"U0604PD417C","is_bot":true,"is_enterprise_install":false}],"is_ext_shared_channel":false,"event_context":"4-eyJldCI6Im1lc3NhZ2UiLCJ0aWQiOiJUMDI5VjY0NjhSTCIsImFpZCI6IkEwNjAxUkVRTDkzIiwiY2lkIjoiQzAyOVlUNUtFTUIifQ"},"type":"events_api","accepts_response_payload":false,"retry_attempt":0,"retry_reason":""}
[DEBUG] socket-mode:SocketModeClient:0 Received a message on the WebSocket: [object Object]
[DEBUG] socket-mode:SocketModeClient:0 Unable to parse an incoming WebSocket message (will ignore): SyntaxError: Unexpected token o in JSON at position 1, [object Object]Surely the backend doesn't send two events over the wire to an app?
Sure enough, it has to do with the fact that the message handler within socket-mode is currently overloaded. It is due to this code:
Essentially, if a Slack message event comes in, we re-emit the event with the event payload's type as the event name. Using the example logs above, that would mean the following gets re-raised to the SocketModeClient:
"event":{"type":"message"}So, effectively the current code consumes Slack message events twice: once when the web socket message event gets handled by the main client, and then once again when we try to re-emit the specific Slack message event payload.
Packages
@slack/socket-modeReproducible in
A setup similar to this:
Steps to reproduce
messageevent subscription and listerExpected result
The event to be processed from a message handler and delivered to a
messageevent lister 👀Actual result
Incoming events are ignored but it's also interesting that the connection is setup alright 🤔
Initial thoughts
The sent payloads seem valid but the strangeness might be happening in how these are converted from byte to string 👾
The code logging the most interesting parts above is below, and when making the change that follows I get an interesting output:
https://github.com/slackapi/node-slack-sdk/blob/943e153afa7eea063d94935f1a069097d26f9b3e/packages/socket-mode/src/SocketModeClient.ts#L284-L291
Here is the interesting output
``` > node app.js [DEBUG] web-api:WebClient:0 initialized [DEBUG] bolt-app Initializing SocketModeReceiver [DEBUG] web-api:WebClient:0 initialized [DEBUG] socket-mode:SocketModeClient:0 The Socket Mode client has successfully initialized [DEBUG] web-api:WebClient:0 apiCall('auth.test') start [DEBUG] web-api:WebClient:0 http request url: https://slack.com/api/auth.test [DEBUG] web-api:WebClient:0 http request body: {"token":"[[REDACTED]]"} [DEBUG] web-api:WebClient:0 http request headers: {"Accept":"application/json, text/plain, */*","User-Agent":"@slack:bolt/3.22.0 @slack:web-api/7.5.0 node/22.8.0 darwin/23.6.0","Authorization":"[[REDACTED]]"} [DEBUG] socket-mode:SocketModeClient:0 Starting Socket Mode session ... [DEBUG] socket-mode:SocketModeClient:0 Going to retrieve a new WSS URL ... [DEBUG] web-api:WebClient:0 apiCall('apps.connections.open') start [DEBUG] web-api:WebClient:0 http request url: https://slack.com/api/apps.connections.open [DEBUG] web-api:WebClient:0 http request body: {} [DEBUG] web-api:WebClient:0 http request headers: {"Accept":"application/json, text/plain, */*","User-Agent":"@slack:socket-mode/2.0.1 @slack:web-api/7.3.4 node/22.8.0 darwin/23.6.0","Authorization":"[[REDACTED]]"} [DEBUG] web-api:WebClient:0 http response received [DEBUG] web-api:WebClient:0 http request result: {"ok":true,"url":"https://slackbox-ez.slack.com/","team":"slackbox-ez","user":"asdfsdaf","team_id":"T02A074M3U3","user_id":"U07Q305QSQL","bot_id":"B07PXJX2MU5","is_enterprise_install":false,"response_metadata":{"scopes":["app_mentions:read","channels:history"]}} [DEBUG] web-api:WebClient:0 apiCall('auth.test') end [DEBUG] web-api:WebClient:0 http response received [DEBUG] web-api:WebClient:0 http request result: {"ok":true,"url":"wss://wss-primary.slack.com/link/?ticket=79d70413-20d4-4eff-8e4e-68a1391f5838&app_id=5e832c26ada2149bd37da85b44def923ec81f1c8336f61220d53237d0cf8f096","response_metadata":{"scopes":["connections:write"],"acceptedScopes":["connections:write"]}} [DEBUG] web-api:WebClient:0 apiCall('apps.connections.open') end [DEBUG] socket-mode:SlackWebSocket:1 Initiating new WebSocket connection. [DEBUG] socket-mode:SlackWebSocket:1 WebSocket open event received (connection established)! [DEBUG] socket-mode:SlackWebSocket:1 Started monitoring pings to and pongs from Slack. [DEBUG] socket-mode:SocketModeClient:0 Received a message on the WebSocket:And I'm thinking the
ackfunction might be doing something strange here 🤔 It's super interesting too that the message seems to be received as bytes then printed as a string? Confusing times.This section follows soon after too which makes some amount of parsing seem needed, which makes sense! I'm also not certain that it is the
ackfunction causing this, but it does seem tricky if we are needing to parse this 👀https://github.com/slackapi/node-slack-sdk/blob/943e153afa7eea063d94935f1a069097d26f9b3e/packages/socket-mode/src/SocketModeClient.ts#L305-L317
Requirements
For general questions/issues about Slack API platform or its server-side, could you submit questions at https://my.slack.com/help/requests/new instead. :bow:
Please read the Contributing guidelines and Code of Conduct before creating this issue or pull request. By submitting, you are agreeing to those rules.