too_many_websockets disconnect being raised in a single-instance app #1223

filmaj · 2023-10-25T16:05:40Z

Operating context:

there is only a single instance of the app - no multiple-processes-running-the-app
Also @dbudim mentioned that after replacing their application token, the problem is gone for a week 🤔

Relevant logs:

WebSocketConnectReadThread-677874] 2023-10-25 09:45:50 [INFO ] [SocketModeClient:261] - New session is open
[WebSocketConnectReadThread-677874] 2023-10-25 09:45:50 [DEBUG] [SocketModeClient:384] - Socket Mode Request:

{
  "type": "disconnect",
  "reason": "too_many_websockets",
  "debug_info": {
    "host": "applink-6"
  }
}

[WebSocketConnectReadThread-677874] 2023-10-25 09:45:50 [INFO ] [SocketModeClient:272] - onClose listener is called (code: 1006, reason: )
[WebSocketConnectReadThread-677874] 2023-10-25 09:45:50 [DEBUG] [DetailedLoggingListener:84] -

java SDK:

<dependency>
       <groupId>com.slack.api</groupId>
      <artifactId>bolt</artifactId>
      <version>1.34.0</version>
</dependency>
<dependency>
       <groupId>com.slack.api</groupId>
       <artifactId>bolt-socket-mode</artifactId>
       <version>1.34.0</version>
</dependency>

Originally posted by @dbudim in slackapi/node-slack-sdk#1654 (comment)

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

dbudim · 2023-10-25T16:21:15Z

Seems might be caused by #1206

filmaj · 2023-10-25T16:39:50Z

too_many_websockets gets raised by our backend if the backend has more than 10 concurrent connections active with a single app.

Because this is a single instance of an app, this leads me to believe maybe this library is establishing more than these ten connections at a time, possibly due to reconnection logic? Looking at the socket-mode code, it seems to me no connection pool is used in this library. The only location I see where possibly multiple connections are held at the same time is here, but presumably the 'old' session is only active for a very short, overlapping time between the 'new' session is connected, so I'm not sure this is possible.

@dbudim are you able to provide more logs? If possible including verbose logging and from the very first occurrence of any disconnect or warning received from the Slack backend.

Another possibility is perhaps the backend's state-tracking for how many concurrent connections per app ID are active is stale?

dbudim · 2023-10-25T18:10:25Z

too_many_websockets gets raised by our backend if the backend has more than 10 concurrent connections active with a single app.

Because this is a single instance of an app, this leads me to believe maybe this library is establishing more than these ten connections at a time, possibly due to reconnection logic? Looking at the socket-mode code, it seems to me no connection pool is used in this library. The only location I see where possibly multiple connections are held at the same time is here, but presumably the 'old' session is only active for a very short, overlapping time between the 'new' session is connected, so I'm not sure this is possible.

@dbudim are you able to provide more logs? If possible including verbose logging and from the very first occurrence of any disconnect or warning received from the Slack backend.

Another possibility is perhaps the backend's state-tracking for how many concurrent connections per app ID are active is stale?

I'll do on another fail, old logs wasn't saved from beginning.

DEBUG log level is ok? Or need more verbose (trace) ?

Could we don't check sessions count before waiting next failure?

filmaj · 2023-10-25T18:12:40Z

Yes, DEBUG level is fine, thank you!

Could we don't check sessions count before waiting next failure?

Possible. Once we have logs, I think it will be easier to cross-reference behaviour with code to get a better idea of why this is happening.

filmaj · 2023-10-26T16:47:11Z

@dbudim not sure if you saw, but in #1206 the original poster of that issue mentioned that switching to the Tyrus WebSocket implementation addressed the issue for them. Maybe worth a shot to see if that helps you, as well?

dbudim · 2023-10-26T17:53:04Z

@dbudim not sure if you saw, but in #1206 the original poster of that issue mentioned that switching to the Tyrus WebSocket implementation addressed the issue for them. Maybe worth a shot to see if that helps you, as well?

Nice idea, I'll try and back with result within a week)

github-actions · 2023-12-11T00:05:17Z

