Parsing incoming WebSocket message fails with a `SyntaxError` from invalid JSON #2057

zimeg · 2024-10-02T09:00:32Z

Packages

@slack/socket-mode

Reproducible in

A setup similar to this:

$ npm ls | grep -o "\S\+@\S\+$" | tr @ ' ' | awk -v q='"' '{print q$1q": "q"^"$2q","}' | grep slack
"slack/cli-hooks": "^1.1.1",
"slack/web-api": "^7.5.0",
$ node --version
v22.4.1
$ sw_vers && uname -v
ProductName:            macOS
ProductVersion:         14.7
BuildVersion:           23H124
Darwin Kernel Version 23.6.0: Wed Jul 31 20:49:39 PDT 2024; root:xnu-10063.141.1.700.5~1/RELEASE_ARM64_T6000

Steps to reproduce

Setup an app with the changes in bolt v4 bolt-js#2254
Include a message event subscription and lister
Start the app then send a message to a channel with the bot

Expected result

The event to be processed from a message handler and delivered to a message event lister 👀

Actual result

Incoming events are ignored but it's also interesting that the connection is setup alright 🤔

> node dist/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]   Listening for HTTP requests on port 3000
[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.4.1 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.4.1 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":"tails_local3","team_id":"T02A074M3U3","user_id":"U07PHRLU095","bot_id":"B07QB2X9H09","is_enterprise_install":false,"response_metadata":{"scopes":["app_mentions:read","channels:history","channels:manage","channels:read","channels:write.invites","chat:write","chat:write.customize","chat:write.public","commands","files:read","files:write","groups:history","groups:read","groups:write","links:read","im:history","im:read","im:write","mpim:history","mpim:read","mpim:write","reactions:read","reactions:write","users:read"]}}
[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=111e2230-5f4e-49a8-b632-cae318f54517&app_id=7f63efba0a3362d59e4ae57905421308add76c90410999bcbcafb17f6393a4c8","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: {"type":"hello","num_connections":1,"debug_info":{"host":"applink-8","build_number":98,"approximate_connection_time":18060},"connection_info":{"app_id":"A07PYC8PYFL"}}
⚡️ Bolt app is running!
[DEBUG]  socket-mode:SocketModeClient:0 Received a message on the WebSocket: {"envelope_id":"29a549a0-acc0-4c4e-bdd0-14051db7afb3","payload":{"token":"0YZdOnBDzcuPwlCS2qvg5Ffs","team_id":"T02A074M3U3","context_team_id":"T02A074M3U3","context_enterprise_id":null,"api_app_id":"A07PYC8PYFL","event":{"user":"U04051AF9NJ","type":"message","ts":"1727857083.777269","client_msg_id":"248ce6f6-4d32-47e1-946f-bf485bb4ef74","text":"greetings thor","team":"T02A074M3U3","blocks":[{"type":"rich_text","block_id":"LT4s0","elements":[{"type":"rich_text_section","elements":[{"type":"text","text":"greetings thor"}]}]}],"channel":"C07QP2GMURE","event_ts":"1727857083.777269","channel_type":"channel"},"type":"event_callback","event_id":"Ev07Q0BHJ9V0","event_time":1727857083,"authorizations":[{"enterprise_id":null,"team_id":"T02A074M3U3","user_id":"U07PHRLU095","is_bot":true,"is_enterprise_install":false}],"is_ext_shared_channel":false,"event_context":"4-eyJldCI6Im1lc3NhZ2UiLCJ0aWQiOiJUMDJBMDc0TTNVMyIsImFpZCI6IkEwN1BZQzhQWUZMIiwiY2lkIjoiQzA3UVAyR01VUkUifQ"},"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: "[object Object]" is not valid JSON, [object Object]
[DEBUG]  socket-mode:SocketModeClient:0 Calling ack() - type: events_api, envelope_id: 29a549a0-acc0-4c4e-bdd0-14051db7afb3, 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":"29a549a0-acc0-4c4e-bdd0-14051db7afb3","payload":{}}
[DEBUG]  web-api:WebClient:1 initialized

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:

node-slack-sdk/packages/socket-mode/src/SocketModeClient.ts

Lines 284 to 291 in 943e153

    
           protected async onWebSocketMessage(data: WebSocket.RawData, isBinary: boolean): Promise<void> { 
        
             if (isBinary) { 
        
               this.logger.debug('Unexpected binary message received, ignoring.'); 
        
               return; 
        
             } 
        
             const payload = data.toString(); 
        
             // TODO: should we redact things in here? 
        
             this.logger.debug(`Received a message on the WebSocket: ${payload}`);

- this.logger.debug('Received a message on the WebSocket:', payload);
+ this.logger.debug('Received a message on the WebSocket:', data);

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: <Buffer 7b 22 74 79 70 65 22 3a 22 68 65 6c 6c 6f 22 2c 22 6e 75 6d 5f 63 6f 6e 6e 65 63 74 69 6f 6e 73 22 3a 31 2c 22 64 65 62 75 67 5f 69 6e 66 6f 22 3a 7b ... 117 more bytes>
⚡️ Bolt app is running!
[DEBUG]  socket-mode:SocketModeClient:0 Received a message on the WebSocket: <Buffer 7b 22 65 6e 76 65 6c 6f 70 65 5f 69 64 22 3a 22 38 33 63 65 33 30 38 61 2d 39 64 38 33 2d 34 39 38 35 2d 61 65 37 31 2d 34 66 66 35 34 33 39 64 32 31 ... 992 more bytes>
[DEBUG]  socket-mode:SocketModeClient:0 Received a message on the WebSocket: {
  ack: [Function: ack],
  envelope_id: '83ce308a-9d83-4985-ae71-4ff5439d210d',
  body: {
    token: '2QwoaNlbBzzfb6f2obLypul4',
    team_id: 'T02A074M3U3',
    context_team_id: 'T02A074M3U3',
    context_enterprise_id: null,
    api_app_id: 'A07Q0EQ444S',
    event: {
      user: 'U04051AF9NJ',
      type: 'message',
      ts: '1727859227.477379',
      client_msg_id: '2d3a3d88-d821-453d-ba8a-7813271aaee0',
      text: 'asdf',
      team: 'T02A074M3U3',
      blocks: [Array],
      channel: 'C07QP2GMURE',
      event_ts: '1727859227.477379',
      channel_type: 'channel'
    },
    type: 'event_callback',
    event_id: 'Ev07PXLMUDDK',
    event_time: 1727859227,
    authorizations: [ [Object] ],
    is_ext_shared_channel: false,
    event_context: '4-eyJldCI6Im1lc3NhZ2UiLCJ0aWQiOiJUMDJBMDc0TTNVMyIsImFpZCI6IkEwN1EwRVE0NDRTIiwiY2lkIjoiQzA3UVAyR01VUkUifQ'
  },
  event: {
    user: 'U04051AF9NJ',
    type: 'message',
    ts: '1727859227.477379',
    client_msg_id: '2d3a3d88-d821-453d-ba8a-7813271aaee0',
    text: 'asdf',
    team: 'T02A074M3U3',
    blocks: [ [Object] ],
    channel: 'C07QP2GMURE',
    event_ts: '1727859227.477379',
    channel_type: 'channel'
  },
  retry_num: 0,
  retry_reason: '',
  accepts_response_payload: false
}
[DEBUG]  socket-mode:SocketModeClient:0 Unable to parse an incoming WebSocket message (will ignore): SyntaxError: "[object Object]" is not valid JSON, [object Object]
[DEBUG]  socket-mode:SocketModeClient:0 Calling ack() - type: events_api, envelope_id: 83ce308a-9d83-4985-ae71-4ff5439d210d, 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":"83ce308a-9d83-4985-ae71-4ff5439d210d","payload":{}}
[DEBUG]  web-api:WebClient:1 initialized
[DEBUG]  socket-mode:SocketModeClient:0 Received a message on the WebSocket: <Buffer 7b 22 65 6e 76 65 6c 6f 70 65 5f 69 64 22 3a 22 62 61 34 31 38 30 63 34 2d 62 65 39 63 2d 34 31 38 37 2d 38 63 38 64 2d 61 32 30 38 64 36 32 63 64 39 ... 1012 more bytes>
[DEBUG]  socket-mode:SocketModeClient:0 Received a message on the WebSocket: {
  ack: [Function: ack],
  envelope_id: 'ba4180c4-be9c-4187-8c8d-a208d62cd95a',
  body: {
    token: '2QwoaNlbBzzfb6f2obLypul4',
    team_id: 'T02A074M3U3',
    context_team_id: 'T02A074M3U3',
    context_enterprise_id: null,
    api_app_id: 'A07Q0EQ444S',
    event: {
      user: 'U04051AF9NJ',
      type: 'message',
      ts: '1727859232.740919',
      client_msg_id: '3f2024af-d271-44ef-afbf-1d58a6adc12a',
      text: 'greetings loki',
      team: 'T02A074M3U3',
      blocks: [Array],
      channel: 'C07QP2GMURE',
      event_ts: '1727859232.740919',
      channel_type: 'channel'
    },
    type: 'event_callback',
    event_id: 'Ev07PL0J7FB9',
    event_time: 1727859232,
    authorizations: [ [Object] ],
    is_ext_shared_channel: false,
    event_context: '4-eyJldCI6Im1lc3NhZ2UiLCJ0aWQiOiJUMDJBMDc0TTNVMyIsImFpZCI6IkEwN1EwRVE0NDRTIiwiY2lkIjoiQzA3UVAyR01VUkUifQ'
  },
  event: {
    user: 'U04051AF9NJ',
    type: 'message',
    ts: '1727859232.740919',
    client_msg_id: '3f2024af-d271-44ef-afbf-1d58a6adc12a',
    text: 'greetings loki',
    team: 'T02A074M3U3',
    blocks: [ [Object] ],
    channel: 'C07QP2GMURE',
    event_ts: '1727859232.740919',
    channel_type: 'channel'
  },
  retry_num: 0,
  retry_reason: '',
  accepts_response_payload: false
}
[DEBUG]  socket-mode:SocketModeClient:0 Unable to parse an incoming WebSocket message (will ignore): SyntaxError: "[object Object]" is not valid JSON, [object Object]
[DEBUG]  socket-mode:SocketModeClient:0 Calling ack() - type: events_api, envelope_id: ba4180c4-be9c-4187-8c8d-a208d62cd95a, 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":"ba4180c4-be9c-4187-8c8d-a208d62cd95a","payload":{}}

And I'm thinking the ack function 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 ack function causing this, but it does seem tricky if we are needing to parse this 👀

node-slack-sdk/packages/socket-mode/src/SocketModeClient.ts

Lines 305 to 317 in 943e153

    
           try { 
        
             event = JSON.parse(payload); 
        
           } catch (parseError) { 
        
             // Prevent application from crashing on a bad message, but log an error to bring attention 
        
             this.logger.debug(`Unable to parse an incoming WebSocket message (will ignore): ${parseError}, ${payload}`); 
        
             return; 
        
           } 
        
           // Slack has finalized the handshake with a hello message; we are good to go. 
        
           if (event.type === 'hello') { 
        
             this.emit(State.Connected); 
        
             return; 
        
           }

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. 🙇

Please read the Contributing guidelines and Code of Conduct before creating this issue or pull request. By submitting, you are agreeing to those rules.

The text was updated successfully, but these errors were encountered:

filmaj · 2024-10-02T12:53:09Z

Thank you for catching this! I can confirm this behaviour as well 🤔 looking into it 🙇

filmaj · 2024-10-02T13:01:13Z

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 · 2024-10-02T16:05:24Z

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:

node-slack-sdk/packages/socket-mode/src/SlackWebSocket.ts

Lines 126 to 128 in 943e153

    
           ws.on('message', (msg, isBinary) => { 
        
             this.options.client.emit('message', msg, isBinary); 
        
           });

filmaj · 2024-10-02T16:29:42Z

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:

node-slack-sdk/packages/socket-mode/src/SocketModeClient.ts

Lines 338 to 340 in 943e153

    
           // For events_api messages, expose the type of the event 
        
           if (event.type === 'events_api') { 
        
             this.emit(event.payload.event.type, {

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.

zimeg added bug M-T: A confirmed bug report. Issues are confirmed when the reproduction steps are documented pkg:socket-mode applies to `@slack/socket-mode` labels Oct 2, 2024

zimeg mentioned this issue Oct 2, 2024

bolt v4 slackapi/bolt-js#2254

Merged

6 tasks

seratch added this to the socket-mode@2.0.2 milestone Oct 2, 2024

filmaj self-assigned this Oct 2, 2024

filmaj added a commit that referenced this issue Oct 2, 2024

socket-mode(fix): do not handle message events twice. fixes #2057

63d93e0

filmaj mentioned this issue Oct 2, 2024

socket-mode(fix): do not handle message events twice #2059

Merged

filmaj closed this as completed in #2059 Oct 2, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Parsing incoming WebSocket message fails with a `SyntaxError` from invalid JSON #2057

Parsing incoming WebSocket message fails with a `SyntaxError` from invalid JSON #2057

zimeg commented Oct 2, 2024

filmaj commented Oct 2, 2024

filmaj commented Oct 2, 2024

filmaj commented Oct 2, 2024 •

edited

Loading

filmaj commented Oct 2, 2024 •

edited

Loading

Parsing incoming WebSocket message fails with a SyntaxError from invalid JSON #2057

Parsing incoming WebSocket message fails with a SyntaxError from invalid JSON #2057

Comments

zimeg commented Oct 2, 2024

Packages

Reproducible in

Steps to reproduce

Expected result

Actual result

Initial thoughts

Requirements

filmaj commented Oct 2, 2024

filmaj commented Oct 2, 2024

filmaj commented Oct 2, 2024 • edited Loading

filmaj commented Oct 2, 2024 • edited Loading

Parsing incoming WebSocket message fails with a `SyntaxError` from invalid JSON #2057

Parsing incoming WebSocket message fails with a `SyntaxError` from invalid JSON #2057

filmaj commented Oct 2, 2024 •

edited

Loading

filmaj commented Oct 2, 2024 •

edited

Loading