StateMachine: unhandled event 'websocket close' in state 'connecting' #531

malonecm · 2018-04-12T18:55:53Z

Description

Have an always running bot. Had a random crash on 4.1.0 today. Trace follows, which hopefully will help. Not really reproducible. Hopefully just a state transition missing in your state machine.

/opt/local/slack-bot/node_modules/finity/lib/core/StateMachine.js:76

throw new Error('Unhandled event \'' + event + '\' in state \'' + this.currentState + '\'.');
^
Error: Unhandled event 'websocket close' in state 'connecting'.
    at StateMachine.handleUnhandledEvent (/opt/local/slack-bot/node_modules/finity/lib/core/StateMachine.js:76:13)
    at /opt/local/slack-bot/node_modules/finity/lib/core/HierarchicalStateMachine.js:79:33
    at TaskScheduler.execute (/opt/local/slack-bot/node_modules/finity/lib/core/TaskScheduler.js:29:7)
    at TaskScheduler.enqueue (/opt/local/slack-bot/node_modules/finity/lib/core/TaskScheduler.js:19:12)
    at HierarchicalStateMachine.handle (/opt/local/slack-bot/node_modules/finity/lib/core/HierarchicalStateMachine.js:72:24)
    at WebSocket.websocket.addEventListener.event (/opt/local/slack-bot/node_modules/@slack/client/dist/RTMClient.js:375:77)
    at WebSocket.onClose (/opt/local/slack-bot/node_modules/ws/lib/event-target.js:124:16)
    at emitTwo (events.js:126:13)
    at WebSocket.emit (events.js:214:7)
    at _receiver.cleanup (/opt/local/slack-bot/node_modules/ws/lib/websocket.js:220:12)
    at Receiver.cleanup (/opt/local/slack-bot/node_modules/ws/lib/receiver.js:557:13)
    at WebSocket.finalize (/opt/local/slack-bot/node_modules/ws/lib/websocket.js:206:20)
    at emitNone (events.js:111:20)
    at TLSSocket.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1064:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)
    at process._tickCallback (internal/process/next_tick.js:180:9)

What type of issue is this?

Requirements

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 searched for any related issues and avoided creating a duplicate issue.

Bug Report

Filling out the following details about bugs will help us solve your issue sooner.

Reproducible in:

@slack/client version: 4.1.0

node version: v8.10.0

OS version(s): Amazon Linux (4.9.76-38.79.amzn2.x86_64)

Steps to reproduce:

Single occurrence while running an always-on bot, possibly related to network changes

Expected result:

From the error, it sounds like the websocket should just attempt to restart itself if it gets a close while it is connecting.

Actual result:

Node crashed and systemd restarted it, resulting in very small downtime

Attachments:

None

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

aoberoi · 2018-04-13T00:51:46Z

thanks for reporting @malonecm

this sounds like its potentially related to #527, since they both have to do with the websocket being in a closing state unexpectedly. we're a little low on data around how this would happen, but that stack trace is definitely useful, thanks for that.

are you able to increase the logLevel in the RTMClient instance and share those logs in case you see this happen again? i think it would be nice to compare to #527 and also help me trace the steps in order to reproduce.

malonecm · 2018-04-14T03:31:17Z

I've enabled debug logLevel now. If I get another StateMachine issue with websocket close I will post more logs. Thank you!

malonecm · 2018-04-17T02:19:44Z

bot.log

Different crash this time. Debug log doesn't seem to help much to me. The "goodbye" thing I had never noticed before.