👋 It looks like this issue has been open for 30 days with no activity. We'll mark this as stale for now, and wait 10 days for an update or for further comment before closing this issue out. If you think this issue needs to be prioritized, please comment to get the thread going again! Maintainers also review issues marked as stale on a regular basis and comment or adjust status if the issue needs to be reprioritized.

github-actions · 2023-12-25T00:05:16Z

As this issue has been inactive for more than one month, we will be closing it. Thank you to all the participants! If you would like to raise a related issue, please create a new issue which includes your specific details and references this issue number.

dbudim · 2023-12-26T09:48:00Z

@filmaj Hi, sorry for a delay, I have a full portion of logs from a beginning and it starts from
Failed to send a ping message and then makes retries. After that it exceed a limit of sessions. By the way I moved to recommended ws library and nothing helps(

Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: 2217e8d7-6eff-4488-8259-e125c4041301)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2217e8d7-6eff-4488-8259-e125c4041301, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 2217e8d7-6eff-4488-8259-e125c4041301, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@58b2f406[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@4933579e[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@2a8b7534]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@72e510c3[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 16])
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: fac195f4-a738-4bbf-9462-320f6796c25b, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: 09916a41-b340-4f45-8799-54a24b39c9e6)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 09916a41-b340-4f45-8799-54a24b39c9e6, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 965d73cf-f075-431e-9e6e-61aea16123e5, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: caf24176-39f9-44e4-a08b-741d179bf12f)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: caf24176-39f9-44e4-a08b-741d179bf12f, reason: Closed abnormally.)
[socket-mode-session-cleaner-worker-95] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: c1ed11a6-1dfe-4d01-ab22-b34f92df0b2d, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: dbb2bb28-c5ea-4713-8827-17e05464719e, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: 90be2317-2bae-46d7-a749-b7c12ae9e45b)
[Grizzly(2)] 2023-12-24 01:47:06 [INFO ] [SocketModeClient:232] - New session is open (session id: c3b41e09-1085-42be-989a-a4329ec78f9d)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 90be2317-2bae-46d7-a749-b7c12ae9e45b, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2304bf7d[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@59fef065[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@3bb99d78]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@736366eb[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 9])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: d95fcf25-96bb-488e-82d0-c58f34f971fd)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 05b787e7-eac4-46fe-be77-9224c3afe8d4, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: d95fcf25-96bb-488e-82d0-c58f34f971fd, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: fc1f4a6d-dca2-4b2e-a460-ef6e36b85bf7)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 1399de65-d596-4c50-8eb9-0642a739da3a)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: fc1f4a6d-dca2-4b2e-a460-ef6e36b85bf7, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 794fa0c3-be2c-49dd-b1c4-139e48655f62)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 794fa0c3-be2c-49dd-b1c4-139e48655f62, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@473c7589[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1206fbbd[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@5d6631b2]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@bd69ced[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 11])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 79bc4280-dbda-4538-aad1-5d68033edcb0, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 794fa0c3-be2c-49dd-b1c4-139e48655f62, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 5b4f8944-eb06-40d7-aba0-add54fa8e00c)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 5b4f8944-eb06-40d7-aba0-add54fa8e00c, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 14a9dcff-fac7-4474-be19-76b0603d6f73)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 14a9dcff-fac7-4474-be19-76b0603d6f73, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: f5b2229b-47c3-4d32-b38e-b10682988a11)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f5b2229b-47c3-4d32-b38e-b10682988a11, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: e7183eb7-66d6-4d78-b12b-858734bf5462)
[socket-mode-session-cleaner-worker-144] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 4a66a00a-4ee4-493b-9727-cbf2bd19564a, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 4a7c4440-5025-49b9-9540-c8b2b2fbcc8c)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: e6abc674-dc7f-4034-ac90-e3b5da6d2e53)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 8e6205c2-3632-4bbd-a941-f4caf35c9119)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 2f7a5e41-2276-48fd-adfa-d09289dd9145)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 2d043bdb-cc4e-49cc-a5fa-c620d713a7c7)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 791a9efa-d232-4c44-b3c2-d5ce653025bc)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: e6abc674-dc7f-4034-ac90-e3b5da6d2e53, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 65b336bc-f233-452f-a504-e0a6362da1d6, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: d3218d3a-28d3-4af0-b710-81266999c052)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: d3218d3a-28d3-4af0-b710-81266999c052, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: d3218d3a-28d3-4af0-b710-81266999c052, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@68aab4fd[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@733001c1[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@68ec4a4c]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@68b304cb[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 17])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 10f4f6f3-7ba6-414c-8484-be717f253b3f, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 8a4b7f2c-a3c4-4be8-865d-f785658b9d2e, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: b8424916-a257-4621-9f41-c96da7cd38c5)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 576e0f2a-5a31-4438-8691-b11e92488210)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: b8424916-a257-4621-9f41-c96da7cd38c5, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 3f88f8a6-d3b7-4cf9-9bae-aea29cf66800)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 3f88f8a6-d3b7-4cf9-9bae-aea29cf66800, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@3eb2a393[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@46814ab9[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@22826d90]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@73742555[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 4])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 791a9efa-d232-4c44-b3c2-d5ce653025bc, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 3f88f8a6-d3b7-4cf9-9bae-aea29cf66800, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 791a9efa-d232-4c44-b3c2-d5ce653025bc, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@7e63b99d[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@2f98fbc2[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@2e505c5]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5b2e1863[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 32])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 84dcd1e6-9b50-4b00-914c-2b5e5deda05e, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 84dcd1e6-9b50-4b00-914c-2b5e5deda05e, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@24e4cc9c[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@7545533a[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@392c25c1]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5b2e1863[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 32])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2959c247-b34c-421a-947a-1a76bc3a1c85, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: a538df59-61a7-4604-af00-58eaaa4d625c)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: a538df59-61a7-4604-af00-58eaaa4d625c, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: f7eaa661-f240-435c-8e4c-54a293bd58b0)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f7eaa661-f240-435c-8e4c-54a293bd58b0, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 0a4bb8bd-89fd-40d1-b5dd-d3dc39a8d3fc)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 0a4bb8bd-89fd-40d1-b5dd-d3dc39a8d3fc, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 7a02ae57-3271-423c-b343-16659d776df7)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 7a02ae57-3271-423c-b343-16659d776df7, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 9e9b7b70-dafa-4035-8ce0-0aa4bd0d898d)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 9e9b7b70-dafa-4035-8ce0-0aa4bd0d898d, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 84104aab-1b7c-4d3e-a279-d860c86fc30b)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 84104aab-1b7c-4d3e-a279-d860c86fc30b, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 49eb7157-4530-447c-afab-00de8444c204)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 49eb7157-4530-447c-afab-00de8444c204, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@19a1633a[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@540bb83a[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@10c3fd61]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@76af3c45[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 12])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 49eb7157-4530-447c-afab-00de8444c204, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2f7a5e41-2276-48fd-adfa-d09289dd9145, reason: Closed abnormally.)
[socket-mode-session-cleaner-worker-95] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 2f7a5e41-2276-48fd-adfa-d09289dd9145, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@4e75a0aa[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@5b303df2[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@5bce7996]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@268bbaad[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 11])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 6830e028-f620-4e45-85cb-557fea1a9484)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 6830e028-f620-4e45-85cb-557fea1a9484, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 3832638b-6a8c-43fa-84e4-16efe5a0eb9a)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 3832638b-6a8c-43fa-84e4-16efe5a0eb9a, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2be7b175[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@51c897eb[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@4b7d5065]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@10ce62b2[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 19])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 013fc9e9-719f-41d7-931a-358ca821e152, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 3832638b-6a8c-43fa-84e4-16efe5a0eb9a, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 0f49f222-c3c8-4f88-b07a-8876ab9f17e0)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 0f49f222-c3c8-4f88-b07a-8876ab9f17e0, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [WARN ] [SocketModeClient:209] - Failed to send a ping message (session id: 0f49f222-c3c8-4f88-b07a-8876ab9f17e0, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@1652ada[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@1b2299db[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@11080e23]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@501e87a6[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 13])
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 1399de65-d596-4c50-8eb9-0642a739da3a, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 0ba86d61-e074-4d53-b3fa-ebc4aaea9190)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 0ba86d61-e074-4d53-b3fa-ebc4aaea9190, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: f6c805c6-21df-4f49-b1de-f7e29f351515)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f6c805c6-21df-4f49-b1de-f7e29f351515, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: 76fd4f7a-4ec1-47c8-81bc-95a50f12c231)
[Grizzly(1)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 76fd4f7a-4ec1-47c8-81bc-95a50f12c231, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:232] - New session is open (session id: a57e51fb-4255-46bc-9671-cef169764d63)
[Grizzly(1)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: a57e51fb-4255-46bc-9671-cef169764d63, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:07 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 2d043bdb-cc4e-49cc-a5fa-c620d713a7c7, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 03fb50a3-b0d9-4b77-96e5-b6294eb48ee8)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 03fb50a3-b0d9-4b77-96e5-b6294eb48ee8, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: f16c5a1c-5082-4057-b0ba-8cd477c41b01)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: f16c5a1c-5082-4057-b0ba-8cd477c41b01, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: c0eb641c-9c9f-4681-af44-37e405e75cbc)
[socket-mode-session-cleaner-worker-95] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 1c290446-2c5c-49a8-a909-266cc2e48e6d, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 11f5014a-097f-4f9a-9aaf-8a0ce5ce9db4)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 11f5014a-097f-4f9a-9aaf-8a0ce5ce9db4, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 991f9316-1a41-43cd-bffd-7e56d9748ca9)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: d3ab0814-2ea9-4b78-b0e8-ea0a39756fb4)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 991f9316-1a41-43cd-bffd-7e56d9748ca9, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: bbe50fa2-d7fb-4255-9265-229ea2de31f6)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: bbe50fa2-d7fb-4255-9265-229ea2de31f6, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 8ee1d8ee-d023-431b-9625-20387d95748d)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: 8ee1d8ee-d023-431b-9625-20387d95748d, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: e4dc7a9d-2b22-4751-a489-23228c977445)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: e842a265-17c7-49c9-a30c-9163a70c0a28)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:240] - onClose listener is called (session id: e4dc7a9d-2b22-4751-a489-23228c977445, reason: Closed abnormally.)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 592f3a8d-fadb-461f-95c9-e3a250b72af8)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 5e73ec8f-4803-40f3-a8ca-0ed66e3dfd0c)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 8e06ff07-15b0-4524-968b-a3e504627fce)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: fa3f2fe9-ec40-468b-a5cb-2ca7f25a4deb)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 90dba958-8dc5-4fcf-a457-9afabcefb423)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: bd00f506-cac0-402d-882d-690dc5d491bd)
[Grizzly(2)] 2023-12-24 01:47:08 [INFO ] [SocketModeClient:232] - New session is open (session id: 66652362-b9fc-442f-bd59-56fbd2c419a4)
[Grizzly(2)] 2023-12-24 01:47:08 [ERROR] [SocketModeClient:263] - Failed to reconnect to the Socket Mode server: Failed to connect to the Socket Mode API endpoint. (status: 429, error: ratelimited)
java.io.IOException: Failed to connect to the Socket Mode API endpoint. (status: 429, error: ratelimited)
	at com.slack.api.Slack.issueSocketModeUrl(Slack.java:196)
	at com.slack.api.socket_mode.SocketModeClient.connectToNewEndpoint(SocketModeClient.java:65)
	at com.slack.api.socket_mode.SocketModeClient.runCloseListenersAndAutoReconnectAsNecessary(SocketModeClient.java:261)
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.onClose(SocketModeClientTyrusImpl.java:242)
	at jdk.internal.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.glassfish.tyrus.core.AnnotatedEndpoint.callMethod(AnnotatedEndpoint.java:551)
	at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:566)
	at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:575)
	at org.glassfish.tyrus.core.TyrusEndpointWrapper.onClose(TyrusEndpointWrapper.java:1235)
	at org.glassfish.tyrus.core.TyrusWebSocket.onClose(TyrusWebSocket.java:110)
	at org.glassfish.tyrus.core.ProtocolHandler.close(ProtocolHandler.java:488)
	at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:244)
	at org.glassfish.tyrus.client.TyrusClientEngine$2$1.close(TyrusClientEngine.java:613)
	at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter$CloseTask.execute(GrizzlyClientFilter.java:484)
	at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:91)
	at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:68)
	at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleClose(GrizzlyClientFilter.java:198)
	at org.glassfish.grizzly.filterchain.ExecutorResolver$4.execute(ExecutorResolver.java:52)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88)
	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53)
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515)
	at org.glassfish.grizzly.nio.NIOConnection.preClose(NIOConnection.java:881)
	at org.glassfish.grizzly.nio.transport.TCPNIOConnection.preClose(TCPNIOConnection.java:73)
	at org.glassfish.grizzly.nio.NIOConnection.terminate0(NIOConnection.java:599)
	at org.glassfish.grizzly.nio.transport.TCPNIOConnection.terminate0(TCPNIOConnection.java:267)
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:608)
	at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:51)
	at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:149)
	at org.glassfish.grizzly.ssl.SSLBaseFilter$SSLTransportFilterWrapper.handleRead(SSLBaseFilter.java:1120)
	at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109)
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88)
	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53)
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515)
	at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89)
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94)
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33)
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114)
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569)
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: SlackApiException(response=Response{protocol=h2, code=429, message=, url=https://slack.com/api/apps.connections.open}, responseBody={"ok":false,"error":"ratelimited"}, error=SlackApiErrorResponse(ok=false, warning=null, error=ratelimited, needed=null, provided=null, httpResponseHeaders=null))
	at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3553)
	at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3526)
	at com.slack.api.methods.impl.MethodsClientImpl.postFormWithTokenAndParseResponse(MethodsClientImpl.java:3433)
	at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1297)
	at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1302)
	at com.slack.api.Slack.issueSocketModeUrl(Slack.java:184)
	... 47 more

dbudim · 2023-12-27T12:20:36Z

Updated bolt sdk and jdk (saw advices that solves some issues with ssl) but didn't help.

First we hav and hadhsake error and then retries and exceeding a limit

12-26T18:22:47.375Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: fd362d39-f74f-4a84-8954-9acf138768f9)
2023-12-26T18:22:47.390Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: fd362d39-f74f-4a84-8954-9acf138768f9, reason: Closed abnormally.)
2023-12-26T18:22:47.485Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: e0021593-e6f6-41c2-9549-c051c8e876e5)
2023-12-26T18:22:47.504Z  INFO 130 --- [     Grizzly(1)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: e0021593-e6f6-41c2-9549-c051c8e876e5, reason: Closed abnormally.)
2023-12-26T18:22:47.520Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: c045827f-7121-489f-b33c-3362b803a994)
2023-12-26T18:22:47.523Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: c045827f-7121-489f-b33c-3362b803a994, reason: Closed abnormally.)
2023-12-26T18:22:47.594Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 03df01fd-d3a5-4069-bac7-3bc87aa69641)
2023-12-26T18:22:47.614Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: d04a1c12-145f-43f8-9431-b6e49ed7cc03)
2023-12-26T18:22:47.615Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: 03df01fd-d3a5-4069-bac7-3bc87aa69641, reason: Closed abnormally.)
2023-12-26T18:22:47.712Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: f08109c4-ebeb-4152-8de4-a0656248e9a1)
2023-12-26T18:22:47.717Z  WARN 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : Failed to send a ping message (session id: f08109c4-ebeb-4152-8de4-a0656248e9a1, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@61278af5[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@281e57f7[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@541e60a]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@5982a0d1[Shutting down, pool size = 4, active threads = 0, queued tasks = 0, completed tasks = 4])
2023-12-26T18:22:47.757Z  INFO 130 --- [aner-worker-198] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: f08109c4-ebeb-4152-8de4-a0656248e9a1, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
2023-12-26T18:22:47.788Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 9c486e21-b2e0-42b7-a94f-d2049508e21f)
2023-12-26T18:22:47.892Z  INFO 130 --- [aner-worker-192] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: d04a1c12-145f-43f8-9431-b6e49ed7cc03, reason: com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl did it)
2023-12-26T18:22:47.898Z ERROR 130 --- [aner-worker-181] c.s.api.socket_mode.SocketModeClient     : Failed to reconnect to Socket Mode server: javax.websocket.DeploymentException: Handshake error.