[DEBUG] @slack/client:RTMClient transitioning to state: reconnecting
[DEBUG] @slack/client:RTMClient transitioning to state: connecting
[DEBUG] @slack/client:RTMClient transitioning to state: connecting:authenticating
[DEBUG] @slack/client:RTMClient transitioning to state: connecting:authenticated
[DEBUG] @slack/client:RTMClient transitioning to state: connecting:handshaking
[DEBUG] @slack/client:RTMClient received message on websocket: {"type": "hello"}
[DEBUG] @slack/client:RTMClient transitioning to state: connected
[DEBUG] @slack/client:RTMClient transitioning to state: connected:resuming
/opt/local/slack-bot/node_modules/@slack/client/dist/KeepAlive.js:90
throw errors_1.errorWithCode(new Error('no client found'), _1.ErrorCode.KeepAliveInconsistentState);
^
Error: no client found
   at KeepAlive.attemptAcknowledgePong (/opt/local/slack-bot/node_modules/@slack/client/dist/KeepAlive.js:90:54)
   at RTMClient.emit (/opt/local/slack-bot/node_modules/eventemitter3/index.js:182:35)
   at RTMClient.onWebsocketMessage (/opt/local/slack-bot/node_modules/@slack/client/dist/RTMClient.js:430:14)
   at WebSocket.onMessage (/opt/local/slack-bot/node_modules/ws/lib/event-target.js:120:16)
   at emitOne (events.js:116:13)
   at WebSocket.emit (events.js:211:7)
   at Receiver._receiver.onmessage (/opt/local/slack-bot/node_modules/ws/lib/websocket.js:137:47)
   at Receiver.dataMessage (/opt/local/slack-bot/node_modules/ws/lib/receiver.js:409:14)
   at Receiver.getData (/opt/local/slack-bot/node_modules/ws/lib/receiver.js:347:12)
   at Receiver.startLoop (/opt/local/slack-bot/node_modules/ws/lib/receiver.js:143:16)
   at Receiver.add (/opt/local/slack-bot/node_modules/ws/lib/receiver.js:117:10)
   at emitOne (events.js:116:13)
   at TLSSocket.emit (events.js:211:7)
   at addChunk (_stream_readable.js:263:12)
   at readableAddChunk (_stream_readable.js:250:11)
   at TLSSocket.Readable.push (_stream_readable.js:208:10)
   at TLSWrap.onread (net.js:607:20)

malonecm · 2018-04-17T02:21:20Z

And still leaving debug on looking for the first one. If adding this onto this is inappropriate I can open a different issue. Just let me know. Thank you!

aoberoi · 2018-04-18T23:03:33Z

@malonecm looks like you found another issue to me. the new one seems a little more insidious, too.

for this second one, it would be useful to see the log statements from the KeepAlive class. did you filter those out or turn them off specifically? if you're able to get in there and tweak things, mind turning them on too for the next occurrence?

aoberoi · 2018-04-18T23:07:24Z

it looks like the OP in #527 also had a similar issue with KeepAlive as demonstrated in the last log and stacktrace. i'd like to combine these two issues since they seem related.

aoberoi · 2018-04-27T16:16:07Z

we think v4.2.0 fixes this issue. please update and give it a try! if not' feel free to comment and we'll reopen.

aoberoi · 2018-05-01T15:35:44Z

@malonecm have you tried v4.2.0? Any better than the previous version? At the very least, we should have more meaningful logs now.

malonecm · 2018-05-01T15:56:46Z

Yeah, I did upgrade. I have no seen any further crashes. I do still have debug logging on. If I see anything I will let you guys know!

See websockets/ws#1354 And slackapi/node-slack-sdk#531

geoguide · 2022-12-05T16:08:21Z

Not sure if this is the same reason but same crash on @slack in socket mode.

/Users/me/Development/slackbot-mine/node_modules/finity/lib/core/StateMachine.js:76
      throw new Error('Unhandled event \'' + event + '\' in state \'' + this.currentState + '\'.');
            ^
Error: Unhandled event 'websocket open' in state 'connected'.
    at StateMachine.handleUnhandledEvent (/Users/me/Development/slackbot-mine/node_modules/finity/lib/core/StateMachine.js:76:13)
    at /Users/me/Development/slackbot-mine/node_modules/finity/lib/core/HierarchicalStateMachine.js:79:33
    at TaskScheduler.execute (/Users/me/Development/slackbot-mine/node_modules/finity/lib/core/TaskScheduler.js:29:7)
    at TaskScheduler.enqueue (/Users/me/Development/slackbot-mine/node_modules/finity/lib/core/TaskScheduler.js:19:12)
    at HierarchicalStateMachine.handle (/Users/me/Development/slackbot-mine/node_modules/finity/lib/core/HierarchicalStateMachine.js:72:24)
    at WebSocket.<anonymous> (/Users/me/Development/slackbot-mine/node_modules/@slack/socket-mode/src/SocketModeClient.ts:523:25)
    at WebSocket.onOpen (/Users/me/Development/slackbot-mine/node_modules/ws/lib/event-target.js:144:16)
    at WebSocket.emit (node:events:513:28)
    at WebSocket.emit (node:domain:489:12)
    at WebSocket.setSocket (/Users/me/Development/slackbot-mine/node_modules/ws/lib/websocket.js:225:10)

This happened right before that

[WARN]  bolt-app http request failed getaddrinfo ENOTFOUND slack.com
[WARN]  bolt-app http request failed getaddrinfo ENOTFOUND slack.com
[INFO]  socket-mode:SocketModeClient:0 Reconnecting to Slack ...
[INFO]  socket-mode:SocketModeClient:0 Going to establish a new connection to Slack ...
[INFO]  socket-mode:SocketModeClient:0 Now connected to Slack