java.io.IOException: javax.websocket.DeploymentException: Handshake error.
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.connect(SocketModeClientTyrusImpl.java:173) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.SocketModeClient.connectToNewEndpoint(SocketModeClient.java:66) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.SocketModeClient.runCloseListenersAndAutoReconnectAsNecessary(SocketModeClient.java:261) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.onClose(SocketModeClientTyrusImpl.java:242) ~[slack-api-client-1.36.1.jar:1.36.1]
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
	at org.glassfish.tyrus.core.AnnotatedEndpoint.callMethod(AnnotatedEndpoint.java:551) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:566) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:575) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusEndpointWrapper.onClose(TyrusEndpointWrapper.java:1235) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusWebSocket.onClose(TyrusWebSocket.java:110) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.ProtocolHandler.close(ProtocolHandler.java:488) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:244) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:254) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusRemoteEndpoint.close(TyrusRemoteEndpoint.java:480) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusSession.close(TyrusSession.java:211) ~[tyrus-standalone-client-1.21.jar:na]
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.closeSession(SocketModeClientTyrusImpl.java:296) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.lambda$setCurrentSession$1(SocketModeClientTyrusImpl.java:278) ~[slack-api-client-1.36.1.jar:1.36.1]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]
Caused by: javax.websocket.DeploymentException: Handshake error.
	at org.glassfish.tyrus.client.ClientManager$3$1.run(ClientManager.java:658) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.client.ClientManager$3.run(ClientManager.java:696) ~[tyrus-standalone-client-1.21.jar:na]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[na:na]
	at org.glassfish.tyrus.client.ClientManager$SameThreadExecutorService.execute(ClientManager.java:849) ~[tyrus-standalone-client-1.21.jar:na]
	at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:123) ~[na:na]
	at org.glassfish.tyrus.client.ClientManager.connectToServer(ClientManager.java:493) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.client.ClientManager.connectToServer(ClientManager.java:355) ~[tyrus-standalone-client-1.21.jar:na]
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.connect(SocketModeClientTyrusImpl.java:170) ~[slack-api-client-1.36.1.jar:1.36.1]
	... 20 common frames omitted
Caused by: org.glassfish.tyrus.core.HandshakeException: Response code was not 101: 408.
	at org.glassfish.tyrus.client.TyrusClientEngine.processResponse(TyrusClientEngine.java:300) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleHandshake(GrizzlyClientFilter.java:323) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleRead(GrizzlyClientFilter.java:292) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549) ~[tyrus-standalone-client-1.21.jar:na]
	... 1 common frames omitted


ion id: 92c7e0f2-1dba-472a-ab37-f053a8b283fc, reason: Closed abnormally.)
2023-12-26T23:24:16.881Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: a1b4f1cb-0b95-42b9-a5da-c070b8b2947c)
2023-12-26T23:24:16.897Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 7a4a3c63-4fd6-4abe-80cc-2ef6031a361c)
2023-12-26T23:24:16.900Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: a1b4f1cb-0b95-42b9-a5da-c070b8b2947c, reason: Closed abnormally.)
2023-12-26T23:24:16.928Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: a1326811-8a08-448c-b1a3-2645d4b82e0f, reason: Closed abnormally.)
2023-12-26T23:24:16.941Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 8b8d532e-d981-43eb-976a-83493ac4f0fe)
2023-12-26T23:24:16.951Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: 8b8d532e-d981-43eb-976a-83493ac4f0fe, reason: Closed abnormally.)
2023-12-26T23:24:16.998Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 4c32957b-bddf-40f8-8084-b6c5c2e68ecb)
2023-12-26T23:24:17.007Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 355d9b0d-d4b5-4f0b-850c-63645061e1ad)
2023-12-26T23:24:17.011Z  INFO 130 --- [     Grizzly(1)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: 4c32957b-bddf-40f8-8084-b6c5c2e68ecb, reason: Closed abnormally.)
2023-12-26T23:24:17.065Z  WARN 130 --- [aner-worker-198] c.s.api.socket_mode.SocketModeClient     : Failed to send a ping message (session id: 4c32957b-bddf-40f8-8084-b6c5c2e68ecb, error: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@5fec3609[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@2cec5a3c[Wrapped task = org.glassfish.tyrus.core.TyrusSession$IdleTimeoutCommand@6a54033c]] rejected from java.util.concurrent.ScheduledThreadPoolExecutor@2bd3abfd[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 7])
2023-12-26T23:24:17.072Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: 7e7e39af-d1fd-456f-a2e2-c68d378c336c)
2023-12-26T23:24:17.083Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: 7e7e39af-d1fd-456f-a2e2-c68d378c336c, reason: Closed abnormally.)
2023-12-26T23:24:17.089Z ERROR 130 --- [     Grizzly(2)] com.slack.api.methods.impl.TeamIdCache   : Failed to call auth.test API (error: status: 429, error: ratelimited, needed: null, provided: null, warning: null)