nazmariam · 2023-06-15T09:17:32Z

Hello, we also faced the issue

logs:

Going to establish a new connection to Slack ...
Reconnecting to Slack ...
This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason:
Error: Unhandled event 'server disconnect old socket' in state 'connecting'. at StateMachine.handleUnhandledEvent (/app/node_modules/finity/lib/core/StateMachine.js:76:13) at /app/node_modules/finity/lib/core/HierarchicalStateMachine.js:79:33 at TaskScheduler.execute (/app/node_modules/finity/lib/core/TaskScheduler.js:29:7) at TaskScheduler.enqueue (/app/node_modules/finity/lib/core/TaskScheduler.js:19:12) at HierarchicalStateMachine.handle (/app/node_modules/finity/lib/core/HierarchicalStateMachine.js:72:24) at SocketModeClient.onWebSocketMessage (/app/node_modules/@slack/socket-mode/dist/SocketModeClient.js:579:31) at WebSocket.onMessage (/app/node_modules/ws/lib/event-target.js:132:16) at WebSocket.emit (node:events:513:28) at WebSocket.emit (node:domain:489:12) at Receiver.receiverOnMessage (/app/node_modules/ws/lib/websocket.js:1059:20)

jwoo0122 · 2024-04-05T17:05:57Z

We are facing this issue recently, too. Is there any updates or workaround to surpress this error?

aoberoi added needs info An issue that is claimed to be a bug and hasn't been reproduced, or otherwise needs more info and removed needs info An issue that is claimed to be a bug and hasn't been reproduced, or otherwise needs more info labels Apr 13, 2018

This was referenced Apr 18, 2018

@slack/client:KeepAlive Unhandled error #527

Closed

Allow mrkdwn_in, callback_id fields in message attachments #528

Merged

aoberoi added the bug M-T: A confirmed bug report. Issues are confirmed when the reproduction steps are documented label Apr 19, 2018

shaydewael mentioned this issue Apr 19, 2018

Fix and Add Logging for StateMachine websocket close #537

Merged

2 tasks

aoberoi closed this as completed Apr 27, 2018

zcbenz mentioned this issue May 8, 2018

TypeError: Cannot read property 'aborted' of null #552

Closed

9 tasks

shahyar added a commit to shahyar/wey that referenced this issue May 20, 2018

Set minimum version to node 8.11.2

bb345b8

See websockets/ws#1354 And slackapi/node-slack-sdk#531

shahyar added a commit to shahyar/wey that referenced this issue May 21, 2018

Set minimum version to node 8.11.2

18af7d1

See websockets/ws#1354 And slackapi/node-slack-sdk#531

shahyar added a commit to shahyar/wey that referenced this issue May 21, 2018

Set minimum version to node 8.11.2

a22629d

See websockets/ws#1354 And slackapi/node-slack-sdk#531

shahyar mentioned this issue May 21, 2018

Add reaction modification, correct thread updating yue/wey#67

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

StateMachine: unhandled event 'websocket close' in state 'connecting' #531

StateMachine: unhandled event 'websocket close' in state 'connecting' #531

malonecm commented Apr 12, 2018

aoberoi commented Apr 13, 2018

malonecm commented Apr 14, 2018

malonecm commented Apr 17, 2018

malonecm commented Apr 17, 2018

aoberoi commented Apr 18, 2018

aoberoi commented Apr 18, 2018

aoberoi commented Apr 27, 2018

aoberoi commented May 1, 2018

malonecm commented May 1, 2018

geoguide commented Dec 5, 2022 •

edited

Loading

nazmariam commented Jun 15, 2023

jwoo0122 commented Apr 5, 2024

StateMachine: unhandled event 'websocket close' in state 'connecting' #531

StateMachine: unhandled event 'websocket close' in state 'connecting' #531

Comments

malonecm commented Apr 12, 2018

Description

What type of issue is this?

Requirements

Bug Report

Reproducible in:

Steps to reproduce:

Expected result:

Actual result:

Attachments:

aoberoi commented Apr 13, 2018

malonecm commented Apr 14, 2018

malonecm commented Apr 17, 2018

malonecm commented Apr 17, 2018

aoberoi commented Apr 18, 2018

aoberoi commented Apr 18, 2018

aoberoi commented Apr 27, 2018

aoberoi commented May 1, 2018

malonecm commented May 1, 2018

geoguide commented Dec 5, 2022 • edited Loading

nazmariam commented Jun 15, 2023

jwoo0122 commented Apr 5, 2024

geoguide commented Dec 5, 2022 •

edited

Loading