com.slack.api.methods.SlackApiException: status: 429, error: ratelimited, needed: null, provided: null, warning: null
	at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3617) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.methods.impl.MethodsClientImpl.parseJsonResponseAndRunListeners(MethodsClientImpl.java:3590) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.methods.impl.TeamIdCache.lambda$lookupOrResolve$0(TeamIdCache.java:44) ~[slack-api-client-1.36.1.jar:1.36.1]
	at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1708) ~[na:na]
	at com.slack.api.methods.impl.TeamIdCache.lookupOrResolve(TeamIdCache.java:67) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.methods.impl.TeamIdCache.lookupOrResolve(TeamIdCache.java:40) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.methods.impl.MethodsClientImpl.postFormWithTokenAndParseResponse(MethodsClientImpl.java:3488) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1301) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.methods.impl.MethodsClientImpl.appsConnectionsOpen(MethodsClientImpl.java:1306) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.Slack.issueSocketModeUrl(Slack.java:184) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.SocketModeClient.connectToNewEndpoint(SocketModeClient.java:65) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.SocketModeClient.runCloseListenersAndAutoReconnectAsNecessary(SocketModeClient.java:261) ~[slack-api-client-1.36.1.jar:1.36.1]
	at com.slack.api.socket_mode.impl.SocketModeClientTyrusImpl.onClose(SocketModeClientTyrusImpl.java:242) ~[slack-api-client-1.36.1.jar:1.36.1]
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[na:na]
	at org.glassfish.tyrus.core.AnnotatedEndpoint.callMethod(AnnotatedEndpoint.java:551) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:566) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.AnnotatedEndpoint.onClose(AnnotatedEndpoint.java:575) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusEndpointWrapper.onClose(TyrusEndpointWrapper.java:1235) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusWebSocket.onClose(TyrusWebSocket.java:110) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.ProtocolHandler.close(ProtocolHandler.java:488) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.core.TyrusWebSocket.close(TyrusWebSocket.java:244) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.client.TyrusClientEngine$2$1.close(TyrusClientEngine.java:613) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter$CloseTask.execute(GrizzlyClientFilter.java:484) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:91) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.container.grizzly.client.TaskProcessor.processTask(TaskProcessor.java:68) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.tyrus.container.grizzly.client.GrizzlyClientFilter.handleClose(GrizzlyClientFilter.java:198) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.ExecutorResolver$4.execute(ExecutorResolver.java:52) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.NIOConnection.preClose(NIOConnection.java:881) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOConnection.preClose(TCPNIOConnection.java:73) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.NIOConnection.terminate0(NIOConnection.java:599) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOConnection.terminate0(TCPNIOConnection.java:267) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:608) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:51) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.TransportFilter.handleRead(TransportFilter.java:149) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.ssl.SSLBaseFilter$SSLTransportFilterWrapper.handleRead(SSLBaseFilter.java:1120) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:95) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:515) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:89) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:94) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:33) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:114) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:569) ~[tyrus-standalone-client-1.21.jar:na]
	at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:549) ~[tyrus-standalone-client-1.21.jar:na]
	at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]

filmaj · 2024-01-02T17:54:08Z

Hey @dbudim, happy new year!

Regarding your last logs provided in your last comment: it seems the websocket connection gets closed 'abnormally' first:

2023-12-26T18:22:47.375Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : New session is open (session id: fd362d39-f74f-4a84-8954-9acf138768f9)
2023-12-26T18:22:47.390Z  INFO 130 --- [     Grizzly(2)] c.s.api.socket_mode.SocketModeClient     : onClose listener is called (session id: fd362d39-f74f-4a84-8954-9acf138768f9, reason: Closed abnormally.)

This is assuming that session id: fd362d39-f74f-4a84-8954-9acf138768f9 is the 'first' session on app boot up?

According to the WebSocket spec, an abnormal closure is one where the connection was severed without an endpoint sending a Close frame (see close code 1006). This indicates to me that the underlying network connection had an issue.

Regardless, I would expect this SDK to be able to handle this, try to reconnect, and not get itself all confused and cause a rate limit exception 😓

Looking through the logs, it seems to me that possibly the SDK is not accounting for the retries in a correct manner. Some of the session IDs are not 'paired' properly with a open and close message. For example, session ID 7a4a3c63-4fd6-4abe-80cc-2ef6031a361c I only see an 'open' message for, but not a closed one. Additionally, it seems like the socket connection thread pool (of size 4) also experienced issues.

This will probably be difficult to debug / reproduce, but I will try...

filmaj · 2024-01-02T17:55:37Z

Actually, #1256 has very similar logging as here... looking into it.

filmaj · 2024-01-03T15:01:35Z

Going to close this issue as it is a duplicate of #1256 and there is more activity there. If you have more discussion to contribute to this issue, please comment over in #1256.

filmaj mentioned this issue Oct 25, 2023

@slack/socket-mode - Handle event.type === disconnect && reason === 'too_many_websockets' slackapi/node-slack-sdk#1654

Closed

7 tasks

seratch added question M-T: User needs support to use the project project:bolt project:slack-api-client project:slack-api-client labels Nov 7, 2023

github-actions bot added the auto-triage-stale label Dec 11, 2023

github-actions bot closed this as completed Dec 25, 2023

filmaj reopened this Jan 2, 2024

filmaj mentioned this issue Jan 2, 2024

busy to open/close a connection when running slack socket mode for days #1256

Closed

filmaj closed this as completed Jan 3, 2024

seratch added this to the 1.37.0 milestone Jan 11, 2024

seratch mentioned this issue Jan 11, 2024

Fix #1256 Socket Mode connection error issue #1265

Merged

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

too_many_websockets disconnect being raised in a single-instance app #1223

too_many_websockets disconnect being raised in a single-instance app #1223

filmaj commented Oct 25, 2023 •

edited

Loading

dbudim commented Oct 25, 2023

filmaj commented Oct 25, 2023

dbudim commented Oct 25, 2023

filmaj commented Oct 25, 2023

filmaj commented Oct 26, 2023

dbudim commented Oct 26, 2023

github-actions bot commented Dec 11, 2023

github-actions bot commented Dec 25, 2023

dbudim commented Dec 26, 2023

dbudim commented Dec 27, 2023 •

edited

Loading

filmaj commented Jan 2, 2024

filmaj commented Jan 2, 2024

filmaj commented Jan 3, 2024

too_many_websockets disconnect being raised in a single-instance app #1223

too_many_websockets disconnect being raised in a single-instance app #1223

Comments

filmaj commented Oct 25, 2023 • edited Loading

dbudim commented Oct 25, 2023

filmaj commented Oct 25, 2023

dbudim commented Oct 25, 2023

filmaj commented Oct 25, 2023

filmaj commented Oct 26, 2023

dbudim commented Oct 26, 2023

github-actions bot commented Dec 11, 2023

github-actions bot commented Dec 25, 2023

dbudim commented Dec 26, 2023

dbudim commented Dec 27, 2023 • edited Loading

filmaj commented Jan 2, 2024

filmaj commented Jan 2, 2024

filmaj commented Jan 3, 2024

filmaj commented Oct 25, 2023 •

edited

Loading

dbudim commented Dec 27, 2023 •

edited

Loading